[logger] Add option file_check to logger_std_h

OTP-15663

This option indicates how often the handler shall check if the log
file still exists and if the inode is changed.

3 files changed, 109 insertions, 57 deletions

diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml
index ce54a91342..5ed1a2f210 100644
--- a/lib/kernel/doc/src/logger_std_h.xml
+++ b/lib/kernel/doc/src/logger_std_h.xml
@@ -134,6 +134,25 @@
 	value <c>infinity</c>.</p>
 	<p>Defaults to <c>false</c>.</p>
       </item>
+      <tag><marker id="file_check"/><c>file_check = non_neg_integer()</c></tag>
+      <item>
+	<p>When <c>logger_std_h</c> logs to a file, it reads the file
+	  information of the log file prior to each write
+	  operation. This is to make sure the file still exists and
+	  has the same inode as when it was opened. This implies some
+	  performance loss, but ensures that no log events are lost in
+	  the case when the file has been removed or renamed by an
+	  external actor.</p>
+	<p>In order to allow minimizing the performance loss, the
+	  <c>file_check</c> parameter can be set to a positive integer
+	  value, <c>N</c>. The handler will then skip reading the file
+	  information prior to writing, as long as no more
+	  than <c>N</c> milliseconds have passed since it was last
+	  read.</p>
+	<p>Notice that the risk of loosing log events grows when
+	  the <c>file_check</c> value grows.</p>
+	<p>Defaults to 0.</p>
+      </item>
       <tag><c>filesync_repeat_interval = pos_integer() | no_repeat</c></tag>
       <item>
 	<p>This value, in milliseconds, specifies how often the handler does
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl
index 023567c183..c8f1acfca4 100644
--- a/lib/kernel/src/logger_std_h.erl
+++ b/lib/kernel/src/logger_std_h.erl
@@ -106,7 +106,7 @@ filter_config(Config) ->
 %%% logger_h_common callbacks
 %%%===================================================================
 init(Name, Config) ->
-    MyConfig = maps:with([type,file,modes,max_no_bytes,
+    MyConfig = maps:with([type,file,modes,file_check,max_no_bytes,
                           max_no_files,compress_on_rotate],Config),
     case file_ctrl_start(Name, MyConfig) of
         {ok,FileCtrlPid} ->
@@ -146,21 +146,24 @@ check_h_config(HConfig) ->
             {error,{invalid_config,?MODULE,#{Key=>Value}}}
     end.
 
-check_h_config(Type,[{type,Type} | Config]) when Type == standard_io;
-                                                 Type == standard_error;
-                                                 Type == file ->
+check_h_config(Type,[{type,Type} | Config]) when Type =:= standard_io;
+                                                 Type =:= standard_error;
+                                                 Type =:= file ->
     check_h_config(Type,Config);
 check_h_config(file,[{file,File} | Config]) when is_list(File) ->
     check_h_config(file,Config);
 check_h_config(file,[{modes,Modes} | Config]) when is_list(Modes) ->
     check_h_config(file,Config);
 check_h_config(file,[{max_no_bytes,Size} | Config])
-  when (is_integer(Size) andalso Size>0) orelse Size==infinity ->
+  when (is_integer(Size) andalso Size>0) orelse Size=:=infinity ->
     check_h_config(file,Config);
 check_h_config(file,[{max_no_files,Num} | Config]) when is_integer(Num), Num>=0 ->
     check_h_config(file,Config);
 check_h_config(file,[{compress_on_rotate,Bool} | Config]) when is_boolean(Bool) ->
     check_h_config(file,Config);
+check_h_config(file,[{file_check,FileCheck} | Config])
+  when is_integer(FileCheck), FileCheck>=0 ->
+    check_h_config(file,Config);
 check_h_config(_Type,[Other | _]) ->
     {error,Other};
 check_h_config(_Type,[]) ->
@@ -187,6 +190,7 @@ get_default_config(Name,file) ->
      #{type => file,
        file => atom_to_list(Name),
        modes => [raw,append],
+       file_check => 0,
        max_no_bytes => infinity,
        max_no_files => 0,
        compress_on_rotate => false};
@@ -224,35 +228,38 @@ fix_modes(Modes) ->
     end.
 
 config_changed(_Name,
-               #{max_no_bytes:=Size,
+               #{file_check:=FileCheck,
+                 max_no_bytes:=Size,
                  max_no_files:=Count,
                  compress_on_rotate:=Compress},
-               #{max_no_bytes:=Size,
+               #{file_check:=FileCheck,
+                 max_no_bytes:=Size,
                  max_no_files:=Count,
                  compress_on_rotate:=Compress}=State) ->
     State;
 config_changed(_Name,
-               #{max_no_bytes:=Size,
+               #{file_check:=FileCheck,
+                 max_no_bytes:=Size,
                  max_no_files:=Count,
                  compress_on_rotate:=Compress},
                #{file_ctrl_pid := FileCtrlPid} = State) ->
-    FileCtrlPid ! {update_rotation,{Size,Count,Compress}},
-    State#{max_no_bytes:=Size, max_no_files:=Count, compress_on_rotate:=Compress};
+    FileCtrlPid ! {update_config,#{file_check=>FileCheck,
+                                   max_no_bytes=>Size,
+                                   max_no_files=>Count,
+                                   compress_on_rotate=>Compress}},
+    State#{file_check:=FileCheck,
+           max_no_bytes:=Size,
+           max_no_files:=Count,
+           compress_on_rotate:=Compress};
 config_changed(_Name,_NewHConfig,State) ->
     State.
 
-filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) ->
-    ok = file_ctrl_filesync_async(FileCtrlPid),
-    {ok,State};
-filesync(_Name, sync, #{file_ctrl_pid := FileCtrlPid} = State) ->
-    Result = file_ctrl_filesync_sync(FileCtrlPid),
+filesync(_Name, SyncAsync, #{file_ctrl_pid := FileCtrlPid} = State) ->
+    Result = file_ctrl_filesync(SyncAsync, FileCtrlPid),
     {Result,State}.
 
-write(_Name, async, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) ->
-    ok = file_write_async(FileCtrlPid, Bin),
-    {ok,State};
-write(_Name, sync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) ->
-    Result = file_write_sync(FileCtrlPid, Bin),
+write(_Name, SyncAsync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) ->
+    Result = file_write(SyncAsync, FileCtrlPid, Bin),
     {Result,State}.
 
 reset_state(_Name, State) ->
@@ -291,6 +298,7 @@ terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) ->
 open_log_file(HandlerName,#{type:=file,
                             file:=FileName,
                             modes:=Modes,
+                            file_check:=FileCheck,
                             max_no_bytes:=Size,
                             max_no_files:=Count,
                             compress_on_rotate:=Compress}) ->
@@ -300,13 +308,15 @@ open_log_file(HandlerName,#{type:=file,
                 case file:open(FileName, Modes) of
                     {ok, Fd} ->
                         {ok,#file_info{inode=INode}} =
-                            file:read_file_info(FileName),
+                            file:read_file_info(FileName,[raw]),
                         UpdateModes = [append | Modes--[write,append,exclusive]],
                         State0 = #{handler_name=>HandlerName,
                                    file_name=>FileName,
                                    modes=>UpdateModes,
+                                   file_check=>FileCheck,
                                    fd=>Fd,
                                    inode=>INode,
+                                   last_check=>timestamp(),
                                    synced=>false,
                                    write_res=>ok,
                                    sync_res=>ok},
@@ -322,9 +332,10 @@ open_log_file(HandlerName,#{type:=file,
         _:Reason -> {error,Reason}
     end.
 
-close_log_file(#{file:={Fd,_}}) ->
+close_log_file(#{fd:=Fd}) ->
     _ = file:datasync(Fd),
-    _ = file:close(Fd);
+    _ = file:close(Fd),
+    ok;
 close_log_file(_) ->
     ok.
 
@@ -352,18 +363,16 @@ file_ctrl_start(HandlerName, HConfig) ->
 file_ctrl_stop(Pid) ->
     Pid ! stop.
 
-file_write_async(Pid, Bin) ->
+file_write(async, Pid, Bin) ->
     Pid ! {log,Bin},
-    ok.
-
-file_write_sync(Pid, Bin) ->
+    ok;
+file_write(sync, Pid, Bin) ->
     file_ctrl_call(Pid, {log,Bin}).
 
-file_ctrl_filesync_async(Pid) ->
+file_ctrl_filesync(async, Pid) ->
     Pid ! filesync,
-    ok.
-
-file_ctrl_filesync_sync(Pid) ->
+    ok;
+file_ctrl_filesync(sync, Pid) ->
     file_ctrl_call(Pid, filesync).
 
 file_ctrl_call(Pid, Msg) ->
@@ -405,60 +414,79 @@ file_ctrl_loop(State) ->
 
         %% synchronous event
         {{log,Bin},{From,MRef}} ->
-            State1 = write_to_dev(Bin,State),
+            State1 = ensure_file(State),
+            State2 = write_to_dev(Bin,State1),
             From ! {MRef,ok},
-            file_ctrl_loop(State1);
+            file_ctrl_loop(State2);
 
         filesync ->
             State1 = sync_dev(State),
             file_ctrl_loop(State1);
 
         {filesync,{From,MRef}} ->
-            State1 = sync_dev(State),
+            State1 = ensure_file(State),
+            State2 = sync_dev(State1),
             From ! {MRef,ok},
-            file_ctrl_loop(State1);
+            file_ctrl_loop(State2);
 
-        {update_rotation,Rotation} ->
-            State1 = update_rotation(Rotation,State),
-            file_ctrl_loop(State1);
+        {update_config,#{file_check:=FileCheck,
+                         max_no_bytes:=Size,
+                         max_no_files:=Count,
+                         compress_on_rotate:=Compress}} ->
+            State1 = update_rotation({Size,Count,Compress},State),
+            file_ctrl_loop(State1#{file_check=>FileCheck});
 
         stop ->
-            _ = close_log_file(State),
+            close_log_file(State),
             stopped
     end.
 
+maybe_ensure_file(#{file_check:=0}=State) ->
+    ensure_file(State);
+maybe_ensure_file(#{last_check:=T0,file_check:=CheckInt}=State)
+  when is_integer(CheckInt) ->
+    T = timestamp(),
+    if T-T0 > CheckInt -> ensure_file(State);
+       true -> State
+    end;
+maybe_ensure_file(State) ->
+    State.
+
 %% In order to play well with tools like logrotate, we need to be able
 %% to re-create the file if it has disappeared (e.g. if rotated by
 %% logrotate)
 ensure_file(#{fd:=Fd0,inode:=INode0,file_name:=FileName,modes:=Modes}=State) ->
-    case file:read_file_info(FileName) of
+    case file:read_file_info(FileName,[raw]) of
         {ok,#file_info{inode=INode0}} ->
-            State;
+            State#{last_check=>timestamp()};
         _ ->
-            _ = file:close(Fd0),
-            _ = file:close(Fd0), % delayed_write cause close not to close
+            close_log_file(Fd0),
             case file:open(FileName,Modes) of
                 {ok,Fd} ->
                     {ok,#file_info{inode=INode}} =
-                        file:read_file_info(FileName),
-                    State#{fd=>Fd,inode=>INode,synced=>true,sync_res=>ok};
+                        file:read_file_info(FileName,[raw]),
+                    State#{fd=>Fd,inode=>INode,
+                           last_check=>timestamp(),
+                           synced=>true,sync_res=>ok};
                 Error ->
                     exit({could_not_reopen_file,Error})
             end
-    end.
+    end;
+ensure_file(State) ->
+    State.
 
 write_to_dev(Bin,#{dev:=DevName}=State) ->
     io:put_chars(DevName, Bin),
     State;
 write_to_dev(Bin, State) ->
-    State1 = #{fd:=Fd} = ensure_file(State),
+    State1 = #{fd:=Fd} = maybe_ensure_file(State),
     Result = ?file_write(Fd, Bin),
     State2 = maybe_rotate_file(Bin,State1),
     maybe_notify_error(write,Result,State2),
     State2#{synced=>false,write_res=>Result}.
 
 sync_dev(#{synced:=false}=State) ->
-    State1 = #{fd:=Fd} = ensure_file(State),
+    State1 = #{fd:=Fd} = maybe_ensure_file(State),
     Result = ?file_datasync(Fd),
     maybe_notify_error(filesync,Result,State1),
     State1#{synced=>true,sync_res=>Result};
@@ -470,7 +498,7 @@ update_rotation({infinity,_,_},State) ->
     maps:remove(rotation,State);
 update_rotation({Size,Count,Compress},#{file_name:=FileName} = State) ->
     maybe_remove_archives(Count,State),
-    {ok,#file_info{size=CurrSize}} = file:read_file_info(FileName),
+    {ok,#file_info{size=CurrSize}} = file:read_file_info(FileName,[raw]),
     State1 = State#{rotation=>#{size=>Size,
                                 count=>Count,
                                 compress=>Compress,
@@ -481,7 +509,8 @@ update_rotation({Size,Count,Compress},#{file_name:=FileName} = State) ->
 maybe_remove_archives(Count,#{file_name:=FileName}=State) ->
     Archive = rot_file_name(FileName,Count,false),
     CompressedArchive = rot_file_name(FileName,Count,true),
-    case {file:read_file_info(Archive),file:read_file_info(CompressedArchive)} of
+    case {file:read_file_info(Archive,[raw]),
+          file:read_file_info(CompressedArchive,[raw])} of
         {{error,enoent},{error,enoent}} ->
             ok;
         _ ->
@@ -495,7 +524,7 @@ maybe_update_compress(Count,#{rotation:=#{count:=Count}}) ->
 maybe_update_compress(N,#{file_name:=FileName,
                           rotation:=#{compress:=Compress}}=State) ->
     Archive = rot_file_name(FileName,N,not Compress),
-    case file:read_file_info(Archive) of
+    case file:read_file_info(Archive,[raw]) of
         {ok,_} when Compress ->
             compress_file(Archive);
         {ok,_} ->
@@ -525,7 +554,7 @@ rotate_file(#{fd:=Fd0,file_name:=FileName,modes:=Modes,rotation:=Rotation}=State
     rotate_files(FileName,maps:get(count,Rotation),maps:get(compress,Rotation)),
     case file:open(FileName,Modes) of
         {ok,Fd} ->
-            {ok,#file_info{inode=INode}} = file:read_file_info(FileName),
+            {ok,#file_info{inode=INode}} = file:read_file_info(FileName,[raw]),
             State1#{fd=>Fd,inode=>INode,rotation=>Rotation#{curr_size=>0}};
         Error ->
             exit({could_not_reopen_file,Error})
@@ -609,3 +638,6 @@ maybe_notify_error(Op, Result, #{write_res:=WR,sync_res:=SR})
 maybe_notify_error(Op, Error, #{handler_name:=HandlerName,file_name:=FileName}) ->
     logger_h_common:error_notify({HandlerName,Op,FileName,Error}),
     ok.
+
+timestamp() ->
+    erlang:monotonic_time(millisecond).
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index c3cae49ce8..0c5516f82b 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -650,7 +650,7 @@ file_opts(Config) ->
                               filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
                               formatter=>{?MODULE,self()}}),
 
-    ModOpts = [delayed_write|OkFileOpts],      
+    ModOpts = [delayed_write|OkFileOpts],
     #{cb_state := #{handler_state := #{type:=file,
                                        file:=Log,
                                        modes:=ModOpts}}} =
@@ -692,7 +692,8 @@ sync(Config) ->
     Type = {file,Log},
     ok = logger:add_handler(?MODULE,
                             logger_std_h,
-                            #{config => #{type => Type},
+                            #{config => #{type => Type,
+                                          file_check => 10000},
                               filter_default=>log,
                               filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
                               formatter=>{?MODULE,nl}}),
@@ -1457,7 +1458,7 @@ rotate_size_reopen(Config) ->
     {ok,#file_info{size=580}} = file:read_file_info(Log),
     {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"),
     ok.
-rotate_size_reopen(cleanup,Config) ->
+rotate_size_reopen(cleanup,_Config) ->
     ok = stop_handler(?MODULE).
 
 rotation_opts(Config) ->
@@ -1577,7 +1578,7 @@ rotation_opts(Config) ->
                                    compress_on_rotate:=false}}} =
         logger_olp:info(h_proc_name()),
     ok.
-rotation_opts(cleanup,Config) ->
+rotation_opts(cleanup,_Config) ->
     ok = stop_handler(?MODULE).
 
 rotation_opts_restart_handler(Config) ->
@@ -1659,7 +1660,7 @@ rotation_opts_restart_handler(Config) ->
     [_] = filelib:wildcard(Log++".*"),
 
     ok.
-rotation_opts_restart_handler(cleanup,Config) ->
+rotation_opts_restart_handler(cleanup,_Config) ->
     ok = stop_handler(?MODULE).
 
 %%%-----------------------------------------------------------------