aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel
diff options
context:
space:
mode:
Diffstat (limited to 'lib/kernel')
-rw-r--r--lib/kernel/src/logger_disk_log_h.erl707
-rw-r--r--lib/kernel/src/logger_h_common.erl653
-rw-r--r--lib/kernel/src/logger_h_common.hrl16
-rw-r--r--lib/kernel/src/logger_std_h.erl764
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl138
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl66
6 files changed, 947 insertions, 1397 deletions
diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl
index 2a81458ec8..41e0d51a9d 100644
--- a/lib/kernel/src/logger_disk_log_h.erl
+++ b/lib/kernel/src/logger_disk_log_h.erl
@@ -19,59 +19,33 @@
%%
-module(logger_disk_log_h).
--behaviour(gen_server).
-
-include("logger.hrl").
-include("logger_internal.hrl").
-include("logger_h_common.hrl").
%%% API
--export([start_link/3, info/1, filesync/1, reset/1]).
+-export([info/1, filesync/1, reset/1]).
-%% gen_server callbacks
--export([init/1, handle_call/3, handle_cast/2, handle_info/2,
- terminate/2, code_change/3]).
+%% logger_h_common callbacks
+-export([init/2, check_config/4, 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]).
-%% handler internal
--export([log_handler_info/4]).
-
%%%===================================================================
%%% API
%%%===================================================================
%%%-----------------------------------------------------------------
-%%% Start a disk_log handler process and link to caller.
-%%% This function is called by the kernel supervisor when this
-%%% handler process gets added (as a result of calling add/3).
--spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when
- Name :: atom(),
- Config :: logger:handler_config(),
- HandlerState :: map(),
- Pid :: pid(),
- Reason :: term().
-
-start_link(Name, Config, HandlerState) ->
- proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]).
-
-%%%-----------------------------------------------------------------
%%%
-spec filesync(Name) -> ok | {error,Reason} when
Name :: atom(),
Reason :: handler_busy | {badarg,term()}.
-filesync(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- disk_log_sync, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
filesync(Name) ->
- {error,{badarg,{filesync,[Name]}}}.
+ logger_h_common:filesync(?MODULE,Name).
%%%-----------------------------------------------------------------
%%%
@@ -80,15 +54,8 @@ filesync(Name) ->
Info :: term(),
Reason :: handler_busy | {badarg,term()}.
-info(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- info, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
info(Name) ->
- {error,{badarg,{info,[Name]}}}.
+ logger_h_common:info(?MODULE,Name).
%%%-----------------------------------------------------------------
%%%
@@ -96,16 +63,8 @@ info(Name) ->
Name :: atom(),
Reason :: handler_busy | {badarg,term()}.
-reset(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- reset, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
reset(Name) ->
- {error,{badarg,{reset,[Name]}}}.
-
+ logger_h_common:reset(?MODULE,Name).
%%%===================================================================
%%% logger callbacks
@@ -113,30 +72,55 @@ reset(Name) ->
%%%-----------------------------------------------------------------
%%% Handler being added
-adding_handler(#{id:=Name}=Config) ->
- case check_config(adding, Config) of
- {ok, #{config:=HConfig}=Config1} ->
- %% create initial handler state by merging defaults with config
- HState = maps:merge(get_init_state(), HConfig),
- case logger_h_common:overload_levels_ok(HState) of
- true ->
- start(Name, Config1, HState);
- false ->
- #{sync_mode_qlen := SMQL,
- drop_mode_qlen := DMQL,
- flush_qlen := FQL} = HState,
- {error,{invalid_levels,{SMQL,DMQL,FQL}}}
- end;
+adding_handler(Config) ->
+ logger_h_common:adding_handler(Config).
+
+%%%-----------------------------------------------------------------
+%%% Updating handler config
+changing_config(SetOrUpdate, OldConfig, NewConfig) ->
+ logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig).
+
+%%%-----------------------------------------------------------------
+%%% Handler being removed
+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
+filter_config(Config) ->
+ logger_h_common:filter_config(Config).
+
+%%%===================================================================
+%%% logger_h_common callbacks
+%%%===================================================================
+init(Name, #{file:=File,type:=Type,max_no_bytes:=MNB,max_no_files:=MNF}) ->
+ case open_disk_log(Name, File, Type, MNB, MNF) of
+ ok ->
+ {ok,#{log_opts => #{file => File,
+ type => Type,
+ max_no_bytes => MNB,
+ max_no_files => MNF},
+ prev_log_result => ok,
+ prev_sync_result => ok,
+ prev_disk_log_info => undefined}};
Error ->
Error
end.
-%%%-----------------------------------------------------------------
-%%% Updating handler config
-changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) ->
+check_config(Name,set,undefined,HConfig0) ->
+ HConfig=merge_default_logopts(Name,maps:merge(get_default_config(),HConfig0)),
+ check_config(HConfig);
+check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) ->
WriteOnce = maps:with([type,file,max_no_files,max_no_bytes],OldHConfig),
- ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig),
- NewHConfig0 = maps:get(config, NewConfig, #{}),
Default =
case SetOrUpdate of
set ->
@@ -146,66 +130,25 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) ->
OldHConfig
end,
- %% Allow (accidentially) included read-only fields - just overwrite them
- NewHConfig = maps:merge(maps:merge(Default,NewHConfig0),ReadOnly),
+ NewHConfig = maps:merge(Default,NewHConfig0),
- %% But fail if write-once fields are changed
+ %% Fail if write-once fields are changed
case maps:with([type,file,max_no_files,max_no_bytes],NewHConfig) of
WriteOnce ->
- changing_config1(maps:get(handler_pid,OldHConfig),
- OldConfig,
- NewConfig#{config=>NewHConfig});
+ check_config(NewHConfig);
Other ->
{Old,New} = logger_server:diff_maps(WriteOnce,Other),
- {error,{illegal_config_change,#{config=>Old},#{config=>New}}}
+ {error,{illegal_config_change,?MODULE,Old,New}}
end.
-changing_config1(HPid, OldConfig, NewConfig) ->
- case check_config(changing, NewConfig) of
- Result = {ok,NewConfig1} ->
- try gen_server:call(HPid, {change_config,OldConfig,NewConfig1},
- ?DEFAULT_CALL_TIMEOUT) of
- ok -> Result;
- Error -> Error
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
- Error ->
- Error
- end.
-
-check_config(adding, #{id:=Name}=Config) ->
- %% merge handler specific config data
- HConfig1 = maps:get(config, Config, #{}),
- HConfig2 = maps:merge(get_default_config(), HConfig1),
- HConfig3 = merge_default_logopts(Name, HConfig2),
- case check_h_config(maps:to_list(HConfig3)) of
- ok ->
- {ok,Config#{config=>HConfig3}};
- Error ->
- Error
- end;
-check_config(changing, Config) ->
- HConfig = maps:get(config, Config, #{}),
+check_config(HConfig) ->
case check_h_config(maps:to_list(HConfig)) of
- ok -> {ok,Config};
- Error -> Error
+ ok ->
+ {ok,HConfig};
+ {error,{Key,Value}} ->
+ {error,{invalid_config,?MODULE,#{Key=>Value}}}
end.
-merge_default_logopts(Name, HConfig) ->
- Type = maps:get(type, HConfig, wrap),
- {DefaultNoFiles,DefaultNoBytes} =
- case Type of
- halt -> {undefined,infinity};
- _wrap -> {10,1048576}
- end,
- {ok,Dir} = file:get_cwd(),
- Defaults = #{file => filename:join(Dir,Name),
- max_no_files => DefaultNoFiles,
- max_no_bytes => DefaultNoBytes,
- type => Type},
- maps:merge(Defaults, HConfig).
-
check_h_config([{file,File}|Config]) when is_list(File) ->
check_h_config(Config);
check_h_config([{max_no_files,undefined}|Config]) ->
@@ -218,454 +161,59 @@ check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 ->
check_h_config(Config);
check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt ->
check_h_config(Config);
-check_h_config([Other | Config]) ->
- case logger_h_common:check_common_config(Other) of
- valid ->
- check_h_config(Config);
- invalid ->
- {error,{invalid_config,?MODULE,Other}}
- end;
+check_h_config([Other | _]) ->
+ {error,Other};
check_h_config([]) ->
ok.
-%%%-----------------------------------------------------------------
-%%% Handler being removed
-removing_handler(#{id:=Name}) ->
- stop(Name).
-
-%%%-----------------------------------------------------------------
-%%% Log a string or report
--spec log(LogEvent, Config) -> ok when
- LogEvent :: logger:log_event(),
- Config :: logger:handler_config().
-
-log(LogEvent, Config = #{id := Name,
- config := #{handler_pid := HPid,
- mode_tab := ModeTab}}) ->
- %% if the handler has crashed, we must drop this event
- %% and hope the handler restarts so we can try again
- true = is_process_alive(HPid),
- Bin = logger_h_common:log_to_binary(LogEvent, Config),
- logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin).
+get_default_config() ->
+ #{}.
-%%%-----------------------------------------------------------------
-%%% Remove internal fields from configuration
-filter_config(#{config:=HConfig}=Config) ->
- Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}.
+merge_default_logopts(Name, HConfig) ->
+ Type = maps:get(type, HConfig, wrap),
+ {DefaultNoFiles,DefaultNoBytes} =
+ case Type of
+ halt -> {undefined,infinity};
+ _wrap -> {10,1048576}
+ end,
+ {ok,Dir} = file:get_cwd(),
+ Defaults = #{file => filename:join(Dir,Name),
+ max_no_files => DefaultNoFiles,
+ max_no_bytes => DefaultNoBytes,
+ type => Type},
+ maps:merge(Defaults, HConfig).
-%%%===================================================================
-%%% gen_server callbacks
-%%%===================================================================
+filesync(Name,_Mode,State) ->
+ Result = ?disk_log_sync(Name),
+ maybe_notify_error(Name, filesync, Result, prev_sync_result, State).
-init([Name,
- Config = #{config := HConfig = #{file:=File,
- type:=Type,
- max_no_bytes:=MNB,
- max_no_files:=MNF}},
- State = #{dl_sync_int := DLSyncInt}]) ->
-
- RegName = ?name_to_reg_name(?MODULE,Name),
- register(RegName, self()),
- process_flag(trap_exit, true),
- process_flag(message_queue_data, off_heap),
-
- ?init_test_hooks(),
- ?start_observation(Name),
-
- LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF},
- case open_disk_log(Name, File, Type, MNB, MNF) of
- ok ->
- try ets:new(Name, [public]) of
- ModeTab ->
- ?set_mode(ModeTab, async),
- T0 = ?timestamp(),
- State1 =
- ?merge_with_stats(State#{
- id => Name,
- mode_tab => ModeTab,
- mode => async,
- dl_sync => DLSyncInt,
- log_opts => LogOpts,
- last_qlen => 0,
- last_log_ts => T0,
- burst_win_ts => T0,
- burst_msg_count => 0,
- last_op => sync,
- prev_log_result => ok,
- prev_sync_result => ok,
- prev_disk_log_info => undefined}),
- Config1 =
- Config#{config => HConfig#{handler_pid => self(),
- mode_tab => ModeTab}},
- proc_lib:init_ack({ok,self(),Config1}),
- gen_server:cast(self(), repeated_disk_log_sync),
- case logger_h_common:unset_restart_flag(Name, ?MODULE) of
- true ->
- %% inform about restart
- gen_server:cast(self(), {log_handler_info,
- "Handler ~p restarted",
- [Name]});
- false ->
- %% initial start
- ok
- end,
- gen_server:enter_loop(?MODULE, [], State1)
- catch
- _:Error ->
- unregister(RegName),
- logger_h_common:error_notify({open_disk_log,Name,Error}),
- proc_lib:init_ack(Error)
- end;
- Error ->
- unregister(RegName),
- logger_h_common:error_notify({open_disk_log,Name,Error}),
- proc_lib:init_ack(Error)
- end.
+write(Name, Mode, Bin, State) ->
+ Result = ?disk_log_write(Name, Mode, Bin),
+ maybe_notify_error(Name, log, Result, prev_log_result, State).
-%% This is the synchronous log event.
-handle_call({log, Bin}, _From, State) ->
- {Result,State1} = do_log(Bin, call, State),
- %% Result == ok | dropped
- {reply, Result, State1};
-
-handle_call(disk_log_sync, _From, State = #{id := Name}) ->
- State1 = #{prev_sync_result := Result} = disk_log_sync(Name, State),
- {reply, Result, State1};
-
-handle_call({change_config,_OldConfig,NewConfig}, _From,
- State = #{filesync_repeat_interval := FSyncInt0}) ->
- HConfig = maps:get(config, NewConfig, #{}),
- State1 = #{sync_mode_qlen := SMQL,
- drop_mode_qlen := DMQL,
- flush_qlen := FQL} = maps:merge(State, HConfig),
- case logger_h_common:overload_levels_ok(State1) of
- true ->
- _ =
- case maps:get(filesync_repeat_interval, HConfig, undefined) of
- undefined ->
- ok;
- no_repeat ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
- State,
- undefined));
- FSyncInt0 ->
- ok;
- _FSyncInt1 ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
- State,
- undefined)),
- _ = gen_server:cast(self(), repeated_disk_log_sync)
- end,
- {reply, ok, State1};
- false ->
- {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State}
- end;
-
-handle_call(info, _From, State) ->
- {reply, State, State};
-
-handle_call(reset, _From, State) ->
- State1 = ?merge_with_stats(State),
- {reply, ok, State1#{last_qlen => 0,
- last_log_ts => ?timestamp(),
- prev_log_result => ok,
- prev_sync_result => ok,
- prev_disk_log_info => undefined}};
-
-handle_call(stop, _From, State) ->
- {stop, {shutdown,stopped}, ok, State}.
-
-
-%% This is the asynchronous log event.
-handle_cast({log, Bin}, State) ->
- {_,State1} = do_log(Bin, cast, State),
- {noreply, State1};
-
-handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) ->
- log_handler_info(Name, Format, Args, State),
- {noreply, State};
-
-%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this
-%% clause gets called repeatedly by the handler. In order to
-%% guarantee that a filesync *always* happens after the last log
-%% event, the repeat operation must be active!
-handle_cast(repeated_disk_log_sync,
- State = #{id := Name,
- filesync_repeat_interval := FSyncInt,
- last_op := LastOp}) ->
- State1 =
- if is_integer(FSyncInt) ->
- %% only do filesync if something has been
- %% written since last time we checked
- NewState = if LastOp == sync ->
- State;
- true ->
- disk_log_sync(Name, State)
- end,
- {ok,TRef} =
- timer:apply_after(FSyncInt, gen_server,cast,
- [self(),repeated_disk_log_sync]),
- NewState#{rep_sync_tref => TRef, last_op => sync};
- true ->
- State
- end,
- {noreply,State1}.
+reset_state(_Name, State) ->
+ State#{prev_log_result => ok,
+ prev_sync_result => ok,
+ prev_disk_log_info => undefined}.
%% The disk log owner must handle status messages from disk_log.
-handle_info({disk_log, _Node, _Log, {wrap,_NoLostItems}}, State) ->
- {noreply, State};
-handle_info({disk_log, _Node, Log, Info = {truncated,_NoLostItems}},
- State = #{id := Name, prev_disk_log_info := PrevInfo}) ->
- error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}),
- {noreply, State#{prev_disk_log_info => Info}};
-handle_info({disk_log, _Node, Log, Info = {blocked_log,_Items}},
- State = #{id := Name, prev_disk_log_info := PrevInfo}) ->
- error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}),
- {noreply, State#{prev_disk_log_info => Info}};
-handle_info({disk_log, _Node, Log, full},
- State = #{id := Name, prev_disk_log_info := PrevInfo}) ->
- error_notify_new(full, PrevInfo, {disk_log,Name,Log,full}),
- {noreply, State#{prev_disk_log_info => full}};
-handle_info({disk_log, _Node, Log, Info = {error_status,_Status}},
- State = #{id := Name, prev_disk_log_info := PrevInfo}) ->
- error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}),
- {noreply, State#{prev_disk_log_info => Info}};
-
-handle_info({'EXIT',_Pid,_Why}, State = #{id := _Name}) ->
- {noreply, State};
-
-handle_info(_, State) ->
- {noreply, State}.
-
-terminate(Reason, State = #{id := Name}) ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State,
- undefined)),
+handle_info(Name, {disk_log, _Node, Log, Info={truncated,_NoLostItems}}, State) ->
+ maybe_notify_status(Name, Log, Info, prev_disk_log_info, State);
+handle_info(Name, {disk_log, _Node, Log, Info = {blocked_log,_Items}}, State) ->
+ maybe_notify_status(Name, Log, Info, prev_disk_log_info, State);
+handle_info(Name, {disk_log, _Node, Log, Info = full}, State) ->
+ maybe_notify_status(Name, Log, Info, prev_disk_log_info, State);
+handle_info(Name, {disk_log, _Node, Log, Info = {error_status,_Status}}, State) ->
+ maybe_notify_status(Name, Log, Info, prev_disk_log_info, State);
+handle_info(_, _, State) ->
+ State.
+
+terminate(Name, _Reason, _State) ->
_ = close_disk_log(Name, normal),
- ok = logger_h_common:stop_or_restart(Name, Reason, State),
- unregister(?name_to_reg_name(?MODULE, Name)),
ok.
-code_change(_OldVsn, State, _Extra) ->
- {ok, State}.
-
%%%-----------------------------------------------------------------
%%% Internal functions
-
-%%%-----------------------------------------------------------------
-%%%
-get_default_config() ->
- #{sync_mode_qlen => ?SYNC_MODE_QLEN,
- drop_mode_qlen => ?DROP_MODE_QLEN,
- flush_qlen => ?FLUSH_QLEN,
- burst_limit_enable => ?BURST_LIMIT_ENABLE,
- burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT,
- burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME,
- overload_kill_enable => ?OVERLOAD_KILL_ENABLE,
- overload_kill_qlen => ?OVERLOAD_KILL_QLEN,
- overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE,
- overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER,
- filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.
-
-get_init_state() ->
- #{dl_sync_int => ?CONTROLLER_SYNC_INTERVAL,
- filesync_ok_qlen => ?FILESYNC_OK_QLEN}.
-
-%%%-----------------------------------------------------------------
-%%% Add a disk_log handler to the logger.
-%%% This starts a dedicated handler process which should always
-%%% exist if the handler is registered with logger (and should not
-%%% exist if the handler is not registered).
-%%%
-%%% Config is the logger:handler_config() map. Handler specific parameters
-%%% should be provided with a sub map associated with a key named
-%%% 'config', e.g:
-%%%
-%%% Config = #{config => #{sync_mode_qlen => 50}
-%%%
-%%% The 'config' sub map will also contain parameters for configuring
-%%% the disk_log:
-%%%
-%%% Config = #{config => #{file => file:filename(),
-%%% max_no_bytes => integer(),
-%%% max_no_files => integer(),
-%%% type => wrap | halt}}.
-%%%
-%%% If type == halt, then max_no_files is ignored.
-%%%
-%%% The disk_log handler process is linked to logger_sup, which is
-%%% part of the kernel application's supervision tree.
-start(Name, Config, HandlerState) ->
- LoggerDLH =
- #{id => Name,
- start => {?MODULE, start_link, [Name,Config,HandlerState]},
- restart => temporary,
- shutdown => 2000,
- type => worker,
- modules => [?MODULE]},
- case supervisor:start_child(logger_sup, LoggerDLH) of
- {ok,Pid,Config1} ->
- ok = logger_handler_watcher:register_handler(Name,Pid),
- {ok,Config1};
- Error ->
- Error
- end.
-
-%%%-----------------------------------------------------------------
-%%% Stop and remove the handler.
-stop(Name) ->
- case whereis(?name_to_reg_name(?MODULE,Name)) of
- undefined ->
- ok;
- Pid ->
- %% We don't want to do supervisor:terminate_child here
- %% since we need to distinguish this explicit stop from a
- %% system termination in order to avoid circular attempts
- %% at removing the handler (implying deadlocks and
- %% timeouts).
- %% And we don't need to do supervisor:delete_child, since
- %% the restart type is temporary, which means that the
- %% child specification is automatically removed from the
- %% supervisor when the process dies.
- _ = gen_server:call(Pid, stop),
- ok
- end.
-
-%%%-----------------------------------------------------------------
-%%% Logging and overload control.
--define(update_dl_sync(C, Interval),
- if C == 0 -> Interval;
- true -> C-1 end).
-
-%% check for overload between every event (and set Mode to async,
-%% sync or drop accordingly), but never flush the whole mailbox
-%% before LogWindowSize events have been handled
-do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) ->
- T1 = ?timestamp(),
-
- %% check if the handler is getting overloaded, or if it's
- %% recovering from overload (the check must be done for each
- %% event to react quickly to large bursts of events and
- %% to ensure that the handler can never end up in drop mode
- %% with an empty mailbox, which would stop operation)
- {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State),
-
- if (Mode1 == drop) andalso (Mode0 =/= drop) ->
- log_handler_info(Name, "Handler ~p switched to drop mode",
- [Name], State);
- (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) ->
- log_handler_info(Name, "Handler ~p switched to ~w mode",
- [Name,Mode1], State);
- true ->
- ok
- end,
-
- %% kill the handler if it can't keep up with the load
- logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State),
-
- if Mode1 == flush ->
- flush(Name, QLen, T1, State1);
- true ->
- write(Name, Mode1, T1, Bin, CallOrCast, State1)
- end.
-
-%% this function is called by do_log/3 after an overload check
-%% has been performed, where QLen > FlushQLen
-flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) ->
- %% flush messages in the mailbox (a limited number in
- %% order to not cause long delays)
- NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N),
-
- %% write info in log about flushed messages
- log_handler_info(Name, "Handler ~p flushed ~w log events",
- [Name,NewFlushed], State),
-
- %% because of the receive loop when flushing messages, the
- %% handler will be scheduled out often and the mailbox could
- %% grow very large, so we'd better check the queue again here
- {_,_QLen1} = process_info(self(), message_queue_len),
- ?observe(Name,{max_qlen,_QLen1}),
-
- %% Add 1 for the current log event
- ?observe(Name,{flushed,NewFlushed+1}),
-
- State1 = ?update_max_time(?diff_time(T1,_T0),State),
- {dropped,?update_other(flushed,FLUSHED,NewFlushed,
- State1#{mode => ?set_mode(ModeTab,async),
- last_qlen => 0,
- last_log_ts => T1})}.
-
-%% this function is called to write to disk_log
-write(Name, Mode, T1, Bin, _CallOrCast,
- State = #{mode_tab := ModeTab,
- dl_sync := DLSync,
- dl_sync_int := DLSyncInt,
- last_qlen := LastQLen,
- last_log_ts := T0}) ->
- %% check if we need to limit the number of writes
- %% during a burst of log events
- {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State),
-
- %% only send a synhrounous event to the disk_log process
- %% every DLSyncInt time, to give the handler time between
- %% writes so it can keep up with incoming messages
- {Status,LastQLen1,State1} =
- if DoWrite, DLSync == 0 ->
- ?observe(Name,{_CallOrCast,1}),
- NewState = disk_log_write(Name, Bin, State),
- {ok, element(2,process_info(self(),message_queue_len)),
- NewState};
- DoWrite ->
- ?observe(Name,{_CallOrCast,1}),
- NewState = disk_log_write(Name, Bin, State),
- {ok, LastQLen, NewState};
- not DoWrite ->
- ?observe(Name,{flushed,1}),
- {dropped, LastQLen, State}
- end,
-
- %% Check if the time since the previous log event is long enough -
- %% and the queue length small enough - to assume the mailbox has
- %% been emptied, and if so, do filesync operation and reset mode to
- %% async. Note that this is the best we can do to detect an idle
- %% handler without setting a timer after each log call/cast. If the
- %% time between two consecutive log events is fast and no new
- %% event comes in after the last one, idle state won't be detected!
- Time = ?diff_time(T1,T0),
- {Mode1,BurstMsgCount1,State2} =
- if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso
- (Time > ?IDLE_DETECT_TIME_USEC) ->
- {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)};
- true ->
- {Mode, BurstMsgCount,State1}
- end,
-
- State3 =
- ?update_calls_or_casts(_CallOrCast,1,State2),
- State4 =
- ?update_max_time(Time,
- State3#{mode => Mode1,
- last_qlen := LastQLen1,
- last_log_ts => T1,
- burst_win_ts => BurstWinT,
- burst_msg_count => BurstMsgCount1,
- dl_sync => ?update_dl_sync(DLSync,DLSyncInt)}),
- {Status,State4}.
-
-
-log_handler_info(Name, Format, Args, State) ->
- Config =
- case logger:get_handler_config(Name) of
- {ok,Conf} -> Conf;
- _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}
- end,
- Meta = #{time=>erlang:system_time(microsecond)},
- Bin = logger_h_common:log_to_binary(#{level => notice,
- msg => {Format,Args},
- meta => Meta}, Config),
- _ = disk_log_write(Name, Bin, State),
- ok.
-
-
open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) ->
case filelib:ensure_dir(File) of
ok ->
@@ -698,43 +246,26 @@ close_disk_log(Name, _) ->
_ = disk_log:lclose(Name),
ok.
-disk_log_write(Name, Bin, State) ->
- case ?disk_log_blog(Name, Bin) of
- ok ->
- State#{prev_log_result => ok, last_op => write};
- LogError ->
- _ = case maps:get(prev_log_result, State) of
- LogError ->
- %% don't report same error twice
- ok;
- _ ->
- LogOpts = maps:get(log_opts, State),
- logger_h_common:error_notify({Name,log,
- LogOpts,
- LogError})
- end,
- State#{prev_log_result => LogError}
- end.
-
-disk_log_sync(Name, State) ->
- case ?disk_log_sync(Name) of
- ok ->
- State#{prev_sync_result => ok, last_op => sync};
- SyncError ->
- _ = case maps:get(prev_sync_result, State) of
- SyncError ->
- %% don't report same error twice
- ok;
- _ ->
- LogOpts = maps:get(log_opts, State),
- logger_h_common:error_notify({Name,filesync,
- LogOpts,
- SyncError})
- end,
- State#{prev_sync_result => SyncError}
- end.
+disk_log_write(Name, sync, Bin) ->
+ disk_log:blog(Name, Bin);
+disk_log_write(Name, async, Bin) ->
+ disk_log:balog(Name, Bin).
+
+%%%-----------------------------------------------------------------
+%%% Print error messages, but don't repeat the same message
+maybe_notify_error(Name, Op, Result, Key, #{log_opts:=LogOpts}=State) ->
+ {Result,error_notify_new({Name, Op, LogOpts, Result}, Result, Key, State)}.
-error_notify_new(Info,Info, _Term) ->
+maybe_notify_status(Name, Log, Info, Key, State) ->
+ error_notify_new({disk_log, Name, Log, Info}, Info, Key, State).
+
+error_notify_new(Term, What, Key, State) ->
+ error_notify_new(What, maps:get(Key,State), Term),
+ State#{Key => What}.
+
+error_notify_new(ok,_Prev,_Term) ->
+ ok;
+error_notify_new(Same,Same,_Term) ->
ok;
-error_notify_new(_Info0,_Info1, Term) ->
+error_notify_new(_New,_Prev,Term) ->
logger_h_common:error_notify(Term).
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 94c640cb92..74a2d158fc 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -18,26 +18,469 @@
%% %CopyrightEnd%
%%
-module(logger_h_common).
+-behaviour(gen_server).
-include("logger_h_common.hrl").
-include("logger_internal.hrl").
--export([log_to_binary/2,
- check_common_config/1,
- call_cast_or_drop/4,
- check_load/1,
- limit_burst/1,
- kill_if_choked/5,
- flush_log_events/0,
- flush_log_events/1,
- handler_exit/2,
- set_restart_flag/2,
- unset_restart_flag/2,
- cancel_timer/1,
- stop_or_restart/3,
- overload_levels_ok/1,
- error_notify/1,
- info_notify/1]).
+%% API
+-export([start_link/1, info/2, filesync/2, reset/2]).
+
+%% gen_server and proc_lib callbacks
+-export([init/1, handle_call/3, handle_cast/2, handle_info/2,
+ terminate/2, code_change/3]).
+
+%% logger callbacks
+-export([log/2, adding_handler/1, removing_handler/1, changing_config/3,
+ filter_config/1]).
+
+%% Library functions for handlers
+-export([error_notify/1]).
+
+%%%-----------------------------------------------------------------
+-define(CONFIG_KEYS,[sync_mode_qlen,
+ drop_mode_qlen,
+ flush_qlen,
+ burst_limit_enable,
+ burst_limit_max_count,
+ burst_limit_window_time,
+ overload_kill_enable,
+ overload_kill_qlen,
+ overload_kill_mem_size,
+ overload_kill_restart_after,
+ filesync_repeat_interval]).
+-define(READ_ONLY_KEYS,[handler_pid,mode_tab]).
+
+%%%-----------------------------------------------------------------
+%%% API
+
+%% This function is called by the logger_sup supervisor
+start_link(Args) ->
+ proc_lib:start_link(?MODULE,init,[Args]).
+
+filesync(Module, Name) ->
+ call(Module, Name, filesync).
+
+info(Module, Name) ->
+ call(Module, Name, info).
+
+reset(Module, Name) ->
+ call(Module, Name, reset).
+
+%%%-----------------------------------------------------------------
+%%% Handler being added
+adding_handler(#{id:=Name,module:=Module}=Config) ->
+ HConfig0 = maps:get(config, Config, #{}),
+ HandlerConfig0 = maps:without(?CONFIG_KEYS,HConfig0),
+ case Module:check_config(Name,set,undefined,HandlerConfig0) of
+ {ok,HandlerConfig} ->
+ ModifiedCommon = maps:with(?CONFIG_KEYS,HandlerConfig),
+ CommonConfig0 = maps:with(?CONFIG_KEYS,HConfig0),
+ CommonConfig = maps:merge(
+ maps:merge(get_default_config(), CommonConfig0),
+ ModifiedCommon),
+ case check_config(CommonConfig) of
+ ok ->
+ HConfig = maps:merge(CommonConfig,HandlerConfig),
+ start(Config#{config => HConfig});
+ {error,Faulty} ->
+ {error,{invalid_config,Module,Faulty}}
+ end;
+ Error ->
+ Error
+ end.
+
+%%%-----------------------------------------------------------------
+%%% Handler being removed
+removing_handler(#{id:=Name, module:=Module}) ->
+ case whereis(?name_to_reg_name(Module,Name)) of
+ undefined ->
+ ok;
+ Pid ->
+ %% We don't want to do supervisor:terminate_child here
+ %% since we need to distinguish this explicit stop from a
+ %% system termination in order to avoid circular attempts
+ %% at removing the handler (implying deadlocks and
+ %% timeouts).
+ %% And we don't need to do supervisor:delete_child, since
+ %% the restart type is temporary, which means that the
+ %% child specification is automatically removed from the
+ %% supervisor when the process dies.
+ _ = gen_server:call(Pid, stop),
+ ok
+ end.
+
+%%%-----------------------------------------------------------------
+%%% Updating handler config
+changing_config(SetOrUpdate,
+ #{id:=Name,config:=OldHConfig,module:=Module},
+ NewConfig0) ->
+ NewHConfig0 = maps:get(config, NewConfig0, #{}),
+ OldHandlerConfig = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,OldHConfig),
+ NewHandlerConfig0 = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,NewHConfig0),
+ case Module:check_config(Name, SetOrUpdate,
+ OldHandlerConfig,NewHandlerConfig0) of
+ {ok, NewHandlerConfig} ->
+ ModifiedCommon = maps:with(?CONFIG_KEYS,NewHandlerConfig),
+ NewCommonConfig0 = maps:with(?CONFIG_KEYS,NewHConfig0),
+ CommonDefault =
+ case SetOrUpdate of
+ set ->
+ get_default_config();
+ update ->
+ maps:with(?CONFIG_KEYS,OldHConfig)
+ end,
+ NewCommonConfig = maps:merge(
+ maps:merge(CommonDefault,NewCommonConfig0),
+ ModifiedCommon),
+ case check_config(NewCommonConfig) of
+ ok ->
+ ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig),
+ NewHConfig = maps:merge(
+ maps:merge(NewCommonConfig,NewHandlerConfig),
+ ReadOnly),
+ NewConfig = NewConfig0#{config=>NewHConfig},
+ HPid = maps:get(handler_pid,OldHConfig),
+ case call(HPid, {change_config,NewConfig}) of
+ ok -> {ok,NewConfig};
+ Error -> Error
+ end;
+ {error,Faulty} ->
+ {error,{invalid_config,Module,Faulty}}
+ end;
+ Error ->
+ Error
+ end.
+
+%%%-----------------------------------------------------------------
+%%% Log a string or report
+-spec log(LogEvent, Config) -> ok when
+ LogEvent :: logger:log_event(),
+ Config :: logger:handler_config().
+
+log(LogEvent, Config = #{id := Name,
+ config := #{handler_pid := HPid,
+ mode_tab := ModeTab}}) ->
+ %% if the handler has crashed, we must drop this event
+ %% and hope the handler restarts so we can try again
+ true = is_process_alive(HPid),
+ Bin = log_to_binary(LogEvent, Config),
+ call_cast_or_drop(Name, HPid, ModeTab, Bin).
+
+%%%-----------------------------------------------------------------
+%%% Remove internal fields from configuration
+filter_config(#{config:=HConfig}=Config) ->
+ Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}.
+
+%%%-----------------------------------------------------------------
+%%% Start the handler process
+%%%
+%%% The process must always exist if the handler is registered with
+%%% logger (and must not exist if the handler is not registered).
+%%%
+%%% The handler process is linked to logger_sup, which is part of the
+%%% kernel application's supervision tree.
+start(#{id := Name} = Config0) ->
+ ChildSpec =
+ #{id => Name,
+ start => {?MODULE, start_link, [Config0]},
+ restart => temporary,
+ shutdown => 2000,
+ type => worker,
+ modules => [?MODULE]},
+ case supervisor:start_child(logger_sup, ChildSpec) of
+ {ok,Pid,Config} ->
+ ok = logger_handler_watcher:register_handler(Name,Pid),
+ {ok,Config};
+ Error ->
+ Error
+ end.
+
+%%%===================================================================
+%%% gen_server callbacks
+%%%===================================================================
+
+init(#{id := Name, module := Module,
+ formatter := Formatter, config := HConfig0} = Config0) ->
+ RegName = ?name_to_reg_name(Module,Name),
+ register(RegName, self()),
+ process_flag(trap_exit, true),
+ process_flag(message_queue_data, off_heap),
+
+ ?init_test_hooks(),
+ ?start_observation(Name),
+
+ case Module:init(Name, HConfig0) of
+ {ok,HState} ->
+ try ets:new(Name, [public]) of
+ ModeTab ->
+ ?set_mode(ModeTab, async),
+ T0 = ?timestamp(),
+ HConfig = HConfig0#{handler_pid => self(),
+ mode_tab => ModeTab},
+ Config = Config0#{config => HConfig},
+ proc_lib:init_ack({ok,self(),Config}),
+ %% Storing common config in state to avoid copying
+ %% (sending) the config data for each log message
+ CommonConfig = maps:with(?CONFIG_KEYS,HConfig),
+ State =
+ ?merge_with_stats(
+ CommonConfig#{id => Name,
+ module => Module,
+ mode_tab => ModeTab,
+ mode => async,
+ ctrl_sync_count =>
+ ?CONTROLLER_SYNC_INTERVAL,
+ last_qlen => 0,
+ last_log_ts => T0,
+ last_op => sync,
+ burst_win_ts => T0,
+ burst_msg_count => 0,
+ formatter => Formatter,
+ handler_state => HState}),
+ State1 = set_repeated_filesync(State),
+ unset_restart_flag(State1),
+ gen_server:enter_loop(?MODULE, [], State1)
+ catch
+ _:Error ->
+ unregister(RegName),
+ error_notify({init_handler,Name,Error}),
+ proc_lib:init_ack(Error)
+ end;
+ Error ->
+ unregister(RegName),
+ error_notify({init_handler,Name,Error}),
+ proc_lib:init_ack(Error)
+ end.
+
+%% This is the synchronous log event.
+handle_call({log, Bin}, _From, State) ->
+ {Result,State1} = do_log(Bin, call, State),
+ %% Result == ok | dropped
+ {reply,Result, State1};
+
+handle_call(filesync, _From, State = #{id := Name,
+ module := Module,
+ handler_state := HandlerState}) ->
+ {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState),
+ {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}};
+
+handle_call({change_config, #{formatter:=Formatter, config:=NewHConfig}}, _From,
+ State = #{filesync_repeat_interval := FSyncInt0}) ->
+ %% In the future, if handler_state must be updated due to config
+ %% change, then we need to add a callback to Module here.
+ CommonConfig = maps:with(?CONFIG_KEYS,NewHConfig),
+ State1 = maps:merge(State, CommonConfig),
+ State2 =
+ case maps:get(filesync_repeat_interval, NewHConfig) of
+ FSyncInt0 ->
+ State1;
+ _FSyncInt1 ->
+ set_repeated_filesync(cancel_repeated_filesync(State1))
+ end,
+ {reply, ok, State2#{formatter:=Formatter}};
+
+handle_call(info, _From, State) ->
+ {reply, State, State};
+
+handle_call(reset, _From,
+ #{id:=Name,module:=Module,handler_state:=HandlerState}=State) ->
+ State1 = ?merge_with_stats(State),
+ {reply, ok, State1#{last_qlen => 0,
+ last_log_ts => ?timestamp(),
+ handler_state => Module:reset_state(Name,HandlerState)}};
+
+handle_call(stop, _From, State) ->
+ {stop, {shutdown,stopped}, ok, State}.
+
+%% This is the asynchronous log event.
+handle_cast({log, Bin}, State) ->
+ {_,State1} = do_log(Bin, cast, State),
+ {noreply, State1};
+
+%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this
+%% clause gets called repeatedly by the handler. In order to
+%% guarantee that a filesync *always* happens after the last log
+%% event, the repeat operation must be active!
+handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) ->
+ %% This clause handles a race condition which may occur when
+ %% config changes filesync_repeat_interval from an integer value
+ %% to no_repeat.
+ {noreply,State};
+handle_cast(repeated_filesync,
+ State = #{id := Name,
+ module := Module,
+ handler_state := HandlerState,
+ last_op := LastOp}) ->
+ State1 =
+ if LastOp == sync ->
+ State;
+ true ->
+ {_,HS} = Module:filesync(Name, async, HandlerState),
+ State#{handler_state => HS, last_op => sync}
+ end,
+ {noreply,set_repeated_filesync(State1)}.
+
+handle_info(Info, #{id := Name, module := Module,
+ handler_state := HandlerState} = State) ->
+ {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}.
+
+terminate(Reason, State = #{id := Name,
+ module := Module,
+ handler_state := HandlerState}) ->
+ _ = cancel_repeated_filesync(State),
+ _ = Module:terminate(Name, Reason, HandlerState),
+ ok = stop_or_restart(Name, Reason, State),
+ unregister(?name_to_reg_name(Module, Name)),
+ ok.
+
+code_change(_OldVsn, State, _Extra) ->
+ {ok, State}.
+
+
+%%%-----------------------------------------------------------------
+%%% Internal functions
+call(Module, Name, Op) when is_atom(Name) ->
+ call(?name_to_reg_name(Module,Name), Op);
+call(_, Name, Op) ->
+ {error,{badarg,{Op,[Name]}}}.
+
+call(Server, Msg) ->
+ try
+ gen_server:call(Server, Msg, ?DEFAULT_CALL_TIMEOUT)
+ catch
+ _:{timeout,_} -> {error,handler_busy}
+ end.
+
+%% check for overload between every event (and set Mode to async,
+%% sync or drop accordingly), but never flush the whole mailbox
+%% before LogWindowSize events have been handled
+do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) ->
+ T1 = ?timestamp(),
+
+ %% check if the handler is getting overloaded, or if it's
+ %% recovering from overload (the check must be done for each
+ %% event to react quickly to large bursts of events and
+ %% to ensure that the handler can never end up in drop mode
+ %% with an empty mailbox, which would stop operation)
+ {Mode1,QLen,Mem,State1} = check_load(State),
+
+ if (Mode1 == drop) andalso (Mode0 =/= drop) ->
+ log_handler_info(Name, "Handler ~p switched to drop mode",
+ [Name], State);
+ (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) ->
+ log_handler_info(Name, "Handler ~p switched to ~w mode",
+ [Name,Mode1], State);
+ true ->
+ ok
+ end,
+
+ %% kill the handler if it can't keep up with the load
+ kill_if_choked(Name, QLen, Mem, State),
+
+ if Mode1 == flush ->
+ flush(Name, QLen, T1, State1);
+ true ->
+ write(Name, Mode1, T1, Bin, CallOrCast, State1)
+ end.
+
+%% this clause is called by do_log/3 after an overload check
+%% has been performed, where QLen > FlushQLen
+flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) ->
+ %% flush messages in the mailbox (a limited number in
+ %% order to not cause long delays)
+ NewFlushed = flush_log_events(?FLUSH_MAX_N),
+
+ %% write info in log about flushed messages
+ log_handler_info(Name, "Handler ~p flushed ~w log events",
+ [Name,NewFlushed], State),
+
+ %% because of the receive loop when flushing messages, the
+ %% handler will be scheduled out often and the mailbox could
+ %% grow very large, so we'd better check the queue again here
+ {_,_QLen1} = process_info(self(), message_queue_len),
+ ?observe(Name,{max_qlen,_QLen1}),
+
+ %% Add 1 for the current log event
+ ?observe(Name,{flushed,NewFlushed+1}),
+
+ State1 = ?update_max_time(?diff_time(T1,_T0),State),
+ State2 = ?update_max_qlen(_QLen1,State1),
+ {dropped,?update_other(flushed,FLUSHED,NewFlushed,
+ State2#{mode => ?set_mode(ModeTab,async),
+ last_qlen => 0,
+ last_log_ts => T1})}.
+
+%% this clause is called to write to file
+write(Name, Mode, T1, Bin, _CallOrCast,
+ State = #{module := Module,
+ handler_state := HandlerState,
+ mode_tab := ModeTab,
+ ctrl_sync_count := CtrlSync,
+ last_qlen := LastQLen,
+ last_log_ts := T0}) ->
+ %% check if we need to limit the number of writes
+ %% during a burst of log events
+ {DoWrite,State1} = limit_burst(State),
+
+ %% only log synhrounously every ?CONTROLLER_SYNC_INTERVAL time, to
+ %% give the handler time between writes so it can keep up with
+ %% incoming messages
+ {Result,LastQLen1,HandlerState1} =
+ if DoWrite, CtrlSync == 0 ->
+ ?observe(Name,{_CallOrCast,1}),
+ {_,HS1} = Module:write(Name, sync, Bin, HandlerState),
+ {ok,element(2, process_info(self(), message_queue_len)),HS1};
+ DoWrite ->
+ ?observe(Name,{_CallOrCast,1}),
+ {_,HS1} = Module:write(Name, async, Bin, HandlerState),
+ {ok,LastQLen,HS1};
+ not DoWrite ->
+ ?observe(Name,{flushed,1}),
+ {dropped,LastQLen,HandlerState}
+ end,
+
+ %% Check if the time since the previous log event is long enough -
+ %% and the queue length small enough - to assume the mailbox has
+ %% been emptied, and if so, do filesync operation and reset mode to
+ %% async. Note that this is the best we can do to detect an idle
+ %% handler without setting a timer after each log call/cast. If the
+ %% time between two consecutive log events is fast and no new
+ %% event comes in after the last one, idle state won't be detected!
+ Time = ?diff_time(T1,T0),
+ State2 =
+ if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso
+ (Time > ?IDLE_DETECT_TIME_USEC) ->
+ {_,HS2} = Module:filesync(Name,async,HandlerState),
+ State1#{mode => ?change_mode(ModeTab, Mode, async),
+ burst_msg_count => 0,
+ handler_state => HS2};
+ true ->
+ State1#{mode => Mode, handler_state => HandlerState1}
+ end,
+ State3 = ?update_calls_or_casts(_CallOrCast,1,State2),
+ State4 = ?update_max_qlen(LastQLen1,State3),
+ State5 =
+ ?update_max_time(Time,
+ State4#{last_qlen := LastQLen1,
+ last_log_ts => T1,
+ last_op => write,
+ ctrl_sync_count =>
+ if CtrlSync==0 -> ?CONTROLLER_SYNC_INTERVAL;
+ true -> CtrlSync-1
+ end}),
+ {Result,State5}.
+
+log_handler_info(Name, Format, Args, #{module:=Module,
+ formatter:=Formatter,
+ handler_state:=HandlerState}) ->
+ Config = #{formatter=>Formatter},
+ Meta = #{time=>erlang:system_time(microsecond)},
+ Bin = log_to_binary(#{level => notice,
+ msg => {Format,Args},
+ meta => Meta}, Config),
+ _ = Module:write(Name, async, Bin, HandlerState),
+ ok.
%%%-----------------------------------------------------------------
%%% Convert log data on any form to binary
@@ -94,46 +537,65 @@ string_to_binary(String) ->
throw(Error)
end.
-
%%%-----------------------------------------------------------------
%%% Check that the configuration term is valid
-check_common_config({mode_tab,_Tid}) ->
- valid;
-check_common_config({handler_pid,Pid}) when is_pid(Pid) ->
- valid;
-
-check_common_config({sync_mode_qlen,N}) when is_integer(N) ->
- valid;
-check_common_config({drop_mode_qlen,N}) when is_integer(N) ->
- valid;
-check_common_config({flush_qlen,N}) when is_integer(N) ->
- valid;
-
-check_common_config({burst_limit_enable,Bool}) when Bool == true;
- Bool == false ->
- valid;
-check_common_config({burst_limit_max_count,N}) when is_integer(N) ->
- valid;
-check_common_config({burst_limit_window_time,N}) when is_integer(N) ->
- valid;
-
-check_common_config({overload_kill_enable,Bool}) when Bool == true;
- Bool == false ->
- valid;
-check_common_config({overload_kill_qlen,N}) when is_integer(N) ->
- valid;
-check_common_config({overload_kill_mem_size,N}) when is_integer(N) ->
- valid;
-check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA);
- NorA == infinity ->
- valid;
-
-check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA);
- NorA == no_repeat ->
- valid;
-check_common_config(_) ->
- invalid.
+check_config(Config) when is_map(Config) ->
+ case check_common_config(maps:to_list(Config)) of
+ ok ->
+ case overload_levels_ok(Config) of
+ true ->
+ ok;
+ false ->
+ Faulty = maps:with([sync_mode_qlen,
+ drop_mode_qlen,
+ flush_qlen],Config),
+ {error,{invalid_levels,Faulty}}
+ end;
+ Error ->
+ Error
+ end.
+
+check_common_config([{sync_mode_qlen,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{drop_mode_qlen,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{flush_qlen,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{burst_limit_enable,Bool}|Config]) when is_boolean(Bool) ->
+ check_common_config(Config);
+check_common_config([{burst_limit_max_count,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{burst_limit_window_time,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{overload_kill_enable,Bool}|Config]) when is_boolean(Bool) ->
+ check_common_config(Config);
+check_common_config([{overload_kill_qlen,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{overload_kill_mem_size,N}|Config]) when is_integer(N) ->
+ check_common_config(Config);
+check_common_config([{overload_kill_restart_after,NorA}|Config])
+ when is_integer(NorA); NorA == infinity ->
+ check_common_config(Config);
+check_common_config([{filesync_repeat_interval,NorA}|Config])
+ when is_integer(NorA); NorA == no_repeat ->
+ check_common_config(Config);
+check_common_config([{Key,Value}|_]) ->
+ {error,#{Key=>Value}};
+check_common_config([]) ->
+ ok.
+get_default_config() ->
+ #{sync_mode_qlen => ?SYNC_MODE_QLEN,
+ drop_mode_qlen => ?DROP_MODE_QLEN,
+ flush_qlen => ?FLUSH_QLEN,
+ burst_limit_enable => ?BURST_LIMIT_ENABLE,
+ burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT,
+ burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME,
+ overload_kill_enable => ?OVERLOAD_KILL_ENABLE,
+ overload_kill_qlen => ?OVERLOAD_KILL_QLEN,
+ overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE,
+ overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER,
+ filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.
%%%-----------------------------------------------------------------
%%% Overload Protection
@@ -146,15 +608,13 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) ->
async ->
gen_server:cast(HandlerPid, {log,Bin});
sync ->
- try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of
- %% if return value from call == dropped, the
- %% message has been flushed by handler and should
- %% therefore not be counted as dropped in stats
- ok -> ok;
- dropped -> ok
- catch
- _:{timeout,_} ->
- ?observe(_Name,{dropped,1})
+ case call(HandlerPid, {log,Bin}) of
+ ok ->
+ ok;
+ _Other ->
+ %% dropped or {error,handler_busy}
+ ?observe(_Name,{dropped,1}),
+ ok
end;
drop ->
?observe(_Name,{dropped,1})
@@ -165,10 +625,8 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) ->
end,
ok.
-handler_exit(_Name, Reason) ->
- exit(Reason).
-
-set_restart_flag(Name, Module) ->
+set_restart_flag(#{id := Name, module := Module} = State) ->
+ log_handler_info(Name, "Handler ~p overloaded and stopping", [Name], State),
Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])),
spawn(fun() ->
register(Flag, self()),
@@ -176,14 +634,14 @@ set_restart_flag(Name, Module) ->
end),
ok.
-unset_restart_flag(Name, Module) ->
+unset_restart_flag(#{id := Name, module := Module} = State) ->
Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])),
case whereis(Flag) of
undefined ->
- false;
+ ok;
Pid ->
exit(Pid, kill),
- true
+ log_handler_info(Name, "Handler ~p restarted", [Name], State)
end.
check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode,
@@ -221,46 +679,41 @@ check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode,
?update_other(flushes,FLUSHES,_NewFlushes,
State1#{last_qlen => QLen})}.
-limit_burst(#{burst_limit_enable := false}) ->
- {true,0,0};
+limit_burst(#{burst_limit_enable := false}=State) ->
+ {true,State};
limit_burst(#{burst_win_ts := BurstWinT0,
burst_msg_count := BurstMsgCount,
burst_limit_window_time := BurstLimitWinTime,
- burst_limit_max_count := BurstLimitMaxCnt}) ->
+ burst_limit_max_count := BurstLimitMaxCnt} = State) ->
if (BurstMsgCount >= BurstLimitMaxCnt) ->
%% the limit for allowed messages has been reached
BurstWinT1 = ?timestamp(),
case ?diff_time(BurstWinT1,BurstWinT0) of
BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) ->
%% we're still within the burst time frame
- {false,BurstWinT0,BurstMsgCount};
+ {false,?update_other(burst_drops,BURSTS,1,State)};
_BurstCheckTime ->
%% burst time frame passed, reset counters
- {true,BurstWinT1,0}
+ {true,State#{burst_win_ts => BurstWinT1,
+ burst_msg_count => 0}}
end;
true ->
%% the limit for allowed messages not yet reached
- {true,BurstWinT0,BurstMsgCount+1}
+ {true,State#{burst_win_ts => BurstWinT0,
+ burst_msg_count => BurstMsgCount+1}}
end.
-kill_if_choked(Name, QLen, Mem, HandlerMod,
- State = #{overload_kill_enable := KillIfOL,
- overload_kill_qlen := OLKillQLen,
- overload_kill_mem_size := OLKillMem}) ->
+kill_if_choked(Name, QLen, Mem, State = #{overload_kill_enable := KillIfOL,
+ overload_kill_qlen := OLKillQLen,
+ overload_kill_mem_size := OLKillMem}) ->
if KillIfOL andalso
((QLen > OLKillQLen) orelse (Mem > OLKillMem)) ->
- HandlerMod:log_handler_info(Name,
- "Handler ~p overloaded and stopping",
- [Name], State),
- set_restart_flag(Name, HandlerMod),
- handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}});
+ set_restart_flag(State),
+ exit({shutdown,{overloaded,Name,QLen,Mem}});
true ->
ok
end.
-flush_log_events() ->
- flush_log_events(-1).
-
flush_log_events(Limit) ->
process_flag(priority, high),
Flushed = flush_log_events(0, Limit),
@@ -283,16 +736,29 @@ flush_log_events(N, Limit) ->
0 -> N
end.
-cancel_timer(TRef) when is_atom(TRef) -> ok;
-cancel_timer(TRef) -> timer:cancel(TRef).
+set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State)
+ when is_integer(FSyncInt) ->
+ {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast,
+ [self(),repeated_filesync]),
+ State#{rep_sync_tref=>TRef};
+set_repeated_filesync(State) ->
+ State.
+cancel_repeated_filesync(State) ->
+ case maps:take(rep_sync_tref,State) of
+ {TRef,State1} ->
+ _ = timer:cancel(TRef),
+ State1;
+ error ->
+ State
+ end.
stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}},
#{overload_kill_restart_after := RestartAfter}) ->
%% If we're terminating because of an overload situation (see
- %% logger_h_common:kill_if_choked/4), we need to remove the handler
- %% and set a restart timer. A separate process must perform this
- %% in order to avoid deadlock.
+ %% kill_if_choked/4), we need to remove the handler and set a
+ %% restart timer. A separate process must perform this in order to
+ %% avoid deadlock.
HandlerPid = self(),
ConfigResult = logger:get_handler_config(Name),
RemoveAndRestart =
@@ -334,6 +800,3 @@ overload_levels_ok(HandlerConfig) ->
error_notify(Term) ->
?internal_log(error, Term).
-
-info_notify(Term) ->
- ?internal_log(info, Term).
diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl
index e0a7b6e3ca..261b0a6246 100644
--- a/lib/kernel/src/logger_h_common.hrl
+++ b/lib/kernel/src/logger_h_common.hrl
@@ -137,7 +137,7 @@
ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}),
ets:insert(?TEST_HOOKS_TAB, {file_write,ok}),
ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}),
- ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}),
+ ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}),
ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})).
-define(set_internal_log(MOD_FUNC),
@@ -150,7 +150,7 @@
ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}),
ets:insert(?TEST_HOOKS_TAB, {file_write,ok}),
ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}),
- ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}),
+ ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}),
ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})).
-define(internal_log(TYPE, TERM),
@@ -171,11 +171,11 @@
[{_,ERROR}] -> ERROR
catch _:_ -> file:datasync(DEVICE) end).
- -define(disk_log_blog(LOG, DATA),
- try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of
- [{_,ok}] -> disk_log:blog(LOG, DATA);
+ -define(disk_log_write(LOG, MODE, DATA),
+ try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of
+ [{_,ok}] -> disk_log_write(LOG, MODE, DATA);
[{_,ERROR}] -> ERROR
- catch _:_ -> disk_log:blog(LOG, DATA) end).
+ catch _:_ -> disk_log_write(LOG, MODE, DATA) end).
-define(disk_log_sync(LOG),
try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of
@@ -194,7 +194,7 @@
-define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)).
-define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)).
-define(file_datasync(DEVICE), file:datasync(DEVICE)).
- -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)).
+ -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)).
-define(disk_log_sync(LOG), disk_log:sync(LOG)).
-define(DEFAULT_CALL_TIMEOUT, 10000).
-endif.
@@ -210,7 +210,7 @@
-ifdef(SAVE_STATS).
-define(merge_with_stats(STATE),
STATE#{flushes => 0, flushed => 0, drops => 0,
- casts => 0, calls => 0,
+ burst_drops => 0, casts => 0, calls => 0,
max_qlen => 0, max_time => 0}).
-define(update_max_qlen(QLEN, STATE),
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl
index 42e0f5caf4..ebe741e331 100644
--- a/lib/kernel/src/logger_std_h.erl
+++ b/lib/kernel/src/logger_std_h.erl
@@ -19,8 +19,6 @@
%%
-module(logger_std_h).
--behaviour(gen_server).
-
-include("logger.hrl").
-include("logger_internal.hrl").
-include("logger_h_common.hrl").
@@ -28,52 +26,28 @@
-include_lib("kernel/include/file.hrl").
%% API
--export([start_link/3, info/1, filesync/1, reset/1]).
+-export([info/1, filesync/1, reset/1]).
-%% gen_server and proc_lib callbacks
--export([init/1, handle_call/3, handle_cast/2, handle_info/2,
- terminate/2, code_change/3]).
+%% logger_h_common callbacks
+-export([init/2, check_config/4, 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]).
-%% handler internal
--export([log_handler_info/4]).
-
%%%===================================================================
%%% API
%%%===================================================================
%%%-----------------------------------------------------------------
-%%% Start a standard handler process and link to caller.
-%%% This function is called by the kernel supervisor when this
-%%% handler process gets added
--spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when
- Name :: atom(),
- Config :: logger:handler_config(),
- HandlerState :: map(),
- Pid :: pid(),
- Reason :: term().
-
-start_link(Name, Config, HandlerState) ->
- proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]).
-
-%%%-----------------------------------------------------------------
%%%
-spec filesync(Name) -> ok | {error,Reason} when
Name :: atom(),
Reason :: handler_busy | {badarg,term()}.
-filesync(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- filesync, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
filesync(Name) ->
- {error,{badarg,{filesync,[Name]}}}.
+ logger_h_common:filesync(?MODULE,Name).
%%%-----------------------------------------------------------------
%%%
@@ -82,15 +56,8 @@ filesync(Name) ->
Info :: term(),
Reason :: handler_busy | {badarg,term()}.
-info(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- info, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
info(Name) ->
- {error,{badarg,{info,[Name]}}}.
+ logger_h_common:info(?MODULE,Name).
%%%-----------------------------------------------------------------
%%%
@@ -98,47 +65,75 @@ info(Name) ->
Name :: atom(),
Reason :: handler_busy | {badarg,term()}.
-reset(Name) when is_atom(Name) ->
- try
- gen_server:call(?name_to_reg_name(?MODULE,Name),
- reset, ?DEFAULT_CALL_TIMEOUT)
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
reset(Name) ->
- {error,{badarg,{reset,[Name]}}}.
-
+ logger_h_common:reset(?MODULE,Name).
%%%===================================================================
-%%% logger callbacks
+%%% logger callbacks - just forward to logger_h_common
%%%===================================================================
%%%-----------------------------------------------------------------
%%% Handler being added
-adding_handler(#{id:=Name}=Config) ->
- case check_config(adding, Config) of
- {ok, #{config:=HConfig}=Config1} ->
- %% create initial handler state by merging defaults with config
- HState = maps:merge(get_init_state(), HConfig),
- case logger_h_common:overload_levels_ok(HState) of
- true ->
- start(Name, Config1, HState);
- false ->
- #{sync_mode_qlen := SMQL,
- drop_mode_qlen := DMQL,
- flush_qlen := FQL} = HState,
- {error,{invalid_levels,{SMQL,DMQL,FQL}}}
- end;
+-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, #{type := Type}) ->
+ case open_log_file(Name, Type) of
+ {ok,FileCtrlPid} ->
+ {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}};
Error ->
Error
end.
-%%%-----------------------------------------------------------------
-%%% Updating handler config
-changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) ->
+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),
- ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig),
- NewHConfig0 = maps:get(config, NewConfig, #{}),
Default =
case SetOrUpdate of
set ->
@@ -148,48 +143,24 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) ->
OldHConfig
end,
- %% Allow (accidentially) included read-only fields - just overwrite them
- NewHConfig = maps:merge(maps:merge(Default, NewHConfig0),ReadOnly),
+ NewHConfig = maps:merge(Default, NewHConfig0),
- %% But fail if write-once fields are changed
+ %% Fail if write-once fields are changed
case maps:with([type],NewHConfig) of
WriteOnce ->
- changing_config1(maps:get(handler_pid,OldHConfig),
- OldConfig,
- NewConfig#{config=>NewHConfig});
+ check_config(NewHConfig);
Other ->
- {error,{illegal_config_change,#{config=>WriteOnce},#{config=>Other}}}
+ {error,{illegal_config_change,?MODULE,WriteOnce,Other}}
end.
-changing_config1(HPid, OldConfig, NewConfig) ->
- case check_config(changing, NewConfig) of
- Result = {ok,NewConfig1} ->
- try gen_server:call(HPid, {change_config,OldConfig,NewConfig1},
- ?DEFAULT_CALL_TIMEOUT) of
- ok -> Result;
- HError -> HError
- catch
- _:{timeout,_} -> {error,handler_busy}
- end;
- Error ->
- Error
- end.
-
-check_config(adding, Config) ->
- %% Merge in defaults on handler level
- HConfig0 = maps:get(config, Config, #{}),
- HConfig = maps:merge(get_default_config(),HConfig0),
+check_config(#{type:=Type}=HConfig) ->
case check_h_config(maps:to_list(HConfig)) of
+ ok when is_atom(Type) ->
+ {ok,HConfig#{filesync_repeat_interval=>no_repeat}};
ok ->
- {ok,Config#{config=>HConfig}};
- Error ->
- Error
- end;
-check_config(changing, Config) ->
- HConfig = maps:get(config, Config, #{}),
- case check_h_config(maps:to_list(HConfig)) of
- ok -> {ok,Config};
- Error -> Error
+ {ok,HConfig};
+ {error,{Key,Value}} ->
+ {error,{invalid_config,?MODULE,#{Key=>Value}}}
end.
check_h_config([{type,Type} | Config]) when Type == standard_io;
@@ -200,219 +171,40 @@ check_h_config([{type,{file,File}} | Config]) when is_list(File) ->
check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File),
is_list(Modes) ->
check_h_config(Config);
-check_h_config([Other | Config]) ->
- case logger_h_common:check_common_config(Other) of
- valid ->
- check_h_config(Config);
- invalid ->
- {error,{invalid_config,?MODULE,Other}}
- end;
+check_h_config([Other | _]) ->
+ {error,Other};
check_h_config([]) ->
ok.
-
-%%%-----------------------------------------------------------------
-%%% Handler being removed
-removing_handler(#{id:=Name}) ->
- stop(Name).
-
-%%%-----------------------------------------------------------------
-%%% Log a string or report
--spec log(LogEvent, Config) -> ok when
- LogEvent :: logger:log_event(),
- Config :: logger:handler_config().
-
-log(LogEvent, Config = #{id := Name,
- config := #{handler_pid := HPid,
- mode_tab := ModeTab}}) ->
- %% if the handler has crashed, we must drop this event
- %% and hope the handler restarts so we can try again
- true = is_process_alive(HPid),
- Bin = logger_h_common:log_to_binary(LogEvent, Config),
- logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin).
-
-%%%-----------------------------------------------------------------
-%%% Remove internal fields from configuration
-filter_config(#{config:=HConfig}=Config) ->
- Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}.
-
-%%%===================================================================
-%%% gen_server callbacks
-%%%===================================================================
-
-init([Name, Config = #{config := HConfig},
- State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) ->
- RegName = ?name_to_reg_name(?MODULE,Name),
- register(RegName, self()),
- process_flag(trap_exit, true),
- process_flag(message_queue_data, off_heap),
-
- ?init_test_hooks(),
- ?start_observation(Name),
-
- case do_init(Name, Type) of
- {ok,InitState} ->
- try ets:new(Name, [public]) of
- ModeTab ->
- ?set_mode(ModeTab, async),
- State = maps:merge(State0, InitState),
- T0 = ?timestamp(),
- State1 =
- ?merge_with_stats(State#{
- mode_tab => ModeTab,
- mode => async,
- file_ctrl_sync => FileCtrlSyncInt,
- last_qlen => 0,
- last_log_ts => T0,
- last_op => sync,
- burst_win_ts => T0,
- burst_msg_count => 0}),
- Config1 =
- Config#{config => HConfig#{handler_pid => self(),
- mode_tab => ModeTab}},
- proc_lib:init_ack({ok,self(),Config1}),
- gen_server:cast(self(), repeated_filesync),
- gen_server:enter_loop(?MODULE, [], State1)
- catch
- _:Error ->
- unregister(RegName),
- logger_h_common:error_notify({init_handler,Name,Error}),
- proc_lib:init_ack(Error)
- end;
- Error ->
- unregister(RegName),
- logger_h_common:error_notify({init_handler,Name,Error}),
- proc_lib:init_ack(Error)
- end.
-
-do_init(Name, Type) ->
- case open_log_file(Name, Type) of
- {ok,FileCtrlPid} ->
- case logger_h_common:unset_restart_flag(Name, ?MODULE) of
- true ->
- %% inform about restart
- gen_server:cast(self(), {log_handler_info,
- "Handler ~p restarted",
- [Name]});
- false ->
- %% initial start
- ok
- end,
- {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}};
- Error ->
- Error
- end.
-
-%% This is the synchronous log event.
-handle_call({log, Bin}, _From, State) ->
- {Result,State1} = do_log(Bin, call, State),
- %% Result == ok | dropped
- {reply,Result, State1};
-
-handle_call(filesync, _From, State = #{type := Type,
- file_ctrl_pid := FileCtrlPid}) ->
- if is_atom(Type) ->
- {reply, ok, State};
- true ->
- {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}}
- end;
-
-handle_call({change_config,_OldConfig,NewConfig}, _From,
- State = #{filesync_repeat_interval := FSyncInt0}) ->
- HConfig = maps:get(config, NewConfig, #{}),
- State1 = maps:merge(State, HConfig),
- case logger_h_common:overload_levels_ok(State1) of
- true ->
- _ =
- case maps:get(filesync_repeat_interval, HConfig, undefined) of
- undefined ->
- ok;
- no_repeat ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
- State,
- undefined));
- FSyncInt0 ->
- ok;
- _FSyncInt1 ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
- State,
- undefined)),
- gen_server:cast(self(), repeated_filesync)
- end,
- {reply, ok, State1};
- false ->
- #{sync_mode_qlen := SMQL,
- drop_mode_qlen := DMQL,
- flush_qlen := FQL} = State1,
- {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State}
- end;
-
-handle_call(info, _From, State) ->
- {reply, State, State};
-
-handle_call(reset, _From, State) ->
- State1 = ?merge_with_stats(State),
- {reply, ok, State1#{last_qlen => 0,
- last_log_ts => ?timestamp()}};
-
-handle_call(stop, _From, State) ->
- {stop, {shutdown,stopped}, ok, State}.
-
-%% This is the asynchronous log event.
-handle_cast({log, Bin}, State) ->
- {_,State1} = do_log(Bin, cast, State),
- {noreply, State1};
-
-handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) ->
- log_handler_info(Name, Format, Args, State),
- {noreply, State};
-
-%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this
-%% clause gets called repeatedly by the handler. In order to
-%% guarantee that a filesync *always* happens after the last log
-%% event, the repeat operation must be active!
-handle_cast(repeated_filesync,
- State = #{type := Type,
- file_ctrl_pid := FileCtrlPid,
- filesync_repeat_interval := FSyncInt,
- last_op := LastOp}) ->
- State1 =
- if not is_atom(Type), is_integer(FSyncInt) ->
- %% only do filesync if something has been
- %% written since last time we checked
- if LastOp == sync ->
- ok;
- true ->
- file_ctrl_filesync_async(FileCtrlPid)
- end,
- {ok,TRef} =
- timer:apply_after(FSyncInt, gen_server,cast,
- [self(),repeated_filesync]),
- State#{rep_sync_tref => TRef, last_op => sync};
- true ->
- State
- end,
- {noreply,State1}.
-
-handle_info({'EXIT',Pid,Why}, State = #{id := Name, type := FileInfo}) ->
- case maps:get(file_ctrl_pid, State, undefined) of
- Pid ->
- %% file error, terminate handler
- logger_h_common:handler_exit(Name,
- {error,{write_failed,FileInfo,Why}});
- _Other ->
- %% ignore EXIT
- ok
- end,
- {noreply, State};
-
-handle_info(_Info, State) ->
- {noreply, State}.
-
-terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid,
- type:=_FileInfo}) ->
- _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State,
- undefined)),
+get_default_config() ->
+ #{type => standard_io}.
+
+filesync(_Name, _Mode, #{type := Type}=State) when is_atom(Type) ->
+ {ok,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),
+ {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),
+ {Result,State}.
+
+reset_state(_Name, State) ->
+ State.
+
+handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) ->
+ %% file_ctrl_pid died, file error, terminate handler
+ exit({error,{write_failed,FileInfo,Why}});
+handle_info(_, _, State) ->
+ State.
+
+terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) ->
case is_process_alive(FWPid) of
true ->
unlink(FWPid),
@@ -423,17 +215,12 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid,
ok
after
?DEFAULT_CALL_TIMEOUT ->
- exit(FWPid, kill)
+ exit(FWPid, kill),
+ ok
end;
false ->
ok
- end,
- ok = logger_h_common:stop_or_restart(Name, Reason, State),
- unregister(?name_to_reg_name(?MODULE, Name)),
- ok.
-
-code_change(_OldVsn, State, _Extra) ->
- {ok, State}.
+ end.
%%%===================================================================
%%% Internal functions
@@ -441,203 +228,6 @@ code_change(_OldVsn, State, _Extra) ->
%%%-----------------------------------------------------------------
%%%
-get_default_config() ->
- #{type => standard_io,
- sync_mode_qlen => ?SYNC_MODE_QLEN,
- drop_mode_qlen => ?DROP_MODE_QLEN,
- flush_qlen => ?FLUSH_QLEN,
- burst_limit_enable => ?BURST_LIMIT_ENABLE,
- burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT,
- burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME,
- overload_kill_enable => ?OVERLOAD_KILL_ENABLE,
- overload_kill_qlen => ?OVERLOAD_KILL_QLEN,
- overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE,
- overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER,
- filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.
-
-get_init_state() ->
- #{file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL,
- filesync_ok_qlen => ?FILESYNC_OK_QLEN}.
-
-%%%-----------------------------------------------------------------
-%%% Add a standard handler to the logger.
-%%% This starts a dedicated handler process which should always
-%%% exist if the handler is registered with logger (and should not
-%%% exist if the handler is not registered).
-%%%
-%%% Handler specific config should be provided with a sub map associated
-%%% with a key named 'config', e.g:
-%%%
-%%% Config = #{config => #{sync_mode_qlen => 50}
-%%%
-%%% The standard handler process is linked to logger_sup, which is
-%%% part of the kernel application's supervision tree.
-start(Name, Config, HandlerState) ->
- LoggerStdH =
- #{id => Name,
- start => {?MODULE, start_link, [Name,Config,HandlerState]},
- restart => temporary,
- shutdown => 2000,
- type => worker,
- modules => [?MODULE]},
- case supervisor:start_child(logger_sup, LoggerStdH) of
- {ok,Pid,Config1} ->
- ok = logger_handler_watcher:register_handler(Name,Pid),
- {ok,Config1};
- Error ->
- Error
- end.
-
-%%%-----------------------------------------------------------------
-%%% Stop and remove the handler.
-stop(Name) ->
- case whereis(?name_to_reg_name(?MODULE,Name)) of
- undefined ->
- ok;
- Pid ->
- %% We don't want to do supervisor:terminate_child here
- %% since we need to distinguish this explicit stop from a
- %% system termination in order to avoid circular attempts
- %% at removing the handler (implying deadlocks and
- %% timeouts).
- %% And we don't need to do supervisor:delete_child, since
- %% the restart type is temporary, which means that the
- %% child specification is automatically removed from the
- %% supervisor when the process dies.
- _ = gen_server:call(Pid, stop),
- ok
- end.
-
-%%%-----------------------------------------------------------------
-%%% Logging and overload control.
--define(update_file_ctrl_sync(C, Interval),
- if C == 0 -> Interval;
- true -> C-1 end).
-
-%% check for overload between every event (and set Mode to async,
-%% sync or drop accordingly), but never flush the whole mailbox
-%% before LogWindowSize events have been handled
-do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) ->
- T1 = ?timestamp(),
-
- %% check if the handler is getting overloaded, or if it's
- %% recovering from overload (the check must be done for each
- %% event to react quickly to large bursts of events and
- %% to ensure that the handler can never end up in drop mode
- %% with an empty mailbox, which would stop operation)
- {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State),
-
- if (Mode1 == drop) andalso (Mode0 =/= drop) ->
- log_handler_info(Name, "Handler ~p switched to drop mode",
- [Name], State);
- (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) ->
- log_handler_info(Name, "Handler ~p switched to ~w mode",
- [Name,Mode1], State);
- true ->
- ok
- end,
-
- %% kill the handler if it can't keep up with the load
- logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State),
-
- if Mode1 == flush ->
- flush(Name, QLen, T1, State1);
- true ->
- write(Name, Mode1, T1, Bin, CallOrCast, State1)
- end.
-
-%% this clause is called by do_log/3 after an overload check
-%% has been performed, where QLen > FlushQLen
-flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) ->
- %% flush messages in the mailbox (a limited number in
- %% order to not cause long delays)
- NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N),
-
- %% write info in log about flushed messages
- log_handler_info(Name, "Handler ~p flushed ~w log events",
- [Name,NewFlushed], State),
-
- %% because of the receive loop when flushing messages, the
- %% handler will be scheduled out often and the mailbox could
- %% grow very large, so we'd better check the queue again here
- {_,_QLen1} = process_info(self(), message_queue_len),
- ?observe(Name,{max_qlen,_QLen1}),
-
- %% Add 1 for the current log event
- ?observe(Name,{flushed,NewFlushed+1}),
-
- State1 = ?update_max_time(?diff_time(T1,_T0),State),
- {dropped,?update_other(flushed,FLUSHED,NewFlushed,
- State1#{mode => ?set_mode(ModeTab,async),
- last_qlen => 0,
- last_log_ts => T1})}.
-
-%% this clause is called to write to file
-write(_Name, Mode, T1, Bin, _CallOrCast,
- State = #{mode_tab := ModeTab,
- file_ctrl_pid := FileCtrlPid,
- file_ctrl_sync := FileCtrlSync,
- last_qlen := LastQLen,
- last_log_ts := T0,
- file_ctrl_sync_int := FileCtrlSyncInt}) ->
- %% check if we need to limit the number of writes
- %% during a burst of log events
- {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State),
-
- %% only send a synhrounous event to the file controller process
- %% every FileCtrlSyncInt time, to give the handler time between
- %% file writes so it can keep up with incoming messages
- {Result,LastQLen1} =
- if DoWrite, FileCtrlSync == 0 ->
- ?observe(_Name,{_CallOrCast,1}),
- file_write_sync(FileCtrlPid, Bin, false),
- {ok,element(2, process_info(self(), message_queue_len))};
- DoWrite ->
- ?observe(_Name,{_CallOrCast,1}),
- file_write_async(FileCtrlPid, Bin),
- {ok,LastQLen};
- not DoWrite ->
- ?observe(_Name,{flushed,1}),
- {dropped,LastQLen}
- end,
-
- %% Check if the time since the previous log event is long enough -
- %% and the queue length small enough - to assume the mailbox has
- %% been emptied, and if so, do filesync operation and reset mode to
- %% async. Note that this is the best we can do to detect an idle
- %% handler without setting a timer after each log call/cast. If the
- %% time between two consecutive log events is fast and no new
- %% event comes in after the last one, idle state won't be detected!
- Time = ?diff_time(T1,T0),
- {Mode1,BurstMsgCount1} =
- if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso
- (Time > ?IDLE_DETECT_TIME_USEC) ->
- %% do filesync if necessary
- case maps:get(type, State) of
- Std when is_atom(Std) ->
- ok;
- _File ->
- file_ctrl_filesync_async(FileCtrlPid)
- end,
- {?change_mode(ModeTab, Mode, async),0};
- true ->
- {Mode,BurstMsgCount}
- end,
- State1 =
- ?update_calls_or_casts(_CallOrCast,1,State),
- State2 =
- ?update_max_time(Time,
- State1#{mode => Mode1,
- last_qlen := LastQLen1,
- last_log_ts => T1,
- last_op => write,
- burst_win_ts => BurstWinT,
- burst_msg_count => BurstMsgCount1,
- file_ctrl_sync =>
- ?update_file_ctrl_sync(FileCtrlSync,
- FileCtrlSyncInt)}),
- {Result,State2}.
-
open_log_file(HandlerName, FileInfo) ->
case file_ctrl_start(HandlerName, FileInfo) of
OK = {ok,_FileCtrlPid} -> OK;
@@ -669,19 +259,6 @@ close_log_file(Fd) ->
_ = file:close(Fd).
-log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) ->
- Config =
- case logger:get_handler_config(Name) of
- {ok,Conf} -> Conf;
- _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}
- end,
- Meta = #{time=>erlang:system_time(microsecond)},
- Bin = logger_h_common:log_to_binary(#{level => notice,
- msg => {Format,Args},
- meta => Meta}, Config),
- _ = file_write_async(FileCtrlPid, Bin),
- ok.
-
%%%-----------------------------------------------------------------
%%% File control process
@@ -708,24 +285,19 @@ file_write_async(Pid, Bin) ->
Pid ! {log,Bin},
ok.
-file_write_sync(Pid, Bin, FileSync) ->
- case file_ctrl_call(Pid, {log,self(),Bin,FileSync}) of
- {error,Reason} ->
- {error,{write_failed,Bin,Reason}};
- Result ->
- Result
- end.
+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,self()}).
+ file_ctrl_call(Pid, filesync).
file_ctrl_call(Pid, Msg) ->
MRef = monitor(process, Pid),
- Pid ! {Msg,MRef},
+ Pid ! {Msg,{self(),MRef}},
receive
{MRef,Result} ->
demonitor(MRef, [flush]),
@@ -743,74 +315,40 @@ file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) ->
case do_open_log_file(FileInfo) of
{ok,Fd} ->
Starter ! {self(),ok},
- file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName);
+ file_ctrl_loop(Fd, FileName, false, ok, ok, HandlerName);
{error,Reason} ->
Starter ! {self(),{error,{open_failed,FileName,Reason}}}
end;
file_ctrl_init(HandlerName, StdDev, Starter) ->
Starter ! {self(),ok},
- file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName).
+ file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName).
-file_ctrl_loop(Fd, Type, DevName, Synced,
+file_ctrl_loop(Fd, DevName, Synced,
PrevWriteResult, PrevSyncResult, HandlerName) ->
receive
%% asynchronous event
{log,Bin} ->
- Result = if Type == file ->
- write_to_dev(Fd, Bin, DevName,
- PrevWriteResult, HandlerName);
- true ->
- io:put_chars(Fd, Bin)
- end,
- file_ctrl_loop(Fd, Type, DevName, false,
+ Result = write_to_dev(Fd, Bin, DevName, PrevWriteResult, HandlerName),
+ file_ctrl_loop(Fd, DevName, false,
Result, PrevSyncResult, HandlerName);
%% synchronous event
- {{log,From,Bin,FileSync},MRef} ->
- if Type == file ->
- %% check that file hasn't been deleted
- CheckFile =
- fun() -> {ok,_} = file:read_file_info(DevName) end,
- spawn_link(CheckFile),
- WResult = write_to_dev(Fd, Bin, DevName,
- PrevWriteResult, HandlerName),
- {Synced1,SResult} =
- if not FileSync ->
- {false,PrevSyncResult};
- true ->
- case sync_dev(Fd, DevName,
- PrevSyncResult, HandlerName) of
- ok -> {true,ok};
- Error -> {false,Error}
- end
- end,
- From ! {MRef,ok},
- file_ctrl_loop(Fd, Type, DevName, Synced1,
- WResult, SResult, HandlerName);
- true ->
- _ = io:put_chars(Fd, Bin),
- From ! {MRef,ok},
- file_ctrl_loop(Fd, Type, DevName, false,
- ok, PrevSyncResult, HandlerName)
- end;
+ {{log,Bin},{From,MRef}} ->
+ check_exist(Fd, DevName),
+ Result = write_to_dev(Fd, Bin, DevName, PrevWriteResult, HandlerName),
+ From ! {MRef,ok},
+ file_ctrl_loop(Fd, DevName, false,
+ Result, PrevSyncResult, HandlerName);
- filesync when not Synced ->
- Result = sync_dev(Fd, DevName, PrevSyncResult, HandlerName),
- file_ctrl_loop(Fd, Type, DevName, true,
+ filesync ->
+ Result = sync_dev(Fd, DevName, Synced, PrevSyncResult, HandlerName),
+ file_ctrl_loop(Fd, DevName, true,
PrevWriteResult, Result, HandlerName);
- filesync ->
- file_ctrl_loop(Fd, Type, DevName, true,
- PrevWriteResult, PrevSyncResult, HandlerName);
-
- {{filesync,From},MRef} ->
- Result = if not Synced ->
- sync_dev(Fd, DevName, PrevSyncResult, HandlerName);
- true ->
- ok
- end,
+ {filesync,{From,MRef}} ->
+ Result = sync_dev(Fd, DevName, Synced, PrevSyncResult, HandlerName),
From ! {MRef,ok},
- file_ctrl_loop(Fd, Type, DevName, true,
+ file_ctrl_loop(Fd, DevName, true,
PrevWriteResult, Result, HandlerName);
stop ->
@@ -818,26 +356,30 @@ file_ctrl_loop(Fd, Type, DevName, Synced,
stopped
end.
+check_exist(DevName, DevName) when is_atom(DevName) ->
+ ok;
+check_exist(_Fd, FileName) ->
+ _ = spawn_link(fun() -> {ok,_} = file:read_file_info(FileName) end),
+ ok.
+
+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) ->
- case ?file_write(Fd, Bin) of
- ok ->
- ok;
- PrevWriteResult ->
- %% don't report same error twice
- PrevWriteResult;
- Error ->
- logger_h_common:error_notify({HandlerName,write,FileName,Error}),
- Error
- end.
+ Result = ?file_write(Fd, Bin),
+ maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName).
-sync_dev(Fd, DevName, PrevSyncResult, HandlerName) ->
- case ?file_datasync(Fd) of
- ok ->
- ok;
- PrevSyncResult ->
- %% don't report same error twice
- PrevSyncResult;
- Error ->
- logger_h_common:error_notify({HandlerName,filesync,DevName,Error}),
- Error
- end.
+sync_dev(_Fd, _FileName, true, PrevSyncResult, _HandlerName) ->
+ PrevSyncResult;
+sync_dev(Fd, FileName, false, PrevSyncResult, HandlerName) ->
+ Result = ?file_datasync(Fd),
+ maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName).
+
+maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) ->
+ ok;
+maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) ->
+ %% don't report same error twice
+ PrevResult;
+maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) ->
+ logger_h_common:error_notify({HandlerName,Op,FileName,Error}),
+ Error.
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index 905c2c52c5..87b8250781 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -332,16 +332,18 @@ errors(Config) ->
%%! Check how bad log_opts are handled!
{error,{illegal_config_change,
- #{config:=#{type:=wrap}},
- #{config:=#{type:=halt}}}} =
+ logger_disk_log_h,
+ #{type:=wrap},
+ #{type:=halt}}} =
logger:update_handler_config(Name1,
config,
#{type=>halt,
file=>LogFile1}),
{error,{illegal_config_change,
- #{config:=#{file:=LogFile1}},
- #{config:=#{file:="newfilename"}}}} =
+ logger_disk_log_h,
+ #{file:=LogFile1},
+ #{file:="newfilename"}}} =
logger:update_handler_config(Name1,
config,
#{file=>"newfilename"}),
@@ -411,20 +413,25 @@ formatter_fail(cleanup,_Config) ->
ok.
config_fail(_Config) ->
- {error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} =
+ {error,{handler_not_added,{invalid_config,logger_disk_log_h,#{bad:=bad}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{bad => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
- {error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
+ {error,{handler_not_added,{invalid_config,logger_disk_log_h,
+ {invalid_levels,#{drop_mode_qlen:=1}}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{drop_mode_qlen=>1}}),
- {error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
+ {error,{handler_not_added,{invalid_config,logger_disk_log_h,
+ {invalid_levels,#{sync_mode_qlen:=43,
+ drop_mode_qlen:=42}}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{sync_mode_qlen=>43,
drop_mode_qlen=>42}}),
- {error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
+ {error,{handler_not_added,{invalid_config,logger_disk_log_h,
+ {invalid_levels,#{drop_mode_qlen:=43,
+ flush_qlen:=42}}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{drop_mode_qlen=>43,
flush_qlen=>42}}),
@@ -433,20 +440,17 @@ config_fail(_Config) ->
#{filter_default=>log,
formatter=>{?MODULE,self()}}),
%% can't change the disk log options for a log already in use
- {error,{illegal_config_change,_,_}} =
+ {error,{illegal_config_change,logger_disk_log_h,_,_}} =
logger:update_handler_config(?MODULE,config,
#{max_no_files=>2}),
- %% can't change name of an existing handler
- {error,{illegal_config_change,_,_}} =
- logger:update_handler_config(?MODULE,id,bad),
%% incorrect values of OP params
{ok,#{config := HConfig}} = logger:get_handler_config(?MODULE),
- {error,{invalid_levels,_}} =
+ {error,{invalid_config,logger_disk_log_h,{invalid_levels,_}}} =
logger:update_handler_config(?MODULE,config,
HConfig#{sync_mode_qlen=>100,
flush_qlen=>99}),
%% invalid name of config parameter
- {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} =
+ {error,{invalid_config,logger_disk_log_h,#{filesync_rep_int:=2000}}} =
logger:update_handler_config(?MODULE, config,
HConfig#{filesync_rep_int => 2000}),
ok.
@@ -487,10 +491,11 @@ reconfig(Config) ->
overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE,
overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER,
filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL,
- log_opts := #{type := ?DISK_LOG_TYPE,
- max_no_files := ?DISK_LOG_MAX_NO_FILES,
- max_no_bytes := ?DISK_LOG_MAX_NO_BYTES,
- file := DiskLogFile}} =
+ handler_state :=
+ #{log_opts := #{type := ?DISK_LOG_TYPE,
+ max_no_files := ?DISK_LOG_MAX_NO_FILES,
+ max_no_bytes := ?DISK_LOG_MAX_NO_BYTES,
+ file := DiskLogFile}}} =
logger_disk_log_h:info(?MODULE),
{ok,#{config :=
#{sync_mode_qlen := ?SYNC_MODE_QLEN,
@@ -572,10 +577,11 @@ reconfig(Config) ->
max_no_files => 1,
max_no_bytes => 1024,
file => File}}),
- #{log_opts := #{type := halt,
- max_no_files := 1,
- max_no_bytes := 1024,
- file := File}} =
+ #{handler_state :=
+ #{log_opts := #{type := halt,
+ max_no_files := 1,
+ max_no_bytes := 1024,
+ file := File}}} =
logger_disk_log_h:info(?MODULE),
{ok,#{config :=
#{type := halt,
@@ -596,13 +602,13 @@ reconfig(Config) ->
%% You are not allowed to actively set the write once fields
%% (type, max_no_files, max_no_bytes, file) in runtime.
- {error, {illegal_config_change,_,_}} =
+ {error, {illegal_config_change,_,_,_}} =
logger:set_handler_config(?MODULE,config,#{type=>wrap}),
- {error, {illegal_config_change,_,_}} =
+ {error, {illegal_config_change,_,_,_}} =
logger:set_handler_config(?MODULE,config,#{max_no_files=>2}),
- {error, {illegal_config_change,_,_}} =
+ {error, {illegal_config_change,_,_,_}} =
logger:set_handler_config(?MODULE,config,#{max_no_bytes=>2048}),
- {error, {illegal_config_change,_,_}} =
+ {error, {illegal_config_change,_,_,_}} =
logger:set_handler_config(?MODULE,config,#{file=>"otherfile.log"}),
{ok,C7} = logger:get_handler_config(?MODULE),
ct:log("C7: ~p",[C7]),
@@ -630,16 +636,16 @@ sync(Config) ->
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,nl}}),
- start_tracer([{disk_log,blog,2},
- {logger_disk_log_h,disk_log_sync,2}],
- [{disk_log,blog,<<"first\n">>},
- {logger_disk_log_h,disk_log_sync}]),
+ start_tracer([{logger_disk_log_h,disk_log_write,3},
+ {disk_log,sync,1}],
+ [{logger_disk_log_h,disk_log_write,<<"first\n">>},
+ {disk_log,sync}]),
logger:notice("first", ?domain),
%% wait for automatic disk_log_sync
check_tracer(?FILESYNC_REPEAT_INTERVAL*2),
- %% check that if there's no repeated disk_log_sync active,
+ %% check that if there's no repeated filesync active,
%% a disk_log_sync is still performed when handler goes idle
{ok,#{config := HConfig}} = logger:get_handler_config(?MODULE),
HConfig1 = HConfig#{filesync_repeat_interval => no_repeat},
@@ -652,12 +658,12 @@ sync(Config) ->
%% triggered by the idle timeout between "fourth" and "fifth".
timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
- start_tracer([{disk_log,blog,2},
- {logger_disk_log_h,disk_log_sync,2}],
- [{disk_log,blog,<<"second\n">>},
- {logger_disk_log_h,disk_log_sync},
- {disk_log,blog,<<"third\n">>},
- {logger_disk_log_h,disk_log_sync}]),
+ start_tracer([{logger_disk_log_h,disk_log_write,3},
+ {disk_log,sync,1}],
+ [{logger_disk_log_h,disk_log_write,<<"second\n">>},
+ {disk_log,sync},
+ {logger_disk_log_h,disk_log_write,<<"third\n">>},
+ {disk_log,sync}]),
logger:notice("second", ?domain),
timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
@@ -667,13 +673,13 @@ sync(Config) ->
try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000),
- %% switch repeated disk_log_sync on and verify that the looping works
+ %% switch repeated filesync on and verify that the looping works
SyncInt = 1000,
WaitT = 4500,
- OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync},
- %% receive 1 initial repeated_disk_log_sync, then 1 per sec
- start_tracer([{logger_disk_log_h,handle_cast,2}],
- [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+ OneSync = {logger_h_common,handle_cast,repeated_filesync},
+ %% receive 1 repeated_filesync per sec
+ start_tracer([{logger_h_common,handle_cast,2}],
+ [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]),
HConfig2 = HConfig#{filesync_repeat_interval => SyncInt},
ok = logger:update_handler_config(?MODULE, config, HConfig2),
@@ -716,7 +722,7 @@ disk_log_wrap(Config) ->
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
- {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
+ {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []),
Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)],
ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]),
@@ -734,7 +740,7 @@ disk_log_wrap(Config) ->
timer:sleep(1000),
dbg:stop_clear(),
Received = lists:flatmap(fun({trace,_M,handle_info,
- [{disk_log,_Node,_Name,What},_]}) ->
+ [_,{disk_log,_Node,_Name,What},_]}) ->
[{trace,What}];
({log,_}) ->
[]
@@ -770,7 +776,7 @@ disk_log_full(Config) ->
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
- {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
+ {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []),
NoOfChars = 5,
Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)],
@@ -780,14 +786,18 @@ disk_log_full(Config) ->
timer:sleep(2000),
dbg:stop_clear(),
Received = lists:flatmap(fun({trace,_M,handle_info,
- [{disk_log,_Node,_Name,What},_]}) ->
+ [_,{disk_log,_Node,_Name,What},_]}) ->
[{trace,What}];
({log,_}) ->
[]
end, test_server:messages_get()),
ct:pal("Trace =~n~p", [Received]),
- [{trace,full},
- {trace,{error_status,{error,{full,_}}}}] = Received,
+
+ %% The tail here could be an error_status notification, if the
+ %% last write was synchronous, but in most cases it will not be
+ [{trace,full}|_] = Received,
+ %% [{trace,full},
+ %% {trace,{error_status,{error,{full,_}}}}] = Received,
ok.
disk_log_full(cleanup, _Config) ->
dbg:stop_clear(),
@@ -819,14 +829,14 @@ disk_log_events(Config) ->
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
- {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
+ {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []),
[whereis(h_proc_name()) ! E || E <- Events],
%% wait for trace messages
timer:sleep(2000),
dbg:stop_clear(),
Received = lists:map(fun({trace,_M,handle_info,
- [Got,_]}) -> Got
+ [_,Got,_]}) -> Got
end, test_server:messages_get()),
ct:pal("Trace =~n~p", [Received]),
NoOfEvents = length(Events),
@@ -849,13 +859,15 @@ write_failure(Config) ->
false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])),
rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]),
rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]),
- rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]),
+ rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]),
HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]),
- ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]),
+ ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts,
+ maps:get(handler_state,HState))]),
+ %% ?check and ?check_no_log in this test only check for internal log events
ok = log_on_remote_node(Node, "Logged1"),
rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
- ?check_no_log,
+ ?check_no_log, % no internal log when write ok
SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of
true -> 5500;
@@ -864,24 +876,26 @@ write_failure(Config) ->
try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt),
- rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]),
+ rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
+ %% this should have caused an internal log
?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}),
-
+
ok = log_on_remote_node(Node, "No second error printout"),
- ?check_no_log,
+ ?check_no_log, % but don't log same error twice
- rpc:call(Node, ?MODULE, set_result, [disk_log_blog,
+ rpc:call(Node, ?MODULE, set_result, [disk_log_write,
{error,{full,?STANDARD_HANDLER}}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
+ %% this was a different error, so it should be logged
?check({error,{?STANDARD_HANDLER,log,LogOpts,
{error,{full,?STANDARD_HANDLER}}}}),
- rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]),
+ rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]),
ok = log_on_remote_node(Node, "Logged2"),
rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
- ?check_no_log,
+ ?check_no_log, % no internal log when write ok
try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt),
ok.
write_failure(cleanup, _Config) ->
@@ -901,7 +915,7 @@ sync_failure(Config) ->
rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]),
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]),
HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]),
- LogOpts = maps:get(log_opts, HState),
+ LogOpts = maps:get(log_opts, maps:get(handler_state,HState)),
SyncInt = 500,
ok = rpc:call(Node, logger, update_handler_config,
@@ -1606,10 +1620,10 @@ tpl([{M,F,A}|Trace]) ->
tpl([]) ->
ok.
-tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]},Caller},
+tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]},Caller},
{Pid,[{Mod,Func,Op}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller);
-tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) ->
+tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller);
tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func},Caller);
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index b6a09f4980..a1159f280c 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -140,7 +140,7 @@ all() ->
].
add_remove_instance_tty(_Config) ->
- {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} =
+ {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{type => tty},
filter_default=>log,
@@ -234,7 +234,7 @@ errors(Config) ->
{error,
{handler_not_added,
- {invalid_config,logger_std_h,{type,faulty_type}}}} =
+ {invalid_config,logger_std_h,#{type:=faulty_type}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{type => faulty_type}}),
@@ -308,25 +308,30 @@ formatter_fail(cleanup,_Config) ->
logger:remove_handler(?MODULE).
config_fail(_Config) ->
- {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} =
+ {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{bad => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
{error,{handler_not_added,{invalid_config,logger_std_h,
- {restart_type,bad}}}} =
+ #{restart_type:=bad}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{restart_type => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
- {error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
+ {error,{handler_not_added,{invalid_config,logger_std_h,
+ {invalid_levels,#{drop_mode_qlen:=1}}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{drop_mode_qlen=>1}}),
- {error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
+ {error,{handler_not_added,{invalid_config,logger_std_h,
+ {invalid_levels,#{sync_mode_qlen:=43,
+ drop_mode_qlen:=42}}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{sync_mode_qlen=>43,
drop_mode_qlen=>42}}),
- {error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
+ {error,{handler_not_added,{invalid_config,logger_std_h,
+ {invalid_levels,#{drop_mode_qlen:=43,
+ flush_qlen:=42}}}}} =
logger:add_handler(?MODULE,logger_std_h,
#{config => #{drop_mode_qlen=>43,
flush_qlen=>42}}),
@@ -334,15 +339,15 @@ config_fail(_Config) ->
ok = logger:add_handler(?MODULE,logger_std_h,
#{filter_default=>log,
formatter=>{?MODULE,self()}}),
- {error,{illegal_config_change,#{config:=#{type:=_}},#{config:=#{type:=_}}}} =
+ {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} =
logger:set_handler_config(?MODULE,config,
#{type=>{file,"file"}}),
- {error,{invalid_levels,_}} =
+ {error,{invalid_config,logger_std_h,{invalid_levels,_}}} =
logger:set_handler_config(?MODULE,config,
#{sync_mode_qlen=>100,
flush_qlen=>99}),
- {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} =
+ {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} =
logger:set_handler_config(?MODULE, config,
#{filesync_rep_int => 2000}),
@@ -468,8 +473,8 @@ reconfig(Config) ->
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}}),
#{id := ?MODULE,
- type := standard_io,
- file_ctrl_pid := FileCtrlPid,
+ handler_state := #{type := standard_io,
+ file_ctrl_pid := FileCtrlPid},
sync_mode_qlen := ?SYNC_MODE_QLEN,
drop_mode_qlen := ?DROP_MODE_QLEN,
flush_qlen := ?FLUSH_QLEN,
@@ -480,7 +485,7 @@ reconfig(Config) ->
overload_kill_qlen := ?OVERLOAD_KILL_QLEN,
overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE,
overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER,
- filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = DefaultInfo =
+ filesync_repeat_interval := no_repeat} = DefaultInfo =
logger_std_h:info(?MODULE),
{ok,
@@ -496,7 +501,7 @@ reconfig(Config) ->
overload_kill_qlen := ?OVERLOAD_KILL_QLEN,
overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE,
overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER,
- filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} =
+ filesync_repeat_interval := no_repeat} =
DefaultHConf}}
= logger:get_handler_config(?MODULE),
@@ -511,10 +516,10 @@ reconfig(Config) ->
overload_kill_qlen => 100000,
overload_kill_mem_size => 10000000,
overload_kill_restart_after => infinity,
- filesync_repeat_interval => no_repeat}),
+ filesync_repeat_interval => 5000}),
#{id := ?MODULE,
- type := standard_io,
- file_ctrl_pid := FileCtrlPid,
+ handler_state := #{type := standard_io,
+ file_ctrl_pid := FileCtrlPid},
sync_mode_qlen := 1,
drop_mode_qlen := 2,
flush_qlen := 3,
@@ -584,7 +589,7 @@ reconfig(Config) ->
%% You are not allowed to actively set 'type' in runtime, since
%% this is a write once field.
- {error, {illegal_config_change,_,_}} =
+ {error, {illegal_config_change,logger_std_h,_,_}} =
logger:set_handler_config(?MODULE,config,#{type=>standard_io}),
{ok,#{config:=C6}} = logger:get_handler_config(?MODULE),
ct:log("C6: ~p",[C6]),
@@ -620,7 +625,7 @@ file_opts(Config) ->
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}}),
- #{type := OkType} = logger_std_h:info(?MODULE),
+ #{handler_state := #{type := OkType}} = logger_std_h:info(?MODULE),
logger:notice(M1=?msg,?domain),
?check(M1),
B1 = ?bin(M1),
@@ -643,10 +648,8 @@ sync(Config) ->
%% check repeated filesync happens
start_tracer([{logger_std_h, write_to_dev, 5},
- {logger_std_h, sync_dev, 4},
{file, datasync, 1}],
[{logger_std_h, write_to_dev, <<"first\n">>},
- {logger_std_h, sync_dev},
{file,datasync}]),
logger:notice("first", ?domain),
@@ -655,10 +658,8 @@ sync(Config) ->
%% check that explicit filesync is only done once
start_tracer([{logger_std_h, write_to_dev, 5},
- {logger_std_h, sync_dev, 4},
{file, datasync, 1}],
[{logger_std_h, write_to_dev, <<"second\n">>},
- {logger_std_h, sync_dev},
{file,datasync},
{no_more,500}
]),
@@ -679,13 +680,10 @@ sync(Config) ->
%% triggered by the idle timeout between "thrid" and "fourth".
timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
start_tracer([{logger_std_h, write_to_dev, 5},
- {logger_std_h, sync_dev, 4},
{file, datasync, 1}],
[{logger_std_h, write_to_dev, <<"third\n">>},
- {logger_std_h, sync_dev},
{file,datasync},
{logger_std_h, write_to_dev, <<"fourth\n">>},
- {logger_std_h, sync_dev},
{file,datasync}]),
logger:notice("third", ?domain),
%% wait for automatic filesync
@@ -697,10 +695,10 @@ sync(Config) ->
%% switch repeated filesync on and verify that the looping works
SyncInt = 1000,
WaitT = 4500,
- OneSync = {logger_std_h,handle_cast,repeated_filesync},
- %% receive 1 initial repeated_filesync, then 1 per sec
- start_tracer([{logger_std_h,handle_cast,2}],
- [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+ OneSync = {logger_h_common,handle_cast,repeated_filesync},
+ %% receive 1 repeated_filesync per sec
+ start_tracer([{logger_h_common,handle_cast,2}],
+ [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]),
ok = logger:update_handler_config(?MODULE, config,
#{filesync_repeat_interval => SyncInt}),
@@ -1533,7 +1531,7 @@ start_op_trace() ->
{ok,_} = dbg:p(self(), [c]),
MS1 = dbg:fun2ms(fun([_]) -> return_trace() end),
- {ok,_} = dbg:tp(logger_h_common, check_load, 1, MS1),
+ {ok,_} = dbg:tpl(logger_h_common, check_load, 1, MS1),
{ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []),
@@ -1607,7 +1605,9 @@ analyse(Msgs) ->
start_tracer(Trace,Expected) ->
Pid = self(),
- FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)),
+ FileCtrlPid = maps:get(file_ctrl_pid,
+ maps:get(handler_state,
+ logger_std_h:info(?MODULE))),
dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
dbg:p(whereis(h_proc_name()),[c]),
dbg:p(FileCtrlPid,[c]),
@@ -1628,7 +1628,7 @@ tpl([{M,F,A}|Trace]) ->
tpl([]) ->
ok.
-tracer({trace,_,call,{logger_std_h,handle_cast,[Op|_]}},
+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,_,_,_]}},
generated by cgit v1.2.3 (git 2.25.1) at 2024-11-02 17:39:39 +0000