diff options
author | Siri Hansen <[email protected]> | 2018-06-12 14:06:46 +0200 |
---|---|---|
committer | GitHub <[email protected]> | 2018-06-12 14:06:46 +0200 |
commit | 465d2849ed0d832577a25a52f0717ec5f7eb94bd (patch) | |
tree | 490304495c0562d34dc4fb7415a64deafd25f470 /lib/kernel/src | |
parent | 0f752d6e9cb447552673bddebccab31539e55358 (diff) | |
parent | 8ae3b6289f25e6c283be5b0d67cd5f6c4434b6e2 (diff) | |
download | otp-465d2849ed0d832577a25a52f0717ec5f7eb94bd.tar.gz otp-465d2849ed0d832577a25a52f0717ec5f7eb94bd.tar.bz2 otp-465d2849ed0d832577a25a52f0717ec5f7eb94bd.zip |
Merge pull request #1835 from sirihansen/siri/logger-fix
Diffstat (limited to 'lib/kernel/src')
-rw-r--r-- | lib/kernel/src/application_controller.erl | 16 | ||||
-rw-r--r-- | lib/kernel/src/error_logger.erl | 77 | ||||
-rw-r--r-- | lib/kernel/src/kernel.app.src | 5 | ||||
-rw-r--r-- | lib/kernel/src/logger.erl | 279 | ||||
-rw-r--r-- | lib/kernel/src/logger_backend.erl | 4 | ||||
-rw-r--r-- | lib/kernel/src/logger_config.erl | 46 | ||||
-rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 412 | ||||
-rw-r--r-- | lib/kernel/src/logger_formatter.erl | 129 | ||||
-rw-r--r-- | lib/kernel/src/logger_h_common.erl | 165 | ||||
-rw-r--r-- | lib/kernel/src/logger_h_common.hrl | 55 | ||||
-rw-r--r-- | lib/kernel/src/logger_internal.hrl | 15 | ||||
-rw-r--r-- | lib/kernel/src/logger_server.erl | 95 | ||||
-rw-r--r-- | lib/kernel/src/logger_std_h.erl | 348 |
13 files changed, 888 insertions, 758 deletions
diff --git a/lib/kernel/src/application_controller.erl b/lib/kernel/src/application_controller.erl index 6906ad0d6e..0dad6ae935 100644 --- a/lib/kernel/src/application_controller.erl +++ b/lib/kernel/src/application_controller.erl @@ -1914,19 +1914,19 @@ info_started(Name, Node) -> ?LOG_INFO(#{label=>{application_controller,progress}, report=>[{application, Name}, {started_at, Node}]}, - #{domain=>[beam,erlang,otp,sasl], + #{domain=>[otp,sasl], report_cb=>fun logger:format_otp_report/1, logger_formatter=>#{title=>"PROGRESS REPORT"}, error_logger=>#{tag=>info_report,type=>progress}}). info_exited(Name, Reason, Type) -> - ?LOG_INFO(#{label=>{application_controller,exit}, - report=>[{application, Name}, - {exited, Reason}, - {type, Type}]}, - #{domain=>[beam,erlang,otp], - report_cb=>fun logger:format_otp_report/1, - error_logger=>#{tag=>info_report,type=>std_info}}). + ?LOG_NOTICE(#{label=>{application_controller,exit}, + report=>[{application, Name}, + {exited, Reason}, + {type, Type}]}, + #{domain=>[otp], + report_cb=>fun logger:format_otp_report/1, + error_logger=>#{tag=>info_report,type=>std_info}}). %%----------------------------------------------------------------- %% Reply to all processes waiting this application to be started. diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index b3957d0c7e..918a915729 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -101,8 +101,8 @@ stop() -> %%%----------------------------------------------------------------- %%% Callbacks for logger --spec adding_handler(logger:config()) -> - {ok,logger:config()} | {error,term()}. +-spec adding_handler(logger:handler_config()) -> + {ok,logger:handler_config()} | {error,term()}. adding_handler(#{id:=?MODULE}=Config) -> case start() of ok -> @@ -111,12 +111,12 @@ adding_handler(#{id:=?MODULE}=Config) -> Error end. --spec removing_handler(logger:config()) -> ok. +-spec removing_handler(logger:handler_config()) -> ok. removing_handler(#{id:=?MODULE}) -> stop(), ok. --spec log(logger:log_event(),logger:config()) -> ok. +-spec log(logger:log_event(),logger:handler_config()) -> ok. log(#{level:=Level,msg:=Msg,meta:=Meta},_Config) -> do_log(Level,Msg,Meta). @@ -169,16 +169,25 @@ do_log(_Level,_Msg,_Meta) -> -spec notify(logger:level(), msg_tag(), any(), any(), map()) -> 'ok'. notify(Level,Tag0,FormatOrType0,ArgsOrReport,#{pid:=Pid0,gl:=GL,?MODULE:=My}) -> - Tag = fix_warning_tag(Level,Tag0), + {Tag,FormatOrType} = maybe_map_warnings(Level,Tag0,FormatOrType0), Pid = case maps:get(emulator,My,false) of true -> emulator; _ -> Pid0 end, - FormatOrType = fix_warning_type(Level,FormatOrType0), gen_event:notify(?MODULE,{Tag,GL,{Pid,FormatOrType,ArgsOrReport}}). -%% This is to fix the case when the client has explicitly added the -%% error logger tag and type in metadata, and not checked the warning map. +%% For backwards compatibility with really old even handlers, check +%% the warning map and update tag and type. +maybe_map_warnings(warning,Tag,FormatOrType) -> + case error_logger:warning_map() of + warning -> + {Tag,FormatOrType}; + Level -> + {fix_warning_tag(Level,Tag),fix_warning_type(Level,FormatOrType)} + end; +maybe_map_warnings(_,Tag,FormatOrType) -> + {Tag,FormatOrType}. + fix_warning_tag(error,warning_msg) -> error; fix_warning_tag(error,warning_report) -> error_report; fix_warning_tag(info,warning_msg) -> info_msg; @@ -263,29 +272,10 @@ warning_report(Report) -> Report :: report(). warning_report(Type, Report) -> - Level = error_logger:warning_map(), - {Tag, NType} = case Level of - info -> - if - Type =:= std_warning -> - {info_report, std_info}; - true -> - {info_report, Type} - end; - warning -> - {warning_report, Type}; - error -> - if - Type =:= std_warning -> - {error_report, std_error}; - true -> - {error_report, Type} - end - end, - logger:log(Level, + logger:log(warning, #{label=>{?MODULE,warning_report}, report=>Report}, - meta(Tag,NType)). + meta(warning_report,Type)). %%----------------------------------------------------------------- %% This function provides similar functions as error_msg for @@ -304,20 +294,11 @@ warning_msg(Format) -> Data :: list(). warning_msg(Format, Args) -> - Level = error_logger:warning_map(), - Tag = case Level of - warning -> - warning_msg; - info -> - info_msg; - error -> - error - end, - logger:log(Level, + logger:log(warning, #{label=>{?MODULE,warning_msg}, format=>Format, args=>Args}, - meta(Tag)). + meta(warning_msg)). %%----------------------------------------------------------------- %% This function should be used for information reports. Events @@ -336,7 +317,7 @@ info_report(Report) -> Report :: report(). info_report(Type, Report) -> - logger:log(info, + logger:log(notice, #{label=>{?MODULE,info_report}, report=>Report}, meta(info_report,Type)). @@ -357,7 +338,7 @@ info_msg(Format) -> Data :: list(). info_msg(Format, Args) -> - logger:log(info, + logger:log(notice, #{label=>{?MODULE,info_msg}, format=>Format, args=>Args}, @@ -377,7 +358,7 @@ error_info(Error) -> false -> {"~p",[Error]} end, MyMeta = #{tag=>info,type=>Error}, - logger:log(info, Format, Args, #{?MODULE=>MyMeta,domain=>[Error]}). + logger:log(notice, Format, Args, #{?MODULE=>MyMeta,domain=>[Error]}). %%----------------------------------------------------------------- %% Create metadata @@ -532,17 +513,17 @@ tty(true) -> _ = case lists:member(error_logger_tty_h, which_report_handlers()) of false -> case logger:get_handler_config(default) of - {ok,{logger_std_h,#{logger_std_h:=#{type:=standard_io}}}} -> + {ok,#{module:=logger_std_h,config:=#{type:=standard_io}}} -> logger:remove_handler_filter(default, error_logger_tty_false); _ -> logger:add_handler(error_logger_tty_true,logger_std_h, #{filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS( - [beam,erlang,otp]), + [otp]), formatter=>{?DEFAULT_FORMATTER, ?DEFAULT_FORMAT_CONFIG}, - logger_std_h=>#{type=>standard_io}}) + config=>#{type=>standard_io}}) end; true -> ok @@ -552,7 +533,7 @@ tty(false) -> delete_report_handler(error_logger_tty_h), _ = logger:remove_handler(error_logger_tty_true), _ = case logger:get_handler_config(default) of - {ok,{logger_std_h,#{logger_std_h:=#{type:=standard_io}}}} -> + {ok,#{module:=logger_std_h,config:=#{type:=standard_io}}} -> logger:add_handler_filter(default,error_logger_tty_false, {fun(_,_) -> stop end, ok}); _ -> @@ -575,6 +556,8 @@ get_format_depth() -> case application:get_env(kernel, error_logger_format_depth) of {ok, Depth} when is_integer(Depth) -> max(10, Depth); + {ok, unlimited} -> + unlimited; undefined -> unlimited end. diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index d873178f55..390f1fa42a 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -140,9 +140,8 @@ inet_db, pg2]}, {applications, []}, - {env, [{logger_level, info}, - {logger_sasl_compatible, false}, - {logger_progress_reports, stop} + {env, [{logger_level, notice}, + {logger_sasl_compatible, false} ]}, {mod, {kernel, []}}, {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 3beb3102fa..7d121f22fe 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -35,14 +35,17 @@ %% Configuration -export([add_handler/3, remove_handler/1, - add_logger_filter/2, add_handler_filter/3, - remove_logger_filter/1, remove_handler_filter/2, - set_module_level/2, unset_module_level/1, - set_logger_config/1, set_logger_config/2, + add_primary_filter/2, add_handler_filter/3, + remove_primary_filter/1, remove_handler_filter/2, + set_module_level/2, + unset_module_level/1, unset_module_level/0, + get_module_level/0, get_module_level/1, + set_primary_config/1, set_primary_config/2, set_handler_config/2, set_handler_config/3, - update_logger_config/1, update_handler_config/2, + update_primary_config/1, update_handler_config/2, update_formatter_config/2, update_formatter_config/3, - get_logger_config/0, get_handler_config/1, + get_primary_config/0, get_handler_config/1, + get_handler_config/0, get_handler_ids/0, get_config/0, add_handlers/1]). %% Private configuration @@ -52,7 +55,6 @@ -export([compare_levels/2]). -export([set_process_metadata/1, update_process_metadata/1, unset_process_metadata/0, get_process_metadata/0]). --export([i/0, i/1]). %% Basic report formatting -export([format_report/1, format_otp_report/1]). @@ -93,19 +95,24 @@ filter_return()),filter_arg()}. -type filter_arg() :: term(). -type filter_return() :: stop | ignore | log_event(). --type config() :: #{id => handler_id(), - level => level(), - filter_default => log | stop, - filters => [{filter_id(),filter()}], - formatter => {module(),formatter_config()}, - atom() => term()}. +-type primary_config() :: #{level => level() | all | none, + filter_default => log | stop, + filters => [{filter_id(),filter()}]}. +-type handler_config() :: #{id => handler_id(), + config => term(), + level => level() | all | none, + module => module(), + filter_default => log | stop, + filters => [{filter_id(),filter()}], + formatter => {module(),formatter_config()}}. -type timestamp() :: integer(). -type formatter_config() :: #{atom() => term()}. --type config_handler() :: {handler, handler_id(), module(), config()}. +-type config_handler() :: {handler, handler_id(), module(), handler_config()}. --export_type([log_event/0,level/0,report/0,msg_fun/0,metadata/0,config/0, - handler_id/0,filter_id/0,filter/0,filter_arg/0,filter_return/0, +-export_type([log_event/0,level/0,report/0,msg_fun/0,metadata/0, + primary_config/0,handler_config/0,handler_id/0, + filter_id/0,filter/0,filter_arg/0,filter_return/0, config_handler/0,formatter_config/0]). %%%----------------------------------------------------------------- @@ -308,11 +315,11 @@ internal_log(Level,Term) when is_atom(Level) -> %%%----------------------------------------------------------------- %%% Configuration --spec add_logger_filter(FilterId,Filter) -> ok | {error,term()} when +-spec add_primary_filter(FilterId,Filter) -> ok | {error,term()} when FilterId :: filter_id(), Filter :: filter(). -add_logger_filter(FilterId,Filter) -> - logger_server:add_filter(logger,{FilterId,Filter}). +add_primary_filter(FilterId,Filter) -> + logger_server:add_filter(primary,{FilterId,Filter}). -spec add_handler_filter(HandlerId,FilterId,Filter) -> ok | {error,term()} when HandlerId :: handler_id(), @@ -322,10 +329,10 @@ add_handler_filter(HandlerId,FilterId,Filter) -> logger_server:add_filter(HandlerId,{FilterId,Filter}). --spec remove_logger_filter(FilterId) -> ok | {error,term()} when +-spec remove_primary_filter(FilterId) -> ok | {error,term()} when FilterId :: filter_id(). -remove_logger_filter(FilterId) -> - logger_server:remove_filter(logger,FilterId). +remove_primary_filter(FilterId) -> + logger_server:remove_filter(primary,FilterId). -spec remove_handler_filter(HandlerId,FilterId) -> ok | {error,term()} when HandlerId :: handler_id(), @@ -336,7 +343,7 @@ remove_handler_filter(HandlerId,FilterId) -> -spec add_handler(HandlerId,Module,Config) -> ok | {error,term()} when HandlerId :: handler_id(), Module :: module(), - Config :: config(). + Config :: handler_config(). add_handler(HandlerId,Module,Config) -> logger_server:add_handler(HandlerId,Module,Config). @@ -345,16 +352,16 @@ add_handler(HandlerId,Module,Config) -> remove_handler(HandlerId) -> logger_server:remove_handler(HandlerId). --spec set_logger_config(Key,Value) -> ok | {error,term()} when +-spec set_primary_config(Key,Value) -> ok | {error,term()} when Key :: atom(), Value :: term(). -set_logger_config(Key,Value) -> - logger_server:set_config(logger,Key,Value). +set_primary_config(Key,Value) -> + logger_server:set_config(primary,Key,Value). --spec set_logger_config(Config) -> ok | {error,term()} when - Config :: config(). -set_logger_config(Config) -> - logger_server:set_config(logger,Config). +-spec set_primary_config(Config) -> ok | {error,term()} when + Config :: primary_config(). +set_primary_config(Config) -> + logger_server:set_config(primary,Config). -spec set_handler_config(HandlerId,Key,Value) -> ok | {error,term()} when HandlerId :: handler_id(), @@ -365,59 +372,101 @@ set_handler_config(HandlerId,Key,Value) -> -spec set_handler_config(HandlerId,Config) -> ok | {error,term()} when HandlerId :: handler_id(), - Config :: config(). + Config :: handler_config(). set_handler_config(HandlerId,Config) -> logger_server:set_config(HandlerId,Config). --spec update_logger_config(Config) -> ok | {error,term()} when - Config :: config(). -update_logger_config(Config) -> - logger_server:update_config(logger,Config). +-spec update_primary_config(Config) -> ok | {error,term()} when + Config :: primary_config(). +update_primary_config(Config) -> + logger_server:update_config(primary,Config). -spec update_handler_config(HandlerId,Config) -> ok | {error,term()} when HandlerId :: handler_id(), - Config :: config(). + Config :: handler_config(). update_handler_config(HandlerId,Config) -> logger_server:update_config(HandlerId,Config). --spec get_logger_config() -> {ok,Config} when - Config :: config(). -get_logger_config() -> - {ok,Config} = logger_config:get(?LOGGER_TABLE,logger), - {ok,maps:remove(handlers,Config)}. +-spec get_primary_config() -> Config when + Config :: primary_config(). +get_primary_config() -> + {ok,Config} = logger_config:get(?LOGGER_TABLE,primary), + maps:remove(handlers,Config). --spec get_handler_config(HandlerId) -> {ok,{Module,Config}} | {error,term()} when +-spec get_handler_config(HandlerId) -> {ok,Config} | {error,term()} when HandlerId :: handler_id(), - Module :: module(), - Config :: config(). + Config :: handler_config(). get_handler_config(HandlerId) -> - logger_config:get(?LOGGER_TABLE,HandlerId). + case logger_config:get(?LOGGER_TABLE,HandlerId) of + {ok,{_,Config}} -> + {ok,Config}; + Error -> + Error + end. + +-spec get_handler_config() -> [Config] when + Config :: handler_config(). +get_handler_config() -> + [begin + {ok,Config} = get_handler_config(HandlerId), + Config + end || HandlerId <- get_handler_ids()]. + +-spec get_handler_ids() -> [HandlerId] when + HandlerId :: handler_id(). +get_handler_ids() -> + {ok,#{handlers:=HandlerIds}} = logger_config:get(?LOGGER_TABLE,primary), + HandlerIds. -spec update_formatter_config(HandlerId,FormatterConfig) -> ok | {error,term()} when - HandlerId :: config(), + HandlerId :: handler_id(), FormatterConfig :: formatter_config(). update_formatter_config(HandlerId,FormatterConfig) -> logger_server:update_formatter_config(HandlerId,FormatterConfig). -spec update_formatter_config(HandlerId,Key,Value) -> ok | {error,term()} when - HandlerId :: config(), + HandlerId :: handler_id(), Key :: atom(), Value :: term(). update_formatter_config(HandlerId,Key,Value) -> logger_server:update_formatter_config(HandlerId,#{Key=>Value}). --spec set_module_level(Module,Level) -> ok | {error,term()} when +-spec set_module_level(Modules,Level) -> ok | {error,term()} when + Modules :: [module()] | module(), + Level :: level() | all | none. +set_module_level(Module,Level) when is_atom(Module) -> + set_module_level([Module],Level); +set_module_level(Modules,Level) -> + logger_server:set_module_level(Modules,Level). + +-spec unset_module_level(Modules) -> ok when + Modules :: [module()] | module(). +unset_module_level(Module) when is_atom(Module) -> + unset_module_level([Module]); +unset_module_level(Modules) -> + logger_server:unset_module_level(Modules). + +-spec unset_module_level() -> ok. +unset_module_level() -> + logger_server:unset_module_level(). + +-spec get_module_level(Modules) -> [{Module,Level}] when + Modules :: [Module] | Module, Module :: module(), - Level :: level(). -set_module_level(Module,Level) -> - logger_server:set_module_level(Module,Level). - --spec unset_module_level(Module) -> ok | {error,term()} when - Module :: module(). -unset_module_level(Module) -> - logger_server:unset_module_level(Module). + Level :: level() | all | none. +get_module_level(Module) when is_atom(Module) -> + get_module_level([Module]); +get_module_level(Modules) when is_list(Modules) -> + [{M,L} || {M,L} <- get_module_level(), + lists:member(M,Modules)]. + +-spec get_module_level() -> [{Module,Level}] when + Module :: module(), + Level :: level() | all | none. +get_module_level() -> + logger_config:get_module_level(?LOGGER_TABLE). %%%----------------------------------------------------------------- %%% Misc @@ -466,82 +515,13 @@ unset_process_metadata() -> _ = erase(?LOGGER_META_KEY), ok. --spec i() -> #{logger=>config(), - handlers=>[{handler_id(),module(),config()}], - module_levels=>[{module(),level()}]}. -i() -> - i(term). - --spec i(term) -> #{logger=>config(), - handlers=>[{handler_id(),module(),config()}], - module_levels=>[{module(),level()}]}; - (print) -> ok; - (string) -> iolist(). -i(_Action = print) -> - io:put_chars(i(string)); -i(_Action = string) -> - #{logger := #{level := Level, - filters := Filters, - filter_default := FilterDefault}, - handlers := HandlerConfigs, - module_levels := Modules} = i(term), - [io_lib:format("Current logger configuration:~n", []), - io_lib:format(" Level: ~p~n",[Level]), - io_lib:format(" Filter Default: ~p~n", [FilterDefault]), - io_lib:format(" Filters: ~n", []), - print_filters(4, Filters), - io_lib:format(" Handlers: ~n", []), - print_handlers(HandlerConfigs), - io_lib:format(" Level set per module: ~n", []), - print_module_levels(Modules) - ]; -i(_Action = term) -> - {Logger, Handlers, Modules} = logger_config:get(tid()), - #{logger=>maps:remove(handlers,Logger), - handlers=>lists:keysort(1,Handlers), - module_levels=>lists:keysort(1,Modules)}. - -print_filters(Indent, {Id, {Fun, Config}}) -> - io_lib:format("~sId: ~p~n" - "~s Fun: ~p~n" - "~s Config: ~p~n",[Indent, Id, Indent, Fun, Indent, Config]); -print_filters(Indent, Filters) -> - IndentStr = io_lib:format("~.*s",[Indent, ""]), - lists:map(fun(Filter) ->print_filters(IndentStr, Filter) end, Filters). - - -print_handlers({Id,Module, - #{level := Level, - filters := Filters, filter_default := FilterDefault, - formatter := {FormatterModule,FormatterConfig}} = Config}) -> - MyKeys = [filter_default, filters, formatter, level, id], - UnhandledConfig = maps:filter(fun(Key, _) -> - not lists:member(Key, MyKeys) - end, Config), - Unhandled = lists:map(fun({Key, Value}) -> - io_lib:format(" ~p: ~p~n",[Key, Value]) - end, maps:to_list(UnhandledConfig)), - io_lib:format(" Id: ~p~n" - " Module: ~p~n" - " Level: ~p~n" - " Formatter:~n" - " Module: ~p~n" - " Config: ~p~n" - " Filter Default: ~p~n" - " Filters:~n~s" - " Handler Config:~n" - "~s" - "",[Id, Module, Level, FormatterModule, FormatterConfig, - FilterDefault, print_filters(8, Filters), Unhandled]); -print_handlers(Handlers) -> - lists:map(fun print_handlers/1, Handlers). - -print_module_levels({Module,Level}) -> - io_lib:format(" Module: ~p~n" - " Level: ~p~n", - [Module,Level]); -print_module_levels(ModuleLevels) -> - lists:map(fun print_module_levels/1, ModuleLevels). +-spec get_config() -> #{primary=>primary_config(), + handlers=>[handler_config()], + module_levels=>[{module(),level() | all | none}]}. +get_config() -> + #{primary=>get_primary_config(), + handlers=>get_handler_config(), + module_levels=>lists:keysort(1,get_module_level())}. -spec internal_init_logger() -> ok | {error,term()}. %% This function is responsible for config of the logger @@ -550,13 +530,13 @@ print_module_levels(ModuleLevels) -> %% tree is started. internal_init_logger() -> try - ok = logger:set_logger_config(level, get_logger_level()), - ok = logger:set_logger_config(filter_default, get_logger_filter_default()), + ok = logger:set_primary_config(level, get_logger_level()), + ok = logger:set_primary_config(filter_default, get_primary_filter_default()), - [case logger:add_logger_filter(Id, Filter) of + [case logger:add_primary_filter(Id, Filter) of ok -> ok; {error, Reason} -> throw(Reason) - end || {Id, Filter} <- get_logger_filters()], + end || {Id, Filter} <- get_primary_filters()], _ = [[case logger:set_module_level(Module, Level) of ok -> ok; @@ -677,7 +657,7 @@ get_logger_level() -> throw({logger_level, Level}) end. -get_logger_filter_default() -> +get_primary_filter_default() -> case lists:keyfind(filters,1,get_logger_env()) of {filters,Default,_} -> Default; @@ -685,7 +665,7 @@ get_logger_filter_default() -> log end. -get_logger_filters() -> +get_primary_filters() -> lists:foldl( fun({filters, _, Filters}, _Acc) -> Filters; @@ -700,7 +680,7 @@ init_default_config(Type) when Type==standard_io; element(1,Type)==file -> Env = get_logger_env(), DefaultFormatter = #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}, - DefaultConfig = DefaultFormatter#{logger_std_h=>#{type=>Type}}, + DefaultConfig = DefaultFormatter#{config=>#{type=>Type}}, NewLoggerEnv = case lists:keyfind(default, 2, Env) of {handler, default, Module, Config} -> @@ -731,17 +711,9 @@ init_default_config(Type) -> get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of true -> - ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp]); + ?DEFAULT_HANDLER_FILTERS([otp]); false -> - Extra = - case application:get_env(kernel, logger_progress_reports, stop) of - log -> - []; - stop -> - [{stop_progress, - {fun logger_filters:progress/2,stop}}] - end, - Extra ++ ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp,sasl]) + ?DEFAULT_HANDLER_FILTERS([otp,sasl]) end. get_logger_env() -> @@ -749,19 +721,14 @@ get_logger_env() -> %%%----------------------------------------------------------------- %%% Internal -do_log(warning,Msg,Meta) -> - do_log_1(error_logger:warning_map(),Msg,Meta); -do_log(Level,Msg,Meta) -> - do_log_1(Level,Msg,Meta). - -do_log_1(Level,Msg,#{mfa:={Module,_,_}}=Meta) -> +do_log(Level,Msg,#{mfa:={Module,_,_}}=Meta) -> case logger_config:allow(?LOGGER_TABLE,Level,Module) of true -> log_allowed(#{},Level,Msg,Meta); false -> ok end; -do_log_1(Level,Msg,Meta) -> +do_log(Level,Msg,Meta) -> case logger_config:allow(?LOGGER_TABLE,Level) of true -> log_allowed(#{},Level,Msg,Meta); diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl index b3cf7d67dd..a73b681e0d 100644 --- a/lib/kernel/src/logger_backend.erl +++ b/lib/kernel/src/logger_backend.erl @@ -28,9 +28,9 @@ %%%----------------------------------------------------------------- %%% The default logger backend log_allowed(Log, Tid) -> - {ok,Config} = logger_config:get(Tid,logger), + {ok,Config} = logger_config:get(Tid,primary), Filters = maps:get(filters,Config,[]), - case apply_filters(logger,Log,Filters,Config) of + case apply_filters(primary,Log,Filters,Config) of stop -> ok; Log1 -> diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 1d35c2e068..7b2148d034 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -25,7 +25,7 @@ get/2, get/3, get/1, create/3, create/4, set/3, set_module_level/3,unset_module_level/2, - cache_module_level/2, + get_module_level/1,cache_module_level/2, level_to_int/1]). -include("logger_internal.hrl"). @@ -54,7 +54,7 @@ allow(Tid,Level,Module) -> end. allow(Tid,Level) -> - GlobalLevelInt = ets:lookup_element(Tid,?LOGGER_KEY,2), + GlobalLevelInt = ets:lookup_element(Tid,?PRIMARY_KEY,2), level_to_int(Level) =< GlobalLevelInt. exist(Tid,What) -> @@ -71,7 +71,7 @@ get(Tid,What) -> end. get(Tid,What,Level) -> - MS = [{{table_key(What),'$1','$2'}, % logger config + MS = [{{table_key(What),'$1','$2'}, % primary config [{'>=','$1',level_to_int(Level)}], ['$2']}, {{table_key(What),'$1','$2','$3'}, % handler config @@ -94,7 +94,7 @@ set(Tid,What,Config) -> %% Should do this only if the level has actually changed. Possibly %% overwrite instead of delete? case What of - logger -> + primary -> _ = ets:select_delete(Tid,[{{'_',{'$1',cached}}, [{'=/=','$1',LevelInt}], [true]}]), @@ -105,27 +105,38 @@ set(Tid,What,Config) -> ets:update_element(Tid,table_key(What),[{2,LevelInt},{3,Config}]), ok. -set_module_level(Tid,Module,Level) -> - ets:insert(Tid,{Module,level_to_int(Level)}), +set_module_level(Tid,Modules,Level) -> + LevelInt = level_to_int(Level), + [ets:insert(Tid,{Module,LevelInt}) || Module <- Modules], ok. -unset_module_level(Tid,Module) -> - ets:delete(Tid,Module), % should possibley overwrite instead of delete? +%% should possibly overwrite instead of delete? +unset_module_level(Tid,all) -> + MS = [{{'$1','$2'},[{is_atom,'$1'},{is_integer,'$2'}],[true]}], + _ = ets:select_delete(Tid,MS), + ok; +unset_module_level(Tid,Modules) -> + [ets:delete(Tid,Module) || Module <- Modules], ok. +get_module_level(Tid) -> + MS = [{{'$1','$2'},[{is_atom,'$1'},{is_integer,'$2'}],[{{'$1','$2'}}]}], + Modules = ets:select(Tid,MS), + lists:sort([{M,int_to_level(L)} || {M,L} <- Modules]). + cache_module_level(Tid,Module) -> - GlobalLevelInt = ets:lookup_element(Tid,?LOGGER_KEY,2), + GlobalLevelInt = ets:lookup_element(Tid,?PRIMARY_KEY,2), ets:insert_new(Tid,{Module,{GlobalLevelInt,cached}}), ok. get(Tid) -> - {ok,Logger} = get(Tid,logger), + {ok,Primary} = get(Tid,primary), HMS = [{{table_key('$1'),'_','$2','$3'},[],[{{'$1','$3','$2'}}]}], Handlers = ets:select(Tid,HMS), - MMS = [{{'$1','$2'},[{is_atom,'$1'},{is_integer,'$2'}],[{{'$1','$2'}}]}], - Modules = ets:select(Tid,MMS), - {Logger,Handlers,[{M,int_to_level(L)} || {M,L} <- Modules]}. + Modules = get_module_level(Tid), + {Primary,Handlers,Modules}. +level_to_int(none) -> ?LOG_NONE; level_to_int(emergency) -> ?EMERGENCY; level_to_int(alert) -> ?ALERT; level_to_int(critical) -> ?CRITICAL; @@ -133,8 +144,10 @@ level_to_int(error) -> ?ERROR; level_to_int(warning) -> ?WARNING; level_to_int(notice) -> ?NOTICE; level_to_int(info) -> ?INFO; -level_to_int(debug) -> ?DEBUG. +level_to_int(debug) -> ?DEBUG; +level_to_int(all) -> ?LOG_ALL. +int_to_level(?LOG_NONE) -> none; int_to_level(?EMERGENCY) -> emergency; int_to_level(?ALERT) -> alert; int_to_level(?CRITICAL) -> critical; @@ -142,10 +155,11 @@ int_to_level(?ERROR) -> error; int_to_level(?WARNING) -> warning; int_to_level(?NOTICE) -> notice; int_to_level(?INFO) -> info; -int_to_level(?DEBUG) -> debug. +int_to_level(?DEBUG) -> debug; +int_to_level(?LOG_ALL) -> all. %%%----------------------------------------------------------------- %%% Internal -table_key(logger) -> ?LOGGER_KEY; +table_key(primary) -> ?PRIMARY_KEY; table_key(HandlerId) -> {?HANDLER_KEY,HandlerId}. diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 773aa75bc6..a074d0210e 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -26,16 +26,17 @@ -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, disk_log_sync/1, reset/1]). +-export([start_link/3, info/1, sync/1, reset/1]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). %% logger callbacks --export([log/2, - adding_handler/1, removing_handler/1, - changing_config/2, swap_buffer/2]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). + +%% handler internal +-export([log_handler_info/4]). %%%=================================================================== %%% API @@ -47,7 +48,7 @@ %%% handler process gets added (as a result of calling add/3). -spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when Name :: atom(), - Config :: logger:config(), + Config :: logger:handler_config(), HandlerState :: map(), Pid :: pid(), Reason :: term(). @@ -57,18 +58,19 @@ start_link(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% --spec disk_log_sync(Name) -> ok | {error,Reason} when +-spec sync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -disk_log_sync(Name) when is_atom(Name) -> +sync(Name) when is_atom(Name) -> try - gen_server:call(Name, disk_log_sync, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + disk_log_sync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; -disk_log_sync(Name) -> - {error,{badarg,{disk_log_sync,[Name]}}}. +sync(Name) -> + {error,{badarg,{sync,[Name]}}}. %%%----------------------------------------------------------------- %%% @@ -79,7 +81,8 @@ disk_log_sync(Name) -> info(Name) when is_atom(Name) -> try - gen_server:call(Name, info, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + info, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -94,7 +97,8 @@ info(Name) -> reset(Name) when is_atom(Name) -> try - gen_server:call(Name, reset, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + reset, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -112,23 +116,16 @@ adding_handler(#{id:=Name}=Config) -> case check_config(adding, Config) of {ok, Config1} -> %% create initial handler state by merging defaults with config - HConfig = maps:get(?MODULE, Config1, #{}), + HConfig = maps:get(config, Config1, #{}), HState = maps:merge(get_init_state(), HConfig), case logger_h_common:overload_levels_ok(HState) of true -> - case start(Name, Config1, HState) of - ok -> - %% Make sure wait_for_buffer is not stored, so we - %% won't hang and wait for buffer on a restart - {ok, maps:remove(wait_for_buffer,Config1)}; - Error -> - Error - end; + start(Name, Config1, HState); false -> - #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = HState, - {error,{invalid_levels,{TSQL,DNRQL,FRQL}}} + #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = HState, + {error,{invalid_levels,{SMQL,DMQL,FQL}}} end; Error -> Error @@ -136,86 +133,89 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts}, - NewConfig=#{id:=Name, disk_log_opts:=DLOpts}) -> +changing_config(OldConfig = #{id:=Name, config:=OldHConfig}, + NewConfig = #{id:=Name, config:=NewHConfig}) -> + #{type:=Type, file:=File, max_no_files:=MaxFs, + max_no_bytes:=MaxBytes} = OldHConfig, + case NewHConfig of + #{type:=Type, file:=File, max_no_files:=MaxFs, + max_no_bytes:=MaxBytes} -> + changing_config1(OldConfig, NewConfig); + _ -> + {error,{illegal_config_change,OldConfig,NewConfig}} + end; +changing_config(OldConfig, NewConfig) -> + {error,{illegal_config_change,OldConfig,NewConfig}}. + +changing_config1(OldConfig=#{config:=OldHConfig}, NewConfig) -> case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, + {ok,NewConfig1 = #{config:=NewHConfig}} -> + #{handler_pid:=HPid, + mode_tab:=ModeTab} = OldHConfig, + NewHConfig1 = NewHConfig#{handler_pid=>HPid, + mode_tab=>ModeTab}, + NewConfig2 = NewConfig1#{config=>NewHConfig1}, + try gen_server:call(HPid, {change_config,OldConfig,NewConfig2}, ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; + ok -> {ok,NewConfig2}; HError -> HError catch _:{timeout,_} -> {error,handler_busy} end; Error -> Error - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. + end. check_config(adding, #{id:=Name}=Config) -> - %% Merge in defaults on handler level - LogOpts0 = maps:get(disk_log_opts, Config, #{}), - LogOpts = merge_default_logopts(Name, LogOpts0), - case check_log_opts(maps:to_list(LogOpts)) of + %% merge handler specific config data + HConfig = merge_default_logopts(Name, maps:get(config, Config, #{})), + case check_h_config(maps:to_list(HConfig)) of ok -> - MyConfig = maps:get(?MODULE, Config, #{}), - case check_my_config(maps:to_list(MyConfig)) of - ok -> - {ok,Config#{disk_log_opts=>LogOpts, - ?MODULE=>MyConfig}}; - Error -> - Error - end; + {ok,Config#{config=>HConfig}}; Error -> Error end; check_config(changing, Config) -> - MyConfig = maps:get(?MODULE, Config, #{}), - case check_my_config(maps:to_list(MyConfig)) of + HConfig = maps:get(config, Config, #{}), + case check_h_config(maps:to_list(HConfig)) of ok -> {ok,Config}; Error -> Error end. -merge_default_logopts(Name, LogOpts) -> - Type = maps:get(type, LogOpts, wrap), +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), {DefaultNoFiles,DefaultNoBytes} = case Type of halt -> {undefined,infinity}; _wrap -> {10,1048576} end, {ok,Dir} = file:get_cwd(), - Default = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Default,LogOpts). - -check_log_opts([{file,File}|Opts]) when is_list(File) -> - check_log_opts(Opts); -check_log_opts([{max_no_files,undefined}|Opts]) -> - check_log_opts(Opts); -check_log_opts([{max_no_files,N}|Opts]) when is_integer(N), N>0 -> - check_log_opts(Opts); -check_log_opts([{max_no_bytes,infinity}|Opts]) -> - check_log_opts(Opts); -check_log_opts([{max_no_bytes,N}|Opts]) when is_integer(N), N>0 -> - check_log_opts(Opts); -check_log_opts([{type,Type}|Opts]) when Type==wrap; Type==halt -> - check_log_opts(Opts); -check_log_opts([Invalid|_]) -> - {error,{invalid_config,disk_log_opt,Invalid}}; -check_log_opts([]) -> - ok. - -check_my_config([Other | Config]) -> + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). + +check_h_config([{file,File}|Config]) when is_list(File) -> + check_h_config(Config); +check_h_config([{max_no_files,undefined}|Config]) -> + check_h_config(Config); +check_h_config([{max_no_files,N}|Config]) when is_integer(N), N>0 -> + check_h_config(Config); +check_h_config([{max_no_bytes,infinity}|Config]) -> + check_h_config(Config); +check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> + check_h_config(Config); +check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> + check_h_config(Config); +check_h_config([Other | Config]) -> case logger_h_common:check_common_config(Other) of valid -> - check_my_config(Config); + check_h_config(Config); invalid -> {error,{invalid_config,?MODULE,Other}} end; -check_my_config([]) -> +check_h_config([]) -> ok. %%%----------------------------------------------------------------- @@ -224,86 +224,90 @@ removing_handler(#{id:=Name}) -> stop(Name). %%%----------------------------------------------------------------- -%%% Get buffer when swapping from simple handler -swap_buffer(Name,Buffer) -> - case whereis(Name) of - undefined -> - ok; - _ -> - Name ! {buffer,Buffer} - end. - -%%%----------------------------------------------------------------- %%% Log a string or report -spec log(LogEvent, Config) -> ok | dropped when LogEvent :: logger:log_event(), - Config :: logger:config(). + Config :: logger:handler_config(). -log(LogEvent,Config=#{id:=Name}) -> - %% if the handler has crashed, we must drop this request +log(LogEvent, Config = #{id := Name, + config := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> + %% if the handler has crashed, we must drop this event %% and hope the handler restarts so we can try again - true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(LogEvent,Config), - logger_h_common:call_cast_or_drop(Name, Bin). - + true = is_process_alive(HPid), + Bin = logger_h_common:log_to_binary(LogEvent, Config), + logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). %%%=================================================================== %%% gen_server callbacks %%%=================================================================== -init([Name, Config = #{disk_log_opts := LogOpts}, +init([Name, + Config = #{config := HConfig = #{file:=File, + type:=Type, + max_no_bytes:=MNB, + max_no_files:=MNF}}, State = #{dl_sync_int := DLSyncInt}]) -> - register(Name, self()), + + register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), process_flag(message_queue_data, off_heap), ?init_test_hooks(), ?start_observation(Name), - - case open_disk_log(Name, LogOpts) of + + LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, + case open_disk_log(Name, File, Type, MNB, MNF) of ok -> - catch ets:new(Name, [public, named_table]), - ?set_mode(Name, async), - proc_lib:init_ack({ok,self()}), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{id => Name, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - last_log_ts => T0, - burst_win_ts => T0, - burst_msg_count => 0, - last_op => sync, - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}), - gen_server:cast(self(), repeated_disk_log_sync), - enter_loop(Config, State1); + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + T0 = ?timestamp(), + State1 = + ?merge_with_stats(State#{ + id => Name, + mode_tab => ModeTab, + mode => async, + dl_sync => DLSyncInt, + log_opts => LogOpts, + last_qlen => 0, + last_log_ts => T0, + burst_win_ts => T0, + burst_msg_count => 0, + last_op => sync, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}), + Config1 = + Config#{config => HConfig#{handler_pid => self(), + mode_tab => ModeTab}}, + proc_lib:init_ack({ok,self(),Config1}), + gen_server:cast(self(), repeated_disk_log_sync), + case logger_h_common:unset_restart_flag(Name, ?MODULE) of + true -> + %% inform about restart + gen_server:cast(self(), {log_handler_info, + "Handler ~p restarted", + [Name]}); + false -> + %% initial start + ok + end, + enter_loop(Config1, State1) + catch + _:Error -> + logger_h_common:error_notify({open_disk_log,Name,Error}), + proc_lib:init_ack(Error) + end; Error -> logger_h_common:error_notify({open_disk_log,Name,Error}), proc_lib:init_ack(Error) end. -enter_loop(#{wait_for_buffer:=true}=Config,State) -> - State1 = - receive - {buffer,Buffer} -> - lists:foldl( - fun(Log,S) -> - Bin = logger_h_common:log_to_binary(Log,Config), - {_,S1} = do_log(Bin,cast,S), - S1 - end, - State, - Buffer) - end, - gen_server:enter_loop(?MODULE,[],State1); enter_loop(_Config,State) -> gen_server:enter_loop(?MODULE,[],State). -%% This is the synchronous log request. +%% This is the synchronous log event. handle_call({log, Bin}, _From, State) -> {Result,State1} = do_log(Bin, call, State), %% Result == ok | dropped @@ -315,10 +319,10 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) -> handle_call({change_config,_OldConfig,NewConfig}, _From, State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(?MODULE, NewConfig, #{}), - State1 = #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = maps:merge(State, HConfig), + HConfig = maps:get(config, NewConfig, #{}), + State1 = #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = maps:merge(State, HConfig), case logger_h_common:overload_levels_ok(State1) of true -> _ = @@ -339,7 +343,7 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, end, {reply, ok, State1}; false -> - {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State} + {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} end; handle_call(info, _From, State) -> @@ -357,15 +361,19 @@ handle_call(stop, _From, State) -> {stop, {shutdown,stopped}, ok, State}. -%% This is the asynchronous log request. +%% This is the asynchronous log event. handle_cast({log, Bin}, State) -> {_,State1} = do_log(Bin, cast, State), {noreply, State1}; +handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> + log_handler_info(Name, Format, Args, State), + {noreply, State}; + %% 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 -%% request, the repeat operation must be active! +%% event, the repeat operation must be active! handle_cast(repeated_disk_log_sync, State = #{id := Name, filesync_repeat_interval := FSyncInt, @@ -429,19 +437,19 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% get_init_state() -> - #{toggle_sync_qlen => ?TOGGLE_SYNC_QLEN, - drop_new_reqs_qlen => ?DROP_NEW_REQS_QLEN, - flush_reqs_qlen => ?FLUSH_REQS_QLEN, - enable_burst_limit => ?ENABLE_BURST_LIMIT, - burst_limit_size => ?BURST_LIMIT_SIZE, - burst_window_time => ?BURST_WINDOW_TIME, - enable_kill_overloaded => ?ENABLE_KILL_OVERLOADED, - handler_overloaded_qlen => ?HANDLER_OVERLOADED_QLEN, - handler_overloaded_mem => ?HANDLER_OVERLOADED_MEM, - handler_restart_after => ?HANDLER_RESTART_AFTER, - dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, + filesync_ok_qlen => ?FILESYNC_OK_QLEN, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Add a disk_log handler to the logger. @@ -449,22 +457,21 @@ get_init_state() -> %%% exist if the handler is registered with logger (and should not %%% exist if the handler is not registered). %%% -%%% Config is the logger:config() map containing a sub map with any of -%%% the following associations: +%%% Config is the logger:handler_config() map. Handler specific parameters +%%% should be provided with a sub map associated with a key named +%%% 'config', e.g: %%% -%%% Config = #{disk_log_opts => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. +%%% Config = #{config => #{sync_mode_qlen => 50} %%% -%%% This map will be merged with the logger configuration data for -%%% the disk_log LogName. If type == halt, then max_no_files is -%%% ignored. +%%% The 'config' sub map will also contain parameters for configuring +%%% the disk_log: %%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named the same as this module, e.g: +%%% Config = #{config => #{file => file:filename(), +%%% max_no_bytes => integer(), +%%% max_no_files => integer(), +%%% type => wrap | halt}}. %%% -%%% Config = #{logger_disk_log_h => #{toggle_sync_qlen => 50} +%%% If type == halt, then max_no_files is ignored. %%% %%% The disk_log handler process is linked to logger_sup, which is %%% part of the kernel application's supervision tree. @@ -477,8 +484,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,_} -> - ok; + {ok,_Pid,Config1} -> + {ok,Config1}; Error -> Error end. @@ -486,16 +493,16 @@ start(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% Stop and remove the handler. stop(Name) -> - case whereis(Name) of + 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). - _ = gen_server:call(Name,stop), + _ = gen_server:call(Pid, stop), _ = supervisor:delete_child(logger_sup, Name), ok end. @@ -506,21 +513,31 @@ stop(Name) -> if C == 0 -> Interval; true -> C-1 end). -%% check for overload between every request (and set Mode to async, +%% check for overload between every event (and set Mode to async, %% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize requests have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := _Mode0}) -> +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> T1 = ?timestamp(), %% check if the handler is getting overloaded, or if it's %% recovering from overload (the check must be done for each - %% request to react quickly to large bursts of requests and + %% event to react quickly to large bursts of events and %% to ensure that the handler can never end up in drop mode %% with an empty mailbox, which would stop operation) {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, State), + logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), if Mode1 == flush -> flush(Name, QLen, T1, State1); @@ -530,10 +547,14 @@ do_log(Bin, CallOrCast, State = #{id:=Name, mode := _Mode0}) -> %% this function is called by do_log/3 after an overload check %% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> +flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> %% flush messages in the mailbox (a limited number in %% order to not cause long delays) - _NewFlushed = logger_h_common:flush_log_requests(?FLUSH_MAX_N), + NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), %% because of the receive loop when flushing messages, the %% handler will be scheduled out often and the mailbox could @@ -541,26 +562,27 @@ flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> {_,_QLen1} = process_info(self(), message_queue_len), ?observe(Name,{max_qlen,_QLen1}), - %% Add 1 for the current log request - ?observe(Name,{flushed,_NewFlushed+1}), + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,_NewFlushed, - State1#{mode => ?set_mode(Name,async), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State1#{mode => ?set_mode(ModeTab,async), last_qlen => 0, last_log_ts => T1})}. %% this function is called to write to disk_log write(Name, Mode, T1, Bin, _CallOrCast, - State = #{dl_sync := DLSync, + State = #{mode_tab := ModeTab, + dl_sync := DLSync, dl_sync_int := DLSyncInt, last_qlen := LastQLen, last_log_ts := T0}) -> %% check if we need to limit the number of writes - %% during a burst of log requests + %% during a burst of log events {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - %% only send a synhrounous request to the disk_log process + %% only send a synhrounous event to the disk_log process %% every DLSyncInt time, to give the handler time between %% writes so it can keep up with incoming messages {Status,LastQLen1,State1} = @@ -578,18 +600,18 @@ write(Name, Mode, T1, Bin, _CallOrCast, {dropped, LastQLen, State} end, - %% Check if the time since the previous log request is long enough - + %% Check if the time since the previous log event is long enough - %% and the queue length small enough - to assume the mailbox has %% been emptied, and if so, do filesync operation and reset mode to %% async. Note that this is the best we can do to detect an idle %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log requests is fast and no new - %% request comes in after the last one, idle state won't be detected! + %% time between two consecutive log events is fast and no new + %% event comes in after the last one, idle state won't be detected! Time = ?diff_time(T1,T0), {Mode1,BurstMsgCount1,State2} = if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(Name,Mode,async), 0, disk_log_sync(Name,State1)}; + {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; true -> {Mode, BurstMsgCount,State1} end, @@ -607,11 +629,21 @@ write(Name, Mode, T1, Bin, _CallOrCast, {Status,State4}. -open_disk_log(Name, LogOpts) -> - #{file := File, - max_no_bytes := MaxNoBytes, - max_no_files := MaxNoFiles, - type := Type} = LogOpts, +log_handler_info(Name, Format, Args, 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 = logger_h_common:log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = disk_log_write(Name, Bin, State), + ok. + + +open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> Size = diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 4d727b3da0..33b250eef6 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -35,7 +35,8 @@ template=>template(), time_designator=>byte(), time_offset=>integer()|[byte()]}. --type template() :: [atom()|tuple()|string()]. +-type template() :: [metakey()|{metakey(),template(),template()}|string()]. +-type metakey() :: atom() | [atom()]. %%%----------------------------------------------------------------- %%% API @@ -53,8 +54,8 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) [msg|Rest] -> {true,Rest}; _ ->{false,AT0} end, - B = do_format(Level,"",Meta1,BT,Config), - A = do_format(Level,"",Meta1,AT,Config), + B = do_format(Level,Meta1,BT,Config), + A = do_format(Level,Meta1,AT,Config), MsgStr = if DoMsg -> Config1 = @@ -84,26 +85,37 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) end, truncate(B ++ MsgStr ++ A,maps:get(max_size,Config)). -do_format(Level,Msg,Data,[level|Format],Config) -> - [to_string(level,Level,Config)|do_format(Level,Msg,Data,Format,Config)]; -do_format(Level,Msg,Data,[Key|Format],Config) when is_atom(Key); is_tuple(Key) -> - Value = value(Key,Data), - [to_string(Key,Value,Config)|do_format(Level,Msg,Data,Format,Config)]; -do_format(Level,Msg,Data,[Str|Format],Config) -> - [Str|do_format(Level,Msg,Data,Format,Config)]; -do_format(_Level,_Msg,_Data,[],_Config) -> +do_format(Level,Data,[level|Format],Config) -> + [to_string(level,Level,Config)|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[{Key,IfExist,Else}|Format],Config) -> + String = + case value(Key,Data) of + {ok,Value} -> do_format(Level,Data#{Key=>Value},IfExist,Config); + error -> do_format(Level,Data,Else,Config) + end, + [String|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[Key|Format],Config) + when is_atom(Key) orelse + (is_list(Key) andalso is_atom(hd(Key))) -> + String = + case value(Key,Data) of + {ok,Value} -> to_string(Key,Value,Config); + error -> "" + end, + [String|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[Str|Format],Config) -> + [Str|do_format(Level,Data,Format,Config)]; +do_format(_Level,_Data,[],_Config) -> []. -value(Key,Meta) when is_atom(Key), is_map(Meta) -> - maps:get(Key,Meta,""); -value(Key,_) when is_atom(Key) -> - ""; -value(Keys,Meta) when is_tuple(Keys) -> - value(tuple_to_list(Keys),Meta); -value([Key|Keys],Meta) -> - value(Keys,value(Key,Meta)); +value(Key,Meta) when is_map_key(Key,Meta) -> + {ok,maps:get(Key,Meta)}; +value([Key|Keys],Meta) when is_map_key(Key,Meta) -> + value(Keys,maps:get(Key,Meta)); value([],Value) -> - Value. + {ok,Value}; +value(_,_) -> + error. to_string(time,Time,Config) -> format_time(Time,Config); @@ -223,7 +235,7 @@ format_mfa(MFA) -> maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> - #{title:=Title}=MyMeta = add_legacy_title(Level,maps:get(?MODULE,Meta,#{})), + #{title:=Title}=MyMeta = add_legacy_title(Level,Meta,Config), {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = timestamp_to_datetimemicro(Timestamp,Config), Header = @@ -233,11 +245,23 @@ maybe_add_legacy_header(Level, maybe_add_legacy_header(_,Meta,_) -> Meta. -add_legacy_title(_Level,#{title:=_}=MyMeta) -> +add_legacy_title(_Level,#{?MODULE:=#{title:=_}=MyMeta},_) -> MyMeta; -add_legacy_title(Level,MyMeta) -> - Title = string:uppercase(atom_to_list(Level)) ++ " REPORT", - MyMeta#{title=>Title}. +add_legacy_title(Level,Meta,Config) -> + case maps:get(?MODULE,Meta,#{}) of + #{title:=_}=MyMeta -> + MyMeta; + MyMeta -> + TitleLevel = + case (Level=:=notice andalso maps:find(error_logger,Meta)) of + {ok,_} -> + maps:get(error_logger_notice_header,Config); + _ -> + Level + end, + Title = string:uppercase(atom_to_list(TitleLevel)) ++ " REPORT", + MyMeta#{title=>Title} + end. month(1) -> "Jan"; month(2) -> "Feb"; @@ -257,6 +281,7 @@ month(12) -> "Dec". add_default_config(Config0) -> Default = #{legacy_header=>false, + error_logger_notice_header=>info, single_line=>true, chars_limit=>unlimited, time_designator=>$T}, @@ -341,19 +366,15 @@ do_check_config([{single_line,SL}|Config]) when is_boolean(SL) -> do_check_config(Config); do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> do_check_config(Config); +do_check_config([{error_logger_notice_header,ELNH}|Config]) when ELNH == info; + ELNH == notice -> + do_check_config(Config); do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1) -> do_check_config(Config); -do_check_config([{template,T}|Config]) when is_list(T) -> - case lists:all(fun(X) when is_atom(X) -> true; - (X) when is_tuple(X), is_atom(element(1,X)) -> true; - (X) when is_list(X) -> io_lib:printable_unicode_list(X); - (_) -> false - end, - T) of - true -> - do_check_config(Config); - false -> - {error,{invalid_formatter_template,?MODULE,T}} +do_check_config([{template,T}|Config]) -> + case check_template(T) of + ok -> do_check_config(Config); + error -> {error,{invalid_formatter_template,?MODULE,T}} end; do_check_config([{time_offset,Offset}|Config]) -> case check_offset(Offset) of @@ -381,6 +402,42 @@ check_limit(unlimited) -> check_limit(_) -> error. +check_template([Key|T]) when is_atom(Key) -> + check_template(T); +check_template([Key|T]) when is_list(Key), is_atom(hd(Key)) -> + case lists:all(fun(X) when is_atom(X) -> true; + (_) -> false + end, + Key) of + true -> + check_template(T); + false -> + error + end; +check_template([{Key,IfExist,Else}|T]) + when is_atom(Key) orelse + (is_list(Key) andalso is_atom(hd(Key))) -> + case check_template(IfExist) of + ok -> + case check_template(Else) of + ok -> + check_template(T); + error -> + error + end; + error -> + error + end; +check_template([Str|T]) when is_list(Str) -> + case io_lib:printable_unicode_list(Str) of + true -> check_template(T); + false -> error + end; +check_template([]) -> + ok; +check_template(_) -> + error. + check_offset(I) when is_integer(I) -> ok; check_offset(Tz) when Tz=:=""; Tz=:="Z"; Tz=:="z" -> diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 336398cd4a..d556938f02 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -24,13 +24,15 @@ -export([log_to_binary/2, check_common_config/1, - call_cast_or_drop/2, + call_cast_or_drop/4, check_load/1, limit_burst/1, - kill_if_choked/4, - flush_log_requests/0, - flush_log_requests/1, + kill_if_choked/5, + flush_log_events/0, + flush_log_events/1, handler_exit/2, + set_restart_flag/2, + unset_restart_flag/2, cancel_timer/1, stop_or_restart/3, overload_levels_ok/1, @@ -41,7 +43,7 @@ %%% Covert log data on any form to binary -spec log_to_binary(LogEvent,Config) -> LogString when LogEvent :: logger:log_event(), - Config :: logger:config(), + Config :: logger:handler_config(), LogString :: binary(). log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) -> do_log_to_binary(Log,Config); @@ -52,7 +54,8 @@ log_to_binary(Log,Config) -> do_log_to_binary(Log,Config). do_log_to_binary(Log,Config) -> - {Formatter,FormatterConfig} = maps:get(formatter,Config), + {Formatter,FormatterConfig} = + maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), String = try_format(Log,Formatter,FormatterConfig), try unicode:characters_to_binary(String) catch _:_ -> @@ -84,29 +87,37 @@ try_format(Log,Formatter,FormatterConfig) -> %%%----------------------------------------------------------------- %%% Check that the configuration term is valid -check_common_config({toggle_sync_qlen,N}) when is_integer(N) -> +check_common_config({mode_tab,_Tid}) -> valid; -check_common_config({drop_new_reqs_qlen,N}) when is_integer(N) -> +check_common_config({handler_pid,Pid}) when is_pid(Pid) -> valid; -check_common_config({flush_reqs_qlen,N}) when is_integer(N) -> + +check_common_config({sync_mode_qlen,N}) when is_integer(N) -> + valid; +check_common_config({drop_mode_qlen,N}) when is_integer(N) -> + valid; +check_common_config({flush_qlen,N}) when is_integer(N) -> valid; -check_common_config({enable_burst_limit,Bool}) when Bool == true; + +check_common_config({burst_limit_enable,Bool}) when Bool == true; Bool == false -> valid; -check_common_config({burst_limit_size,N}) when is_integer(N) -> +check_common_config({burst_limit_max_count,N}) when is_integer(N) -> valid; -check_common_config({burst_window_time,N}) when is_integer(N) -> +check_common_config({burst_limit_window_time,N}) when is_integer(N) -> valid; -check_common_config({enable_kill_overloaded,Bool}) when Bool == true; - Bool == false -> + +check_common_config({overload_kill_enable,Bool}) when Bool == true; + Bool == false -> valid; -check_common_config({handler_overloaded_qlen,N}) when is_integer(N) -> +check_common_config({overload_kill_qlen,N}) when is_integer(N) -> valid; -check_common_config({handler_overloaded_mem,N}) when is_integer(N) -> +check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> valid; -check_common_config({handler_restart_after,NorA}) when is_integer(NorA); - NorA == never -> +check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); + NorA == never -> valid; + check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); NorA == no_repeat -> valid; @@ -116,16 +127,16 @@ check_common_config(_) -> %%%----------------------------------------------------------------- %%% Overload Protection -call_cast_or_drop(Name, Bin) -> - %% If the handler process is getting overloaded, the log request +call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> + %% If the handler process is getting overloaded, the log event %% will be synchronous instead of asynchronous (slows down the %% logging tempo of a process doing lots of logging. If the - %% handler is choked, drop mode is set and no request will be sent. - try ?get_mode(Name) of + %% handler is choked, drop mode is set and no event will be sent. + try ?get_mode(ModeTab) of async -> - gen_server:cast(Name, {log,Bin}); + gen_server:cast(HandlerPid, {log,Bin}); sync -> - try gen_server:call(Name, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of + try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of %% if return value from call == dropped, the %% message has been flushed by handler and should %% therefore not be counted as dropped in stats @@ -133,32 +144,50 @@ call_cast_or_drop(Name, Bin) -> dropped -> ok catch _:{timeout,_} -> - ?observe(Name,{dropped,1}) + ?observe(_Name,{dropped,1}) end; drop -> - ?observe(Name,{dropped,1}) + ?observe(_Name,{dropped,1}) catch %% if the ETS table doesn't exist (maybe because of a - %% handler restart), we can only drop the request - _:_ -> ?observe(Name,{dropped,1}) + %% handler restart), we can only drop the event + _:_ -> ?observe(_Name,{dropped,1}) end, ok. handler_exit(_Name, Reason) -> exit(Reason). -check_load(State = #{id:=Name, mode := Mode, - toggle_sync_qlen := ToggleSyncQLen, - drop_new_reqs_qlen := DropNewQLen, - flush_reqs_qlen := FlushQLen}) -> +set_restart_flag(Name, Module) -> + Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), + spawn(fun() -> + register(Flag, self()), + timer:sleep(infinity) + end), + ok. + +unset_restart_flag(Name, Module) -> + Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), + case whereis(Flag) of + undefined -> + false; + Pid -> + exit(Pid, kill), + true + end. + +check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, + sync_mode_qlen := SyncModeQLen, + drop_mode_qlen := DropModeQLen, + flush_qlen := FlushQLen}) -> {_,Mem} = process_info(self(), memory), - ?observe(Name,{max_mem,Mem}), + ?observe(_Name,{max_mem,Mem}), {_,QLen} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,QLen}), + ?observe(_Name,{max_qlen,QLen}), %% When the handler process gets scheduled in, it's impossible %% to predict the QLen. We could jump "up" arbitrarily from say %% async to sync, async to drop, sync to flush, etc. However, when - %% the handler process manages the log requests (without flushing), + %% the handler process manages the log events (without flushing), %% one after the other, we will move "down" from drop to sync and %% from sync to async. This way we don't risk getting stuck in %% drop or sync mode with an empty mailbox. @@ -166,33 +195,33 @@ check_load(State = #{id:=Name, mode := Mode, if QLen >= FlushQLen -> {flush, 0,1}; - QLen >= DropNewQLen -> - %% Note that drop mode will force log requests to + QLen >= DropModeQLen -> + %% Note that drop mode will force log events to %% be dropped on the client side (never sent get to %% the handler). IncDrops = if Mode == drop -> 0; true -> 1 end, - {?change_mode(Name, Mode, drop), IncDrops,0}; - QLen >= ToggleSyncQLen -> - {?change_mode(Name, Mode, sync), 0,0}; + {?change_mode(ModeTab, Mode, drop), IncDrops,0}; + QLen >= SyncModeQLen -> + {?change_mode(ModeTab, Mode, sync), 0,0}; true -> - {?change_mode(Name, Mode, async), 0,0} + {?change_mode(ModeTab, Mode, async), 0,0} end, State1 = ?update_other(drops,DROPS,_NewDrops,State), {Mode1, QLen, Mem, ?update_other(flushes,FLUSHES,_NewFlushes, State1#{last_qlen => QLen})}. -limit_burst(#{enable_burst_limit := false}) -> +limit_burst(#{burst_limit_enable := false}) -> {true,0,0}; limit_burst(#{burst_win_ts := BurstWinT0, burst_msg_count := BurstMsgCount, - burst_window_time := BurstWinTime, - burst_limit_size := BurstLimitSz}) -> - if (BurstMsgCount >= BurstLimitSz) -> + burst_limit_window_time := BurstLimitWinTime, + burst_limit_max_count := BurstLimitMaxCnt}) -> + if (BurstMsgCount >= BurstLimitMaxCnt) -> %% the limit for allowed messages has been reached BurstWinT1 = ?timestamp(), case ?diff_time(BurstWinT1,BurstWinT0) of - BurstCheckTime when BurstCheckTime < (BurstWinTime*1000) -> + BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> %% we're still within the burst time frame {false,BurstWinT0,BurstMsgCount}; _BurstCheckTime -> @@ -204,38 +233,42 @@ limit_burst(#{burst_win_ts := BurstWinT0, {true,BurstWinT0,BurstMsgCount+1} end. -kill_if_choked(Name, QLen, Mem, - #{enable_kill_overloaded := KillIfOL, - handler_overloaded_qlen := HOLQLen, - handler_overloaded_mem := HOLMem}) -> +kill_if_choked(Name, QLen, Mem, HandlerMod, + State = #{overload_kill_enable := KillIfOL, + overload_kill_qlen := OLKillQLen, + overload_kill_mem_size := OLKillMem}) -> if KillIfOL andalso - ((QLen > HOLQLen) orelse (Mem > HOLMem)) -> + ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> + HandlerMod:log_handler_info(Name, + "Handler ~p overloaded and stopping", + [Name], State), + set_restart_flag(Name, HandlerMod), handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}}); true -> ok end. -flush_log_requests() -> - flush_log_requests(-1). +flush_log_events() -> + flush_log_events(-1). -flush_log_requests(Limit) -> +flush_log_events(Limit) -> process_flag(priority, high), - Flushed = flush_log_requests(0, Limit), + Flushed = flush_log_events(0, Limit), process_flag(priority, normal), Flushed. -flush_log_requests(Limit, Limit) -> +flush_log_events(Limit, Limit) -> Limit; -flush_log_requests(N, Limit) -> - %% flush log requests but leave other requests, such as +flush_log_events(N, Limit) -> + %% flush log events but leave other events, such as %% file/disk_log_sync, info and change_config, so that these %% have a chance to be processed even under heavy load receive {'$gen_cast',{log,_}} -> - flush_log_requests(N+1, Limit); + flush_log_events(N+1, Limit); {'$gen_call',{Pid,MRef},{log,_}} -> Pid ! {MRef, dropped}, - flush_log_requests(N+1, Limit) + flush_log_events(N+1, Limit) after 0 -> N end. @@ -245,7 +278,7 @@ cancel_timer(TRef) -> timer:cancel(TRef). stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, - #{handler_restart_after := RestartAfter}) -> + #{overload_kill_restart_after := RestartAfter}) -> %% If we're terminating because of an overload situation (see %% logger_h_common:kill_if_choked/4), we need to remove the handler %% and set a restart timer. A separate process must perform this @@ -262,7 +295,7 @@ stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, exit(HandlerPid, kill) end, case logger:get_handler_config(Name) of - {ok,{HMod,HConfig}} when is_integer(RestartAfter) -> + {ok,#{module:=HMod}=HConfig} when is_integer(RestartAfter) -> _ = logger:remove_handler(Name), _ = timer:apply_after(RestartAfter, logger, add_handler, [Name,HMod,HConfig]); @@ -293,10 +326,10 @@ stop_or_restart(_Name, _Reason, _State) -> ok. overload_levels_ok(HandlerConfig) -> - TSQL = maps:get(toggle_sync_qlen, HandlerConfig, ?TOGGLE_SYNC_QLEN), - DNRQL = maps:get(drop_new_reqs_qlen, HandlerConfig, ?DROP_NEW_REQS_QLEN), - FRQL = maps:get(flush_reqs_qlen, HandlerConfig, ?FLUSH_REQS_QLEN), - (DNRQL > 1) andalso (TSQL =< DNRQL) andalso (DNRQL =< FRQL). + SMQL = maps:get(sync_mode_qlen, HandlerConfig, ?SYNC_MODE_QLEN), + DMQL = maps:get(drop_mode_qlen, HandlerConfig, ?DROP_MODE_QLEN), + FQL = maps:get(flush_qlen, HandlerConfig, ?FLUSH_QLEN), + (DMQL > 1) andalso (SMQL =< DMQL) andalso (DMQL =< FQL). error_notify(Term) -> ?internal_log(error, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index ed365ce6eb..ad80b51109 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -4,47 +4,47 @@ %%! *** NOTE *** %%! It's important that: -%%! TOGGLE_SYNC_QLEN < DROP_NEW_REQS_QLEN < FLUSH_REQS_QLEN -%%! and that DROP_NEW_REQS_QLEN >= 2. +%%! SYNC_MODE_QLEN =< DROP_MODE_QLEN =< FLUSH_QLEN +%%! and that DROP_MODE_QLEN >= 2. %%! Otherwise the handler could end up in drop mode with no new %%! log requests to process. This would cause all future requests %%! to be dropped (no switch to async mode would ever take place). %% This specifies the message_queue_len value where the log %% requests switch from asynchronous casts to synchronous calls. --define(TOGGLE_SYNC_QLEN, 10). +-define(SYNC_MODE_QLEN, 10). %% Above this message_queue_len, log requests will be dropped, %% i.e. no log requests get sent to the handler process. --define(DROP_NEW_REQS_QLEN, 200). +-define(DROP_MODE_QLEN, 200). %% Above this message_queue_len, the handler process will flush %% its mailbox and only leave this number of messages in it. --define(FLUSH_REQS_QLEN, 1000). +-define(FLUSH_QLEN, 1000). %% Never flush more than this number of messages in one go, %% or the handler will be unresponsive for seconds (keep this %% number as large as possible or the mailbox could grow large). -define(FLUSH_MAX_N, 5000). -%% BURST_LIMIT is the max number of log requests allowed to be -%% written within a BURST_WINDOW_TIME time frame. --define(ENABLE_BURST_LIMIT, true). --define(BURST_LIMIT_SIZE, 500). --define(BURST_WINDOW_TIME, 1000). +%% BURST_LIMIT_MAX_COUNT is the max number of log requests allowed +%% to be written within a BURST_LIMIT_WINDOW_TIME time frame. +-define(BURST_LIMIT_ENABLE, true). +-define(BURST_LIMIT_MAX_COUNT, 500). +-define(BURST_LIMIT_WINDOW_TIME, 1000). %% This enables/disables the feature to automatically get the %% handler terminated if it gets too loaded (and can't keep up). --define(ENABLE_KILL_OVERLOADED, false). +-define(OVERLOAD_KILL_ENABLE, false). %% If the message_queue_len goes above this size even after %% flushing has been performed, the handler is terminated. --define(HANDLER_OVERLOADED_QLEN, 20000). +-define(OVERLOAD_KILL_QLEN, 20000). %% If the memory usage exceeds this level --define(HANDLER_OVERLOADED_MEM, 3000000). +-define(OVERLOAD_KILL_MEM_SIZE, 3000000). %% This is the default time that the handler will wait before %% restarting and accepting new requests. The value 'never' %% disables restarts. --define(HANDLER_RESTART_AFTER, 5000). -%%-define(HANDLER_RESTART_AFTER, never). +-define(OVERLOAD_KILL_RESTART_AFTER, 5000). +%%-define(OVERLOAD_KILL_RESTART_AFTER, never). %% The handler sends asynchronous write requests to the process %% controlling the i/o device, but every once in this interval @@ -77,29 +77,30 @@ -define(DISK_LOG_MAX_NO_BYTES, 1048576). %%%----------------------------------------------------------------- +%%% Utility macros + +-define(name_to_reg_name(MODULE,Name), + list_to_atom(lists:concat([MODULE,"_",Name]))). + +%%%----------------------------------------------------------------- %%% Overload protection macros -define(timestamp(), erlang:monotonic_time(microsecond)). --define(get_mode(HandlerName), - case ets:lookup(HandlerName, mode) of - [{mode,sync}] -> - case whereis(HandlerName)==self() of - true -> async; - _ -> sync - end; +-define(get_mode(Tid), + case ets:lookup(Tid, mode) of [{mode,M}] -> M; _ -> async end). --define(set_mode(HandlerName, M), - begin ets:insert(HandlerName, {mode,M}), M end). +-define(set_mode(Tid, M), + begin ets:insert(Tid, {mode,M}), M end). --define(change_mode(HandlerName, M0, M1), +-define(change_mode(Tid, M0, M1), if M0 == M1 -> M0; true -> - ets:insert(HandlerName, {mode,M1}), + ets:insert(Tid, {mode,M1}), M1 end). @@ -124,7 +125,7 @@ %%% slow down execution and therefore should not be include in code %%% to be officially released. --define(TEST_HOOKS, true). +%%-define(TEST_HOOKS, true). -ifdef(TEST_HOOKS). -define(TEST_HOOKS_TAB, logger_h_test_hooks). diff --git a/lib/kernel/src/logger_internal.hrl b/lib/kernel/src/logger_internal.hrl index fedd6db370..8941409a25 100644 --- a/lib/kernel/src/logger_internal.hrl +++ b/lib/kernel/src/logger_internal.hrl @@ -19,12 +19,11 @@ %% -include_lib("kernel/include/logger.hrl"). -define(LOGGER_TABLE,logger). --define(LOGGER_KEY,'$logger_config$'). +-define(PRIMARY_KEY,'$primary_config$'). -define(HANDLER_KEY,'$handler_config$'). -define(LOGGER_META_KEY,'$logger_metadata$'). -define(STANDARD_HANDLER, default). --define(DEFAULT_HANDLER_FILTERS, - ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp])). +-define(DEFAULT_HANDLER_FILTERS,?DEFAULT_HANDLER_FILTERS([otp])). -define(DEFAULT_HANDLER_FILTERS(Domain), [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, {domain,{fun logger_filters:domain/2,{log,super,Domain}}}, @@ -33,7 +32,7 @@ -define(DEFAULT_FORMAT_CONFIG,#{legacy_header=>true, single_line=>false}). -define(DEFAULT_FORMAT_TEMPLATE_HEADER, - [{logger_formatter,header},"\n",msg,"\n"]). + [[logger_formatter,header],"\n",msg,"\n"]). -define(DEFAULT_FORMAT_TEMPLATE_SINGLE, [time," ",level,": ",msg,"\n"]). -define(DEFAULT_FORMAT_TEMPLATE, @@ -55,14 +54,17 @@ %%%----------------------------------------------------------------- %%% Levels %%% Using same as syslog --define(LEVELS,[emergency, +-define(LEVELS,[none, + emergency, alert, critical, error, warning, notice, info, - debug]). + debug, + all]). +-define(LOG_NONE,-1). -define(EMERGENCY,0). -define(ALERT,1). -define(CRITICAL,2). @@ -71,6 +73,7 @@ -define(NOTICE,5). -define(INFO,6). -define(DEBUG,7). +-define(LOG_ALL,10). -define(IS_LEVEL(L), (L=:=emergency orelse diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index 024b9dfa39..e50954fc40 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -25,8 +25,8 @@ -export([start_link/0, add_handler/3, remove_handler/1, add_filter/2, remove_filter/2, - set_module_level/2, unset_module_level/1, - cache_module_level/1, + set_module_level/2, unset_module_level/0, + unset_module_level/1, cache_module_level/1, set_config/2, set_config/3, update_config/2, update_formatter_config/2]). @@ -53,7 +53,7 @@ add_handler(Id,Module,Config0) -> {ok,ok} -> case sanity_check(Id,Config0) of ok -> - Default = default_config(Id), + Default = default_config(Id,Module), Config = maps:merge(Default,Config0), call({add_handler,Id,Module,Config}); Error -> @@ -75,30 +75,41 @@ add_filter(Owner,Filter) -> remove_filter(Owner,FilterId) -> call({remove_filter,Owner,FilterId}). -set_module_level(Module,Level) when is_atom(Module) -> - case sanity_check(logger,level,Level) of - ok -> call({set_module_level,Module,Level}); - Error -> Error +set_module_level(Modules,Level) when is_list(Modules) -> + case lists:all(fun(M) -> is_atom(M) end,Modules) of + true -> + case sanity_check(primary,level,Level) of + ok -> call({set_module_level,Modules,Level}); + Error -> Error + end; + false -> + {error,{not_a_list_of_modles,Modules}} end; -set_module_level(Module,_) -> - {error,{not_a_module,Module}}. +set_module_level(Modules,_) -> + {error,{not_a_list_of_modules,Modules}}. + +unset_module_level() -> + call({unset_module_level,all}). -unset_module_level(Module) when is_atom(Module) -> - call({unset_module_level,Module}); -unset_module_level(Module) -> - {error,{not_a_module,Module}}. +unset_module_level(Modules) when is_list(Modules) -> + case lists:all(fun(M) -> is_atom(M) end,Modules) of + true -> + call({unset_module_level,Modules}); + false -> + {error,{not_a_list_of_modles,Modules}} + end; +unset_module_level(Modules) -> + {error,{not_a_list_of_modules,Modules}}. cache_module_level(Module) -> gen_server:cast(?SERVER,{cache_module_level,Module}). - set_config(Owner,Key,Value) -> update_config(Owner,#{Key=>Value}). -set_config(Owner,Config0) -> - case sanity_check(Owner,Config0) of +set_config(Owner,Config) -> + case sanity_check(Owner,Config) of ok -> - Config = maps:merge(default_config(Owner),Config0), call({set_config,Owner,Config}); Error -> Error @@ -127,10 +138,10 @@ init([]) -> process_flag(trap_exit, true), put(?LOGGER_SERVER_TAG,true), Tid = logger_config:new(?LOGGER_TABLE), - LoggerConfig = maps:merge(default_config(logger), + PrimaryConfig = maps:merge(default_config(primary), #{handlers=>[simple]}), - logger_config:create(Tid,logger,LoggerConfig), - SimpleConfig0 = maps:merge(default_config(simple), + logger_config:create(Tid,primary,PrimaryConfig), + SimpleConfig0 = maps:merge(default_config(simple,logger_simple_h), #{filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS}), %% If this fails, then the node should crash @@ -155,9 +166,9 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> case erlang:function_exported(Module, log, 2) of true -> logger_config:create(Tid,Id,Module,HConfig1), - {ok,Config} = do_get_config(Tid,logger), + {ok,Config} = do_get_config(Tid,primary), Handlers = maps:get(handlers,Config,[]), - do_set_config(Tid,logger, + do_set_config(Tid,primary, Config#{handlers=>[Id|Handlers]}); false -> {error,{invalid_handler, @@ -171,7 +182,7 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of {ok,{Module,HConfig}} -> - {ok,Config} = do_get_config(Tid,logger), + {ok,Config} = do_get_config(Tid,primary), Handlers0 = maps:get(handlers,Config,[]), Handlers = lists:delete(HandlerId,Handlers0), call_h_async( @@ -180,7 +191,7 @@ handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> call_h(Module,removing_handler,[HConfig],ok) end, fun(_Res) -> - do_set_config(Tid,logger,Config#{handlers=>Handlers}), + do_set_config(Tid,primary,Config#{handlers=>Handlers}), logger_config:delete(Tid,HandlerId), ok end,From,State); @@ -204,13 +215,15 @@ handle_call({update_config,Id,NewConfig}, From, #state{tid=Tid}=State) -> Error -> {reply,Error,State} end; -handle_call({set_config,logger,Config}, _From, #state{tid=Tid}=State) -> - {ok,#{handlers:=Handlers}} = logger_config:get(Tid,logger), - Reply = do_set_config(Tid,logger,Config#{handlers=>Handlers}), +handle_call({set_config,primary,Config0}, _From, #state{tid=Tid}=State) -> + Config = maps:merge(default_config(primary),Config0), + {ok,#{handlers:=Handlers}} = logger_config:get(Tid,primary), + Reply = do_set_config(Tid,primary,Config#{handlers=>Handlers}), {reply,Reply,State}; -handle_call({set_config,HandlerId,Config}, From, #state{tid=Tid}=State) -> +handle_call({set_config,HandlerId,Config0}, From, #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of {ok,{Module,OldConfig}} -> + Config = maps:merge(default_config(HandlerId,Module),Config0), call_h_async( fun() -> call_h(Module,changing_config,[OldConfig,Config], @@ -240,11 +253,11 @@ handle_call({update_formatter_config,HandlerId,NewFConfig},_From, {error,{not_found,HandlerId}} end, {reply,Reply,State}; -handle_call({set_module_level,Module,Level}, _From, #state{tid=Tid}=State) -> - Reply = logger_config:set_module_level(Tid,Module,Level), +handle_call({set_module_level,Modules,Level}, _From, #state{tid=Tid}=State) -> + Reply = logger_config:set_module_level(Tid,Modules,Level), {reply,Reply,State}; -handle_call({unset_module_level,Module}, _From, #state{tid=Tid}=State) -> - Reply = logger_config:unset_module_level(Tid,Module), +handle_call({unset_module_level,Modules}, _From, #state{tid=Tid}=State) -> + Reply = logger_config:unset_module_level(Tid,Modules), {reply,Reply,State}. handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) -> @@ -271,7 +284,7 @@ handle_info({Ref,_Reply},State) when is_reference(Ref) -> handle_info({'DOWN',_Ref,_Proc,_Pid,_Reason} = Down,State) -> call_h_reply(Down,State); handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' -> - %% The simple logger will send an 'EXIT' message when it is replaced + %% The simple handler will send an 'EXIT' message when it is replaced %% We may as well ignore all 'EXIT' messages that we get ?LOG_INTERNAL(debug, [{logger,got_unexpected_message}, @@ -344,16 +357,18 @@ do_set_config(Tid,Id,Config) -> logger_config:set(Tid,Id,Config), ok. -default_config(logger) -> - #{level=>info, +default_config(primary) -> + #{level=>notice, filters=>[], filter_default=>log}; default_config(Id) -> #{id=>Id, - level=>info, + level=>all, filters=>[], filter_default=>log, formatter=>{?DEFAULT_FORMATTER,#{}}}. +default_config(Id,Module) -> + (default_config(Id))#{module=>Module}. sanity_check(Owner,Key,Value) -> sanity_check_1(Owner,[{Key,Value}]). @@ -370,8 +385,8 @@ sanity_check_1(Owner,Config) when is_list(Config) -> catch throw:Error -> {error,Error} end. -get_type(logger) -> - logger; +get_type(primary) -> + primary; get_type(Id) -> check_id(Id), handler. @@ -388,8 +403,8 @@ check_config(Owner,[{filter_default,FD}|Config]) -> check_config(handler,[{formatter,Formatter}|Config]) -> check_formatter(Formatter), check_config(handler,Config); -check_config(logger,[C|_]) -> - throw({invalid_logger_config,C}); +check_config(primary,[C|_]) -> + throw({invalid_primary_config,C}); check_config(handler,[{_,_}|Config]) -> %% Arbitrary config elements are allowed for handlers check_config(handler,Config); diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 63c3ab2dac..ce9daa50ab 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -28,15 +28,17 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([start_link/3, info/1, sync/1, reset/1]). %% gen_server and proc_lib callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). %% logger callbacks --export([log/2, adding_handler/1, removing_handler/1, - changing_config/2, swap_buffer/2]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). + +%% handler internal +-export([log_handler_info/4]). %%%=================================================================== %%% API @@ -48,7 +50,7 @@ %%% handler process gets added -spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when Name :: atom(), - Config :: logger:config(), + Config :: logger:handler_config(), HandlerState :: map(), Pid :: pid(), Reason :: term(). @@ -58,18 +60,19 @@ start_link(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% --spec filesync(Name) -> ok | {error,Reason} when +-spec sync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> +sync(Name) when is_atom(Name) -> try - gen_server:call(Name, filesync, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + filesync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; -filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. +sync(Name) -> + {error,{badarg,{sync,[Name]}}}. %%%----------------------------------------------------------------- %%% @@ -80,7 +83,8 @@ filesync(Name) -> info(Name) when is_atom(Name) -> try - gen_server:call(Name, info, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + info, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -95,7 +99,8 @@ info(Name) -> reset(Name) when is_atom(Name) -> try - gen_server:call(Name, reset, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + reset, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -113,23 +118,16 @@ adding_handler(#{id:=Name}=Config) -> case check_config(adding, Config) of {ok, Config1} -> %% create initial handler state by merging defaults with config - HConfig = maps:get(?MODULE, Config1, #{}), + HConfig = maps:get(config, Config1, #{}), HState = maps:merge(get_init_state(), HConfig), case logger_h_common:overload_levels_ok(HState) of true -> - case start(Name, Config1, HState) of - ok -> - %% Make sure wait_for_buffer is not stored, so we - %% won't hang and wait for buffer on a restart - {ok, maps:remove(wait_for_buffer,Config1)}; - Error -> - Error - end; + start(Name, Config1, HState); false -> - #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = HState, - {error,{invalid_levels,{TSQL,DNRQL,FRQL}}} + #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = HState, + {error,{invalid_levels,{SMQL,DMQL,FQL}}} end; Error -> Error @@ -137,24 +135,27 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, ?MODULE:=#{type:=Type}}, +changing_config(OldConfig=#{id:=Name, config:=OldHConfig}, NewConfig=#{id:=Name}) -> - MyConfig = maps:get(?MODULE, NewConfig, #{}), - case maps:get(type, MyConfig, Type) of + #{type:=Type, handler_pid:=HPid, mode_tab:=ModeTab} = OldHConfig, + NewHConfig = maps:get(config, NewConfig, #{}), + case maps:get(type, NewHConfig, Type) of Type -> - MyConfig1 = MyConfig#{type=>Type}, - changing_config1(Name, OldConfig, - NewConfig#{?MODULE=>MyConfig1}); + NewHConfig1 = NewHConfig#{type=>Type, + handler_pid=>HPid, + mode_tab=>ModeTab}, + changing_config1(HPid, OldConfig, + NewConfig#{config=>NewHConfig1}); _ -> {error,{illegal_config_change,OldConfig,NewConfig}} end; changing_config(OldConfig, NewConfig) -> {error,{illegal_config_change,OldConfig,NewConfig}}. -changing_config1(Name, OldConfig, NewConfig) -> +changing_config1(HPid, OldConfig, NewConfig) -> case check_config(changing, NewConfig) of Result = {ok,NewConfig1} -> - try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, + try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, ?DEFAULT_CALL_TIMEOUT) of ok -> Result; HError -> HError @@ -167,38 +168,38 @@ changing_config1(Name, OldConfig, NewConfig) -> check_config(adding, Config) -> %% Merge in defaults on handler level - MyConfig0 = maps:get(?MODULE, Config, #{}), - MyConfig = maps:merge(#{type => standard_io}, - MyConfig0), - case check_my_config(maps:to_list(MyConfig)) of + HConfig0 = maps:get(config, Config, #{}), + HConfig = maps:merge(#{type => standard_io}, + HConfig0), + case check_h_config(maps:to_list(HConfig)) of ok -> - {ok,Config#{?MODULE=>MyConfig}}; + {ok,Config#{config=>HConfig}}; Error -> Error end; check_config(changing, Config) -> - MyConfig = maps:get(?MODULE, Config, #{}), - case check_my_config(maps:to_list(MyConfig)) of + HConfig = maps:get(config, Config, #{}), + case check_h_config(maps:to_list(HConfig)) of ok -> {ok,Config}; Error -> Error end. -check_my_config([{type,Type} | Config]) when Type == standard_io; - Type == standard_error -> - check_my_config(Config); -check_my_config([{type,{file,File}} | Config]) when is_list(File) -> - check_my_config(Config); -check_my_config([{type,{file,File,Modes}} | Config]) when is_list(File), - is_list(Modes) -> - check_my_config(Config); -check_my_config([Other | Config]) -> +check_h_config([{type,Type} | Config]) when Type == standard_io; + Type == standard_error -> + check_h_config(Config); +check_h_config([{type,{file,File}} | Config]) when is_list(File) -> + check_h_config(Config); +check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), + is_list(Modes) -> + check_h_config(Config); +check_h_config([Other | Config]) -> case logger_h_common:check_common_config(Other) of valid -> - check_my_config(Config); + check_h_config(Config); invalid -> {error,{invalid_config,?MODULE,Other}} end; -check_my_config([]) -> +check_h_config([]) -> ok. @@ -208,35 +209,27 @@ removing_handler(#{id:=Name}) -> stop(Name). %%%----------------------------------------------------------------- -%%% Get buffer when swapping from simple handler -swap_buffer(Name,Buffer) -> - case whereis(Name) of - undefined -> - ok; - _ -> - Name ! {buffer,Buffer} - end. - -%%%----------------------------------------------------------------- %%% Log a string or report -spec log(LogEvent, Config) -> ok | dropped when LogEvent :: logger:log_event(), - Config :: logger:config(). + Config :: logger:handler_config(). -log(LogEvent,Config=#{id:=Name}) -> - %% if the handler has crashed, we must drop this request +log(LogEvent, Config = #{id := Name, + config := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> + %% if the handler has crashed, we must drop this event %% and hope the handler restarts so we can try again - true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(LogEvent,Config), - logger_h_common:call_cast_or_drop(Name, Bin). + true = is_process_alive(HPid), + Bin = logger_h_common:log_to_binary(LogEvent, Config), + logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). %%%=================================================================== %%% gen_server callbacks %%%=================================================================== -init([Name, Config, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - register(Name, self()), +init([Name, Config = #{config := HConfig}, + State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> + register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), process_flag(message_queue_data, off_heap), @@ -245,59 +238,59 @@ init([Name, Config, case do_init(Name, Type) of {ok,InitState} -> - catch ets:new(Name, [public, named_table]), - ?set_mode(Name, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - proc_lib:init_ack({ok,self()}), - gen_server:cast(self(), repeated_filesync), - enter_loop(Config, State1); + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + State = maps:merge(State0, InitState), + T0 = ?timestamp(), + State1 = + ?merge_with_stats(State#{ + mode_tab => ModeTab, + mode => async, + file_ctrl_sync => FileCtrlSyncInt, + last_qlen => 0, + last_log_ts => T0, + last_op => sync, + burst_win_ts => T0, + burst_msg_count => 0}), + Config1 = + Config#{config => HConfig#{handler_pid => self(), + mode_tab => ModeTab}}, + proc_lib:init_ack({ok,self(),Config1}), + gen_server:cast(self(), repeated_filesync), + enter_loop(Config1, State1) + catch + _:Error -> + logger_h_common:error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; Error -> logger_h_common:error_notify({init_handler,Name,Error}), proc_lib:init_ack(Error) end. -do_init(Name, Std) when Std=:=standard_io; Std=:=standard_error -> - case open_log_file(Name, Std) of - {ok,FileCtrlPid} -> - {ok,#{id=>Name,type=>Std,file_ctrl_pid=>FileCtrlPid}}; - Error -> - Error - end; -do_init(Name, FileInfo) when is_tuple(FileInfo) -> - case open_log_file(Name, FileInfo) of +do_init(Name, Type) -> + case open_log_file(Name, Type) of {ok,FileCtrlPid} -> - {ok,#{id=>Name,type=>FileInfo,file_ctrl_pid=>FileCtrlPid}}; + case logger_h_common:unset_restart_flag(Name, ?MODULE) of + true -> + %% inform about restart + gen_server:cast(self(), {log_handler_info, + "Handler ~p restarted", + [Name]}); + false -> + %% initial start + ok + end, + {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -enter_loop(#{wait_for_buffer:=true}=Config,State) -> - State1 = - receive - {buffer,Buffer} -> - lists:foldl( - fun(Log,S) -> - Bin = logger_h_common:log_to_binary(Log,Config), - {_,S1} = do_log(Bin,cast,S), - S1 - end, - State, - Buffer) - end, - gen_server:enter_loop(?MODULE,[],State1); enter_loop(_Config,State) -> gen_server:enter_loop(?MODULE,[],State). -%% This is the synchronous log request. +%% This is the synchronous log event. handle_call({log, Bin}, _From, State) -> {Result,State1} = do_log(Bin, call, State), %% Result == ok | dropped @@ -313,7 +306,7 @@ handle_call(filesync, _From, State = #{type := Type, handle_call({change_config,_OldConfig,NewConfig}, _From, State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(?MODULE, NewConfig, #{}), + HConfig = maps:get(config, NewConfig, #{}), State1 = maps:merge(State, HConfig), case logger_h_common:overload_levels_ok(State1) of true -> @@ -335,10 +328,10 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, end, {reply, ok, State1}; false -> - #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = State1, - {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State} + #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = State1, + {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} end; handle_call(info, _From, State) -> @@ -352,15 +345,19 @@ handle_call(reset, _From, State) -> handle_call(stop, _From, State) -> {stop, {shutdown,stopped}, ok, State}. -%% This is the asynchronous log request. +%% This is the asynchronous log event. handle_cast({log, Bin}, State) -> {_,State1} = do_log(Bin, cast, State), {noreply, State1}; +handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> + log_handler_info(Name, Format, Args, State), + {noreply, State}; + %% 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 -%% request, the repeat operation must be active! +%% event, the repeat operation must be active! handle_cast(repeated_filesync, State = #{type := Type, file_ctrl_pid := FileCtrlPid, @@ -430,19 +427,19 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% get_init_state() -> - #{toggle_sync_qlen => ?TOGGLE_SYNC_QLEN, - drop_new_reqs_qlen => ?DROP_NEW_REQS_QLEN, - flush_reqs_qlen => ?FLUSH_REQS_QLEN, - enable_burst_limit => ?ENABLE_BURST_LIMIT, - burst_limit_size => ?BURST_LIMIT_SIZE, - burst_window_time => ?BURST_WINDOW_TIME, - enable_kill_overloaded => ?ENABLE_KILL_OVERLOADED, - handler_overloaded_qlen => ?HANDLER_OVERLOADED_QLEN, - handler_overloaded_mem => ?HANDLER_OVERLOADED_MEM, - handler_restart_after => ?HANDLER_RESTART_AFTER, - file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, + filesync_ok_qlen => ?FILESYNC_OK_QLEN, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Add a standard handler to the logger. @@ -451,9 +448,9 @@ get_init_state() -> %%% exist if the handler is not registered). %%% %%% Handler specific config should be provided with a sub map associated -%%% with a key named the same as this module, e.g: +%%% with a key named 'config', e.g: %%% -%%% Config = #{logger_std_h => #{toggle_sync_qlen => 50} +%%% Config = #{config => #{sync_mode_qlen => 50} %%% %%% The standard handler process is linked to logger_sup, which is %%% part of the kernel application's supervision tree. @@ -466,8 +463,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,_Pid} -> - ok; + {ok,_Pid,Config1} -> + {ok,Config1}; Error -> Error end. @@ -475,16 +472,16 @@ start(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% Stop and remove the handler. stop(Name) -> - case whereis(Name) of + 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). - _ = gen_server:call(Name,stop), + _ = gen_server:call(Pid, stop), _ = supervisor:delete_child(logger_sup, Name), ok end. @@ -495,21 +492,31 @@ stop(Name) -> if C == 0 -> Interval; true -> C-1 end). -%% check for overload between every request (and set Mode to async, +%% check for overload between every event (and set Mode to async, %% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize requests have been handled -do_log(Bin, CallOrCast, State = #{id:=Name}) -> +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> T1 = ?timestamp(), %% check if the handler is getting overloaded, or if it's %% recovering from overload (the check must be done for each - %% request to react quickly to large bursts of requests and + %% event to react quickly to large bursts of events and %% to ensure that the handler can never end up in drop mode %% with an empty mailbox, which would stop operation) {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, State), + logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), if Mode1 == flush -> flush(Name, QLen, T1, State1); @@ -519,10 +526,14 @@ do_log(Bin, CallOrCast, State = #{id:=Name}) -> %% this clause is called by do_log/3 after an overload check %% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> +flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> %% flush messages in the mailbox (a limited number in %% order to not cause long delays) - _NewFlushed = logger_h_common:flush_log_requests(?FLUSH_MAX_N), + NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), %% because of the receive loop when flushing messages, the %% handler will be scheduled out often and the mailbox could @@ -530,50 +541,51 @@ flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> {_,_QLen1} = process_info(self(), message_queue_len), ?observe(Name,{max_qlen,_QLen1}), - %% Add 1 for the current log request - ?observe(Name,{flushed,_NewFlushed+1}), + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,_NewFlushed, - State1#{mode => ?set_mode(Name,async), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State1#{mode => ?set_mode(ModeTab,async), last_qlen => 0, last_log_ts => T1})}. %% this clause is called to write to file -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{file_ctrl_pid := FileCtrlPid, +write(_Name, Mode, T1, Bin, _CallOrCast, + State = #{mode_tab := ModeTab, + file_ctrl_pid := FileCtrlPid, file_ctrl_sync := FileCtrlSync, last_qlen := LastQLen, last_log_ts := T0, file_ctrl_sync_int := FileCtrlSyncInt}) -> %% check if we need to limit the number of writes - %% during a burst of log requests + %% during a burst of log events {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - %% only send a synhrounous request to the file controller process + %% only send a synhrounous event to the file controller process %% every FileCtrlSyncInt time, to give the handler time between %% file writes so it can keep up with incoming messages {Result,LastQLen1} = if DoWrite, FileCtrlSync == 0 -> - ?observe(Name,{_CallOrCast,1}), + ?observe(_Name,{_CallOrCast,1}), file_write_sync(FileCtrlPid, Bin, false), {ok,element(2, process_info(self(), message_queue_len))}; DoWrite -> - ?observe(Name,{_CallOrCast,1}), + ?observe(_Name,{_CallOrCast,1}), file_write_async(FileCtrlPid, Bin), {ok,LastQLen}; not DoWrite -> - ?observe(Name,{flushed,1}), + ?observe(_Name,{flushed,1}), {dropped,LastQLen} end, - %% Check if the time since the previous log request is long enough - + %% Check if the time since the previous log event is long enough - %% and the queue length small enough - to assume the mailbox has %% been emptied, and if so, do filesync operation and reset mode to %% async. Note that this is the best we can do to detect an idle %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log requests is fast and no new - %% request comes in after the last one, idle state won't be detected! + %% time between two consecutive log events is fast and no new + %% event comes in after the last one, idle state won't be detected! Time = ?diff_time(T1,T0), {Mode1,BurstMsgCount1} = if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso @@ -585,7 +597,7 @@ write(Name, Mode, T1, Bin, _CallOrCast, _File -> file_ctrl_filesync_async(FileCtrlPid) end, - {?change_mode(Name, Mode, async),0}; + {?change_mode(ModeTab, Mode, async),0}; true -> {Mode,BurstMsgCount} end, @@ -634,6 +646,20 @@ close_log_file(Fd) -> _ = file:datasync(Fd), _ = file:close(Fd). + +log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) -> + 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 = logger_h_common:log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = file_write_async(FileCtrlPid, Bin), + ok. + %%%----------------------------------------------------------------- %%% File control process @@ -706,7 +732,7 @@ file_ctrl_init(HandlerName, StdDev, Starter) -> file_ctrl_loop(Fd, Type, DevName, Synced, PrevWriteResult, PrevSyncResult, HandlerName) -> receive - %% asynchronous request + %% asynchronous event {log,Bin} -> Result = if Type == file -> write_to_dev(Fd, Bin, DevName, @@ -717,7 +743,7 @@ file_ctrl_loop(Fd, Type, DevName, Synced, file_ctrl_loop(Fd, Type, DevName, false, Result, PrevSyncResult, HandlerName); - %% synchronous request + %% synchronous event {{log,From,Bin,FileSync},MRef} -> if Type == file -> %% check that file hasn't been deleted @@ -790,7 +816,7 @@ sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> %% don't report same error twice PrevSyncResult; Error -> - logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), + logger_h_common:error_notify({HandlerName,sync,DevName,Error}), Error end. |