Du kan inte välja fler än 25 ämnen Ämnen måste starta med en bokstav eller siffra, kan innehålla bindestreck ('-') och vara max 35 tecken långa.

734 rader
37 KiB

14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
14 år sedan
  1. %% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved.
  2. %%
  3. %% This file is provided to you under the Apache License,
  4. %% Version 2.0 (the "License"); you may not use this file
  5. %% except in compliance with the License. You may obtain
  6. %% a copy of the License at
  7. %%
  8. %% http://www.apache.org/licenses/LICENSE-2.0
  9. %%
  10. %% Unless required by applicable law or agreed to in writing,
  11. %% software distributed under the License is distributed on an
  12. %% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  13. %% KIND, either express or implied. See the License for the
  14. %% specific language governing permissions and limitations
  15. %% under the License.
  16. -module(lager_test_backend).
  17. -include("lager.hrl").
  18. -behaviour(gen_event).
  19. -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
  20. code_change/3]).
  21. -record(state, {level, buffer, ignored}).
  22. -compile([{parse_transform, lager_transform}]).
  23. -ifdef(TEST).
  24. -include_lib("eunit/include/eunit.hrl").
  25. -export([pop/0, count/0, count_ignored/0, flush/0]).
  26. -endif.
  27. init(Level) ->
  28. {ok, #state{level=lager_util:level_to_num(Level), buffer=[], ignored=[]}}.
  29. handle_call(count, #state{buffer=Buffer} = State) ->
  30. {ok, length(Buffer), State};
  31. handle_call(count_ignored, #state{ignored=Ignored} = State) ->
  32. {ok, length(Ignored), State};
  33. handle_call(flush, State) ->
  34. {ok, ok, State#state{buffer=[], ignored=[]}};
  35. handle_call(pop, #state{buffer=Buffer} = State) ->
  36. case Buffer of
  37. [] ->
  38. {ok, undefined, State};
  39. [H|T] ->
  40. {ok, H, State#state{buffer=T}}
  41. end;
  42. handle_call(get_loglevel, #state{level=Level} = State) ->
  43. {ok, Level, State};
  44. handle_call({set_loglevel, Level}, State) ->
  45. {ok, ok, State#state{level=lager_util:level_to_num(Level)}};
  46. handle_call(_Request, State) ->
  47. {ok, ok, State}.
  48. handle_event({log, Msg},
  49. #state{level=LogLevel,buffer=Buffer,ignored=Ignored} = State) ->
  50. case lager_util:is_loggable(Msg, LogLevel, ?MODULE) of
  51. true -> {ok, State#state{buffer=Buffer ++
  52. [{lager_msg:severity_as_int(Msg),
  53. lager_msg:timestamp(Msg),
  54. lager_msg:message(Msg), lager_msg:metadata(Msg)}]}};
  55. _ -> {ok, State#state{ignored=Ignored ++ [ignored]}}
  56. end;
  57. handle_event(_Event, State) ->
  58. {ok, State}.
  59. handle_info(_Info, State) ->
  60. {ok, State}.
  61. terminate(_Reason, _State) ->
  62. ok.
  63. code_change(_OldVsn, State, _Extra) ->
  64. {ok, State}.
  65. -ifdef(TEST).
  66. pop() ->
  67. gen_event:call(lager_event, ?MODULE, pop).
  68. count() ->
  69. gen_event:call(lager_event, ?MODULE, count).
  70. count_ignored() ->
  71. gen_event:call(lager_event, ?MODULE, count_ignored).
  72. flush() ->
  73. gen_event:call(lager_event, ?MODULE, flush).
  74. has_line_numbers() ->
  75. %% are we R15 or greater
  76. Rel = erlang:system_info(otp_release),
  77. {match, [Major]} = re:run(Rel, "^R(\\d+)[A|B](|0(\\d))$", [{capture, [1], list}]),
  78. list_to_integer(Major) >= 15.
  79. not_running_test() ->
  80. ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).
  81. lager_test_() ->
  82. {foreach,
  83. fun setup/0,
  84. fun cleanup/1,
  85. [
  86. {"observe that there is nothing up my sleeve",
  87. fun() ->
  88. ?assertEqual(undefined, pop()),
  89. ?assertEqual(0, count())
  90. end
  91. },
  92. {"logging works",
  93. fun() ->
  94. lager:warning("test message"),
  95. ?assertEqual(1, count()),
  96. {Level, _Time, Message, _Metadata} = pop(),
  97. ?assertMatch(Level, lager_util:level_to_num(warning)),
  98. ?assertEqual("test message", Message),
  99. ok
  100. end
  101. },
  102. {"logging with arguments works",
  103. fun() ->
  104. lager:warning("test message ~p", [self()]),
  105. ?assertEqual(1, count()),
  106. {Level, _Time, Message,_Metadata} = pop(),
  107. ?assertMatch(Level, lager_util:level_to_num(warning)),
  108. ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
  109. ok
  110. end
  111. },
  112. {"logging works from inside a begin/end block",
  113. fun() ->
  114. ?assertEqual(0, count()),
  115. begin
  116. lager:warning("test message 2")
  117. end,
  118. ?assertEqual(1, count()),
  119. ok
  120. end
  121. },
  122. {"logging works from inside a list comprehension",
  123. fun() ->
  124. ?assertEqual(0, count()),
  125. [lager:warning("test message") || _N <- lists:seq(1, 10)],
  126. ?assertEqual(10, count()),
  127. ok
  128. end
  129. },
  130. {"logging works from a begin/end block inside a list comprehension",
  131. fun() ->
  132. ?assertEqual(0, count()),
  133. [ begin lager:warning("test message") end || _N <- lists:seq(1, 10)],
  134. ?assertEqual(10, count()),
  135. ok
  136. end
  137. },
  138. {"logging works from a nested list comprehension",
  139. fun() ->
  140. ?assertEqual(0, count()),
  141. [ [lager:warning("test message") || _N <- lists:seq(1, 10)] ||
  142. _I <- lists:seq(1, 10)],
  143. ?assertEqual(100, count()),
  144. ok
  145. end
  146. },
  147. {"log messages below the threshold are ignored",
  148. fun() ->
  149. ?assertEqual(0, count()),
  150. lager:debug("this message will be ignored"),
  151. ?assertEqual(0, count()),
  152. ?assertEqual(0, count_ignored()),
  153. lager_mochiglobal:put(loglevel, {?DEBUG, []}),
  154. lager:debug("this message should be ignored"),
  155. ?assertEqual(0, count()),
  156. ?assertEqual(1, count_ignored()),
  157. lager:set_loglevel(?MODULE, debug),
  158. lager:debug("this message should be logged"),
  159. ?assertEqual(1, count()),
  160. ?assertEqual(1, count_ignored()),
  161. ?assertEqual(debug, lager:get_loglevel(?MODULE)),
  162. ok
  163. end
  164. },
  165. {"tracing works",
  166. fun() ->
  167. lager_mochiglobal:put(loglevel, {?ERROR, []}),
  168. ok = lager:info("hello world"),
  169. ?assertEqual(0, count()),
  170. lager_mochiglobal:put(loglevel, {?ERROR, [{[{module,
  171. ?MODULE}], ?DEBUG, ?MODULE}]}),
  172. ok = lager:info("hello world"),
  173. ?assertEqual(1, count()),
  174. ok
  175. end
  176. },
  177. {"tracing works with custom attributes",
  178. fun() ->
  179. lager_mochiglobal:put(loglevel, {?ERROR, []}),
  180. lager:info([{requestid, 6}], "hello world"),
  181. ?assertEqual(0, count()),
  182. lager_mochiglobal:put(loglevel, {?ERROR,
  183. [{[{requestid, 6}], ?DEBUG, ?MODULE}]}),
  184. lager:info([{requestid, 6}, {foo, bar}], "hello world"),
  185. ?assertEqual(1, count()),
  186. lager_mochiglobal:put(loglevel, {?ERROR,
  187. [{[{requestid, '*'}], ?DEBUG, ?MODULE}]}),
  188. lager:info([{requestid, 6}], "hello world"),
  189. ?assertEqual(2, count()),
  190. ok
  191. end
  192. },
  193. {"tracing honors loglevel",
  194. fun() ->
  195. lager_mochiglobal:put(loglevel, {?ERROR, [{[{module,
  196. ?MODULE}], ?NOTICE, ?MODULE}]}),
  197. ok = lager:info("hello world"),
  198. ?assertEqual(0, count()),
  199. ok = lager:notice("hello world"),
  200. ?assertEqual(1, count()),
  201. ok
  202. end
  203. }
  204. ]
  205. }.
  206. setup() ->
  207. error_logger:tty(false),
  208. application:load(lager),
  209. application:set_env(lager, handlers, [{?MODULE, info}]),
  210. application:set_env(lager, error_logger_redirect, false),
  211. application:start(compiler),
  212. application:start(syntax_tools),
  213. application:start(lager),
  214. gen_event:call(lager_event, ?MODULE, flush).
  215. cleanup(_) ->
  216. application:stop(lager),
  217. error_logger:tty(true).
  218. crash(Type) ->
  219. spawn(fun() -> gen_server:call(crash, Type) end),
  220. timer:sleep(100),
  221. _ = gen_event:which_handlers(error_logger),
  222. ok.
  223. test_body(Expected, Actual) ->
  224. case has_line_numbers() of
  225. true ->
  226. FileLine = string:substr(Actual, length(Expected)+1),
  227. Body = string:substr(Actual, 1, length(Expected)),
  228. ?assertEqual(Expected, Body),
  229. case string:substr(FileLine, 1, 6) of
  230. [] ->
  231. %% sometimes there's no line information...
  232. ?assert(true);
  233. " line " ->
  234. ?assert(true);
  235. Other ->
  236. ?debugFmt("unexpected trailing data ~p", [Other]),
  237. ?assert(false)
  238. end;
  239. false ->
  240. ?assertEqual(Expected, Actual)
  241. end.
  242. error_logger_redirect_crash_test_() ->
  243. TestBody=fun(Name,CrashReason,Expected) -> {Name,
  244. fun() ->
  245. Pid = whereis(crash),
  246. crash(CrashReason),
  247. {Level, _, Msg,Metadata} = pop(),
  248. test_body(Expected, lists:flatten(Msg)),
  249. ?assertEqual(Pid,proplists:get_value(pid,Metadata)),
  250. ?assertEqual(lager_util:level_to_num(error),Level)
  251. end
  252. }
  253. end,
  254. {foreach,
  255. fun() ->
  256. error_logger:tty(false),
  257. application:load(lager),
  258. application:set_env(lager, error_logger_redirect, true),
  259. application:set_env(lager, handlers, [{?MODULE, error}]),
  260. application:start(compiler),
  261. application:start(syntax_tools),
  262. application:start(lager),
  263. crash:start()
  264. end,
  265. fun(_) ->
  266. application:stop(lager),
  267. case whereis(crash) of
  268. undefined -> ok;
  269. Pid -> exit(Pid, kill)
  270. end,
  271. error_logger:tty(true)
  272. end,
  273. [
  274. {"again, there is nothing up my sleeve",
  275. fun() ->
  276. ?assertEqual(undefined, pop()),
  277. ?assertEqual(0, count())
  278. end
  279. },
  280. TestBody("bad return value",bad_return,"gen_server crash terminated with reason: bad return value: bleh"),
  281. TestBody("bad return value with string",bad_return_string,"gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}"),
  282. TestBody("bad return uncaught throw",throw,"gen_server crash terminated with reason: bad return value: a_ball"),
  283. TestBody("case clause",case_clause,"gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3"),
  284. TestBody("case clause string",case_clause_string,"gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3"),
  285. TestBody("function clause",function_clause,"gen_server crash terminated with reason: no function clause matching crash:function({})"),
  286. TestBody("if clause",if_clause,"gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3"),
  287. TestBody("try clause",try_clause,"gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3"),
  288. TestBody("undefined function",undef,"gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3"),
  289. TestBody("bad math",badarith,"gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3"),
  290. TestBody("bad match",badmatch,"gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3"),
  291. TestBody("bad arity",badarity,"gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3"),
  292. TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"),
  293. TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"),
  294. TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"),
  295. TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"),
  296. TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3")
  297. ]
  298. }.
  299. error_logger_redirect_test_() ->
  300. {foreach,
  301. fun() ->
  302. error_logger:tty(false),
  303. application:load(lager),
  304. application:set_env(lager, error_logger_redirect, true),
  305. application:set_env(lager, handlers, [{?MODULE, info}]),
  306. application:start(lager),
  307. lager:log(error, self(), "flush flush"),
  308. timer:sleep(100),
  309. gen_event:call(lager_event, ?MODULE, flush)
  310. end,
  311. fun(_) ->
  312. application:stop(lager),
  313. error_logger:tty(true)
  314. end,
  315. [
  316. {"error reports are printed",
  317. fun() ->
  318. sync_error_logger:error_report([{this, is}, a, {silly, format}]),
  319. _ = gen_event:which_handlers(error_logger),
  320. {Level, _, Msg,Metadata} = pop(),
  321. ?assertEqual(lager_util:level_to_num(error),Level),
  322. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  323. Expected = "this: is, a, silly: format",
  324. ?assertEqual(Expected, lists:flatten(Msg))
  325. end
  326. },
  327. {"string error reports are printed",
  328. fun() ->
  329. sync_error_logger:error_report("this is less silly"),
  330. _ = gen_event:which_handlers(error_logger),
  331. {Level, _, Msg,Metadata} = pop(),
  332. ?assertEqual(lager_util:level_to_num(error),Level),
  333. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  334. Expected = "this is less silly",
  335. ?assertEqual(Expected, lists:flatten(Msg))
  336. end
  337. },
  338. {"error messages are printed",
  339. fun() ->
  340. sync_error_logger:error_msg("doom, doom has come upon you all"),
  341. _ = gen_event:which_handlers(error_logger),
  342. {Level, _, Msg,Metadata} = pop(),
  343. ?assertEqual(lager_util:level_to_num(error),Level),
  344. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  345. Expected = "doom, doom has come upon you all",
  346. ?assertEqual(Expected, lists:flatten(Msg))
  347. end
  348. },
  349. {"error messages are truncated at 4096 characters",
  350. fun() ->
  351. sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
  352. _ = gen_event:which_handlers(error_logger),
  353. {_, _, Msg,_Metadata} = pop(),
  354. ?assert(length(lists:flatten(Msg)) < 5100)
  355. end
  356. },
  357. {"info reports are printed",
  358. fun() ->
  359. sync_error_logger:info_report([{this, is}, a, {silly, format}]),
  360. _ = gen_event:which_handlers(error_logger),
  361. {Level, _, Msg,Metadata} = pop(),
  362. ?assertEqual(lager_util:level_to_num(info),Level),
  363. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  364. Expected = "this: is, a, silly: format",
  365. ?assertEqual(Expected, lists:flatten(Msg))
  366. end
  367. },
  368. {"info reports are truncated at 4096 characters",
  369. fun() ->
  370. sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]),
  371. _ = gen_event:which_handlers(error_logger),
  372. {Level, _, Msg,Metadata} = pop(),
  373. ?assertEqual(lager_util:level_to_num(info),Level),
  374. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  375. ?assert(length(lists:flatten(Msg)) < 5000)
  376. end
  377. },
  378. {"single term info reports are printed",
  379. fun() ->
  380. sync_error_logger:info_report({foolish, bees}),
  381. _ = gen_event:which_handlers(error_logger),
  382. {Level, _, Msg,Metadata} = pop(),
  383. ?assertEqual(lager_util:level_to_num(info),Level),
  384. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  385. ?assertEqual("{foolish,bees}", lists:flatten(Msg))
  386. end
  387. },
  388. {"single term error reports are printed",
  389. fun() ->
  390. sync_error_logger:error_report({foolish, bees}),
  391. _ = gen_event:which_handlers(error_logger),
  392. {Level, _, Msg,Metadata} = pop(),
  393. ?assertEqual(lager_util:level_to_num(error),Level),
  394. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  395. ?assertEqual("{foolish,bees}", lists:flatten(Msg))
  396. end
  397. },
  398. {"string info reports are printed",
  399. fun() ->
  400. sync_error_logger:info_report("this is less silly"),
  401. _ = gen_event:which_handlers(error_logger),
  402. {Level, _, Msg,Metadata} = pop(),
  403. ?assertEqual(lager_util:level_to_num(info),Level),
  404. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  405. ?assertEqual("this is less silly", lists:flatten(Msg))
  406. end
  407. },
  408. {"string info reports are truncated at 4096 characters",
  409. fun() ->
  410. sync_error_logger:info_report(string:copies("this is less silly", 1000)),
  411. _ = gen_event:which_handlers(error_logger),
  412. {Level, _, Msg,Metadata} = pop(),
  413. ?assertEqual(lager_util:level_to_num(info),Level),
  414. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  415. ?assert(length(lists:flatten(Msg)) < 5100)
  416. end
  417. },
  418. {"strings in a mixed report are printed as strings",
  419. fun() ->
  420. sync_error_logger:info_report(["this is less silly", {than, "this"}]),
  421. _ = gen_event:which_handlers(error_logger),
  422. {Level, _, Msg,Metadata} = pop(),
  423. ?assertEqual(lager_util:level_to_num(info),Level),
  424. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  425. ?assertEqual("\"this is less silly\", than: \"this\"", lists:flatten(Msg))
  426. end
  427. },
  428. {"info messages are printed",
  429. fun() ->
  430. sync_error_logger:info_msg("doom, doom has come upon you all"),
  431. _ = gen_event:which_handlers(error_logger),
  432. {Level, _, Msg,Metadata} = pop(),
  433. ?assertEqual(lager_util:level_to_num(info),Level),
  434. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  435. ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg))
  436. end
  437. },
  438. {"info messages are truncated at 4096 characters",
  439. fun() ->
  440. sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
  441. _ = gen_event:which_handlers(error_logger),
  442. {Level, _, Msg,Metadata} = pop(),
  443. ?assertEqual(lager_util:level_to_num(info),Level),
  444. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  445. ?assert(length(lists:flatten(Msg)) < 5100)
  446. end
  447. },
  448. {"warning messages are printed at the correct level",
  449. fun() ->
  450. sync_error_logger:warning_msg("doom, doom has come upon you all"),
  451. Map = error_logger:warning_map(),
  452. _ = gen_event:which_handlers(error_logger),
  453. {Level, _, Msg,Metadata} = pop(),
  454. ?assertEqual(lager_util:level_to_num(Map),Level),
  455. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  456. ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg))
  457. end
  458. },
  459. {"warning reports are printed at the correct level",
  460. fun() ->
  461. sync_error_logger:warning_report([{i, like}, pie]),
  462. Map = error_logger:warning_map(),
  463. _ = gen_event:which_handlers(error_logger),
  464. {Level, _, Msg,Metadata} = pop(),
  465. ?assertEqual(lager_util:level_to_num(Map),Level),
  466. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  467. ?assertEqual("i: like, pie", lists:flatten(Msg))
  468. end
  469. },
  470. {"single term warning reports are printed at the correct level",
  471. fun() ->
  472. sync_error_logger:warning_report({foolish, bees}),
  473. Map = error_logger:warning_map(),
  474. _ = gen_event:which_handlers(error_logger),
  475. {Level, _, Msg,Metadata} = pop(),
  476. ?assertEqual(lager_util:level_to_num(Map),Level),
  477. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  478. ?assertEqual("{foolish,bees}", lists:flatten(Msg))
  479. end
  480. },
  481. {"application stop reports",
  482. fun() ->
  483. sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]),
  484. _ = gen_event:which_handlers(error_logger),
  485. {Level, _, Msg,Metadata} = pop(),
  486. ?assertEqual(lager_util:level_to_num(info),Level),
  487. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  488. ?assertEqual("Application foo exited with reason: quittin_time", lists:flatten(Msg))
  489. end
  490. },
  491. {"supervisor reports",
  492. fun() ->
  493. sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
  494. _ = gen_event:which_handlers(error_logger),
  495. {Level, _, Msg,Metadata} = pop(),
  496. ?assertEqual(lager_util:level_to_num(error),Level),
  497. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  498. ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", lists:flatten(Msg))
  499. end
  500. },
  501. {"supervisor reports with real error",
  502. fun() ->
  503. sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, {function_clause,[{crash,handle_info,[foo]}]}}, {supervisor, {local, steve}}]),
  504. _ = gen_event:which_handlers(error_logger),
  505. {Level, _, Msg,Metadata} = pop(),
  506. ?assertEqual(lager_util:level_to_num(error),Level),
  507. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  508. ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", lists:flatten(Msg))
  509. end
  510. },
  511. {"supervisor_bridge reports",
  512. fun() ->
  513. sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
  514. _ = gen_event:which_handlers(error_logger),
  515. {Level, _, Msg,Metadata} = pop(),
  516. ?assertEqual(lager_util:level_to_num(error),Level),
  517. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  518. ?assertEqual("Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", lists:flatten(Msg))
  519. end
  520. },
  521. {"application progress report",
  522. fun() ->
  523. sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]),
  524. _ = gen_event:which_handlers(error_logger),
  525. {Level, _, Msg,Metadata} = pop(),
  526. ?assertEqual(lager_util:level_to_num(info),Level),
  527. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  528. Expected = lists:flatten(io_lib:format("Application foo started on node ~w", [node()])),
  529. ?assertEqual(Expected, lists:flatten(Msg))
  530. end
  531. },
  532. {"supervisor progress report",
  533. fun() ->
  534. lager:set_loglevel(?MODULE, debug),
  535. sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]),
  536. _ = gen_event:which_handlers(error_logger),
  537. {Level, _, Msg,Metadata} = pop(),
  538. ?assertEqual(lager_util:level_to_num(debug),Level),
  539. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  540. ?assertEqual("Supervisor foo started foo:bar/1 at pid baz", lists:flatten(Msg))
  541. end
  542. },
  543. {"crash report for emfile",
  544. fun() ->
  545. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, emfile, [{stack, trace, 1}]}}], []]),
  546. _ = gen_event:which_handlers(error_logger),
  547. {Level, _, Msg,Metadata} = pop(),
  548. ?assertEqual(lager_util:level_to_num(error),Level),
  549. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  550. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self()])),
  551. ?assertEqual(Expected, lists:flatten(Msg))
  552. end
  553. },
  554. {"crash report for system process limit",
  555. fun() ->
  556. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn, 1}]}}], []]),
  557. _ = gen_event:which_handlers(error_logger),
  558. {Level, _, Msg,Metadata} = pop(),
  559. ?assertEqual(lager_util:level_to_num(error),Level),
  560. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  561. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])),
  562. ?assertEqual(Expected, lists:flatten(Msg))
  563. end
  564. },
  565. {"crash report for system process limit2",
  566. fun() ->
  567. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn_opt, 1}]}}], []]),
  568. _ = gen_event:which_handlers(error_logger),
  569. {Level, _, Msg,Metadata} = pop(),
  570. ?assertEqual(lager_util:level_to_num(error),Level),
  571. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  572. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])),
  573. ?assertEqual(Expected, lists:flatten(Msg))
  574. end
  575. },
  576. {"crash report for system port limit",
  577. fun() ->
  578. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, open_port, 1}]}}], []]),
  579. _ = gen_event:which_handlers(error_logger),
  580. {Level, _, Msg,Metadata} = pop(),
  581. ?assertEqual(lager_util:level_to_num(error),Level),
  582. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  583. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self()])),
  584. ?assertEqual(Expected, lists:flatten(Msg))
  585. end
  586. },
  587. {"crash report for system port limit",
  588. fun() ->
  589. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, list_to_atom, 1}]}}], []]),
  590. _ = gen_event:which_handlers(error_logger),
  591. {Level, _, Msg,Metadata} = pop(),
  592. ?assertEqual(lager_util:level_to_num(error),Level),
  593. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  594. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: tried to create an atom larger than 255, or maximum atom count exceeded", [self()])),
  595. ?assertEqual(Expected, lists:flatten(Msg))
  596. end
  597. },
  598. {"crash report for system ets table limit",
  599. fun() ->
  600. sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, test}, {error_info, {error, system_limit, [{ets,new,[segment_offsets,[ordered_set,public]]},{mi_segment,open_write,1},{mi_buffer_converter,handle_cast,2},{gen_server,handle_msg,5},{proc_lib,init_p_do_apply,3}]}}], []]),
  601. _ = gen_event:which_handlers(error_logger),
  602. {Level, _, Msg,Metadata} = pop(),
  603. ?assertEqual(lager_util:level_to_num(error),Level),
  604. ?assertEqual(self(),proplists:get_value(pid,Metadata)),
  605. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [test])),
  606. ?assertEqual(Expected, lists:flatten(Msg))
  607. end
  608. },
  609. {"crash report for unknown system limit should be truncated at 500 characters",
  610. fun() ->
  611. sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, system_limit, [{wtf,boom,[string:copies("aaaa", 4096)]}]}}], []]),
  612. _ = gen_event:which_handlers(error_logger),
  613. {_, _, Msg,_Metadata} = pop(),
  614. ?assert(length(lists:flatten(Msg)) > 550),
  615. ?assert(length(lists:flatten(Msg)) < 600)
  616. end
  617. },
  618. {"crash reports for 'special processes' should be handled right - function_clause",
  619. fun() ->
  620. {ok, Pid} = special_process:start(),
  621. unlink(Pid),
  622. Pid ! function_clause,
  623. timer:sleep(500),
  624. _ = gen_event:which_handlers(error_logger),
  625. {_, _, Msg, _Metadata} = pop(),
  626. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no function clause matching special_process:foo(bar)",
  627. [Pid])),
  628. test_body(Expected, lists:flatten(Msg))
  629. end
  630. },
  631. {"crash reports for 'special processes' should be handled right - case_clause",
  632. fun() ->
  633. {ok, Pid} = special_process:start(),
  634. unlink(Pid),
  635. Pid ! {case_clause, wtf},
  636. timer:sleep(500),
  637. _ = gen_event:which_handlers(error_logger),
  638. {_, _, Msg, _Metadata} = pop(),
  639. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no case clause matching wtf in special_process:loop/0",
  640. [Pid])),
  641. test_body(Expected, lists:flatten(Msg))
  642. end
  643. },
  644. {"crash reports for 'special processes' should be handled right - exit",
  645. fun() ->
  646. {ok, Pid} = special_process:start(),
  647. unlink(Pid),
  648. Pid ! exit,
  649. timer:sleep(500),
  650. _ = gen_event:which_handlers(error_logger),
  651. {_, _, Msg, _Metadata} = pop(),
  652. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours exited with reason: byebye in special_process:loop/0",
  653. [Pid])),
  654. test_body(Expected, lists:flatten(Msg))
  655. end
  656. },
  657. {"crash reports for 'special processes' should be handled right - error",
  658. fun() ->
  659. {ok, Pid} = special_process:start(),
  660. unlink(Pid),
  661. Pid ! error,
  662. timer:sleep(500),
  663. _ = gen_event:which_handlers(error_logger),
  664. {_, _, Msg, _Metadata} = pop(),
  665. Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: mybad in special_process:loop/0",
  666. [Pid])),
  667. test_body(Expected, lists:flatten(Msg))
  668. end
  669. },
  670. {"messages should not be generated if they don't satisfy the threshold",
  671. fun() ->
  672. lager:set_loglevel(?MODULE, error),
  673. sync_error_logger:info_report([hello, world]),
  674. _ = gen_event:which_handlers(error_logger),
  675. ?assertEqual(0, count()),
  676. ?assertEqual(0, count_ignored()),
  677. lager:set_loglevel(?MODULE, info),
  678. sync_error_logger:info_report([hello, world]),
  679. _ = gen_event:which_handlers(error_logger),
  680. ?assertEqual(1, count()),
  681. ?assertEqual(0, count_ignored()),
  682. lager:set_loglevel(?MODULE, error),
  683. lager_mochiglobal:put(loglevel, {?DEBUG, []}),
  684. sync_error_logger:info_report([hello, world]),
  685. _ = gen_event:which_handlers(error_logger),
  686. ?assertEqual(1, count()),
  687. ?assertEqual(1, count_ignored())
  688. end
  689. }
  690. ]
  691. }.
  692. safe_format_test() ->
  693. ?assertEqual("foo bar", lists:flatten(lager:safe_format("~p ~p", [foo, bar], 1024))),
  694. ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))),
  695. ok.
  696. -endif.