diff options
Diffstat (limited to 'lib/kernel/src')
24 files changed, 851 insertions, 627 deletions
diff --git a/lib/kernel/src/Makefile b/lib/kernel/src/Makefile index eeb8c6ab2f..f265fdd272 100644 --- a/lib/kernel/src/Makefile +++ b/lib/kernel/src/Makefile @@ -118,7 +118,7 @@ MODULES = \ logger_filters \ logger_formatter \ logger_server \ - logger_simple \ + logger_simple_h \ logger_sup \ net \ net_adm \ @@ -279,7 +279,7 @@ $(EBIN)/logger_disk_log_h.beam: logger_h_common.hrl logger_internal.hrl ../inclu $(EBIN)/logger_filters.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_formatter.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_server.beam: logger_internal.hrl ../include/logger.hrl -$(EBIN)/logger_simple.beam: logger_internal.hrl ../include/logger.hrl +$(EBIN)/logger_simple_h.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_std_h.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl ../include/file.hrl $(EBIN)/logger_h_common.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl $(EBIN)/net_kernel.beam: ../include/net_address.hrl diff --git a/lib/kernel/src/code.erl b/lib/kernel/src/code.erl index f143a49d2f..7faef93609 100644 --- a/lib/kernel/src/code.erl +++ b/lib/kernel/src/code.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -630,7 +630,7 @@ do_par_recv(N, Good, Bad) -> call(Req) -> code_server:call(Req). --spec start_link() -> {'ok', pid()} | {'error', 'crash'}. +-spec start_link() -> {'ok', pid()}. start_link() -> do_start(). diff --git a/lib/kernel/src/code_server.erl b/lib/kernel/src/code_server.erl index bbfa2a995d..1a7677295b 100644 --- a/lib/kernel/src/code_server.erl +++ b/lib/kernel/src/code_server.erl @@ -1437,7 +1437,7 @@ error_msg(Format, Args) -> logger ! {log,error,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:monotonic_time(microsecond), + time=>erlang:system_time(microsecond), error_logger=>#{tag=>error}}}, ok. @@ -1446,7 +1446,7 @@ info_msg(Format, Args) -> logger ! {log,info,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:monotonic_time(microsecond), + time=>erlang:system_time(microsecond), error_logger=>#{tag=>info_msg}}}, ok. diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index 47d0ca5ea3..b3957d0c7e 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -32,7 +32,7 @@ which_report_handlers/0]). %% logger callbacks --export([adding_handler/2, removing_handler/2, log/2]). +-export([adding_handler/1, removing_handler/1, log/2]). -export([get_format_depth/0, limit_term/1]). @@ -101,9 +101,9 @@ stop() -> %%%----------------------------------------------------------------- %%% Callbacks for logger --spec adding_handler(logger:handler_id(),logger:config()) -> +-spec adding_handler(logger:config()) -> {ok,logger:config()} | {error,term()}. -adding_handler(?MODULE,Config) -> +adding_handler(#{id:=?MODULE}=Config) -> case start() of ok -> {ok,Config}; @@ -111,12 +111,12 @@ adding_handler(?MODULE,Config) -> Error end. --spec removing_handler(logger:handler_id(),logger:config()) -> ok. -removing_handler(?MODULE,_Config) -> +-spec removing_handler(logger:config()) -> ok. +removing_handler(#{id:=?MODULE}) -> stop(), ok. --spec log(logger:log(),logger:config()) -> ok. +-spec log(logger:log_event(),logger:config()) -> ok. log(#{level:=Level,msg:=Msg,meta:=Meta},_Config) -> do_log(Level,Msg,Meta). @@ -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/file_server.erl b/lib/kernel/src/file_server.erl index ecc1ffbdd6..29eaa23375 100644 --- a/lib/kernel/src/file_server.erl +++ b/lib/kernel/src/file_server.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2000-2017. All Rights Reserved. +%% Copyright Ericsson AB 2000-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -73,7 +73,7 @@ stop() -> %% {stop, Reason} %%---------------------------------------------------------------------- --spec init([]) -> {'ok', state()} | {'stop', term()}. +-spec init([]) -> {'ok', state()}. init([]) -> process_flag(trap_exit, true), @@ -225,7 +225,7 @@ handle_cast(Msg, State) -> %%---------------------------------------------------------------------- -spec handle_info(term(), state()) -> - {'noreply', state()} | {'stop', 'normal', state()}. + {'noreply', state()}. handle_info({'EXIT', Pid, _Reason}, State) when is_pid(Pid) -> ets:delete(?FILE_IO_SERVER_TABLE, Pid), diff --git a/lib/kernel/src/gen_sctp.erl b/lib/kernel/src/gen_sctp.erl index a6aa0edd15..3526df3600 100644 --- a/lib/kernel/src/gen_sctp.erl +++ b/lib/kernel/src/gen_sctp.erl @@ -118,6 +118,8 @@ open() -> | inet:address_family() | {port,Port} | {type,SockType} + | {netns, file:filename_all()} + | {bind_to_device, binary()} | option(), IP :: inet:ip_address() | any | loopback, Port :: inet:port_number(), diff --git a/lib/kernel/src/gen_tcp.erl b/lib/kernel/src/gen_tcp.erl index ac61dbc792..253c63528f 100644 --- a/lib/kernel/src/gen_tcp.erl +++ b/lib/kernel/src/gen_tcp.erl @@ -102,6 +102,8 @@ inet:address_family() | {port, inet:port_number()} | {tcp_module, module()} | + {netns, file:filename_all()} | + {bind_to_device, binary()} | option(). -type listen_option() :: {ip, inet:socket_address()} | @@ -111,6 +113,8 @@ {port, inet:port_number()} | {backlog, B :: non_neg_integer()} | {tcp_module, module()} | + {netns, file:filename_all()} | + {bind_to_device, binary()} | option(). -type socket() :: port(). diff --git a/lib/kernel/src/gen_udp.erl b/lib/kernel/src/gen_udp.erl index 3121544719..9ab58011ec 100644 --- a/lib/kernel/src/gen_udp.erl +++ b/lib/kernel/src/gen_udp.erl @@ -97,6 +97,8 @@ open(Port) -> | {ifaddr, inet:socket_address()} | inet:address_family() | {port, inet:port_number()} + | {netns, file:filename_all()} + | {bind_to_device, binary()} | option(), Socket :: socket(), Reason :: inet:posix(). diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index afffcd156e..d873178f55 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -68,7 +68,7 @@ logger_formatter, logger_h_common, logger_server, - logger_simple, + logger_simple_h, logger_std_h, logger_sup, net, @@ -140,7 +140,10 @@ inet_db, pg2]}, {applications, []}, - {env, []}, + {env, [{logger_level, info}, + {logger_sasl_compatible, false}, + {logger_progress_reports, stop} + ]}, {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/kernel_refc.erl b/lib/kernel/src/kernel_refc.erl index 05076dc885..8e04ff99d8 100644 --- a/lib/kernel/src/kernel_refc.erl +++ b/lib/kernel/src/kernel_refc.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2017. All Rights Reserved. +%% Copyright Ericsson AB 2017-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -44,7 +44,7 @@ scheduler_wall_time(Bool) -> %% Callback functions from gen_server %%----------------------------------------------------------------- --spec init([]) -> {'ok', map()} | {'stop', term()}. +-spec init([]) -> {'ok', map()}. init([]) -> resource(scheduler_wall_time, false), diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 98a9937111..3beb3102fa 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -37,18 +37,22 @@ -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, reset_module_level/1, + set_module_level/2, unset_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, + update_formatter_config/2, update_formatter_config/3, + 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]). @@ -60,11 +64,11 @@ %%%----------------------------------------------------------------- %%% Types --type log() :: #{level:=level(), - msg:={io:format(),[term()]} | - {report,report()} | - {string,unicode:chardata()}, - meta:=metadata()}. +-type log_event() :: #{level:=level(), + msg:={io:format(),[term()]} | + {report,report()} | + {string,unicode:chardata()}, + meta:=metadata()}. -type level() :: emergency | alert | critical | error | warning | notice | info | debug. -type report() :: map() | [{atom(),term()}]. @@ -77,24 +81,32 @@ mfa => {module(),atom(),non_neg_integer()}, file => file:filename(), line => non_neg_integer(), - term() => term()}. + domain => [atom()], + report_cb => fun((report()) -> {io:format(),[term()]}), + atom() => term()}. -type location() :: #{mfa := {module(),atom(),non_neg_integer()}, file := file:filename(), line := non_neg_integer()}. -type handler_id() :: atom(). -type filter_id() :: atom(). --type filter() :: {fun((log(),filter_arg()) -> filter_return()),filter_arg()}. +-type filter() :: {fun((log_event(),filter_arg()) -> + filter_return()),filter_arg()}. -type filter_arg() :: term(). --type filter_return() :: stop | ignore | log(). --type config() :: #{level => level(), +-type filter_return() :: stop | ignore | log_event(). +-type config() :: #{id => handler_id(), + level => level(), filter_default => log | stop, filters => [{filter_id(),filter()}], - formatter => {module(),term()}, - term() => term()}. + formatter => {module(),formatter_config()}, + atom() => term()}. -type timestamp() :: integer(). +-type formatter_config() :: #{atom() => term()}. + +-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]). +-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, + config_handler/0,formatter_config/0]). %%%----------------------------------------------------------------- %%% API @@ -357,10 +369,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(), @@ -369,16 +393,31 @@ get_logger_config() -> get_handler_config(HandlerId) -> logger_config:get(?LOGGER_TABLE,HandlerId). +-spec update_formatter_config(HandlerId,FormatterConfig) -> + ok | {error,term()} when + HandlerId :: config(), + 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(), + 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 Module :: module(), Level :: level(). set_module_level(Module,Level) -> logger_server:set_module_level(Module,Level). --spec reset_module_level(Module) -> ok | {error,term()} when +-spec unset_module_level(Module) -> ok | {error,term()} when Module :: module(). -reset_module_level(Module) -> - logger_server:reset_module_level(Module). +unset_module_level(Module) -> + logger_server:unset_module_level(Module). %%%----------------------------------------------------------------- %%% Misc @@ -441,8 +480,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 +491,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,204 +543,209 @@ 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(simple,filters, + get_default_handler_filters()) of + ok -> ok; + {error,{not_found,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(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(simple) of + ok -> ok; + {error,{not_found,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(), + DefaultFormatter = #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}, + DefaultConfig = DefaultFormatter#{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)}; + ({handler, default, logger_disk_log_h, _}) -> + %% Add default formatter. The point of this + %% is to get the expected formatter config + %% for the default handler, since this + %% differs from the default values that + %% logger_formatter itself adds. + {handler, default, logger_disk_log_h, maps:merge(DefaultFormatter,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]); false -> Extra = - case application:get_env(kernel, logger_log_progress, false) of - true -> + case application:get_env(kernel, logger_progress_reports, stop) of + log -> []; - false -> + stop -> [{stop_progress, {fun logger_filters:progress/2,stop}}] end, 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 @@ -819,7 +863,7 @@ proc_meta() -> default(pid) -> self(); default(gl) -> group_leader(); -default(time) -> erlang:monotonic_time(microsecond). +default(time) -> erlang:system_time(microsecond). %% Remove everything upto and including this module from the stacktrace filter_stacktrace(Module,[{Module,_,_,_}|_]) -> diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl index d9f5aa6faf..b3cf7d67dd 100644 --- a/lib/kernel/src/logger_backend.erl +++ b/lib/kernel/src/logger_backend.erl @@ -58,7 +58,7 @@ call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) -> debug, [{logger,removed_failing_handler}, {handler,{Id,Module}}, - {log,Log1}, + {log_event,Log1}, {config,Config1}, {reason,{C,R,filter_stacktrace(S)}}]); {error,{not_found,_}} -> @@ -122,7 +122,7 @@ handle_filter_failed({Id,_}=Filter,Owner,Log,Reason) -> [{logger,removed_failing_filter}, {filter,Filter}, {owner,Owner}, - {log,Log}, + {log_event,Log}, {reason,Reason}]); _ -> ok diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 799aea9617..1d35c2e068 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -24,14 +24,14 @@ allow/2,allow/3, get/2, get/3, get/1, create/3, create/4, set/3, - set_module_level/3,reset_module_level/2, + set_module_level/3,unset_module_level/2, cache_module_level/2, level_to_int/1]). -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) -> @@ -109,7 +109,7 @@ set_module_level(Tid,Module,Level) -> ets:insert(Tid,{Module,level_to_int(Level)}), ok. -reset_module_level(Tid,Module) -> +unset_module_level(Tid,Module) -> ets:delete(Tid,Module), % should possibley overwrite instead of delete? ok. diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 0150fa781a..773aa75bc6 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -34,8 +34,8 @@ %% logger callbacks -export([log/2, - adding_handler/2, removing_handler/2, - changing_config/3, swap_buffer/2]). + adding_handler/1, removing_handler/1, + changing_config/2, swap_buffer/2]). %%%=================================================================== %%% API @@ -108,8 +108,8 @@ reset(Name) -> %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(Name, Config) -> - case check_config(adding, Name, Config) of +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, #{}), @@ -136,10 +136,9 @@ adding_handler(Name, Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(Name, - OldConfig=#{id:=Id, disk_log_opts:=DLOpts}, - NewConfig=#{id:=Id, disk_log_opts:=DLOpts}) -> - case check_config(changing, Name, NewConfig) of +changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts}, + NewConfig=#{id:=Name, disk_log_opts:=DLOpts}) -> + case check_config(changing, NewConfig) of Result = {ok,NewConfig1} -> try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, ?DEFAULT_CALL_TIMEOUT) of @@ -151,12 +150,10 @@ changing_config(Name, Error -> Error end; -changing_config(_Name, OldConfig, NewConfig) -> +changing_config(OldConfig, NewConfig) -> {error,{illegal_config_change,OldConfig,NewConfig}}. -check_config(adding, Name, Config0) -> - %% Merge in defaults on top level - Config = maps:merge(#{id => Name}, Config0), +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), @@ -173,7 +170,7 @@ check_config(adding, Name, Config0) -> Error -> Error end; -check_config(changing, _Name, Config) -> +check_config(changing, Config) -> MyConfig = maps:get(?MODULE, Config, #{}), case check_my_config(maps:to_list(MyConfig)) of ok -> {ok,Config}; @@ -223,7 +220,7 @@ check_my_config([]) -> %%%----------------------------------------------------------------- %%% Handler being removed -removing_handler(Name, _Config) -> +removing_handler(#{id:=Name}) -> stop(Name). %%%----------------------------------------------------------------- @@ -238,15 +235,15 @@ swap_buffer(Name,Buffer) -> %%%----------------------------------------------------------------- %%% Log a string or report --spec log(Log, Config) -> ok | dropped when - Log :: logger:log(), +-spec log(LogEvent, Config) -> ok | dropped when + LogEvent :: logger:log_event(), Config :: logger:config(). -log(Log,Config=#{id:=Name}) -> +log(LogEvent,Config=#{id:=Name}) -> %% if the handler has crashed, we must drop this request %% and hope the handler restarts so we can try again true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(Log,Config), + Bin = logger_h_common:log_to_binary(LogEvent,Config), logger_h_common:call_cast_or_drop(Name, Bin). @@ -278,10 +275,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 +314,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 +335,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 +366,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 +644,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 +658,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..7359b3b4b7 100644 --- a/lib/kernel/src/logger_filters.erl +++ b/lib/kernel/src/logger_filters.erl @@ -27,30 +27,31 @@ -include("logger_internal.hrl"). -define(IS_ACTION(A), (A==log orelse A==stop)). --spec domain(Log,Extra) -> logger:filter_return() when - Log :: logger:log(), +-spec domain(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), Extra :: {Action,Compare,MatchDomain}, Action :: log | stop, - Compare :: prefix_of | starts_with | equals | no_domain, + Compare :: super | sub | equal | not_equal | undefined, MatchDomain :: list(atom()). -domain(#{meta:=Meta}=Log,{Action,Compare,MatchDomain}) +domain(#{meta:=Meta}=LogEvent,{Action,Compare,MatchDomain}) when ?IS_ACTION(Action) andalso - (Compare==prefix_of orelse - Compare==starts_with orelse - Compare==equals orelse - Compare==no_domain) andalso + (Compare==super orelse + Compare==sub orelse + Compare==equal orelse + Compare==not_equal orelse + Compare==undefined) andalso is_list(MatchDomain) -> - filter_domain(Compare,Meta,MatchDomain,on_match(Action,Log)); -domain(Log,Extra) -> - erlang:error(badarg,[Log,Extra]). + filter_domain(Compare,Meta,MatchDomain,on_match(Action,LogEvent)); +domain(LogEvent,Extra) -> + erlang:error(badarg,[LogEvent,Extra]). --spec level(Log,Extra) -> logger:filter_return() when - Log :: logger:log(), +-spec level(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), Extra :: {Action,Operator,MatchLevel}, Action :: log | stop, Operator :: neq | eq | lt | gt | lteq | gteq, MatchLevel :: logger:level(). -level(#{level:=L1}=Log,{Action,Op,L2}) +level(#{level:=L1}=LogEvent,{Action,Op,L2}) when ?IS_ACTION(Action) andalso (Op==neq orelse Op==eq orelse @@ -59,37 +60,40 @@ level(#{level:=L1}=Log,{Action,Op,L2}) Op==lteq orelse Op==gteq) andalso ?IS_LEVEL(L2) -> - filter_level(Op,L1,L2,on_match(Action,Log)); -level(Log,Extra) -> - erlang:error(badarg,[Log,Extra]). + filter_level(Op,L1,L2,on_match(Action,LogEvent)); +level(LogEvent,Extra) -> + erlang:error(badarg,[LogEvent,Extra]). --spec progress(Log,Extra) -> logger:filter_return() when - Log :: logger:log(), +-spec progress(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), Extra :: log | stop. -progress(Log,Action) when ?IS_ACTION(Action) -> - filter_progress(Log,on_match(Action,Log)); -progress(Log,Action) -> - erlang:error(badarg,[Log,Action]). +progress(LogEvent,Action) when ?IS_ACTION(Action) -> + filter_progress(LogEvent,on_match(Action,LogEvent)); +progress(LogEvent,Action) -> + erlang:error(badarg,[LogEvent,Action]). --spec remote_gl(Log,Extra) -> logger:filter_return() when - Log :: logger:log(), +-spec remote_gl(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), Extra :: log | stop. -remote_gl(Log,Action) when ?IS_ACTION(Action) -> - filter_remote_gl(Log,on_match(Action,Log)); -remote_gl(Log,Action) -> - erlang:error(badarg,[Log,Action]). +remote_gl(LogEvent,Action) when ?IS_ACTION(Action) -> + filter_remote_gl(LogEvent,on_match(Action,LogEvent)); +remote_gl(LogEvent,Action) -> + erlang:error(badarg,[LogEvent,Action]). %%%----------------------------------------------------------------- %%% Internal -filter_domain(prefix_of,#{domain:=Domain},MatchDomain,OnMatch) -> +filter_domain(super,#{domain:=Domain},MatchDomain,OnMatch) -> is_prefix(Domain,MatchDomain,OnMatch); -filter_domain(starts_with,#{domain:=Domain},MatchDomain,OnMatch) -> +filter_domain(sub,#{domain:=Domain},MatchDomain,OnMatch) -> is_prefix(MatchDomain,Domain,OnMatch); -filter_domain(equals,#{domain:=Domain},Domain,OnMatch) -> +filter_domain(equal,#{domain:=Domain},Domain,OnMatch) -> OnMatch; -filter_domain(Action,Meta,_,OnMatch) -> +filter_domain(not_equal,#{domain:=Domain},MatchDomain,OnMatch) + when Domain=/=MatchDomain -> + OnMatch; +filter_domain(Compare,Meta,_,OnMatch) -> case maps:is_key(domain,Meta) of - false when Action==no_domain -> OnMatch; + false when Compare==undefined; Compare==not_equal -> OnMatch; _ -> ignore end. @@ -119,5 +123,5 @@ filter_remote_gl(#{meta:=#{gl:=GL}},OnMatch) when node(GL)=/=node() -> filter_remote_gl(_,_) -> ignore. -on_match(log,Log) -> Log; +on_match(log,LogEvent) -> LogEvent; on_match(stop,_) -> stop. diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 8e954f8d98..4d727b3da0 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -20,25 +20,28 @@ -module(logger_formatter). -export([format/2]). +-export([check_config/1]). -include("logger_internal.hrl"). %%%----------------------------------------------------------------- %%% Types +-type config() :: #{chars_limit=>pos_integer()| unlimited, + depth=>pos_integer() | unlimited, + legacy_header=>boolean(), + max_size=>pos_integer() | unlimited, + report_cb=>fun((logger:report()) -> {io:format(),[term()]}), + single_line=>boolean(), + template=>template(), + time_designator=>byte(), + time_offset=>integer()|[byte()]}. -type template() :: [atom()|tuple()|string()]. %%%----------------------------------------------------------------- %%% API --spec format(Log,Config) -> unicode:chardata() when - Log :: logger:log(), - Config :: #{single_line=>boolean(), - legacy_header=>boolean(), - report_cb=>fun((logger:report()) -> {io:format(),[term()]}), - chars_limit=>pos_integer()| unlimited, - max_size=>pos_integer() | unlimited, - depth=>pos_integer() | unlimited, - template=>template(), - utc=>boolean()}. +-spec format(LogEvent,Config) -> unicode:chardata() when + LogEvent :: logger:log_event(), + Config :: config(). format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) when is_map(Config0) -> Config = add_default_config(Config0), @@ -83,8 +86,6 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) 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,[msg|Format],Config) -> - [Msg|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)]; @@ -128,9 +129,7 @@ to_string(X) -> io_lib:format("~tp",[X]). format_msg({string,Chardata},Meta,Config) -> - try unicode:characters_to_list(Chardata) - catch _:_ -> format_msg({"INVALID STRING: ~tp",[Chardata]},Meta,Config) - end; + format_msg({"~ts",[Chardata]},Meta,Config); format_msg({report,_}=Msg,Meta,#{report_cb:=Fun}=Config) when is_function(Fun,1) -> format_msg(Msg,Meta#{report_cb=>Fun},maps:remove(report_cb,Config)); format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,1) -> @@ -195,29 +194,24 @@ 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]). +%% SysTime is the system time in microseconds +format_time(SysTime,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(SysTime) -> + 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) -> - SysTime = Timestamp + erlang:time_offset(microsecond), +%% SysTime is the system time in microseconds +timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> 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 +224,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 +252,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 +279,123 @@ 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. + +-spec check_config(Config) -> ok | {error,term()} when + Config :: config(). +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..336398cd4a 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -39,8 +39,8 @@ %%%----------------------------------------------------------------- %%% Covert log data on any form to binary --spec log_to_binary(Log,Config) -> LogString when - Log :: logger:log(), +-spec log_to_binary(LogEvent,Config) -> LogString when + LogEvent :: logger:log_event(), Config :: logger:config(), LogString :: binary(). log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) -> @@ -58,7 +58,7 @@ do_log_to_binary(Log,Config) -> catch _:_ -> ?LOG_INTERNAL(debug,[{formatter_error,Formatter}, {config,FormatterConfig}, - {log,Log}, + {log_event,Log}, {bad_return_value,String}]), <<"FORMATTER ERROR: bad_return_value">> end. @@ -69,10 +69,10 @@ try_format(Log,Formatter,FormatterConfig) -> C:R:S -> ?LOG_INTERNAL(debug,[{formatter_crashed,Formatter}, {config,FormatterConfig}, - {log,Log}, + {log_event,Log}, {reason, {C,R,logger:filter_stacktrace(?MODULE,S)}}]), - case {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG} of + case {?DEFAULT_FORMATTER,#{}} of {Formatter,FormatterConfig} -> "DEFAULT FORMATTER CRASHED"; {DefaultFormatter,DefaultConfig} -> @@ -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..fedd6db370 100644 --- a/lib/kernel/src/logger_internal.hrl +++ b/lib/kernel/src/logger_internal.hrl @@ -22,17 +22,16 @@ -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), [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, - {domain,{fun logger_filters:domain/2,{log,prefix_of,Domain}}}, - {no_domain,{fun logger_filters:domain/2,{log,no_domain,[]}}}]). + {domain,{fun logger_filters:domain/2,{log,super,Domain}}}, + {no_domain,{fun logger_filters:domain/2,{log,undefined,[]}}}]). -define(DEFAULT_FORMATTER,logger_formatter). -define(DEFAULT_FORMAT_CONFIG,#{legacy_header=>true, - single_line=>false, - template=>?DEFAULT_FORMAT_TEMPLATE_HEADER}). + single_line=>false}). -define(DEFAULT_FORMAT_TEMPLATE_HEADER, [{logger_formatter,header},"\n",msg,"\n"]). -define(DEFAULT_FORMAT_TEMPLATE_SINGLE, diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index a7f302ac8f..47010c9fa5 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -25,9 +25,10 @@ -export([start_link/0, add_handler/3, remove_handler/1, add_filter/2, remove_filter/2, - set_module_level/2, reset_module_level/1, + set_module_level/2, unset_module_level/1, cache_module_level/1, - set_config/2, set_config/3]). + set_config/2, set_config/3, update_config/2, + update_formatter_config/2]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -36,8 +37,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 +49,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) -> @@ -86,9 +83,9 @@ set_module_level(Module,Level) when is_atom(Module) -> set_module_level(Module,_) -> {error,{not_a_module,Module}}. -reset_module_level(Module) when is_atom(Module) -> - call({reset_module_level,Module}); -reset_module_level(Module) -> +unset_module_level(Module) when is_atom(Module) -> + call({unset_module_level,Module}); +unset_module_level(Module) -> {error,{not_a_module,Module}}. cache_module_level(Module) -> @@ -96,10 +93,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 +104,21 @@ 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. + +update_formatter_config(HandlerId, FormatterConfig) + when is_map(FormatterConfig) -> + call({update_formatter_config,HandlerId,FormatterConfig}); +update_formatter_config(_HandlerId, FormatterConfig) -> + {error,{invalid_formatter_config,FormatterConfig}}. + + %%%=================================================================== %%% gen_server callbacks %%%=================================================================== @@ -118,104 +127,127 @@ init([]) -> process_flag(trap_exit, true), Tid = logger_config:new(?LOGGER_TABLE), LoggerConfig = maps:merge(default_config(logger), - #{handlers=>[logger_simple]}), + #{handlers=>[simple]}), logger_config:create(Tid,logger,LoggerConfig), - SimpleConfig0 = maps:merge(default_config(logger_simple), + SimpleConfig0 = maps:merge(default_config(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}}. + {ok,SimpleConfig} = logger_simple_h:adding_handler(SimpleConfig0), + logger_config:create(Tid,simple,logger_simple_h,SimpleConfig), + {ok, #state{tid=Tid, async_req_queue = queue:new()}}. -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}; +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,[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,[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), + {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) -> +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,[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({update_formatter_config,HandlerId,NewFConfig},_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 + {ok,{_Mod,#{formatter:={FMod,OldFConfig}}=Config}} -> + try + FConfig = maps:merge(OldFConfig,NewFConfig), + check_formatter({FMod,FConfig}), + do_set_config(Tid,HandlerId, + Config#{formatter=>{FMod,FConfig}}) + catch throw:Reason -> {error,Reason} end; _ -> - {error,{not_found,HandlerId}} + {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), {reply,Reply,State}; -handle_call({reset_module_level,Module}, _From, #state{tid=Tid}=State) -> - Reply = logger_config:reset_module_level(Tid,Module), +handle_call({unset_module_level,Module}, _From, #state{tid=Tid}=State) -> + Reply = logger_config:unset_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 +267,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 +291,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,13 +346,13 @@ do_set_config(Tid,Id,Config) -> default_config(logger) -> #{level=>info, filters=>[], - filter_default=>log, - handlers=>[]}; -default_config(_) -> - #{level=>info, + filter_default=>log}; +default_config(Id) -> + #{id=>Id, + level=>info, filters=>[], filter_default=>log, - formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}. + formatter=>{?DEFAULT_FORMATTER,#{}}}. sanity_check(Owner,Key,Value) -> sanity_check_1(Owner,[{Key,Value}]). @@ -333,9 +378,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 +415,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 +429,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 +458,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_h.erl index a1b427b96c..19fb3b54ba 100644 --- a/lib/kernel/src/logger_simple.erl +++ b/lib/kernel/src/logger_simple_h.erl @@ -17,40 +17,21 @@ %% %% %CopyrightEnd% %% --module(logger_simple). +-module(logger_simple_h). --export([adding_handler/2, removing_handler/2, log/2]). --export([get_buffer/0]). +-export([adding_handler/1, removing_handler/1, log/2]). %% 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) -> +adding_handler(#{id:=simple}=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} -> @@ -63,7 +44,7 @@ adding_handler(?MODULE,Config) -> {error,{handler_process_name_already_exists,?MODULE}} end. -removing_handler(?MODULE,_Config) -> +removing_handler(#{id:=simple}) -> case whereis(?MODULE) of undefined -> ok; @@ -89,7 +70,7 @@ log(#{msg:=_,meta:=#{time:=_}}=Log,_Config) -> do_log( #{level=>error, msg=>{report,{error,simple_handler_process_dead}}, - meta=>#{time=>erlang:monotonic_time(microsecond)}}), + meta=>#{time=>erlang:system_time(microsecond)}}), do_log(Log); _ -> ?MODULE ! {log,Log} @@ -102,54 +83,50 @@ 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) -> [#{level=>info, msg=>{"Simple handler buffer full, dropped ~w messages",[N]}, - meta=>#{time=>erlang:monotonic_time(microsecond)}}]. + meta=>#{time=>erlang:system_time(microsecond)}}]. %%%----------------------------------------------------------------- %%% Internal @@ -164,8 +141,7 @@ do_log(#{msg:=Msg,meta:=#{time:=T}}) -> display_date(T), display(Msg). -display_date(Timestamp0) when is_integer(Timestamp0) -> - Timestamp = Timestamp0 + erlang:time_offset(microsecond), +display_date(Timestamp) when is_integer(Timestamp) -> Micro = Timestamp rem 1000000, Sec = Timestamp div 1000000, {{Y,Mo,D},{H,Mi,S}} = erlang:universaltime_to_localtime( diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 31edcfea8b..63c3ab2dac 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -35,8 +35,8 @@ terminate/2, code_change/3]). %% logger callbacks --export([log/2, adding_handler/2, removing_handler/2, - changing_config/3, swap_buffer/2]). +-export([log/2, adding_handler/1, removing_handler/1, + changing_config/2, swap_buffer/2]). %%%=================================================================== %%% API @@ -109,8 +109,8 @@ reset(Name) -> %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(Name, Config) -> - case check_config(adding, Name, Config) of +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, #{}), @@ -137,9 +137,8 @@ adding_handler(Name, Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(Name, - OldConfig=#{id:=Id, ?MODULE:=#{type:=Type}}, - NewConfig=#{id:=Id}) -> +changing_config(OldConfig=#{id:=Name, ?MODULE:=#{type:=Type}}, + NewConfig=#{id:=Name}) -> MyConfig = maps:get(?MODULE, NewConfig, #{}), case maps:get(type, MyConfig, Type) of Type -> @@ -149,11 +148,11 @@ changing_config(Name, _ -> {error,{illegal_config_change,OldConfig,NewConfig}} end; -changing_config(_Name, OldConfig, NewConfig) -> +changing_config(OldConfig, NewConfig) -> {error,{illegal_config_change,OldConfig,NewConfig}}. changing_config1(Name, OldConfig, NewConfig) -> - case check_config(changing, Name, NewConfig) of + case check_config(changing, NewConfig) of Result = {ok,NewConfig1} -> try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, ?DEFAULT_CALL_TIMEOUT) of @@ -166,9 +165,7 @@ changing_config1(Name, OldConfig, NewConfig) -> Error end. -check_config(adding, Name, Config0) -> - %% Merge in defaults on top level - Config = maps:merge(#{id => Name}, Config0), +check_config(adding, Config) -> %% Merge in defaults on handler level MyConfig0 = maps:get(?MODULE, Config, #{}), MyConfig = maps:merge(#{type => standard_io}, @@ -179,7 +176,7 @@ check_config(adding, Name, Config0) -> Error -> Error end; -check_config(changing, _Name, Config) -> +check_config(changing, Config) -> MyConfig = maps:get(?MODULE, Config, #{}), case check_my_config(maps:to_list(MyConfig)) of ok -> {ok,Config}; @@ -207,7 +204,7 @@ check_my_config([]) -> %%%----------------------------------------------------------------- %%% Handler being removed -removing_handler(Name,_Config) -> +removing_handler(#{id:=Name}) -> stop(Name). %%%----------------------------------------------------------------- @@ -222,15 +219,15 @@ swap_buffer(Name,Buffer) -> %%%----------------------------------------------------------------- %%% Log a string or report --spec log(Log, Config) -> ok | dropped when - Log :: logger:log(), +-spec log(LogEvent, Config) -> ok | dropped when + LogEvent :: logger:log_event(), Config :: logger:config(). -log(Log,Config=#{id:=Name}) -> +log(LogEvent,Config=#{id:=Name}) -> %% if the handler has crashed, we must drop this request %% and hope the handler restarts so we can try again true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(Log,Config), + Bin = logger_h_common:log_to_binary(LogEvent,Config), logger_h_common:call_cast_or_drop(Name, Bin). %%%=================================================================== @@ -257,10 +254,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 +308,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 +331,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 +361,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 +596,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 => |