diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 5a48238..b6d7e67 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -52,6 +52,7 @@ name :: string(), fd :: pid() | undefined, inode :: integer() | undefined, + ctime :: file:date_time() | undefined, fmtmaxbytes :: integer(), size :: integer(), date :: undefined | string(), @@ -74,9 +75,9 @@ start(Filename, MaxBytes, Size, Date, Count, Rotator) -> init([RelFilename, MaxBytes, Size, Date, Count, Rotator]) -> Filename = lager_util:expand_path(RelFilename), case Rotator:open_logfile(Filename, false) of - {ok, {FD, Inode, _}} -> + {ok, {FD, Inode, Ctime, _Size}} -> schedule_rotation(Date), - {ok, #state{name=Filename, fd=FD, inode=Inode, + {ok, #state{name=Filename, fd=FD, inode=Inode, ctime=Ctime, fmtmaxbytes=MaxBytes, size=Size, count=Count, date=Date, rotator=Rotator}}; {error, Reason} -> @@ -188,7 +189,7 @@ sasl_limited_str(progress, Report, FmtMaxBytes) -> sasl_limited_str(crash_report, Report, FmtMaxBytes) -> lager_stdlib:proc_lib_format(Report, FmtMaxBytes). -do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, +do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap, fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count, rotator=Rotator} = State) -> %% borrowed from riak_err {ReportStr, Pid, MsgStr, _ErrorP} = case Event of @@ -204,11 +205,11 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, if ReportStr == ignore -> {ok, State}; true -> - case Rotator:ensure_logfile(Name, FD, Inode, false) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, false) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> _ = Rotator:rotate_logfile(Name, Count), handle_cast({log, Event}, State); - {ok, {NewFD, NewInode, _Size}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> {Date, TS} = lager_util:format_time( lager_stdlib:maybe_utc(erlang:localtime())), Time = [Date, " ", TS," =", ReportStr, "====\n"], @@ -218,11 +219,11 @@ do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, {error, Reason} when Flap == false -> ?INT_LOG(error, "Failed to write log message to file ~s: ~s", [Name, file:format_error(Reason)]), - {ok, State#state{fd=NewFD, inode=NewInode, flap=true}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=true}}; ok -> - {ok, State#state{fd=NewFD, inode=NewInode, flap=false}}; + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime, flap=false}}; _ -> - {ok, State#state{fd=NewFD, inode=NewInode}} + {ok, State#state{fd=NewFD, inode=NewInode, ctime=NewCtime}} end; {error, Reason} -> case Flap of diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index fc1cbd8..213bbaa 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -63,8 +63,9 @@ name :: string(), level :: {'mask', integer()}, fd :: file:io_device() | undefined, - inode :: integer() | undefined, - flap=false :: boolean(), + inode = undefined :: integer() | undefined, + ctime = undefined :: file:date_time() | undefined, + flap = false :: boolean(), size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), @@ -123,8 +124,8 @@ init(LogFileConfig) when is_list(LogFileConfig) -> shaper=Shaper, formatter=Formatter, formatter_config=FormatterConfig, sync_on=SyncOn, sync_interval=SyncInterval, sync_size=SyncSize, check_interval=CheckInterval}, State = case Rotator:create_logfile(Name, {SyncSize, SyncInterval}) of - {ok, {FD, Inode, _}} -> - State0#state{fd=FD, inode=Inode}; + {ok, {FD, Inode, Ctime, _Size}} -> + State0#state{fd=FD, inode=Inode, ctime=Ctime}; {error, Reason} -> ?INT_LOG(error, "Failed to open log file ~s with error ~s", [Name, file:format_error(Reason)]), State0#state{flap=true} @@ -244,8 +245,10 @@ write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, case LastCheck >= State#state.check_interval orelse FD == undefined of true -> %% need to check for rotation - case Rotator:ensure_logfile(Name, FD, Inode, {State#state.sync_size, State#state.sync_interval}) of - {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> + Ctime = State#state.ctime, + Buffer = {State#state.sync_size, State#state.sync_interval}, + case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of + {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize -> case Rotator:rotate_logfile(Name, Count) of ok -> %% go around the loop again, we'll do another rotation check and hit the next clause of ensure_logfile @@ -259,9 +262,9 @@ write(#state{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, State#state{flap=true} end end; - {ok, {NewFD, NewInode, _}} -> + {ok, {NewFD, NewInode, NewCtime, _Size}} -> %% update our last check and try again - do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode}, Level, Msg); + do_write(State#state{last_check=Timestamp, fd=NewFD, inode=NewInode, ctime=NewCtime}, Level, Msg); {error, Reason} -> case Flap of true -> @@ -464,10 +467,10 @@ close_file(#state{fd=FD} = State) -> get_loglevel_test() -> {ok, Level, _} = handle_call(get_loglevel, - #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0}), + #state{name="bar", level=lager_util:config_to_mask(info), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level, lager_util:config_to_mask(info)), {ok, Level2, _} = handle_call(get_loglevel, - #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0}), + #state{name="foo", level=lager_util:config_to_mask(warning), fd=0, inode=0, ctime=undefined}), ?assertEqual(Level2, lager_util:config_to_mask(warning)). rotation_test_() -> @@ -490,20 +493,21 @@ rotation_test_() -> fun(DefaultState = #state{name=TestLog, sync_size=SyncSize, sync_interval=SyncInterval, rotator=Rotator}) -> {"External rotation should work", fun() -> - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd=FD, inode=Inode}, - ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode}, - write(State0, os:timestamp(), ?DEBUG, "hello world")), + {ok, {FD, Inode, Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + State0 = DefaultState#state{fd=FD, inode=Inode, ctime=Ctime}, + State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), + ?assertMatch(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, State1), ?assertEqual(ok, file:delete(TestLog)), - Result = write(State0, os:timestamp(), ?DEBUG, "hello world"), + State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed - ?assert(#state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode} =/= Result), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result), + ExpState1 = #state{name=TestLog, level=?DEBUG, fd=FD, inode=Inode, ctime=Ctime}, + ?assertNotEqual(ExpState1, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State2), ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), - Result2 = write(Result, os:timestamp(), ?DEBUG, "hello world"), + State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed - ?assert(Result =/= Result2), - ?assertMatch(#state{name=TestLog, level=?DEBUG}, Result2), + ?assertNotEqual(State3, State2), + ?assertMatch(#state{name=TestLog, level=?DEBUG}, State3), ok end} end, @@ -515,7 +519,7 @@ rotation_test_() -> RotationSize = 15, PreviousCheck = os:timestamp(), - {ok, {FD, Inode, _}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), + {ok, {FD, Inode, _Ctime, _Size}} = Rotator:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{ fd=FD, inode=Inode, size=RotationSize, check_interval=CheckInterval, last_check=PreviousCheck}, @@ -660,8 +664,7 @@ filesystem_test_() -> {"file that becomes unavailable at runtime should trigger an error message", fun() -> {ok, TestDir} = lager_util:get_test_dir(), - TestFileName = "test_" ++ erlang:integer_to_list(erlang:phash2(os:timestamp())) ++ ".log", - TestLog = filename:join(TestDir, TestFileName), + TestLog = filename:join(TestDir, "test.log"), gen_event:add_handler(lager_event, lager_file_backend, [{file, TestLog}, {level, info}, {check_interval, 0}]), @@ -721,14 +724,14 @@ filesystem_test_() -> ?assertEqual(0, lager_test_backend:count()), lager:log(error, self(), "Test message1"), ?assertEqual(1, lager_test_backend:count()), - file:delete(TestLog), - file:write_file(TestLog, ""), + ?assertEqual(ok, file:delete(TestLog)), + ?assertEqual(ok, file:write_file(TestLog, "")), lager:log(error, self(), "Test message2"), {ok, Bin} = file:read_file(TestLog), Pid = pid_to_list(self()), ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])), - file:rename(TestLog, TestLog0), + ?assertEqual(ok, file:rename(TestLog, TestLog0)), lager:log(error, self(), "Test message3"), {ok, Bin2} = file:read_file(TestLog), ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], diff --git a/src/lager_rotator_behaviour.erl b/src/lager_rotator_behaviour.erl index 5b6e5e8..a37d94a 100644 --- a/src/lager_rotator_behaviour.erl +++ b/src/lager_rotator_behaviour.erl @@ -2,16 +2,16 @@ %% Create a log file -callback(create_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Open a log file -callback(open_logfile(Name::list(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Ensure reference to current target, could be rotated --callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), +-callback(ensure_logfile(Name::list(), FD::file:io_device(), Inode::integer(), Ctime::file:date_time(), Buffer::{integer(), integer()} | any()) -> - {ok, {file:io_device(), integer(), integer()}} | {error, any()}). + {ok, {file:io_device(), integer(), file:date_time(), integer()}} | {error, any()}). %% Rotate the log file -callback(rotate_logfile(Name::list(), Count::integer()) -> diff --git a/src/lager_rotator_default.erl b/src/lager_rotator_default.erl index 553a861..4bfb61a 100644 --- a/src/lager_rotator_default.erl +++ b/src/lager_rotator_default.erl @@ -5,7 +5,7 @@ -behaviour(lager_rotator_behaviour). -export([ - create_logfile/2, open_logfile/2, ensure_logfile/4, rotate_logfile/2 + create_logfile/2, open_logfile/2, ensure_logfile/5, rotate_logfile/2 ]). -ifdef(TEST). @@ -20,8 +20,8 @@ open_logfile(Name, Buffer) -> ok -> Options = [append, raw] ++ case Buffer of - {Size, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size), Size >= 0 -> - [{delayed_write, Size, Interval}]; + {Size0, Interval} when is_integer(Interval), Interval >= 0, is_integer(Size0), Size0 >= 0 -> + [{delayed_write, Size0, Interval}]; _ -> [] end, case file:open(Name, Options) of @@ -29,7 +29,9 @@ open_logfile(Name, Buffer) -> case file:read_file_info(Name) of {ok, FInfo} -> Inode = FInfo#file_info.inode, - {ok, {FD, Inode, FInfo#file_info.size}}; + Ctime = FInfo#file_info.ctime, + Size1 = FInfo#file_info.size, + {ok, {FD, Inode, Ctime, Size1}}; X -> X end; Y -> Y @@ -37,39 +39,42 @@ open_logfile(Name, Buffer) -> Z -> Z end. -ensure_logfile(Name, undefined, _Inode, Buffer) -> +ensure_logfile(Name, undefined, _Inode, _Ctime, Buffer) -> open_logfile(Name, Buffer); -ensure_logfile(Name, FD, Inode, Buffer) -> +ensure_logfile(Name, FD, Inode0, Ctime0, Buffer) -> case file:read_file_info(Name) of {ok, FInfo} -> - Inode2 = FInfo#file_info.inode, - case Inode == Inode2 of - true -> - {ok, {FD, Inode, FInfo#file_info.size}}; - false -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% inode changed, file was probably moved and - %% recreated - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end + {OsType, _} = os:type(), + Inode1 = FInfo#file_info.inode, + Ctime1 = FInfo#file_info.ctime, + case {OsType, Inode0 =:= Inode1, Ctime0 =:= Ctime1} of + % Note: on win32, Inode is always zero + % So check the file's ctime to see if it + % needs to be re-opened + {win32, _, false} -> + reopen_logfile(Name, FD, Buffer); + {win32, _, true} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; + {unix, true, _} -> + {ok, {FD, Inode0, Ctime0, FInfo#file_info.size}}; + {unix, false, _} -> + reopen_logfile(Name, FD, Buffer) end; _ -> - %% delayed write can cause file:close not to do a close - _ = file:close(FD), - _ = file:close(FD), - case open_logfile(Name, Buffer) of - {ok, {FD2, Inode3, Size}} -> - %% file was removed - {ok, {FD2, Inode3, Size}}; - Error -> - Error - end + reopen_logfile(Name, FD, Buffer) + end. + +reopen_logfile(Name, FD0, Buffer) -> + %% delayed write can cause file:close not to do a close + _ = file:close(FD0), + _ = file:close(FD0), + case open_logfile(Name, Buffer) of + {ok, {_FD1, _Inode, _Size, _Ctime}=FileInfo} -> + %% inode changed, file was probably moved and + %% recreated + {ok, FileInfo}; + Error -> + Error end. %% renames failing are OK