diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index a541be1..67289cc 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -1,4 +1,6 @@ -%% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved. +%% ------------------------------------------------------------------- +%% +%% 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 @@ -13,6 +15,8 @@ %% KIND, either express or implied. See the License for the %% specific language governing permissions and limitations %% under the License. +%% +%% ------------------------------------------------------------------- %% @doc Lager crash log writer. This module implements a gen_server which writes %% error_logger error messages out to a file in their original format. The @@ -236,105 +240,118 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, filesystem_test_() -> {foreach, fun() -> - file:write_file("crash_test.log", ""), - 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(100), - lager_test_backend:flush() - end, - fun(_) -> - case whereis(lager_crash_log) of - P when is_pid(P) -> - exit(P, kill); - _ -> ok - end, - file:delete("crash_test.log"), - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) + 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(100), + lager_test_backend:flush(), + CrashLog end, - [ + fun(CrashLog) -> + case whereis(lager_crash_log) of + P when is_pid(P) -> + exit(P, kill); + _ -> + ok + end, + application:stop(lager), + application:stop(goldrush), + lager_util:delete_test_dir(filename:dirname(CrashLog)), + error_logger:tty(true) + end, [ + fun(CrashLog) -> {"under normal circumstances, file should be opened", - fun() -> - {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - _ = gen_event:which_handlers(error_logger), - sync_error_logger:error_msg("Test message\n"), - {ok, Bin} = file:read_file("crash_test.log"), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) - end - }, + fun() -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0), + _ = gen_event:which_handlers(error_logger), + sync_error_logger:error_msg("Test message\n"), + {ok, Bin} = file:read_file(CrashLog), + ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) + end} + end, + fun(CrashLog) -> {"file can't be opened on startup triggers an error message", - fun() -> - {ok, FInfo} = file:read_file_info("crash_test.log"), - file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), - {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)) - end - }, + fun() -> + {ok, FInfo} = file:read_file_info(CrashLog), + file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to open crash log file " ++ CrashLog ++ " with error: permission denied", + lists:flatten(Message)) + end} + end, + fun(CrashLog) -> {"file that becomes unavailable at runtime should trigger an error message", - fun() -> - {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - ?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()), - file:delete("crash_test.log"), - file:write_file("crash_test.log", ""), - {ok, FInfo} = file:read_file_info("crash_test.log"), - file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual("Failed to reopen crash log crash_test.log with error: permission denied", lists:flatten(Message)) - end - }, + fun() -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0), + ?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()), + file:delete(CrashLog), + file:write_file(CrashLog, ""), + {ok, FInfo} = file:read_file_info(CrashLog), + file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), + ?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, + fun(CrashLog) -> {"unavailable files that are fixed at runtime should start having log messages written", - fun() -> - {ok, FInfo} = file:read_file_info("crash_test.log"), - OldPerms = FInfo#file_info.mode, - file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), - {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)), - file:write_file_info("crash_test.log", FInfo#file_info{mode = OldPerms}), - sync_error_logger:error_msg("Test message~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin} = file:read_file("crash_test.log"), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) - end - }, + fun() -> + {ok, FInfo} = file:read_file_info(CrashLog), + OldPerms = FInfo#file_info.mode, + file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to open crash log file " ++ CrashLog ++ " with error: permission denied", + lists:flatten(Message)), + file:write_file_info(CrashLog, FInfo#file_info{mode = OldPerms}), + 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}])) + end} + end, + fun(CrashLog) -> {"external logfile rotation/deletion should be handled", - fun() -> - {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), - ?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("crash_test.log"), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - file:delete("crash_test.log"), - file:write_file("crash_test.log", ""), - sync_error_logger:error_msg("Test message1~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin1} = file:read_file("crash_test.log"), - ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), - file:rename("crash_test.log", "crash_test.log.0"), - sync_error_logger:error_msg("Test message2~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin2} = file:read_file("crash_test.log"), - ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) - end - } - ] - }. + fun() -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0), + ?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}])), + file:delete(CrashLog), + file: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 + ]}. -endif. diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 56dbd6c..21fddcf 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -1,4 +1,6 @@ -%% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved. +%% ------------------------------------------------------------------- +%% +%% 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 @@ -13,6 +15,8 @@ %% KIND, either express or implied. See the License for the %% specific language governing permissions and limitations %% under the License. +%% +%% ------------------------------------------------------------------- %% @doc File backend for lager, with multiple file support. %% Multiple files are supported, each with the path and the loglevel being @@ -424,85 +428,87 @@ get_loglevel_test() -> rotation_test_() -> {foreach, - fun() -> - [file:delete(F)||F <- filelib:wildcard("test.log*")], - SyncLevel = validate_loglevel(?DEFAULT_SYNC_LEVEL), - SyncSize = ?DEFAULT_SYNC_SIZE, - SyncInterval = ?DEFAULT_SYNC_INTERVAL, - CheckInterval = 0, %% hard to test delayed mode - - #state{name="test.log", level=?DEBUG, sync_on=SyncLevel, - sync_size=SyncSize, sync_interval=SyncInterval, check_interval=CheckInterval} - - end, - fun(_) -> - [file:delete(F)||F <- filelib:wildcard("test.log*")] - end, - [fun(DefaultState = #state{sync_size=SyncSize, sync_interval = SyncInterval}) -> - {"External rotation should work", - fun() -> - {ok, {FD, Inode, _}} = lager_util:open_logfile("test.log", {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd=FD, inode=Inode}, - ?assertMatch(#state{name="test.log", level=?DEBUG, fd=FD, inode=Inode}, - write(State0, os:timestamp(), ?DEBUG, "hello world")), - file:delete("test.log"), - Result = write(State0, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ?assert(#state{name="test.log", level=?DEBUG, fd=FD, inode=Inode} =/= Result), - ?assertMatch(#state{name="test.log", level=?DEBUG}, Result), - file:rename("test.log", "test.log.1"), - Result2 = write(Result, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ?assert(Result =/= Result2), - ?assertMatch(#state{name="test.log", level=?DEBUG}, Result2), - ok - end} - end, - fun(DefaultState = #state{sync_size=SyncSize, sync_interval = SyncInterval}) -> - {"Internal rotation and delayed write", - fun() -> - CheckInterval = 3000, % 3 sec - RotationSize = 15, - PreviousCheck = os:timestamp(), - - {ok, {FD, Inode, _}} = lager_util:open_logfile("test.log", {SyncSize, SyncInterval}), - State0 = DefaultState#state{ - fd=FD, inode=Inode, 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"), - - %% 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"), - - %% although file size is big enough... - {ok, FInfo} = file:read_file_info("test.log"), - ?assert(RotationSize < FInfo#file_info.size), - %% ...no rotation yet - ?assertEqual(PreviousCheck, State2#state.last_check), - ?assertNot(filelib:is_regular("test.log.0")), - - %% new message after check interval - Msg3Timestamp = add_secs(PreviousCheck, 4), - _State3 = write(State2, Msg3Timestamp, ?DEBUG, "message 3"), - - %% rotation happened - ?assert(filelib:is_regular("test.log.0")), - - {ok, Bin1} = file:read_file("test.log.0"), - {ok, Bin2} = file:read_file("test.log"), - %% message 1-3 written to file - ?assertEqual(<<"big big message 1buffered message 2">>, Bin1), - %% message 4 buffered, not yet written to file - ?assertEqual(<<"">>, Bin2), - ok - end} - end - ]}. + fun() -> + SyncLevel = validate_loglevel(?DEFAULT_SYNC_LEVEL), + SyncSize = ?DEFAULT_SYNC_SIZE, + SyncInterval = ?DEFAULT_SYNC_INTERVAL, + CheckInterval = 0, %% hard to test delayed mode + 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} + + end, + fun(#state{name=TestLog}) -> + lager_util:delete_test_dir(filename:dirname(TestLog)) + end, [ + fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval}) -> + {"External rotation should work", + fun() -> + {ok, {FD, Inode, _}} = lager_util: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), + 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"), + Result2 = write(Result, os:timestamp(), ?DEBUG, "hello world"), + %% assert file has changed + ?assert(Result =/= Result2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result2), + ok + end} + end, + fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval}) -> + {"Internal rotation and delayed write", + fun() -> + TestLog0 = TestLog ++ ".0", + CheckInterval = 3000, % 3 sec + RotationSize = 15, + PreviousCheck = os:timestamp(), + + {ok, {FD, Inode, _}} = lager_util:open_logfile(TestLog, {SyncSize, SyncInterval}), + State0 = DefaultState#state{ + fd=FD, inode=Inode, 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"), + + %% 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"), + + %% although file size is big enough... + {ok, FInfo} = file:read_file_info(TestLog), + ?assert(RotationSize < FInfo#file_info.size), + %% ...no rotation yet + ?assertEqual(PreviousCheck, State2#state.last_check), + ?assertNot(filelib:is_regular(TestLog0)), + + %% new message after check interval + Msg3Timestamp = add_secs(PreviousCheck, 4), + _State3 = write(State2, Msg3Timestamp, ?DEBUG, "message 3"), + + %% rotation happened + ?assert(filelib:is_regular(TestLog0)), + + {ok, Bin1} = file:read_file(TestLog0), + {ok, Bin2} = file:read_file(TestLog), + %% message 1-3 written to file + ?assertEqual(<<"big big message 1buffered message 2">>, Bin1), + %% message 4 buffered, not yet written to file + ?assertEqual(<<"">>, Bin2), + ok + end} + end + ]}. add_secs({Mega, Secs, Micro}, Add) -> NewSecs = Secs + Add, @@ -511,397 +517,514 @@ add_secs({Mega, Secs, Micro}, Add) -> filesystem_test_() -> {foreach, fun() -> - file:write_file("test.log", ""), - file:delete("foo.log"), - file:delete("foo.log.0"), - file:delete("foo.log.1"), - 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), - lager:start(), - %% race condition where lager logs its own start up - %% makes several tests fail. See test/lager_test_backend - %% around line 800 for more information. - timer:sleep(5), - lager_test_backend:flush() + 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), + lager:start(), + %% race condition where lager logs its own start up + %% makes several tests fail. See test/lager_test_backend + %% around line 800 for more information. + timer:sleep(5), + lager_test_backend:flush() end, fun(_) -> - file:delete("test.log"), - file:delete("test.log.0"), - file:delete("test.log.1"), - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end, - [ - {"under normal circumstances, file should be opened", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}, {lager_default_formatter}]), - lager:log(error, self(), "Test message"), - {ok, Bin} = file:read_file("test.log"), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) - end - }, - {"don't choke on unicode", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}, {lager_default_formatter}]), - lager:log(error, self(),"~ts", [[20013,25991,27979,35797]]), - {ok, Bin} = file:read_file("test.log"), - 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}])) - end - }, - {"don't choke on latin-1", - fun() -> - %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! - gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}, {lager_default_formatter}]), - lager:log(error, self(),"~ts", [[76, 198, 221, 206, 78, $-, 239]]), - {ok, Bin} = file:read_file("test.log"), - 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) - end - }, - {"file can't be opened on startup triggers an error message", - fun() -> - {ok, FInfo} = file:read_file_info("test.log"), - file:write_file_info("test.log", FInfo#file_info{mode = 0}), - gen_event:add_handler(lager_event, lager_file_backend, {"test.log", info, 10*1024*1024, "$D0", 5}), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time,Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)) - end - }, - {"file that becomes unavailable at runtime should trigger an error message", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - lager:log(error, self(), "Test message"), - ?assertEqual(1, lager_test_backend:count()), - file:delete("test.log"), - file:write_file("test.log", ""), - {ok, FInfo} = file:read_file_info("test.log"), - file:write_file_info("test.log", FInfo#file_info{mode = 0}), - lager:log(error, self(), "Test message"), - ?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 test.log with error permission denied", lists:flatten(Message)) - end - }, - {"unavailable files that are fixed at runtime should start having log messages written", - fun() -> - {ok, FInfo} = file:read_file_info("test.log"), - OldPerms = FInfo#file_info.mode, - file:write_file_info("test.log", FInfo#file_info{mode = 0}), - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"},{check_interval, 0}]), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), - ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)), - file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}), - lager:log(error, self(), "Test message"), - {ok, Bin} = file:read_file("test.log"), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) - end - }, - {"external logfile rotation/deletion should be handled", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - lager:log(error, self(), "Test message1"), - ?assertEqual(1, lager_test_backend:count()), - file:delete("test.log"), - file:write_file("test.log", ""), - lager:log(error, self(), "Test message2"), - {ok, Bin} = file:read_file("test.log"), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])), - file:rename("test.log", "test.log.0"), - lager:log(error, self(), "Test message3"), - {ok, Bin2} = file:read_file("test.log"), - ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}])) - end - }, - {"internal size rotation should work", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {check_interval, 0}, {size, 10}]), - lager:log(error, self(), "Test message1"), - lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular("test.log.0")) - end - }, - {"internal time rotation should work", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {check_interval, 1000}]), - lager:log(error, self(), "Test message1"), - lager:log(error, self(), "Test message1"), - whereis(lager_event) ! {rotate, "test.log"}, - lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular("test.log.0")) - end - }, - {"rotation call should work", - fun() -> - gen_event:add_handler(lager_event, {lager_file_backend, "test.log"}, [{file, "test.log"}, {level, info}, {check_interval, 1000}]), - lager:log(error, self(), "Test message1"), - lager:log(error, self(), "Test message1"), - gen_event:call(lager_event, {lager_file_backend, "test.log"}, rotate, infinity), - lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular("test.log.0")) - end - }, - {"sync_on option should work", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {sync_on, "=info"}, {check_interval, 5000}, {sync_interval, 5000}]), - lager:log(error, self(), "Test message1"), - lager:log(error, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - lager:log(info, self(), "Test message1"), - {ok, Bin} = file:read_file("test.log"), - ?assert(<<>> /= Bin) - end - }, - {"sync_on none option should work (also tests sync_interval)", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {sync_on, "none"}, {check_interval, 5000}, {sync_interval, 1000}]), - lager:log(error, self(), "Test message1"), - lager:log(error, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - lager:log(info, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - timer:sleep(2000), - {ok, Bin} = file:read_file("test.log"), - ?assert(<<>> /= Bin) - end - }, - {"sync_size option should work", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {sync_on, "none"}, {check_interval, 5001}, {sync_size, 640}, {sync_interval, 5001}]), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - lager:log(error, self(), "Test messageis64bytes"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - %% now we've written enough bytes - lager:log(error, self(), "Test messageis64bytes"), - {ok, Bin} = file:read_file("test.log"), - ?assert(<<>> /= Bin) - end - }, - {"runtime level changes", - fun() -> - gen_event:add_handler(lager_event, {lager_file_backend, "test.log"}, {"test.log", info}), - ?assertEqual(0, lager_test_backend:count()), - lager:log(info, self(), "Test message1"), - lager:log(error, self(), "Test message2"), - {ok, Bin} = file:read_file("test.log"), - Lines = length(re:split(Bin, "\n", [{return, list}, trim])), - ?assertEqual(Lines, 2), - ?assertEqual(ok, lager:set_loglevel(lager_file_backend, "test.log", warning)), - lager:log(info, self(), "Test message3"), %% this won't get logged - lager:log(error, self(), "Test message4"), - {ok, Bin2} = file:read_file("test.log"), - Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])), - ?assertEqual(Lines2, 3) - end - }, - {"invalid runtime level changes", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info, 10*1024*1024, "$D0", 5}, {lager_default_formatter}]), - gen_event:add_handler(lager_event, lager_file_backend, {"test3.log", info}), - ?assertEqual({error, bad_module}, lager:set_loglevel(lager_file_backend, "test.log", warning)) - end - }, - {"tracing should work", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, - {"test.log", critical}), - lager:error("Test message"), - ?assertEqual({ok, <<>>}, file:read_file("test.log")), - {Level, _} = lager_config:get({lager_event, loglevel}), - lager_config:set({lager_event, loglevel}, {Level, [{[{module, - ?MODULE}], ?DEBUG, - {lager_file_backend, "test.log"}}]}), - lager:error("Test message"), - timer:sleep(1000), - {ok, Bin} = file:read_file("test.log"), - ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) - end - }, - {"tracing should not duplicate messages", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend, - [{file, "test.log"}, {level, critical}, {check_interval, always}]), - lager:critical("Test message"), - {ok, Bin1} = file:read_file("test.log"), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], re:split(Bin1, " ", [{return, list}, {parts, 5}])), - ok = file:delete("test.log"), - {Level, _} = lager_config:get({lager_event, loglevel}), - lager_config:set({lager_event, loglevel}, {Level, [{[{module, - ?MODULE}], ?DEBUG, - {lager_file_backend, "test.log"}}]}), - lager:critical("Test message"), - {ok, Bin2} = file:read_file("test.log"), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}])), - ok = file:delete("test.log"), - lager:error("Test message"), - {ok, Bin3} = file:read_file("test.log"), - ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end - }, - {"tracing to a dedicated file should work", - fun() -> - file:delete("foo.log"), - {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}]), - lager:error("Test message"), - %% not elegible for trace - lager:log(error, self(), "Test message"), - {ok, Bin3} = file:read_file("foo.log"), - ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end - }, - {"tracing to a dedicated file should work even if root_log is set", - fun() -> - {ok, P} = file:get_cwd(), - file:delete(P ++ "/test_root_log/foo.log"), - application:set_env(lager, log_root, P++"/test_root_log"), - {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}]), - lager:error("Test message"), - %% not elegible for trace - lager:log(error, self(), "Test message"), - {ok, Bin3} = file:read_file(P++"/test_root_log/foo.log"), - application:unset_env(lager, log_root), - ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end - }, - {"tracing with options should work", - fun() -> - file:delete("foo.log"), - {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}], [{size, 20}, {check_interval, 1}]), - lager:error("Test message"), - ?assertNot(filelib:is_regular("foo.log.0")), - %% rotation is sensitive to intervals between - %% writes so we sleep to exceed the 1 - %% millisecond interval specified by - %% check_interval above - timer:sleep(2), - lager:error("Test message"), - timer:sleep(10), - ?assert(filelib:is_regular("foo.log.0")) - end - } - ] - }. + application:stop(lager), + application:stop(goldrush), + error_logger:tty(true) + end, [ + {"under normal circumstances, file should be opened", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{TestLog, info}, {lager_default_formatter}]), + lager:log(error, self(), "Test message"), + {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) + end}, + {"don't choke on unicode", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{TestLog, info}, {lager_default_formatter}]), + lager:log(error, self(),"~ts", [[20013,25991,27979,35797]]), + {ok, Bin} = file:read_file(TestLog), + 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) + end}, + {"don't choke on latin-1", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! + gen_event:add_handler(lager_event, lager_file_backend, + [{TestLog, info}, {lager_default_formatter}]), + lager:log(error, self(),"~ts", [[76, 198, 221, 206, 78, $-, 239]]), + {ok, Bin} = file:read_file(TestLog), + 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) + end}, + {"file can't be opened on startup triggers an error message", + fun() -> + TestDir = lager_util:create_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}), + 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(), + ?assertEqual( + "Failed to open log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)), + + lager_util:delete_test_dir(TestDir) + end}, + {"file that becomes unavailable at runtime should trigger an error message", + fun() -> + TestDir = lager_util:create_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()), + 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) + end}, + {"unavailable files that are fixed at runtime should start having log messages written", + fun() -> + TestDir = lager_util:create_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}), + 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(), + ?assertEqual( + "Failed to open log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)), + 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()), + ?assertMatch([_, _, "[error]", Pid, "Test message\n"], + re:split(Bin, " ", [{return, list}, {parts, 5}])), + + lager_util:delete_test_dir(TestDir) + end}, + {"external logfile rotation/deletion should be handled", + fun() -> + TestDir = lager_util:create_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()), + file:delete(TestLog), + 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), + 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) + end}, + {"internal size rotation should work", + fun() -> + TestDir = lager_util:create_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}, {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) + end}, + {"internal time rotation should work", + fun() -> + TestDir = lager_util:create_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, 1000}]), + lager:log(error, self(), "Test message1"), + 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) + end}, + {"rotation call should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + TestLog0 = TestLog ++ ".0", + + gen_event:add_handler(lager_event, {lager_file_backend, TestLog}, + [{file, TestLog}, {level, info}, {check_interval, 1000}]), + lager:log(error, self(), "Test message1"), + 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) + end}, + {"sync_on option should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, + {level, info}, {sync_on, "=info"}, {check_interval, 5000}, {sync_interval, 5000}]), + lager:log(error, self(), "Test message1"), + lager:log(error, self(), "Test message1"), + ?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) + end}, + {"sync_on none option should work (also tests sync_interval)", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, + {level, info}, {sync_on, "none"}, {check_interval, 5000}, {sync_interval, 1000}]), + lager:log(error, self(), "Test message1"), + lager:log(error, self(), "Test message1"), + ?assertEqual({ok, <<>>}, file:read_file(TestLog)), + lager:log(info, self(), "Test message1"), + ?assertEqual({ok, <<>>}, file:read_file(TestLog)), + timer:sleep(2000), + {ok, Bin} = file:read_file(TestLog), + ?assert(<<>> /= Bin), + + lager_util:delete_test_dir(TestDir) + end}, + {"sync_size option should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, + {sync_on, "none"}, {check_interval, 5001}, {sync_size, 640}, {sync_interval, 5001}]), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + ?assertEqual({ok, <<>>}, file:read_file(TestLog)), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + lager:log(error, self(), "Test messageis64bytes"), + ?assertEqual({ok, <<>>}, file:read_file(TestLog)), + %% 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) + end}, + {"runtime level changes", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, {lager_file_backend, TestLog}, {TestLog, info}), + ?assertEqual(0, lager_test_backend:count()), + lager:log(info, self(), "Test message1"), + lager:log(error, self(), "Test message2"), + {ok, Bin} = file:read_file(TestLog), + Lines = length(re:split(Bin, "\n", [{return, list}, trim])), + ?assertEqual(Lines, 2), + ?assertEqual(ok, lager:set_loglevel(lager_file_backend, TestLog, warning)), + lager:log(info, self(), "Test message3"), %% this won't get logged + 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) + end}, + {"invalid runtime level changes", + fun() -> + TestDir = lager_util:create_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) + end}, + {"tracing should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, {TestLog, critical}), + lager:error("Test message"), + ?assertEqual({ok, <<>>}, file:read_file(TestLog)), + {Level, _} = lager_config:get({lager_event, loglevel}), + lager_config:set({lager_event, loglevel}, {Level, + [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), + lager:error("Test message"), + 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) + end}, + {"tracing should not duplicate messages", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, critical}, {check_interval, always}]), + 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}])), + + lager_util:delete_test_dir(TestDir) + end}, + {"tracing to a dedicated file should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "foo.log"), + + {ok, _} = lager:trace_file(TestLog, [{module, ?MODULE}]), + lager:error("Test message"), + %% not eligible for trace + 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) + end}, + {"tracing to a dedicated file should work even if root_log is set", + fun() -> + TestDir = lager_util:create_test_dir(), + LogName = "foo.log", + LogPath = filename:join(TestDir, LogName), + + application:set_env(lager, log_root, TestDir), + {ok, _} = lager:trace_file(LogName, [{module, ?MODULE}]), + lager:error("Test message"), + %% not eligible for trace + lager:log(error, self(), "Test message"), + {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) + end}, + {"tracing with options should work", + fun() -> + TestDir = lager_util:create_test_dir(), + TestLog = filename:join(TestDir, "foo.log"), + TestLog0 = TestLog ++ ".0", + + {ok, _} = lager:trace_file(TestLog, [{module, ?MODULE}], + [{size, 20}, {check_interval, 1}]), + lager:error("Test message"), + ?assertNot(filelib:is_regular(TestLog0)), + %% rotation is sensitive to intervals between + %% writes so we sleep to exceed the 1 + %% millisecond interval specified by + %% check_interval above + timer:sleep(2), + lager:error("Test message"), + timer:sleep(10), + ?assert(filelib:is_regular(TestLog0)), + + lager_util:delete_test_dir(TestDir) + end} + ]}. trace_files_test_() -> {foreach, fun() -> - file:delete("events.log"), - file:delete("test.log"), - file:delete("debug.log"), - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_file_backend, [{file, "test.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.log"}, [{module, ?MODULE}] - }, - { % Handler Filters Level - {lager_file_backend, "events.log"}, [{module, ?MODULE}], notice - } - ] - ), - application:set_env(lager, async_threshold, undefined), - lager:start() - end, - fun(_) -> - catch ets:delete(lager_config), - application:unset_env(lager, traces), - application:stop(lager), - - file:delete("events.log"), - file:delete("test.log"), - file:delete("debug.log"), - error_logger:tty(true) + Dir = lager_util:create_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} end, - [ + fun({Dir, _, _, _}) -> + catch ets:delete(lager_config), + application:unset_env(lager, traces), + application:stop(lager), + + lager_util:delete_test_dir(Dir), + error_logger:tty(true) + end, [ + fun({_, Log, Debug, Events}) -> {"a trace using file backend set up in configuration should work", - fun() -> - lager:error("trace test error message"), - lager:info("info message"), - %% not eligible for trace - lager:log(error, self(), "Not trace test message"), - {ok, BinInfo} = file:read_file("events.log"), - ?assertMatch([_, _, "[error]", _, "trace test error message\n"], - re:split(BinInfo, " ", [{return, list}, {parts, 5}])), - ?assert(filelib:is_regular("test.log")), - {ok, BinInfo2} = file:read_file("test.log"), - ?assertMatch(["trace test error message", "Not trace test message\n"], - re:split(BinInfo2, "\n", [{return, list}, {parts, 2}])), - ?assert(filelib:is_regular("debug.log")), - %% XXX Aughhhh, wish I could force this to flush somehow... - timer:sleep(1000), - {ok, BinInfo3} = file:read_file("debug.log"), - ?assertEqual(2, length(re:split(BinInfo3, "\n", [{return, list}, trim]))) - end - } - ] - }. + fun() -> + lager:error("trace test error message"), + lager:info("info message"), + %% not eligible for trace + lager:log(error, self(), "Not trace test message"), + {ok, BinInfo} = file:read_file(Events), + ?assertMatch([_, _, "[error]", _, "trace test error message\n"], + re:split(BinInfo, " ", [{return, list}, {parts, 5}])), + ?assert(filelib:is_regular(Log)), + {ok, BinInfo2} = file:read_file(Log), + ?assertMatch(["trace test error message", "Not trace test message\n"], + re:split(BinInfo2, "\n", [{return, list}, {parts, 2}])), + ?assert(filelib:is_regular(Debug)), + %% XXX Aughhhh, wish I could force this to flush somehow... + timer:sleep(1000), + {ok, BinInfo3} = file:read_file(Debug), + ?assertEqual(2, length(re:split(BinInfo3, "\n", [{return, list}, trim]))) + end} + end + ]}. formatting_test_() -> {foreach, fun() -> - file:write_file("test.log", ""), - file:write_file("test2.log", ""), - 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(), - %% same race condition issue - timer:sleep(5) - end, - fun(_) -> - file:delete("test.log"), - file:delete("test2.log"), - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) + Dir = lager_util:create_test_dir(), + Log1 = filename:join(Dir, "test.log"), + Log2 = filename:join(Dir, "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(), + %% same race condition issue + timer:sleep(5), + {Dir, Log1, Log2} end, - [{"Should have two log files, the second prefixed with 2>", - fun() -> - gen_event:add_handler(lager_event, lager_file_backend,[{"test.log", debug},{lager_default_formatter,["[",severity,"] ", message, "\n"]}]), - gen_event:add_handler(lager_event, lager_file_backend,[{"test2.log", debug},{lager_default_formatter,["2> [",severity,"] ", message, "\n"]}]), - lager:log(error, self(), "Test message"), - ?assertMatch({ok, <<"[error] Test message\n">>},file:read_file("test.log")), - ?assertMatch({ok, <<"2> [error] Test message\n">>},file:read_file("test2.log")) - end - } - ]}. + fun({Dir, _, _}) -> + application:stop(lager), + application:stop(goldrush), + lager_util:delete_test_dir(Dir), + error_logger:tty(true) + end, [ + fun({_, Log1, Log2}) -> + {"Should have two log files, the second prefixed with 2>", + fun() -> + gen_event:add_handler(lager_event, lager_file_backend, + [{Log1, debug}, {lager_default_formatter, ["[",severity,"] ", message, "\n"]}]), + gen_event:add_handler(lager_event, lager_file_backend, + [{Log2, debug}, {lager_default_formatter, ["2> [",severity,"] ", message, "\n"]}]), + lager:log(error, self(), "Test message"), + ?assertMatch({ok, <<"[error] Test message\n">>},file:read_file(Log1)), + ?assertMatch({ok, <<"2> [error] Test message\n">>},file:read_file(Log2)) + end} + end + ]}. config_validation_test_() -> [ {"missing file", ?_assertEqual(false, - validate_logfile_proplist([{level, info},{size, 10}])) + validate_logfile_proplist([{level, info}, {size, 10}])) }, {"bad level", ?_assertEqual(false, - validate_logfile_proplist([{file, "test.log"}, {level, blah},{size, 10}])) + validate_logfile_proplist([{file, "test.log"}, {level, blah}, {size, 10}])) }, {"bad size", ?_assertEqual(false, diff --git a/src/lager_util.erl b/src/lager_util.erl index 2ce568e..468baa0 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -1,4 +1,6 @@ -%% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved. +%% ------------------------------------------------------------------- +%% +%% 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 @@ -13,6 +15,8 @@ %% KIND, either express or implied. See the License for the %% specific language governing permissions and limitations %% under the License. +%% +%% ------------------------------------------------------------------- -module(lager_util). @@ -26,6 +30,7 @@ trace_filter/1, trace_filter/2, expand_path/1, check_hwm/1, make_internal_sink_name/1]). -ifdef(TEST). +-export([create_test_dir/0, delete_test_dir/1]). -include_lib("eunit/include/eunit.hrl"). -endif. @@ -368,7 +373,7 @@ calculate_next_rotation([{date, Date}|T], {{Year, Month, Day}, _} = Now) -> trace_filter(Query) -> trace_filter(?DEFAULT_TRACER, Query). -%% TODO: Support multiple trace modules +%% TODO: Support multiple trace modules %-spec trace_filter(Module :: atom(), Query :: 'none' | [tuple()]) -> {ok, any()}. trace_filter(Module, Query) when Query == none; Query == [] -> {ok, _} = glc:compile(Module, glc:null(false)); @@ -401,7 +406,7 @@ validate_trace(_) -> validate_trace_filter(Filter) when is_tuple(Filter), is_atom(element(1, Filter)) =:= false -> false; validate_trace_filter(Filter) -> - case lists:all(fun({Key, '*'}) when is_atom(Key) -> true; + case lists:all(fun({Key, '*'}) when is_atom(Key) -> true; ({Key, '!'}) when is_atom(Key) -> true; ({Key, _Value}) when is_atom(Key) -> true; ({Key, '=', _Value}) when is_atom(Key) -> true; @@ -414,16 +419,16 @@ validate_trace_filter(Filter) -> false end. -trace_all(Query) -> +trace_all(Query) -> glc:all(trace_acc(Query)). -trace_any(Query) -> +trace_any(Query) -> glc:any(Query). trace_acc(Query) -> trace_acc(Query, []). -trace_acc([], Acc) -> +trace_acc([], Acc) -> lists:reverse(Acc); trace_acc([{Key, '*'}|T], Acc) -> trace_acc(T, [glc:wc(Key)|Acc]); @@ -437,7 +442,7 @@ trace_acc([{Key, '>', Val}|T], Acc) -> trace_acc(T, [glc:gt(Key, Val)|Acc]); trace_acc([{Key, '<', Val}|T], Acc) -> trace_acc(T, [glc:lt(Key, Val)|Acc]). - + check_traces(_, _, [], Acc) -> lists:flatten(Acc); @@ -614,49 +619,52 @@ rotation_calculation_test() -> ?assertMatch({{2000, 1, 7}, {16, 0, 0}}, calculate_next_rotation([{day, 5}, {hour, 16}], {{2000, 1, 3}, {17, 34, 43}})), - + ?assertMatch({{2000, 1, 3}, {16, 0, 0}}, calculate_next_rotation([{day, 1}, {hour, 16}], {{1999, 12, 28}, {17, 34, 43}})), ok. rotate_file_test() -> - file:delete("rotation.log"), - [file:delete(["rotation.log.", integer_to_list(N)]) || N <- lists:seq(0, 9)], - [begin - file:write_file("rotation.log", integer_to_list(N)), - Count = case N > 10 of - true -> 10; - _ -> N - end, - [begin - FileName = ["rotation.log.", integer_to_list(M)], - ?assert(filelib:is_regular(FileName)), - %% check the expected value is in the file - Number = list_to_binary(integer_to_list(N - M - 1)), - ?assertEqual({ok, Number}, file:read_file(FileName)) - end - || M <- lists:seq(0, Count-1)], - rotate_logfile("rotation.log", 10) - end || N <- lists:seq(0, 20)]. + RotCount = 10, + TestDir = create_test_dir(), + TestLog = filename:join(TestDir, "rotation.log"), + Outer = fun(N) -> + ?assertEqual(ok, file: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)), + %% check the expected value is in the file + Number = erlang:list_to_binary(integer_to_list(N - M - 1)), + ?assertEqual({ok, Number}, file:read_file(File)) + end, + Count = erlang:min(N, RotCount), + % The first time through, Count == 0, so the sequence is empty, + % effectively skipping the inner loop so a rotation can occur that + % creates the file that Inner looks for. + % Don't shoot the messenger, it was worse before this refactoring. + lists:foreach(Inner, lists:seq(0, Count-1)), + rotate_logfile(TestLog, RotCount) + end, + lists:foreach(Outer, lists:seq(0, (RotCount * 2))), + delete_test_dir(TestDir). rotate_file_fail_test() -> - %% make sure the directory exists - ?assertEqual(ok, filelib:ensure_dir("rotation/rotation.log")), - %% fix the permissions on it - os:cmd("chown -R u+rwx rotation"), - %% delete any old files - [ok = file:delete(F) || F <- filelib:wildcard("rotation/*")], + TestDir = create_test_dir(), + TestLog = filename:join(TestDir, "rotation.log"), + %% set known permissions on it + os:cmd("chmod -R u+rwx " ++ TestDir), %% write a file - file:write_file("rotation/rotation.log", "hello"), + file:write_file(TestLog, "hello"), %% hose up the permissions - os:cmd("chown u-w rotation"), - ?assertMatch({error, _}, rotate_logfile("rotation.log", 10)), - ?assert(filelib:is_regular("rotation/rotation.log")), - os:cmd("chown u+w rotation"), - ?assertMatch(ok, rotate_logfile("rotation/rotation.log", 10)), - ?assert(filelib:is_regular("rotation/rotation.log.0")), - ?assertEqual(false, filelib:is_regular("rotation/rotation.log")), - ok. + os:cmd("chmod u-w " ++ TestDir), + ?assertMatch({error, _}, rotate_logfile(TestLog, 10)), + ?assert(filelib:is_regular(TestLog)), + %% fix the permissions + os:cmd("chmod u+w " ++ TestDir), + ?assertMatch(ok, rotate_logfile(TestLog, 10)), + ?assert(filelib:is_regular(TestLog ++ ".0")), + ?assertEqual(false, filelib:is_regular(TestLog)), + delete_test_dir(TestDir). check_trace_test() -> lager:start(), @@ -803,4 +811,32 @@ sink_name_test_() -> ?_assertEqual(audit_lager_event, make_internal_sink_name(audit)) ]. +create_test_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) -> + ListRet = file:list_dir_all(Dir), + ?assertMatch({ok, _}, ListRet), + {_, Entries} = ListRet, + lists:foreach( + fun(Entry) -> + FsElem = filename:join(Dir, Entry), + case filelib:is_dir(FsElem) of + true -> + delete_test_dir(FsElem); + _ -> + ?assertEqual(ok, file:delete(FsElem)) + end + end, Entries), + ?assertEqual(ok, file:del_dir(Dir)). + -endif. diff --git a/test/lager_rotate.erl b/test/lager_rotate.erl index fbcd819..cf9376e 100644 --- a/test/lager_rotate.erl +++ b/test/lager_rotate.erl @@ -1,3 +1,23 @@ +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2016-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_rotate). -compile(export_all). @@ -6,54 +26,71 @@ -include_lib("eunit/include/eunit.hrl"). -endif. +-record(state, { + dir :: string(), + log1 :: string(), + log1r :: string(), + log2 :: string(), + log2r :: string(), + sink :: string(), + sinkr :: string() +}). rotate_test_() -> {foreach, fun() -> - file:write_file("test1.log", ""), - file:write_file("test2.log", ""), - file:write_file("test3.log", ""), - file:delete("test1.log.0"), - file:delete("test2.log.0"), - file:delete("test3.log.0"), - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, - [{lager_file_backend, [{file, "test1.log"}, {level, info}]}, - {lager_file_backend, [{file, "test2.log"}, {level, info}]}]), - application:set_env(lager, extra_sinks, - [{sink_event, - [{handlers, - [{lager_file_backend, [{file, "test3.log"}, {level, info}]}]} - ]}]), - application:set_env(lager, error_logger_redirect, false), - application:set_env(lager, async_threshold, undefined), - lager:start() - end, - fun(_) -> - file:delete("test1.log"), - file:delete("test2.log"), - file:delete("test3.log"), - file:delete("test1.log.0"), - file:delete("test2.log.0"), - file:delete("test3.log.0"), - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) + Dir = lager_util:create_test_dir(), + Log1 = filename:join(Dir, "test1.log"), + Log2 = filename:join(Dir, "test2.log"), + Sink = filename:join(Dir, "sink.log"), + State = #state{ + dir = Dir, + log1 = Log1, + log1r = Log1 ++ ".0", + log2 = Log2, + log2r = Log2 ++ ".0", + sink = Sink, + sinkr = Sink ++ ".0" + }, + file:write_file(Log1, []), + file:write_file(Log2, []), + file:write_file(Sink, []), + + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, [ + {lager_file_backend, [{file, Log1}, {level, info}]}, + {lager_file_backend, [{file, Log2}, {level, info}]} ]), + application:set_env(lager, extra_sinks, [ + {sink_event, + [{handlers, + [{lager_file_backend, [{file, Sink}, {level, info}]}]} + ]}]), + application:set_env(lager, error_logger_redirect, false), + application:set_env(lager, async_threshold, undefined), + lager:start(), + State end, - [{"Rotate single file", + fun(#state{dir = Dir}) -> + application:stop(lager), + application:stop(goldrush), + lager_util:delete_test_dir(Dir), + error_logger:tty(true) + end, [ + fun(State) -> + {"Rotate single file", fun() -> lager:log(error, self(), "Test message 1"), lager:log(sink_event, error, self(), "Sink test message 1", []), - lager:rotate_handler({lager_file_backend, "test1.log"}), - ok = wait_until(fun() -> filelib:is_regular("test1.log.0") end, 10), + lager:rotate_handler({lager_file_backend, State#state.log1}), + ok = wait_until(fun() -> filelib:is_regular(State#state.log1r) end, 10), lager:log(error, self(), "Test message 2"), lager:log(sink_event, error, self(), "Sink test message 2", []), - - {ok, File1} = file:read_file("test1.log"), - {ok, File2} = file:read_file("test2.log"), - {ok, SinkFile} = file:read_file("test3.log"), - {ok, File1Old} = file:read_file("test1.log.0"), + + {ok, File1} = file:read_file(State#state.log1), + {ok, File2} = file:read_file(State#state.log2), + {ok, SinkFile} = file:read_file(State#state.sink), + {ok, File1Old} = file:read_file(State#state.log1r), have_no_log(File1, <<"Test message 1">>), have_log(File1, <<"Test message 2">>), @@ -66,19 +103,21 @@ rotate_test_() -> have_log(SinkFile, <<"Sink test message 1">>), have_log(SinkFile, <<"Sink test message 2">>) - end}, - {"Rotate sink", + end} + end, + fun(State) -> + {"Rotate sink", fun() -> lager:log(error, self(), "Test message 1"), lager:log(sink_event, error, self(), "Sink test message 1", []), lager:rotate_sink(sink_event), - ok = wait_until(fun() -> filelib:is_regular("test3.log.0") end, 10), + ok = wait_until(fun() -> filelib:is_regular(State#state.sinkr) end, 10), lager:log(error, self(), "Test message 2"), lager:log(sink_event, error, self(), "Sink test message 2", []), - {ok, File1} = file:read_file("test1.log"), - {ok, File2} = file:read_file("test2.log"), - {ok, SinkFile} = file:read_file("test3.log"), - {ok, SinkFileOld} = file:read_file("test3.log.0"), + {ok, File1} = file:read_file(State#state.log1), + {ok, File2} = file:read_file(State#state.log2), + {ok, SinkFile} = file:read_file(State#state.sink), + {ok, SinkFileOld} = file:read_file(State#state.sinkr), have_log(File1, <<"Test message 1">>), have_log(File1, <<"Test message 2">>), @@ -91,21 +130,23 @@ rotate_test_() -> have_no_log(SinkFile, <<"Sink test message 1">>), have_log(SinkFile, <<"Sink test message 2">>) - end}, - {"Rotate all", + end} + end, + fun(State) -> + {"Rotate all", fun() -> lager:log(error, self(), "Test message 1"), lager:log(sink_event, error, self(), "Sink test message 1", []), lager:rotate_all(), - ok = wait_until(fun() -> filelib:is_regular("test3.log.0") end, 10), + ok = wait_until(fun() -> filelib:is_regular(State#state.sinkr) end, 10), lager:log(error, self(), "Test message 2"), lager:log(sink_event, error, self(), "Sink test message 2", []), - {ok, File1} = file:read_file("test1.log"), - {ok, File2} = file:read_file("test2.log"), - {ok, SinkFile} = file:read_file("test3.log"), - {ok, File1Old} = file:read_file("test1.log.0"), - {ok, File2Old} = file:read_file("test2.log.0"), - {ok, SinkFileOld} = file:read_file("test3.log.0"), + {ok, File1} = file:read_file(State#state.log1), + {ok, File2} = file:read_file(State#state.log2), + {ok, SinkFile} = file:read_file(State#state.sink), + {ok, File1Old} = file:read_file(State#state.log1r), + {ok, File2Old} = file:read_file(State#state.log2r), + {ok, SinkFileOld} = file:read_file(State#state.sinkr), have_no_log(File1, <<"Test message 1">>), have_log(File1, <<"Test message 2">>), @@ -125,7 +166,9 @@ rotate_test_() -> have_log(File2Old, <<"Test message 1">>), have_no_log(File2Old, <<"Test message 2">>) - end}]}. + end} + end + ]}. have_log(Data, Log) -> {_,_} = binary:match(Data, Log).