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_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,Log,[{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\n">> 401 end. 402 403try_format(Log,Formatter,FormatterConfig) -> 404 try Formatter:format(Log,FormatterConfig) 405 catch 406 C:R:S -> 407 ?LOG_INTERNAL(debug,Log,[{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\n"; 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