diff options
Diffstat (limited to 'lib/kernel/src')
| -rw-r--r-- | lib/kernel/src/error_logger.erl | 43 | ||||
| -rw-r--r-- | lib/kernel/src/file.erl | 2 | ||||
| -rw-r--r-- | lib/kernel/src/kernel.app.src | 5 | ||||
| -rw-r--r-- | lib/kernel/src/kernel.erl | 14 | ||||
| -rw-r--r-- | lib/kernel/src/logger.erl | 360 | ||||
| -rw-r--r-- | lib/kernel/src/logger_config.erl | 2 | ||||
| -rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 64 | ||||
| -rw-r--r-- | lib/kernel/src/logger_filters.erl | 6 | ||||
| -rw-r--r-- | lib/kernel/src/logger_formatter.erl | 175 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.erl | 16 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.hrl | 2 | ||||
| -rw-r--r-- | lib/kernel/src/logger_internal.hrl | 2 | ||||
| -rw-r--r-- | lib/kernel/src/logger_server.erl | 338 | ||||
| -rw-r--r-- | lib/kernel/src/logger_simple.erl | 69 | ||||
| -rw-r--r-- | lib/kernel/src/logger_std_h.erl | 22 |
15 files changed, 646 insertions, 474 deletions
diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index 47d0ca5ea3..6c3b308308 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -529,18 +529,38 @@ logfile(filename) -> Flag :: boolean(). tty(true) -> - case lists:member(error_logger_tty_h, which_report_handlers()) of - false -> - add_report_handler(error_logger_tty_h, []); - true -> - ignore - end, + _ = 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}}}} -> + 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]), + formatter=>{?DEFAULT_FORMATTER, + ?DEFAULT_FORMAT_CONFIG}, + logger_std_h=>#{type=>standard_io}}) + end; + true -> + ok + end, ok; tty(false) -> - delete_report_handler(error_logger_tty_h). + 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}}}} -> + logger:add_handler_filter(default,error_logger_tty_false, + {fun(_,_) -> stop end, ok}); + _ -> + ok + end, + ok. %%%----------------------------------------------------------------- - -spec limit_term(term()) -> term(). limit_term(Term) -> @@ -552,4 +572,9 @@ limit_term(Term) -> -spec get_format_depth() -> 'unlimited' | pos_integer(). get_format_depth() -> - logger:get_format_depth(). + case application:get_env(kernel, error_logger_format_depth) of + {ok, Depth} when is_integer(Depth) -> + max(10, Depth); + undefined -> + unlimited + end. diff --git a/lib/kernel/src/file.erl b/lib/kernel/src/file.erl index 57d8fc7a15..1d4e37196c 100644 --- a/lib/kernel/src/file.erl +++ b/lib/kernel/src/file.erl @@ -69,7 +69,7 @@ %% Types that can be used from other modules -- alphabetically ordered. -export_type([date_time/0, fd/0, file_info/0, filename/0, filename_all/0, - io_device/0, name/0, name_all/0, posix/0]). + io_device/0, mode/0, name/0, name_all/0, posix/0]). %%% Includes and defines -include("file_int.hrl"). diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index afffcd156e..23ac5b3444 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -140,7 +140,10 @@ inet_db, pg2]}, {applications, []}, - {env, []}, + {env, [{logger_level, info}, + {logger_sasl_compatible, false}, + {logger_log_progress, false} + ]}, {mod, {kernel, []}}, {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} ] diff --git a/lib/kernel/src/kernel.erl b/lib/kernel/src/kernel.erl index ae982c1741..b0e8c00bbf 100644 --- a/lib/kernel/src/kernel.erl +++ b/lib/kernel/src/kernel.erl @@ -30,17 +30,13 @@ %%% Callback functions for the kernel application. %%%----------------------------------------------------------------- start(_, []) -> + %% Setup the logger and configure the kernel logger environment + ok = logger:internal_init_logger(), case supervisor:start_link({local, kernel_sup}, kernel, []) of {ok, Pid} -> ok = erl_signal_handler:start(), - %% add error handler - case logger:setup_standard_handler() of - ok -> {ok, Pid, []}; - Error -> - %% Not necessary since the node will crash anyway: - exit(Pid, shutdown), - Error - end; + ok = logger:add_handlers(kernel), + {ok, Pid, []}; Error -> Error end. @@ -147,7 +143,7 @@ init([]) -> case init:get_argument(mode) of {ok, [["minimal"]]} -> {ok, {SupFlags, - [Code, File, StdError, User, Config, RefC, SafeSup, LoggerSup]}}; + [Code, File, StdError, User, LoggerSup, Config, RefC, SafeSup]}}; _ -> Rpc = #{id => rex, start => {rpc, start_link, []}, diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 98a9937111..a839f97e62 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -40,15 +40,18 @@ set_module_level/2, reset_module_level/1, set_logger_config/1, set_logger_config/2, set_handler_config/2, set_handler_config/3, - get_logger_config/0, get_handler_config/1]). + update_logger_config/1, update_handler_config/2, + get_logger_config/0, get_handler_config/1, + add_handlers/1]). + +%% Private configuration +-export([internal_init_logger/0]). %% Misc -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]). --export([setup_standard_handler/0, replace_simple_handler/3]). --export([limit_term/1, get_format_depth/0, get_max_size/0, get_utc_config/0]). %% Basic report formatting -export([format_report/1, format_otp_report/1]). @@ -93,8 +96,10 @@ term() => term()}. -type timestamp() :: integer(). +-type config_handler() :: {handler, handler_id(), module(), config()}. + -export_type([log/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]). + filter_id/0,filter/0,filter_arg/0,filter_return/0, config_handler/0]). %%%----------------------------------------------------------------- %%% API @@ -357,10 +362,22 @@ set_handler_config(HandlerId,Key,Value) -> 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_handler_config(HandlerId,Config) -> ok | {error,term()} when + HandlerId :: handler_id(), + Config :: config(). +update_handler_config(HandlerId,Config) -> + logger_server:update_config(HandlerId,Config). + -spec get_logger_config() -> {ok,Config} when Config :: config(). get_logger_config() -> - logger_config:get(?LOGGER_TABLE,logger). + {ok,Config} = logger_config:get(?LOGGER_TABLE,logger), + {ok,maps:remove(handlers,Config)}. -spec get_handler_config(HandlerId) -> {ok,{Module,Config}} | {error,term()} when HandlerId :: handler_id(), @@ -441,8 +458,9 @@ i() -> i(_Action = print) -> io:put_chars(i(string)); i(_Action = string) -> - #{logger := #{level := Level, handlers := Handlers, - filters := Filters, filter_default := FilterDefault}, + #{logger := #{level := Level, + filters := Filters, + filter_default := FilterDefault}, handlers := HandlerConfigs, module_levels := Modules} = i(term), [io_lib:format("Current logger configuration:~n", []), @@ -451,16 +469,15 @@ i(_Action = string) -> io_lib:format(" Filters: ~n", []), print_filters(4, Filters), io_lib:format(" Handlers: ~n", []), - print_handlers([C || {Id, _, _} = C <- HandlerConfigs, - lists:member(Id, Handlers)]), + 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=>Logger, - handlers=>Handlers, - module_levels=>Modules}. + #{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" @@ -504,118 +521,184 @@ print_module_levels({Module,Level}) -> print_module_levels(ModuleLevels) -> lists:map(fun print_module_levels/1, ModuleLevels). --spec setup_standard_handler() -> ok | {error,term()}. -setup_standard_handler() -> - case get_logger_type() of - {ok,silent} -> - Level = get_logger_level(), - ok = set_logger_config(level,Level), - remove_handler(logger_simple); - {ok,Type} -> - Level = get_logger_level(), - ok = set_logger_config(level,Level), - Filters = get_logger_filters(), - setup_standard_handler(Type,#{level=>Level, - filter_default=>stop, - filters=>Filters}); - Error -> - Error +-spec internal_init_logger() -> ok | {error,term()}. +%% This function is responsible for config of the logger +%% This is done before add_handlers because we want the +%% logger settings to take effect before the kernel supervisor +%% 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()), + + [case logger:add_logger_filter(Id, Filter) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {Id, Filter} <- get_logger_filters()], + + _ = [[case logger:set_module_level(Module, Level) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || Module <- Modules] + || {module_level, Level, Modules} <- get_logger_env()], + + case logger:set_handler_config(logger_simple,filters, + get_default_handler_filters()) of + ok -> ok; + {error,{not_found,logger_simple}} -> ok + end, + + init_kernel_handlers() + catch throw:Reason -> + ?LOG_ERROR("Invalid logger config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} end. --spec setup_standard_handler(Type,Config) -> ok | {error,term()} when - Type :: tty | standard_io | standard_error | {file,File} | - {file,File,Modes} | {disk_log,LogOpts} | false, - File :: file:filename(), - Modes :: [term()], % [file:mode()], or more specific? - Config :: config(), - LogOpts :: map(). -setup_standard_handler(false,#{level:=Level,filters:=Filters}) -> - case set_handler_config(logger_simple,level,Level) of - ok -> - set_handler_config(logger_simple,filters,Filters); - Error -> - Error - end; -setup_standard_handler(Type,Config) -> - {Module,TypeConfig} = get_type_config(Type), - replace_simple_handler(?STANDARD_HANDLER, - Module, - maps:merge(Config,TypeConfig)). - --spec replace_simple_handler(Id,Module,Config) -> ok | {error,term()} when - Id :: handler_id(), - Module :: module(), - Config :: config(). -replace_simple_handler(Id,Module,Config) -> - _ = code:ensure_loaded(Module), - DoBuffer = erlang:function_exported(Module,swap_buffer,2), - case add_handler(Id,Module,Config#{wait_for_buffer=>DoBuffer}) of - ok -> - if DoBuffer -> - {ok,Buffered} = logger_simple:get_buffer(), - _ = remove_handler(logger_simple), - Module:swap_buffer(?STANDARD_HANDLER,Buffered); - true -> - _ = remove_handler(logger_simple), - ok - end, - ok; - Error -> - Error +-spec init_kernel_handlers() -> ok | {error,term()}. +%% Setup the kernel environment variables to be correct +%% The actual handlers are started by a call to add_handlers. +init_kernel_handlers() -> + try + case get_logger_type() of + {ok,silent} -> + ok = logger:remove_handler(logger_simple); + {ok,false} -> + ok; + {ok,Type} -> + init_default_config(Type) + end + catch throw:Reason -> + ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} + end. + +-spec add_handlers(Application) -> ok | {error,term()} when + Application :: atom(); + (HandlerConfig) -> ok | {error,term()} when + HandlerConfig :: [config_handler()]. +%% This function is responsible for resolving the handler config +%% and then starting the correct handlers. This is done after the +%% kernel supervisor tree has been started as it needs the logger_sup. +add_handlers(App) when is_atom(App) -> + add_handlers(application:get_env(App, logger, [])); +add_handlers(HandlerConfig) -> + try + check_logger_config(HandlerConfig), + DefaultAdded = + lists:foldl( + fun({handler, default = Id, Module, Config}, _) + when not is_map_key(filters, Config) -> + %% The default handler should have a couple of extra filters + %% set on it by default. + DefConfig = #{ filter_default => stop, + filters => get_default_handler_filters()}, + setup_handler(Id, Module, maps:merge(DefConfig,Config)), + true; + ({handler, Id, Module, Config}, Default) -> + setup_handler(Id, Module, Config), + Default orelse Id == default; + (_, Default) -> Default + end, false, HandlerConfig), + %% If a default handler was added we try to remove the simple_logger + %% If the simple logger exists it will replay its log events + %% to the handler(s) added in the fold above. + _ = [case logger:remove_handler(logger_simple) of + ok -> ok; + {error,{not_found,logger_simple}} -> ok + end || DefaultAdded], + ok + catch throw:Reason -> + ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), + {error, {bad_config, {handler, Reason}}} end. +setup_handler(Id, Module, Config) -> + case logger:add_handler(Id, Module, Config) of + ok -> ok; + {error, Reason} -> throw(Reason) + end. + +check_logger_config(_) -> + ok. + +-spec get_logger_type() -> {ok, standard_io | false | silent | + {file, file:name_all()} | + {file, file:name_all(), [file:mode()]}}. get_logger_type() -> - Type0 = - case application:get_env(kernel, logger_dest) of - undefined -> - application:get_env(kernel, error_logger); - T -> - T - end, - case Type0 of + case application:get_env(kernel, error_logger) of {ok, tty} -> - {ok, tty}; + {ok, standard_io}; {ok, {file, File}} when is_list(File) -> {ok, {file, File}}; {ok, {file, File, Modes}} when is_list(File), is_list(Modes) -> {ok, {file, File, Modes}}; - {ok, {disk_log, File}} when is_list(File) -> - {ok, {disk_log, get_disk_log_config(File)}}; {ok, false} -> {ok, false}; {ok, silent} -> {ok, silent}; undefined -> - {ok, tty}; % default value + case lists:member({handler,default,undefined}, get_logger_env()) of + true -> + {ok, false}; + false -> + {ok, standard_io} % default value + end; {ok, Bad} -> - {error,{bad_config, {kernel, {logger_dest, Bad}}}} + throw({error_logger, Bad}) end. -get_disk_log_config(File) -> - Config1 = - case application:get_env(kernel,logger_disk_log_maxfiles) of - undefined -> #{}; - {ok,MF} -> #{max_no_files=>MF} - end, - Config2 = - case application:get_env(kernel,logger_disk_log_maxbytes) of - undefined -> Config1; - {ok,MB} -> Config1#{max_no_bytes=>MB} - end, - Config3 = - case application:get_env(kernel,logger_disk_log_type) of - undefined -> Config2; - {ok,T} -> Config1#{type=>T} - end, - Config3#{file=>File}. - get_logger_level() -> - case application:get_env(kernel,logger_level) of - undefined -> info; - {ok,Level} when ?IS_LEVEL(Level) -> Level + case application:get_env(kernel,logger_level,info) of + Level when ?IS_LEVEL(Level) -> + Level; + Level -> + throw({logger_level, Level}) + end. + +get_logger_filter_default() -> + case lists:keyfind(filters,1,get_logger_env()) of + {filters,Default,_} -> + Default; + false -> + log end. get_logger_filters() -> + lists:foldl( + fun({filters, _, Filters}, _Acc) -> + Filters; + (_, Acc) -> + Acc + end, [], get_logger_env()). + +%% This function looks at the kernel logger environment +%% and updates it so that the correct logger is configured +init_default_config(Type) when Type==standard_io; + Type==standard_error; + element(1,Type)==file -> + Env = get_logger_env(), + DefaultConfig = #{logger_std_h=>#{type=>Type}}, + NewLoggerEnv = + case lists:keyfind(default, 2, Env) of + {handler, default, Module, Config} -> + lists:map( + fun({handler, default, logger_std_h, _}) -> + %% Only want to add the logger_std_h config + %% if not configured by user AND the default + %% handler is still the logger_std_h. + {handler, default, Module, maps:merge(DefaultConfig,Config)}; + (Other) -> + Other + end, Env); + _ -> + %% Nothing has been configured, use default + [{handler, default, logger_std_h, DefaultConfig} | Env] + end, + application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]); +init_default_config(Type) -> + throw({illegal_logger_type,Type}). + +get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of true -> ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp]); @@ -631,77 +714,8 @@ get_logger_filters() -> Extra ++ ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp,sasl]) end. -get_type_config({disk_log,LogOpts}) -> - {logger_disk_log_h,#{disk_log_opts=>LogOpts}}; -get_type_config(tty) -> - %% This is only for backwards compatibility with error_logger and - %% old kernel and sasl environment variables - get_type_config(standard_io); -get_type_config(Type) when Type==standard_io; - Type==standard_error; - element(1,Type)==file -> - {logger_std_h,#{logger_std_h=>#{type=>Type}}}; -get_type_config(Type) -> - {error,{illegal_logger_type,Type}}. - -%%%----------------------------------------------------------------- --spec limit_term(term()) -> term(). - -limit_term(Term) -> - try get_format_depth() of - unlimited -> Term; - D -> io_lib:limit_term(Term, D) - catch error:badarg -> - %% This could happen during system termination, after - %% application_controller process is dead. - unlimited - end. - --spec get_format_depth() -> 'unlimited' | pos_integer(). - -get_format_depth() -> - Depth = - case application:get_env(kernel, logger_format_depth) of - {ok, D} when is_integer(D) -> - D; - undefined -> - case application:get_env(kernel, error_logger_format_depth) of - {ok, D} when is_integer(D) -> - D; - undefined -> - unlimited - end - end, - max(10, Depth). - --spec get_max_size() -> 'unlimited' | pos_integer(). - -get_max_size() -> - case application:get_env(kernel, logger_max_size) of - {ok, Size} when is_integer(Size) -> - max(50, Size); - undefined -> - unlimited - end. - --spec get_utc_config() -> boolean(). - -get_utc_config() -> - %% Kernel's logger_utc configuration overrides SASL utc_log, which - %% in turn overrides stdlib config - in order to have uniform - %% timestamps in log messages - case application:get_env(kernel, logger_utc) of - {ok, Val} -> Val; - undefined -> - case application:get_env(sasl, utc_log) of - {ok, Val} -> Val; - undefined -> - case application:get_env(stdlib, utc_log) of - {ok, Val} -> Val; - undefined -> false - end - end - end. +get_logger_env() -> + application:get_env(kernel, logger, []). %%%----------------------------------------------------------------- %%% Internal diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 799aea9617..40dc1b1e1b 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -31,7 +31,7 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table]), + _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), ets:whereis(Name). delete(Tid,Id) -> diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 0150fa781a..57c54ce27e 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -278,10 +278,11 @@ init([Name, Config = #{disk_log_opts := LogOpts}, 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,T0}), + gen_server:cast(self(), repeated_disk_log_sync), enter_loop(Config, State1); Error -> logger_h_common:error_notify({open_disk_log,Name,Error}), @@ -316,8 +317,7 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) -> {reply, Result, State1}; handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0, - last_log_ts := LastLogTS}) -> + State = #{filesync_repeat_interval := FSyncInt0}) -> HConfig = maps:get(?MODULE, NewConfig, #{}), State1 = #{toggle_sync_qlen := TSQL, drop_new_reqs_qlen := DNRQL, @@ -338,9 +338,8 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, undefined)), - _ = gen_server:cast(self(), {repeated_disk_log_sync, - LastLogTS}) - end, + _ = gen_server:cast(self(), repeated_disk_log_sync) + end, {reply, ok, State1}; false -> {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State} @@ -370,24 +369,23 @@ handle_cast({log, Bin}, State) -> %% 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! -handle_cast({repeated_disk_log_sync,LastLogTS0}, +handle_cast(repeated_disk_log_sync, State = #{id := Name, filesync_repeat_interval := FSyncInt, - last_log_ts := LastLogTS1}) -> + last_op := LastOp}) -> State1 = if is_integer(FSyncInt) -> %% only do filesync if something has been %% written since last time we checked - NewState = if LastLogTS1 == LastLogTS0 -> + NewState = if LastOp == sync -> State; true -> disk_log_sync(Name, State) end, {ok,TRef} = timer:apply_after(FSyncInt, gen_server,cast, - [self(), - {repeated_disk_log_sync,LastLogTS1}]), - NewState#{rep_sync_tref => TRef}; + [self(),repeated_disk_log_sync]), + NewState#{rep_sync_tref => TRef, last_op => sync}; true -> State end, @@ -649,10 +647,9 @@ close_disk_log(Name, _) -> ok. disk_log_write(Name, Bin, State) -> - Result = case ?disk_log_blog(Name, Bin) of ok -> - ok; + State#{prev_log_result => ok, last_op => write}; LogError -> _ = case maps:get(prev_log_result, State) of LogError -> @@ -664,29 +661,26 @@ disk_log_write(Name, Bin, State) -> LogOpts, LogError}) end, - LogError - end, - State#{prev_log_result => Result}. + State#{prev_log_result => LogError} + end. disk_log_sync(Name, State) -> - Result = - case ?disk_log_sync(Name) of - ok -> - ok; - SyncError -> - _ = case maps:get(prev_sync_result, State) of - SyncError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,sync, - LogOpts, - SyncError}) - end, - SyncError - end, - State#{prev_sync_result => Result}. + case ?disk_log_sync(Name) of + ok -> + State#{prev_sync_result => ok, last_op => sync}; + SyncError -> + _ = case maps:get(prev_sync_result, State) of + SyncError -> + %% don't report same error twice + ok; + _ -> + LogOpts = maps:get(log_opts, State), + logger_h_common:error_notify({Name,sync, + LogOpts, + SyncError}) + end, + State#{prev_sync_result => SyncError} + end. error_notify_new(Info,Info, _Term) -> ok; diff --git a/lib/kernel/src/logger_filters.erl b/lib/kernel/src/logger_filters.erl index 85928f0fd6..592ff28cc2 100644 --- a/lib/kernel/src/logger_filters.erl +++ b/lib/kernel/src/logger_filters.erl @@ -38,6 +38,7 @@ domain(#{meta:=Meta}=Log,{Action,Compare,MatchDomain}) (Compare==prefix_of orelse Compare==starts_with orelse Compare==equals orelse + Compare==differs orelse Compare==no_domain) andalso is_list(MatchDomain) -> filter_domain(Compare,Meta,MatchDomain,on_match(Action,Log)); @@ -87,9 +88,12 @@ filter_domain(starts_with,#{domain:=Domain},MatchDomain,OnMatch) -> is_prefix(MatchDomain,Domain,OnMatch); filter_domain(equals,#{domain:=Domain},Domain,OnMatch) -> OnMatch; +filter_domain(differs,#{domain:=Domain},MatchDomain,OnMatch) + when Domain=/=MatchDomain -> + OnMatch; filter_domain(Action,Meta,_,OnMatch) -> case maps:is_key(domain,Meta) of - false when Action==no_domain -> OnMatch; + false when Action==no_domain; Action==differs -> OnMatch; _ -> ignore end. diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 8e954f8d98..602c666cc7 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -20,6 +20,7 @@ -module(logger_formatter). -export([format/2]). +-export([check_config/1]). -include("logger_internal.hrl"). @@ -38,7 +39,8 @@ max_size=>pos_integer() | unlimited, depth=>pos_integer() | unlimited, template=>template(), - utc=>boolean()}. + time_designator=>byte(), + time_offset=>integer()|[byte()]}. format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) when is_map(Config0) -> Config = add_default_config(Config0), @@ -195,16 +197,12 @@ truncate(String,Size) -> String end. -format_time(Timestamp,Config) when is_integer(Timestamp) -> - {Date,Time,Micro} = timestamp_to_datetimemicro(Timestamp,Config), - format_time(Date,Time,Micro); -format_time(Other,_Config) -> - %% E.g. a string - to_string(Other). - -format_time({Y,M,D},{H,Min,S},Micro) -> - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro]). +format_time(Timestamp,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(Timestamp) -> + SysTime = Timestamp + erlang:time_offset(microsecond), + calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, + {offset,Offset}, + {time_designator,Des}]). %% Assuming this is monotonic time in microseconds timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> @@ -212,12 +210,12 @@ timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> Micro = SysTime rem 1000000, Sec = SysTime div 1000000, UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - case Config of - #{utc:=true} -> UniversalTime; - _ -> erlang:universaltime_to_localtime(UniversalTime) + {{Date,Time},UtcStr} = + case offset_to_utc(maps:get(time_offset,Config)) of + true -> {UniversalTime,"UTC "}; + _ -> {erlang:universaltime_to_localtime(UniversalTime),""} end, - {Date,Time,Micro}. + {Date,Time,Micro,UtcStr}. format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_integer(A) -> atom_to_list(M)++":"++atom_to_list(F)++"/"++integer_to_list(A); @@ -230,9 +228,11 @@ maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> #{title:=Title}=MyMeta = add_legacy_title(Level,maps:get(?MODULE,Meta,#{})), - {{Y,Mo,D},{H,Mi,S},Micro} = timestamp_to_datetimemicro(Timestamp,Config), - Header = io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", - [Title,D,month(Mo),Y,H,Mi,S,Micro,utcstr(Config)]), + {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = + timestamp_to_datetimemicro(Timestamp,Config), + Header = + io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", + [Title,D,month(Mo),Y,H,Mi,S,Micro,UtcStr]), Meta#{?MODULE=>MyMeta#{header=>Header}}; maybe_add_legacy_header(_,Meta,_) -> Meta. @@ -256,20 +256,20 @@ month(10) -> "Oct"; month(11) -> "Nov"; month(12) -> "Dec". -utcstr(#{utc:=true}) -> "UTC "; -utcstr(_) -> "". - -add_default_config(#{utc:=_}=Config0) -> +%% Ensure that all valid configuration parameters exist in the final +%% configuration map +add_default_config(Config0) -> Default = #{legacy_header=>false, single_line=>true, - chars_limit=>unlimited}, - MaxSize = get_max_size(maps:get(max_size,Config0,false)), - Depth = get_depth(maps:get(depth,Config0,false)), + chars_limit=>unlimited, + time_designator=>$T}, + MaxSize = get_max_size(maps:get(max_size,Config0,undefined)), + Depth = get_depth(maps:get(depth,Config0,undefined)), + Offset = get_offset(maps:get(time_offset,Config0,undefined)), add_default_template(maps:merge(Default,Config0#{max_size=>MaxSize, - depth=>Depth})); -add_default_config(Config) -> - add_default_config(Config#{utc=>logger:get_utc_config()}). + depth=>Depth, + time_offset=>Offset})). add_default_template(#{template:=_}=Config) -> Config; @@ -283,12 +283,121 @@ default_template(#{single_line:=true}) -> default_template(_) -> ?DEFAULT_FORMAT_TEMPLATE. -get_max_size(false) -> - logger:get_max_size(); +get_max_size(undefined) -> + unlimited; get_max_size(S) -> max(10,S). -get_depth(false) -> - logger:get_format_depth(); +get_depth(undefined) -> + error_logger:get_format_depth(); get_depth(S) -> max(5,S). + +get_offset(undefined) -> + utc_to_offset(get_utc_config()); +get_offset(Offset) -> + Offset. + +utc_to_offset(true) -> + "Z"; +utc_to_offset(false) -> + "". + +get_utc_config() -> + %% SASL utc_log overrides stdlib config - in order to have uniform + %% timestamps in log messages + case application:get_env(sasl, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> + case application:get_env(stdlib, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> false + end + end. + +offset_to_utc(Z) when Z=:=0; Z=:="z"; Z=:="Z" -> + true; +offset_to_utc([$+|Tz]) -> + case io_lib:fread("~d:~d", Tz) of + {ok, [0, 0], []} -> + true; + _ -> + false + end; +offset_to_utc(_) -> + false. + +check_config(Config) when is_map(Config) -> + do_check_config(maps:to_list(Config)); +check_config(Config) -> + {error,{invalid_formatter_config,?MODULE,Config}}. + +do_check_config([{Type,L}|Config]) when Type == chars_limit; + Type == depth; + Type == max_size -> + case check_limit(L) of + ok -> do_check_config(Config); + error -> {error,{invalid_formatter_config,?MODULE,{Type,L}}} + end; +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([{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}} + end; +do_check_config([{time_offset,Offset}|Config]) -> + case check_offset(Offset) of + ok -> + do_check_config(Config); + error -> + {error,{invalid_formatter_config,?MODULE,{time_offset,Offset}}} + end; +do_check_config([{time_designator,Char}|Config]) when Char>=0, Char=<255 -> + case io_lib:printable_latin1_list([Char]) of + true -> + do_check_config(Config); + false -> + {error,{invalid_formatter_config,?MODULE,{time_designator,Char}}} + end; +do_check_config([C|_]) -> + {error,{invalid_formatter_config,?MODULE,C}}; +do_check_config([]) -> + ok. + +check_limit(L) when is_integer(L), L>0 -> + ok; +check_limit(unlimited) -> + ok; +check_limit(_) -> + error. + +check_offset(I) when is_integer(I) -> + ok; +check_offset(Tz) when Tz=:=""; Tz=:="Z"; Tz=:="z" -> + ok; +check_offset([Sign|Tz]) when Sign=:=$+; Sign=:=$- -> + check_timezone(Tz); +check_offset(_) -> + error. + +check_timezone(Tz) -> + try io_lib:fread("~d:~d", Tz) of + {ok, [_, _], []} -> + ok; + _ -> + error + catch _:_ -> + error + end. diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 7caad366ae..901c4c0dad 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -135,7 +135,8 @@ call_cast_or_drop(Name, Bin) -> _:{timeout,_} -> ?observe(Name,{dropped,1}) end; - drop -> ?observe(Name,{dropped,1}) + drop -> + ?observe(Name,{dropped,1}) catch %% if the ETS table doesn't exist (maybe because of a %% handler restart), we can only drop the request @@ -152,12 +153,15 @@ check_load(State = #{id:=Name, mode := Mode, flush_reqs_qlen := FlushQLen}) -> {_,Mem} = process_info(self(), memory), ?observe(Name,{max_mem,Mem}), - %% make sure the handler process doesn't get scheduled - %% out between the message_queue_len check below and the - %% action that follows (flush or write). {_,QLen} = process_info(self(), message_queue_len), ?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), + %% 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. {Mode1,_NewDrops,_NewFlushes} = if QLen >= FlushQLen -> @@ -292,7 +296,7 @@ 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), - (TSQL < DNRQL) andalso (DNRQL < FRQL). + (DNRQL > 1) andalso (TSQL =< DNRQL) andalso (DNRQL =< FRQL). 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 89378dbb10..ed365ce6eb 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -124,7 +124,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 8c0fc2725d..f9377259f3 100644 --- a/lib/kernel/src/logger_internal.hrl +++ b/lib/kernel/src/logger_internal.hrl @@ -22,7 +22,7 @@ -define(LOGGER_KEY,'$logger_config$'). -define(HANDLER_KEY,'$handler_config$'). -define(LOGGER_META_KEY,'$logger_metadata$'). --define(STANDARD_HANDLER, logger_std_h). +-define(STANDARD_HANDLER, default). -define(DEFAULT_HANDLER_FILTERS, ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp])). -define(DEFAULT_HANDLER_FILTERS(Domain), diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index a7f302ac8f..275b9c476f 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -27,7 +27,7 @@ add_filter/2, remove_filter/2, set_module_level/2, reset_module_level/1, cache_module_level/1, - set_config/2, set_config/3]). + set_config/2, set_config/3, update_config/2]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -36,8 +36,9 @@ -include("logger_internal.hrl"). -define(SERVER, logger). +-define(LOGGER_SERVER_TAG, '$logger_cb_process'). --record(state, {tid}). +-record(state, {tid, async_req, async_req_queue}). %%%=================================================================== %%% API @@ -47,23 +48,18 @@ start_link() -> gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). add_handler(Id,Module,Config0) -> - case sanity_check(logger,handlers,[Id]) of - ok -> - try check_mod(Module) of + try {check_id(Id),check_mod(Module)} of + {ok,ok} -> + case sanity_check(Id,Config0) of ok -> - case sanity_check(Id,Config0) of - ok -> - Default = default_config(Id), - Config = maps:merge(Default,Config0), - call({add_handler,Id,Module,Config}); - Error -> - Error - end - catch throw:Error -> - {error,Error} - end; - Error -> - Error + Default = default_config(Id), + Config = maps:merge(Default,Config0), + call({add_handler,Id,Module,Config}); + Error -> + Error + end + catch throw:Error -> + {error,Error} end. remove_handler(HandlerId) -> @@ -96,10 +92,7 @@ cache_module_level(Module) -> set_config(Owner,Key,Value) -> - case sanity_check(Owner,Key,Value) of - ok -> call({update_config,Owner,#{Key=>Value}}); - Error -> Error - end. + update_config(Owner,#{Key=>Value}). set_config(Owner,Config0) -> case sanity_check(Owner,Config0) of @@ -110,6 +103,14 @@ set_config(Owner,Config0) -> Error end. +update_config(Owner, Config) -> + case sanity_check(Owner,Config) of + ok -> + call({update_config,Owner,Config}); + Error -> + Error + end. + %%%=================================================================== %%% gen_server callbacks %%%=================================================================== @@ -122,93 +123,99 @@ init([]) -> logger_config:create(Tid,logger,LoggerConfig), SimpleConfig0 = maps:merge(default_config(logger_simple), #{filter_default=>stop, - filters=>?DEFAULT_HANDLER_FILTERS, - logger_simple=>#{buffer=>true}}), + filters=>?DEFAULT_HANDLER_FILTERS}), %% If this fails, then the node should crash {ok,SimpleConfig} = logger_simple:adding_handler(logger_simple,SimpleConfig0), logger_config:create(Tid,logger_simple,logger_simple,SimpleConfig), - {ok, #state{tid=Tid}}. - -handle_call({add_handler,Id,Module,HConfig}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:exist(Tid,Id) of - true -> - {error,{already_exist,Id}}; - false -> - %% inform the handler - case call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig}) of - {ok,HConfig1} -> - logger_config:create(Tid,Id,Module,HConfig1), - {ok,Config} = do_get_config(Tid,logger), - Handlers = maps:get(handlers,Config,[]), - do_set_config(Tid,logger, - Config#{handlers=>[Id|Handlers]}), - ok; - {error,HReason} -> - {error,{handler_not_added,HReason}} - end - end, - {reply,Reply,State}; -handle_call({remove_handler,HandlerId}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,HandlerId) of - {ok,{Module,_}} -> - {ok,Config} = do_get_config(Tid,logger), - Handlers0 = maps:get(handlers,Config,[]), - Handlers = lists:delete(HandlerId,Handlers0), - %% inform the handler - _ = call_h(Module,removing_handler,[HandlerId,Config],ok), - do_set_config(Tid,logger,Config#{handlers=>Handlers}), - logger_config:delete(Tid,HandlerId), - ok; - _ -> - {error,{not_found,HandlerId}} - end, - {reply,Reply,State}; + {ok, #state{tid=Tid, async_req_queue = queue:new()}}. + +handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> + case logger_config:exist(Tid,Id) of + true -> + {reply,{error,{already_exist,Id}},State}; + false -> + call_h_async( + fun() -> + %% inform the handler + call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig}) + end, + fun({ok,HConfig1}) -> + %% We know that the call_h would have loaded the module + %% if it existed, so it is safe here to call function_exported + %% to find out if this is a valid handler + case erlang:function_exported(Module, log, 2) of + true -> + logger_config:create(Tid,Id,Module,HConfig1), + {ok,Config} = do_get_config(Tid,logger), + Handlers = maps:get(handlers,Config,[]), + do_set_config(Tid,logger, + Config#{handlers=>[Id|Handlers]}); + false -> + {error,{invalid_handler, + {function_not_exported, + {Module,log,2}}}} + end; + ({error,HReason}) -> + {error,{handler_not_added,HReason}} + end,From,State) + end; +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), + Handlers0 = maps:get(handlers,Config,[]), + Handlers = lists:delete(HandlerId,Handlers0), + call_h_async( + fun() -> + %% inform the handler + call_h(Module,removing_handler,[HandlerId,HConfig],ok) + end, + fun(_Res) -> + do_set_config(Tid,logger,Config#{handlers=>Handlers}), + logger_config:delete(Tid,HandlerId), + ok + end,From,State); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) -> Reply = do_add_filter(Tid,Id,Filter), {reply,Reply,State}; handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) -> Reply = do_remove_filter(Tid,Id,FilterId), {reply,Reply,State}; -handle_call({update_config,Id,NewConfig}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,Id) of - {ok,{Module,OldConfig}} -> - Config = maps:merge(OldConfig,NewConfig), - case call_h(Module,changing_config,[Id,OldConfig,Config], - {ok,Config}) of - {ok,Config1} -> - do_set_config(Tid,Id,Config1); - Error -> - Error - end; - {ok,OldConfig} -> - Config = maps:merge(OldConfig,NewConfig), - do_set_config(Tid,Id,Config); - Error -> - Error - end, - {reply,Reply,State}; +handle_call({update_config,Id,NewConfig}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,Id) of + {ok,{_Module,OldConfig}} -> + Config = maps:merge(OldConfig,NewConfig), + handle_call({set_config,Id,Config}, From, State); + {ok,OldConfig} -> + Config = maps:merge(OldConfig,NewConfig), + {reply,do_set_config(Tid,Id,Config),State}; + Error -> + {reply,Error,State} + end; handle_call({set_config,logger,Config}, _From, #state{tid=Tid}=State) -> - Reply = do_set_config(Tid,logger,Config), - {reply,Reply,State}; -handle_call({set_config,HandlerId,Config}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,HandlerId) of - {ok,{Module,OldConfig}} -> - case call_h(Module,changing_config,[HandlerId,OldConfig,Config], - {ok,Config}) of - {ok,Config1} -> - do_set_config(Tid,HandlerId,Config1); - Error -> - Error - end; - _ -> - {error,{not_found,HandlerId}} - end, + {ok,#{handlers:=Handlers}} = logger_config:get(Tid,logger), + Reply = do_set_config(Tid,logger,Config#{handlers=>Handlers}), {reply,Reply,State}; +handle_call({set_config,HandlerId,Config}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,{Module,OldConfig}} -> + call_h_async( + fun() -> + call_h(Module,changing_config,[HandlerId,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + do_set_config(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; handle_call({set_module_level,Module,Level}, _From, #state{tid=Tid}=State) -> Reply = logger_config:set_module_level(Tid,Module,Level), {reply,Reply,State}; @@ -216,6 +223,8 @@ handle_call({reset_module_level,Module}, _From, #state{tid=Tid}=State) -> Reply = logger_config:reset_module_level(Tid,Module), {reply,Reply,State}. +handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) -> + call_h_reply(Reply,State); handle_cast({cache_module_level,Module}, #state{tid=Tid}=State) -> logger_config:cache_module_level(Tid,Module), {noreply, State}. @@ -235,11 +244,21 @@ handle_info({log,Level,Report,Meta}, State) -> handle_info({Ref,_Reply},State) when is_reference(Ref) -> %% Assuming this is a timed-out gen_server reply - ignoring {noreply, State}; -handle_info(Unexpected,State) -> +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 + %% We may as well ignore all 'EXIT' messages that we get ?LOG_INTERNAL(debug, [{logger,got_unexpected_message}, {process,?SERVER}, {message,Unexpected}]), + {noreply,State}; +handle_info(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), {noreply,State}. terminate(_Reason, _State) -> @@ -249,8 +268,11 @@ terminate(_Reason, _State) -> %%% Internal functions %%%=================================================================== call(Request) -> - case whereis(?SERVER) of - Pid when Pid==self() -> + Action = element(1,Request), + case get(?LOGGER_SERVER_TAG) of + true when + Action == add_handler; Action == remove_handler; + Action == update_config; Action == set_config -> {error,{attempting_syncronous_call_to_self,Request}}; _ -> gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT) @@ -301,8 +323,7 @@ do_set_config(Tid,Id,Config) -> default_config(logger) -> #{level=>info, filters=>[], - filter_default=>log, - handlers=>[]}; + filter_default=>log}; default_config(_) -> #{level=>info, filters=>[], @@ -333,9 +354,6 @@ get_type(Id) -> check_config(Owner,[{level,Level}|Config]) -> check_level(Level), check_config(Owner,Config); -check_config(logger,[{handlers,Handlers}|Config]) -> - check_handlers(Handlers), - check_config(logger,Config); check_config(Owner,[{filters,Filters}|Config]) -> check_filters(Filters), check_config(Owner,Config); @@ -373,14 +391,6 @@ check_level(Level) -> throw({invalid_level,Level}) end. -check_handlers([Id|Handlers]) -> - check_id(Id), - check_handlers(Handlers); -check_handlers([]) -> - ok; -check_handlers(Handlers) -> - throw({invalid_handlers,Handlers}). - check_filters([{Id,{Fun,_Args}}|Filters]) when is_atom(Id), is_function(Fun,2) -> check_filters(Filters); check_filters([Filter|_]) -> @@ -395,40 +405,24 @@ check_filter_default(FD) when FD==stop; FD==log -> check_filter_default(FD) -> throw({invalid_filter_default,FD}). -check_formatter({logger_formatter,Config}) when is_map(Config) -> - check_logger_formatter_config(maps:to_list(Config)); -check_formatter({logger_formatter,Config}) -> - throw({invalid_formatter_config,Config}); -check_formatter({Mod,_}) -> - %% no knowledge of other formatters - check_mod(Mod); +check_formatter({Mod,Config}) -> + check_mod(Mod), + try Mod:check_config(Config) of + ok -> ok; + {error,Error} -> throw(Error) + catch + C:R:S -> + case {C,R,S} of + {error,undef,[{Mod,check_config,[Config],_}|_]} -> + ok; + _ -> + throw({callback_crashed, + {C,R,logger:filter_stacktrace(?MODULE,S)}}) + end + end; check_formatter(Formatter) -> throw({invalid_formatter,Formatter}). - -check_logger_formatter_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 -> - check_logger_formatter_config(Config); - false -> - throw({invalid_formatter_template,T}) - end; -check_logger_formatter_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([{single_line,SL}|Config]) when is_boolean(SL) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([{utc,Utc}|Config]) when is_boolean(Utc) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([C|_]) -> - throw({invalid_formatter_config,C}); -check_logger_formatter_config([]) -> - ok. - call_h(Module, Function, Args, DefRet) -> %% Not calling code:ensure_loaded + erlang:function_exported here, %% since in some rare terminal cases, the code_server might not @@ -440,7 +434,59 @@ call_h(Module, Function, Args, DefRet) -> {error,undef,[{Module,Function,Args,_}|_]} -> DefRet; _ -> - {error,{callback_crashed, - {C,R,logger:filter_stacktrace(?MODULE,S)}}} + ST = logger:filter_stacktrace(?MODULE,S), + ?LOG_INTERNAL(error, + [{logger,callback_crashed}, + {process,?SERVER}, + {reason,{C,R,ST}}]), + {error,{callback_crashed,{C,R,ST}}} end end. + +%% There are all sort of API functions that can cause deadlocks if called +%% from the handler callbacks. So we spawn a process that does the request +%% for the logger_server. There are still APIs that will cause problems, +%% namely logger:add_handler +call_h_async(AsyncFun,PostFun,From,#state{ async_req = undefined } = State) -> + Parent = self(), + {Pid, Ref} = spawn_monitor( + fun() -> + put(?LOGGER_SERVER_TAG,true), + receive Ref -> Ref end, + gen_server:cast(Parent, {async_req_reply, Ref, AsyncFun()}) + end), + Pid ! Ref, + {noreply,State#state{ async_req = {Ref,PostFun,From} }}; +call_h_async(AsyncFun,PostFun,From,#state{ async_req_queue = Q } = State) -> + {noreply,State#state{ async_req_queue = queue:in({AsyncFun,PostFun,From},Q) }}. + +call_h_reply({async_req_reply,Ref,Reply}, + #state{ async_req = {Ref,PostFun,From}, async_req_queue = Q} = State) -> + erlang:demonitor(Ref,[flush]), + _ = gen_server:reply(From, PostFun(Reply)), + {Value,NewQ} = queue:out(Q), + NewState = State#state{ async_req = undefined, + async_req_queue = NewQ }, + case Value of + {value,{AsyncFun,NPostFun,NFrom}} -> + call_h_async(AsyncFun,NPostFun,NFrom,NewState); + empty -> + {noreply,NewState} + end; +call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_From}} = State) -> + %% This clause should only be triggered if someone explicitly sends an exit signal + %% to the spawned process. It is only here to make sure that the logger_server does + %% not deadlock if that happens. + ?LOG_INTERNAL(error, + [{logger,process_exited}, + {process,Pid}, + {reason,Reason}]), + call_h_reply( + {async_req_reply,Ref,{error,{logger_process_exited,Pid,Reason}}}, + State); +call_h_reply(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), + {noreply,State}. diff --git a/lib/kernel/src/logger_simple.erl b/lib/kernel/src/logger_simple.erl index a1b427b96c..5272455a2d 100644 --- a/lib/kernel/src/logger_simple.erl +++ b/lib/kernel/src/logger_simple.erl @@ -20,37 +20,18 @@ -module(logger_simple). -export([adding_handler/2, removing_handler/2, log/2]). --export([get_buffer/0]). %% This module implements a simple handler for logger. It is the %% default used during system start. %%%----------------------------------------------------------------- -%%% API -get_buffer() -> - case whereis(?MODULE) of - undefined -> - {error,noproc}; - Pid -> - Ref = erlang:monitor(process,Pid), - Pid ! {get_buffer,self()}, - receive - {buffer,Buffer} -> - erlang:demonitor(Ref,[flush]), - {ok,Buffer}; - {'DOWN',Ref,process,Pid,Reason} -> - {error,Reason} - end - end. - -%%%----------------------------------------------------------------- %%% Logger callback adding_handler(?MODULE,Config) -> Me = self(), case whereis(?MODULE) of undefined -> - {Pid,Ref} = spawn_opt(fun() -> init(Me,Config) end, + {Pid,Ref} = spawn_opt(fun() -> init(Me) end, [link,monitor,{message_queue_data,off_heap}]), receive {'DOWN',Ref,process,Pid,Reason} -> @@ -102,48 +83,44 @@ log(_,_) -> %%%----------------------------------------------------------------- %%% Process -init(Starter,Config) -> +init(Starter) -> register(?MODULE,self()), Starter ! {self(),started}, - BufferSize = - case Config of - #{?MODULE:=#{buffer:=true}} -> - 10; - _ -> - infinity - end, - loop(#{buffer_size=>BufferSize,dropped=>0,buffer=>[]},infinity). + loop(#{buffer_size=>10,dropped=>0,buffer=>[]}). -loop(Buffer,Timeout) -> +loop(Buffer) -> receive stop -> - ok; - {get_buffer,From} -> - loop(Buffer#{send_to=>From},0); + %% We replay the logger messages of there is + %% a default handler when the simple handler + %% is removed. + case logger:get_handler_config(default) of + {ok, _} -> + replay_buffer(Buffer); + _ -> + ok + end; {log,#{msg:=_,meta:=#{time:=_}}=Log} -> do_log(Log), - loop(update_buffer(Buffer,Log),Timeout); + loop(update_buffer(Buffer,Log)); _ -> %% Unexpected message - flush it! - loop(Buffer,Timeout) - after Timeout -> - #{dropped:=D,buffer:=B,send_to:=Pid} = Buffer, - LogList = lists:reverse(B) ++ drop_msg(D), - Pid ! {buffer,LogList}, - loop(Buffer#{buffer_size=>infinity, - dropped=>0, - buffer=>[], - send_to=>false}, - infinity) + loop(Buffer) end. -update_buffer(#{buffer_size:=infinity}=Buffer,_Log) -> - Buffer; update_buffer(#{buffer_size:=0,dropped:=D}=Buffer,_Log) -> Buffer#{dropped=>D+1}; update_buffer(#{buffer_size:=S,buffer:=B}=Buffer,Log) -> Buffer#{buffer_size=>S-1,buffer=>[Log|B]}. +replay_buffer(#{ dropped := D, buffer := Buffer }) -> + lists:foreach( + fun F(#{msg := {Tag, Msg}} = L) when Tag =:= string; Tag =:= report -> + F(L#{ msg := Msg }); + F(#{ level := Level, msg := Msg, meta := MD}) -> + logger:log(Level, Msg, MD) + end, lists:reverse(Buffer, drop_msg(D))). + drop_msg(0) -> []; drop_msg(N) -> diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 31edcfea8b..e5e0febc88 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -257,10 +257,11 @@ init([Name, Config, 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,T0}), + gen_server:cast(self(), repeated_filesync), enter_loop(Config, State1); Error -> logger_h_common:error_notify({init_handler,Name,Error}), @@ -310,12 +311,11 @@ handle_call(filesync, _From, State = #{type := Type, if is_atom(Type) -> {reply, ok, State}; true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State} + {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} end; handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0, - last_log_ts := LastLogTS}) -> + State = #{filesync_repeat_interval := FSyncInt0}) -> HConfig = maps:get(?MODULE, NewConfig, #{}), State1 = maps:merge(State, HConfig), case logger_h_common:overload_levels_ok(State1) of @@ -334,8 +334,7 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, undefined)), - gen_server:cast(self(), {repeated_filesync, - LastLogTS}) + gen_server:cast(self(), repeated_filesync) end, {reply, ok, State1}; false -> @@ -365,24 +364,24 @@ handle_cast({log, Bin}, State) -> %% 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! -handle_cast({repeated_filesync,LastLogTS0}, +handle_cast(repeated_filesync, State = #{type := Type, file_ctrl_pid := FileCtrlPid, filesync_repeat_interval := FSyncInt, - last_log_ts := LastLogTS1}) -> + last_op := LastOp}) -> State1 = if not is_atom(Type), is_integer(FSyncInt) -> %% only do filesync if something has been %% written since last time we checked - if LastLogTS1 == LastLogTS0 -> + if LastOp == sync -> ok; true -> file_ctrl_filesync_async(FileCtrlPid) end, {ok,TRef} = timer:apply_after(FSyncInt, gen_server,cast, - [self(),{repeated_filesync,LastLogTS1}]), - State#{rep_sync_tref => TRef}; + [self(),repeated_filesync]), + State#{rep_sync_tref => TRef, last_op => sync}; true -> State end, @@ -600,6 +599,7 @@ write(Name, Mode, T1, Bin, _CallOrCast, State1#{mode => Mode1, last_qlen := LastQLen1, last_log_ts => T1, + last_op => write, burst_win_ts => BurstWinT, burst_msg_count => BurstMsgCount1, file_ctrl_sync => |