From 990210faa9b97908d2a07099fd0176385eaffec1 Mon Sep 17 00:00:00 2001 From: Luke Bakken Date: Tue, 30 Jul 2019 16:57:43 -0700 Subject: [PATCH] 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).