%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2017-2018. All Rights Reserved.
%%
%% Licensed under the Apache License, Version 2.0 (the "License");
%% you may not use this file except in compliance with the License.
%% You may obtain a copy of the License at
%%
%% http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing, software
%% distributed under the License is distributed on an "AS IS" BASIS,
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
%% See the License for the specific language governing permissions and
%% limitations under the License.
%%
%% %CopyrightEnd%
%%
-module(logger_h_common).
-behaviour(gen_server).
-include("logger_h_common.hrl").
-include("logger_internal.hrl").
%% API
-export([filesync/2]).
%% logger_olp callbacks
-export([init/1, handle_load/2, handle_call/3, handle_cast/2, handle_info/2,
terminate/2, code_change/3, notify/2, reset_state/1]).
%% 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(OLP_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]).
-define(COMMON_KEYS,[filesync_repeat_interval]).
-define(READ_ONLY_KEYS,[olp]).
%%%-----------------------------------------------------------------
%%% API
%% This function is called by the logger_sup supervisor
filesync(Module, Name) ->
call(Module, Name, filesync).
%%%-----------------------------------------------------------------
%%% Handler being added
adding_handler(#{id:=Name,module:=Module}=Config) ->
HConfig0 = maps:get(config, Config, #{}),
HandlerConfig0 = maps:without(?OLP_KEYS++?COMMON_KEYS,HConfig0),
case Module:check_config(Name,set,undefined,HandlerConfig0) of
{ok,HandlerConfig} ->
ModifiedCommon = maps:with(?COMMON_KEYS,HandlerConfig),
CommonConfig0 = maps:with(?COMMON_KEYS,HConfig0),
CommonConfig = maps:merge(
maps:merge(get_default_config(), CommonConfig0),
ModifiedCommon),
case check_config(CommonConfig) of
ok ->
HConfig = maps:merge(CommonConfig,HandlerConfig),
OlpOpts = maps:with(?OLP_KEYS,HConfig0),
start(OlpOpts, Config#{config => HConfig});
{error,Faulty} ->
{error,{invalid_config,Module,Faulty}}
end;
Error ->
Error
end.
%%%-----------------------------------------------------------------
%%% Handler being removed
removing_handler(#{id:=Name, module:=Module, config:=#{olp:=Olp}}) ->
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.
_ = logger_olp:stop(Olp),
ok
end.
%%%-----------------------------------------------------------------
%%% Updating handler config
changing_config(SetOrUpdate,
#{id:=Name,config:=OldHConfig,module:=Module},
NewConfig0) ->
NewHConfig0 = maps:get(config, NewConfig0, #{}),
NoHandlerKeys = ?OLP_KEYS++?COMMON_KEYS++?READ_ONLY_KEYS,
OldHandlerConfig = maps:without(NoHandlerKeys,OldHConfig),
NewHandlerConfig0 = maps:without(NoHandlerKeys,NewHConfig0),
case Module:check_config(Name, SetOrUpdate,
OldHandlerConfig,NewHandlerConfig0) of
{ok, NewHandlerConfig} ->
ModifiedCommon = maps:with(?COMMON_KEYS,NewHandlerConfig),
NewCommonConfig0 = maps:with(?COMMON_KEYS,NewHConfig0),
OldCommonConfig = maps:with(?COMMON_KEYS,OldHConfig),
CommonDefault =
case SetOrUpdate of
set ->
get_default_config();
update ->
OldCommonConfig
end,
NewCommonConfig = maps:merge(
maps:merge(CommonDefault,NewCommonConfig0),
ModifiedCommon),
case check_config(NewCommonConfig) of
ok ->
OlpDefault =
case SetOrUpdate of
set ->
logger_olp:get_default_opts();
update ->
maps:with(?OLP_KEYS,OldHConfig)
end,
Olp = maps:get(olp,OldHConfig),
NewOlpOpts = maps:merge(OlpDefault,
maps:with(?OLP_KEYS,NewHConfig0)),
case logger_olp:set_opts(Olp,NewOlpOpts) of
ok ->
maybe_set_repeated_filesync(Olp,OldCommonConfig,
NewCommonConfig),
ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig),
NewHConfig =
maps:merge(
maps:merge(
maps:merge(NewCommonConfig,NewHandlerConfig),
ReadOnly),
NewOlpOpts),
NewConfig = NewConfig0#{config=>NewHConfig},
{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 = #{config := #{olp:=Olp}}) ->
%% if the handler has crashed, we must drop this event
%% and hope the handler restarts so we can try again
true = is_process_alive(logger_olp:get_pid(Olp)),
Bin = log_to_binary(LogEvent, Config),
logger_olp:load(Olp,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(OlpOpts0, #{id := Name, module:=Module, config:=HConfig} = Config0) ->
RegName = ?name_to_reg_name(Module,Name),
ChildSpec =
#{id => Name,
start => {logger_olp, start_link, [RegName,?MODULE,
Config0, OlpOpts0]},
restart => temporary,
shutdown => 2000,
type => worker,
modules => [?MODULE]},
case supervisor:start_child(logger_sup, ChildSpec) of
{ok,Pid,Olp} ->
ok = logger_handler_watcher:register_handler(Name,Pid),
OlpOpts = logger_olp:get_opts(Olp),
{ok,Config0#{config=>(maps:merge(HConfig,OlpOpts))#{olp=>Olp}}};
{error,{Reason,Ch}} when is_tuple(Ch), element(1,Ch)==child ->
{error,Reason};
Error ->
Error
end.
%%%===================================================================
%%% gen_server callbacks
%%%===================================================================
init(#{id := Name, module := Module, config := HConfig}) ->
process_flag(trap_exit, true),
?init_test_hooks(),
case Module:init(Name, HConfig) of
{ok,HState} ->
%% Storing common config in state to avoid copying
%% (sending) the config data for each log message
CommonConfig = maps:with(?COMMON_KEYS,HConfig),
State = CommonConfig#{id => Name,
module => Module,
ctrl_sync_count =>
?CONTROLLER_SYNC_INTERVAL,
last_op => sync,
handler_state => HState},
State1 = set_repeated_filesync(State),
{ok,State1};
Error ->
Error
end.
%% This is the log event.
handle_load(Bin, #{id:=Name,
module:=Module,
handler_state:=HandlerState,
ctrl_sync_count := CtrlSync}=State) ->
if CtrlSync==0 ->
{_,HS1} = Module:write(Name, sync, Bin, HandlerState),
State#{handler_state => HS1,
ctrl_sync_count => ?CONTROLLER_SYNC_INTERVAL,
last_op=>write};
true ->
{_,HS1} = Module:write(Name, async, Bin, HandlerState),
State#{handler_state => HS1,
ctrl_sync_count => CtrlSync-1,
last_op=>write}
end.
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}}.
%% 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_cast({set_repeated_filesync,FSyncInt},State) ->
State1 = State#{filesync_repeat_interval=>FSyncInt},
State2 = set_repeated_filesync(cancel_repeated_filesync(State1)),
{noreply, State2}.
handle_info(Info, #{id := Name, module := Module,
handler_state := HandlerState} = State) ->
{noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}.
terminate(overloaded=Reason, #{id:=Name}=State) ->
_ = log_handler_info(Name,"Handler ~p overloaded and stopping",[Name],State),
do_terminate(Reason,State),
ConfigResult = logger:get_handler_config(Name),
case ConfigResult of
{ok,#{module:=Module}=HConfig0} ->
spawn(fun() -> logger:remove_handler(Name) end),
HConfig = try Module:filter_config(HConfig0)
catch _:_ -> HConfig0
end,
{ok,fun() -> logger:add_handler(Name,Module,HConfig) end};
Error ->
error_notify({Name,restart_impossible,Error}),
Error
end;
terminate(Reason, State) ->
do_terminate(Reason, State).
do_terminate(Reason, State = #{id := Name,
module := Module,
handler_state := HandlerState}) ->
_ = cancel_repeated_filesync(State),
_ = Module:terminate(Name, Reason, HandlerState),
ok.
code_change(_OldVsn, State, _Extra) ->
{ok, State}.
reset_state(#{id:=Name, module:=Module, handler_state:=HandlerState} = State) ->
State#{handler_state=>Module:reset_state(Name, HandlerState)}.
%%%-----------------------------------------------------------------
%%% Internal functions
call(Module, Name, Op) when is_atom(Name) ->
case logger_olp:call(?name_to_reg_name(Module,Name), Op) of
{error,busy} -> {error,handler_busy};
Other -> Other
end;
call(_, Name, Op) ->
{error,{badarg,{Op,[Name]}}}.
notify({mode_change,Mode0,Mode1},#{id:=Name}=State) ->
log_handler_info(Name,"Handler ~p switched from ~p to ~p mode",
[Name,Mode0,Mode1], State);
notify({flushed,Flushed},#{id:=Name}=State) ->
log_handler_info(Name, "Handler ~p flushed ~w log events",
[Name,Flushed], State);
notify(restart,#{id:=Name}=State) ->
log_handler_info(Name, "Handler ~p restarted", [Name], State);
notify(idle,#{id:=Name,module:=Module,handler_state:=HandlerState}=State) ->
{_,HS} = Module:filesync(Name,async,HandlerState),
State#{handler_state=>HS, last_op=>sync}.
log_handler_info(Name, Format, Args, #{module:=Module,
handler_state:=HandlerState}=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 = log_to_binary(#{level => notice,
msg => {Format,Args},
meta => Meta}, Config),
{_,HS} = Module:write(Name, async, Bin, HandlerState),
State#{handler_state=>HS, last_op=>write}.
%%%-----------------------------------------------------------------
%%% Convert log data on any form to binary
-spec log_to_binary(LogEvent,Config) -> LogString when
LogEvent :: logger:log_event(),
Config :: logger:handler_config(),
LogString :: binary().
log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) ->
do_log_to_binary(Log,Config);
log_to_binary(#{msg:={report,_},meta:=Meta}=Log,Config) ->
DefaultReportCb = fun logger:format_otp_report/1,
do_log_to_binary(Log#{meta=>Meta#{report_cb=>DefaultReportCb}},Config);
log_to_binary(Log,Config) ->
do_log_to_binary(Log,Config).
do_log_to_binary(Log,Config) ->
{Formatter,FormatterConfig} =
maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}),
String = try_format(Log,Formatter,FormatterConfig),
try string_to_binary(String)
catch C2:R2:S2 ->
?LOG_INTERNAL(debug,[{formatter_error,Formatter},
{config,FormatterConfig},
{log_event,Log},
{bad_return_value,String},
{catched,{C2,R2,S2}}]),
<<"FORMATTER ERROR: bad return value">>
end.
try_format(Log,Formatter,FormatterConfig) ->
try Formatter:format(Log,FormatterConfig)
catch
C:R:S ->
?LOG_INTERNAL(debug,[{formatter_crashed,Formatter},
{config,FormatterConfig},
{log_event,Log},
{reason,
{C,R,logger:filter_stacktrace(?MODULE,S)}}]),
case {?DEFAULT_FORMATTER,#{}} of
{Formatter,FormatterConfig} ->
"DEFAULT FORMATTER CRASHED";
{DefaultFormatter,DefaultConfig} ->
try_format(Log#{msg=>{"FORMATTER CRASH: ~tp",
[maps:get(msg,Log)]}},
DefaultFormatter,DefaultConfig)
end
end.
string_to_binary(String) ->
case unicode:characters_to_binary(String) of
Binary when is_binary(Binary) ->
Binary;
Error ->
throw(Error)
end.
%%%-----------------------------------------------------------------
%%% Check that the configuration term is valid
check_config(Config) when is_map(Config) ->
check_common_config(maps:to_list(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() ->
#{filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.
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.
error_notify(Term) ->
?internal_log(error, Term).
maybe_set_repeated_filesync(_Olp,
#{filesync_repeat_interval:=FSyncInt},
#{filesync_repeat_interval:=FSyncInt}) ->
ok;
maybe_set_repeated_filesync(Olp,_,#{filesync_repeat_interval:=FSyncInt}) ->
logger_olp:cast(Olp,{set_repeated_filesync,FSyncInt}).
