diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 2d50165..be6e059 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -520,7 +520,12 @@ filesystem_test_() -> application:set_env(lager, handlers, [{lager_test_backend, info}]), application:set_env(lager, error_logger_redirect, false), application:set_env(lager, async_threshold, undefined), - lager:start() + lager:start(), + %% race condition where lager logs its own start up + %% makes several tests fail. See test/lager_test_backend + %% around line 800 for more information. + timer:sleep(5), + lager_test_backend:flush() end, fun(_) -> file:delete("test.log"), @@ -866,7 +871,9 @@ formatting_test_() -> application:load(lager), application:set_env(lager, handlers, [{lager_test_backend, info}]), application:set_env(lager, error_logger_redirect, false), - lager:start() + lager:start(), + %% same race condition issue + timer:sleep(5) end, fun(_) -> file:delete("test.log"), diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index df92584..e1ea43f 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -150,11 +150,10 @@ reinstall_on_initial_failure_test_() -> application:unset_env(lager, crash_log), lager:start(), try - ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :"++_, lists:flatten(Message)), - ?assertEqual(0, lager_test_backend:count()), timer:sleep(6000), + lager_test_backend:flush(), ?assertEqual(0, lager_test_backend:count()), ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(lager_event))) after @@ -177,10 +176,10 @@ reinstall_on_runtime_failure_test_() -> application:unset_env(lager, crash_log), lager:start(), try - ?assertEqual(0, lager_test_backend:count()), ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(lager_event))), timer:sleep(6000), - ?assertEqual(2, lager_test_backend:count()), + _ = lager_test_backend:pop(), %% throw away application start up message + _ = lager_test_backend:pop(), %% throw away gen_event crash message {_Severity, _Date, Msg, _Metadata} = lager_test_backend:pop(), ?assertEqual("Lager event handler lager_crash_backend exited with reason crash", lists:flatten(Msg)), {_Severity2, _Date2, Msg2, _Metadata2} = lager_test_backend:pop(), diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index d8af4d4..c97dbb8 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -796,6 +796,18 @@ setup() -> application:set_env(lager, error_logger_redirect, false), application:unset_env(lager, traces), lager:start(), + %% There is a race condition between the application start up, lager logging its own + %% start up condition and several tests that count messages or parse the output of + %% tests. When the lager start up message wins the race, it causes these tests + %% which parse output or count message arrivals to fail. + %% + %% We introduce a sleep here to allow `flush' to arrive *after* the start up + %% message has been received and processed. + %% + %% This race condition was first exposed during the work on + %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager + %% manager killer PR. + timer:sleep(5), gen_event:call(lager_event, ?MODULE, flush). cleanup(_) ->