From 6fac9ebc69f39f2995be8ffd31acbadb1df66a73 Mon Sep 17 00:00:00 2001 From: Ted Burghart Date: Thu, 19 Jan 2017 18:10:10 -0500 Subject: [PATCH] Stop leaving test files in the current directory. Just. Stop. It. Uses lager_util:create_test_dir/0 and lager_util:delete_test_dir/1 to give tests, or groups thereof, their own clean directory to work in. Turn off whitespace diffs to review, as much code is shifted left to allow sane wrapping within around 100 columns. --- src/lager_crash_log.erl | 205 ++++---- src/lager_file_backend.erl | 1023 ++++++++++++++++++++---------------- test/lager_rotate.erl | 153 ++++-- 3 files changed, 782 insertions(+), 599 deletions(-) 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/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).