From 4dfee06cd92728e4a801e8c48b624164432f6c15 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Tue, 16 Aug 2011 22:59:46 -0400 Subject: [PATCH 1/2] Make tests less dependant on timer:sleeps to function correctly --- src/error_logger_lager_h.erl | 2 +- src/lager_crash_log.erl | 51 +++++++------- src/lager_file_backend.erl | 1 - test/lager_test_backend.erl | 133 +++++++++++++++++------------------ test/sync_error_logger.erl | 89 +++++++++++++++++++++++ 5 files changed, 180 insertions(+), 96 deletions(-) create mode 100644 test/sync_error_logger.erl diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 30fa1bb..5e475a6 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -47,7 +47,7 @@ end). -define(CRASH_LOG(Event), - gen_server:cast(lager_crash_log, {log, Event})). + catch(gen_server:call(lager_crash_log, {log, Event}))). -spec init(any()) -> {ok, {}}. init(_) -> diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 430a046..50ae246 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -80,11 +80,7 @@ init([Filename, MaxBytes, Size, Date, Count]) -> end. %% @private -handle_call(_Call, _From, State) -> - {reply, ok, State}. - -%% @private -handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, +handle_call({log, Event}, _From, #state{name=Name, fd=FD, inode=Inode, flap=Flap, fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count} = State) -> %% borrowed from riak_err {ReportStr, Pid, MsgStr, _ErrorP} = case Event of @@ -98,7 +94,7 @@ handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, {ignore, ignore, ignore, false} end, if ReportStr == ignore -> - {noreply, State}; + {reply, ok, State}; true -> case lager_util:ensure_logfile(Name, FD, Inode, false) of {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> @@ -114,23 +110,27 @@ handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, {error, Reason} when Flap == false -> ?INT_LOG(error, "Failed to write log message to file ~s: ~s", [Name, file:format_error(Reason)]), - {noreply, State#state{fd=NewFD, inode=NewInode, flap=true}}; + {reply, ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; ok -> - {noreply, State#state{fd=NewFD, inode=NewInode, flap=false}}; + {reply, ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; _ -> - {noreply, State#state{fd=NewFD, inode=NewInode}} + {reply, ok, State#state{fd=NewFD, inode=NewInode}} end; {error, Reason} -> case Flap of true -> - {noreply, State}; + {reply, ok, State}; _ -> ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s", [Name, file:format_error(Reason)]), - {noreply, State#state{flap=true}} + {reply, ok, State#state{flap=true}} end end end; +handle_call(_Call, _From, State) -> + {reply, ok, State}. + +%% @private handle_cast(_Request, State) -> {noreply, State}. @@ -250,8 +250,8 @@ filesystem_test_() -> {"under normal circumstances, file should be opened", fun() -> {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - error_logger:error_msg("Test message\n"), - timer:sleep(100), + _ = gen_event:which_handlers(error_logger), + sync_error_logger:error_msg("Test message\n"), {ok, Bin} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) end @@ -270,18 +270,17 @@ filesystem_test_() -> fun() -> {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), ?assertEqual(0, lager_test_backend:count()), - error_logger:error_msg("Test message\n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), ?assertEqual(1, lager_test_backend:count()), file:delete("crash_test.log"), file:write_file("crash_test.log", ""), {ok, FInfo} = file:read_file_info("crash_test.log"), file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), - error_logger:error_msg("Test message\n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), - lager_test_backend:pop(), {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), ?assertEqual("Failed to reopen crash log crash_test.log with error: permission denied", lists:flatten(Message)) end @@ -296,8 +295,8 @@ filesystem_test_() -> {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)), file:write_file_info("crash_test.log", FInfo#file_info{mode = OldPerms}), - error_logger:error_msg("Test message~n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message~n"), + _ = gen_event:which_handlers(error_logger), {ok, Bin} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) end @@ -306,19 +305,19 @@ filesystem_test_() -> fun() -> {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), ?assertEqual(0, lager_test_backend:count()), - error_logger:error_msg("Test message~n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message~n"), + _ = gen_event:which_handlers(error_logger), {ok, Bin} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), file:delete("crash_test.log"), file:write_file("crash_test.log", ""), - error_logger:error_msg("Test message1~n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message1~n"), + _ = gen_event:which_handlers(error_logger), {ok, Bin1} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), file:rename("crash_test.log", "crash_test.log.0"), - error_logger:error_msg("Test message2~n"), - timer:sleep(100), + sync_error_logger:error_msg("Test message2~n"), + _ = gen_event:which_handlers(error_logger), {ok, Bin2} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) end diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 2562039..5debe3f 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -302,7 +302,6 @@ filesystem_test_() -> {ok, FInfo} = file:read_file_info("test.log"), file:write_file_info("test.log", FInfo#file_info{mode = 0}), lager:log(error, self(), "Test message"), - timer:sleep(100), ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), lager_test_backend:pop(), diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index c216d44..445f5ce 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -194,12 +194,8 @@ cleanup(_) -> crash(Type) -> spawn(fun() -> gen_server:call(crash, Type) end), - timer:sleep(100). - -custom_sleep(MSec) -> - timer:sleep(MSec), - [_|_] = gen_event:which_handlers(error_logger), - [_|_] = gen_event:which_handlers(lager_event), + timer:sleep(100), + _ = gen_event:which_handlers(error_logger), ok. error_logger_redirect_crash_test_() -> @@ -375,6 +371,7 @@ error_logger_redirect_test_() -> application:set_env(lager, error_logger_redirect, true), application:set_env(lager, handlers, [{?MODULE, info}]), application:start(lager), + lager:log(error, self(), "flush flush"), timer:sleep(100), gen_event:call(lager_event, ?MODULE, flush) end, @@ -386,8 +383,8 @@ error_logger_redirect_test_() -> [ {"error reports are printed", fun() -> - error_logger:error_report([{this, is}, a, {silly, format}]), - custom_sleep(100), + sync_error_logger:error_report([{this, is}, a, {silly, format}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[error] ~w this: is, a, silly: format", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -395,8 +392,8 @@ error_logger_redirect_test_() -> }, {"string error reports are printed", fun() -> - error_logger:error_report("this is less silly"), - custom_sleep(100), + sync_error_logger:error_report("this is less silly"), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[error] ~w this is less silly", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -404,8 +401,8 @@ error_logger_redirect_test_() -> }, {"error messages are printed", fun() -> - error_logger:error_msg("doom, doom has come upon you all"), - custom_sleep(100), + sync_error_logger:error_msg("doom, doom has come upon you all"), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[error] ~w doom, doom has come upon you all", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -413,16 +410,16 @@ error_logger_redirect_test_() -> }, {"error messages are truncated at 4096 characters", fun() -> - error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), - custom_sleep(1000), + sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), ?assert(length(lists:flatten(Msg)) < 5100) end }, {"info reports are printed", fun() -> - error_logger:info_report([{this, is}, a, {silly, format}]), - custom_sleep(100), + sync_error_logger:info_report([{this, is}, a, {silly, format}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w this: is, a, silly: format", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -430,16 +427,16 @@ error_logger_redirect_test_() -> }, {"info reports are truncated at 4096 characters", fun() -> - error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]), - custom_sleep(1000), + sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), ?assert(length(lists:flatten(Msg)) < 5000) end }, {"single term info reports are printed", fun() -> - error_logger:info_report({foolish, bees}), - custom_sleep(100), + sync_error_logger:info_report({foolish, bees}), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w {foolish,bees}", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -447,8 +444,8 @@ error_logger_redirect_test_() -> }, {"single term error reports are printed", fun() -> - error_logger:error_report({foolish, bees}), - custom_sleep(100), + sync_error_logger:error_report({foolish, bees}), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[error] ~w {foolish,bees}", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -456,8 +453,8 @@ error_logger_redirect_test_() -> }, {"string info reports are printed", fun() -> - error_logger:info_report("this is less silly"), - custom_sleep(100), + sync_error_logger:info_report("this is less silly"), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w this is less silly", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -465,8 +462,8 @@ error_logger_redirect_test_() -> }, {"string info reports are truncated at 4096 characters", fun() -> - error_logger:info_report(string:copies("this is less silly", 1000)), - custom_sleep(1000), + sync_error_logger:info_report(string:copies("this is less silly", 1000)), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), ?assert(length(lists:flatten(Msg)) < 5100) end @@ -474,8 +471,8 @@ error_logger_redirect_test_() -> {"info messages are printed", fun() -> - error_logger:info_msg("doom, doom has come upon you all"), - custom_sleep(100), + sync_error_logger:info_msg("doom, doom has come upon you all"), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w doom, doom has come upon you all", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -483,8 +480,8 @@ error_logger_redirect_test_() -> }, {"info messages are truncated at 4096 characters", fun() -> - error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), - custom_sleep(1000), + sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), ?assert(length(lists:flatten(Msg)) < 5100) end @@ -492,9 +489,9 @@ error_logger_redirect_test_() -> {"warning messages are printed at the correct level", fun() -> - error_logger:warning_msg("doom, doom has come upon you all"), + sync_error_logger:warning_msg("doom, doom has come upon you all"), Map = error_logger:warning_map(), - custom_sleep(100), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[~w] ~w doom, doom has come upon you all", [Map, self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -502,9 +499,9 @@ error_logger_redirect_test_() -> }, {"warning reports are printed at the correct level", fun() -> - error_logger:warning_report([{i, like}, pie]), + sync_error_logger:warning_report([{i, like}, pie]), Map = error_logger:warning_map(), - custom_sleep(100), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[~w] ~w i: like, pie", [Map, self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -512,9 +509,9 @@ error_logger_redirect_test_() -> }, {"single term warning reports are printed at the correct level", fun() -> - error_logger:warning_report({foolish, bees}), + sync_error_logger:warning_report({foolish, bees}), Map = error_logger:warning_map(), - custom_sleep(100), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[~w] ~w {foolish,bees}", [Map, self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -522,8 +519,8 @@ error_logger_redirect_test_() -> }, {"application stop reports", fun() -> - error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]), - custom_sleep(100), + sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w Application foo exited with reason: quittin_time", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -531,8 +528,8 @@ error_logger_redirect_test_() -> }, {"supervisor reports", fun() -> - error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), - custom_sleep(100), + sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -540,8 +537,8 @@ error_logger_redirect_test_() -> }, {"supervisor reports with real error", fun() -> - 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}}]), - custom_sleep(100), + 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}}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -550,8 +547,8 @@ error_logger_redirect_test_() -> {"supervisor_bridge reports", fun() -> - error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), - custom_sleep(100), + sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -559,8 +556,8 @@ error_logger_redirect_test_() -> }, {"application progress report", fun() -> - error_logger:info_report(progress, [{application, foo}, {started_at, node()}]), - custom_sleep(100), + sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[info] ~w Application foo started on node ~w", [self(), node()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -569,8 +566,8 @@ error_logger_redirect_test_() -> {"supervisor progress report", fun() -> lager:set_loglevel(?MODULE, debug), - error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]), - custom_sleep(100), + sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), Expected = lists:flatten(io_lib:format("[debug] ~w Supervisor foo started foo:bar/1 at pid baz", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -578,8 +575,8 @@ error_logger_redirect_test_() -> }, {"crash report for emfile", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {emfile, [{stack, trace, 1}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {emfile, [{stack, trace, 1}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -587,8 +584,8 @@ error_logger_redirect_test_() -> }, {"crash report for system process limit", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn, 1}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn, 1}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -596,8 +593,8 @@ error_logger_redirect_test_() -> }, {"crash report for system process limit2", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn_opt, 1}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn_opt, 1}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -605,8 +602,8 @@ error_logger_redirect_test_() -> }, {"crash report for system port limit", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, open_port, 1}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, open_port, 1}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -614,8 +611,8 @@ error_logger_redirect_test_() -> }, {"crash report for system port limit", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, list_to_atom, 1}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, list_to_atom, 1}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -623,8 +620,8 @@ error_logger_redirect_test_() -> }, {"crash report for system ets table limit", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {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}]}, []}}], []]), - custom_sleep(100), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {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}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), 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(), self()])), ?assertEqual(Expected, lists:flatten(Msg)) @@ -632,8 +629,8 @@ error_logger_redirect_test_() -> }, {"crash report for unknown system limit should be truncated at 500 characters", fun() -> - error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit,[{wtf,boom,[string:copies("aaaa", 4096)]}]}, []}}], []]), - custom_sleep(1000), + sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit,[{wtf,boom,[string:copies("aaaa", 4096)]}]}, []}}], []]), + _ = gen_event:which_handlers(error_logger), {_, _, Msg} = pop(), ?assert(length(lists:flatten(Msg)) > 500), ?assert(length(lists:flatten(Msg)) < 700) @@ -642,19 +639,19 @@ error_logger_redirect_test_() -> {"messages should not be generated if they don't satisfy the threshold", fun() -> lager:set_loglevel(?MODULE, error), - error_logger:info_report([hello, world]), - custom_sleep(100), + sync_error_logger:info_report([hello, world]), + _ = gen_event:which_handlers(error_logger), ?assertEqual(0, count()), ?assertEqual(0, count_ignored()), lager:set_loglevel(?MODULE, info), - error_logger:info_report([hello, world]), - custom_sleep(100), + sync_error_logger:info_report([hello, world]), + _ = gen_event:which_handlers(error_logger), ?assertEqual(1, count()), ?assertEqual(0, count_ignored()), lager:set_loglevel(?MODULE, error), lager_mochiglobal:put(loglevel, ?DEBUG), - error_logger:info_report([hello, world]), - custom_sleep(100), + sync_error_logger:info_report([hello, world]), + _ = gen_event:which_handlers(error_logger), ?assertEqual(1, count()), ?assertEqual(1, count_ignored()) end diff --git a/test/sync_error_logger.erl b/test/sync_error_logger.erl new file mode 100644 index 0000000..078000f --- /dev/null +++ b/test/sync_error_logger.erl @@ -0,0 +1,89 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 1996-2009. All Rights Reserved. +%% +%% The contents of this file are subject to the Erlang Public License, +%% Version 1.1, (the "License"); you may not use this file except in +%% compliance with the License. You should have received a copy of the +%% Erlang Public License along with this software. If not, it can be +%% retrieved online at http://www.erlang.org/. +%% +%% Software distributed under the License is distributed on an "AS IS" +%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See +%% the License for the specific language governing rights and limitations +%% under the License. +%% +%% %CopyrightEnd% +%% +-module(sync_error_logger). + +%% The error_logger API, but synchronous! +%% This is helpful for tests, otherwise you need lots of nasty timer:sleep. +%% Additionally, the warning map can be set on a per-process level, for +%% convienience, via the process dictionary value `warning_map'. + +-export([ + info_msg/1, info_msg/2, + warning_msg/1, warning_msg/2, + error_msg/1,error_msg/2 + ]). + +-export([ + info_report/1, info_report/2, + warning_report/1, warning_report/2, + error_report/1, error_report/2 + ]). + +info_msg(Format) -> + info_msg(Format, []). + +info_msg(Format, Args) -> + gen_event:sync_notify(error_logger, {info_msg, group_leader(), {self(), Format, Args}}). + +warning_msg(Format) -> + warning_msg(Format, []). + +warning_msg(Format, Args) -> + gen_event:sync_notify(error_logger, {warning_msg_tag(), group_leader(), {self(), Format, Args}}). + +error_msg(Format) -> + error_msg(Format, []). + +error_msg(Format, Args) -> + gen_event:sync_notify(error_logger, {error, group_leader(), {self(), Format, Args}}). + +info_report(Report) -> + info_report(std_info, Report). + +info_report(Type, Report) -> + gen_event:sync_notify(error_logger, {info_report, group_leader(), {self(), Type, Report}}). + +warning_report(Report) -> + warning_report(std_warning, Report). + +warning_report(Type, Report) -> + {Tag, NType} = warning_report_tag(Type), + gen_event:sync_notify(error_logger, {Tag, group_leader(), {self(), NType, Report}}). + +error_report(Report) -> + error_report(std_error, Report). + +error_report(Type, Report) -> + gen_event:sync_notify(error_logger, {error_report, group_leader(), {self(), Type, Report}}). + +warning_msg_tag() -> + case get(warning_map) of + warning -> warning_msg; + info -> info_msg; + _ -> error + end. + +warning_report_tag(Type) -> + case {get(warning_map), Type == std_warning} of + {warning, _} -> {warning_report, Type}; + {info, true} -> {info_report, std_info}; + {info, false} -> {info_report, Type}; + {_, true} -> {error_report, std_error}; + {_, false} -> {error_report, Type} + end. From b61718ff800581ab9f135fadf14f7c0d9f076aed Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Wed, 7 Sep 2011 16:07:26 -0400 Subject: [PATCH 2/2] Make the call to the crash log synchronous only when testing --- src/error_logger_lager_h.erl | 6 +++ src/lager_crash_log.erl | 102 +++++++++++++++++++---------------- 2 files changed, 61 insertions(+), 47 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 5e475a6..4c143d7 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -46,8 +46,14 @@ _ -> ok end). +-ifdef(TEST). +%% Make CRASH synchronous when testing, to avoid timing headaches -define(CRASH_LOG(Event), catch(gen_server:call(lager_crash_log, {log, Event}))). +-else. +-define(CRASH_LOG(Event), + gen_server:cast(lager_crash_log, {log, Event})). +-endif. -spec init(any()) -> {ok, {}}. init(_) -> diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 50ae246..75b2974 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -80,57 +80,16 @@ init([Filename, MaxBytes, Size, Date, Count]) -> end. %% @private -handle_call({log, Event}, _From, #state{name=Name, fd=FD, inode=Inode, flap=Flap, - fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count} = State) -> - %% borrowed from riak_err - {ReportStr, Pid, MsgStr, _ErrorP} = case Event of - {error, _GL, {Pid1, Fmt, Args}} -> - {"ERROR REPORT", Pid1, limited_fmt(Fmt, Args, FmtMaxBytes), true}; - {error_report, _GL, {Pid1, std_error, Rep}} -> - {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes), true}; - {error_report, _GL, Other} -> - perhaps_a_sasl_report(error_report, Other, FmtMaxBytes); - _ -> - {ignore, ignore, ignore, false} - end, - if ReportStr == ignore -> - {reply, ok, State}; - true -> - case lager_util:ensure_logfile(Name, FD, Inode, false) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> - lager_util:rotate_logfile(Name, Count), - handle_cast({log, Event}, State); - {ok, {NewFD, NewInode, _Size}} -> - {Date, TS} = lager_util:format_time( - lager_stdlib:maybe_utc(erlang:localtime())), - Time = [Date, " ", TS," =", ReportStr, "====\n"], - NodeSuffix = other_node_suffix(Pid), - Msg = io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix]), - case file:write(NewFD, Msg) of - {error, Reason} when Flap == false -> - ?INT_LOG(error, "Failed to write log message to file ~s: ~s", - [Name, file:format_error(Reason)]), - {reply, ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; - ok -> - {reply, ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; - _ -> - {reply, ok, State#state{fd=NewFD, inode=NewInode}} - end; - {error, Reason} -> - case Flap of - true -> - {reply, ok, State}; - _ -> - ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s", - [Name, file:format_error(Reason)]), - {reply, ok, State#state{flap=true}} - end - end - end; +handle_call({log, _} = Log, _From, State) -> + {Reply, NewState} = do_log(Log, State), + {reply, Reply, NewState}; handle_call(_Call, _From, State) -> {reply, ok, State}. %% @private +handle_cast({log, _} = Log, State) -> + {_, NewState} = do_log(Log, State), + {noreply, NewState}; handle_cast(_Request, State) -> {noreply, State}. @@ -221,6 +180,55 @@ sasl_limited_str(progress, Report, FmtMaxBytes) -> sasl_limited_str(crash_report, Report, FmtMaxBytes) -> lager_stdlib:proc_lib_format(Report, FmtMaxBytes). +do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, + fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count} = State) -> + %% borrowed from riak_err + {ReportStr, Pid, MsgStr, _ErrorP} = case Event of + {error, _GL, {Pid1, Fmt, Args}} -> + {"ERROR REPORT", Pid1, limited_fmt(Fmt, Args, FmtMaxBytes), true}; + {error_report, _GL, {Pid1, std_error, Rep}} -> + {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes), true}; + {error_report, _GL, Other} -> + perhaps_a_sasl_report(error_report, Other, FmtMaxBytes); + _ -> + {ignore, ignore, ignore, false} + end, + if ReportStr == ignore -> + {ok, State}; + true -> + case lager_util:ensure_logfile(Name, FD, Inode, false) of + {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + lager_util:rotate_logfile(Name, Count), + handle_cast({log, Event}, State); + {ok, {NewFD, NewInode, _Size}} -> + {Date, TS} = lager_util:format_time( + lager_stdlib:maybe_utc(erlang:localtime())), + Time = [Date, " ", TS," =", ReportStr, "====\n"], + NodeSuffix = other_node_suffix(Pid), + Msg = io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix]), + case file:write(NewFD, Msg) of + {error, Reason} when Flap == false -> + ?INT_LOG(error, "Failed to write log message to file ~s: ~s", + [Name, file:format_error(Reason)]), + {ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; + ok -> + {ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; + _ -> + {ok, State#state{fd=NewFD, inode=NewInode}} + end; + {error, Reason} -> + case Flap of + true -> + {ok, State}; + _ -> + ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s", + [Name, file:format_error(Reason)]), + {ok, State#state{flap=true}} + end + end + end. + + -ifdef(TEST). filesystem_test_() ->