From 62cd2601e1206d2623a9a3c9d93d62f3c1f1556c Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 21 Feb 2019 20:40:06 +0100 Subject: [logger] Make sure log file is re-opened with configured file options Earlier, if the log file had to be re-opened, e.g. due to it being renamed or removed, it would always be opened with the default file options, even if other options were set in the configuration. Now, the configured options are used, except that 'append' is always added and 'exclusive' is always removed. --- lib/kernel/src/logger_std_h.erl | 60 ++++++++++++++++++++++++----------------- 1 file changed, 35 insertions(+), 25 deletions(-) diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 65f5b3876e..04e7f6ad83 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -301,51 +301,59 @@ file_ctrl_call(Pid, Msg) -> file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> process_flag(message_queue_data, off_heap), - FileName = element(2, FileInfo), case do_open_log_file(FileInfo) of {ok,File} -> Starter ! {self(),ok}, - file_ctrl_loop(File, FileName, false, ok, ok, HandlerName); + FileInfo1 = set_file_opt_append(FileInfo), + file_ctrl_loop(File, FileInfo1, false, ok, ok, HandlerName); {error,Reason} -> + FileName = element(2, FileInfo), Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; file_ctrl_init(HandlerName, StdDev, Starter) -> Starter ! {self(),ok}, file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). -file_ctrl_loop(File, DevName, Synced, +%% Modify file options to use when re-opening if the inode has +%% changed. I.e. the file may exist and if so should be appended to. +set_file_opt_append({file, FileName, Modes}) -> + {file, FileName, [append | Modes--[exclusive]]}; +set_file_opt_append(FileInfo) -> + FileInfo. + +file_ctrl_loop(File, FileInfo, Synced, PrevWriteResult, PrevSyncResult, HandlerName) -> receive %% asynchronous event {log,Bin} -> - File1 = ensure(File, DevName), - Result = write_to_dev(File1, Bin, DevName, + File1 = ensure(File, FileInfo), + Result = write_to_dev(File1, Bin, FileInfo, PrevWriteResult, HandlerName), - file_ctrl_loop(File1, DevName, false, + file_ctrl_loop(File1, FileInfo, false, Result, PrevSyncResult, HandlerName); %% synchronous event {{log,Bin},{From,MRef}} -> - File1 = ensure(File, DevName), - Result = write_to_dev(File1, Bin, DevName, + File1 = ensure(File, FileInfo), + Result = write_to_dev(File1, Bin, FileInfo, PrevWriteResult, HandlerName), From ! {MRef,ok}, - file_ctrl_loop(File1, DevName, false, + file_ctrl_loop(File1, FileInfo, false, Result, PrevSyncResult, HandlerName); filesync -> - File1 = ensure(File, DevName), - Result = sync_dev(File1, DevName, Synced, + File1 = ensure(File, FileInfo), + Result = sync_dev(File1, FileInfo, Synced, PrevSyncResult, HandlerName), - file_ctrl_loop(File1, DevName, true, + file_ctrl_loop(File1, FileInfo, true, PrevWriteResult, Result, HandlerName); {filesync,{From,MRef}} -> - File1 = ensure(File, DevName), - Result = sync_dev(File1, DevName, Synced, + File1 = ensure(File, FileInfo), + Result = sync_dev(File1, FileInfo, Synced, PrevSyncResult, HandlerName), From ! {MRef,ok}, - file_ctrl_loop(File1, DevName, true, + file_ctrl_loop(File1, FileInfo, true, PrevWriteResult, Result, HandlerName); stop -> @@ -358,14 +366,15 @@ file_ctrl_loop(File, DevName, Synced, %% logrotate) ensure(Fd,DevName) when is_atom(DevName) -> Fd; -ensure({Fd,INode},FileName) -> +ensure({Fd,INode},FileInfo) -> + FileName = element(2, FileInfo), case file:read_file_info(FileName) of {ok,#file_info{inode=INode}} -> {Fd,INode}; _ -> _ = file:close(Fd), _ = file:close(Fd), % delayed_write cause close not to close - case do_open_log_file({file,FileName}) of + case do_open_log_file(FileInfo) of {ok,File} -> File; Error -> @@ -376,21 +385,22 @@ ensure({Fd,INode},FileName) -> write_to_dev(DevName, Bin, _DevName, _PrevWriteResult, _HandlerName) when is_atom(DevName) -> io:put_chars(DevName, Bin); -write_to_dev({Fd,_}, Bin, FileName, PrevWriteResult, HandlerName) -> +write_to_dev({Fd,_}, Bin, FileInfo, PrevWriteResult, HandlerName) -> Result = ?file_write(Fd, Bin), - maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName). + maybe_notify_error(write,Result,PrevWriteResult,FileInfo,HandlerName). -sync_dev(_, _FileName, true, PrevSyncResult, _HandlerName) -> +sync_dev(_, _FileInfo, true, PrevSyncResult, _HandlerName) -> PrevSyncResult; -sync_dev({Fd,_}, FileName, false, PrevSyncResult, HandlerName) -> +sync_dev({Fd,_}, FileInfo, false, PrevSyncResult, HandlerName) -> Result = ?file_datasync(Fd), - maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName). + maybe_notify_error(filesync,Result,PrevSyncResult,FileInfo,HandlerName). -maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) -> +maybe_notify_error(_Op, ok, _PrevResult, _FileInfo, _HandlerName) -> ok; -maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) -> +maybe_notify_error(_Op, PrevResult, PrevResult, _FileInfo, _HandlerName) -> %% don't report same error twice PrevResult; -maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) -> +maybe_notify_error(Op, Error, _PrevResult, FileInfo, HandlerName) -> + FileName = element(2, FileInfo), logger_h_common:error_notify({HandlerName,Op,FileName,Error}), Error. -- cgit v1.2.3 From 0fb9b241d11588bdae29aa64ff96d1eb67d230af Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 22 Feb 2019 16:03:08 +0100 Subject: [logger] Refactor logger_std_h --- lib/kernel/src/logger_std_h.erl | 101 ++++++++++++++++----------------- lib/kernel/test/logger_std_h_SUITE.erl | 8 +-- 2 files changed, 53 insertions(+), 56 deletions(-) diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 04e7f6ad83..392ac7e67b 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -242,11 +242,12 @@ do_open_log_file({file,FileName,Modes}) -> _:Reason -> {error,Reason} end. -close_log_file(Std) when Std == standard_io; Std == standard_error -> - ok; -close_log_file({Fd,_}) -> +close_log_file(#{file:={Fd,_}}) -> _ = file:datasync(Fd), - _ = file:close(Fd). + _ = file:close(Fd); +close_log_file(_) -> + ok. + %%%----------------------------------------------------------------- @@ -305,14 +306,19 @@ file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> {ok,File} -> Starter ! {self(),ok}, FileInfo1 = set_file_opt_append(FileInfo), - file_ctrl_loop(File, FileInfo1, false, ok, ok, HandlerName); + file_ctrl_loop(#{name=>HandlerName, + file=>File, + file_info=>FileInfo1, + synced=>false, + write_res=>ok, + sync_res=>ok}); {error,Reason} -> FileName = element(2, FileInfo), Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; file_ctrl_init(HandlerName, StdDev, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(#{name=>HandlerName,dev=>StdDev}). %% Modify file options to use when re-opening if the inode has %% changed. I.e. the file may exist and if so should be appended to. @@ -321,86 +327,77 @@ set_file_opt_append({file, FileName, Modes}) -> set_file_opt_append(FileInfo) -> FileInfo. -file_ctrl_loop(File, FileInfo, Synced, - PrevWriteResult, PrevSyncResult, HandlerName) -> +file_ctrl_loop(State) -> receive %% asynchronous event {log,Bin} -> - File1 = ensure(File, FileInfo), - Result = write_to_dev(File1, Bin, FileInfo, - PrevWriteResult, HandlerName), - file_ctrl_loop(File1, FileInfo, false, - Result, PrevSyncResult, HandlerName); + State1 = write_to_dev(Bin,State), + file_ctrl_loop(State1); %% synchronous event {{log,Bin},{From,MRef}} -> - File1 = ensure(File, FileInfo), - Result = write_to_dev(File1, Bin, FileInfo, - PrevWriteResult, HandlerName), + State1 = write_to_dev(Bin,State), From ! {MRef,ok}, - file_ctrl_loop(File1, FileInfo, false, - Result, PrevSyncResult, HandlerName); + file_ctrl_loop(State1); filesync -> - File1 = ensure(File, FileInfo), - Result = sync_dev(File1, FileInfo, Synced, - PrevSyncResult, HandlerName), - file_ctrl_loop(File1, FileInfo, true, - PrevWriteResult, Result, HandlerName); + State1 = sync_dev(State), + file_ctrl_loop(State1); {filesync,{From,MRef}} -> - File1 = ensure(File, FileInfo), - Result = sync_dev(File1, FileInfo, Synced, - PrevSyncResult, HandlerName), + State1 = sync_dev(State), From ! {MRef,ok}, - file_ctrl_loop(File1, FileInfo, true, - PrevWriteResult, Result, HandlerName); + file_ctrl_loop(State1); stop -> - _ = close_log_file(File), + _ = close_log_file(State), stopped end. +write_to_dev(Bin,#{dev:=DevName}=State) -> + io:put_chars(DevName, Bin), + State; +write_to_dev(Bin, State) -> + State1 = #{file:={Fd,_}} = ensure_file(State), + Result = ?file_write(Fd, Bin), + maybe_notify_error(write,Result,State1), + State1#{synced=>false,write_res=>Result}. + +sync_dev(#{synced:=false}=State) -> + State1 = #{file:={Fd,_}} = ensure_file(State), + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,State1), + State1#{synced=>true,sync_res=>Result}; +sync_dev(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(Fd,DevName) when is_atom(DevName) -> - Fd; -ensure({Fd,INode},FileInfo) -> +ensure_file(#{file:={Fd,INode},file_info:=FileInfo}=State) -> FileName = element(2, FileInfo), case file:read_file_info(FileName) of {ok,#file_info{inode=INode}} -> - {Fd,INode}; + State; _ -> _ = file:close(Fd), _ = file:close(Fd), % delayed_write cause close not to close case do_open_log_file(FileInfo) of {ok,File} -> - File; + State#{file=>File}; Error -> exit({could_not_reopen_file,Error}) end end. -write_to_dev(DevName, Bin, _DevName, _PrevWriteResult, _HandlerName) - when is_atom(DevName) -> - io:put_chars(DevName, Bin); -write_to_dev({Fd,_}, Bin, FileInfo, PrevWriteResult, HandlerName) -> - Result = ?file_write(Fd, Bin), - maybe_notify_error(write,Result,PrevWriteResult,FileInfo,HandlerName). - -sync_dev(_, _FileInfo, true, PrevSyncResult, _HandlerName) -> - PrevSyncResult; -sync_dev({Fd,_}, FileInfo, false, PrevSyncResult, HandlerName) -> - Result = ?file_datasync(Fd), - maybe_notify_error(filesync,Result,PrevSyncResult,FileInfo,HandlerName). - -maybe_notify_error(_Op, ok, _PrevResult, _FileInfo, _HandlerName) -> +maybe_notify_error(_Op, ok, _State) -> ok; -maybe_notify_error(_Op, PrevResult, PrevResult, _FileInfo, _HandlerName) -> +maybe_notify_error(Op, Result, #{write_res:=WR,sync_res:=SR}) + when (Op==write andalso Result==WR) orelse + (Op==filesync andalso Result==SR) -> %% don't report same error twice - PrevResult; -maybe_notify_error(Op, Error, _PrevResult, FileInfo, HandlerName) -> + ok; +maybe_notify_error(Op, Error, #{name:=HandlerName,file_info:=FileInfo}) -> FileName = element(2, FileInfo), logger_h_common:error_notify({HandlerName,Op,FileName,Error}), - Error. + ok. diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index b2c2c8ba67..ba491ac5fa 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -646,7 +646,7 @@ sync(Config) -> formatter=>{?MODULE,nl}}), %% check repeated filesync happens - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, {file,datasync}]), @@ -656,7 +656,7 @@ sync(Config) -> check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, {file,datasync}, @@ -675,7 +675,7 @@ sync(Config) -> #{filesync_repeat_interval => no_repeat}), no_repeat = maps:get(filesync_repeat_interval, maps:get(cb_state, logger_olp:info(h_proc_name()))), - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, {file,datasync}, @@ -1658,7 +1658,7 @@ tpl([]) -> tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); -tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, +tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[Data,_]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> -- cgit v1.2.3 From e03c2bd640e1fc1503e92dfd74991f4205973c61 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 5 Mar 2019 11:25:00 +0100 Subject: [logger] Add better control of file modes in logger_std_h OTP-15602 It is allowed to set file modes for the handler to use when opening its log file. The given modes were earlier accepted without any checks, which could make the handler behave unexpectedly. This commit makes sure that * if none of write, append or exclusive is given, then append is added * if raw is not given, it is added * if delayed_write or {delayed_write,_,_} is not given, then delayed_write is added --- lib/kernel/doc/src/logger_std_h.xml | 23 ++++++++++------ lib/kernel/src/logger_std_h.erl | 50 +++++++++++++++++++++++++--------- lib/kernel/test/logger_SUITE.erl | 11 ++++---- lib/kernel/test/logger_std_h_SUITE.erl | 23 ++++++++++------ 4 files changed, 72 insertions(+), 35 deletions(-) diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index fcd180abd6..8c5a476d86 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -59,14 +59,21 @@

This has the value standard_io, standard_error, {file,LogFileName}, or {file,LogFileName,LogFileOpts}.

-

If LogFileOpts is specified, it replaces the default - list of options used when opening the log file. The default - list is [raw,append,delayed_write]. One reason to do - so can be to change append to, for - example, write, ensuring that the old log is - truncated when a node is restarted. See the reference manual - for file:open/2 - for more information about file options.

+

LogFileOpts specify the file options used when + opening the log file, + see file:open/2. + If LogFileOpts is not specified, the default option + list used is [raw,append,delayed_write]. If LogFileOpts + is specified, it replaces the default options list with the + following adjustments:

+ + + If raw is not found in the list, it is added + + + It write, append or exclusice are not + found in the list, append is added +

Log files are always UTF-8 encoded. The encoding can not be changed by setting the option {encoding,Encoding} in LogFileOpts.

diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 392ac7e67b..c634f86550 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -136,12 +136,10 @@ check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> {error,{illegal_config_change,?MODULE,WriteOnce,Other}} end. -check_config(#{type:=Type}=HConfig) -> +check_config(HConfig) -> case check_h_config(maps:to_list(HConfig)) of - ok when is_atom(Type) -> - {ok,HConfig#{filesync_repeat_interval=>no_repeat}}; ok -> - {ok,HConfig}; + {ok,fix_file_opts(HConfig)}; {error,{Key,Value}} -> {error,{invalid_config,?MODULE,#{Key=>Value}}} end. @@ -162,8 +160,40 @@ check_h_config([]) -> get_default_config() -> #{type => standard_io}. -filesync(_Name, _Mode, #{type := Type}=State) when is_atom(Type) -> - {ok,State}; +fix_file_opts(#{type:={file,File}}=HConfig) -> + fix_file_opts(HConfig#{type=>{file,File,[raw,append,delayed_write]}}); +fix_file_opts(#{type:={file,File,[]}}=HConfig) -> + fix_file_opts(HConfig#{type=>{file,File,[raw,append,delayed_write]}}); +fix_file_opts(#{type:={file,File,Modes}}=HConfig) -> + HConfig#{type=>{file,File,fix_modes(Modes)}}; +fix_file_opts(HConfig) -> + HConfig#{filesync_repeat_interval=>no_repeat}. + +fix_modes(Modes) -> + %% Ensure write|append|exclusive + Modes1 = + case [M || M <- Modes, + lists:member(M,[write,append,exclusive])] of + [] -> [append|Modes]; + _ -> Modes + end, + %% Ensure raw + Modes2 = + case lists:member(raw,Modes) of + false -> [raw|Modes1]; + true -> Modes1 + end, + %% Ensure delayed_write + case lists:partition(fun(delayed_write) -> true; + ({delayed_write,_,_}) -> true; + (_) -> false + end, Modes2) of + {[],_} -> + [delayed_write|Modes2]; + _ -> + Modes2 + end. + filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) -> ok = file_ctrl_filesync_async(FileCtrlPid), {ok,State}; @@ -217,12 +247,6 @@ open_log_file(HandlerName, FileInfo) -> Error -> Error end. -do_open_log_file({file,FileName}) -> - do_open_log_file({file,FileName,[raw,append,delayed_write]}); - -do_open_log_file({file,FileName,[]}) -> - do_open_log_file({file,FileName,[raw,append,delayed_write]}); - do_open_log_file({file,FileName,Modes}) -> try case filelib:ensure_dir(FileName) of @@ -323,7 +347,7 @@ file_ctrl_init(HandlerName, StdDev, Starter) -> %% Modify file options to use when re-opening if the inode has %% changed. I.e. the file may exist and if so should be appended to. set_file_opt_append({file, FileName, Modes}) -> - {file, FileName, [append | Modes--[exclusive]]}; + {file, FileName, [append | Modes--[write,append,exclusive]]}; set_file_opt_append(FileInfo) -> FileInfo. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 2dad651f9c..ce0c2efa10 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -1047,8 +1047,9 @@ kernel_config(Config) -> ok = rpc:call(Node,application,unset_env,[kernel,logger]), ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), + DefModes = [raw,append,delayed_write], #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,DefModes}}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but using 'logger' parameter instead of 'error_logger' @@ -1060,26 +1061,26 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,DefModes}}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with type={file,File,Modes} ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], + M = [raw,write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_std_h, #{config=>#{type=>{file,F,M}}}}]]), ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,M}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:={file,F,[delayed_write|M]}}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with disk_log handler ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_disk_log_h, #{config=>#{file=>F}}}]]), diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index ba491ac5fa..8cadb1083b 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -257,9 +257,10 @@ errors(Config) -> end, {error, - {handler_not_added,{open_failed,Log,_}}} = + {handler_not_added, + {invalid_config,logger_std_h,#{type:={file,Log,bad_file_opt}}}}} = logger:add_handler(myh3,logger_std_h, - #{config=>#{type=>{file,Log,[bad_file_opt]}}}), + #{config=>#{type=>{file,Log,bad_file_opt}}}), ok = logger:notice(?msg). @@ -607,11 +608,14 @@ reconfig(cleanup, _Config) -> file_opts(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), - BadFileOpts = [raw], - BadType = {file,Log,BadFileOpts}, - {error,{handler_not_added,{open_failed,Log,enoent}}} = - logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => BadType}}), + MissingAccess = [raw], + Type1 = {file,Log,MissingAccess}, + ok = logger:add_handler(?MODULE, logger_std_h, + #{config => #{type => Type1}}), + {ok,#{config:=#{type:={file,Log,Modes1}}}} = + logger:get_handler_config(?MODULE), + [append,delayed_write,raw] = lists:sort(Modes1), + ok = logger:remove_handler(?MODULE), OkFileOpts = [raw,append], OkType = {file,Log,OkFileOpts}, @@ -622,9 +626,10 @@ file_opts(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{cb_state := #{handler_state := #{type := OkType}}} = + ModType = {file,Log,[delayed_write|OkFileOpts]}, + #{cb_state := #{handler_state := #{type := ModType}}} = logger_olp:info(h_proc_name()), - {ok,#{config := #{type := OkType}}} = logger:get_handler_config(?MODULE), + {ok,#{config := #{type := ModType}}} = logger:get_handler_config(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), -- cgit v1.2.3 From 56cacefda4f18c8fdc45839b6bec1d07d0d2d78e Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 28 Feb 2019 20:49:08 +0100 Subject: [logger] Add log file rotation by options to logger_std_h OTP-15479 OTP-15662 New configuration map for logger_std_h: #{type => file, file => file:filename(), modes => [file:mode()], max_no_bytes => pos_integer() | infinity, max_no_files => non_neg_integer(), compress_on_rotate => boolean()} For backwards compatibility, the old variant for specifying the file name via the 'type' parameter is still supported, i.e. {file,FileName} and {file,FileName,Modes}, but it is no longer documented. Rotation scheme: The current log file always has the same name, and the archived files get extensions ".0", ".1", ... The newest archive has extension ".0", and the oldest archive has the highest number. If 'compress_on_rotate' is set to true, the archived files are gzipped and get the additional extension ".gz", e.g. error.log.0.gz. Rotation is turned off by setting 'max_no_bytes' to infinity. Setting 'max_no_files' to 0 does not turn off rotation, but only specifies that no archives are to be saved. --- lib/kernel/doc/src/kernel_app.xml | 10 +- lib/kernel/doc/src/logger.xml | 2 +- lib/kernel/doc/src/logger_chapter.xml | 14 +- lib/kernel/doc/src/logger_std_h.xml | 96 ++++++-- lib/kernel/src/logger_h_common.erl | 35 +-- lib/kernel/src/logger_std_h.erl | 358 ++++++++++++++++++++++------- lib/kernel/test/logger_SUITE.erl | 11 +- lib/kernel/test/logger_std_h_SUITE.erl | 408 +++++++++++++++++++++++++++++++-- 8 files changed, 778 insertions(+), 156 deletions(-) diff --git a/lib/kernel/doc/src/kernel_app.xml b/lib/kernel/doc/src/kernel_app.xml index 15dbdb47dc..dbd83e1a6e 100644 --- a/lib/kernel/doc/src/kernel_app.xml +++ b/lib/kernel/doc/src/kernel_app.xml @@ -510,11 +510,13 @@ MaxT = TickTime + TickTime / 4 parameters for Logger are not set.

error_logger - Replaced by setting the type of the default - logger_std_h - to the same value. Example: + Replaced by setting the type, and possibly + file and + modes + parameters of the default logger_std_h handler. Example: -erl -kernel logger '[{handler,default,logger_std_h,#{config=>#{type=>{file,"/tmp/erlang.log"}}}}]' +erl -kernel logger '[{handler,default,logger_std_h,#{config=>#{file=>"/tmp/erlang.log"}}}]' error_logger_format_depth diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index df2d081d76..50b1419783 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -66,7 +66,7 @@ logger:error("error happened because: ~p", [Reason]). % Without macro [{kernel, [{logger, [{handler, default, logger_std_h, - #{config => #{type => {file, "path/to/file.log"}}}}]}]}]. + #{config => #{file => "path/to/file.log"}}}]}]}].

For more information about: diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 5ed7397135..bfd0acf634 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -801,7 +801,7 @@ logger:debug(#{got => connection_request, id => Id, state => State}, [{kernel, [{logger, [{handler, default, logger_std_h, % {handler, HandlerId, Module, - #{config => #{type => {file,"log/erlang.log"}}}} % Config} + #{config => #{file => "log/erlang.log"}}} % Config} ]}]}].

Modify the default handler to print each log event as a @@ -831,10 +831,10 @@ logger:debug(#{got => connection_request, id => Id, state => State}, [{logger, [{handler, default, logger_std_h, #{level => error, - config => #{type => {file, "log/erlang.log"}}}}, + config => #{file => "log/erlang.log"}}}, {handler, info, logger_std_h, #{level => debug, - config => #{type => {file, "log/debug.log"}}}} + config => #{file => "log/debug.log"}}} ]}]}]. @@ -1004,10 +1004,10 @@ ok

Then, add a new handler which prints to file. You can use the handler module logger_std_h, - and specify type {file,File}.:

+ and configure it to log to file:

-4> Config = #{config => #{type => {file,"./info.log"}}, level => info}.
-#{config => #{type => {file,"./info.log"}},level => info}
+4> Config = #{config => #{file => "./info.log"}, level => info}.
+#{config => #{file => "./info.log"},level => info}
 5> logger:add_handler(myhandler, logger_std_h, Config).
 ok

Since filter_default defaults to log, this @@ -1246,7 +1246,7 @@ do_log(Fd, LogEvent, #{formatter := {FModule, FConfig}}) ->

A configuration example:

logger:add_handler(my_standard_h, logger_std_h, - #{config => #{type => {file,"./system_info.log"}, + #{config => #{file => "./system_info.log", sync_mode_qlen => 100, drop_mode_qlen => 1000, flush_qlen => 2000}}). diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index 8c5a476d86..ce54a91342 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -55,37 +55,86 @@ is stored in a sub map with the key config, and can contain the following parameters:

- type + type = standard_io | standard_error | file -

This has the value standard_io, standard_error, - {file,LogFileName}, or {file,LogFileName,LogFileOpts}.

-

LogFileOpts specify the file options used when - opening the log file, +

Specifies the log destination.

+

The value is set when the handler is added, and it can not + be changed in runtime.

+

Defaults to standard_io, unless + parameter file is + given, in which case it defaults to file.

+ + file = file:filename() + +

This specifies the name of the log file when the handler is + of type file.

+

The value is set when the handler is added, and it can not + be changed in runtime.

+

Defaults to the same name as the handler identity, in the + current directory.

+ + modes = [file:mode()] + +

This specifies the file modes to use when opening the log + file, see file:open/2. - If LogFileOpts is not specified, the default option - list used is [raw,append,delayed_write]. If LogFileOpts - is specified, it replaces the default options list with the + If modes are not specified, the default list used + is [raw,append,delayed_write]. If modes are + specified, the list replaces the default modes list with the following adjustments:

- If raw is not found in the list, it is added + If raw is not found in the list, it is added. - It write, append or exclusice are not - found in the list, append is added + If none of write, append or exclusive is + found in the list, append is added. + If none of delayed_write + or {delayed_write,Size,Delay} is found in the + list, delayed_write is added.

Log files are always UTF-8 encoded. The encoding can not be - changed by setting the option {encoding,Encoding} - in LogFileOpts.

-

Notice that the standard handler does not have support for - circular logging. Use the disk_log handler, - logger_disk_log_h, - for this.

+ changed by setting the mode {encoding,Encoding}.

The value is set when the handler is added, and it can not be changed in runtime.

-

Defaults to standard_io.

+

Defaults to [raw,append,delayed_write].

+ + max_no_bytes = pos_integer() | infinity + +

This parameter specifies if the log file should be rotated + or not. The value infinity means the log file will + grow indefinitely, while an integer value specifies at which + file size (bytes) the file is rotated.

+

Defaults to infinity.

+ + max_no_files = non_neg_integer() + +

This parameter specifies the number of rotated log file + archives to keep. This has meaning only + if max_no_bytes + is set to an integer value.

+

The log archives are + named FileName.0, FileName.1, + ... FileName.N, where FileName is the name of + the current log file. FileName.0 is the newest of the + archives. The maximum value for N is the value + of max_no_files minus 1.

+

Notice that setting this value to 0 does not turn of + rotation. It only specifies that no archives are kept.

+

Defaults to 0.

+ + compress_on_rotate = boolean() + +

This parameter specifies if the rotated log file archives + shall be compressed or not. If set to true, all + archives are compressed with gzip, and renamed + to FileName.N.gz

+

compress_on_rotate has no meaning if max_no_bytes has the + value infinity.

+

Defaults to false.

 - filesync_repeat_interval + filesync_repeat_interval = pos_integer() | no_repeat

This value, in milliseconds, specifies how often the handler does a file sync operation to write buffered data to disk. The handler attempts @@ -104,12 +153,13 @@ standard handler and the disk_log handler, and are documented in the User's Guide .

-

Notice that if changing the configuration of the handler in runtime, - the type parameter must not be modified.

+

Notice that if changing the configuration of the handler in + runtime, the type, file, or modes parameters + must not be modified.

Example of adding a standard handler:

logger:add_handler(my_standard_h, logger_std_h, - #{config => #{type => {file,"./system_info.log"}, + #{config => #{file => "./system_info.log", filesync_repeat_interval => 1000}}).

To set the default handler, that starts initially with @@ -117,7 +167,7 @@ logger:add_handler(my_standard_h, logger_std_h, change the Kernel default logger configuration. Example:

erl -kernel logger '[{handler,default,logger_std_h, - #{config => #{type => {file,"./log.log"}}}}]' + #{config => #{file => "./log.log"}}}]'

An example of how to replace the standard handler with a disk_log handler at startup is found in the diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index e69f6de38d..1a4119a9ba 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -142,8 +142,9 @@ changing_config(SetOrUpdate, maps:with(?OLP_KEYS,NewHConfig0)), case logger_olp:set_opts(Olp,NewOlpOpts) of ok -> - maybe_set_repeated_filesync(Olp,OldCommonConfig, - NewCommonConfig), + logger_olp:cast(Olp, {config_changed, + NewCommonConfig, + NewHandlerConfig}), ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), NewHConfig = maps:merge( @@ -281,11 +282,24 @@ handle_cast(repeated_filesync, State#{handler_state => HS, last_op => sync} end, {noreply,set_repeated_filesync(State1)}; - -handle_cast({set_repeated_filesync,FSyncInt},State) -> - State1 = State#{filesync_repeat_interval=>FSyncInt}, - State2 = set_repeated_filesync(cancel_repeated_filesync(State1)), - {noreply, State2}. +handle_cast({config_changed, CommonConfig, HConfig}, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + filesync_repeat_interval := OldFSyncInt}) -> + State1 = + case maps:get(filesync_repeat_interval,CommonConfig) of + OldFSyncInt -> + State; + FSyncInt -> + set_repeated_filesync( + cancel_repeated_filesync( + State#{filesync_repeat_interval=>FSyncInt})) + end, + HS = try Module:config_changed(Name, HConfig, HandlerState) + catch error:undef -> HandlerState + end, + {noreply, State1#{handler_state => HS}}. handle_info(Info, #{id := Name, module := Module, handler_state := HandlerState} = State) -> @@ -447,10 +461,3 @@ cancel_repeated_filesync(State) -> end. error_notify(Term) -> ?internal_log(error, Term). - -maybe_set_repeated_filesync(_Olp, - #{filesync_repeat_interval:=FSyncInt}, - #{filesync_repeat_interval:=FSyncInt}) -> - ok; -maybe_set_repeated_filesync(Olp,_,#{filesync_repeat_interval:=FSyncInt}) -> - logger_olp:cast(Olp,{set_repeated_filesync,FSyncInt}). diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index c634f86550..023567c183 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -29,7 +29,7 @@ -export([filesync/1]). %% logger_h_common callbacks --export([init/2, check_config/4, reset_state/2, +-export([init/2, check_config/4, config_changed/3, reset_state/2, filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks @@ -105,67 +105,96 @@ filter_config(Config) -> %%%=================================================================== %%% logger_h_common callbacks %%%=================================================================== -init(Name, #{type := Type}) -> - case open_log_file(Name, Type) of +init(Name, Config) -> + MyConfig = maps:with([type,file,modes,max_no_bytes, + max_no_files,compress_on_rotate],Config), + case file_ctrl_start(Name, MyConfig) of {ok,FileCtrlPid} -> - {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}}; + {ok,MyConfig#{file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -check_config(_Name,set,undefined,NewHConfig) -> - check_config(maps:merge(get_default_config(),NewHConfig)); -check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> - WriteOnce = maps:with([type],OldHConfig), +check_config(Name,set,undefined,NewHConfig) -> + check_h_config(merge_default_config(Name,normalize_config(NewHConfig))); +check_config(Name,SetOrUpdate,OldHConfig,NewHConfig0) -> + WriteOnce = maps:with([type,file,modes],OldHConfig), Default = case SetOrUpdate of set -> %% Do not reset write-once fields to defaults - maps:merge(get_default_config(),WriteOnce); + merge_default_config(Name,WriteOnce); update -> OldHConfig end, - NewHConfig = maps:merge(Default, NewHConfig0), + NewHConfig = maps:merge(Default, normalize_config(NewHConfig0)), %% Fail if write-once fields are changed - case maps:with([type],NewHConfig) of + case maps:with([type,file,modes],NewHConfig) of WriteOnce -> - check_config(NewHConfig); + check_h_config(NewHConfig); Other -> {error,{illegal_config_change,?MODULE,WriteOnce,Other}} end. -check_config(HConfig) -> - case check_h_config(maps:to_list(HConfig)) of +check_h_config(HConfig) -> + case check_h_config(maps:get(type,HConfig),maps:to_list(HConfig)) of ok -> {ok,fix_file_opts(HConfig)}; {error,{Key,Value}} -> {error,{invalid_config,?MODULE,#{Key=>Value}}} end. -check_h_config([{type,Type} | Config]) when Type == standard_io; - Type == standard_error -> - check_h_config(Config); -check_h_config([{type,{file,File}} | Config]) when is_list(File) -> - check_h_config(Config); -check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), - is_list(Modes) -> - check_h_config(Config); -check_h_config([Other | _]) -> +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 -> + 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(_Type,[Other | _]) -> {error,Other}; -check_h_config([]) -> +check_h_config(_Type,[]) -> ok. -get_default_config() -> - #{type => standard_io}. - -fix_file_opts(#{type:={file,File}}=HConfig) -> - fix_file_opts(HConfig#{type=>{file,File,[raw,append,delayed_write]}}); -fix_file_opts(#{type:={file,File,[]}}=HConfig) -> - fix_file_opts(HConfig#{type=>{file,File,[raw,append,delayed_write]}}); -fix_file_opts(#{type:={file,File,Modes}}=HConfig) -> - HConfig#{type=>{file,File,fix_modes(Modes)}}; +normalize_config(#{type:={file,File}}=HConfig) -> + HConfig#{type=>file,file=>File}; +normalize_config(#{type:={file,File,Modes}}=HConfig) -> + HConfig#{type=>file,file=>File,modes=>Modes}; +normalize_config(HConfig) -> + HConfig. + +merge_default_config(Name,#{type:=Type}=HConfig) -> + merge_default_config(Name,Type,HConfig); +merge_default_config(Name,#{file:=_}=HConfig) -> + merge_default_config(Name,file,HConfig); +merge_default_config(Name,HConfig) -> + merge_default_config(Name,standard_io,HConfig). + +merge_default_config(Name,Type,HConfig) -> + maps:merge(get_default_config(Name,Type),HConfig). + +get_default_config(Name,file) -> + #{type => file, + file => atom_to_list(Name), + modes => [raw,append], + max_no_bytes => infinity, + max_no_files => 0, + compress_on_rotate => false}; +get_default_config(_Name,Type) -> + #{type => Type}. + +fix_file_opts(#{modes:=Modes}=HConfig) -> + HConfig#{modes=>fix_modes(Modes)}; fix_file_opts(HConfig) -> HConfig#{filesync_repeat_interval=>no_repeat}. @@ -194,6 +223,24 @@ fix_modes(Modes) -> Modes2 end. +config_changed(_Name, + #{max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}=State) -> + State; +config_changed(_Name, + #{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}; +config_changed(_Name,_NewHConfig,State) -> + State. + filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) -> ok = file_ctrl_filesync_async(FileCtrlPid), {ok,State}; @@ -211,9 +258,9 @@ write(_Name, sync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> reset_state(_Name, State) -> State. -handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) -> +handle_info(_Name, {'EXIT',Pid,Why}, #{file_ctrl_pid := Pid}=State) -> %% file_ctrl_pid died, file error, terminate handler - exit({error,{write_failed,FileInfo,Why}}); + exit({error,{write_failed,maps:with([type,file,modes],State),Why}}); handle_info(_, _, State) -> State. @@ -241,13 +288,12 @@ terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> %%%----------------------------------------------------------------- %%% -open_log_file(HandlerName, FileInfo) -> - case file_ctrl_start(HandlerName, FileInfo) of - OK = {ok,_FileCtrlPid} -> OK; - Error -> Error - end. - -do_open_log_file({file,FileName,Modes}) -> +open_log_file(HandlerName,#{type:=file, + file:=FileName, + modes:=Modes, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}) -> try case filelib:ensure_dir(FileName) of ok -> @@ -255,7 +301,17 @@ do_open_log_file({file,FileName,Modes}) -> {ok, Fd} -> {ok,#file_info{inode=INode}} = file:read_file_info(FileName), - {ok, {Fd, INode}}; + UpdateModes = [append | Modes--[write,append,exclusive]], + State0 = #{handler_name=>HandlerName, + file_name=>FileName, + modes=>UpdateModes, + fd=>Fd, + inode=>INode, + synced=>false, + write_res=>ok, + sync_res=>ok}, + State = update_rotation({Size,Count,Compress},State0), + {ok,State}; Error -> Error end; @@ -277,11 +333,11 @@ close_log_file(_) -> %%%----------------------------------------------------------------- %%% File control process -file_ctrl_start(HandlerName, FileInfo) -> +file_ctrl_start(HandlerName, HConfig) -> Starter = self(), FileCtrlPid = spawn_link(fun() -> - file_ctrl_init(HandlerName, FileInfo, Starter) + file_ctrl_init(HandlerName, HConfig, Starter) end), receive {FileCtrlPid,ok} -> @@ -324,32 +380,21 @@ file_ctrl_call(Pid, Msg) -> {error,{no_response,Pid}} end. -file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> +file_ctrl_init(HandlerName, + #{type:=file, + file:=FileName} = HConfig, + Starter) -> process_flag(message_queue_data, off_heap), - case do_open_log_file(FileInfo) of - {ok,File} -> + case open_log_file(HandlerName,HConfig) of + {ok,State} -> Starter ! {self(),ok}, - FileInfo1 = set_file_opt_append(FileInfo), - file_ctrl_loop(#{name=>HandlerName, - file=>File, - file_info=>FileInfo1, - synced=>false, - write_res=>ok, - sync_res=>ok}); + file_ctrl_loop(State); {error,Reason} -> - FileName = element(2, FileInfo), Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; -file_ctrl_init(HandlerName, StdDev, Starter) -> +file_ctrl_init(HandlerName, #{type:=StdDev}, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(#{name=>HandlerName,dev=>StdDev}). - -%% Modify file options to use when re-opening if the inode has -%% changed. I.e. the file may exist and if so should be appended to. -set_file_opt_append({file, FileName, Modes}) -> - {file, FileName, [append | Modes--[write,append,exclusive]]}; -set_file_opt_append(FileInfo) -> - FileInfo. + file_ctrl_loop(#{handler_name=>HandlerName,dev=>StdDev}). file_ctrl_loop(State) -> receive @@ -373,45 +418,185 @@ file_ctrl_loop(State) -> From ! {MRef,ok}, file_ctrl_loop(State1); + {update_rotation,Rotation} -> + State1 = update_rotation(Rotation,State), + file_ctrl_loop(State1); + stop -> _ = close_log_file(State), stopped end. +%% 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 + {ok,#file_info{inode=INode0}} -> + State; + _ -> + _ = file:close(Fd0), + _ = file:close(Fd0), % delayed_write cause close not to close + 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}; + Error -> + exit({could_not_reopen_file,Error}) + end + end. + write_to_dev(Bin,#{dev:=DevName}=State) -> io:put_chars(DevName, Bin), State; write_to_dev(Bin, State) -> - State1 = #{file:={Fd,_}} = ensure_file(State), + State1 = #{fd:=Fd} = ensure_file(State), Result = ?file_write(Fd, Bin), - maybe_notify_error(write,Result,State1), - State1#{synced=>false,write_res=>Result}. + State2 = maybe_rotate_file(Bin,State1), + maybe_notify_error(write,Result,State2), + State2#{synced=>false,write_res=>Result}. sync_dev(#{synced:=false}=State) -> - State1 = #{file:={Fd,_}} = ensure_file(State), + State1 = #{fd:=Fd} = ensure_file(State), Result = ?file_datasync(Fd), maybe_notify_error(filesync,Result,State1), State1#{synced=>true,sync_res=>Result}; sync_dev(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(#{file:={Fd,INode},file_info:=FileInfo}=State) -> - FileName = element(2, FileInfo), - case file:read_file_info(FileName) of - {ok,#file_info{inode=INode}} -> - State; +update_rotation({infinity,_,_},State) -> + maybe_remove_archives(0,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), + State1 = State#{rotation=>#{size=>Size, + count=>Count, + compress=>Compress, + curr_size=>CurrSize}}, + maybe_update_compress(0,State1), + maybe_rotate_file(0,State1). + +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 + {{error,enoent},{error,enoent}} -> + ok; _ -> - _ = file:close(Fd), - _ = file:close(Fd), % delayed_write cause close not to close - case do_open_log_file(FileInfo) of - {ok,File} -> - State#{file=>File}; - Error -> - exit({could_not_reopen_file,Error}) - end + _ = file:delete(Archive), + _ = file:delete(CompressedArchive), + maybe_remove_archives(Count+1,State) + end. + +maybe_update_compress(Count,#{rotation:=#{count:=Count}}) -> + ok; +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 + {ok,_} when Compress -> + compress_file(Archive); + {ok,_} -> + decompress_file(Archive); + _ -> + ok + end, + maybe_update_compress(N+1,State). + +maybe_rotate_file(Bin,#{rotation:=_}=State) when is_binary(Bin) -> + maybe_rotate_file(byte_size(Bin),State); +maybe_rotate_file(AddSize,#{rotation:=#{size:=RotSize, + curr_size:=CurrSize}=Rotation}=State) -> + NewSize = CurrSize + AddSize, + if NewSize>RotSize -> + rotate_file(State#{rotation=>Rotation#{curr_size=>NewSize}}); + true -> + State#{rotation=>Rotation#{curr_size=>NewSize}} + end; +maybe_rotate_file(_Bin,State) -> + State. + +rotate_file(#{fd:=Fd0,file_name:=FileName,modes:=Modes,rotation:=Rotation}=State) -> + State1 = sync_dev(State), + _ = file:close(Fd0), + _ = file:close(Fd0), + 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), + State1#{fd=>Fd,inode=>INode,rotation=>Rotation#{curr_size=>0}}; + Error -> + exit({could_not_reopen_file,Error}) + end. + +rotate_files(FileName,0,_Compress) -> + _ = file:delete(FileName), + ok; +rotate_files(FileName,1,Compress) -> + FileName0 = FileName++".0", + _ = file:rename(FileName,FileName0), + if Compress -> compress_file(FileName0); + true -> ok + end, + ok; +rotate_files(FileName,Count,Compress) -> + _ = file:rename(rot_file_name(FileName,Count-2,Compress), + rot_file_name(FileName,Count-1,Compress)), + rotate_files(FileName,Count-1,Compress). + +rot_file_name(FileName,Count,false) -> + FileName ++ "." ++ integer_to_list(Count); +rot_file_name(FileName,Count,true) -> + rot_file_name(FileName,Count,false) ++ ".gz". + +compress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(FileName++".gz",[write]), + Z = zlib:open(), + zlib:deflateInit(Z, default, deflated, 31, 8, default), + compress_data(Z,In,Out), + zlib:deflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +compress_data(Z,In,Out) -> + case file:read(In,100000) of + {ok,Data} -> + Compressed = zlib:deflate(Z, Data), + _ = file:write(Out,Compressed), + compress_data(Z,In,Out); + eof -> + Compressed = zlib:deflate(Z, <<>>, finish), + _ = file:write(Out,Compressed), + ok + end. + +decompress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(filename:rootname(FileName,".gz"),[write]), + Z = zlib:open(), + zlib:inflateInit(Z, 31), + decompress_data(Z,In,Out), + zlib:inflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +decompress_data(Z,In,Out) -> + case file:read(In,1000) of + {ok,Data} -> + Decompressed = zlib:inflate(Z, Data), + _ = file:write(Out,Decompressed), + decompress_data(Z,In,Out); + eof -> + ok end. maybe_notify_error(_Op, ok, _State) -> @@ -421,7 +606,6 @@ maybe_notify_error(Op, Result, #{write_res:=WR,sync_res:=SR}) (Op==filesync andalso Result==SR) -> %% don't report same error twice ok; -maybe_notify_error(Op, Error, #{name:=HandlerName,file_info:=FileInfo}) -> - FileName = element(2, FileInfo), +maybe_notify_error(Op, Error, #{handler_name:=HandlerName,file_name:=FileName}) -> logger_h_common:error_notify({HandlerName,Op,FileName,Error}), ok. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index ce0c2efa10..b7439a3fa8 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -1047,10 +1047,12 @@ kernel_config(Config) -> ok = rpc:call(Node,application,unset_env,[kernel,logger]), ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), - DefModes = [raw,append,delayed_write], #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,DefModes}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + [append,delayed_write,raw] = lists:sort(Modes), + %% Same, but using 'logger' parameter instead of 'error_logger' ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again @@ -1061,7 +1063,8 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,DefModes}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with type={file,File,Modes} @@ -1075,7 +1078,7 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, handlers:=[#{id:=default,filters:=DF, - config:=#{type:={file,F,[delayed_write|M]}}}], + config:=#{type:=file,file:=F,modes:=[delayed_write|M]}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with disk_log handler diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 8cadb1083b..c3cae49ce8 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -112,6 +112,8 @@ all() -> add_remove_instance_standard_error, add_remove_instance_file1, add_remove_instance_file2, + add_remove_instance_file3, + add_remove_instance_file4, default_formatter, filter_config, errors, @@ -142,7 +144,12 @@ all() -> restart_after, handler_requests_under_load, recreate_deleted_log, - reopen_changed_log + reopen_changed_log, + rotate_size, + rotate_size_compressed, + rotate_size_reopen, + rotation_opts, + rotation_opts_restart_handler ]. add_remove_instance_tty(_Config) -> @@ -179,10 +186,27 @@ add_remove_instance_file2(Config) -> add_remove_instance_file2(cleanup,_Config) -> logger_std_h_remove(). -add_remove_instance_file(Log, Type) -> +add_remove_instance_file3(_Config) -> + Log = atom_to_list(?MODULE), + StdHConfig = #{type=>file}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file3(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file4(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog4.txt"), + StdHConfig = #{file=>Log,modes=>[]}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file4(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file(Log, Type) when not is_map(Type) -> + add_remove_instance_file(Log,#{type=>Type}); +add_remove_instance_file(Log, StdHConfig) when is_map(StdHConfig) -> ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => StdHConfig, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), @@ -258,7 +282,7 @@ errors(Config) -> {error, {handler_not_added, - {invalid_config,logger_std_h,#{type:={file,Log,bad_file_opt}}}}} = + {invalid_config,logger_std_h,#{modes:=bad_file_opt}}}} = logger:add_handler(myh3,logger_std_h, #{config=>#{type=>{file,Log,bad_file_opt}}}), @@ -608,11 +632,11 @@ reconfig(cleanup, _Config) -> file_opts(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), - MissingAccess = [raw], - Type1 = {file,Log,MissingAccess}, + MissingOpts = [raw], + Type1 = {file,Log,MissingOpts}, ok = logger:add_handler(?MODULE, logger_std_h, #{config => #{type => Type1}}), - {ok,#{config:=#{type:={file,Log,Modes1}}}} = + {ok,#{config:=#{type:=file,file:=Log,modes:=Modes1}}} = logger:get_handler_config(?MODULE), [append,delayed_write,raw] = lists:sort(Modes1), ok = logger:remove_handler(?MODULE), @@ -621,15 +645,38 @@ file_opts(Config) -> OkType = {file,Log,OkFileOpts}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => OkType}, + #{config => #{type => OkType}, % old format + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + ModOpts = [delayed_write|OkFileOpts], + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => file, + file => Log, + modes => OkFileOpts}, % new format filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - ModType = {file,Log,[delayed_write|OkFileOpts]}, - #{cb_state := #{handler_state := #{type := ModType}}} = + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger_olp:info(h_proc_name()), - {ok,#{config := #{type := ModType}}} = logger:get_handler_config(?MODULE), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger:get_handler_config(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -1290,6 +1337,331 @@ reopen_changed_log(Config) -> reopen_changed_log(cleanup, _Config) -> ok = stop_handler(?MODULE). +rotate_size(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".1"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1005}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + ok. +rotate_size(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_compressed(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + #{config=>#{max_no_bytes=>1000, + max_no_files=>2, + compress_on_rotate=>true}}), + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".0.gz"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".1.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=38}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + ok. +rotate_size_compressed(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_reopen(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + {ok,HConfig} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler(?MODULE,maps:get(module,HConfig),HConfig), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {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) -> + ok = stop_handler(?MODULE). + +rotation_opts(Config) -> + {Log,_HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + #{max_no_bytes:=infinity, + max_no_files:=0, + compress_on_rotate:=false} = StdHConfig, + + %% Test bad rotation config + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_bytes=>0}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_files=>infinity}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config, + #{compress_on_rotate=>undefined}), + + + %% Test good rotation config - start with no rotation + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=200}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Turn on rotation, check that existing file is rotated since its + %% size exceeds max_no_bytes + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0 = Log++".0", + {ok,#file_info{size=200}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Extend size and count and check that nothing changes with existing files + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>200, + max_no_files=>3}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Add more log events and see that extended size and count works + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".2"), + [_,_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and check that archive files that exceed the new + %% count are moved + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Extend size and count again, and turn on compression. Check + %% that archives are compressed + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2, + compress_on_rotate=>true}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0gz = Log0++".gz", + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + [Log0gz] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + {ok,#file_info{size=29}} = file:read_file_info(Log++".1.gz"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and turn off compression. Check that archives that + %% exceeds the new count are removed, and the rest are + %% uncompressed. + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1, + compress_on_rotate=>false}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Check that config and handler state agree on the current rotation settings + {ok,#{config:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger:get_handler_config(?MODULE), + #{cb_state:=#{handler_state:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger_olp:info(h_proc_name()), + ok. +rotation_opts(cleanup,Config) -> + ok = stop_handler(?MODULE). + +rotation_opts_restart_handler(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + + %% Fill all logs + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,15)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=60}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off rotation. Check that archives are removed. + {ok,#{config:=StdHConfig1}=HConfig1} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig1#{config=>StdHConfig1#{max_no_bytes=>infinity}}), + timer:sleep(100), + {ok,#file_info{size=60}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Add some log events and check that file is no longer rotated. + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=260}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and trun on rotation. Check that file is rotated. + {ok,#{config:=StdHConfig2}=HConfig2} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig2#{config=>StdHConfig2#{max_no_bytes=>100, + max_no_files=>2}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=260}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=80}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=260}} = file:read_file_info(Log++".1"), + + %% Stop/start handler, reduce count and turn on compression. Check + %% that excess archives are removed, and the rest compressed. + {ok,#{config:=StdHConfig3}=HConfig3} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig3#{config=>StdHConfig3#{max_no_bytes=>75, + max_no_files=>1, + compress_on_rotate=>true}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log++".0.gz"), + [_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off compression. Check that achives + %% are decompressed. + {ok,#{config:=StdHConfig4}=HConfig4} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig4#{config=>StdHConfig4#{compress_on_rotate=>false}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=80}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + ok. +rotation_opts_restart_handler(cleanup,Config) -> + ok = stop_handler(?MODULE). + %%%----------------------------------------------------------------- %%% send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> @@ -1310,8 +1682,8 @@ start_handler(Name, TTY, _Config) when TTY == standard_io; ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {HConfig,StdHConfig}; @@ -1325,12 +1697,17 @@ start_handler(Name, FuncName, Config) -> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => Type}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {Log,HConfig,StdHConfig}. + +filter_only_this_domain(Name) -> + [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, + {domain,{fun logger_filters:domain/2,{log,super,[Name]}}}]. + stop_handler(Name) -> R = logger:remove_handler(Name), ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), @@ -1747,4 +2124,3 @@ filesync_rep_int() -> file_delete(Log) -> file:delete(Log). - -- cgit v1.2.3 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(-) 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