Refactor lager_rotator_behaviour to return a files ctime value, which is necessary for detecting changes on win32

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

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"],

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()) ->

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