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