25개 이상의 토픽을 선택하실 수 없습니다. Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

810 lines
39 KiB

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