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(-) (limited to 'lib') 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