1%%
2%% %CopyrightBegin%
3%%
4%% Copyright Ericsson AB 2017-2020. 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_server).
21
22-behaviour(gen_server).
23
24%% API
25-export([start_link/0, add_handler/3, remove_handler/1,
26         add_filter/2, remove_filter/2,
27         set_module_level/2, unset_module_level/0,
28         unset_module_level/1,
29         set_config/2, set_config/3,
30         update_config/2, update_config/3,
31         update_formatter_config/2]).
32
33%% Helper
34-export([diff_maps/2,do_internal_log/4]).
35
36%% gen_server callbacks
37-export([init/1, handle_call/3, handle_cast/2, handle_info/2,
38         terminate/2]).
39
40-include("logger_internal.hrl").
41
42-define(SERVER, logger).
43-define(LOGGER_SERVER_TAG, '$logger_cb_process').
44
45-record(state, {tid, async_req, async_req_queue, remote_logger}).
46
47%%%===================================================================
48%%% API
49%%%===================================================================
50
51start_link() ->
52    gen_server:start_link({local, ?SERVER}, ?MODULE, [], []).
53
54add_handler(Id,Module,Config0) ->
55    try {check_id(Id),check_mod(Module)} of
56        {ok,ok} ->
57            case sanity_check(Id,Config0) of
58                ok ->
59                    Default = default_config(Id,Module),
60                    Config = maps:merge(Default,Config0),
61                    call({add_handler,Id,Module,Config});
62                Error ->
63                    Error
64            end
65    catch throw:Error ->
66            {error,Error}
67    end.
68
69remove_handler(HandlerId) ->
70    call({remove_handler,HandlerId}).
71
72add_filter(Owner,Filter) ->
73    case sanity_check(Owner,filters,[Filter]) of
74        ok -> call({add_filter,Owner,Filter});
75        Error -> Error
76    end.
77
78remove_filter(Owner,FilterId) ->
79    call({remove_filter,Owner,FilterId}).
80
81set_module_level(Modules,Level) when is_list(Modules) ->
82    case lists:all(fun(M) -> is_atom(M) end,Modules) of
83        true ->
84            case sanity_check(primary,level,Level) of
85                ok -> call({set_module_level,Modules,Level});
86                Error -> Error
87            end;
88        false ->
89            {error,{not_a_list_of_modules,Modules}}
90    end;
91set_module_level(Modules,_) ->
92    {error,{not_a_list_of_modules,Modules}}.
93
94unset_module_level() ->
95    call({unset_module_level,all}).
96
97unset_module_level(Modules) when is_list(Modules) ->
98    case lists:all(fun(M) -> is_atom(M) end,Modules) of
99        true ->
100            call({unset_module_level,Modules});
101        false ->
102            {error,{not_a_list_of_modules,Modules}}
103    end;
104unset_module_level(Modules) ->
105    {error,{not_a_list_of_modules,Modules}}.
106
107set_config(Owner,Key,Value) ->
108    case sanity_check(Owner,Key,Value) of
109        ok ->
110            call({change_config,set,Owner,Key,Value});
111        Error ->
112            Error
113    end.
114
115set_config(Owner,Config) ->
116    case sanity_check(Owner,Config) of
117        ok ->
118            call({change_config,set,Owner,Config});
119        Error ->
120            Error
121    end.
122
123update_config(Owner,Key,Value) ->
124    case sanity_check(Owner,Key,Value) of
125        ok ->
126            call({change_config,update,Owner,Key,Value});
127        Error ->
128            Error
129    end.
130
131update_config(Owner, Config) ->
132    case sanity_check(Owner,Config) of
133        ok ->
134            call({change_config,update,Owner,Config});
135        Error ->
136            Error
137    end.
138
139update_formatter_config(HandlerId, FormatterConfig)
140  when is_map(FormatterConfig) ->
141    call({update_formatter_config,HandlerId,FormatterConfig});
142update_formatter_config(_HandlerId, FormatterConfig) ->
143    {error,{invalid_formatter_config,FormatterConfig}}.
144
145
146%%%===================================================================
147%%% gen_server callbacks
148%%%===================================================================
149
150init([]) ->
151    process_flag(trap_exit, true),
152    put(?LOGGER_SERVER_TAG,true),
153    Tid = logger_config:new(?LOGGER_TABLE),
154    %% Store initial proxy config. logger_proxy reads config from here at startup.
155    logger_config:create(Tid,proxy,logger_proxy:get_default_config()),
156    PrimaryConfig = maps:merge(default_config(primary),
157                              #{handlers=>[simple]}),
158    logger_config:create(Tid,primary,PrimaryConfig),
159    SimpleConfig0 = maps:merge(default_config(simple,logger_simple_h),
160                               #{filter_default=>stop,
161                                 filters=>?DEFAULT_HANDLER_FILTERS}),
162    %% If this fails, then the node should crash
163    {ok,SimpleConfig} = logger_simple_h:adding_handler(SimpleConfig0),
164    logger_config:create(Tid,simple,SimpleConfig),
165    {ok, #state{tid=Tid, async_req_queue = queue:new()}}.
166
167handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) ->
168    case logger_config:exist(Tid,Id) of
169        true ->
170            {reply,{error,{already_exist,Id}},State};
171        false ->
172            call_h_async(
173              fun() ->
174                      %% inform the handler
175                      call_h(Module,adding_handler,[HConfig],{ok,HConfig})
176              end,
177              fun({ok,HConfig1}) ->
178                      %% We know that the call_h would have loaded the module
179                      %% if it existed, so it is safe here to call function_exported
180                      %% to find out if this is a valid handler
181                      case erlang:function_exported(Module, log, 2) of
182                          true ->
183                              logger_config:create(Tid,Id,HConfig1),
184                              {ok,Config} = logger_config:get(Tid,primary),
185                              Handlers = maps:get(handlers,Config,[]),
186                              logger_config:set(Tid,primary,
187                                                Config#{handlers=>[Id|Handlers]});
188                          false ->
189                              {error,{invalid_handler,
190                                      {function_not_exported,
191                                       {Module,log,2}}}}
192                      end;
193                 ({error,HReason}) ->
194                      {error,{handler_not_added,HReason}}
195              end,From,State)
196    end;
197handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) ->
198    case logger_config:get(Tid,HandlerId) of
199        {ok,#{module:=Module}=HConfig} ->
200            {ok,Config} = logger_config:get(Tid,primary),
201            Handlers0 = maps:get(handlers,Config,[]),
202            Handlers = lists:delete(HandlerId,Handlers0),
203            call_h_async(
204              fun() ->
205                      %% inform the handler
206                      call_h(Module,removing_handler,[HConfig],ok)
207              end,
208              fun(_Res) ->
209                      logger_config:set(Tid,primary,Config#{handlers=>Handlers}),
210                      logger_config:delete(Tid,HandlerId),
211                      ok
212              end,From,State);
213        _ ->
214            {reply,{error,{not_found,HandlerId}},State}
215    end;
216handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) ->
217    Reply = do_add_filter(Tid,Id,Filter),
218    {reply,Reply,State};
219handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) ->
220    Reply = do_remove_filter(Tid,Id,FilterId),
221    {reply,Reply,State};
222handle_call({change_config,SetOrUpd,proxy,Config0},_From,#state{tid=Tid}=State) ->
223    Default =
224        case SetOrUpd of
225            set ->
226                logger_proxy:get_default_config();
227            update ->
228                {ok,OldConfig} = logger_config:get(Tid,proxy),
229                OldConfig
230        end,
231    Config = maps:merge(Default,Config0),
232    Reply =
233        case logger_olp:set_opts(logger_proxy,Config) of
234            ok ->
235                logger_config:set(Tid,proxy,Config);
236            Error ->
237                Error
238        end,
239    {reply,Reply,State};
240handle_call({change_config,SetOrUpd,primary,Config0}, _From,
241            #state{tid=Tid}=State) ->
242    {ok,#{handlers:=Handlers}=OldConfig} = logger_config:get(Tid,primary),
243    Default =
244        case SetOrUpd of
245            set -> default_config(primary);
246            update -> OldConfig
247        end,
248    Config = maps:merge(Default,Config0),
249    Reply = logger_config:set(Tid,primary,Config#{handlers=>Handlers}),
250    {reply,Reply,State};
251handle_call({change_config,_SetOrUpd,primary,Key,Value}, _From,
252            #state{tid=Tid}=State) ->
253    {ok,OldConfig} = logger_config:get(Tid,primary),
254    Reply = logger_config:set(Tid,primary,OldConfig#{Key=>Value}),
255    {reply,Reply,State};
256handle_call({change_config,SetOrUpd,HandlerId,Config0}, From,
257            #state{tid=Tid}=State) ->
258    case logger_config:get(Tid,HandlerId) of
259        {ok,#{module:=Module}=OldConfig} ->
260            Default =
261                case SetOrUpd of
262                    set -> default_config(HandlerId,Module);
263                    update -> OldConfig
264                end,
265            Config = maps:merge(Default,Config0),
266            case check_config_change(OldConfig,Config) of
267                ok ->
268                    call_h_async(
269                      fun() ->
270                              call_h(Module,changing_config,
271                                     [SetOrUpd,OldConfig,Config],
272                                     {ok,Config})
273                      end,
274                      fun({ok,Config1}) ->
275                              logger_config:set(Tid,HandlerId,Config1);
276                         (Error) ->
277                              Error
278                      end,From,State);
279                Error ->
280                    {reply,Error,State}
281            end;
282        _ ->
283            {reply,{error,{not_found,HandlerId}},State}
284    end;
285handle_call({change_config,SetOrUpd,HandlerId,Key,Value}, From,
286            #state{tid=Tid}=State) ->
287    case logger_config:get(Tid,HandlerId) of
288        {ok,#{module:=Module}=OldConfig} ->
289            Config = OldConfig#{Key=>Value},
290            case check_config_change(OldConfig,Config) of
291                ok ->
292                    call_h_async(
293                      fun() ->
294                              call_h(Module,changing_config,
295                                     [SetOrUpd,OldConfig,Config],
296                                     {ok,Config})
297                      end,
298                      fun({ok,Config1}) ->
299                              logger_config:set(Tid,HandlerId,Config1);
300                         (Error) ->
301                              Error
302                      end,From,State);
303                Error ->
304                    {reply,Error,State}
305            end;
306        _ ->
307            {reply,{error,{not_found,HandlerId}},State}
308    end;
309handle_call({update_formatter_config,HandlerId,NewFConfig},_From,
310            #state{tid=Tid}=State) ->
311    Reply =
312        case logger_config:get(Tid,HandlerId) of
313            {ok,#{formatter:={FMod,OldFConfig}}=Config} ->
314                try
315                    FConfig = maps:merge(OldFConfig,NewFConfig),
316                    check_formatter({FMod,FConfig}),
317                    logger_config:set(Tid,HandlerId,
318                                      Config#{formatter=>{FMod,FConfig}})
319                catch throw:Reason -> {error,Reason}
320                end;
321            _ ->
322            {error,{not_found,HandlerId}}
323        end,
324    {reply,Reply,State};
325handle_call({set_module_level,Modules,Level}, _From, State) ->
326    Reply = logger_config:set_module_level(Modules,Level),
327    {reply,Reply,State};
328handle_call({unset_module_level,Modules}, _From, State) ->
329    Reply = logger_config:unset_module_level(Modules),
330    {reply,Reply,State}.
331
332handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) ->
333    call_h_reply(Reply,State).
334
335%% Interface for those who can't call the API - e.g. the emulator, or
336%% places related to code loading.
337%%
338%% This can also be log events from remote nodes which are sent from
339%% logger.erl when the group leader of the client process is on a
340%% same node as the client process itself.
341handle_info({log,Level,Format,Args,Meta}, State) ->
342    logger:log(Level,Format,Args,Meta),
343    {noreply, State};
344handle_info({log,Level,Report,Meta}, State) ->
345    logger:log(Level,Report,Meta),
346    {noreply, State};
347handle_info({Ref,_Reply},State) when is_reference(Ref) ->
348    %% Assuming this is a timed-out gen_server reply - ignoring
349    {noreply, State};
350handle_info({'DOWN',_Ref,_Proc,_Pid,_Reason} = Down,State) ->
351    call_h_reply(Down,State);
352handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' ->
353    %% The simple handler will send an 'EXIT' message when it is replaced
354    %% We may as well ignore all 'EXIT' messages that we get
355    ?LOG_INTERNAL(debug,
356                  #{},
357                  [{logger,got_unexpected_message},
358                   {process,?SERVER},
359                   {message,Unexpected}]),
360    {noreply,State};
361handle_info(Unexpected,State) ->
362    ?LOG_INTERNAL(info,
363                  #{},
364                  [{logger,got_unexpected_message},
365                   {process,?SERVER},
366                   {message,Unexpected}]),
367    {noreply,State}.
368
369terminate(_Reason, _State) ->
370    ok.
371
372%%%===================================================================
373%%% Internal functions
374%%%===================================================================
375call(Request) when is_tuple(Request) ->
376    Action = element(1,Request),
377    case get(?LOGGER_SERVER_TAG) of
378        true when
379              Action == add_handler; Action == remove_handler;
380              Action == add_filter; Action == remove_filter;
381              Action == change_config ->
382            {error,{attempting_syncronous_call_to_self,Request}};
383        _ ->
384            gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT)
385    end.
386
387
388do_add_filter(Tid,Id,{FId,_} = Filter) ->
389    case logger_config:get(Tid,Id) of
390        {ok,Config} ->
391            Filters = maps:get(filters,Config,[]),
392            case lists:keymember(FId,1,Filters) of
393                true ->
394                    {error,{already_exist,FId}};
395                false ->
396                    logger_config:set(Tid,Id,Config#{filters=>[Filter|Filters]})
397            end;
398        Error ->
399            Error
400    end.
401
402do_remove_filter(Tid,Id,FilterId) ->
403    case logger_config:get(Tid,Id) of
404        {ok,Config} ->
405            Filters0 = maps:get(filters,Config,[]),
406            case lists:keytake(FilterId,1,Filters0) of
407                {value,_,Filters} ->
408                    logger_config:set(Tid,Id,Config#{filters=>Filters});
409                false ->
410                    {error,{not_found,FilterId}}
411            end;
412        Error ->
413            Error
414    end.
415
416default_config(primary) ->
417    #{level=>notice,
418      filters=>[],
419      filter_default=>log};
420default_config(Id) ->
421    #{id=>Id,
422      level=>all,
423      filters=>[],
424      filter_default=>log,
425      formatter=>{?DEFAULT_FORMATTER,#{}}}.
426default_config(Id,Module) ->
427    (default_config(Id))#{module=>Module}.
428
429sanity_check(Owner,Key,Value) ->
430    sanity_check_1(Owner,[{Key,Value}]).
431
432sanity_check(Owner,Config) when is_map(Config) ->
433    sanity_check_1(Owner,maps:to_list(Config));
434sanity_check(_,Config) ->
435    {error,{invalid_config,Config}}.
436
437sanity_check_1(proxy,_Config) ->
438    ok; % Details are checked by logger_olp:set_opts/2
439sanity_check_1(Owner,Config) when is_list(Config) ->
440    try
441        Type = get_type(Owner),
442        check_config(Type,Config)
443    catch throw:Error -> {error,Error}
444    end.
445
446get_type(primary) ->
447    primary;
448get_type(Id) ->
449    check_id(Id),
450    handler.
451
452check_config(Owner,[{level,Level}|Config]) ->
453    check_level(Level),
454    check_config(Owner,Config);
455check_config(Owner,[{filters,Filters}|Config]) ->
456    check_filters(Filters),
457    check_config(Owner,Config);
458check_config(Owner,[{filter_default,FD}|Config]) ->
459    check_filter_default(FD),
460    check_config(Owner,Config);
461check_config(handler,[{formatter,Formatter}|Config]) ->
462    check_formatter(Formatter),
463    check_config(handler,Config);
464check_config(primary,[C|_]) ->
465    throw({invalid_primary_config,C});
466check_config(handler,[{_,_}|Config]) ->
467    %% Arbitrary config elements are allowed for handlers
468    check_config(handler,Config);
469check_config(_,[]) ->
470    ok.
471
472check_id(Id) when is_atom(Id) ->
473    ok;
474check_id(Id) ->
475    throw({invalid_id,Id}).
476
477check_mod(Mod) when is_atom(Mod) ->
478    ok;
479check_mod(Mod) ->
480    throw({invalid_module,Mod}).
481
482check_level(Level) ->
483    case lists:member(Level,?LEVELS) of
484        true ->
485            ok;
486        false ->
487            throw({invalid_level,Level})
488    end.
489
490check_filters([{Id,{Fun,_Args}}|Filters]) when is_atom(Id), is_function(Fun,2) ->
491    check_filters(Filters);
492check_filters([Filter|_]) ->
493    throw({invalid_filter,Filter});
494check_filters([]) ->
495    ok;
496check_filters(Filters) ->
497    throw({invalid_filters,Filters}).
498
499check_filter_default(FD) when FD==stop; FD==log ->
500    ok;
501check_filter_default(FD) ->
502    throw({invalid_filter_default,FD}).
503
504check_formatter({Mod,Config}) ->
505    check_mod(Mod),
506    try Mod:check_config(Config) of
507        ok -> ok;
508        {error,Error} -> throw(Error)
509    catch
510        C:R:S ->
511            case {C,R,S} of
512                {error,undef,[{Mod,check_config,[Config],_}|_]} ->
513                    ok;
514                _ ->
515                    throw({callback_crashed,
516                           {C,R,logger:filter_stacktrace(?MODULE,S)}})
517            end
518    end;
519check_formatter(Formatter) ->
520    throw({invalid_formatter,Formatter}).
521
522%% When changing configuration for a handler, the id and module fields
523%% can not be changed.
524check_config_change(#{id:=Id,module:=Module},#{id:=Id,module:=Module}) ->
525    ok;
526check_config_change(OldConfig,NewConfig) ->
527    {Old,New} = logger_server:diff_maps(maps:with([id,module],OldConfig),
528                                        maps:with([id,module],NewConfig)),
529    {error,{illegal_config_change,Old,New}}.
530
531call_h(Module, Function, Args, DefRet) ->
532    %% Not calling code:ensure_loaded + erlang:function_exported here,
533    %% since in some rare terminal cases, the code_server might not
534    %% exist and we'll get a deadlock in removing the handler.
535    try apply(Module, Function, Args)
536    catch
537        C:R:S ->
538            case {C,R,S} of
539                {error,undef,[{Module,Function=changing_config,Args,_}|_]}
540                  when length(Args)=:=3 ->
541                    %% Backwards compatible call, if changing_config/3
542                    %% did not exist.
543                    call_h(Module, Function, tl(Args), DefRet);
544                {error,undef,[{Module,Function,Args,_}|_]} ->
545                    DefRet;
546                _ ->
547                    ST = logger:filter_stacktrace(?MODULE,S),
548                    ?LOG_INTERNAL(error,
549                                  #{},
550                                  [{logger,callback_crashed},
551                                   {process,?SERVER},
552                                   {reason,{C,R,ST}}]),
553                    {error,{callback_crashed,{C,R,ST}}}
554            end
555    end.
556
557%% There are all sort of API functions that can cause deadlocks if called
558%% from the handler callbacks. So we spawn a process that does the request
559%% for the logger_server. There are still APIs that will cause problems,
560%% namely logger:add_handler
561call_h_async(AsyncFun,PostFun,From,#state{ async_req = undefined } = State) ->
562    Parent = self(),
563    {Pid, Ref} = spawn_monitor(
564                    fun() ->
565                            put(?LOGGER_SERVER_TAG,true),
566                            receive Ref -> Ref end,
567                            gen_server:cast(Parent, {async_req_reply, Ref, AsyncFun()})
568                    end),
569    Pid ! Ref,
570    {noreply,State#state{ async_req = {Ref,PostFun,From} }};
571call_h_async(AsyncFun,PostFun,From,#state{ async_req_queue = Q } = State) ->
572    {noreply,State#state{ async_req_queue = queue:in({AsyncFun,PostFun,From},Q) }}.
573
574call_h_reply({async_req_reply,Ref,Reply},
575              #state{ async_req = {Ref,PostFun,From}, async_req_queue = Q} = State) ->
576    erlang:demonitor(Ref,[flush]),
577    _ = gen_server:reply(From, PostFun(Reply)),
578    {Value,NewQ} = queue:out(Q),
579    NewState = State#state{ async_req = undefined,
580                            async_req_queue = NewQ },
581    case Value of
582        {value,{AsyncFun,NPostFun,NFrom}} ->
583            call_h_async(AsyncFun,NPostFun,NFrom,NewState);
584        empty ->
585            {noreply,NewState}
586    end;
587call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_From}} = State) ->
588    %% This clause should only be triggered if someone explicitly sends an exit signal
589    %% to the spawned process. It is only here to make sure that the logger_server does
590    %% not deadlock if that happens.
591    ?LOG_INTERNAL(error,
592                  #{},
593                  [{logger,process_exited},
594                   {process,Pid},
595                   {reason,Reason}]),
596    call_h_reply(
597      {async_req_reply,Ref,{error,{logger_process_exited,Pid,Reason}}},
598      State);
599call_h_reply(Unexpected,State) ->
600    ?LOG_INTERNAL(info,
601                  #{},
602                  [{logger,got_unexpected_message},
603                   {process,?SERVER},
604                   {message,Unexpected}]),
605    {noreply,State}.
606
607%% Return two maps containing only the fields that differ.
608diff_maps(M1,M2) ->
609    diffs(lists:sort(maps:to_list(M1)),lists:sort(maps:to_list(M2)),#{},#{}).
610
611diffs([H|T1],[H|T2],D1,D2) ->
612    diffs(T1,T2,D1,D2);
613diffs([{K,V1}|T1],[{K,V2}|T2],D1,D2) ->
614    diffs(T1,T2,D1#{K=>V1},D2#{K=>V2});
615diffs([],[],D1,D2) ->
616    {D1,D2}.
617
618do_internal_log(Level,Location,Log,[Report] = Data) ->
619    do_internal_log(Level,Location,Log,Data,{report,Report});
620do_internal_log(Level,Location,Log,[Fmt,Args] = Data) ->
621    do_internal_log(Level,Location,Log,Data,{Fmt,Args}).
622do_internal_log(Level,Location,Log,Data,Msg) ->
623    Meta = logger:add_default_metadata(maps:merge(Location,maps:get(meta,Log,#{}))),
624    %% Spawn these to avoid deadlocks
625    case Log of
626        #{ meta := #{ internal_log_event := true } } ->
627            _ = spawn(logger_simple_h,log,[#{level=>Level,msg=>Msg,meta=>Meta},#{}]);
628        _ ->
629            _ = spawn(logger,macro_log,[Location,Level|Data]++
630                          [Meta#{internal_log_event=>true}])
631    end.
632