You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

735 lines
36 KiB

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