From f03fa288d032ff11b65b71e45743ae3bf30c5f8b Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Mon, 29 Jul 2019 15:01:52 -0700 Subject: [PATCH 01/36] Remove code causing some warnings --- src/error_logger_lager_h.erl | 1 - src/lager_app.erl | 1 - src/lager_default_formatter.erl | 15 +++++++-------- test/compress_pr_record_test.erl | 8 +++++++- test/lager_rotate.erl | 2 -- test/zzzz_gh280_crash.erl | 1 - 6 files changed, 14 insertions(+), 14 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 95d4f93..3a06255 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -58,7 +58,6 @@ end). -ifdef(TEST). --compile(export_all). %% Make CRASH synchronous when testing, to avoid timing headaches -define(CRASH_LOG(Event), catch(gen_server:call(lager_crash_log, {log, Event}))). diff --git a/src/lager_app.erl b/src/lager_app.erl index 70eef45..82c0139 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -23,7 +23,6 @@ -behaviour(application). -include("lager.hrl"). -ifdef(TEST). --compile([export_all]). -include_lib("eunit/include/eunit.hrl"). -endif. -export([start/0, diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl index a74cdc7..147cedf 100644 --- a/src/lager_default_formatter.erl +++ b/src/lager_default_formatter.erl @@ -484,14 +484,13 @@ basic_test_() -> }, {"node formatting basic", begin - [N, F] = format(lager_msg:new("Message", - Now, - info, - [{pid, self()}], - []), - [node, "foo"]), - ?_assertEqual("foo", F), - ?_assertNotEqual(nomatch, re:run(N, <<"@">>)) + [N, "foo"] = format(lager_msg:new("Message", + Now, + info, + [{pid, self()}], + []), + [node, "foo"]), + ?_assertNotMatch(nomatch, re:run(N, <<"@">>)) end } ]. diff --git a/test/compress_pr_record_test.erl b/test/compress_pr_record_test.erl index e3de673..9f62c5b 100644 --- a/test/compress_pr_record_test.erl +++ b/test/compress_pr_record_test.erl @@ -2,7 +2,13 @@ -compile([{parse_transform, lager_transform}]). --record(a, {field1, field2, foo, bar, baz, zyu, zix}). +-record(a, {field1 :: term(), + field2 :: term(), + foo :: term(), + bar :: term(), + baz :: term(), + zyu :: term(), + zix :: term()}). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). diff --git a/test/lager_rotate.erl b/test/lager_rotate.erl index c84a9ff..95077ee 100644 --- a/test/lager_rotate.erl +++ b/test/lager_rotate.erl @@ -20,8 +20,6 @@ -module(lager_rotate). --compile(export_all). - -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). -endif. diff --git a/test/zzzz_gh280_crash.erl b/test/zzzz_gh280_crash.erl index aa85ab2..c384dc6 100644 --- a/test/zzzz_gh280_crash.erl +++ b/test/zzzz_gh280_crash.erl @@ -5,7 +5,6 @@ %% and lager starts up to replace the current handlers with its own. This causes a start up crash because %% OTP error logging modules do not have any notion of a lager-style log level. -module(zzzz_gh280_crash). --compile(export_all). -include_lib("eunit/include/eunit.hrl"). From a4ceb21b38412cda488133b383c49717f3c35075 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Tue, 30 Jul 2019 10:53:11 -0700 Subject: [PATCH 02/36] Fix rotate_file_fail_test on win32 --- src/lager_rotator_default.erl | 22 +++++++++++++++++----- src/lager_util.erl | 13 ++++++++++++- 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 7a18de9..45921e9 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -138,22 +138,33 @@ rotate_file_zero_count_test() -> rotate_file_fail_test() -> TestDir = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), + %% set known permissions on it - os:cmd("chmod -R u+rwx " ++ TestDir), + ok = lager_util:set_dir_permissions("u+rwx", TestDir), + %% write a file file:write_file(TestLog, "hello"), - %% hose up the permissions - os:cmd("chmod -R u-w " ++ TestDir), - ?assertMatch({error, _}, rotate_logfile(TestLog, 10)), + + case os:type() of + {win32, _} -> ok; + _ -> + %% hose up the permissions + ok = lager_util:set_dir_permissions("u-w", TestDir), + ?assertMatch({error, _}, rotate_logfile(TestLog, 10)) + end, + %% check we still only have one file, rotation.log ?assertEqual([TestLog], filelib:wildcard(TestLog++"*")), ?assert(filelib:is_regular(TestLog)), + %% fix the permissions - os:cmd("chmod -R u+w " ++ TestDir), + ok = lager_util:set_dir_permissions("u+w", TestDir), + ?assertMatch(ok, rotate_logfile(TestLog, 10)), ?assert(filelib:is_regular(TestLog ++ ".0")), ?assertEqual(true, filelib:is_regular(TestLog)), ?assertEqual(2, length(filelib:wildcard(TestLog++"*"))), + %% assert the new file is 0 size: case file:read_file_info(TestLog) of {ok, FInfo} -> @@ -161,6 +172,7 @@ rotate_file_fail_test() -> _ -> ?assert(false) end, + %% check that the .0 file now has the contents "hello" ?assertEqual({ok, <<"hello">>}, file:read_file(TestLog++".0")), lager_util:delete_test_dir(TestDir). diff --git a/src/lager_util.erl b/src/lager_util.erl index 372565c..f11dbc8 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -31,7 +31,9 @@ ]). -ifdef(TEST). --export([create_test_dir/0, delete_test_dir/1]). +-export([create_test_dir/0, + delete_test_dir/1, + set_dir_permissions/2]). -include_lib("eunit/include/eunit.hrl"). -endif. @@ -861,4 +863,13 @@ do_delete_test_dir(Dir) -> end, Entries), ?assertEqual(ok, file:del_dir(Dir)). +set_dir_permissions(Perms, Dir) -> + do_set_dir_permissions(os:type(), Perms, Dir). + +do_set_dir_permissions({win32, _}, _Perms, _Dir) -> + ok; +do_set_dir_permissions({unix, _}, Perms, Dir) -> + os:cmd("chmod -R " ++ Perms ++ " " ++ Dir), + ok. + -endif. From 990210faa9b97908d2a07099fd0176385eaffec1 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Tue, 30 Jul 2019 16:57:43 -0700 Subject: [PATCH 03/36] Making progress on getting lager_file_backend tests passing on win32 --- src/lager_file_backend.erl | 187 ++++++++++++++++--------------------- src/lager_util.erl | 68 ++++++++++---- 2 files changed, 132 insertions(+), 123 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index e725312..4781ae0 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -475,7 +475,7 @@ rotation_test_() -> SyncInterval = ?DEFAULT_SYNC_INTERVAL, Rotator = ?DEFAULT_ROTATION_MOD, CheckInterval = 0, %% hard to test delayed mode - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), #state{name=TestLog, level=?DEBUG, sync_on=SyncLevel, @@ -560,11 +560,19 @@ add_secs({Mega, Secs, Micro}, Add) -> filesystem_test_() -> {foreach, fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, false), - application:set_env(lager, async_threshold, undefined), + ok = error_logger:tty(false), + case application:load(lager) of + ok -> ok; + {error,{already_loaded,lager}} -> ok; + Error -> + % TODO how to report EUnit errors? + io:format(standard_error, "ERROR: application:load(lager) returned ~p~n", [Error]), + ?assert(false) + end, + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = application:set_env(lager, async_threshold, undefined), + ok = lager_util:create_test_dir(), lager:start(), %% race condition where lager logs its own start up %% makes several tests fail. See test/lager_test_backend @@ -573,13 +581,14 @@ filesystem_test_() -> lager_test_backend:flush() end, fun(_) -> - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = error_logger:tty(true), + ok = lager_util:delete_test_dir() end, [ {"under normal circumstances, file should be opened", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -588,13 +597,11 @@ filesystem_test_() -> {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"don't choke on unicode", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -604,13 +611,11 @@ filesystem_test_() -> Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, [228,184,173,230,150,135,230,181,139,232,175,149, $\n]], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"don't choke on latin-1", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! @@ -621,13 +626,11 @@ filesystem_test_() -> Pid = pid_to_list(self()), Res = re:split(Bin, " ", [{return, list}, {parts, 5}]), ?assertMatch([_, _, "[error]", Pid, - [76,195,134,195,157,195,142,78,45,195,175,$\n]], Res), - - lager_util:delete_test_dir(TestDir) + [76,195,134,195,157,195,142,78,45,195,175,$\n]], Res) end}, {"file can't be opened on startup triggers an error message", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), ?assertEqual(ok, file:write_file(TestLog, [])), @@ -636,16 +639,14 @@ filesystem_test_() -> gen_event:add_handler(lager_event, lager_file_backend, {TestLog, info, 10*1024*1024, "$D0", 5}), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time,Message,_Metadata} = lager_test_backend:pop(), + {_Level, _Time,Message, _Metadata} = lager_test_backend:pop(), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)), - - lager_util:delete_test_dir(TestDir) + lists:flatten(Message)) end}, {"file that becomes unavailable at runtime should trigger an error message", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -653,24 +654,27 @@ filesystem_test_() -> ?assertEqual(0, lager_test_backend:count()), lager:log(error, self(), "Test message"), ?assertEqual(1, lager_test_backend:count()), - file:delete(TestLog), - file:write_file(TestLog, ""), - {ok, FInfo} = file:read_file_info(TestLog), - file:write_file_info(TestLog, FInfo#file_info{mode = 0}), - lager:log(error, self(), "Test message"), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)), - - lager_util:delete_test_dir(TestDir) + ?assertEqual(ok, file:delete(TestLog)), + case os:type() of + {win32, _} -> + ?assertEqual({error, eacces}, file:write_file(TestLog, "")); + {unix, _} -> + ?assertEqual(ok, file:write_file(TestLog, "")), + {ok, FInfo} = file:read_file_info(TestLog), + file:write_file_info(TestLog, FInfo#file_info{mode = 0}), + lager:log(error, self(), "Test message"), + ?assertEqual(3, lager_test_backend:count()), + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) + end end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), ?assertEqual(ok, file:write_file(TestLog, [])), @@ -680,7 +684,7 @@ filesystem_test_() -> gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog},{check_interval, 0}]), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", lists:flatten(Message)), @@ -689,13 +693,11 @@ filesystem_test_() -> {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"external logfile rotation/deletion should be handled", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -715,13 +717,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message3"), {ok, Bin2} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin2, " ", [{return, list}, {parts, 5}])) end}, {"internal size rotation should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -729,13 +729,11 @@ filesystem_test_() -> [{file, TestLog}, {level, info}, {check_interval, 0}, {size, 10}]), lager:log(error, self(), "Test message1"), lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"internal time rotation should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -745,13 +743,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), whereis(lager_event) ! {rotate, TestLog}, lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"rotation call should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -761,13 +757,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), gen_event:call(lager_event, {lager_file_backend, TestLog}, rotate, infinity), lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"sync_on option should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -777,13 +771,11 @@ filesystem_test_() -> ?assertEqual({ok, <<>>}, file:read_file(TestLog)), lager:log(info, self(), "Test message1"), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"sync_on none option should work (also tests sync_interval)", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -795,13 +787,11 @@ filesystem_test_() -> ?assertEqual({ok, <<>>}, file:read_file(TestLog)), timer:sleep(2000), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"sync_size option should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, @@ -820,13 +810,11 @@ filesystem_test_() -> %% now we've written enough bytes lager:log(error, self(), "Test messageis64bytes"), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"runtime level changes", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, {lager_file_backend, TestLog}, {TestLog, info}), @@ -841,26 +829,22 @@ filesystem_test_() -> lager:log(error, self(), "Test message4"), {ok, Bin2} = file:read_file(TestLog), Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])), - ?assertEqual(Lines2, 3), - - lager_util:delete_test_dir(TestDir) + ?assertEqual(Lines2, 3) end}, {"invalid runtime level changes", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog3 = filename:join(TestDir, "test3.log"), gen_event:add_handler(lager_event, lager_file_backend, [{TestLog, info, 10*1024*1024, "$D0", 5}, {lager_default_formatter}]), gen_event:add_handler(lager_event, lager_file_backend, {TestLog3, info}), - ?assertEqual({error, bad_module}, lager:set_loglevel(lager_file_backend, TestLog, warning)), - - lager_util:delete_test_dir(TestDir) + ?assertEqual({error, bad_module}, lager:set_loglevel(lager_file_backend, TestLog, warning)) end}, {"tracing should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, {TestLog, critical}), @@ -873,13 +857,11 @@ filesystem_test_() -> timer:sleep(1000), {ok, Bin} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"tracing should not duplicate messages", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -901,13 +883,11 @@ filesystem_test_() -> lager:error("Test message"), {ok, Bin3} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin3, " ", [{return, list}, {parts, 5}])) end}, {"tracing to a dedicated file should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), {ok, _} = lager:trace_file(TestLog, [{module, ?MODULE}]), @@ -916,13 +896,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), {ok, Bin3} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin3, " ", [{return, list}, {parts, 5}])) end}, {"tracing to a dedicated file should work even if root_log is set", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), LogName = "foo.log", LogPath = filename:join(TestDir, LogName), @@ -934,13 +912,11 @@ filesystem_test_() -> {ok, Bin3} = file:read_file(LogPath), application:unset_env(lager, log_root), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin3, " ", [{return, list}, {parts, 5}])) end}, {"tracing with options should work", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), TestLog0 = TestLog ++ ".0", @@ -955,13 +931,11 @@ filesystem_test_() -> timer:sleep(2), lager:error("Test message"), timer:sleep(10), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"no silent hwm drops", fun() -> - TestDir = lager_util:create_test_dir(), + TestDir = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {high_water_mark, 5}, {flush_queue, false}, {sync_on, "=warning"}]), @@ -973,15 +947,14 @@ filesystem_test_() -> {ok, Bin} = file:read_file(TestLog), Last = lists:last(re:split(Bin, "\n", [{return, list}, trim])), ?assertMatch([_, _, _, _, "lager_file_backend dropped 10 messages in the last second that exceeded the limit of 5 messages/sec"], - re:split(Last, " ", [{return, list}, {parts, 5}])), - lager_util:delete_test_dir(TestDir) + re:split(Last, " ", [{return, list}, {parts, 5}])) end} ]}. trace_files_test_() -> {foreach, fun() -> - Dir = lager_util:create_test_dir(), + Dir = lager_util:get_test_dir(), Log = filename:join(Dir, "test.log"), Debug = filename:join(Dir, "debug.log"), Events = filename:join(Dir, "events.log"), @@ -1056,7 +1029,7 @@ count_lines_until(Lines, Timeout, File, Last) -> formatting_test_() -> {foreach, fun() -> - Dir = lager_util:create_test_dir(), + Dir = lager_util:get_test_dir(), Log1 = filename:join(Dir, "test.log"), Log2 = filename:join(Dir, "test2.log"), ?assertEqual(ok, file:write_file(Log1, [])), diff --git a/src/lager_util.erl b/src/lager_util.erl index f11dbc8..8d716a8 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -32,7 +32,8 @@ -ifdef(TEST). -export([create_test_dir/0, - delete_test_dir/1, + get_test_dir/0, + delete_test_dir/0, set_dir_permissions/2]). -include_lib("eunit/include/eunit.hrl"). -endif. @@ -828,23 +829,48 @@ sink_name_test_() -> ]. create_test_dir() -> - Dir = filename:join(["/tmp", "lager_test", + {ok, Tmp} = get_temp_dir(), + Dir = filename:join([Tmp, "lager_test", erlang:integer_to_list(erlang:phash2(os:timestamp()))]), ?assertEqual(ok, filelib:ensure_dir(Dir)), - case file:make_dir(Dir) of - ok -> - Dir; - Err -> - ?assertEqual({error, eexist}, Err), - create_test_dir() - end. - -delete_test_dir(Dir) -> - case otp_version() of - 15 -> - os:cmd("rm -rf " ++ Dir); - _ -> - do_delete_test_dir(Dir) + TestDir = case file:make_dir(Dir) of + ok -> + Dir; + Err -> + ?assertEqual({error, eexist}, Err), + create_test_dir() + end, + ok = application:set_env(lager, test_dir, TestDir). + +get_test_dir() -> + {ok, TestDir} = application:get_env(lager, test_dir), + TestDir. + +get_temp_dir() -> + Tmp = case os:getenv("TEMP") of + false -> + case os:getenv("TMP") of + false -> "/tmp"; + Dir1 -> Dir1 + end; + Dir0 -> Dir0 + end, + ?assertEqual(true, filelib:is_dir(Tmp)), + {ok, Tmp}. + +delete_test_dir() -> + delete_test_dir(get_test_dir()). + +delete_test_dir(TestDir) -> + {OsType, _} = os:type(), + case {OsType, otp_version()} of + {win32, _} -> + application:stop(lager), + do_delete_test_dir(TestDir); + {unix, 15} -> + os:cmd("rm -rf " ++ TestDir); + {unix, _} -> + do_delete_test_dir(TestDir) end. do_delete_test_dir(Dir) -> @@ -863,6 +889,16 @@ do_delete_test_dir(Dir) -> end, Entries), ?assertEqual(ok, file:del_dir(Dir)). +do_delete_file(_FsElem, 0) -> + ?assert(false); +do_delete_file(FsElem, Attempts) -> + case file:delete(FsElem) of + ok -> ok; + Error -> + io:format(standard_error, "@@@@@@@@ DELETE FILE ~p ERROR ~p~n", [FsElem, Error]), + do_delete_file(FsElem, Attempts - 1) + end. + set_dir_permissions(Perms, Dir) -> do_set_dir_permissions(os:type(), Perms, Dir). From 3267b9861dff7768da3392b6e9d9a388258e96d1 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Tue, 30 Jul 2019 18:23:10 -0700 Subject: [PATCH 04/36] All but one lager_file_backend test passes on win32 --- src/lager_file_backend.erl | 187 +++++++++++++++++++------------------ src/lager_util.erl | 31 +++--- 2 files changed, 114 insertions(+), 104 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 4781ae0..d4957b6 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -475,16 +475,14 @@ rotation_test_() -> SyncInterval = ?DEFAULT_SYNC_INTERVAL, Rotator = ?DEFAULT_ROTATION_MOD, CheckInterval = 0, %% hard to test delayed mode - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - #state{name=TestLog, level=?DEBUG, sync_on=SyncLevel, sync_size=SyncSize, sync_interval=SyncInterval, check_interval=CheckInterval, rotator=Rotator} - end, - fun(#state{name=TestLog}) -> - lager_util:delete_test_dir(filename:dirname(TestLog)) + fun(#state{}) -> + ok = lager_util:delete_test_dir() end, [ fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval, rotator = Rotator}) -> {"External rotation should work", @@ -506,7 +504,7 @@ rotation_test_() -> ok end} end, - fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval, rotator = Rotator}) -> + fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"Internal rotation and delayed write", fun() -> TestLog0 = TestLog ++ ".0", @@ -561,14 +559,7 @@ filesystem_test_() -> {foreach, fun() -> ok = error_logger:tty(false), - case application:load(lager) of - ok -> ok; - {error,{already_loaded,lager}} -> ok; - Error -> - % TODO how to report EUnit errors? - io:format(standard_error, "ERROR: application:load(lager) returned ~p~n", [Error]), - ?assert(false) - end, + ok = safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = application:set_env(lager, async_threshold, undefined), @@ -588,7 +579,7 @@ filesystem_test_() -> end, [ {"under normal circumstances, file should be opened", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -601,7 +592,7 @@ filesystem_test_() -> end}, {"don't choke on unicode", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -615,7 +606,7 @@ filesystem_test_() -> end}, {"don't choke on latin-1", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! @@ -630,23 +621,26 @@ filesystem_test_() -> end}, {"file can't be opened on startup triggers an error message", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), ?assertEqual(ok, file:write_file(TestLog, [])), - {ok, FInfo} = file:read_file_info(TestLog), - file:write_file_info(TestLog, FInfo#file_info{mode = 0}), + {ok, FInfo0} = file:read_file_info(TestLog), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), gen_event:add_handler(lager_event, lager_file_backend, {TestLog, info, 10*1024*1024, "$D0", 5}), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time,Message, _Metadata} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + MessageFlat = lists:flatten(Message), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) + MessageFlat), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)) end}, {"file that becomes unavailable at runtime should trigger an error message", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -661,7 +655,7 @@ filesystem_test_() -> {unix, _} -> ?assertEqual(ok, file:write_file(TestLog, "")), {ok, FInfo} = file:read_file_info(TestLog), - file:write_file_info(TestLog, FInfo#file_info{mode = 0}), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), lager:log(error, self(), "Test message"), ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), @@ -674,13 +668,13 @@ filesystem_test_() -> end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), ?assertEqual(ok, file:write_file(TestLog, [])), {ok, FInfo} = file:read_file_info(TestLog), OldPerms = FInfo#file_info.mode, - file:write_file_info(TestLog, FInfo#file_info{mode = 0}), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog},{check_interval, 0}]), ?assertEqual(1, lager_test_backend:count()), @@ -688,7 +682,7 @@ filesystem_test_() -> ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", lists:flatten(Message)), - file:write_file_info(TestLog, FInfo#file_info{mode = OldPerms}), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = OldPerms})), lager:log(error, self(), "Test message"), {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), @@ -697,7 +691,7 @@ filesystem_test_() -> end}, {"external logfile rotation/deletion should be handled", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -721,7 +715,7 @@ filesystem_test_() -> end}, {"internal size rotation should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -733,7 +727,7 @@ filesystem_test_() -> end}, {"internal time rotation should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -747,7 +741,7 @@ filesystem_test_() -> end}, {"rotation call should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -761,7 +755,7 @@ filesystem_test_() -> end}, {"sync_on option should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -775,7 +769,7 @@ filesystem_test_() -> end}, {"sync_on none option should work (also tests sync_interval)", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -791,7 +785,7 @@ filesystem_test_() -> end}, {"sync_size option should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, @@ -814,7 +808,7 @@ filesystem_test_() -> end}, {"runtime level changes", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, {lager_file_backend, TestLog}, {TestLog, info}), @@ -833,7 +827,7 @@ filesystem_test_() -> end}, {"invalid runtime level changes", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog3 = filename:join(TestDir, "test3.log"), @@ -844,7 +838,7 @@ filesystem_test_() -> end}, {"tracing should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, {TestLog, critical}), @@ -861,7 +855,7 @@ filesystem_test_() -> end}, {"tracing should not duplicate messages", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -887,7 +881,7 @@ filesystem_test_() -> end}, {"tracing to a dedicated file should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), {ok, _} = lager:trace_file(TestLog, [{module, ?MODULE}]), @@ -900,7 +894,7 @@ filesystem_test_() -> end}, {"tracing to a dedicated file should work even if root_log is set", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), LogName = "foo.log", LogPath = filename:join(TestDir, LogName), @@ -916,7 +910,7 @@ filesystem_test_() -> end}, {"tracing with options should work", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), TestLog0 = TestLog ++ ".0", @@ -935,7 +929,7 @@ filesystem_test_() -> end}, {"no silent hwm drops", fun() -> - TestDir = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {high_water_mark, 5}, {flush_queue, false}, {sync_on, "=warning"}]), @@ -954,42 +948,41 @@ filesystem_test_() -> trace_files_test_() -> {foreach, fun() -> - Dir = lager_util:get_test_dir(), - Log = filename:join(Dir, "test.log"), - Debug = filename:join(Dir, "debug.log"), - Events = filename:join(Dir, "events.log"), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [ - {lager_file_backend, [ - {file, Log}, - {level, error}, - {formatter, lager_default_formatter}, - {formatter_config, [message, "\n"]} - ]} - ]), - application:set_env(lager, traces, [ - { % get default level of debug - {lager_file_backend, Debug}, [{module, ?MODULE}] - }, - { % Handler Filters Level - {lager_file_backend, Events}, [{module, ?MODULE}], notice - } - ]), - application:set_env(lager, async_threshold, undefined), - lager:start(), - {Dir, Log, Debug, Events} + {ok, TestDir} = lager_util:get_test_dir(), + Log = filename:join(TestDir, "test.log"), + Debug = filename:join(TestDir, "debug.log"), + Events = filename:join(TestDir, "events.log"), + + ok = error_logger:tty(false), + ok = safe_application_load(lager), + ok = application:set_env(lager, handlers, [ + {lager_file_backend, [ + {file, Log}, + {level, error}, + {formatter, lager_default_formatter}, + {formatter_config, [message, "\n"]} + ]} + ]), + ok = application:set_env(lager, traces, [ + { % get default level of debug + {lager_file_backend, Debug}, [{module, ?MODULE}] + }, + { % Handler Filters Level + {lager_file_backend, Events}, [{module, ?MODULE}], notice + } + ]), + ok = application:set_env(lager, async_threshold, undefined), + ok = lager:start(), + {Log, Debug, Events} end, - fun({Dir, _, _, _}) -> + fun({_, _, _}) -> catch ets:delete(lager_config), - application:unset_env(lager, traces), - application:stop(lager), - - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + ok = application:unset_env(lager, traces), + ok = application:stop(lager), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ - fun({_, Log, Debug, Events}) -> + fun({Log, Debug, Events}) -> {"a trace using file backend set up in configuration should work", fun() -> lager:error("trace test error message"), @@ -1029,28 +1022,27 @@ count_lines_until(Lines, Timeout, File, Last) -> formatting_test_() -> {foreach, fun() -> - Dir = lager_util:get_test_dir(), - Log1 = filename:join(Dir, "test.log"), - Log2 = filename:join(Dir, "test2.log"), + {ok, TestDir} = lager_util:get_test_dir(), + Log1 = filename:join(TestDir, "test.log"), + Log2 = filename:join(TestDir, "test2.log"), ?assertEqual(ok, file:write_file(Log1, [])), ?assertEqual(ok, file:write_file(Log2, [])), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, false), - lager:start(), + ok = error_logger:tty(false), + ok = safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = lager:start(), %% same race condition issue - timer:sleep(5), - {Dir, Log1, Log2} + ok = timer:sleep(5), + {ok, Log1, Log2} end, - fun({Dir, _, _}) -> - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + fun({ok, _, _}) -> + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ - fun({_, Log1, Log2}) -> + fun({ok, Log1, Log2}) -> {"Should have two log files, the second prefixed with 2>", fun() -> gen_event:add_handler(lager_event, lager_file_backend, @@ -1124,5 +1116,16 @@ config_validation_test_() -> } ]. +safe_application_load(App) -> + case application:load(App) of + ok -> + ok; + {error, {already_loaded, App}} -> + ok; + Error -> + % TODO how to report EUnit errors? + io:format(standard_error, "ERROR: application:load(~p) returned ~p~n", [App, Error]), + ?assert(false) + end. -endif. diff --git a/src/lager_util.erl b/src/lager_util.erl index 8d716a8..5d8fd0f 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -843,8 +843,13 @@ create_test_dir() -> ok = application:set_env(lager, test_dir, TestDir). get_test_dir() -> - {ok, TestDir} = application:get_env(lager, test_dir), - TestDir. + case application:get_env(lager, test_dir) of + undefined -> + create_test_dir(), + get_test_dir(); + {ok, _}=Res -> + Res + end. get_temp_dir() -> Tmp = case os:getenv("TEMP") of @@ -859,19 +864,21 @@ get_temp_dir() -> {ok, Tmp}. delete_test_dir() -> - delete_test_dir(get_test_dir()). + {ok, TestDir} = get_test_dir(), + ok = delete_test_dir(TestDir). delete_test_dir(TestDir) -> {OsType, _} = os:type(), - case {OsType, otp_version()} of - {win32, _} -> - application:stop(lager), - do_delete_test_dir(TestDir); - {unix, 15} -> - os:cmd("rm -rf " ++ TestDir); - {unix, _} -> - do_delete_test_dir(TestDir) - end. + ok = case {OsType, otp_version()} of + {win32, _} -> + application:stop(lager), + do_delete_test_dir(TestDir); + {unix, 15} -> + os:cmd("rm -rf " ++ TestDir); + {unix, _} -> + do_delete_test_dir(TestDir) + end, + ok = application:unset_env(lager, test_dir). do_delete_test_dir(Dir) -> ListRet = file:list_dir_all(Dir), From ecb0f8c3cf70af9e680374c40b29ccd893e5c39c Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Wed, 31 Jul 2019 11:39:29 -0700 Subject: [PATCH 05/36] Fix a couple more win32 test issues in lager_file_backend --- src/lager_file_backend.erl | 56 +++++++++++++++++++++----------------- src/lager_util.erl | 7 ++++- 2 files changed, 37 insertions(+), 26 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index d4957b6..0c75ba2 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -453,8 +453,9 @@ close_file(#state{fd=undefined} = State) -> State; close_file(#state{fd=FD} = State) -> %% Flush and close any file handles. - _ = file:datasync(FD), - _ = file:close(FD), + %% TODO LRB don't match, but preserve errors + ok = file:datasync(FD), + ok = file:close(FD), State#state{fd=undefined}. -ifdef(TEST). @@ -564,7 +565,7 @@ filesystem_test_() -> ok = application:set_env(lager, error_logger_redirect, false), ok = application:set_env(lager, async_threshold, undefined), ok = lager_util:create_test_dir(), - lager:start(), + ok = 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. @@ -628,20 +629,26 @@ filesystem_test_() -> {ok, FInfo0} = file:read_file_info(TestLog), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), + gen_event:add_handler(lager_event, lager_file_backend, {TestLog, info, 10*1024*1024, "$D0", 5}), + + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), + ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), MessageFlat = lists:flatten(Message), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", - MessageFlat), - ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)) + MessageFlat) end}, {"file that becomes unavailable at runtime should trigger an error message", fun() -> {ok, TestDir} = lager_util:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), + TestFileName = "test_" ++ erlang:integer_to_list(erlang:phash2(os:timestamp())) ++ ".log", + TestLog = filename:join(TestDir, TestFileName), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {check_interval, 0}]), @@ -649,22 +656,23 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - case os:type() of - {win32, _} -> - ?assertEqual({error, eacces}, file:write_file(TestLog, "")); - {unix, _} -> - ?assertEqual(ok, file:write_file(TestLog, "")), - {ok, FInfo} = file:read_file_info(TestLog), - ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), - lager:log(error, self(), "Test message"), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) - end + ?assertEqual(ok, file:write_file(TestLog, "")), + {ok, FInfo0} = file:read_file_info(TestLog), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), + lager:log(error, self(), "Test message"), + + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), + + ?assertEqual(3, lager_test_backend:count()), + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> @@ -1123,9 +1131,7 @@ safe_application_load(App) -> {error, {already_loaded, App}} -> ok; Error -> - % TODO how to report EUnit errors? - io:format(standard_error, "ERROR: application:load(~p) returned ~p~n", [App, Error]), - ?assert(false) + ?assertEqual(ok, Error) end. -endif. diff --git a/src/lager_util.erl b/src/lager_util.erl index 5d8fd0f..1c64c00 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -891,7 +891,12 @@ do_delete_test_dir(Dir) -> true -> delete_test_dir(FsElem); _ -> - ?assertEqual(ok, file:delete(FsElem)) + case file:delete(FsElem) of + ok -> ok; + Error -> + io:format(standard_error, "[ERROR]: error deleting file ~p~n", [FsElem]), + ?assertEqual(ok, Error) + end end end, Entries), ?assertEqual(ok, file:del_dir(Dir)). From 39c1248f969b114b7175f7872472a532b6f215f8 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Wed, 31 Jul 2019 14:15:38 -0700 Subject: [PATCH 06/36] Fix "Internal rotation and delayed write" test on win32 --- src/lager_file_backend.erl | 31 ++++++++++++++++++++++--------- src/lager_rotator_default.erl | 2 +- 2 files changed, 23 insertions(+), 10 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 0c75ba2..fc1cbd8 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -453,9 +453,11 @@ close_file(#state{fd=undefined} = State) -> State; close_file(#state{fd=FD} = State) -> %% Flush and close any file handles. - %% TODO LRB don't match, but preserve errors - ok = file:datasync(FD), - ok = file:close(FD), + %% TODO LRB don't match, but report errors??? + _ = file:datasync(FD), + %% delayed write can cause file:close not to do a close + _ = file:close(FD), + _ = file:close(FD), State#state{fd=undefined}. -ifdef(TEST). @@ -485,19 +487,19 @@ rotation_test_() -> fun(#state{}) -> ok = lager_util:delete_test_dir() end, [ - fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval, rotator = Rotator}) -> + fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"External rotation should work", fun() -> {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{fd=FD, inode=Inode}, ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode}, - write(State0, os:timestamp(), ?DEBUG, "hello world")), - file:delete(TestLog), + write(State0, os:timestamp(), ?DEBUG, "hello world")), + ?assertEqual(ok, file:delete(TestLog)), Result = write(State0, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed ?assert(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode} =/= Result), ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result), - file:rename(TestLog, TestLog ++ ".1"), + ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), Result2 = write(Result, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed ?assert(Result =/= Result2), @@ -527,6 +529,17 @@ rotation_test_() -> Msg2Timestamp = add_secs(PreviousCheck, 2), State0 = State2 = write(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), + % Note: we must ensure at least one second (DEFAULT_SYNC_INTERVAL) has passed + % for message 1 and 2 to be written to disk + ElapsedMs = timer:now_diff(os:timestamp(), PreviousCheck) div 1000, + case ElapsedMs > SyncInterval of + true -> + ok; + _ -> + S = SyncInterval - ElapsedMs, + timer:sleep(S) + end, + %% although file size is big enough... {ok, FInfo} = file:read_file_info(TestLog), ?assert(RotationSize < FInfo#file_info.size), @@ -543,9 +556,9 @@ rotation_test_() -> {ok, Bin1} = file:read_file(TestLog0), {ok, Bin2} = file:read_file(TestLog), - %% message 1-3 written to file + %% message 1-2 written to file ?assertEqual(<<"big big message 1buffered message 2">>, Bin1), - %% message 4 buffered, not yet written to file + %% message 3 buffered, not yet written to file ?assertEqual(<<"">>, Bin2), ok end} diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 45921e9..553a861 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -19,7 +19,7 @@ open_logfile(Name, Buffer) -> case filelib:ensure_dir(Name) of ok -> Options = [append, raw] ++ - case Buffer of + case Buffer of {Size, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size), Size >= 0 -> [{delayed_write, Size, Interval}]; _ -> [] From 7bb09880cd123cfbc0c11f39995529d100c135d8 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Wed, 31 Jul 2019 15:39:44 -0700 Subject: [PATCH 07/36] Refactor lager_rotator_behaviour to return a files ctime value, which is necessary for detecting changes on win32 --- src/lager_crash_log.erl | 19 ++++----- src/lager_file_backend.erl | 55 +++++++++++++------------- src/lager_rotator_behaviour.erl | 8 ++-- src/lager_rotator_default.erl | 69 ++++++++++++++++++--------------- 4 files changed, 80 insertions(+), 71 deletions(-) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 5a48238..b6d7e67 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -52,6 +52,7 @@ name :: string(), fd :: pid() | undefined, inode :: integer() | undefined, + ctime :: file:date_time() | undefined, fmtmaxbytes :: integer(), size :: integer(), date :: undefined | string(), @@ -74,9 +75,9 @@ start(Filename, MaxBytes, Size, Date, Count, Rotator) -> init([RelFilename, MaxBytes, Size, Date, Count, Rotator]) -> Filename = lager_util:expand_path(RelFilename), case Rotator:open_logfile(Filename, false) of - {ok, {FD, Inode, _}} -> + {ok, {FD, Inode, Ctime, _Size}} -> schedule_rotation(Date), - {ok, #state{name=Filename, fd=FD, inode=Inode, + {ok, #state{name=Filename, fd=FD, inode=Inode, ctime=Ctime, fmtmaxbytes=MaxBytes, size=Size, count=Count, date=Date, rotator=Rotator}}; {error, Reason} -> @@ -188,7 +189,7 @@ 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, +do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap, fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count, rotator=Rotator} = State) -> %% borrowed from riak_err {ReportStr, Pid, MsgStr, _ErrorP} = case Event of @@ -204,11 +205,11 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, if ReportStr == ignore -> {ok, State}; true -> - case Rotator:ensure_logfile(Name, FD, Inode, false) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, false) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> _ = Rotator:rotate_logfile(Name, Count), handle_cast({log, Event}, State); - {ok, {NewFD, NewInode, _Size}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> {Date, TS} = lager_util:format_time( lager_stdlib:maybe_utc(erlang:localtime())), Time = [Date, " ", TS," =", ReportStr, "====\n"], @@ -218,11 +219,11 @@ do_log({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)]), - {ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=true}}; ok -> - {ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=false}}; _ -> - {ok, State#state{fd=NewFD, inode=NewInode}} + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime}} end; {error, Reason} -> case Flap of diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index fc1cbd8..213bbaa 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -63,8 +63,9 @@ name :: string(), level :: {'mask', integer()}, fd :: file:io_device() | undefined, - inode :: integer() | undefined, - flap=false :: boolean(), + inode = undefined :: integer() | undefined, + ctime = undefined :: file:date_time() | undefined, + flap = false :: boolean(), size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), @@ -123,8 +124,8 @@ init(LogFileConfig) when is_list(LogFileConfig) -> shaper=Shaper, formatter=Formatter, formatter_config=FormatterConfig, sync_on=SyncOn, sync_interval=SyncInterval, sync_size=SyncSize, check_interval=CheckInterval}, State = case Rotator:create_logfile(Name, {SyncSize, SyncInterval}) of - {ok, {FD, Inode, _}} -> - State0#state{fd=FD, inode=Inode}; + {ok, {FD, Inode, Ctime, _Size}} -> + State0#state{fd=FD, inode=Inode, ctime=Ctime}; {error, Reason} -> ?INT_LOG(error, "Failed to open log file ~s with error ~s", [Name, file:format_error(Reason)]), State0#state{flap=true} @@ -244,8 +245,10 @@ write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, case LastCheck >= State#state.check_interval orelse FD == undefined of true -> %% need to check for rotation - case Rotator:ensure_logfile(Name, FD, Inode, {State#state.sync_size, State#state.sync_interval}) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + Ctime = State#state.ctime, + Buffer = {State#state.sync_size, State#state.sync_interval}, + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> case Rotator:rotate_logfile(Name, Count) of ok -> %% go around the loop again, we'll do another rotation check and hit the next clause of ensure_logfile @@ -259,9 +262,9 @@ write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, State#state{flap=true} end end; - {ok, {NewFD, NewInode, _}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> %% update our last check and try again - do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode}, Level, Msg); + do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode, ctime=NewCtime}, Level, Msg); {error, Reason} -> case Flap of true -> @@ -464,10 +467,10 @@ close_file(#state{fd=FD} = State) -> get_loglevel_test() -> {ok, Level, _} = handle_call(get_loglevel, - #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0}), + #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level, lager_util:config_to_mask(info)), {ok, Level2, _} = handle_call(get_loglevel, - #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0}), + #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level2, lager_util:config_to_mask(warning)). rotation_test_() -> @@ -490,20 +493,21 @@ rotation_test_() -> fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"External rotation should work", fun() -> - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd=FD, inode=Inode}, - ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode}, - write(State0, os:timestamp(), ?DEBUG, "hello world")), + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + State0 = DefaultState#state{fd=FD, inode=Inode, ctime=Ctime}, + State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, State1), ?assertEqual(ok, file:delete(TestLog)), - Result = write(State0, os:timestamp(), ?DEBUG, "hello world"), + State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed - ?assert(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode} =/= Result), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result), + ExpState1 = #state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, + ?assertNotEqual(ExpState1, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State2), ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), - Result2 = write(Result, os:timestamp(), ?DEBUG, "hello world"), + State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed - ?assert(Result =/= Result2), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result2), + ?assertNotEqual(State3, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State3), ok end} end, @@ -515,7 +519,7 @@ rotation_test_() -> RotationSize = 15, PreviousCheck = os:timestamp(), - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + {ok, {FD, Inode, _Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{ fd=FD, inode=Inode, size=RotationSize, check_interval=CheckInterval, last_check=PreviousCheck}, @@ -660,8 +664,7 @@ filesystem_test_() -> {"file that becomes unavailable at runtime should trigger an error message", fun() -> {ok, TestDir} = lager_util:get_test_dir(), - TestFileName = "test_" ++ erlang:integer_to_list(erlang:phash2(os:timestamp())) ++ ".log", - TestLog = filename:join(TestDir, TestFileName), + TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {check_interval, 0}]), @@ -721,14 +724,14 @@ filesystem_test_() -> ?assertEqual(0, lager_test_backend:count()), lager:log(error, self(), "Test message1"), ?assertEqual(1, lager_test_backend:count()), - file:delete(TestLog), - file:write_file(TestLog, ""), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, file:write_file(TestLog, "")), lager:log(error, self(), "Test message2"), {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])), - file:rename(TestLog, TestLog0), + ?assertEqual(ok, file:rename(TestLog, TestLog0)), lager:log(error, self(), "Test message3"), {ok, Bin2} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], diff --git a/src/lager_rotator_behaviour.erl b/src/lager_rotator_behaviour.erl index 5b6e5e8..a37d94a 100644 --- a/src/lager_rotator_behaviour.erl +++ b/src/lager_rotator_behaviour.erl @@ -2,16 +2,16 @@ %% Create a log file -callback(create_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Open a log file -callback(open_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Ensure reference to current target, could be rotated --callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), +-callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), Ctime::file:date_time(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Rotate the log file -callback(rotate_logfile(Name::list(), Count::integer()) -> diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 553a861..4bfb61a 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -5,7 +5,7 @@ -behaviour(lager_rotator_behaviour). -export([ - create_logfile/2, open_logfile/2, ensure_logfile/4, rotate_logfile/2 + create_logfile/2, open_logfile/2, ensure_logfile/5, rotate_logfile/2 ]). -ifdef(TEST). @@ -20,8 +20,8 @@ open_logfile(Name, Buffer) -> ok -> Options = [append, raw] ++ case Buffer of - {Size, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size), Size >= 0 -> - [{delayed_write, Size, Interval}]; + {Size0, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size0), Size0 >= 0 -> + [{delayed_write, Size0, Interval}]; _ -> [] end, case file:open(Name, Options) of @@ -29,7 +29,9 @@ open_logfile(Name, Buffer) -> case file:read_file_info(Name) of {ok, FInfo} -> Inode = FInfo#file_info.inode, - {ok, {FD, Inode, FInfo#file_info.size}}; + Ctime = FInfo#file_info.ctime, + Size1 = FInfo#file_info.size, + {ok, {FD, Inode, Ctime, Size1}}; X -> X end; Y -> Y @@ -37,39 +39,42 @@ open_logfile(Name, Buffer) -> Z -> Z end. -ensure_logfile(Name, undefined, _Inode, Buffer) -> +ensure_logfile(Name, undefined, _Inode, _Ctime, Buffer) -> open_logfile(Name, Buffer); -ensure_logfile(Name, FD, Inode, Buffer) -> +ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> case file:read_file_info(Name) of {ok, FInfo} -> - Inode2 = FInfo#file_info.inode, - case Inode == Inode2 of - true -> - {ok, {FD, Inode, FInfo#file_info.size}}; - false -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% inode changed, file was probably moved and - %% recreated - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end + {OsType, _} = os:type(), + Inode1 = FInfo#file_info.inode, + Ctime1 = FInfo#file_info.ctime, + case {OsType, Inode0 =:= Inode1, Ctime0 =:= Ctime1} of + % Note: on win32, Inode is always zero + % So check the file's ctime to see if it + % needs to be re-opened + {win32, _, false} -> + reopen_logfile(Name, FD, Buffer); + {win32, _, true} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; + {unix, true, _} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; + {unix, false, _} -> + reopen_logfile(Name, FD, Buffer) end; _ -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% file was removed - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end + reopen_logfile(Name, FD, Buffer) + end. + +reopen_logfile(Name, FD0, Buffer) -> + %% delayed write can cause file:close not to do a close + _ = file:close(FD0), + _ = file:close(FD0), + case open_logfile(Name, Buffer) of + {ok, {_FD1, _Inode, _Size, _Ctime}=FileInfo} -> + %% inode changed, file was probably moved and + %% recreated + {ok, FileInfo}; + Error -> + Error end. %% renames failing are OK From 439e82c40ffbb65acc4a58e1487caaa6e5baad73 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Wed, 31 Jul 2019 16:19:34 -0700 Subject: [PATCH 08/36] Take a file ctime into account when write/4 is called --- src/lager_file_backend.erl | 39 ++++++++++++++++++++++++++++---------- 1 file changed, 29 insertions(+), 10 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 213bbaa..8387db9 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -35,12 +35,12 @@ -module(lager_file_backend). -include("lager.hrl"). +-include_lib("kernel/include/file.hrl"). -behaviour(gen_event). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). --include_lib("kernel/include/file.hrl"). -compile([{parse_transform, lager_transform}]). -endif. @@ -239,13 +239,13 @@ config_to_id(Config) -> end. -write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, - count=Count, rotator=Rotator} = State, Timestamp, Level, Msg) -> - LastCheck = timer:now_diff(Timestamp, State#state.last_check) div 1000, - case LastCheck >= State#state.check_interval orelse FD == undefined of +write(#state{name=Name, fd=FD, + inode=Inode, ctime=Ctime, + flap=Flap, size=RotSize, + count=Count, rotator=Rotator} = State, Timestamp, Level, Msg) -> + case write_should_check(State, Timestamp) of true -> %% need to check for rotation - Ctime = State#state.ctime, Buffer = {State#state.sync_size, State#state.sync_interval}, case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> @@ -278,6 +278,23 @@ write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, do_write(State, Level, Msg) end. +write_should_check(#state{fd=undefined}, _Timestamp) -> + true; +write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, + name=Name, ctime=Ctime0}, Timestamp) -> + LastCheck1 = timer:now_diff(Timestamp, LastCheck0) div 1000, + case LastCheck1 >= CheckInterval of + true -> + true; + _ -> + case file:read_file_info(Name) of + {ok, #file_info{ctime=Ctime1}} -> + Ctime0 =/= Ctime1; + _ -> + true + end + end. + do_write(#state{fd=FD, name=Name, flap=Flap} = State, Level, Msg) -> %% delayed_write doesn't report errors _ = file:write(FD, unicode:characters_to_binary(Msg)), @@ -519,19 +536,21 @@ rotation_test_() -> RotationSize = 15, PreviousCheck = os:timestamp(), - {ok, {FD, Inode, _Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{ - fd=FD, inode=Inode, size=RotationSize, + fd=FD, inode=Inode, ctime=Ctime, size=RotationSize, check_interval=CheckInterval, last_check=PreviousCheck}, %% new message within check interval with sync_on level Msg1Timestamp = add_secs(PreviousCheck, 1), - State0 = State1 = write(State0, Msg1Timestamp, ?ERROR, "big big message 1"), + State1 = write(State0, Msg1Timestamp, ?ERROR, "big big message 1"), + ?assertEqual(State0, State1), %% new message within check interval under sync_on level %% not written to disk yet Msg2Timestamp = add_secs(PreviousCheck, 2), - State0 = State2 = write(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), + State2 = write(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), + ?assertEqual(State0, State2), % Note: we must ensure at least one second (DEFAULT_SYNC_INTERVAL) has passed % for message 1 and 2 to be written to disk From c7d7fce951a2f974ef19db7c79bfd0e875c09cbf Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 1 Aug 2019 08:09:03 -0700 Subject: [PATCH 09/36] Fix test in lager_file_backend with exception for win32 --- src/lager_file_backend.erl | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 8387db9..074124a 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -701,13 +701,18 @@ filesystem_test_() -> % from preventing cleanup ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) + case os:type() of + {win32, _} -> + % Note: on win32, setting mode = 0 does not result in a permission error + ?assertEqual(2, lager_test_backend:count()); + _ -> + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) + end end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> From 0bc318cfd15f419ab8bcf91c49a8c1a78746e073 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 1 Aug 2019 10:47:56 -0700 Subject: [PATCH 10/36] Ensure creation time is updated on win32 when files are created --- src/lager_crash_log.erl | 6 +++--- src/lager_file_backend.erl | 36 +++++++++++++++++++------------ src/lager_rotator_default.erl | 40 ++++++++++++++++++++++++++++------- 3 files changed, 57 insertions(+), 25 deletions(-) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index b6d7e67..b4434d1 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -281,7 +281,7 @@ filesystem_test_() -> fun(CrashLog) -> {"file can't be opened on startup triggers an error message", fun() -> - {ok, FInfo} = file:read_file_info(CrashLog), + {ok, FInfo} = file:read_file_info(CrashLog, [raw]), file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), ?assertEqual(1, lager_test_backend:count()), @@ -301,7 +301,7 @@ filesystem_test_() -> ?assertEqual(1, lager_test_backend:count()), file:delete(CrashLog), file:write_file(CrashLog, ""), - {ok, FInfo} = file:read_file_info(CrashLog), + {ok, FInfo} = file:read_file_info(CrashLog, [raw]), file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), sync_error_logger:error_msg("Test message\n"), _ = gen_event:which_handlers(error_logger), @@ -316,7 +316,7 @@ filesystem_test_() -> fun(CrashLog) -> {"unavailable files that are fixed at runtime should start having log messages written", fun() -> - {ok, FInfo} = file:read_file_info(CrashLog), + {ok, FInfo} = file:read_file_info(CrashLog, [raw]), OldPerms = FInfo#file_info.mode, file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 074124a..573fa28 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -63,8 +63,8 @@ name :: string(), level :: {'mask', integer()}, fd :: file:io_device() | undefined, - inode = undefined :: integer() | undefined, - ctime = undefined :: file:date_time() | undefined, + inode :: integer() | undefined, + ctime :: file:date_time() | undefined, flap = false :: boolean(), size = 0 :: integer(), date :: undefined | string(), @@ -238,7 +238,6 @@ config_to_id(Config) -> {?MODULE, File} end. - write(#state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap, size=RotSize, @@ -287,7 +286,7 @@ write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, true -> true; _ -> - case file:read_file_info(Name) of + case file:read_file_info(Name, [raw]) of {ok, #file_info{ctime=Ctime1}} -> Ctime0 =/= Ctime1; _ -> @@ -564,7 +563,7 @@ rotation_test_() -> end, %% although file size is big enough... - {ok, FInfo} = file:read_file_info(TestLog), + {ok, FInfo} = file:read_file_info(TestLog, [raw]), ?assert(RotationSize < FInfo#file_info.size), %% ...no rotation yet ?assertEqual(PreviousCheck, State2#state.last_check), @@ -660,9 +659,9 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, file:write_file(TestLog, [])), + ?assertEqual(ok, safe_write_file(TestLog, [])), - {ok, FInfo0} = file:read_file_info(TestLog), + {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), @@ -691,8 +690,8 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, file:write_file(TestLog, "")), - {ok, FInfo0} = file:read_file_info(TestLog), + ?assertEqual(ok, safe_write_file(TestLog, "")), + {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), lager:log(error, self(), "Test message"), @@ -718,9 +717,9 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, file:write_file(TestLog, [])), + ?assertEqual(ok, safe_write_file(TestLog, [])), - {ok, FInfo} = file:read_file_info(TestLog), + {ok, FInfo} = file:read_file_info(TestLog, [raw]), OldPerms = FInfo#file_info.mode, ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), gen_event:add_handler(lager_event, lager_file_backend, @@ -749,14 +748,16 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, file:write_file(TestLog, "")), + ?assertEqual(ok, safe_write_file(TestLog, "")), lager:log(error, self(), "Test message2"), + ?assertEqual(2, lager_test_backend:count()), {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])), ?assertEqual(ok, file:rename(TestLog, TestLog0)), lager:log(error, self(), "Test message3"), + ?assertEqual(3, lager_test_backend:count()), {ok, Bin2} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}])) @@ -1073,8 +1074,8 @@ formatting_test_() -> {ok, TestDir} = lager_util:get_test_dir(), Log1 = filename:join(TestDir, "test.log"), Log2 = filename:join(TestDir, "test2.log"), - ?assertEqual(ok, file:write_file(Log1, [])), - ?assertEqual(ok, file:write_file(Log2, [])), + ?assertEqual(ok, safe_write_file(Log1, [])), + ?assertEqual(ok, safe_write_file(Log2, [])), ok = error_logger:tty(false), ok = safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), @@ -1174,4 +1175,11 @@ safe_application_load(App) -> ?assertEqual(ok, Error) end. +safe_write_file(File, Content) -> + ?assertEqual(ok, file:write_file(File, Content)), + NewCtime = calendar:local_time(), + {ok, FInfo0} = file:read_file_info(File, [raw]), + FInfo1 = FInfo0#file_info{ctime = NewCtime}, + ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). + -endif. diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 4bfb61a..2d8a14f 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -26,11 +26,11 @@ open_logfile(Name, Buffer) -> end, case file:open(Name, Options) of {ok, FD} -> - case file:read_file_info(Name) of - {ok, FInfo} -> - Inode = FInfo#file_info.inode, - Ctime = FInfo#file_info.ctime, - Size1 = FInfo#file_info.size, + case file:read_file_info(Name, [raw]) of + {ok, FInfo0} -> + Inode = FInfo0#file_info.inode, + {ok, Ctime} = maybe_update_ctime(Name, FInfo0), + Size1 = FInfo0#file_info.size, {ok, {FD, Inode, Ctime, Size1}}; X -> X end; @@ -42,7 +42,7 @@ open_logfile(Name, Buffer) -> ensure_logfile(Name, undefined, _Inode, _Ctime, Buffer) -> open_logfile(Name, Buffer); ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> - case file:read_file_info(Name) of + case file:read_file_info(Name, [raw]) of {ok, FInfo} -> {OsType, _} = os:type(), Inode1 = FInfo#file_info.inode, @@ -83,6 +83,7 @@ rotate_logfile(File, 0) -> case file:open(File, [write]) of {ok, FD} -> _ = file:close(FD), + {ok, _Ctime} = maybe_update_ctime(File), ok; Error -> Error @@ -97,6 +98,29 @@ rotate_logfile(File0, Count) -> _ = file:rename(File1, File2), rotate_logfile(File0, Count - 1). +maybe_update_ctime(Name) -> + case file:read_file_info(Name, [raw]) of + {ok, FInfo} -> + maybe_update_ctime(Name, FInfo); + _ -> + {ok, calendar:local_time()} + end. + +maybe_update_ctime(Name, FInfo) -> + {OsType, _} = os:type(), + do_update_ctime(OsType, Name, FInfo). + +do_update_ctime(win32, Name, FInfo0) -> + % Note: we force the creation time to be the current time. + % On win32 this may prevent the ctime from being updated: + % https://stackoverflow.com/q/8804342/1466825 + NewCtime = calendar:local_time(), + FInfo1 = FInfo0#file_info{ctime = NewCtime}, + ok = file:write_file_info(Name, FInfo1, [raw]), + {ok, NewCtime}; +do_update_ctime(_, _Name, FInfo) -> + {ok, FInfo#file_info.ctime}. + -ifdef(TEST). rotate_file_test() -> @@ -132,7 +156,7 @@ rotate_file_zero_count_test() -> ?assertEqual(true, filelib:is_regular(TestLog)), ?assertEqual(1, length(filelib:wildcard(TestLog++"*"))), %% assert the new file is 0 size: - case file:read_file_info(TestLog) of + case file:read_file_info(TestLog, [raw]) of {ok, FInfo} -> ?assertEqual(0, FInfo#file_info.size); _ -> @@ -171,7 +195,7 @@ rotate_file_fail_test() -> ?assertEqual(2, length(filelib:wildcard(TestLog++"*"))), %% assert the new file is 0 size: - case file:read_file_info(TestLog) of + case file:read_file_info(TestLog, [raw]) of {ok, FInfo} -> ?assertEqual(0, FInfo#file_info.size); _ -> From 3e9e4eb3d18f079fb61941af6fbcb909bd43485b Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 1 Aug 2019 11:49:25 -0700 Subject: [PATCH 11/36] Write test files using 1 second creation time in the future, lager_file_backend suite passes on win32 --- src/lager_file_backend.erl | 40 +++++++++++++++++++------------------- 1 file changed, 20 insertions(+), 20 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 573fa28..fdab1b2 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -695,23 +695,15 @@ filesystem_test_() -> FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), lager:log(error, self(), "Test message"), - % Note: required on win32, do this early to prevent subsequent failures % from preventing cleanup ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), - - case os:type() of - {win32, _} -> - % Note: on win32, setting mode = 0 does not result in a permission error - ?assertEqual(2, lager_test_backend:count()); - _ -> - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) - end + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> @@ -978,15 +970,18 @@ filesystem_test_() -> end}, {"no silent hwm drops", fun() -> + MsgCount = 15, {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {high_water_mark, 5}, {flush_queue, false}, {sync_on, "=warning"}]), {_, _, MS} = os:timestamp(), - timer:sleep((1000000 - MS) div 1000 + 1), - %start close to the beginning of a new second - [lager:log(info, self(), "Foo ~p", [K]) || K <- lists:seq(1, 15)], - timer:sleep(1000), + % start close to the beginning of a new second + ?assertEqual(ok, timer:sleep((1000000 - MS) div 1000 + 1)), + [lager:log(info, self(), "Foo ~p", [K]) || K <- lists:seq(1, MsgCount)], + ?assertEqual(MsgCount, lager_test_backend:count()), + % Note: bumped from 1000 to 1250 to ensure delayed write flushes to disk + ?assertEqual(ok, timer:sleep(1250)), {ok, Bin} = file:read_file(TestLog), Last = lists:last(re:split(Bin, "\n", [{return, list}, trim])), ?assertMatch([_, _, _, _, "lager_file_backend dropped 10 messages in the last second that exceeded the limit of 5 messages/sec"], @@ -1176,10 +1171,15 @@ safe_application_load(App) -> end. safe_write_file(File, Content) -> + % Note: ensures that the new creation time is at least one second + % in the future ?assertEqual(ok, file:write_file(File, Content)), - NewCtime = calendar:local_time(), + Ctime0 = calendar:local_time(), + Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), + Ctime1Sec = Ctime0Sec + 1, + Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), {ok, FInfo0} = file:read_file_info(File, [raw]), - FInfo1 = FInfo0#file_info{ctime = NewCtime}, + FInfo1 = FInfo0#file_info{ctime = Ctime1}, ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). -endif. From 62e847acaab5a8ae4c7f1d1c6e9169a95fbb392e Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 1 Aug 2019 11:57:58 -0700 Subject: [PATCH 12/36] Add inode check to write_should_check --- src/lager_file_backend.erl | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index fdab1b2..862e821 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -280,15 +280,18 @@ write(#state{name=Name, fd=FD, write_should_check(#state{fd=undefined}, _Timestamp) -> true; write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, - name=Name, ctime=Ctime0}, Timestamp) -> + name=Name, inode=Inode0, ctime=Ctime0}, Timestamp) -> LastCheck1 = timer:now_diff(Timestamp, LastCheck0) div 1000, case LastCheck1 >= CheckInterval of true -> true; _ -> + % TODO this code is duplicated in the default rotator, but we need + % to know if the file has changed "out from under lager" so we don't + % write to an invalid FD case file:read_file_info(Name, [raw]) of - {ok, #file_info{ctime=Ctime1}} -> - Ctime0 =/= Ctime1; + {ok, #file_info{inode=Inode1, ctime=Ctime1}} -> + Inode0 =/= Inode1 orelse Ctime0 =/= Ctime1; _ -> true end From cd5f69dafe7d42b949234c373e1f449989454a11 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 07:36:54 -0700 Subject: [PATCH 13/36] Factor out common code into lager_util:has_file_changed --- src/lager_file_backend.erl | 8 ++------ src/lager_rotator_default.erl | 25 +++++-------------------- src/lager_util.erl | 25 ++++++++++++++++++++++++- 3 files changed, 31 insertions(+), 27 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 862e821..83a0b3c 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -289,12 +289,8 @@ write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, % TODO this code is duplicated in the default rotator, but we need % to know if the file has changed "out from under lager" so we don't % write to an invalid FD - case file:read_file_info(Name, [raw]) of - {ok, #file_info{inode=Inode1, ctime=Ctime1}} -> - Inode0 =/= Inode1 orelse Ctime0 =/= Ctime1; - _ -> - true - end + {Result, _FInfo} = lager_util:has_file_changed(Name, Inode0, Ctime0), + Result end. do_write(#state{fd=FD, name=Name, flap=Flap} = State, Level, Msg) -> diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 2d8a14f..f910c73 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -42,26 +42,11 @@ open_logfile(Name, Buffer) -> ensure_logfile(Name, undefined, _Inode, _Ctime, Buffer) -> open_logfile(Name, Buffer); ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> - case file:read_file_info(Name, [raw]) of - {ok, FInfo} -> - {OsType, _} = os:type(), - Inode1 = FInfo#file_info.inode, - Ctime1 = FInfo#file_info.ctime, - case {OsType, Inode0 =:= Inode1, Ctime0 =:= Ctime1} of - % Note: on win32, Inode is always zero - % So check the file's ctime to see if it - % needs to be re-opened - {win32, _, false} -> - reopen_logfile(Name, FD, Buffer); - {win32, _, true} -> - {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; - {unix, true, _} -> - {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; - {unix, false, _} -> - reopen_logfile(Name, FD, Buffer) - end; - _ -> - reopen_logfile(Name, FD, Buffer) + case lager_util:has_file_changed(Name, Inode0, Ctime0) of + {true, _FInfo} -> + reopen_logfile(Name, FD, Buffer); + {_, FInfo} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}} end. reopen_logfile(Name, FD0, Buffer) -> diff --git a/src/lager_util.erl b/src/lager_util.erl index 1c64c00..852b169 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -27,7 +27,8 @@ localtime_ms/0, localtime_ms/1, maybe_utc/1, parse_rotation_date_spec/1, calculate_next_rotation/1, validate_trace/1, check_traces/4, is_loggable/3, trace_filter/1, trace_filter/2, expand_path/1, find_file/2, check_hwm/1, check_hwm/2, - make_internal_sink_name/1, otp_version/0, maybe_flush/2 + make_internal_sink_name/1, otp_version/0, maybe_flush/2, + has_file_changed/3 ]). -ifdef(TEST). @@ -40,6 +41,8 @@ -include("lager.hrl"). +-include_lib("kernel/include/file.hrl"). + levels() -> [debug, info, notice, warning, error, critical, alert, emergency, none]. @@ -592,6 +595,26 @@ maybe_flush(undefined, #lager_shaper{} = S) -> maybe_flush(Flag, #lager_shaper{} = S) when is_boolean(Flag) -> S#lager_shaper{flush_queue = Flag}. +-spec has_file_changed(Name :: file:name_all(), + Inode0 :: pos_integer(), + Ctime0 :: file:date_time()) -> {boolean(), file:file_info()}. +has_file_changed(Name, Inode0, Ctime0) -> + {OsType, _} = os:type(), + F = file:read_file_info(Name, [raw]), + case {OsType, F} of + {win32, {ok, #file_info{ctime=Ctime1}=FInfo}} -> + % Note: on win32, Inode is always zero + % So check the file's ctime to see if it + % needs to be re-opened + Changed = Ctime0 =/= Ctime1, + {Changed, FInfo}; + {_, {ok, #file_info{inode=Inode1}=FInfo}} -> + Changed = Inode0 =/= Inode1, + {Changed, FInfo}; + {_, _} -> + {true, undefined} + end. + -ifdef(TEST). parse_test() -> From b069aeaac8718a5d1789a265c2b7e695ba48325b Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 09:56:38 -0700 Subject: [PATCH 14/36] Fixed tests in lager_crash_log on win32 --- src/lager_crash_log.erl | 56 ++++++++++++++++++++++---------------- src/lager_file_backend.erl | 44 ++++++++---------------------- src/lager_util.erl | 8 +++--- test/lager_test_util.erl | 52 +++++++++++++++++++++++++++++++++++ 4 files changed, 99 insertions(+), 61 deletions(-) create mode 100644 test/lager_test_util.erl diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index b4434d1..8b97255 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -243,30 +243,30 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Fla filesystem_test_() -> {foreach, fun() -> - CrashLog = filename:join(lager_util:create_test_dir(), "crash_test.log"), - file:write_file(CrashLog, []), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, true), - application:unset_env(lager, crash_log), - lager:start(), - timer:sleep(1000), - lager_test_backend:flush(), + {ok, TestDir} = lager_util:get_test_dir(), + CrashLog = filename:join(TestDir, "crash_test.log"), + ok = lager_test_util:safe_write_file(CrashLog, []), + ok = error_logger:tty(false), + ok = lager_test_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, true), + ok = application:unset_env(lager, crash_log), + ok = lager:start(), + ok = timer:sleep(1000), + ok = lager_test_backend:flush(), CrashLog end, - fun(CrashLog) -> + fun(_CrashLog) -> case whereis(lager_crash_log) of P when is_pid(P) -> - exit(P, kill); + gen_server:stop(P); _ -> ok end, - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(filename:dirname(CrashLog)), - error_logger:tty(true) + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ fun(CrashLog) -> {"under normal circumstances, file should be opened", @@ -281,9 +281,13 @@ filesystem_test_() -> fun(CrashLog) -> {"file can't be opened on startup triggers an error message", fun() -> - {ok, FInfo} = file:read_file_info(CrashLog, [raw]), - file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual( @@ -300,11 +304,15 @@ filesystem_test_() -> _ = gen_event:which_handlers(error_logger), ?assertEqual(1, lager_test_backend:count()), file:delete(CrashLog), - file:write_file(CrashLog, ""), - {ok, FInfo} = file:read_file_info(CrashLog, [raw]), - file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + ok = lager_test_util:safe_write_file(CrashLog, ""), + {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), sync_error_logger:error_msg("Test message\n"), _ = gen_event:which_handlers(error_logger), + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), @@ -341,8 +349,8 @@ filesystem_test_() -> _ = gen_event:which_handlers(error_logger), {ok, Bin} = file:read_file(CrashLog), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - file:delete(CrashLog), - file:write_file(CrashLog, ""), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_test_util:safe_write_file(CrashLog, "")), sync_error_logger:error_msg("Test message1~n"), _ = gen_event:which_handlers(error_logger), {ok, Bin1} = file:read_file(CrashLog), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 83a0b3c..e60d25d 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -594,7 +594,7 @@ filesystem_test_() -> {foreach, fun() -> ok = error_logger:tty(false), - ok = safe_application_load(lager), + ok = lager_test_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = application:set_env(lager, async_threshold, undefined), @@ -603,8 +603,8 @@ filesystem_test_() -> %% 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() + ok = timer:sleep(5), + ok = lager_test_backend:flush() end, fun(_) -> ok = application:stop(lager), @@ -658,7 +658,7 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, safe_write_file(TestLog, [])), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, [])), {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, @@ -689,7 +689,7 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, safe_write_file(TestLog, "")), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "")), {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), @@ -708,7 +708,7 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, safe_write_file(TestLog, [])), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, [])), {ok, FInfo} = file:read_file_info(TestLog, [raw]), OldPerms = FInfo#file_info.mode, @@ -739,7 +739,7 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, safe_write_file(TestLog, "")), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "")), lager:log(error, self(), "Test message2"), ?assertEqual(2, lager_test_backend:count()), {ok, Bin} = file:read_file(TestLog), @@ -997,7 +997,7 @@ trace_files_test_() -> Events = filename:join(TestDir, "events.log"), ok = error_logger:tty(false), - ok = safe_application_load(lager), + ok = lager_test_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [ {lager_file_backend, [ {file, Log}, @@ -1068,10 +1068,10 @@ formatting_test_() -> {ok, TestDir} = lager_util:get_test_dir(), Log1 = filename:join(TestDir, "test.log"), Log2 = filename:join(TestDir, "test2.log"), - ?assertEqual(ok, safe_write_file(Log1, [])), - ?assertEqual(ok, safe_write_file(Log2, [])), + ?assertEqual(ok, lager_test_util:safe_write_file(Log1, [])), + ?assertEqual(ok, lager_test_util:safe_write_file(Log2, [])), ok = error_logger:tty(false), - ok = safe_application_load(lager), + ok = lager_test_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = lager:start(), @@ -1159,26 +1159,4 @@ config_validation_test_() -> } ]. -safe_application_load(App) -> - case application:load(App) of - ok -> - ok; - {error, {already_loaded, App}} -> - ok; - Error -> - ?assertEqual(ok, Error) - end. - -safe_write_file(File, Content) -> - % Note: ensures that the new creation time is at least one second - % in the future - ?assertEqual(ok, file:write_file(File, Content)), - Ctime0 = calendar:local_time(), - Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), - Ctime1Sec = Ctime0Sec + 1, - Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), - {ok, FInfo0} = file:read_file_info(File, [raw]), - FInfo1 = FInfo0#file_info{ctime = Ctime1}, - ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). - -endif. diff --git a/src/lager_util.erl b/src/lager_util.erl index 852b169..5755a13 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -597,7 +597,7 @@ maybe_flush(Flag, #lager_shaper{} = S) when is_boolean(Flag) -> -spec has_file_changed(Name :: file:name_all(), Inode0 :: pos_integer(), - Ctime0 :: file:date_time()) -> {boolean(), file:file_info()}. + Ctime0 :: file:date_time()) -> {boolean(), file:file_info() | undefined}. has_file_changed(Name, Inode0, Ctime0) -> {OsType, _} = os:type(), F = file:read_file_info(Name, [raw]), @@ -868,7 +868,7 @@ create_test_dir() -> get_test_dir() -> case application:get_env(lager, test_dir) of undefined -> - create_test_dir(), + ok = create_test_dir(), get_test_dir(); {ok, _}=Res -> Res @@ -891,6 +891,7 @@ delete_test_dir() -> ok = delete_test_dir(TestDir). delete_test_dir(TestDir) -> + ok = application:unset_env(lager, test_dir), {OsType, _} = os:type(), ok = case {OsType, otp_version()} of {win32, _} -> @@ -900,8 +901,7 @@ delete_test_dir(TestDir) -> os:cmd("rm -rf " ++ TestDir); {unix, _} -> do_delete_test_dir(TestDir) - end, - ok = application:unset_env(lager, test_dir). + end. do_delete_test_dir(Dir) -> ListRet = file:list_dir_all(Dir), diff --git a/test/lager_test_util.erl b/test/lager_test_util.erl new file mode 100644 index 0000000..48df299 --- /dev/null +++ b/test/lager_test_util.erl @@ -0,0 +1,52 @@ +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2011-2017 Basho Technologies, Inc. +%% +%% This file is provided to you under the Apache License, +%% Version 2.0 (the "License"); you may not use this file +%% except in compliance with the License. You may obtain +%% a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, +%% software distributed under the License is distributed on an +%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +%% KIND, either express or implied. See the License for the +%% specific language governing permissions and limitations +%% under the License. +%% +%% ------------------------------------------------------------------- + +-module(lager_test_util). + +-ifdef(TEST). + +-export([safe_application_load/1, safe_write_file/2]). + +-include_lib("eunit/include/eunit.hrl"). +-include_lib("kernel/include/file.hrl"). + +safe_application_load(App) -> + case application:load(App) of + ok -> + ok; + {error, {already_loaded, App}} -> + ok; + Error -> + ?assertEqual(ok, Error) + end. + +safe_write_file(File, Content) -> + % Note: ensures that the new creation time is at least one second + % in the future + ?assertEqual(ok, file:write_file(File, Content)), + Ctime0 = calendar:local_time(), + Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), + Ctime1Sec = Ctime0Sec + 1, + Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), + {ok, FInfo0} = file:read_file_info(File, [raw]), + FInfo1 = FInfo0#file_info{ctime = Ctime1}, + ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). + +-endif. From d45849a54598dc116a68c0f59af5286817605841 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 10:08:49 -0700 Subject: [PATCH 15/36] Fix lager_rotator_default tests on win32 --- src/lager_crash_log.erl | 2 +- src/lager_file_backend.erl | 4 ++-- src/lager_rotator_default.erl | 10 +++++----- src/lager_util.erl | 6 +++--- test/lager_rotate.erl | 12 ++++++------ 5 files changed, 17 insertions(+), 17 deletions(-) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 8b97255..4bff771 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -243,7 +243,7 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Fla filesystem_test_() -> {foreach, fun() -> - {ok, TestDir} = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), CrashLog = filename:join(TestDir, "crash_test.log"), ok = lager_test_util:safe_write_file(CrashLog, []), ok = error_logger:tty(false), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index e60d25d..b86b7c3 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -496,7 +496,7 @@ rotation_test_() -> SyncInterval = ?DEFAULT_SYNC_INTERVAL, Rotator = ?DEFAULT_ROTATION_MOD, CheckInterval = 0, %% hard to test delayed mode - {ok, TestDir} = lager_util:get_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "test.log"), #state{name=TestLog, level=?DEBUG, sync_on=SyncLevel, sync_size=SyncSize, sync_interval=SyncInterval, check_interval=CheckInterval, @@ -598,7 +598,7 @@ filesystem_test_() -> ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = application:set_env(lager, async_threshold, undefined), - ok = lager_util:create_test_dir(), + {ok, _TestDir} = lager_util:create_test_dir(), ok = lager:start(), %% race condition where lager logs its own start up %% makes several tests fail. See test/lager_test_backend diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index f910c73..1620c22 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -110,10 +110,10 @@ do_update_ctime(_, _Name, FInfo) -> rotate_file_test() -> RotCount = 10, - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), Outer = fun(N) -> - ?assertEqual(ok, file:write_file(TestLog, erlang:integer_to_list(N))), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, erlang:integer_to_list(N))), Inner = fun(M) -> File = lists:flatten([TestLog, $., erlang:integer_to_list(M)]), ?assert(filelib:is_regular(File)), @@ -134,7 +134,7 @@ rotate_file_test() -> rotate_file_zero_count_test() -> %% Test that a rotation count of 0 simply truncates the file - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), ?assertMatch(ok, rotate_logfile(TestLog, 0)), ?assertNot(filelib:is_regular(TestLog ++ ".0")), @@ -150,14 +150,14 @@ rotate_file_zero_count_test() -> lager_util:delete_test_dir(TestDir). rotate_file_fail_test() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), %% set known permissions on it ok = lager_util:set_dir_permissions("u+rwx", TestDir), %% write a file - file:write_file(TestLog, "hello"), + ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "hello")), case os:type() of {win32, _} -> ok; diff --git a/src/lager_util.erl b/src/lager_util.erl index 5755a13..75f639b 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -863,13 +863,13 @@ create_test_dir() -> ?assertEqual({error, eexist}, Err), create_test_dir() end, - ok = application:set_env(lager, test_dir, TestDir). + ok = application:set_env(lager, test_dir, TestDir), + {ok, TestDir}. get_test_dir() -> case application:get_env(lager, test_dir) of undefined -> - ok = create_test_dir(), - get_test_dir(); + create_test_dir(); {ok, _}=Res -> Res end. diff --git a/test/lager_rotate.erl b/test/lager_rotate.erl index 95077ee..5c6c1e3 100644 --- a/test/lager_rotate.erl +++ b/test/lager_rotate.erl @@ -37,7 +37,7 @@ rotate_test_() -> {foreach, fun() -> - Dir = lager_util:create_test_dir(), + {ok, Dir} = lager_util:create_test_dir(), Log1 = filename:join(Dir, "test1.log"), Log2 = filename:join(Dir, "test2.log"), Sink = filename:join(Dir, "sink.log"), @@ -70,11 +70,11 @@ rotate_test_() -> timer:sleep(1000), State end, - fun(#state{dir = Dir}) -> - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + fun(#state{}) -> + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ fun(State) -> {"Rotate single file", From 8b942003282da7e50da568b06acec1346dd74a1a Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 10:13:30 -0700 Subject: [PATCH 16/36] Move test util functions into TEST section of lager_util --- src/lager_crash_log.erl | 8 +++--- src/lager_file_backend.erl | 18 ++++++------ src/lager_rotator_default.erl | 4 +-- src/lager_util.erl | 30 +++++++++++++++++--- test/lager_test_util.erl | 52 ----------------------------------- 5 files changed, 41 insertions(+), 71 deletions(-) delete mode 100644 test/lager_test_util.erl diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 4bff771..6a4263e 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -245,9 +245,9 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:create_test_dir(), CrashLog = filename:join(TestDir, "crash_test.log"), - ok = lager_test_util:safe_write_file(CrashLog, []), + ok = lager_util:safe_write_file(CrashLog, []), ok = error_logger:tty(false), - ok = lager_test_util:safe_application_load(lager), + ok = lager_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, true), ok = application:unset_env(lager, crash_log), @@ -304,7 +304,7 @@ filesystem_test_() -> _ = gen_event:which_handlers(error_logger), ?assertEqual(1, lager_test_backend:count()), file:delete(CrashLog), - ok = lager_test_util:safe_write_file(CrashLog, ""), + ok = lager_util:safe_write_file(CrashLog, ""), {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), @@ -350,7 +350,7 @@ filesystem_test_() -> {ok, Bin} = file:read_file(CrashLog), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), ?assertEqual(ok, file:delete(CrashLog)), - ?assertEqual(ok, lager_test_util:safe_write_file(CrashLog, "")), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), sync_error_logger:error_msg("Test message1~n"), _ = gen_event:which_handlers(error_logger), {ok, Bin1} = file:read_file(CrashLog), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index b86b7c3..579374d 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -594,7 +594,7 @@ filesystem_test_() -> {foreach, fun() -> ok = error_logger:tty(false), - ok = lager_test_util:safe_application_load(lager), + ok = lager_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = application:set_env(lager, async_threshold, undefined), @@ -658,7 +658,7 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, [])), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, [])), {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, @@ -689,7 +689,7 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "")), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), {ok, FInfo0} = file:read_file_info(TestLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), @@ -708,7 +708,7 @@ filesystem_test_() -> fun() -> {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, [])), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, [])), {ok, FInfo} = file:read_file_info(TestLog, [raw]), OldPerms = FInfo#file_info.mode, @@ -739,7 +739,7 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), ?assertEqual(1, lager_test_backend:count()), ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "")), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), lager:log(error, self(), "Test message2"), ?assertEqual(2, lager_test_backend:count()), {ok, Bin} = file:read_file(TestLog), @@ -997,7 +997,7 @@ trace_files_test_() -> Events = filename:join(TestDir, "events.log"), ok = error_logger:tty(false), - ok = lager_test_util:safe_application_load(lager), + ok = lager_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [ {lager_file_backend, [ {file, Log}, @@ -1068,10 +1068,10 @@ formatting_test_() -> {ok, TestDir} = lager_util:get_test_dir(), Log1 = filename:join(TestDir, "test.log"), Log2 = filename:join(TestDir, "test2.log"), - ?assertEqual(ok, lager_test_util:safe_write_file(Log1, [])), - ?assertEqual(ok, lager_test_util:safe_write_file(Log2, [])), + ?assertEqual(ok, lager_util:safe_write_file(Log1, [])), + ?assertEqual(ok, lager_util:safe_write_file(Log2, [])), ok = error_logger:tty(false), - ok = lager_test_util:safe_application_load(lager), + ok = lager_util:safe_application_load(lager), ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), ok = application:set_env(lager, error_logger_redirect, false), ok = lager:start(), diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 1620c22..4472df7 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -113,7 +113,7 @@ rotate_file_test() -> {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), Outer = fun(N) -> - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, erlang:integer_to_list(N))), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, erlang:integer_to_list(N))), Inner = fun(M) -> File = lists:flatten([TestLog, $., erlang:integer_to_list(M)]), ?assert(filelib:is_regular(File)), @@ -157,7 +157,7 @@ rotate_file_fail_test() -> ok = lager_util:set_dir_permissions("u+rwx", TestDir), %% write a file - ?assertEqual(ok, lager_test_util:safe_write_file(TestLog, "hello")), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "hello")), case os:type() of {win32, _} -> ok; diff --git a/src/lager_util.erl b/src/lager_util.erl index 75f639b..5901d1a 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -32,10 +32,10 @@ ]). -ifdef(TEST). --export([create_test_dir/0, - get_test_dir/0, - delete_test_dir/0, - set_dir_permissions/2]). +-export([create_test_dir/0, get_test_dir/0, delete_test_dir/0, + set_dir_permissions/2, + safe_application_load/1, + safe_write_file/2]). -include_lib("eunit/include/eunit.hrl"). -endif. @@ -943,4 +943,26 @@ do_set_dir_permissions({unix, _}, Perms, Dir) -> os:cmd("chmod -R " ++ Perms ++ " " ++ Dir), ok. +safe_application_load(App) -> + case application:load(App) of + ok -> + ok; + {error, {already_loaded, App}} -> + ok; + Error -> + ?assertEqual(ok, Error) + end. + +safe_write_file(File, Content) -> + % Note: ensures that the new creation time is at least one second + % in the future + ?assertEqual(ok, file:write_file(File, Content)), + Ctime0 = calendar:local_time(), + Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), + Ctime1Sec = Ctime0Sec + 1, + Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), + {ok, FInfo0} = file:read_file_info(File, [raw]), + FInfo1 = FInfo0#file_info{ctime = Ctime1}, + ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). + -endif. diff --git a/test/lager_test_util.erl b/test/lager_test_util.erl deleted file mode 100644 index 48df299..0000000 --- a/test/lager_test_util.erl +++ /dev/null @@ -1,52 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% Copyright (c) 2011-2017 Basho Technologies, Inc. -%% -%% This file is provided to you under the Apache License, -%% Version 2.0 (the "License"); you may not use this file -%% except in compliance with the License. You may obtain -%% a copy of the License at -%% -%% http://www.apache.org/licenses/LICENSE-2.0 -%% -%% Unless required by applicable law or agreed to in writing, -%% software distributed under the License is distributed on an -%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY -%% KIND, either express or implied. See the License for the -%% specific language governing permissions and limitations -%% under the License. -%% -%% ------------------------------------------------------------------- - --module(lager_test_util). - --ifdef(TEST). - --export([safe_application_load/1, safe_write_file/2]). - --include_lib("eunit/include/eunit.hrl"). --include_lib("kernel/include/file.hrl"). - -safe_application_load(App) -> - case application:load(App) of - ok -> - ok; - {error, {already_loaded, App}} -> - ok; - Error -> - ?assertEqual(ok, Error) - end. - -safe_write_file(File, Content) -> - % Note: ensures that the new creation time is at least one second - % in the future - ?assertEqual(ok, file:write_file(File, Content)), - Ctime0 = calendar:local_time(), - Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), - Ctime1Sec = Ctime0Sec + 1, - Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), - {ok, FInfo0} = file:read_file_info(File, [raw]), - FInfo1 = FInfo0#file_info{ctime = Ctime1}, - ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). - --endif. From b64c05ea5b6b3286a7a98830c5cb5a3fc1466894 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 10:34:15 -0700 Subject: [PATCH 17/36] Fix lager_test_function_transform tests on win32 as monotonic_time can return the same value --- test/lager_test_function_transform.erl | 291 ++++++++++++------------- 1 file changed, 145 insertions(+), 146 deletions(-) diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index cc49ad7..e845fa6 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -25,12 +25,12 @@ -compile([{nowarn_deprecated_function, [{erlang, now, 0}]}]). -lager_function_transforms([ - {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, - {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, - {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, + {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, + {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, + {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, - {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, - {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} + {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, + {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} ]). -compile({parse_transform, lager_transform}). @@ -38,162 +38,161 @@ -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). -export([ - transform_static/0, - transform_dynamic/0 + transform_static/0, + transform_dynamic/0 ]). -endif. -ifdef(TEST). transform_static() -> - static_result. + static_result. transform_dynamic() -> - case lager_util:otp_version() >= 18 of - true -> - erlang:monotonic_time(); - false -> - erlang:now() - end. + case lager_util:otp_version() >= 18 of + true -> + erlang:monotonic_time(); + false -> + erlang:now() + end. not_running_test() -> - ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). + ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). setup() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - 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, lager_test_backend, flush). - + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = application:unset_env(lager, traces), + ok = 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. + ok = timer:sleep(250), + ok = gen_event:call(lager_event, lager_test_backend, flush). cleanup(_) -> - catch ets:delete(lager_config), %% kill the ets config table with fire - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true). + catch ets:delete(lager_config), %% kill the ets config table with fire + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = error_logger:tty(true). transform_function_test_() -> - {foreach, - fun setup/0, - fun cleanup/1, - [ - {"observe that there is nothing up my sleeve", - fun() -> - ?assertEqual(undefined, lager_test_backend:pop()), - ?assertEqual(0, lager_test_backend:count()) - end - }, - {"logging works", - fun() -> - lager:warning("test message"), - ?assertEqual(1, lager_test_backend:count()), - {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertMatch(Level, lager_util:level_to_num(warning)), - ?assertEqual("test message", Message), - ok - end - }, - {"Testing calling a function returns the same content on emit", - fun() -> - lager:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_static_emit, Metadata), - ?assertEqual(transform_static(), Function()), - ok - end - }, - {"Testing calling a function which returns content which can change on emit", - fun() -> - lager:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ok - end - }, - {"Testing a undefined function returns undefined on emit", - fun() -> - lager:warning("Undefined error"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_undefined_emit, Metadata), - [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), - ?assertNot(erlang:function_exported(Module, Name, 0)), - ok - end - }, - {"Testing calling a function returns the same content on log", - fun() -> - lager:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), - ok - end - }, - {"Testing calling a dynamic function on log which returns the same value", - fun() -> - lager:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ok - end - }, - {"Testing differences in results for on_log vs on emit from dynamic function", - fun() -> - lager:warning("on_log vs on emit"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - FunctionResult = Function(), - ?assert(Value < FunctionResult), - ?assert(Value < Function()), - ?assert(FunctionResult < Function()), - ok - end - }, - {"Testing a function provided via metadata", - fun()-> - Provided = fun()-> - provided_metadata - end, - lager:md([{provided, Provided}]), - lager:warning("Provided metadata"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(provided, Metadata), - ?assertEqual(Provided(), Function()), - ok - end - } - ] - }. + {foreach, + fun setup/0, + fun cleanup/1, + [ + {"observe that there is nothing up my sleeve", + fun() -> + ?assertEqual(undefined, lager_test_backend:pop()), + ?assertEqual(0, lager_test_backend:count()) + end + }, + {"logging works", + fun() -> + lager:warning("test message"), + ?assertEqual(1, lager_test_backend:count()), + {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual("test message", Message), + ok + end + }, + {"Testing calling a function returns the same content on emit", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_static_emit, Metadata), + ?assertEqual(transform_static(), Function()), + ok + end + }, + {"Testing calling a function which returns content which can change on emit", + fun() -> + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_dynamic_emit, Metadata), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ok + end + }, + {"Testing a undefined function returns undefined on emit", + fun() -> + lager:warning("Undefined error"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_undefined_emit, Metadata), + [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), + ?assertNot(erlang:function_exported(Module, Name, 0)), + ok + end + }, + {"Testing calling a function returns the same content on log", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), + ok + end + }, + {"Testing calling a dynamic function on log which returns the same value", + fun() -> + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ok + end + }, + {"Testing differences in results for on_log vs on emit from dynamic function", + fun() -> + lager:warning("on_log vs on emit"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + Function = proplists:get_value(returns_dynamic_emit, Metadata), + FunctionResult = Function(), + ?assert(Value =< FunctionResult), + ?assert(Value =< Function()), + ?assert(FunctionResult =< Function()), + ok + end + }, + {"Testing a function provided via metadata", + fun()-> + Provided = fun() -> + provided_metadata + end, + lager:md([{provided, Provided}]), + lager:warning("Provided metadata"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(provided, Metadata), + ?assertEqual(Provided(), Function()), + ok + end + } + ] + }. -endif. From 847b811095ab20ec9ed395570ba992663dae7b9c Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 11:23:05 -0700 Subject: [PATCH 18/36] Fix test failures on win32 in pr_stacktrace_test module --- test/pr_stacktrace_test.erl | 38 ++++++++++++------------------------- 1 file changed, 12 insertions(+), 26 deletions(-) diff --git a/test/pr_stacktrace_test.erl b/test/pr_stacktrace_test.erl index e8bc433..468d61f 100644 --- a/test/pr_stacktrace_test.erl +++ b/test/pr_stacktrace_test.erl @@ -22,56 +22,42 @@ bad_arg() -> integer_to_list(1.0). pr_stacktrace_throw_test() -> - Result = try + Got = try make_throw() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26 - pr_stacktrace_test:make_throw/0 line 16 -throw:{test,exception}", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). - + Want = "pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26\n pr_stacktrace_test:make_throw/0 line 16\nthrow:{test,exception}", + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_bad_arg_test() -> - Result = try + Got = try bad_arg() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 40 - pr_stacktrace_test:bad_arg/0 line 22 -error:badarg", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). - + Want = "pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 36\n pr_stacktrace_test:bad_arg/0 line 22\nerror:badarg", + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_bad_arity_test() -> - Result = try + Got = try bad_arity() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 54 - lists:concat([], []) -error:undef", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). + Want = "pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46\n lists:concat([], [])\nerror:undef", + ?assertNotEqual(nomatch, string:str(Got, Want)). pr_stacktrace_no_reverse_test() -> application:set_env(lager, reverse_pretty_stacktrace, false), - Result = try + Got = try bad_arity() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = "error:undef - lists:concat([], []) - pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 68", - - ?assertEqual(0, string:str(Result, ExpectedPart)). + Want = "error:undef\n lists:concat([], [])\n pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 57", + ?assertEqual(nomatch, string:find(Got, Want)). From 745fd81e5dc8ef365d84961e8ffe70a777a62d9d Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 11:34:48 -0700 Subject: [PATCH 19/36] Add AppVeyor build file --- appveyor.yml | 9 +++++++++ 1 file changed, 9 insertions(+) create mode 100644 appveyor.yml diff --git a/appveyor.yml b/appveyor.yml new file mode 100644 index 0000000..0d363f0 --- /dev/null +++ b/appveyor.yml @@ -0,0 +1,9 @@ +# Windows build and test of lager + +install: + - cinst rebar3 + +test_script: + - rebar3 eunit + +deploy: false From a173cb2984846e052402ff15f63b56e63473438e Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 11:43:06 -0700 Subject: [PATCH 20/36] Cache chocolatey since Erlang takes forever to download --- appveyor.yml | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/appveyor.yml b/appveyor.yml index 0d363f0..96b51a6 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,5 +1,9 @@ # Windows build and test of lager +cache: + - C:\ProgramData\chocolatey\bin -> appveyor.yml + - C:\ProgramData\chocolatey\lib -> appveyor.yml + install: - cinst rebar3 From 22c8a2bfe479deed0000bd899f8c2df6f2ad8586 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 11:46:32 -0700 Subject: [PATCH 21/36] Tweak appveyor settings --- appveyor.yml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/appveyor.yml b/appveyor.yml index 96b51a6..e58d9d5 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -7,6 +7,8 @@ cache: install: - cinst rebar3 +build: off + test_script: - rebar3 eunit From 003a50fd31670ee486749d78e102513d73556bf1 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 11:59:40 -0700 Subject: [PATCH 22/36] Check rval with assertEqual --- src/lager_crash_log.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 6a4263e..ffacc69 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -303,8 +303,8 @@ filesystem_test_() -> sync_error_logger:error_msg("Test message\n"), _ = gen_event:which_handlers(error_logger), ?assertEqual(1, lager_test_backend:count()), - file:delete(CrashLog), - ok = lager_util:safe_write_file(CrashLog, ""), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), FInfo1 = FInfo0#file_info{mode = 0}, ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), From d6f15556e728a1177de25bf74df224d155b3d3b0 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 12:01:09 -0700 Subject: [PATCH 23/36] Caching Erlang does not work --- appveyor.yml | 6 ------ 1 file changed, 6 deletions(-) diff --git a/appveyor.yml b/appveyor.yml index e58d9d5..e78aed2 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,9 +1,3 @@ -# Windows build and test of lager - -cache: - - C:\ProgramData\chocolatey\bin -> appveyor.yml - - C:\ProgramData\chocolatey\lib -> appveyor.yml - install: - cinst rebar3 From fe1ec6812c7ff88b205610b2973edc955c4594f0 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 12:05:50 -0700 Subject: [PATCH 24/36] Do not install Erlang, instead use what is on appveyor --- appveyor.yml | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/appveyor.yml b/appveyor.yml index e78aed2..d6c2bdd 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,9 +1,6 @@ -install: - - cinst rebar3 - build: off test_script: - - rebar3 eunit + - escript rebar eunit deploy: false From 0d75a9ce77a4488d24540cc8edd5e64704d50e8f Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 12:08:57 -0700 Subject: [PATCH 25/36] Tweak appveyor --- appveyor.yml | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/appveyor.yml b/appveyor.yml index d6c2bdd..8a0d12d 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,6 +1,8 @@ build: off test_script: - - escript rebar eunit + - escript ./rebar get-deps + - escript ./rebar compile + - escript ./rebar eunit deploy: false From 9f5fcf81a8040c94afa5d6a3979a89471ca1a188 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 14:14:02 -0700 Subject: [PATCH 26/36] Skip two tests that will fail on win32 --- src/lager_file_backend.erl | 106 ++++++++++++++++++++++--------------- 1 file changed, 62 insertions(+), 44 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 579374d..8a115d1 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -77,7 +77,8 @@ check_interval = ?DEFAULT_CHECK_INTERVAL :: non_neg_integer(), sync_interval = ?DEFAULT_SYNC_INTERVAL :: non_neg_integer(), sync_size = ?DEFAULT_SYNC_SIZE :: non_neg_integer(), - last_check = os:timestamp() :: erlang:timestamp() + last_check = os:timestamp() :: erlang:timestamp(), + os_type :: atom() }). -type option() :: {file, string()} | {level, lager:log_level()} | @@ -498,32 +499,45 @@ rotation_test_() -> CheckInterval = 0, %% hard to test delayed mode {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "test.log"), - #state{name=TestLog, level=?DEBUG, sync_on=SyncLevel, - sync_size=SyncSize, sync_interval=SyncInterval, check_interval=CheckInterval, - rotator=Rotator} + {OsType, _} = os:type(), + #state{name=TestLog, + level=?DEBUG, + sync_on=SyncLevel, + sync_size=SyncSize, + sync_interval=SyncInterval, + check_interval=CheckInterval, + rotator=Rotator, + os_type=OsType} end, fun(#state{}) -> ok = lager_util:delete_test_dir() end, [ - fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> + fun(DefaultState=#state{name=TestLog, os_type=OsType, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"External rotation should work", fun() -> - {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd=FD, inode=Inode, ctime=Ctime}, - State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), - ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, State1), - ?assertEqual(ok, file:delete(TestLog)), - State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ExpState1 = #state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, - ?assertNotEqual(ExpState1, State2), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, State2), - ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), - State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ?assertNotEqual(State3, State2), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, State3), - ok + case OsType of + win32 -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + State0 = DefaultState#state{fd=FD, inode=Inode, ctime=Ctime}, + State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, State1), + ?assertEqual(ok, file:delete(TestLog)), + State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + %% assert file has changed + ExpState1 = #state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, + ?assertNotEqual(ExpState1, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State2), + ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), + State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), + %% assert file has changed + ?assertNotEqual(State3, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State3), + ok + end end} end, fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> @@ -680,29 +694,33 @@ filesystem_test_() -> end}, {"file that becomes unavailable at runtime should trigger an error message", fun() -> - {ok, TestDir} = lager_util:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(lager_event, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - lager:log(error, self(), "Test message"), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), - {ok, FInfo0} = file:read_file_info(TestLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), - lager:log(error, self(), "Test message"), - % Note: required on win32, do this early to prevent subsequent failures - % from preventing cleanup - ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be + % deleted or renamed while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, info}, {check_interval, 0}]), + ?assertEqual(0, lager_test_backend:count()), + lager:log(error, self(), "Test message"), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), + {ok, FInfo0} = file:read_file_info(TestLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), + lager:log(error, self(), "Test message"), + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) + end end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> From d25eee4ac6c32a6f73a7c94a5abe9f3434099c49 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 14:23:57 -0700 Subject: [PATCH 27/36] Skip more tests that will fail on win32 --- src/lager_crash_log.erl | 90 ++++++++++++++++++++++---------------- src/lager_file_backend.erl | 51 +++++++++++---------- 2 files changed, 81 insertions(+), 60 deletions(-) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index ffacc69..e3fdf7c 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -298,27 +298,34 @@ filesystem_test_() -> fun(CrashLog) -> {"file that becomes unavailable at runtime should trigger an error message", fun() -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(CrashLog)), - ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), - {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - % Note: required on win32, do this early to prevent subsequent failures - % from preventing cleanup - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen crash log " ++ CrashLog ++ " with error: permission denied", - lists:flatten(Message)) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + ?assertEqual(0, lager_test_backend:count()), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), + {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), + ?assertEqual(3, lager_test_backend:count()), + lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen crash log " ++ CrashLog ++ " with error: permission denied", + lists:flatten(Message)) + end end} end, fun(CrashLog) -> @@ -343,23 +350,30 @@ filesystem_test_() -> fun(CrashLog) -> {"external logfile rotation/deletion should be handled", fun() -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin} = file:read_file(CrashLog), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - ?assertEqual(ok, file:delete(CrashLog)), - ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), - sync_error_logger:error_msg("Test message1~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin1} = file:read_file(CrashLog), - ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), - file:rename(CrashLog, CrashLog ++ ".0"), - sync_error_logger:error_msg("Test message2~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin2} = file:read_file(CrashLog), - ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + ?assertEqual(0, lager_test_backend:count()), + sync_error_logger:error_msg("Test message~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin} = file:read_file(CrashLog), + ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), + sync_error_logger:error_msg("Test message1~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin1} = file:read_file(CrashLog), + ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), + file:rename(CrashLog, CrashLog ++ ".0"), + sync_error_logger:error_msg("Test message2~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin2} = file:read_file(CrashLog), + ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) + end end} end ]}. diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 8a115d1..61a895a 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -747,29 +747,36 @@ filesystem_test_() -> end}, {"external logfile rotation/deletion should be handled", fun() -> - {ok, TestDir} = lager_util:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog0 = TestLog ++ ".0", + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + TestLog0 = TestLog ++ ".0", - gen_event:add_handler(lager_event, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - lager:log(error, self(), "Test message1"), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), - lager:log(error, self(), "Test message2"), - ?assertEqual(2, lager_test_backend:count()), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - ?assertEqual(ok, file:rename(TestLog, TestLog0)), - lager:log(error, self(), "Test message3"), - ?assertEqual(3, lager_test_backend:count()), - {ok, Bin2} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])) + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, info}, {check_interval, 0}]), + ?assertEqual(0, lager_test_backend:count()), + lager:log(error, self(), "Test message1"), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), + lager:log(error, self(), "Test message2"), + ?assertEqual(2, lager_test_backend:count()), + {ok, Bin} = file:read_file(TestLog), + Pid = pid_to_list(self()), + ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], + re:split(Bin, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:rename(TestLog, TestLog0)), + lager:log(error, self(), "Test message3"), + ?assertEqual(3, lager_test_backend:count()), + {ok, Bin2} = file:read_file(TestLog), + ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], + re:split(Bin2, " ", [{return, list}, {parts, 5}])) + end end}, {"internal size rotation should work", fun() -> From 0979fd7079d5cd5862c8cf8c8a6b7f5fcbba3e24 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 2 Aug 2019 14:31:47 -0700 Subject: [PATCH 28/36] Skip one test that will fail on win32 --- src/lager_file_backend.erl | 51 ++++++++++++++++++++++---------------- 1 file changed, 29 insertions(+), 22 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 61a895a..5298c52 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -920,29 +920,36 @@ filesystem_test_() -> end}, {"tracing should not duplicate messages", fun() -> - {ok, TestDir} = lager_util:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be + % deleted or renamed while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), - gen_event:add_handler(lager_event, lager_file_backend, - [{file, TestLog}, {level, critical}, {check_interval, always}]), - timer:sleep(500), - lager:critical("Test message"), - {ok, Bin1} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin1, " ", [{return, list}, {parts, 5}])), - ok = file:delete(TestLog), - {Level, _} = lager_config:get({lager_event, loglevel}), - lager_config:set({lager_event, loglevel}, - {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), - lager:critical("Test message"), - {ok, Bin2} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])), - ok = file:delete(TestLog), - lager:error("Test message"), - {ok, Bin3} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])) + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, critical}, {check_interval, always}]), + timer:sleep(500), + lager:critical("Test message"), + {ok, Bin1} = file:read_file(TestLog), + ?assertMatch([_, _, "[critical]", _, "Test message\n"], + re:split(Bin1, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:delete(TestLog)), + {Level, _} = lager_config:get({lager_event, loglevel}), + lager_config:set({lager_event, loglevel}, + {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), + lager:critical("Test message"), + {ok, Bin2} = file:read_file(TestLog), + ?assertMatch([_, _, "[critical]", _, "Test message\n"], + re:split(Bin2, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:delete(TestLog)), + lager:error("Test message"), + {ok, Bin3} = file:read_file(TestLog), + ?assertMatch([_, _, "[error]", _, "Test message\n"], + re:split(Bin3, " ", [{return, list}, {parts, 5}])) + end end}, {"tracing to a dedicated file should work", fun() -> From 4ed9b558ac44b5a4cabf2bc82c0b604eccbb6817 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Mon, 5 Aug 2019 14:28:04 -0700 Subject: [PATCH 29/36] Remove TODO and add a second file:close due to delayed write --- src/lager_file_backend.erl | 1 - src/lager_rotator_default.erl | 1 + 2 files changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 5298c52..d8d5c2d 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -472,7 +472,6 @@ close_file(#state{fd=undefined} = State) -> State; close_file(#state{fd=FD} = State) -> %% Flush and close any file handles. - %% TODO LRB don't match, but report errors??? _ = file:datasync(FD), %% delayed write can cause file:close not to do a close _ = file:close(FD), diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 4472df7..690cc4d 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -67,6 +67,7 @@ rotate_logfile(File, 0) -> %% open the file in write-only mode to truncate/create it case file:open(File, [write]) of {ok, FD} -> + _ = file:close(FD), _ = file:close(FD), {ok, _Ctime} = maybe_update_ctime(File), ok; From e2e748f86f1fd54762bcf534deb6a3d9560157e9 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Mon, 5 Aug 2019 16:57:56 -0700 Subject: [PATCH 30/36] Ensure that all calls to rotate a log file are preceded by closing the FDs associated with it --- src/lager_file_backend.erl | 35 ++++++++++++++++++----------------- src/lager_rotator_default.erl | 2 ++ src/lager_util.erl | 1 - 3 files changed, 20 insertions(+), 18 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index d8d5c2d..4bca39e 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -191,8 +191,8 @@ handle_event(_Event, State) -> {ok, State}. %% @private -handle_info({rotate, File}, #state{name=File,count=Count,date=Date,rotator=Rotator} = State) -> - State1 = close_file(State), +handle_info({rotate, File}, #state{name=File, count=Count, date=Date, rotator=Rotator}=State0) -> + State1 = close_file(State0), _ = Rotator:rotate_logfile(File, Count), schedule_rotation(File, Date), {ok, State1}; @@ -242,40 +242,42 @@ config_to_id(Config) -> write(#state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap, size=RotSize, - count=Count, rotator=Rotator} = State, Timestamp, Level, Msg) -> - case write_should_check(State, Timestamp) of + count=Count, rotator=Rotator}=State0, Timestamp, Level, Msg) -> + case write_should_check(State0, Timestamp) of true -> %% need to check for rotation - Buffer = {State#state.sync_size, State#state.sync_interval}, + Buffer = {State0#state.sync_size, State0#state.sync_interval}, case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of - {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize > 0, Size > RotSize -> + State1 = close_file(State0), case Rotator:rotate_logfile(Name, Count) of ok -> %% go around the loop again, we'll do another rotation check and hit the next clause of ensure_logfile - write(State, Timestamp, Level, Msg); + write(State1, Timestamp, Level, Msg); {error, Reason} -> case Flap of true -> - State; + State1; _ -> ?INT_LOG(error, "Failed to rotate log file ~s with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State1#state{flap=true} end end; {ok, {NewFD, NewInode, NewCtime, _Size}} -> %% update our last check and try again - do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode, ctime=NewCtime}, Level, Msg); + State1 = State0#state{last_check=Timestamp, fd=NewFD, inode=NewInode, ctime=NewCtime}, + do_write(State1, Level, Msg); {error, Reason} -> case Flap of true -> - State; + State0; _ -> ?INT_LOG(error, "Failed to reopen log file ~s with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State0#state{flap=true} end end; false -> - do_write(State, Level, Msg) + do_write(State0, Level, Msg) end. write_should_check(#state{fd=undefined}, _Timestamp) -> @@ -287,8 +289,7 @@ write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, true -> true; _ -> - % TODO this code is duplicated in the default rotator, but we need - % to know if the file has changed "out from under lager" so we don't + % We need to know if the file has changed "out from under lager" so we don't % write to an invalid FD {Result, _FInfo} = lager_util:has_file_changed(Name, Inode0, Ctime0), Result @@ -298,7 +299,7 @@ do_write(#state{fd=FD, name=Name, flap=Flap} = State, Level, Msg) -> %% delayed_write doesn't report errors _ = file:write(FD, unicode:characters_to_binary(Msg)), {mask, SyncLevel} = State#state.sync_on, - case (Level band SyncLevel) /= 0 of + case (Level band SyncLevel) =/= 0 of true -> %% force a sync on any message that matches the 'sync_on' bitmask Flap2 = case file:datasync(FD) of @@ -472,8 +473,8 @@ close_file(#state{fd=undefined} = State) -> State; close_file(#state{fd=FD} = State) -> %% Flush and close any file handles. - _ = file:datasync(FD), %% delayed write can cause file:close not to do a close + _ = file:datasync(FD), _ = file:close(FD), _ = file:close(FD), State#state{fd=undefined}. diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 690cc4d..738585f 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -50,7 +50,9 @@ ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> end. reopen_logfile(Name, FD0, Buffer) -> + %% Flush and close any file handles. %% delayed write can cause file:close not to do a close + _ = file:datasync(FD0), _ = file:close(FD0), _ = file:close(FD0), case open_logfile(Name, Buffer) of diff --git a/src/lager_util.erl b/src/lager_util.erl index 5901d1a..715fecc 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -930,7 +930,6 @@ do_delete_file(FsElem, Attempts) -> case file:delete(FsElem) of ok -> ok; Error -> - io:format(standard_error, "@@@@@@@@ DELETE FILE ~p ERROR ~p~n", [FsElem, Error]), do_delete_file(FsElem, Attempts - 1) end. From f23e3e677c60ffc83f09f072b49449f0c59945fe Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Mon, 5 Aug 2019 16:57:56 -0700 Subject: [PATCH 31/36] Ensure that all calls to rotate a log file are preceded by closing the FDs associated with it --- test/pr_stacktrace_test.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/pr_stacktrace_test.erl b/test/pr_stacktrace_test.erl index 468d61f..2853a22 100644 --- a/test/pr_stacktrace_test.erl +++ b/test/pr_stacktrace_test.erl @@ -49,7 +49,7 @@ pr_stacktrace_bad_arity_test() -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, Want = "pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46\n lists:concat([], [])\nerror:undef", - ?assertNotEqual(nomatch, string:str(Got, Want)). + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_no_reverse_test() -> application:set_env(lager, reverse_pretty_stacktrace, false), From 1a8e47d245e7a0debc727987dde179b107702309 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 8 Aug 2019 12:46:12 -0700 Subject: [PATCH 32/36] Add 3.8.0 change log entries --- README.md | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/README.md b/README.md index 8f6cf42..c17ecb2 100644 --- a/README.md +++ b/README.md @@ -1141,6 +1141,16 @@ Example Usage: 3.x Changelog ------------- +3.8.0 - 12 August 2019 + + * API change: Modify the `lager_rotator_behaviour` to pass in a file's creation + time to `ensure_logfile/5` to be used to determine if file has changed on + systems where inodes are not available (i.e. `win32`). The return value from + `create_logfile/2`, `open_logfile/2` and `ensure_logfile/5` now requires + ctime to be returned (#509) + * Bugfix: ensure log file rotation works on `win32` (#509) + * Bugfix: ensure test suite passes on `win32` (#509) + 3.7.0 - 24 May 2019 * Policy: Officially ending support for OTP 19 (Support OTP 20, 21, 22) From c3d712b3e31483009b25e42ea88c29f6ceb463b4 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 8 Aug 2019 15:25:39 -0700 Subject: [PATCH 33/36] Add a sleep to (maybe) fix a test on Travis CI --- test/lager_test_backend.erl | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 69489b9..1a21238 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1790,7 +1790,7 @@ async_threshold_test_() -> %% serialize on mailbox _ = gen_event:which_handlers(lager_event), - timer:sleep(500), + timer:sleep(1000), %% By now the flood of messages should have forced the backend throttle %% to turn off async mode, but it's possible all outstanding requests @@ -1812,6 +1812,7 @@ async_threshold_test_() -> timer:sleep(1000), lager:info("hello world"), _ = gen_event:which_handlers(lager_event), + timer:sleep(1000), %% async is true again now that the mailbox has drained ?assertEqual(true, lager_config:get(async)), From 9991ac45715c2767e883124fd5faf40cae297b55 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Thu, 8 Aug 2019 16:44:27 -0700 Subject: [PATCH 34/36] Really bump up sleeps to fix tests on Travis CI --- test/lager_test_backend.erl | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 1a21238..6ecd633 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1790,7 +1790,7 @@ async_threshold_test_() -> %% serialize on mailbox _ = gen_event:which_handlers(lager_event), - timer:sleep(1000), + timer:sleep(5000), %% By now the flood of messages should have forced the backend throttle %% to turn off async mode, but it's possible all outstanding requests @@ -1807,12 +1807,12 @@ async_threshold_test_() -> %% serialize on the mailbox again _ = gen_event:which_handlers(lager_event), + timer:sleep(5000), - %% just in case... - timer:sleep(1000), lager:info("hello world"), + _ = gen_event:which_handlers(lager_event), - timer:sleep(1000), + timer:sleep(5000), %% async is true again now that the mailbox has drained ?assertEqual(true, lager_config:get(async)), From aa09a2cd9c7c5a613db9026c7546eedb48b3d8ff Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Fri, 9 Aug 2019 12:17:38 -0700 Subject: [PATCH 35/36] Only sleep for a long time when CI env variable is present, like on Travis CI --- test/lager_test_backend.erl | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 6ecd633..94dd22e 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1776,6 +1776,8 @@ async_threshold_test_() -> {foreach, Setup, Cleanup, [ {"async threshold works", {timeout, 30, fun() -> + Sleep = get_long_sleep_value(), + %% we start out async ?assertEqual(true, lager_config:get(async)), ?assertEqual([{sync_toggled, 0}], @@ -1790,7 +1792,7 @@ async_threshold_test_() -> %% serialize on mailbox _ = gen_event:which_handlers(lager_event), - timer:sleep(5000), + timer:sleep(Sleep), %% By now the flood of messages should have forced the backend throttle %% to turn off async mode, but it's possible all outstanding requests @@ -1807,12 +1809,12 @@ async_threshold_test_() -> %% serialize on the mailbox again _ = gen_event:which_handlers(lager_event), - timer:sleep(5000), + timer:sleep(Sleep), lager:info("hello world"), _ = gen_event:which_handlers(lager_event), - timer:sleep(5000), + timer:sleep(Sleep), %% async is true again now that the mailbox has drained ?assertEqual(true, lager_config:get(async)), @@ -1904,4 +1906,12 @@ high_watermark_test_() -> ] }. +get_long_sleep_value() -> + case os:getenv("CI") of + false -> + 500; + _ -> + 5000 + end. + -endif. From fc6221c92ce125462c1f0ce3c944c21cfb8e69b6 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 9 Aug 2019 22:39:05 -0500 Subject: [PATCH 36/36] Fixup --- src/lager_file_backend.erl | 4 ++-- src/lager_util.erl | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 093a3a5..6b1ab17 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -260,7 +260,7 @@ write(#state{name=Name, fd=FD, State1; _ -> ?INT_LOG(error, "Failed to rotate log file ~ts with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State1#state{flap=true} end end; {ok, {NewFD, NewInode, NewCtime, _Size}} -> @@ -273,7 +273,7 @@ write(#state{name=Name, fd=FD, State0; _ -> ?INT_LOG(error, "Failed to reopen log file ~ts with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State0#state{flap=true} end end; false -> diff --git a/src/lager_util.erl b/src/lager_util.erl index 715fecc..21e84b7 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -929,7 +929,7 @@ do_delete_file(_FsElem, 0) -> do_delete_file(FsElem, Attempts) -> case file:delete(FsElem) of ok -> ok; - Error -> + _Error -> do_delete_file(FsElem, Attempts - 1) end.