1%%
2%% %CopyrightBegin%
3%%
4%% Copyright Ericsson AB 2017-2018. All Rights Reserved.
5%%
6%% Licensed under the Apache License, Version 2.0 (the "License");
7%% you may not use this file except in compliance with the License.
8%% You may obtain a copy of the License at
9%%
10%%     http://www.apache.org/licenses/LICENSE-2.0
11%%
12%% Unless required by applicable law or agreed to in writing, software
13%% distributed under the License is distributed on an "AS IS" BASIS,
14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15%% See the License for the specific language governing permissions and
16%% limitations under the License.
17%%
18%% %CopyrightEnd%
19%%
20-module(logger_h_common).
21-behaviour(gen_server).
22
23-include("logger_h_common.hrl").
24-include("logger_internal.hrl").
25
26%% API
27-export([filesync/2]).
28
29%% logger_olp callbacks
30-export([init/1, handle_load/2, handle_call/3, handle_cast/2, handle_info/2,
31         terminate/2, code_change/3, notify/2, reset_state/1]).
32
33%% logger callbacks
34-export([log/2, adding_handler/1, removing_handler/1, changing_config/3,
35         filter_config/1]).
36
37%% Library functions for handlers
38-export([error_notify/1]).
39
40-define(OLP_KEYS,[sync_mode_qlen,
41                  drop_mode_qlen,
42                  flush_qlen,
43                  burst_limit_enable,
44                  burst_limit_max_count,
45                  burst_limit_window_time,
46                  overload_kill_enable,
47                  overload_kill_qlen,
48                  overload_kill_mem_size,
49                  overload_kill_restart_after]).
50
51-define(COMMON_KEYS,[filesync_repeat_interval]).
52
53-define(READ_ONLY_KEYS,[olp]).
54
55%%%-----------------------------------------------------------------
56%%% API
57
58%% This function is called by the logger_sup supervisor
59filesync(Module, Name) ->
60    call(Module, Name, filesync).
61
62%%%-----------------------------------------------------------------
63%%% Handler being added
64adding_handler(#{id:=Name,module:=Module}=Config) ->
65    HConfig0 = maps:get(config, Config, #{}),
66    HandlerConfig0 = maps:without(?OLP_KEYS++?COMMON_KEYS,HConfig0),
67    case Module:check_config(Name,set,undefined,HandlerConfig0) of
68        {ok,HandlerConfig} ->
69            ModifiedCommon = maps:with(?COMMON_KEYS,HandlerConfig),
70            CommonConfig0 = maps:with(?COMMON_KEYS,HConfig0),
71            CommonConfig = maps:merge(
72                             maps:merge(get_default_config(), CommonConfig0),
73                             ModifiedCommon),
74            case check_config(CommonConfig) of
75                ok ->
76                    HConfig = maps:merge(CommonConfig,HandlerConfig),
77                    OlpOpts = maps:with(?OLP_KEYS,HConfig0),
78                    start(OlpOpts, Config#{config => HConfig});
79                {error,Faulty} ->
80                    {error,{invalid_config,Module,Faulty}}
81            end;
82        Error ->
83            Error
84    end.
85
86%%%-----------------------------------------------------------------
87%%% Handler being removed
88removing_handler(#{id:=Name, module:=Module, config:=#{olp:=Olp}}) ->
89    case whereis(?name_to_reg_name(Module,Name)) of
90        undefined ->
91            ok;
92        _Pid ->
93            %% We don't want to do supervisor:terminate_child here
94            %% since we need to distinguish this explicit stop from a
95            %% system termination in order to avoid circular attempts
96            %% at removing the handler (implying deadlocks and
97            %% timeouts).
98            %% And we don't need to do supervisor:delete_child, since
99            %% the restart type is temporary, which means that the
100            %% child specification is automatically removed from the
101            %% supervisor when the process dies.
102            _ = logger_olp:stop(Olp),
103            ok
104    end.
105
106%%%-----------------------------------------------------------------
107%%% Updating handler config
108changing_config(SetOrUpdate,
109                #{id:=Name,config:=OldHConfig,module:=Module},
110                NewConfig0) ->
111    NewHConfig0 = maps:get(config, NewConfig0, #{}),
112    NoHandlerKeys = ?OLP_KEYS++?COMMON_KEYS++?READ_ONLY_KEYS,
113    OldHandlerConfig = maps:without(NoHandlerKeys,OldHConfig),
114    NewHandlerConfig0 = maps:without(NoHandlerKeys,NewHConfig0),
115    case Module:check_config(Name, SetOrUpdate,
116                             OldHandlerConfig,NewHandlerConfig0) of
117        {ok, NewHandlerConfig} ->
118            ModifiedCommon = maps:with(?COMMON_KEYS,NewHandlerConfig),
119            NewCommonConfig0 = maps:with(?COMMON_KEYS,NewHConfig0),
120            OldCommonConfig = maps:with(?COMMON_KEYS,OldHConfig),
121            CommonDefault =
122                case SetOrUpdate of
123                    set ->
124                        get_default_config();
125                    update ->
126                        OldCommonConfig
127                end,
128            NewCommonConfig = maps:merge(
129                                maps:merge(CommonDefault,NewCommonConfig0),
130                                ModifiedCommon),
131            case check_config(NewCommonConfig) of
132                ok ->
133                    OlpDefault =
134                        case SetOrUpdate of
135                            set ->
136                                logger_olp:get_default_opts();
137                            update ->
138                                maps:with(?OLP_KEYS,OldHConfig)
139                        end,
140                    Olp = maps:get(olp,OldHConfig),
141                    NewOlpOpts = maps:merge(OlpDefault,
142                                            maps:with(?OLP_KEYS,NewHConfig0)),
143                    case logger_olp:set_opts(Olp,NewOlpOpts) of
144                        ok ->
145                            logger_olp:cast(Olp, {config_changed,
146                                                  NewCommonConfig,
147                                                  NewHandlerConfig}),
148                            ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig),
149                            NewHConfig =
150                                maps:merge(
151                                  maps:merge(
152                                    maps:merge(NewCommonConfig,NewHandlerConfig),
153                                    ReadOnly),
154                                  NewOlpOpts),
155                            NewConfig = NewConfig0#{config=>NewHConfig},
156                            {ok,NewConfig};
157                        Error  ->
158                            Error
159                    end;
160                {error,Faulty} ->
161                    {error,{invalid_config,Module,Faulty}}
162            end;
163        Error ->
164            Error
165    end.
166
167%%%-----------------------------------------------------------------
168%%% Log a string or report
169-spec log(LogEvent, Config) -> ok when
170      LogEvent :: logger:log_event(),
171      Config :: logger:handler_config().
172
173log(LogEvent, Config = #{config := #{olp:=Olp}}) ->
174    %% if the handler has crashed, we must drop this event
175    %% and hope the handler restarts so we can try again
176    true = is_process_alive(logger_olp:get_pid(Olp)),
177    Bin = log_to_binary(LogEvent, Config),
178    logger_olp:load(Olp,Bin).
179
180%%%-----------------------------------------------------------------
181%%% Remove internal fields from configuration
182filter_config(#{config:=HConfig}=Config) ->
183    Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}.
184
185%%%-----------------------------------------------------------------
186%%% Start the handler process
187%%%
188%%% The process must always exist if the handler is registered with
189%%% logger (and must not exist if the handler is not registered).
190%%%
191%%% The handler process is linked to logger_sup, which is part of the
192%%% kernel application's supervision tree.
193start(OlpOpts0, #{id := Name, module:=Module, config:=HConfig} = Config0) ->
194    RegName = ?name_to_reg_name(Module,Name),
195    ChildSpec =
196        #{id       => Name,
197          start    => {logger_olp, start_link, [RegName,?MODULE,
198                                                Config0, OlpOpts0]},
199          restart  => temporary,
200          shutdown => 2000,
201          type     => worker,
202          modules  => [?MODULE]},
203    case supervisor:start_child(logger_sup, ChildSpec) of
204        {ok,Pid,Olp} ->
205            ok = logger_handler_watcher:register_handler(Name,Pid),
206            OlpOpts = logger_olp:get_opts(Olp),
207            {ok,Config0#{config=>(maps:merge(HConfig,OlpOpts))#{olp=>Olp}}};
208        {error,{Reason,Ch}} when is_tuple(Ch), element(1,Ch)==child ->
209            {error,Reason};
210        Error ->
211            Error
212    end.
213
214%%%===================================================================
215%%% gen_server callbacks
216%%%===================================================================
217
218init(#{id := Name, module := Module, config := HConfig}) ->
219    process_flag(trap_exit, true),
220
221    ?init_test_hooks(),
222
223    case Module:init(Name, HConfig) of
224        {ok,HState} ->
225            %% Storing common config in state to avoid copying
226            %% (sending) the config data for each log message
227            CommonConfig = maps:with(?COMMON_KEYS,HConfig),
228            State = CommonConfig#{id => Name,
229                                  module => Module,
230                                  ctrl_sync_count =>
231                                      ?CONTROLLER_SYNC_INTERVAL,
232                                  last_op => sync,
233                                  handler_state => HState},
234            State1 = set_repeated_filesync(State),
235            {ok,State1};
236        Error ->
237            Error
238    end.
239
240%% This is the log event.
241handle_load(Bin, #{id:=Name,
242                   module:=Module,
243                   handler_state:=HandlerState,
244                   ctrl_sync_count := CtrlSync}=State) ->
245    if CtrlSync==0 ->
246            {_,HS1} = Module:write(Name, sync, Bin, HandlerState),
247            State#{handler_state => HS1,
248                   ctrl_sync_count => ?CONTROLLER_SYNC_INTERVAL,
249                   last_op=>write};
250       true ->
251            {_,HS1} = Module:write(Name, async, Bin, HandlerState),
252            State#{handler_state => HS1,
253                   ctrl_sync_count => CtrlSync-1,
254                   last_op=>write}
255    end.
256
257handle_call(filesync, _From, State = #{id := Name,
258                                       module := Module,
259                                       handler_state := HandlerState}) ->
260    {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState),
261    {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}.
262
263%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this
264%% clause gets called repeatedly by the handler. In order to
265%% guarantee that a filesync *always* happens after the last log
266%% event, the repeat operation must be active!
267handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) ->
268    %% This clause handles a race condition which may occur when
269    %% config changes filesync_repeat_interval from an integer value
270    %% to no_repeat.
271    {noreply,State};
272handle_cast(repeated_filesync,
273            State = #{id := Name,
274                      module := Module,
275                      handler_state := HandlerState,
276                      last_op := LastOp}) ->
277    State1 =
278        if LastOp == sync ->
279                State;
280           true ->
281                {_,HS} = Module:filesync(Name, async, HandlerState),
282                State#{handler_state => HS, last_op => sync}
283        end,
284    {noreply,set_repeated_filesync(State1)};
285handle_cast({config_changed, CommonConfig, HConfig},
286            State = #{id := Name,
287                      module := Module,
288                      handler_state := HandlerState,
289                      filesync_repeat_interval := OldFSyncInt}) ->
290    State1 =
291        case maps:get(filesync_repeat_interval,CommonConfig) of
292            OldFSyncInt ->
293                State;
294            FSyncInt ->
295                set_repeated_filesync(
296                  cancel_repeated_filesync(
297                    State#{filesync_repeat_interval=>FSyncInt}))
298        end,
299    HS = try Module:config_changed(Name, HConfig, HandlerState)
300         catch error:undef -> HandlerState
301         end,
302    {noreply, State1#{handler_state => HS}}.
303
304handle_info(Info, #{id := Name, module := Module,
305                    handler_state := HandlerState} = State) ->
306    {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}.
307
308terminate(overloaded=Reason, #{id:=Name}=State) ->
309    _ = log_handler_info(Name,"Handler ~p overloaded and stopping",[Name],State),
310    do_terminate(Reason,State),
311    ConfigResult = logger:get_handler_config(Name),
312    case ConfigResult of
313        {ok,#{module:=Module}=HConfig0} ->
314            spawn(fun() -> logger:remove_handler(Name) end),
315            HConfig = try Module:filter_config(HConfig0)
316                      catch _:_ -> HConfig0
317                      end,
318            {ok,fun() -> logger:add_handler(Name,Module,HConfig) end};
319        Error ->
320            error_notify({Name,restart_impossible,Error}),
321            Error
322    end;
323terminate(Reason, State) ->
324    do_terminate(Reason, State).
325
326do_terminate(Reason, State = #{id := Name,
327                               module := Module,
328                               handler_state := HandlerState}) ->
329    _ = cancel_repeated_filesync(State),
330    _ = Module:terminate(Name, Reason, HandlerState),
331    ok.
332
333code_change(_OldVsn, State, _Extra) ->
334    {ok, State}.
335
336reset_state(#{id:=Name, module:=Module, handler_state:=HandlerState} = State) ->
337    State#{handler_state=>Module:reset_state(Name, HandlerState)}.
338
339%%%-----------------------------------------------------------------
340%%% Internal functions
341call(Module, Name, Op) when is_atom(Name) ->
342    case logger_olp:call(?name_to_reg_name(Module,Name), Op) of
343        {error,busy} -> {error,handler_busy};
344        Other -> Other
345    end;
346call(_, Name, Op) ->
347    {error,{badarg,{Op,[Name]}}}.
348
349notify({mode_change,Mode0,Mode1},#{id:=Name}=State) ->
350    log_handler_info(Name,"Handler ~p switched from  ~p to ~p mode",
351                     [Name,Mode0,Mode1], State);
352notify({flushed,Flushed},#{id:=Name}=State) ->
353    log_handler_info(Name, "Handler ~p flushed ~w log events",
354                     [Name,Flushed], State);
355notify(restart,#{id:=Name}=State) ->
356    log_handler_info(Name, "Handler ~p restarted", [Name], State);
357notify(idle,#{id:=Name,module:=Module,handler_state:=HandlerState}=State) ->
358    {_,HS} = Module:filesync(Name,async,HandlerState),
359    State#{handler_state=>HS, last_op=>sync}.
360
361log_handler_info(Name, Format, Args, #{module:=Module,
362                                       handler_state:=HandlerState}=State) ->
363    Config =
364        case logger:get_handler_config(Name) of
365            {ok,Conf} -> Conf;
366            _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}
367        end,
368    Meta = #{time=>logger:timestamp()},
369    Bin = log_to_binary(#{level => notice,
370                          msg => {Format,Args},
371                          meta => Meta}, Config),
372    {_,HS} = Module:write(Name, async, Bin, HandlerState),
373    State#{handler_state=>HS, last_op=>write}.
374
375%%%-----------------------------------------------------------------
376%%% Convert log data on any form to binary
377-spec log_to_binary(LogEvent,Config) -> LogString when
378      LogEvent :: logger:log_event(),
379      Config :: logger:handler_config(),
380      LogString :: binary().
381log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) ->
382    do_log_to_binary(Log,Config);
383log_to_binary(#{msg:={report,_},meta:=Meta}=Log,Config) ->
384    DefaultReportCb = fun logger:format_otp_report/1,
385    do_log_to_binary(Log#{meta=>Meta#{report_cb=>DefaultReportCb}},Config);
386log_to_binary(Log,Config) ->
387    do_log_to_binary(Log,Config).
388
389do_log_to_binary(Log,Config) ->
390    {Formatter,FormatterConfig} =
391        maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}),
392    String = try_format(Log,Formatter,FormatterConfig),
393    try string_to_binary(String)
394    catch C2:R2:S2 ->
395            ?LOG_INTERNAL(debug,[{formatter_error,Formatter},
396                                 {config,FormatterConfig},
397                                 {log_event,Log},
398                                 {bad_return_value,String},
399                                 {catched,{C2,R2,S2}}]),
400            <<"FORMATTER ERROR: bad return value">>
401    end.
402
403try_format(Log,Formatter,FormatterConfig) ->
404    try Formatter:format(Log,FormatterConfig)
405    catch
406        C:R:S ->
407            ?LOG_INTERNAL(debug,[{formatter_crashed,Formatter},
408                                 {config,FormatterConfig},
409                                 {log_event,Log},
410                                 {reason,
411                                  {C,R,logger:filter_stacktrace(?MODULE,S)}}]),
412            case {?DEFAULT_FORMATTER,#{}} of
413                {Formatter,FormatterConfig} ->
414                    "DEFAULT FORMATTER CRASHED";
415                {DefaultFormatter,DefaultConfig} ->
416                    try_format(Log#{msg=>{"FORMATTER CRASH: ~tp",
417                                          [maps:get(msg,Log)]}},
418                              DefaultFormatter,DefaultConfig)
419            end
420    end.
421
422string_to_binary(String) ->
423    case unicode:characters_to_binary(String) of
424        Binary when is_binary(Binary) ->
425            Binary;
426        Error ->
427            throw(Error)
428    end.
429
430%%%-----------------------------------------------------------------
431%%% Check that the configuration term is valid
432check_config(Config) when is_map(Config) ->
433    check_common_config(maps:to_list(Config)).
434
435check_common_config([{filesync_repeat_interval,NorA}|Config])
436  when is_integer(NorA); NorA == no_repeat ->
437    check_common_config(Config);
438check_common_config([{Key,Value}|_]) ->
439    {error,#{Key=>Value}};
440check_common_config([]) ->
441    ok.
442
443get_default_config() ->
444    #{filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.
445
446set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State)
447  when is_integer(FSyncInt) ->
448    {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast,
449                                  [self(),repeated_filesync]),
450    State#{rep_sync_tref=>TRef};
451set_repeated_filesync(State) ->
452    State.
453
454cancel_repeated_filesync(State) ->
455    case maps:take(rep_sync_tref,State) of
456        {TRef,State1} ->
457            _ = timer:cancel(TRef),
458            State1;
459        error ->
460            State
461    end.
462error_notify(Term) ->
463    ?internal_log(error, Term).
464