diff options
Diffstat (limited to 'lib/kernel/src/logger_std_h.erl')
| -rw-r--r-- | lib/kernel/src/logger_std_h.erl | 645 |
1 files changed, 645 insertions, 0 deletions
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl new file mode 100644 index 0000000000..2b078ef091 --- /dev/null +++ b/lib/kernel/src/logger_std_h.erl @@ -0,0 +1,645 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017-2018. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% +-module(logger_std_h). + +-include("logger.hrl"). +-include("logger_internal.hrl"). +-include("logger_h_common.hrl"). + +-include_lib("kernel/include/file.hrl"). + +%% API +-export([filesync/1]). + +%% logger_h_common callbacks +-export([init/2, check_config/4, config_changed/3, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). + +-define(DEFAULT_CALL_TIMEOUT, 5000). + +%%%=================================================================== +%%% API +%%%=================================================================== + +%%%----------------------------------------------------------------- +%%% +-spec filesync(Name) -> ok | {error,Reason} when + Name :: atom(), + Reason :: handler_busy | {badarg,term()}. + +filesync(Name) -> + logger_h_common:filesync(?MODULE,Name). + +%%%=================================================================== +%%% logger callbacks - just forward to logger_h_common +%%%=================================================================== + +%%%----------------------------------------------------------------- +%%% Handler being added +-spec adding_handler(Config) -> {ok,Config} | {error,Reason} when + Config :: logger:handler_config(), + Reason :: term(). + +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +-spec changing_config(SetOrUpdate, OldConfig, NewConfig) -> + {ok,Config} | {error,Reason} when + SetOrUpdate :: set | update, + OldConfig :: logger:handler_config(), + NewConfig :: logger:handler_config(), + Config :: logger:handler_config(), + Reason :: term(). + +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). + +%%%----------------------------------------------------------------- +%%% Handler being removed +-spec removing_handler(Config) -> ok when + Config :: logger:handler_config(). + +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +-spec filter_config(Config) -> Config when + Config :: logger:handler_config(). + +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, Config) -> + 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} -> + {ok,MyConfig#{file_ctrl_pid=>FileCtrlPid}}; + Error -> + Error + end. + +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 + merge_default_config(Name,WriteOnce); + update -> + OldHConfig + end, + + NewHConfig = maps:merge(Default, normalize_config(NewHConfig0)), + + %% Fail if write-once fields are changed + case maps:with([type,file,modes],NewHConfig) of + WriteOnce -> + check_h_config(NewHConfig); + Other -> + {error,{illegal_config_change,?MODULE,WriteOnce,Other}} + end. + +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,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(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,[]) -> + ok. + +normalize_config(#{type:={file,File}}=HConfig) -> + normalize_config(HConfig#{type=>file,file=>File}); +normalize_config(#{type:={file,File,Modes}}=HConfig) -> + normalize_config(HConfig#{type=>file,file=>File,modes=>Modes}); +normalize_config(#{file:=File}=HConfig) -> + HConfig#{file=>filename:absname(File)}; +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 => filename:absname(atom_to_list(Name)), + modes => [raw,append], + file_check => 0, + 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}. + +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. + +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}=State) -> + State; +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_ctrl_pid := FileCtrlPid} = State) -> + 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, SyncAsync, #{file_ctrl_pid := FileCtrlPid} = State) -> + Result = file_ctrl_filesync(SyncAsync, FileCtrlPid), + {Result,State}. + +write(_Name, SyncAsync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + Result = file_write(SyncAsync, FileCtrlPid, Bin), + {Result,State}. + +reset_state(_Name, State) -> + State. + +handle_info(_Name, {'EXIT',Pid,Why}, #{file_ctrl_pid := Pid}=State) -> + %% file_ctrl_pid died, file error, terminate handler + exit({error,{write_failed,maps:with([type,file,modes],State),Why}}); +handle_info(_, _, State) -> + State. + +terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> + case is_process_alive(FWPid) of + true -> + unlink(FWPid), + _ = file_ctrl_stop(FWPid), + MRef = erlang:monitor(process, FWPid), + receive + {'DOWN',MRef,_,_,_} -> + ok + after + ?DEFAULT_CALL_TIMEOUT -> + exit(FWPid, kill), + ok + end; + false -> + ok + end. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== + +%%%----------------------------------------------------------------- +%%% +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}) -> + try + case filelib:ensure_dir(FileName) of + ok -> + case file:open(FileName, Modes) of + {ok, Fd} -> + {ok,#file_info{inode=INode}} = + 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}, + State = update_rotation({Size,Count,Compress},State0), + {ok,State}; + Error -> + Error + end; + Error -> + Error + end + catch + _:Reason -> {error,Reason} + end. + +close_log_file(#{fd:=Fd}) -> + _ = file:datasync(Fd), + _ = file:close(Fd), + ok; +close_log_file(_) -> + ok. + + + +%%%----------------------------------------------------------------- +%%% File control process + +file_ctrl_start(HandlerName, HConfig) -> + Starter = self(), + FileCtrlPid = + spawn_link(fun() -> + file_ctrl_init(HandlerName, HConfig, Starter) + end), + receive + {FileCtrlPid,ok} -> + {ok,FileCtrlPid}; + {FileCtrlPid,Error} -> + Error + after + ?DEFAULT_CALL_TIMEOUT -> + {error,file_ctrl_process_not_started} + end. + +file_ctrl_stop(Pid) -> + Pid ! stop. + +file_write(async, Pid, Bin) -> + Pid ! {log,Bin}, + ok; +file_write(sync, Pid, Bin) -> + file_ctrl_call(Pid, {log,Bin}). + +file_ctrl_filesync(async, Pid) -> + Pid ! filesync, + ok; +file_ctrl_filesync(sync, Pid) -> + file_ctrl_call(Pid, filesync). + +file_ctrl_call(Pid, Msg) -> + MRef = monitor(process, Pid), + Pid ! {Msg,{self(),MRef}}, + receive + {MRef,Result} -> + demonitor(MRef, [flush]), + Result; + {'DOWN',MRef,_Type,_Object,Reason} -> + {error,Reason} + after + ?DEFAULT_CALL_TIMEOUT -> + {error,{no_response,Pid}} + end. + +file_ctrl_init(HandlerName, + #{type:=file, + file:=FileName} = HConfig, + Starter) -> + process_flag(message_queue_data, off_heap), + case open_log_file(HandlerName,HConfig) of + {ok,State} -> + Starter ! {self(),ok}, + file_ctrl_loop(State); + {error,Reason} -> + Starter ! {self(),{error,{open_failed,FileName,Reason}}} + end; +file_ctrl_init(HandlerName, #{type:=StdDev}, Starter) -> + Starter ! {self(),ok}, + file_ctrl_loop(#{handler_name=>HandlerName,dev=>StdDev}). + +file_ctrl_loop(State) -> + receive + %% asynchronous event + {log,Bin} -> + State1 = write_to_dev(Bin,State), + file_ctrl_loop(State1); + + %% synchronous event + {{log,Bin},{From,MRef}} -> + State1 = ensure_file(State), + State2 = write_to_dev(Bin,State1), + From ! {MRef,ok}, + file_ctrl_loop(State2); + + filesync -> + State1 = sync_dev(State), + file_ctrl_loop(State1); + + {filesync,{From,MRef}} -> + State1 = ensure_file(State), + State2 = sync_dev(State1), + From ! {MRef,ok}, + file_ctrl_loop(State2); + + {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), + 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,[raw]) of + {ok,#file_info{inode=INode0}} -> + State#{last_check=>timestamp()}; + _ -> + close_log_file(Fd0), + case file:open(FileName,Modes) of + {ok,Fd} -> + {ok,#file_info{inode=INode}} = + 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; +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} = 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} = maybe_ensure_file(State), + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,State1), + State1#{synced=>true,sync_res=>Result}; +sync_dev(State) -> + 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,[raw]), + 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,[raw]), + file:read_file_info(CompressedArchive,[raw])} of + {{error,enoent},{error,enoent}} -> + ok; + _ -> + _ = 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,[raw]) 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,[raw]), + 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) -> + ok; +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 + ok; +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). |