From e2af137524ac6a645689daf309871893dcc655a1 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 4 Mar 2019 19:15:24 +0100 Subject: [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. --- lib/kernel/doc/src/logger_std_h.xml | 19 +++++ lib/kernel/src/logger_std_h.erl | 136 ++++++++++++++++++++------------- lib/kernel/test/logger_std_h_SUITE.erl | 11 +-- 3 files changed, 109 insertions(+), 57 deletions(-) (limited to 'lib/kernel') 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 infinity.

Defaults to false.

+ file_check = non_neg_integer() + +

When logger_std_h 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.

+

In order to allow minimizing the performance loss, the + file_check parameter can be set to a positive integer + value, N. The handler will then skip reading the file + information prior to writing, as long as no more + than N milliseconds have passed since it was last + read.

+

Notice that the risk of loosing log events grows when + the file_check value grows.

+

Defaults to 0.

+ filesync_repeat_interval = pos_integer() | no_repeat

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). %%%----------------------------------------------------------------- -- cgit v1.2.3