diff --git a/README.md b/README.md index 8f6cf42..c17ecb2 100644 --- a/README.md +++ b/README.md @@ -1141,6 +1141,16 @@ Example Usage: 3.x Changelog ------------- +3.8.0 - 12 August 2019 + + * API change: Modify the `lager_rotator_behaviour` to pass in a file's creation + time to `ensure_logfile/5` to be used to determine if file has changed on + systems where inodes are not available (i.e. `win32`). The return value from + `create_logfile/2`, `open_logfile/2` and `ensure_logfile/5` now requires + ctime to be returned (#509) + * Bugfix: ensure log file rotation works on `win32` (#509) + * Bugfix: ensure test suite passes on `win32` (#509) + 3.7.0 - 24 May 2019 * Policy: Officially ending support for OTP 19 (Support OTP 20, 21, 22) diff --git a/appveyor.yml b/appveyor.yml new file mode 100644 index 0000000..8a0d12d --- /dev/null +++ b/appveyor.yml @@ -0,0 +1,8 @@ +build: off + +test_script: + - escript ./rebar get-deps + - escript ./rebar compile + - escript ./rebar eunit + +deploy: false diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 95d4f93..3a06255 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -58,7 +58,6 @@ end). -ifdef(TEST). --compile(export_all). %% Make CRASH synchronous when testing, to avoid timing headaches -define(CRASH_LOG(Event), catch(gen_server:call(lager_crash_log, {log, Event}))). diff --git a/src/lager_app.erl b/src/lager_app.erl index 70eef45..82c0139 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -23,7 +23,6 @@ -behaviour(application). -include("lager.hrl"). -ifdef(TEST). --compile([export_all]). -include_lib("eunit/include/eunit.hrl"). -endif. -export([start/0, diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index b3377f6..c7de2b5 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -52,6 +52,7 @@ name :: string(), fd :: pid() | undefined, inode :: integer() | undefined, + ctime :: file:date_time() | undefined, fmtmaxbytes :: integer(), size :: integer(), date :: undefined | string(), @@ -74,9 +75,9 @@ start(Filename, MaxBytes, Size, Date, Count, Rotator) -> init([RelFilename, MaxBytes, Size, Date, Count, Rotator]) -> Filename = lager_util:expand_path(RelFilename), case Rotator:open_logfile(Filename, false) of - {ok, {FD, Inode, _}} -> + {ok, {FD, Inode, Ctime, _Size}} -> schedule_rotation(Date), - {ok, #state{name=Filename, fd=FD, inode=Inode, + {ok, #state{name=Filename, fd=FD, inode=Inode, ctime=Ctime, fmtmaxbytes=MaxBytes, size=Size, count=Count, date=Date, rotator=Rotator}}; {error, Reason} -> @@ -188,7 +189,7 @@ sasl_limited_str(progress, Report, FmtMaxBytes) -> sasl_limited_str(crash_report, Report, FmtMaxBytes) -> lager_stdlib:proc_lib_format(Report, FmtMaxBytes). -do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, +do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap, fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count, rotator=Rotator} = State) -> %% borrowed from riak_err {ReportStr, Pid, MsgStr, _ErrorP} = case Event of @@ -204,11 +205,11 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, if ReportStr == ignore -> {ok, State}; true -> - case Rotator:ensure_logfile(Name, FD, Inode, false) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, false) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> _ = Rotator:rotate_logfile(Name, Count), handle_cast({log, Event}, State); - {ok, {NewFD, NewInode, _Size}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> {Date, TS} = lager_util:format_time( lager_stdlib:maybe_utc(erlang:localtime())), Time = [Date, " ", TS," =", ReportStr, "====\n"], @@ -218,11 +219,11 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, {error, Reason} when Flap == false -> ?INT_LOG(error, "Failed to write log message to file ~ts: ~s", [Name, file:format_error(Reason)]), - {ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=true}}; ok -> - {ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=false}}; _ -> - {ok, State#state{fd=NewFD, inode=NewInode}} + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime}} end; {error, Reason} -> case Flap of @@ -242,30 +243,30 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, filesystem_test_() -> {foreach, fun() -> - CrashLog = filename:join(lager_util:create_test_dir(), "crash_test.log"), - file:write_file(CrashLog, []), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, true), - application:unset_env(lager, crash_log), - lager:start(), - timer:sleep(1000), - lager_test_backend:flush(), + {ok, TestDir} = lager_util:create_test_dir(), + CrashLog = filename:join(TestDir, "crash_test.log"), + ok = lager_util:safe_write_file(CrashLog, []), + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, true), + ok = application:unset_env(lager, crash_log), + ok = lager:start(), + ok = timer:sleep(1000), + ok = lager_test_backend:flush(), CrashLog end, - fun(CrashLog) -> + fun(_CrashLog) -> case whereis(lager_crash_log) of P when is_pid(P) -> - exit(P, kill); + gen_server:stop(P); _ -> ok end, - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(filename:dirname(CrashLog)), - error_logger:tty(true) + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ fun(CrashLog) -> {"under normal circumstances, file should be opened", @@ -280,9 +281,13 @@ filesystem_test_() -> fun(CrashLog) -> {"file can't be opened on startup triggers an error message", fun() -> - {ok, FInfo} = file:read_file_info(CrashLog), - file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), + {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual( @@ -293,29 +298,40 @@ filesystem_test_() -> fun(CrashLog) -> {"file that becomes unavailable at runtime should trigger an error message", fun() -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - ?assertEqual(1, lager_test_backend:count()), - 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)) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + ?assertEqual(0, lager_test_backend:count()), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), + {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), + sync_error_logger:error_msg("Test message\n"), + _ = gen_event:which_handlers(error_logger), + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), + ?assertEqual(3, lager_test_backend:count()), + lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen crash log " ++ CrashLog ++ " with error: permission denied", + lists:flatten(Message)) + end end} end, fun(CrashLog) -> {"unavailable files that are fixed at runtime should start having log messages written", fun() -> - {ok, FInfo} = file:read_file_info(CrashLog), + {ok, FInfo} = file:read_file_info(CrashLog, [raw]), OldPerms = FInfo#file_info.mode, file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), @@ -334,23 +350,30 @@ filesystem_test_() -> fun(CrashLog) -> {"external logfile rotation/deletion should be handled", fun() -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin} = file:read_file(CrashLog), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - 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}])) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), + ?assertEqual(0, lager_test_backend:count()), + sync_error_logger:error_msg("Test message~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin} = file:read_file(CrashLog), + ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), + ?assertEqual(ok, file:delete(CrashLog)), + ?assertEqual(ok, lager_util:safe_write_file(CrashLog, "")), + sync_error_logger:error_msg("Test message1~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin1} = file:read_file(CrashLog), + ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), + file:rename(CrashLog, CrashLog ++ ".0"), + sync_error_logger:error_msg("Test message2~n"), + _ = gen_event:which_handlers(error_logger), + {ok, Bin2} = file:read_file(CrashLog), + ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) + end end} end ]}. diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl index a74cdc7..147cedf 100644 --- a/src/lager_default_formatter.erl +++ b/src/lager_default_formatter.erl @@ -484,14 +484,13 @@ basic_test_() -> }, {"node formatting basic", begin - [N, F] = format(lager_msg:new("Message", - Now, - info, - [{pid, self()}], - []), - [node, "foo"]), - ?_assertEqual("foo", F), - ?_assertNotEqual(nomatch, re:run(N, <<"@">>)) + [N, "foo"] = format(lager_msg:new("Message", + Now, + info, + [{pid, self()}], + []), + [node, "foo"]), + ?_assertNotMatch(nomatch, re:run(N, <<"@">>)) end } ]. diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 1e9caab..6b1ab17 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -35,12 +35,12 @@ -module(lager_file_backend). -include("lager.hrl"). +-include_lib("kernel/include/file.hrl"). -behaviour(gen_event). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). --include_lib("kernel/include/file.hrl"). -compile([{parse_transform, lager_transform}]). -endif. @@ -64,7 +64,8 @@ level :: {'mask', integer()}, fd :: file:io_device() | undefined, inode :: integer() | undefined, - flap=false :: boolean(), + ctime :: file:date_time() | undefined, + flap = false :: boolean(), size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), @@ -76,7 +77,8 @@ check_interval = ?DEFAULT_CHECK_INTERVAL :: non_neg_integer(), sync_interval = ?DEFAULT_SYNC_INTERVAL :: non_neg_integer(), sync_size = ?DEFAULT_SYNC_SIZE :: non_neg_integer(), - last_check = os:timestamp() :: erlang:timestamp() + last_check = os:timestamp() :: erlang:timestamp(), + os_type :: atom() }). -type option() :: {file, string()} | {level, lager:log_level()} | @@ -123,8 +125,8 @@ init(LogFileConfig) when is_list(LogFileConfig) -> shaper=Shaper, formatter=Formatter, formatter_config=FormatterConfig, sync_on=SyncOn, sync_interval=SyncInterval, sync_size=SyncSize, check_interval=CheckInterval}, State = case Rotator:create_logfile(Name, {SyncSize, SyncInterval}) of - {ok, {FD, Inode, _}} -> - State0#state{fd=FD, inode=Inode}; + {ok, {FD, Inode, Ctime, _Size}} -> + State0#state{fd=FD, inode=Inode, ctime=Ctime}; {error, Reason} -> ?INT_LOG(error, "Failed to open log file ~ts with error ~s", [Name, file:format_error(Reason)]), State0#state{flap=true} @@ -189,8 +191,8 @@ handle_event(_Event, State) -> {ok, State}. %% @private -handle_info({rotate, File}, #state{name=File,count=Count,date=Date,rotator=Rotator} = State) -> - State1 = close_file(State), +handle_info({rotate, File}, #state{name=File, count=Count, date=Date, rotator=Rotator}=State0) -> + State1 = close_file(State0), _ = Rotator:rotate_logfile(File, Count), schedule_rotation(File, Date), {ok, State1}; @@ -237,49 +239,67 @@ config_to_id(Config) -> {?MODULE, File} end. - -write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, - count=Count, rotator=Rotator} = State, Timestamp, Level, Msg) -> - LastCheck = timer:now_diff(Timestamp, State#state.last_check) div 1000, - case LastCheck >= State#state.check_interval orelse FD == undefined of +write(#state{name=Name, fd=FD, + inode=Inode, ctime=Ctime, + flap=Flap, size=RotSize, + count=Count, rotator=Rotator}=State0, Timestamp, Level, Msg) -> + case write_should_check(State0, Timestamp) of true -> %% need to check for rotation - case Rotator:ensure_logfile(Name, FD, Inode, {State#state.sync_size, State#state.sync_interval}) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + Buffer = {State0#state.sync_size, State0#state.sync_interval}, + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize > 0, Size > RotSize -> + State1 = close_file(State0), case Rotator:rotate_logfile(Name, Count) of ok -> %% go around the loop again, we'll do another rotation check and hit the next clause of ensure_logfile - write(State, Timestamp, Level, Msg); + write(State1, Timestamp, Level, Msg); {error, Reason} -> case Flap of true -> - State; + State1; _ -> ?INT_LOG(error, "Failed to rotate log file ~ts with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State1#state{flap=true} end end; - {ok, {NewFD, NewInode, _}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> %% update our last check and try again - do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode}, Level, Msg); + State1 = State0#state{last_check=Timestamp, fd=NewFD, inode=NewInode, ctime=NewCtime}, + do_write(State1, Level, Msg); {error, Reason} -> case Flap of true -> - State; + State0; _ -> ?INT_LOG(error, "Failed to reopen log file ~ts with error ~s", [Name, file:format_error(Reason)]), - State#state{flap=true} + State0#state{flap=true} end end; false -> - do_write(State, Level, Msg) + do_write(State0, Level, Msg) + end. + +write_should_check(#state{fd=undefined}, _Timestamp) -> + true; +write_should_check(#state{last_check=LastCheck0, check_interval=CheckInterval, + name=Name, inode=Inode0, ctime=Ctime0}, Timestamp) -> + LastCheck1 = timer:now_diff(Timestamp, LastCheck0) div 1000, + case LastCheck1 >= CheckInterval of + true -> + true; + _ -> + % We need to know if the file has changed "out from under lager" so we don't + % write to an invalid FD + {Result, _FInfo} = lager_util:has_file_changed(Name, Inode0, Ctime0), + Result end. do_write(#state{fd=FD, name=Name, flap=Flap} = State, Level, Msg) -> %% delayed_write doesn't report errors _ = file:write(FD, unicode:characters_to_binary(Msg)), {mask, SyncLevel} = State#state.sync_on, - case (Level band SyncLevel) /= 0 of + case (Level band SyncLevel) =/= 0 of true -> %% force a sync on any message that matches the 'sync_on' bitmask Flap2 = case file:datasync(FD) of @@ -453,18 +473,20 @@ close_file(#state{fd=undefined} = State) -> State; close_file(#state{fd=FD} = State) -> %% Flush and close any file handles. + %% delayed write can cause file:close not to do a close _ = file:datasync(FD), _ = file:close(FD), + _ = file:close(FD), State#state{fd=undefined}. -ifdef(TEST). get_loglevel_test() -> {ok, Level, _} = handle_call(get_loglevel, - #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0}), + #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level, lager_util:config_to_mask(info)), {ok, Level2, _} = handle_call(get_loglevel, - #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0}), + #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level2, lager_util:config_to_mask(warning)). rotation_test_() -> @@ -475,38 +497,50 @@ rotation_test_() -> SyncInterval = ?DEFAULT_SYNC_INTERVAL, Rotator = ?DEFAULT_ROTATION_MOD, CheckInterval = 0, %% hard to test delayed mode - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "test.log"), - - #state{name=TestLog, level=?DEBUG, sync_on=SyncLevel, - sync_size=SyncSize, sync_interval=SyncInterval, check_interval=CheckInterval, - rotator=Rotator} - + {OsType, _} = os:type(), + #state{name=TestLog, + level=?DEBUG, + sync_on=SyncLevel, + sync_size=SyncSize, + sync_interval=SyncInterval, + check_interval=CheckInterval, + rotator=Rotator, + os_type=OsType} end, - fun(#state{name=TestLog}) -> - lager_util:delete_test_dir(filename:dirname(TestLog)) + fun(#state{}) -> + ok = lager_util:delete_test_dir() end, [ - fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval, rotator = Rotator}) -> + fun(DefaultState=#state{name=TestLog, os_type=OsType, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"External rotation should work", fun() -> - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd=FD, inode=Inode}, - ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode}, - write(State0, os:timestamp(), ?DEBUG, "hello world")), - file:delete(TestLog), - 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 + case OsType of + win32 -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + State0 = DefaultState#state{fd=FD, inode=Inode, ctime=Ctime}, + State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, State1), + ?assertEqual(ok, file:delete(TestLog)), + State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + %% assert file has changed + ExpState1 = #state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, + ?assertNotEqual(ExpState1, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State2), + ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), + State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), + %% assert file has changed + ?assertNotEqual(State3, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State3), + ok + end end} end, - fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval = SyncInterval, rotator = Rotator}) -> + fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"Internal rotation and delayed write", fun() -> TestLog0 = TestLog ++ ".0", @@ -514,22 +548,35 @@ rotation_test_() -> RotationSize = 15, PreviousCheck = os:timestamp(), - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{ - fd=FD, inode=Inode, size=RotationSize, + fd=FD, inode=Inode, ctime=Ctime, size=RotationSize, check_interval=CheckInterval, last_check=PreviousCheck}, %% new message within check interval with sync_on level Msg1Timestamp = add_secs(PreviousCheck, 1), - State0 = State1 = write(State0, Msg1Timestamp, ?ERROR, "big big message 1"), + State1 = write(State0, Msg1Timestamp, ?ERROR, "big big message 1"), + ?assertEqual(State0, State1), %% new message within check interval under sync_on level %% not written to disk yet Msg2Timestamp = add_secs(PreviousCheck, 2), - State0 = State2 = write(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), + State2 = write(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), + ?assertEqual(State0, State2), + + % Note: we must ensure at least one second (DEFAULT_SYNC_INTERVAL) has passed + % for message 1 and 2 to be written to disk + ElapsedMs = timer:now_diff(os:timestamp(), PreviousCheck) div 1000, + case ElapsedMs > SyncInterval of + true -> + ok; + _ -> + S = SyncInterval - ElapsedMs, + timer:sleep(S) + end, %% although file size is big enough... - {ok, FInfo} = file:read_file_info(TestLog), + {ok, FInfo} = file:read_file_info(TestLog, [raw]), ?assert(RotationSize < FInfo#file_info.size), %% ...no rotation yet ?assertEqual(PreviousCheck, State2#state.last_check), @@ -544,9 +591,9 @@ rotation_test_() -> {ok, Bin1} = file:read_file(TestLog0), {ok, Bin2} = file:read_file(TestLog), - %% message 1-3 written to file + %% message 1-2 written to file ?assertEqual(<<"big big message 1buffered message 2">>, Bin1), - %% message 4 buffered, not yet written to file + %% message 3 buffered, not yet written to file ?assertEqual(<<"">>, Bin2), ok end} @@ -560,26 +607,28 @@ add_secs({Mega, Secs, Micro}, Add) -> filesystem_test_() -> {foreach, fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, false), - application:set_env(lager, async_threshold, undefined), - lager:start(), + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = application:set_env(lager, async_threshold, undefined), + {ok, _TestDir} = lager_util:create_test_dir(), + ok = lager:start(), %% race condition where lager logs its own start up %% makes several tests fail. See test/lager_test_backend %% around line 800 for more information. - timer:sleep(5), - lager_test_backend:flush() + ok = timer:sleep(5), + ok = lager_test_backend:flush() end, fun(_) -> - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = error_logger:tty(true), + ok = lager_util:delete_test_dir() end, [ {"under normal circumstances, file should be opened", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -588,13 +637,11 @@ filesystem_test_() -> {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"don't choke on unicode", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, @@ -604,13 +651,11 @@ filesystem_test_() -> Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, [228,184,173,230,150,135,230,181,139,232,175,149, $\n]], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"don't choke on latin-1", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! @@ -621,107 +666,121 @@ filesystem_test_() -> Pid = pid_to_list(self()), Res = re:split(Bin, " ", [{return, list}, {parts, 5}]), ?assertMatch([_, _, "[error]", Pid, - [76,195,134,195,157,195,142,78,45,195,175,$\n]], Res), - - lager_util:delete_test_dir(TestDir) + [76,195,134,195,157,195,142,78,45,195,175,$\n]], Res) end}, {"file can't be opened on startup triggers an error message", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, file:write_file(TestLog, [])), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, [])), + + {ok, FInfo0} = file:read_file_info(TestLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), - {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}), + + % Note: required on win32, do this early to prevent subsequent failures + % from preventing cleanup + ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), + ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time,Message,_Metadata} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + MessageFlat = lists:flatten(Message), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)), - - lager_util:delete_test_dir(TestDir) + MessageFlat) 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) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be + % deleted or renamed while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, info}, {check_interval, 0}]), + ?assertEqual(0, lager_test_backend:count()), + lager:log(error, self(), "Test message"), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), + {ok, FInfo0} = file:read_file_info(TestLog, [raw]), + FInfo1 = FInfo0#file_info{mode = 0}, + ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), + lager:log(error, self(), "Test message"), + lager_test_backend:pop(), + lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertEqual( + "Failed to reopen log file " ++ TestLog ++ " with error permission denied", + lists:flatten(Message)) + end end}, {"unavailable files that are fixed at runtime should start having log messages written", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, file:write_file(TestLog, [])), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, [])), - {ok, FInfo} = file:read_file_info(TestLog), + {ok, FInfo} = file:read_file_info(TestLog, [raw]), OldPerms = FInfo#file_info.mode, - file:write_file_info(TestLog, FInfo#file_info{mode = 0}), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog},{check_interval, 0}]), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), ?assertEqual( "Failed to open log file " ++ TestLog ++ " with error permission denied", lists:flatten(Message)), - file:write_file_info(TestLog, FInfo#file_info{mode = OldPerms}), + ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = OldPerms})), lager:log(error, self(), "Test message"), {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"external logfile rotation/deletion should be handled", fun() -> - TestDir = lager_util:create_test_dir(), - 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) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed + % while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + TestLog0 = TestLog ++ ".0", + + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, info}, {check_interval, 0}]), + ?assertEqual(0, lager_test_backend:count()), + lager:log(error, self(), "Test message1"), + ?assertEqual(1, lager_test_backend:count()), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "")), + lager:log(error, self(), "Test message2"), + ?assertEqual(2, lager_test_backend:count()), + {ok, Bin} = file:read_file(TestLog), + Pid = pid_to_list(self()), + ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], + re:split(Bin, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:rename(TestLog, TestLog0)), + lager:log(error, self(), "Test message3"), + ?assertEqual(3, lager_test_backend:count()), + {ok, Bin2} = file:read_file(TestLog), + ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], + re:split(Bin2, " ", [{return, list}, {parts, 5}])) + end end}, {"internal size rotation should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -729,13 +788,11 @@ filesystem_test_() -> [{file, TestLog}, {level, info}, {check_interval, 0}, {size, 10}]), lager:log(error, self(), "Test message1"), lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"internal time rotation should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -745,13 +802,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), whereis(lager_event) ! {rotate, TestLog}, lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"rotation call should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog0 = TestLog ++ ".0", @@ -761,13 +816,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message1"), gen_event:call(lager_event, {lager_file_backend, TestLog}, rotate, infinity), lager:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"sync_on option should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -777,13 +830,11 @@ filesystem_test_() -> ?assertEqual({ok, <<>>}, file:read_file(TestLog)), lager:log(info, self(), "Test message1"), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"sync_on none option should work (also tests sync_interval)", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, @@ -795,13 +846,11 @@ filesystem_test_() -> ?assertEqual({ok, <<>>}, file:read_file(TestLog)), timer:sleep(2000), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"sync_size option should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, @@ -820,13 +869,11 @@ filesystem_test_() -> %% now we've written enough bytes lager:log(error, self(), "Test messageis64bytes"), {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin), - - lager_util:delete_test_dir(TestDir) + ?assert(<<>> /= Bin) end}, {"runtime level changes", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, {lager_file_backend, TestLog}, {TestLog, info}), @@ -841,26 +888,22 @@ filesystem_test_() -> lager:log(error, self(), "Test message4"), {ok, Bin2} = file:read_file(TestLog), Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])), - ?assertEqual(Lines2, 3), - - lager_util:delete_test_dir(TestDir) + ?assertEqual(Lines2, 3) end}, {"invalid runtime level changes", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), TestLog3 = filename:join(TestDir, "test3.log"), gen_event:add_handler(lager_event, lager_file_backend, [{TestLog, info, 10*1024*1024, "$D0", 5}, {lager_default_formatter}]), gen_event:add_handler(lager_event, lager_file_backend, {TestLog3, info}), - ?assertEqual({error, bad_module}, lager:set_loglevel(lager_file_backend, TestLog, warning)), - - lager_util:delete_test_dir(TestDir) + ?assertEqual({error, bad_module}, lager:set_loglevel(lager_file_backend, TestLog, warning)) end}, {"tracing should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, {TestLog, critical}), @@ -873,41 +916,44 @@ filesystem_test_() -> timer:sleep(1000), {ok, Bin} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin, " ", [{return, list}, {parts, 5}])) end}, {"tracing should not duplicate messages", fun() -> - TestDir = lager_util:create_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(lager_event, lager_file_backend, - [{file, TestLog}, {level, critical}, {check_interval, always}]), - timer:sleep(500), - lager:critical("Test message"), - {ok, Bin1} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin1, " ", [{return, list}, {parts, 5}])), - ok = file:delete(TestLog), - {Level, _} = lager_config:get({lager_event, loglevel}), - lager_config:set({lager_event, loglevel}, - {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), - lager:critical("Test message"), - {ok, Bin2} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])), - ok = file:delete(TestLog), - lager:error("Test message"), - {ok, Bin3} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + case os:type() of + {win32, _} -> + % Note: test is skipped on win32 due to the fact that a file can't be + % deleted or renamed while a process has an open file handle referencing it + ok; + _ -> + {ok, TestDir} = lager_util:get_test_dir(), + TestLog = filename:join(TestDir, "test.log"), + + gen_event:add_handler(lager_event, lager_file_backend, + [{file, TestLog}, {level, critical}, {check_interval, always}]), + timer:sleep(500), + lager:critical("Test message"), + {ok, Bin1} = file:read_file(TestLog), + ?assertMatch([_, _, "[critical]", _, "Test message\n"], + re:split(Bin1, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:delete(TestLog)), + {Level, _} = lager_config:get({lager_event, loglevel}), + lager_config:set({lager_event, loglevel}, + {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), + lager:critical("Test message"), + {ok, Bin2} = file:read_file(TestLog), + ?assertMatch([_, _, "[critical]", _, "Test message\n"], + re:split(Bin2, " ", [{return, list}, {parts, 5}])), + ?assertEqual(ok, file:delete(TestLog)), + lager:error("Test message"), + {ok, Bin3} = file:read_file(TestLog), + ?assertMatch([_, _, "[error]", _, "Test message\n"], + re:split(Bin3, " ", [{return, list}, {parts, 5}])) + end end}, {"tracing to a dedicated file should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), {ok, _} = lager:trace_file(TestLog, [{module, ?MODULE}]), @@ -916,13 +962,11 @@ filesystem_test_() -> lager:log(error, self(), "Test message"), {ok, Bin3} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin3, " ", [{return, list}, {parts, 5}])) end}, {"tracing to a dedicated file should work even if root_log is set", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), LogName = "foo.log", LogPath = filename:join(TestDir, LogName), @@ -934,13 +978,11 @@ filesystem_test_() -> {ok, Bin3} = file:read_file(LogPath), application:unset_env(lager, log_root), ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])), - - lager_util:delete_test_dir(TestDir) + re:split(Bin3, " ", [{return, list}, {parts, 5}])) end}, {"tracing with options should work", fun() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "foo.log"), TestLog0 = TestLog ++ ".0", @@ -955,68 +997,67 @@ filesystem_test_() -> timer:sleep(2), lager:error("Test message"), timer:sleep(10), - ?assert(filelib:is_regular(TestLog0)), - - lager_util:delete_test_dir(TestDir) + ?assert(filelib:is_regular(TestLog0)) end}, {"no silent hwm drops", fun() -> - TestDir = lager_util:create_test_dir(), + MsgCount = 15, + {ok, TestDir} = lager_util:get_test_dir(), TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {high_water_mark, 5}, {flush_queue, false}, {sync_on, "=warning"}]), {_, _, MS} = os:timestamp(), - timer:sleep((1000000 - MS) div 1000 + 1), - %start close to the beginning of a new second - [lager:log(info, self(), "Foo ~p", [K]) || K <- lists:seq(1, 15)], - timer:sleep(1000), + % start close to the beginning of a new second + ?assertEqual(ok, timer:sleep((1000000 - MS) div 1000 + 1)), + [lager:log(info, self(), "Foo ~p", [K]) || K <- lists:seq(1, MsgCount)], + ?assertEqual(MsgCount, lager_test_backend:count()), + % Note: bumped from 1000 to 1250 to ensure delayed write flushes to disk + ?assertEqual(ok, timer:sleep(1250)), {ok, Bin} = file:read_file(TestLog), Last = lists:last(re:split(Bin, "\n", [{return, list}, trim])), ?assertMatch([_, _, _, _, "lager_file_backend dropped 10 messages in the last second that exceeded the limit of 5 messages/sec"], - re:split(Last, " ", [{return, list}, {parts, 5}])), - lager_util:delete_test_dir(TestDir) + re:split(Last, " ", [{return, list}, {parts, 5}])) end} ]}. trace_files_test_() -> {foreach, fun() -> - Dir = lager_util:create_test_dir(), - Log = filename:join(Dir, "test.log"), - Debug = filename:join(Dir, "debug.log"), - Events = filename:join(Dir, "events.log"), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [ - {lager_file_backend, [ - {file, Log}, - {level, error}, - {formatter, lager_default_formatter}, - {formatter_config, [message, "\n"]} - ]} - ]), - application:set_env(lager, traces, [ - { % get default level of debug - {lager_file_backend, Debug}, [{module, ?MODULE}] - }, - { % Handler Filters Level - {lager_file_backend, Events}, [{module, ?MODULE}], notice - } - ]), - application:set_env(lager, async_threshold, undefined), - lager:start(), - {Dir, Log, Debug, Events} + {ok, TestDir} = lager_util:get_test_dir(), + Log = filename:join(TestDir, "test.log"), + Debug = filename:join(TestDir, "debug.log"), + Events = filename:join(TestDir, "events.log"), + + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [ + {lager_file_backend, [ + {file, Log}, + {level, error}, + {formatter, lager_default_formatter}, + {formatter_config, [message, "\n"]} + ]} + ]), + ok = application:set_env(lager, traces, [ + { % get default level of debug + {lager_file_backend, Debug}, [{module, ?MODULE}] + }, + { % Handler Filters Level + {lager_file_backend, Events}, [{module, ?MODULE}], notice + } + ]), + ok = application:set_env(lager, async_threshold, undefined), + ok = lager:start(), + {Log, Debug, Events} end, - fun({Dir, _, _, _}) -> + fun({_, _, _}) -> catch ets:delete(lager_config), - application:unset_env(lager, traces), - application:stop(lager), - - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + ok = application:unset_env(lager, traces), + ok = application:stop(lager), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ - fun({_, Log, Debug, Events}) -> + fun({Log, Debug, Events}) -> {"a trace using file backend set up in configuration should work", fun() -> lager:error("trace test error message"), @@ -1056,28 +1097,27 @@ count_lines_until(Lines, Timeout, File, Last) -> formatting_test_() -> {foreach, fun() -> - 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(), + {ok, TestDir} = lager_util:get_test_dir(), + Log1 = filename:join(TestDir, "test.log"), + Log2 = filename:join(TestDir, "test2.log"), + ?assertEqual(ok, lager_util:safe_write_file(Log1, [])), + ?assertEqual(ok, lager_util:safe_write_file(Log2, [])), + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = lager:start(), %% same race condition issue - timer:sleep(5), - {Dir, Log1, Log2} + ok = timer:sleep(5), + {ok, Log1, Log2} end, - fun({Dir, _, _}) -> - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + fun({ok, _, _}) -> + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ - fun({_, Log1, Log2}) -> + fun({ok, Log1, Log2}) -> {"Should have two log files, the second prefixed with 2>", fun() -> gen_event:add_handler(lager_event, lager_file_backend, @@ -1151,5 +1191,4 @@ config_validation_test_() -> } ]. - -endif. diff --git a/src/lager_rotator_behaviour.erl b/src/lager_rotator_behaviour.erl index 5b6e5e8..a37d94a 100644 --- a/src/lager_rotator_behaviour.erl +++ b/src/lager_rotator_behaviour.erl @@ -2,16 +2,16 @@ %% Create a log file -callback(create_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Open a log file -callback(open_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Ensure reference to current target, could be rotated --callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), +-callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), Ctime::file:date_time(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Rotate the log file -callback(rotate_logfile(Name::list(), Count::integer()) -> diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 7a18de9..738585f 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -5,7 +5,7 @@ -behaviour(lager_rotator_behaviour). -export([ - create_logfile/2, open_logfile/2, ensure_logfile/4, rotate_logfile/2 + create_logfile/2, open_logfile/2, ensure_logfile/5, rotate_logfile/2 ]). -ifdef(TEST). @@ -19,17 +19,19 @@ open_logfile(Name, Buffer) -> case filelib:ensure_dir(Name) of ok -> Options = [append, raw] ++ - case Buffer of - {Size, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size), Size >= 0 -> - [{delayed_write, Size, Interval}]; + case Buffer of + {Size0, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size0), Size0 >= 0 -> + [{delayed_write, Size0, Interval}]; _ -> [] end, case file:open(Name, Options) of {ok, FD} -> - case file:read_file_info(Name) of - {ok, FInfo} -> - Inode = FInfo#file_info.inode, - {ok, {FD, Inode, FInfo#file_info.size}}; + case file:read_file_info(Name, [raw]) of + {ok, FInfo0} -> + Inode = FInfo0#file_info.inode, + {ok, Ctime} = maybe_update_ctime(Name, FInfo0), + Size1 = FInfo0#file_info.size, + {ok, {FD, Inode, Ctime, Size1}}; X -> X end; Y -> Y @@ -37,39 +39,29 @@ open_logfile(Name, Buffer) -> Z -> Z end. -ensure_logfile(Name, undefined, _Inode, Buffer) -> +ensure_logfile(Name, undefined, _Inode, _Ctime, Buffer) -> open_logfile(Name, Buffer); -ensure_logfile(Name, FD, Inode, Buffer) -> - case file:read_file_info(Name) of - {ok, FInfo} -> - Inode2 = FInfo#file_info.inode, - case Inode == Inode2 of - true -> - {ok, {FD, Inode, FInfo#file_info.size}}; - false -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% inode changed, file was probably moved and - %% recreated - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end - end; - _ -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% file was removed - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end +ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> + case lager_util:has_file_changed(Name, Inode0, Ctime0) of + {true, _FInfo} -> + reopen_logfile(Name, FD, Buffer); + {_, FInfo} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}} + end. + +reopen_logfile(Name, FD0, Buffer) -> + %% Flush and close any file handles. + %% delayed write can cause file:close not to do a close + _ = file:datasync(FD0), + _ = file:close(FD0), + _ = file:close(FD0), + case open_logfile(Name, Buffer) of + {ok, {_FD1, _Inode, _Size, _Ctime}=FileInfo} -> + %% inode changed, file was probably moved and + %% recreated + {ok, FileInfo}; + Error -> + Error end. %% renames failing are OK @@ -78,6 +70,8 @@ rotate_logfile(File, 0) -> case file:open(File, [write]) of {ok, FD} -> _ = file:close(FD), + _ = file:close(FD), + {ok, _Ctime} = maybe_update_ctime(File), ok; Error -> Error @@ -92,14 +86,37 @@ rotate_logfile(File0, Count) -> _ = file:rename(File1, File2), rotate_logfile(File0, Count - 1). +maybe_update_ctime(Name) -> + case file:read_file_info(Name, [raw]) of + {ok, FInfo} -> + maybe_update_ctime(Name, FInfo); + _ -> + {ok, calendar:local_time()} + end. + +maybe_update_ctime(Name, FInfo) -> + {OsType, _} = os:type(), + do_update_ctime(OsType, Name, FInfo). + +do_update_ctime(win32, Name, FInfo0) -> + % Note: we force the creation time to be the current time. + % On win32 this may prevent the ctime from being updated: + % https://stackoverflow.com/q/8804342/1466825 + NewCtime = calendar:local_time(), + FInfo1 = FInfo0#file_info{ctime = NewCtime}, + ok = file:write_file_info(Name, FInfo1, [raw]), + {ok, NewCtime}; +do_update_ctime(_, _Name, FInfo) -> + {ok, FInfo#file_info.ctime}. + -ifdef(TEST). rotate_file_test() -> RotCount = 10, - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), Outer = fun(N) -> - ?assertEqual(ok, file:write_file(TestLog, erlang:integer_to_list(N))), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, erlang:integer_to_list(N))), Inner = fun(M) -> File = lists:flatten([TestLog, $., erlang:integer_to_list(M)]), ?assert(filelib:is_regular(File)), @@ -120,14 +137,14 @@ rotate_file_test() -> rotate_file_zero_count_test() -> %% Test that a rotation count of 0 simply truncates the file - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), ?assertMatch(ok, rotate_logfile(TestLog, 0)), ?assertNot(filelib:is_regular(TestLog ++ ".0")), ?assertEqual(true, filelib:is_regular(TestLog)), ?assertEqual(1, length(filelib:wildcard(TestLog++"*"))), %% assert the new file is 0 size: - case file:read_file_info(TestLog) of + case file:read_file_info(TestLog, [raw]) of {ok, FInfo} -> ?assertEqual(0, FInfo#file_info.size); _ -> @@ -136,31 +153,43 @@ rotate_file_zero_count_test() -> lager_util:delete_test_dir(TestDir). rotate_file_fail_test() -> - TestDir = lager_util:create_test_dir(), + {ok, TestDir} = lager_util:create_test_dir(), TestLog = filename:join(TestDir, "rotation.log"), + %% set known permissions on it - os:cmd("chmod -R u+rwx " ++ TestDir), + ok = lager_util:set_dir_permissions("u+rwx", TestDir), + %% write a file - file:write_file(TestLog, "hello"), - %% hose up the permissions - os:cmd("chmod -R u-w " ++ TestDir), - ?assertMatch({error, _}, rotate_logfile(TestLog, 10)), + ?assertEqual(ok, lager_util:safe_write_file(TestLog, "hello")), + + case os:type() of + {win32, _} -> ok; + _ -> + %% hose up the permissions + ok = lager_util:set_dir_permissions("u-w", TestDir), + ?assertMatch({error, _}, rotate_logfile(TestLog, 10)) + end, + %% check we still only have one file, rotation.log ?assertEqual([TestLog], filelib:wildcard(TestLog++"*")), ?assert(filelib:is_regular(TestLog)), + %% fix the permissions - os:cmd("chmod -R u+w " ++ TestDir), + ok = lager_util:set_dir_permissions("u+w", TestDir), + ?assertMatch(ok, rotate_logfile(TestLog, 10)), ?assert(filelib:is_regular(TestLog ++ ".0")), ?assertEqual(true, filelib:is_regular(TestLog)), ?assertEqual(2, length(filelib:wildcard(TestLog++"*"))), + %% assert the new file is 0 size: - case file:read_file_info(TestLog) of + case file:read_file_info(TestLog, [raw]) of {ok, FInfo} -> ?assertEqual(0, FInfo#file_info.size); _ -> ?assert(false) end, + %% check that the .0 file now has the contents "hello" ?assertEqual({ok, <<"hello">>}, file:read_file(TestLog++".0")), lager_util:delete_test_dir(TestDir). diff --git a/src/lager_util.erl b/src/lager_util.erl index 372565c..21e84b7 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -27,16 +27,22 @@ localtime_ms/0, localtime_ms/1, maybe_utc/1, parse_rotation_date_spec/1, calculate_next_rotation/1, validate_trace/1, check_traces/4, is_loggable/3, trace_filter/1, trace_filter/2, expand_path/1, find_file/2, check_hwm/1, check_hwm/2, - make_internal_sink_name/1, otp_version/0, maybe_flush/2 + make_internal_sink_name/1, otp_version/0, maybe_flush/2, + has_file_changed/3 ]). -ifdef(TEST). --export([create_test_dir/0, delete_test_dir/1]). +-export([create_test_dir/0, get_test_dir/0, delete_test_dir/0, + set_dir_permissions/2, + safe_application_load/1, + safe_write_file/2]). -include_lib("eunit/include/eunit.hrl"). -endif. -include("lager.hrl"). +-include_lib("kernel/include/file.hrl"). + levels() -> [debug, info, notice, warning, error, critical, alert, emergency, none]. @@ -589,6 +595,26 @@ maybe_flush(undefined, #lager_shaper{} = S) -> maybe_flush(Flag, #lager_shaper{} = S) when is_boolean(Flag) -> S#lager_shaper{flush_queue = Flag}. +-spec has_file_changed(Name :: file:name_all(), + Inode0 :: pos_integer(), + Ctime0 :: file:date_time()) -> {boolean(), file:file_info() | undefined}. +has_file_changed(Name, Inode0, Ctime0) -> + {OsType, _} = os:type(), + F = file:read_file_info(Name, [raw]), + case {OsType, F} of + {win32, {ok, #file_info{ctime=Ctime1}=FInfo}} -> + % Note: on win32, Inode is always zero + % So check the file's ctime to see if it + % needs to be re-opened + Changed = Ctime0 =/= Ctime1, + {Changed, FInfo}; + {_, {ok, #file_info{inode=Inode1}=FInfo}} -> + Changed = Inode0 =/= Inode1, + {Changed, FInfo}; + {_, _} -> + {true, undefined} + end. + -ifdef(TEST). parse_test() -> @@ -826,24 +852,56 @@ sink_name_test_() -> ]. create_test_dir() -> - Dir = filename:join(["/tmp", "lager_test", + {ok, Tmp} = get_temp_dir(), + Dir = filename:join([Tmp, "lager_test", erlang:integer_to_list(erlang:phash2(os:timestamp()))]), ?assertEqual(ok, filelib:ensure_dir(Dir)), - case file:make_dir(Dir) of - ok -> - Dir; - Err -> - ?assertEqual({error, eexist}, Err), - create_test_dir() + TestDir = case file:make_dir(Dir) of + ok -> + Dir; + Err -> + ?assertEqual({error, eexist}, Err), + create_test_dir() + end, + ok = application:set_env(lager, test_dir, TestDir), + {ok, TestDir}. + +get_test_dir() -> + case application:get_env(lager, test_dir) of + undefined -> + create_test_dir(); + {ok, _}=Res -> + Res end. -delete_test_dir(Dir) -> - case otp_version() of - 15 -> - os:cmd("rm -rf " ++ Dir); - _ -> - do_delete_test_dir(Dir) - end. +get_temp_dir() -> + Tmp = case os:getenv("TEMP") of + false -> + case os:getenv("TMP") of + false -> "/tmp"; + Dir1 -> Dir1 + end; + Dir0 -> Dir0 + end, + ?assertEqual(true, filelib:is_dir(Tmp)), + {ok, Tmp}. + +delete_test_dir() -> + {ok, TestDir} = get_test_dir(), + ok = delete_test_dir(TestDir). + +delete_test_dir(TestDir) -> + ok = application:unset_env(lager, test_dir), + {OsType, _} = os:type(), + ok = case {OsType, otp_version()} of + {win32, _} -> + application:stop(lager), + do_delete_test_dir(TestDir); + {unix, 15} -> + os:cmd("rm -rf " ++ TestDir); + {unix, _} -> + do_delete_test_dir(TestDir) + end. do_delete_test_dir(Dir) -> ListRet = file:list_dir_all(Dir), @@ -856,9 +914,54 @@ do_delete_test_dir(Dir) -> true -> delete_test_dir(FsElem); _ -> - ?assertEqual(ok, file:delete(FsElem)) + case file:delete(FsElem) of + ok -> ok; + Error -> + io:format(standard_error, "[ERROR]: error deleting file ~p~n", [FsElem]), + ?assertEqual(ok, Error) + end end end, Entries), ?assertEqual(ok, file:del_dir(Dir)). +do_delete_file(_FsElem, 0) -> + ?assert(false); +do_delete_file(FsElem, Attempts) -> + case file:delete(FsElem) of + ok -> ok; + _Error -> + do_delete_file(FsElem, Attempts - 1) + end. + +set_dir_permissions(Perms, Dir) -> + do_set_dir_permissions(os:type(), Perms, Dir). + +do_set_dir_permissions({win32, _}, _Perms, _Dir) -> + ok; +do_set_dir_permissions({unix, _}, Perms, Dir) -> + os:cmd("chmod -R " ++ Perms ++ " " ++ Dir), + ok. + +safe_application_load(App) -> + case application:load(App) of + ok -> + ok; + {error, {already_loaded, App}} -> + ok; + Error -> + ?assertEqual(ok, Error) + end. + +safe_write_file(File, Content) -> + % Note: ensures that the new creation time is at least one second + % in the future + ?assertEqual(ok, file:write_file(File, Content)), + Ctime0 = calendar:local_time(), + Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), + Ctime1Sec = Ctime0Sec + 1, + Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), + {ok, FInfo0} = file:read_file_info(File, [raw]), + FInfo1 = FInfo0#file_info{ctime = Ctime1}, + ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). + -endif. diff --git a/test/compress_pr_record_test.erl b/test/compress_pr_record_test.erl index e3de673..9f62c5b 100644 --- a/test/compress_pr_record_test.erl +++ b/test/compress_pr_record_test.erl @@ -2,7 +2,13 @@ -compile([{parse_transform, lager_transform}]). --record(a, {field1, field2, foo, bar, baz, zyu, zix}). +-record(a, {field1 :: term(), + field2 :: term(), + foo :: term(), + bar :: term(), + baz :: term(), + zyu :: term(), + zix :: term()}). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). diff --git a/test/lager_rotate.erl b/test/lager_rotate.erl index c84a9ff..5c6c1e3 100644 --- a/test/lager_rotate.erl +++ b/test/lager_rotate.erl @@ -20,8 +20,6 @@ -module(lager_rotate). --compile(export_all). - -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). -endif. @@ -39,7 +37,7 @@ rotate_test_() -> {foreach, fun() -> - Dir = lager_util:create_test_dir(), + {ok, Dir} = lager_util:create_test_dir(), Log1 = filename:join(Dir, "test1.log"), Log2 = filename:join(Dir, "test2.log"), Sink = filename:join(Dir, "sink.log"), @@ -72,11 +70,11 @@ rotate_test_() -> timer:sleep(1000), State end, - fun(#state{dir = Dir}) -> - application:stop(lager), - application:stop(goldrush), - lager_util:delete_test_dir(Dir), - error_logger:tty(true) + fun(#state{}) -> + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = lager_util:delete_test_dir(), + ok = error_logger:tty(true) end, [ fun(State) -> {"Rotate single file", diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 69489b9..94dd22e 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1776,6 +1776,8 @@ async_threshold_test_() -> {foreach, Setup, Cleanup, [ {"async threshold works", {timeout, 30, fun() -> + Sleep = get_long_sleep_value(), + %% we start out async ?assertEqual(true, lager_config:get(async)), ?assertEqual([{sync_toggled, 0}], @@ -1790,7 +1792,7 @@ async_threshold_test_() -> %% serialize on mailbox _ = gen_event:which_handlers(lager_event), - timer:sleep(500), + timer:sleep(Sleep), %% By now the flood of messages should have forced the backend throttle %% to turn off async mode, but it's possible all outstanding requests @@ -1807,11 +1809,12 @@ async_threshold_test_() -> %% serialize on the mailbox again _ = gen_event:which_handlers(lager_event), + timer:sleep(Sleep), - %% just in case... - timer:sleep(1000), lager:info("hello world"), + _ = gen_event:which_handlers(lager_event), + timer:sleep(Sleep), %% async is true again now that the mailbox has drained ?assertEqual(true, lager_config:get(async)), @@ -1903,4 +1906,12 @@ high_watermark_test_() -> ] }. +get_long_sleep_value() -> + case os:getenv("CI") of + false -> + 500; + _ -> + 5000 + end. + -endif. diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index cc49ad7..e845fa6 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -25,12 +25,12 @@ -compile([{nowarn_deprecated_function, [{erlang, now, 0}]}]). -lager_function_transforms([ - {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, - {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, - {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, + {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, + {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, + {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, - {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, - {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} + {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, + {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} ]). -compile({parse_transform, lager_transform}). @@ -38,162 +38,161 @@ -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). -export([ - transform_static/0, - transform_dynamic/0 + transform_static/0, + transform_dynamic/0 ]). -endif. -ifdef(TEST). transform_static() -> - static_result. + static_result. transform_dynamic() -> - case lager_util:otp_version() >= 18 of - true -> - erlang:monotonic_time(); - false -> - erlang:now() - end. + case lager_util:otp_version() >= 18 of + true -> + erlang:monotonic_time(); + false -> + erlang:now() + end. not_running_test() -> - ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). + ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). setup() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, false), - application:unset_env(lager, traces), - lager:start(), - %% There is a race condition between the application start up, lager logging its own - %% start up condition and several tests that count messages or parse the output of - %% tests. When the lager start up message wins the race, it causes these tests - %% which parse output or count message arrivals to fail. - %% - %% We introduce a sleep here to allow `flush' to arrive *after* the start up - %% message has been received and processed. - %% - %% This race condition was first exposed during the work on - %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager - %% manager killer PR. - timer:sleep(5), - gen_event:call(lager_event, lager_test_backend, flush). - + ok = error_logger:tty(false), + ok = lager_util:safe_application_load(lager), + ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), + ok = application:set_env(lager, error_logger_redirect, false), + ok = application:unset_env(lager, traces), + ok = lager:start(), + %% There is a race condition between the application start up, lager logging its own + %% start up condition and several tests that count messages or parse the output of + %% tests. When the lager start up message wins the race, it causes these tests + %% which parse output or count message arrivals to fail. + %% + %% We introduce a sleep here to allow `flush' to arrive *after* the start up + %% message has been received and processed. + %% + %% This race condition was first exposed during the work on + %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager + %% manager killer PR. + ok = timer:sleep(250), + ok = gen_event:call(lager_event, lager_test_backend, flush). cleanup(_) -> - catch ets:delete(lager_config), %% kill the ets config table with fire - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true). + catch ets:delete(lager_config), %% kill the ets config table with fire + ok = application:stop(lager), + ok = application:stop(goldrush), + ok = error_logger:tty(true). transform_function_test_() -> - {foreach, - fun setup/0, - fun cleanup/1, - [ - {"observe that there is nothing up my sleeve", - fun() -> - ?assertEqual(undefined, lager_test_backend:pop()), - ?assertEqual(0, lager_test_backend:count()) - end - }, - {"logging works", - fun() -> - lager:warning("test message"), - ?assertEqual(1, lager_test_backend:count()), - {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertMatch(Level, lager_util:level_to_num(warning)), - ?assertEqual("test message", Message), - ok - end - }, - {"Testing calling a function returns the same content on emit", - fun() -> - lager:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_static_emit, Metadata), - ?assertEqual(transform_static(), Function()), - ok - end - }, - {"Testing calling a function which returns content which can change on emit", - fun() -> - lager:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ?assert(Function() < Function()), - ok - end - }, - {"Testing a undefined function returns undefined on emit", - fun() -> - lager:warning("Undefined error"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_undefined_emit, Metadata), - [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), - ?assertNot(erlang:function_exported(Module, Name, 0)), - ok - end - }, - {"Testing calling a function returns the same content on log", - fun() -> - lager:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), - ok - end - }, - {"Testing calling a dynamic function on log which returns the same value", - fun() -> - lager:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ?assert(Value < transform_dynamic()), - ok - end - }, - {"Testing differences in results for on_log vs on emit from dynamic function", - fun() -> - lager:warning("on_log vs on emit"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - FunctionResult = Function(), - ?assert(Value < FunctionResult), - ?assert(Value < Function()), - ?assert(FunctionResult < Function()), - ok - end - }, - {"Testing a function provided via metadata", - fun()-> - Provided = fun()-> - provided_metadata - end, - lager:md([{provided, Provided}]), - lager:warning("Provided metadata"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(provided, Metadata), - ?assertEqual(Provided(), Function()), - ok - end - } - ] - }. + {foreach, + fun setup/0, + fun cleanup/1, + [ + {"observe that there is nothing up my sleeve", + fun() -> + ?assertEqual(undefined, lager_test_backend:pop()), + ?assertEqual(0, lager_test_backend:count()) + end + }, + {"logging works", + fun() -> + lager:warning("test message"), + ?assertEqual(1, lager_test_backend:count()), + {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual("test message", Message), + ok + end + }, + {"Testing calling a function returns the same content on emit", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_static_emit, Metadata), + ?assertEqual(transform_static(), Function()), + ok + end + }, + {"Testing calling a function which returns content which can change on emit", + fun() -> + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_dynamic_emit, Metadata), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ?assert(Function() =< Function()), + ok + end + }, + {"Testing a undefined function returns undefined on emit", + fun() -> + lager:warning("Undefined error"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_undefined_emit, Metadata), + [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), + ?assertNot(erlang:function_exported(Module, Name, 0)), + ok + end + }, + {"Testing calling a function returns the same content on log", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), + ok + end + }, + {"Testing calling a dynamic function on log which returns the same value", + fun() -> + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ?assert(Value =< transform_dynamic()), + ok + end + }, + {"Testing differences in results for on_log vs on emit from dynamic function", + fun() -> + lager:warning("on_log vs on emit"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + Function = proplists:get_value(returns_dynamic_emit, Metadata), + FunctionResult = Function(), + ?assert(Value =< FunctionResult), + ?assert(Value =< Function()), + ?assert(FunctionResult =< Function()), + ok + end + }, + {"Testing a function provided via metadata", + fun()-> + Provided = fun() -> + provided_metadata + end, + lager:md([{provided, Provided}]), + lager:warning("Provided metadata"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(provided, Metadata), + ?assertEqual(Provided(), Function()), + ok + end + } + ] + }. -endif. diff --git a/test/pr_stacktrace_test.erl b/test/pr_stacktrace_test.erl index e8bc433..2853a22 100644 --- a/test/pr_stacktrace_test.erl +++ b/test/pr_stacktrace_test.erl @@ -22,56 +22,42 @@ bad_arg() -> integer_to_list(1.0). pr_stacktrace_throw_test() -> - Result = try + Got = try make_throw() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26 - pr_stacktrace_test:make_throw/0 line 16 -throw:{test,exception}", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). - + Want = "pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26\n pr_stacktrace_test:make_throw/0 line 16\nthrow:{test,exception}", + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_bad_arg_test() -> - Result = try + Got = try bad_arg() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 40 - pr_stacktrace_test:bad_arg/0 line 22 -error:badarg", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). - + Want = "pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 36\n pr_stacktrace_test:bad_arg/0 line 22\nerror:badarg", + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_bad_arity_test() -> - Result = try + Got = try bad_arity() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = " - pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 54 - lists:concat([], []) -error:undef", - ?assertNotEqual(0, string:str(Result, ExpectedPart)). + Want = "pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46\n lists:concat([], [])\nerror:undef", + ?assertNotEqual(nomatch, string:find(Got, Want)). pr_stacktrace_no_reverse_test() -> application:set_env(lager, reverse_pretty_stacktrace, false), - Result = try + Got = try bad_arity() catch ?EXCEPTION(Class, Reason, Stacktrace) -> lager:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) end, -ExpectedPart = "error:undef - lists:concat([], []) - pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 68", - - ?assertEqual(0, string:str(Result, ExpectedPart)). + Want = "error:undef\n lists:concat([], [])\n pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 57", + ?assertEqual(nomatch, string:find(Got, Want)). diff --git a/test/zzzz_gh280_crash.erl b/test/zzzz_gh280_crash.erl index aa85ab2..c384dc6 100644 --- a/test/zzzz_gh280_crash.erl +++ b/test/zzzz_gh280_crash.erl @@ -5,7 +5,6 @@ %% and lager starts up to replace the current handlers with its own. This causes a start up crash because %% OTP error logging modules do not have any notion of a lager-style log level. -module(zzzz_gh280_crash). --compile(export_all). -include_lib("eunit/include/eunit.hrl").