Make tests less dependant on timer:sleeps to function correctly

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(_) ->

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

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(),

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

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.