From b6289e914c67bd786da829503b144c039303bfd3 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 14 Aug 2018 11:43:18 +0200 Subject: [logger] Refactor some logger internals --- lib/kernel/src/logger.erl | 7 +--- lib/kernel/src/logger_backend.erl | 2 +- lib/kernel/src/logger_config.erl | 23 ++--------- lib/kernel/src/logger_disk_log_h.erl | 5 +-- lib/kernel/src/logger_server.erl | 74 +++++++++++++++++------------------- lib/kernel/src/logger_std_h.erl | 5 +-- lib/kernel/test/logger_SUITE.erl | 2 +- 7 files changed, 44 insertions(+), 74 deletions(-) diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 0020fe220b..7b1377b8ca 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -434,12 +434,7 @@ get_primary_config() -> HandlerId :: handler_id(), Config :: handler_config(). get_handler_config(HandlerId) -> - case logger_config:get(?LOGGER_TABLE,HandlerId) of - {ok,{_,Config}} -> - {ok,Config}; - Error -> - Error - end. + logger_config:get(?LOGGER_TABLE,HandlerId). -spec get_handler_config() -> [Config] when Config :: handler_config(). diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl index 4d7bd6b2a0..432c671afd 100644 --- a/lib/kernel/src/logger_backend.erl +++ b/lib/kernel/src/logger_backend.erl @@ -41,7 +41,7 @@ log_allowed(Log, Tid) -> call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) -> case logger_config:get(Tid,Id,Level) of - {ok,{Module,Config}} -> + {ok,#{module:=Module}=Config} -> Filters = maps:get(filters,Config,[]), case apply_filters(Id,Log,Filters,Config) of stop -> diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 55427dce5a..6bfe658552 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -22,8 +22,8 @@ -export([new/1,delete/2, exist/2, allow/2,allow/3, - get/2, get/3, get/1, - create/3, create/4, set/3, + get/2, get/3, + create/3, set/3, set_module_level/3,unset_module_level/2, get_module_level/1,cache_module_level/2, level_to_int/1]). @@ -64,27 +64,19 @@ get(Tid,What) -> case ets:lookup(Tid,table_key(What)) of [{_,_,Config}] -> {ok,Config}; - [{_,_,Config,Module}] -> - {ok,{Module,Config}}; [] -> {error,{not_found,What}} end. get(Tid,What,Level) -> - MS = [{{table_key(What),'$1','$2'}, % primary config + MS = [{{table_key(What),'$1','$2'}, [{'>=','$1',level_to_int(Level)}], - ['$2']}, - {{table_key(What),'$1','$2','$3'}, % handler config - [{'>=','$1',level_to_int(Level)}], - [{{'$3','$2'}}]}], + ['$2']}], case ets:select(Tid,MS) of [] -> error; [Data] -> {ok,Data} end. -create(Tid,What,Module,Config) -> - LevelInt = level_to_int(maps:get(level,Config)), - ets:insert(Tid,{table_key(What),LevelInt,Config,Module}). create(Tid,What,Config) -> LevelInt = level_to_int(maps:get(level,Config)), ets:insert(Tid,{table_key(What),LevelInt,Config}). @@ -129,13 +121,6 @@ cache_module_level(Tid,Module) -> ets:insert_new(Tid,{Module,{GlobalLevelInt,cached}}), ok. -get(Tid) -> - {ok,Primary} = get(Tid,primary), - HMS = [{{table_key('$1'),'_','$2','$3'},[],[{{'$1','$3','$2'}}]}], - Handlers = ets:select(Tid,HMS), - Modules = get_module_level(Tid), - {Primary,Handlers,Modules}. - level_to_int(none) -> ?LOG_NONE; level_to_int(emergency) -> ?EMERGENCY; level_to_int(alert) -> ?ALERT; diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index e56531c3cb..3c12c9e68b 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -294,7 +294,7 @@ init([Name, %% initial start ok end, - enter_loop(Config1, State1) + gen_server:enter_loop(?MODULE, [], State1) catch _:Error -> unregister(RegName), @@ -307,9 +307,6 @@ init([Name, proc_lib:init_ack(Error) end. -enter_loop(_Config,State) -> - gen_server:enter_loop(?MODULE,[],State). - %% This is the synchronous log event. handle_call({log, Bin}, _From, State) -> {Result,State1} = do_log(Bin, call, State), diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index 644fdd5af2..01ac1b4b50 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -146,7 +146,7 @@ init([]) -> filters=>?DEFAULT_HANDLER_FILTERS}), %% If this fails, then the node should crash {ok,SimpleConfig} = logger_simple_h:adding_handler(SimpleConfig0), - logger_config:create(Tid,simple,logger_simple_h,SimpleConfig), + logger_config:create(Tid,simple,SimpleConfig), {ok, #state{tid=Tid, async_req_queue = queue:new()}}. handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> @@ -165,11 +165,11 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> %% 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,primary), + logger_config:create(Tid,Id,HConfig1), + {ok,Config} = logger_config:get(Tid,primary), Handlers = maps:get(handlers,Config,[]), - do_set_config(Tid,primary, - Config#{handlers=>[Id|Handlers]}); + logger_config:set(Tid,primary, + Config#{handlers=>[Id|Handlers]}); false -> {error,{invalid_handler, {function_not_exported, @@ -181,8 +181,8 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=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,primary), + {ok,#{module:=Module}=HConfig} -> + {ok,Config} = logger_config:get(Tid,primary), Handlers0 = maps:get(handlers,Config,[]), Handlers = lists:delete(HandlerId,Handlers0), call_h_async( @@ -191,7 +191,7 @@ handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> call_h(Module,removing_handler,[HConfig],ok) end, fun(_Res) -> - do_set_config(Tid,primary,Config#{handlers=>Handlers}), + logger_config:set(Tid,primary,Config#{handlers=>Handlers}), logger_config:delete(Tid,HandlerId), ok end,From,State); @@ -204,25 +204,35 @@ handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=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) -> - 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} -> +handle_call({update_config,primary,NewConfig}, _From, #state{tid=Tid}=State) -> + {ok,OldConfig} = logger_config:get(Tid,primary), + Config = maps:merge(OldConfig,NewConfig), + {reply,logger_config:set(Tid,primary,Config),State}; +handle_call({update_config,HandlerId,NewConfig}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,#{module:=Module}=OldConfig} -> Config = maps:merge(OldConfig,NewConfig), - {reply,do_set_config(Tid,Id,Config),State}; + call_h_async( + fun() -> + call_h(Module,changing_config,[OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + logger_config:set(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); Error -> {reply,Error,State} end; handle_call({set_config,primary,Config0}, _From, #state{tid=Tid}=State) -> Config = maps:merge(default_config(primary),Config0), {ok,#{handlers:=Handlers}} = logger_config:get(Tid,primary), - Reply = do_set_config(Tid,primary,Config#{handlers=>Handlers}), + Reply = logger_config:set(Tid,primary,Config#{handlers=>Handlers}), {reply,Reply,State}; handle_call({set_config,HandlerId,Config0}, From, #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of - {ok,{Module,OldConfig}} -> + {ok,#{module:=Module}=OldConfig} -> Config = maps:merge(default_config(HandlerId,Module),Config0), call_h_async( fun() -> @@ -230,7 +240,7 @@ handle_call({set_config,HandlerId,Config0}, From, #state{tid=Tid}=State) -> {ok,Config}) end, fun({ok,Config1}) -> - do_set_config(Tid,HandlerId,Config1); + logger_config:set(Tid,HandlerId,Config1); (Error) -> Error end,From,State); @@ -241,12 +251,12 @@ handle_call({update_formatter_config,HandlerId,NewFConfig},_From, #state{tid=Tid}=State) -> Reply = case logger_config:get(Tid,HandlerId) of - {ok,{_Mod,#{formatter:={FMod,OldFConfig}}=Config}} -> + {ok,#{formatter:={FMod,OldFConfig}}=Config} -> try FConfig = maps:merge(OldFConfig,NewFConfig), check_formatter({FMod,FConfig}), - do_set_config(Tid,HandlerId, - Config#{formatter=>{FMod,FConfig}}) + logger_config:set(Tid,HandlerId, + Config#{formatter=>{FMod,FConfig}}) catch throw:Reason -> {error,Reason} end; _ -> @@ -316,26 +326,26 @@ call(Request) -> end. do_add_filter(Tid,Id,{FId,_} = Filter) -> - case do_get_config(Tid,Id) of + case logger_config:get(Tid,Id) of {ok,Config} -> Filters = maps:get(filters,Config,[]), case lists:keymember(FId,1,Filters) of true -> {error,{already_exist,FId}}; false -> - do_set_config(Tid,Id,Config#{filters=>[Filter|Filters]}) + logger_config:set(Tid,Id,Config#{filters=>[Filter|Filters]}) end; Error -> Error end. do_remove_filter(Tid,Id,FilterId) -> - case do_get_config(Tid,Id) of + case logger_config:get(Tid,Id) of {ok,Config} -> Filters0 = maps:get(filters,Config,[]), case lists:keytake(FilterId,1,Filters0) of {value,_,Filters} -> - do_set_config(Tid,Id,Config#{filters=>Filters}); + logger_config:set(Tid,Id,Config#{filters=>Filters}); false -> {error,{not_found,FilterId}} end; @@ -343,20 +353,6 @@ do_remove_filter(Tid,Id,FilterId) -> Error end. -do_get_config(Tid,Id) -> - case logger_config:get(Tid,Id) of - {ok,{_,Config}} -> - {ok,Config}; - {ok,Config} -> - {ok,Config}; - Error -> - Error - end. - -do_set_config(Tid,Id,Config) -> - logger_config:set(Tid,Id,Config), - ok. - default_config(primary) -> #{level=>notice, filters=>[], diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 9a2a1443b3..b60e7cf587 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -259,7 +259,7 @@ init([Name, Config = #{config := HConfig}, mode_tab => ModeTab}}, proc_lib:init_ack({ok,self(),Config1}), gen_server:cast(self(), repeated_filesync), - enter_loop(Config1, State1) + gen_server:enter_loop(?MODULE, [], State1) catch _:Error -> unregister(RegName), @@ -290,9 +290,6 @@ do_init(Name, Type) -> Error end. -enter_loop(_Config,State) -> - gen_server:enter_loop(?MODULE,[],State). - %% This is the synchronous log event. handle_call({log, Bin}, _From, State) -> {Result,State1} = do_log(Bin, call, State), diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 6bd9b20c35..824c95d6df 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -259,7 +259,7 @@ change_config(_Config) -> logger:get_primary_config(), 3 = maps:size(PC1), %% Check that internal 'handlers' field has not been changed - MS = [{{{?HANDLER_KEY,'$1'},'_','_','_'},[],['$1']}], + MS = [{{{?HANDLER_KEY,'$1'},'_','_'},[],['$1']}], HIds1 = lists:sort(ets:select(?LOGGER_TABLE,MS)), % dirty, internal data HIds2 = lists:sort(logger:get_handler_ids()), HIds1 = HIds2, -- cgit v1.2.3 From 25b2daf1aa19c60eb12964015cc466dc506a3d89 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 14 Aug 2018 15:42:19 +0200 Subject: Remove outdated reference to error loggers --- system/doc/design_principles/des_princ.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/system/doc/design_principles/des_princ.xml b/system/doc/design_principles/des_princ.xml index e21f2a7f4e..dbb31a7bb7 100644 --- a/system/doc/design_principles/des_princ.xml +++ b/system/doc/design_principles/des_princ.xml @@ -64,7 +64,7 @@ the supervisors are similar in structure. The only difference between them is which child processes they supervise. Many of the workers are servers in a server-client relation, - finite-state machines, or event handlers such as error loggers.

+ finite-state machines, or event handlers.

Behaviours are formalizations of these common patterns. The idea is to divide the code for a process in a generic part (a behaviour module) and a specific part (a -- cgit v1.2.3 From 96c1aa0041b368afceef0aef88e82a6c9f8e901d Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 31 Aug 2018 17:08:24 +0200 Subject: [logger] Remove encoding option from logger_formatter The encoding option was introduced in commit 270d909696a753af022df72a404c73f2895b4a02, to allow report callbacks to format according to a given encoding. There was, however, no connection between this encoding option, and the encoding of the device to which the logger handler was writing. Since a formatter is defined to return unicode:chardata(), and in order to avoid mismatch with the encoding of the device, the encoding option is now removed from the formatter. The handler itself must make sure that it does not write illegal data to its device. --- lib/kernel/doc/src/logger_chapter.xml | 11 +++-- lib/kernel/doc/src/logger_formatter.xml | 7 --- lib/kernel/src/logger.erl | 3 +- lib/kernel/src/logger_formatter.erl | 68 ++++++++++++----------------- lib/kernel/src/logger_h_common.erl | 20 ++++++--- lib/kernel/test/logger_disk_log_h_SUITE.erl | 2 +- lib/kernel/test/logger_std_h_SUITE.erl | 2 +- lib/stdlib/src/proc_lib.erl | 2 +- 8 files changed, 52 insertions(+), 63 deletions(-) diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index d58c4a4d42..26066d0777 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -208,12 +208,11 @@ coversion to a string:

fun((logger:report(),logger:report_cb_config()) -> unicode:chardata())
       
-

The fun must obey the encoding, depth - and chars_limit parameters provided in the second - argument, as the formatter can not do anything useful of these - parameters with the returned string. This variant is used when - the formatting of the report depends on the size and encoding - parameters.

+

The fun must obey the depth and chars_limit + parameters provided in the second argument, as the formatter + can not do anything useful of these parameters with the + returned string. This variant is used when the formatting of + the report depends on the size parameters.

Example, format string and arguments:

logger:error("The file does not exist: ~ts",[Filename])

Example, string:

diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 5a060fd42b..24772fd6c4 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -82,13 +82,6 @@ in STDLIB.

Defaults to unlimited.

- encoding = - unicode:encoding() - -

This parameter must reflect the encoding of the device - that the handler prints to.

-

Defaults to utf8

-
legacy_header = boolean()

If set to true a header field is added to diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 7b1377b8ca..df96367d82 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -77,8 +77,7 @@ -type report() :: map() | [{atom(),term()}]. -type report_cb() :: fun((report()) -> {io:format(),[term()]}) | fun((report(),report_cb_config()) -> unicode:chardata()). --type report_cb_config() :: #{encoding := unicode:encoding(), - depth := pos_integer() | unlimited, +-type report_cb_config() :: #{depth := pos_integer() | unlimited, chars_limit := pos_integer() | unlimited}. -type msg_fun() :: fun((term()) -> {io:format(),[term()]} | report() | diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index b0d4adc14d..59aa6ec3af 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -28,7 +28,6 @@ %%% Types -type config() :: #{chars_limit => pos_integer() | unlimited, depth => pos_integer() | unlimited, - encoding => unicode:encoding(), legacy_header => boolean(), max_size => pos_integer() | unlimited, report_cb => logger:report_cb(), @@ -84,7 +83,7 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) true -> "" end, - truncate(B ++ MsgStr ++ A,maps:get(max_size,Config)). + truncate([B,MsgStr,A],maps:get(max_size,Config)). do_format(Level,Data,[level|Format],Config) -> [to_string(level,Level,Config)|do_format(Level,Data,Format,Config)]; @@ -147,7 +146,7 @@ printable_list(X) -> io_lib:printable_list(X). format_msg({string,Chardata},Meta,Config) -> - format_msg({s(Config),[Chardata]},Meta,Config); + format_msg({"~ts",[Chardata]},Meta,Config); format_msg({report,_}=Msg,Meta,#{report_cb:=Fun}=Config) when is_function(Fun,1); is_function(Fun,2) -> format_msg(Msg,Meta#{report_cb=>Fun},maps:remove(report_cb,Config)); @@ -166,13 +165,13 @@ format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,1 Meta,Config) end; format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,2) -> - try Fun(Report,maps:with([encoding,depth,chars_limit],Config)) of - String when ?IS_STRING(String) -> - try unicode:characters_to_list(String) + try Fun(Report,maps:with([depth,chars_limit],Config)) of + Chardata when ?IS_STRING(Chardata) -> + try chardata_to_list(Chardata) % already size limited by report_cb catch _:_ -> P = p(Config), format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, - [Report,String]},Meta,Config) + [Report,Chardata]},Meta,Config) end; Other -> P = p(Config), @@ -189,28 +188,27 @@ format_msg({report,Report},Meta,Config) -> Meta#{report_cb=>fun logger:format_report/1}, Config); format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit, - encoding:=Enc,single_line:=Single}) -> + single_line:=Single}) -> Opts = chars_limit_to_opts(CharsLimit), - format_msg(Msg, Depth, Opts, Enc, Single). + format_msg(Msg, Depth, Opts, Single). chars_limit_to_opts(unlimited) -> []; chars_limit_to_opts(CharsLimit) -> [{chars_limit,CharsLimit}]. -format_msg({Format0,Args},Depth,Opts,Enc,Single) -> +format_msg({Format0,Args},Depth,Opts,Single) -> try Format1 = io_lib:scan_format(Format0, Args), Format = reformat(Format1, Depth, Single), io_lib:build_text(Format,Opts) catch C:R:S -> - P = p(Enc,Single), + P = p(Single), FormatError = "FORMAT ERROR: "++P++" - "++P, case Format0 of FormatError -> %% already been here - avoid failing cyclically erlang:raise(C,R,S); _ -> - format_msg({FormatError,[Format0,Args]}, - Depth,Opts,Enc,Single) + format_msg({FormatError,[Format0,Args]},Depth,Opts,Single) end end. @@ -233,6 +231,14 @@ limit_depth(#{control_char:=C0, args:=Args}=M0, Depth) -> C = C0 - ($a - $A), %To uppercase. M0#{control_char:=C,args:=Args++[Depth]}. +chardata_to_list(Chardata) -> + case unicode:characters_to_list(Chardata,unicode) of + List when is_list(List) -> + List; + Error -> + throw(Error) + end. + truncate(String,unlimited) -> String; truncate(String,Size) -> @@ -278,12 +284,11 @@ maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> #{title:=Title}=MyMeta = add_legacy_title(Level,Meta,Config), - {{Y,Mo,D},{H,Mi,Sec},Micro,UtcStr} = + {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = timestamp_to_datetimemicro(Timestamp,Config), - S = s(Config), Header = - io_lib:format("="++S++"==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", - [Title,D,month(Mo),Y,H,Mi,Sec,Micro,UtcStr]), + 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. @@ -324,7 +329,6 @@ month(12) -> "Dec". add_default_config(Config0) -> Default = #{chars_limit=>unlimited, - encoding=>utf8, error_logger_notice_header=>info, legacy_header=>false, single_line=>true, @@ -502,25 +506,9 @@ check_timezone(Tz) -> error end. -p(#{encoding:=Enc, single_line:=Single}) -> - p(Enc,Single). - -p(Enc,Single) -> - "~"++p_width(Single)++p_char(Enc). - -p_width(true) -> - "0"; -p_width(false) -> - "". - -p_char(latin1) -> - "p"; -p_char(_) -> - "tp". - -s(#{encoding:=Enc}) -> - s(Enc); -s(latin1) -> - "~s"; -s(_) -> - "~ts". +p(#{single_line:=Single}) -> + p(Single); +p(true) -> + "~0tp"; +p(false) -> + "~tp". diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 854e5479b9..2818a460f1 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -40,7 +40,7 @@ info_notify/1]). %%%----------------------------------------------------------------- -%%% Covert log data on any form to binary +%%% Convert log data on any form to binary -spec log_to_binary(LogEvent,Config) -> LogString when LogEvent :: logger:log_event(), Config :: logger:handler_config(), @@ -57,13 +57,14 @@ do_log_to_binary(Log,Config) -> {Formatter,FormatterConfig} = maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), String = try_format(Log,Formatter,FormatterConfig), - try unicode:characters_to_binary(String) - catch _:_ -> + try string_to_binary(String) + catch C2:R2:S2 -> ?LOG_INTERNAL(debug,[{formatter_error,Formatter}, {config,FormatterConfig}, {log_event,Log}, - {bad_return_value,String}]), - <<"FORMATTER ERROR: bad_return_value">> + {bad_return_value,String}, + {catched,{C2,R2,S2}}]), + <<"FORMATTER ERROR: bad return value">> end. try_format(Log,Formatter,FormatterConfig) -> @@ -85,6 +86,15 @@ try_format(Log,Formatter,FormatterConfig) -> end end. +string_to_binary(String) -> + case unicode:characters_to_binary(String) of + Binary when is_binary(Binary) -> + Binary; + Error -> + throw(Error) + end. + + %%%----------------------------------------------------------------- %%% Check that the configuration term is valid check_common_config({mode_tab,_Tid}) -> diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index a4b15c841b..29624b16c2 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -367,7 +367,7 @@ formatter_fail(Config) -> ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}), logger:notice(?msg,?domain), try_match_file(?log_no(LogFile,1), - escape(Got3)++"FORMATTER ERROR: bad_return_value", + escape(Got3)++"FORMATTER ERROR: bad return value", 5000), %% Check that handler is still alive and was never dead diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 0930cd4211..3426567bbf 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -280,7 +280,7 @@ formatter_fail(Config) -> ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,bad_return}), logger:notice(?msg,?domain), try_match_file(Log, - escape(Got3)++"FORMATTER ERROR: bad_return_value", + escape(Got3)++"FORMATTER ERROR: bad return value", 5000), %% Check that handler is still alive and was never dead diff --git a/lib/stdlib/src/proc_lib.erl b/lib/stdlib/src/proc_lib.erl index d07c62500b..d5c92c9a37 100644 --- a/lib/stdlib/src/proc_lib.erl +++ b/lib/stdlib/src/proc_lib.erl @@ -757,7 +757,7 @@ check(Res) -> Res. report_cb(#{label:={proc_lib,crash}, report:=CrashReport}, Extra) -> Default = #{chars_limit => unlimited, depth => unlimited, - encoding => latin1}, + encoding => utf8}, do_format(CrashReport, maps:merge(Default,Extra)). -spec format(CrashReport) -> string() when -- cgit v1.2.3 From d9e58a29f9194ea8b2d9e1bdcf5b89a9cc29f988 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 4 Sep 2018 14:30:49 +0200 Subject: [logger] Update doc about file options in logger_std_h --- lib/kernel/doc/src/logger_std_h.xml | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index b526ed037d..fcd8189bae 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -59,13 +59,22 @@

This has the value standard_io, standard_error, {file,LogFileName}, or {file,LogFileName,LogFileOpts}.

+

If LogFileOpts is specified, it replaces the default + list of options used when opening the log file. The default + list is [raw,append,delayed_write]. One reason to do + so can be to change append to, for + example, write, ensuring that the old log is + truncated when a node is restarted. See the reference manual + for file:open/2 + for more information about file options.

+

Log files are always UTF-8 encoded. The encoding can not be + changed by setting the option {encoding,Encoding} + in LogFileOpts.

+

Notice that the standard handler does not have support for + circular logging. Use the disk_log handler, + logger_disk_log_h, + for this.

Defaults to standard_io.

-

It is recommended not to specify LogFileOpts unless absolutely - necessary. The default options used by the handler to open a file for logging are - raw, append, and delayed_write. Notice that the standard - handler does not have support for circular logging. Use the disk_log handler, - logger_disk_log_h, - for this.

filesync_repeat_interval @@ -73,12 +82,12 @@ a file sync operation to write buffered data to disk. The handler attempts the operation repeatedly, but only performs a new sync if something has actually been logged.

-

Defaults to 5000 milliseconds.

If no_repeat is set as value, the repeated file sync operation is disabled, and it is the operating system settings that determine how quickly or slowly data is written to disk. The user can also call the filesync/1 function to perform a file sync.

+

Defaults to 5000 milliseconds.

Other configuration parameters exist, to be used for customizing -- cgit v1.2.3 From 1832ab7dfb86559af2dfc0518669dcdce4f704ee Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 4 Sep 2018 17:23:08 +0200 Subject: [logger] Fix logger_disk_log_h_SUITE:sync and add som debug info --- lib/kernel/test/logger_disk_log_h_SUITE.erl | 62 +++++++++++++---------------- 1 file changed, 27 insertions(+), 35 deletions(-) diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 29624b16c2..ed441f7e65 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -524,27 +524,14 @@ sync(Config) -> formatter=>{?MODULE,nl}}), start_tracer([{disk_log,blog,2}, - {disk_log,sync,1}], + {logger_disk_log_h,disk_log_sync,2}], [{disk_log,blog,<<"first\n">>}, - {disk_log,sync}]), + {logger_disk_log_h,disk_log_sync}]), logger:notice("first", ?domain), %% wait for automatic disk_log_sync check_tracer(?FILESYNC_REPEAT_INTERVAL*2), - start_tracer([{disk_log,blog,2}, - {disk_log,sync,1}], - [{disk_log,blog,<<"second\n">>}, - {disk_log,blog,<<"third\n">>}, - {disk_log,sync}]), - %% two log requests in fast succession will make the handler skip - %% an automatic disk log sync - logger:notice("second", ?domain), - logger:notice("third", ?domain), - %% do explicit sync - logger_disk_log_h:filesync(?MODULE), - check_tracer(100), - %% check that if there's no repeated disk_log_sync active, %% a disk_log_sync is still performed when handler goes idle {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), @@ -553,20 +540,25 @@ sync(Config) -> no_repeat = maps:get(filesync_repeat_interval, logger_disk_log_h:info(?MODULE)), + %% The following timer is to make sure the time from last log + %% ("first") to next ("second") is long enough, so the a flush is + %% triggered by the idle timeout between "fourth" and "fifth". + timer:sleep(?IDLE_DETECT_TIME_MSEC*2), start_tracer([{disk_log,blog,2}, - {disk_log,sync,1}], - [{disk_log,blog,<<"fourth\n">>}, - {disk_log,blog,<<"fifth\n">>}, - {disk_log,sync}]), + {logger_disk_log_h,disk_log_sync,2}], + [{disk_log,blog,<<"second\n">>}, + {logger_disk_log_h,disk_log_sync}, + {disk_log,blog,<<"third\n">>}, + {logger_disk_log_h,disk_log_sync}]), - logger:notice("fourth", ?domain), + logger:notice("second", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - logger:notice("fifth", ?domain), + logger:notice("third", ?domain), %% wait for automatic disk_log_sync check_tracer(?IDLE_DETECT_TIME_MSEC*2), - try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\nfifth\n">>}, 1000), + try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), %% switch repeated disk_log_sync on and verify that the looping works SyncInt = 1000, @@ -1494,7 +1486,7 @@ start_tracer(Trace,Expected) -> ok. tpl([{M,F,A}|Trace]) -> - {ok,Match} = dbg:tpl(M,F,A,[]), + {ok,Match} = dbg:tpl(M,F,A,c), case lists:keyfind(matched,1,Match) of {_,_,1} -> ok; @@ -1507,23 +1499,23 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]}}, +tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]},Caller}, {Pid,[{Mod,Func,Op}|Expected]}) -> - maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); -tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> - maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); -tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> - maybe_tracer_done(Pid,Expected,{Mod,Func}); -tracer({trace,_,call,Call}, {Pid,Expected}) -> - ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]), + maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); +tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); +tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); +tracer({trace,_,call,Call,Caller}, {Pid,Expected}) -> + ct:log("Tracer got unexpected: ~p~nCaller: ~p~nExpected: ~p~n",[Call,Caller,Expected]), Pid ! {tracer_got_unexpected,Call,Expected}, {Pid,Expected}. -maybe_tracer_done(Pid,[],Got) -> - ct:log("Tracer got: ~p~n",[Got]), +maybe_tracer_done(Pid,[],Got,Caller) -> + ct:log("Tracer got: ~p~nCaller: ~p~n",[Got,Caller]), Pid ! tracer_done; -maybe_tracer_done(Pid,Expected,Got) -> - ct:log("Tracer got: ~p~n",[Got]), +maybe_tracer_done(Pid,Expected,Got,Caller) -> + ct:log("Tracer got: ~p~nCaller: ~p~n",[Got,Caller]), {Pid,Expected}. check_tracer(T) -> -- cgit v1.2.3 From a9a72da93e9b93a1d7ee9936b8e223545277480e Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 6 Sep 2018 13:51:49 +0200 Subject: [logger] Refactor, and add error detection for configuration --- lib/kernel/doc/src/logger.xml | 2 +- lib/kernel/src/logger.erl | 153 +++++++++++--------- lib/kernel/test/logger_SUITE.erl | 222 +++++++++++++++++++++++++++++- lib/kernel/test/logger_simple_h_SUITE.erl | 3 +- 4 files changed, 310 insertions(+), 70 deletions(-) diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index a4d6efa2d8..464c65ba76 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -527,7 +527,7 @@ start(_, []) -> Error -> Error end.

This reads the logger configuration parameter from - the my_all application and starts the configured + the my_app application and starts the configured handlers. The contents of the configuration use the same rules as the logger handler configuration. diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index df96367d82..0ada8b4924 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -115,6 +115,11 @@ -type config_handler() :: {handler, handler_id(), module(), handler_config()}. +-type config_logger() :: [{handler,default,undefined} | + config_handler() | + {filters,log | stop,[{filter_id(),filter()}]} | + {module_level,level(),[module()]}]. + -export_type([log_event/0, level/0, report/0, @@ -582,19 +587,21 @@ get_config() -> %% tree is started. internal_init_logger() -> try + Env = get_logger_env(kernel), + check_logger_config(kernel,Env), ok = logger:set_primary_config(level, get_logger_level()), - ok = logger:set_primary_config(filter_default, get_primary_filter_default()), + ok = logger:set_primary_config(filter_default, + get_primary_filter_default(Env)), [case logger:add_primary_filter(Id, Filter) of ok -> ok; {error, Reason} -> throw(Reason) - end || {Id, Filter} <- get_primary_filters()], + end || {Id, Filter} <- get_primary_filters(Env)], - _ = [[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_module_level(Modules, Level) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {module_level, Level, Modules} <- Env], case logger:set_handler_config(simple,filters, get_default_handler_filters()) of @@ -602,24 +609,24 @@ internal_init_logger() -> {error,{not_found,simple}} -> ok end, - init_kernel_handlers() + init_kernel_handlers(Env) catch throw:Reason -> ?LOG_ERROR("Invalid logger config: ~p", [Reason]), {error, {bad_config, {kernel, Reason}}} end. --spec init_kernel_handlers() -> ok | {error,term()}. +-spec init_kernel_handlers(config_logger()) -> 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() -> +init_kernel_handlers(Env) -> try - case get_logger_type() of + case get_logger_type(Env) of {ok,silent} -> ok = logger:remove_handler(simple); {ok,false} -> ok; {ok,Type} -> - init_default_config(Type) + init_default_config(Type,Env) end catch throw:Reason -> ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), @@ -634,10 +641,13 @@ init_kernel_handlers() -> %% 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(App,get_logger_env(App)); add_handlers(HandlerConfig) -> + add_handlers(application:get_application(),HandlerConfig). + +add_handlers(App,HandlerConfig) -> try - check_logger_config(HandlerConfig), + check_logger_config(App,HandlerConfig), DefaultAdded = lists:foldl( fun({handler, default = Id, Module, Config}, _) @@ -651,17 +661,22 @@ add_handlers(HandlerConfig) -> ({handler, Id, Module, Config}, Default) -> setup_handler(Id, Module, Config), Default orelse Id == default; - (_, Default) -> 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], + [case logger:remove_handler(simple) of + ok -> ok; + {error,{not_found,simple}} -> ok + end || DefaultAdded], ok - catch throw:Reason -> + catch throw:Reason0 -> + Reason = + case App of + undefined -> Reason0; + _ -> {App,Reason0} + end, ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), {error, {bad_config, {handler, Reason}}} end. @@ -672,26 +687,35 @@ setup_handler(Id, Module, Config) -> {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() -> +check_logger_config(_,[]) -> + ok; +check_logger_config(App,[{handler,_,_,_}|Env]) -> + check_logger_config(App,Env); +check_logger_config(kernel,[{handler,default,undefined}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{filters,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{module_level,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(_,Bad) -> + throw(Bad). + +-spec get_logger_type(config_logger()) -> + {ok, standard_io | false | silent | + {file, file:name_all()} | + {file, file:name_all(), [file:mode()]}}. +get_logger_type(Env) -> case application:get_env(kernel, error_logger) of {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, false} -> {ok, false}; {ok, silent} -> {ok, silent}; undefined -> - case lists:member({handler,default,undefined}, get_logger_env()) of + case lists:member({handler,default,undefined}, Env) of true -> {ok, false}; false -> @@ -709,56 +733,55 @@ get_logger_level() -> throw({logger_level, Level}) end. -get_primary_filter_default() -> - case lists:keyfind(filters,1,get_logger_env()) of +get_primary_filter_default(Env) -> + case lists:keyfind(filters,1,Env) of {filters,Default,_} -> Default; false -> log end. -get_primary_filters() -> - lists:foldl( - fun({filters, _, Filters}, _Acc) -> - Filters; - (_, Acc) -> - Acc - end, [], get_logger_env()). +get_primary_filters(Env) -> + case [F || F={filters,_,_} <- Env] of + [{filters,_,Filters}] -> + case lists:all(fun({_,_}) -> true; (_) -> false end,Filters) of + true -> Filters; + false -> throw({invalid_filters,Filters}) + end; + [] -> []; + _ -> throw({multiple_filters,Env}) + end. %% 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(), +init_default_config(Type,Env) when Type==standard_io; + Type==standard_error; + element(1,Type)==file -> DefaultFormatter = #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}, DefaultConfig = DefaultFormatter#{config=>#{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); + {handler, default, logger_std_h, Config} -> + %% Only want to add the logger_std_h config + %% if not configured by user AND the default + %% handler is still the logger_std_h. + lists:keyreplace(default, 2, Env, + {handler, default, logger_std_h, + maps:merge(DefaultConfig,Config)}); + {handler, default, Module,Config} -> + %% 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. + lists:keyreplace(default, 2, Env, + {handler, default, Module, + maps:merge(DefaultFormatter,Config)}); _ -> %% 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}). + application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]). get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of @@ -768,8 +791,8 @@ get_default_handler_filters() -> ?DEFAULT_HANDLER_FILTERS([otp,sasl]) end. -get_logger_env() -> - application:get_env(kernel, logger, []). +get_logger_env(App) -> + application:get_env(App, logger, []). %%%----------------------------------------------------------------- %%% Internal diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 824c95d6df..49b76f03b2 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -37,7 +37,8 @@ suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> case logger:get_handler_config(?STANDARD_HANDLER) of @@ -98,7 +99,9 @@ all() -> via_logger_process, other_node, compare_levels, - process_metadata]. + process_metadata, + app_config, + kernel_config]. start_stop(_Config) -> S = whereis(logger), @@ -895,12 +898,227 @@ process_metadata(_Config) -> ok = logger:unset_process_metadata(), undefined = logger:get_process_metadata(), + ok = logger:update_process_metadata(#{custom=>added_again}), + {error,badarg} = ?TRY(logger:update_process_metadata(bad)), + #{custom:=added_again} = logger:get_process_metadata(), + ok. process_metadata(cleanup,_Config) -> logger:remove_handler(h1), ok. +app_config(Config) -> + %% Start a node with default configuration + {ok,_,Node} = logger_test_lib:setup(Config,[]), + + App1Name = app1, + App1 = {application, App1Name, + [{description, "Test of app with logger config"}, + {applications, [kernel]}]}, + ok = rpc:call(Node,application,load,[App1]), + ok = rpc:call(Node,application,set_env, + [App1Name,logger,[{handler,default,logger_std_h,#{}}]]), + + %% Try to add an own default handler + {error,{bad_config,{handler,{app1,{already_exist,default}}}}} = + rpc:call(Node,logger,add_handlers,[App1Name]), + + %% Add a different handler + ok = rpc:call(Node,application,set_env,[App1Name,logger, + [{handler,myh,logger_std_h,#{}}]]), + ok = rpc:call(Node,logger,add_handlers,[App1Name]), + + {ok,#{filters:=DF}} = rpc:call(Node,logger,get_handler_config,[default]), + {ok,#{filters:=[]}} = rpc:call(Node,logger,get_handler_config,[myh]), + + true = test_server:stop_node(Node), + + %% Start a node with no default handler, then add an own default handler + {ok,#{handlers:=[#{id:=simple}]},Node} = + logger_test_lib:setup(Config,[{logger,[{handler,default,undefined}]}]), + + ok = rpc:call(Node,application,load,[App1]), + ok = rpc:call(Node,application,set_env, + [App1Name,logger,[{handler,default,logger_std_h,#{}}]]), + ok = rpc:call(Node,logger,add_handlers,[App1Name]), + + #{handlers:=[#{id:=default,filters:=DF}]} = + rpc:call(Node,logger,get_config,[]), + + true = test_server:stop_node(Node), + + %% Start a silent node, then add an own default handler + {ok,#{handlers:=[]},Node} = + logger_test_lib:setup(Config,[{error_logger,silent}]), + + {error,{bad_config,{handler,[{some,bad,config}]}}} = + rpc:call(Node,logger,add_handlers,[[{some,bad,config}]]), + ok = rpc:call(Node,logger,add_handlers, + [[{handler,default,logger_std_h,#{}}]]), + + #{handlers:=[#{id:=default,filters:=DF}]} = + rpc:call(Node,logger,get_config,[]), + + ok. + +%% This test case is maintly to see code coverage. Note that +%% logger_env_var_SUITE tests a lot of the same, and checks the +%% functionality more thoroughly, but since it all happens at node +%% start, it is not possible to see code coverage in that test. +kernel_config(Config) -> + %% Start a node with simple handler only, then simulate kernel + %% start by calling internally exported + %% internal_init_logger(). This is to test all variants of kernel + %% config, including bad config, and see the code coverage. + {ok,#{handlers:=[#{id:=simple,filters:=DF}]}=LC,Node} = + logger_test_lib:setup(Config,[{error_logger,false}]), + + %% Same once more, to get coverage + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + LC = rpc:call(Node,logger,get_config,[]), + + %% This shall mean the same as above, but using 'logger' parameter + %% instead of 'error_logger' + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{handler,default,undefined}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + LC = rpc:call(Node,logger,get_config,[]), + + %% Silent + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,application,set_env,[kernel,error_logger,silent]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Default + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% error_logger=tty (same as default) + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,set_env,[kernel,error_logger,tty]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% error_logger={file,File} + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + F = filename:join(?config(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + ok = rpc:call(Node,application,set_env,[kernel,error_logger,{file,F}]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but using 'logger' parameter instead of 'error_logger' + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_std_h, + #{config=>#{type=>{file,F}}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but with type={file,File,Modes} + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + M = [raw,write,delayed_write], + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_std_h, + #{config=>#{type=>{file,F,M}}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,M}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but with disk_log handler + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + M = [raw,write,delayed_write], + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_disk_log_h, + #{config=>#{file=>F}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{file:=F}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Set primary filters and module level. No default handler. + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{handler,default,undefined}, + {filters,stop,[{f1,{fun(_,_) -> log end,ok}}]}, + {module_level,debug,[?MODULE]}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=stop,filters:=[_]}, + handlers:=[], + module_levels:=[{?MODULE,debug}]} = rpc:call(Node,logger,get_config,[]), + + %% Bad config + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + + ok = rpc:call(Node,application,set_env,[kernel,error_logger,bad]), + {error,{bad_config,{kernel,{error_logger,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env,[kernel,logger_level,bad]), + {error,{bad_config,{kernel,{logger_level,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,unset_env,[kernel,logger_level]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[bad]}]]), + {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[bad]}]]), + {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[{f1,bad}]}]]), + {error,{bad_config,{kernel,{invalid_filter,{f1,bad}}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,MF=[{filters,stop,[]},{filters,log,[]}]]), + {error,{bad_config,{kernel,{multiple_filters,MF}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{module_level,bad,[?MODULE]}]]), + {error,{bad_config,{kernel,{invalid_level,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok. + %%%----------------------------------------------------------------- %%% Internal check_logged(Level,Format,Args,Meta) -> diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl index 79e5c057ad..e0ad792bdb 100644 --- a/lib/kernel/test/logger_simple_h_SUITE.erl +++ b/lib/kernel/test/logger_simple_h_SUITE.erl @@ -117,8 +117,7 @@ replace_default(Config) -> log(Node, critical, [?str,[?keyval_rep]]), log(Node, notice, [["fake",string,"line:",?LINE]]), - Env = rpc:call(Node, application, get_env, [kernel, logger, []]), - ok = rpc:call(Node, logger, add_handlers, [Env]), + ok = rpc:call(Node, logger, add_handlers, [kernel]), ok. -- cgit v1.2.3 From 625616652595249ff0866d4de8a04f3c8fa0eec4 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 6 Sep 2018 14:30:36 +0200 Subject: [logger] Improve code coverage in test --- lib/kernel/src/logger_server.erl | 4 +--- lib/kernel/test/logger_SUITE.erl | 9 +++++++-- lib/kernel/test/logger_formatter_SUITE.erl | 7 +++++++ 3 files changed, 15 insertions(+), 5 deletions(-) diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index 01ac1b4b50..e3827c6475 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -372,7 +372,7 @@ sanity_check(Owner,Key,Value) -> sanity_check(HandlerId,Config) when is_map(Config) -> sanity_check_1(HandlerId,maps:to_list(Config)); sanity_check(_,Config) -> - {error,{invalid_handler_config,Config}}. + {error,{invalid_config,Config}}. sanity_check_1(Owner,Config) when is_list(Config) -> try @@ -417,8 +417,6 @@ check_mod(Mod) when is_atom(Mod) -> check_mod(Mod) -> throw({invalid_module,Mod}). -check_level({LevelInt,cached}) when LevelInt>=?EMERGENCY, LevelInt= - ok; check_level(Level) -> case lists:member(Level,?LEVELS) of true -> diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 49b76f03b2..36c093d7f4 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -214,6 +214,7 @@ add_remove_filter(cleanup,_Config) -> change_config(_Config) -> %% Overwrite handler config - check that defaults are added + {error,{not_found,h1}} = logger:set_handler_config(h1,#{}), ok = logger:add_handler(h1,?MODULE,#{level=>notice,custom=>custom}), {ok,#{module:=?MODULE,level:=notice,filter_default:=log,custom:=custom}} = logger:get_handler_config(h1), @@ -392,6 +393,8 @@ set_module_level(_Config) -> {error,{invalid_level,bad}} = logger:set_module_level(?MODULE,bad), {error,{not_a_list_of_modules,{bad}}} = logger:set_module_level({bad},warning), + {error,{not_a_list_of_modules,[{bad}]}} = + logger:set_module_level([{bad}],warning), ok = logger:set_module_level(?MODULE,warning), [{?MODULE,warning}] = logger:get_module_level([?MODULE,other]), [{?MODULE,warning}] = logger:get_module_level(?MODULE), @@ -408,6 +411,7 @@ set_module_level(_Config) -> ok = check_logged(notice,M2,?MY_LOC(1)), {error,{not_a_list_of_modules,{bad}}} = logger:unset_module_level({bad}), + {error,{not_a_list_of_modules,[{bad}]}} = logger:unset_module_level([{bad}]), ok = logger:unset_module_level(?MODULE), [] = logger:get_module_level([?MODULE,other]), [] = logger:get_module_level(?MODULE), @@ -550,7 +554,7 @@ handler_failed(_Config) -> register(callback_receiver,self()), {error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}), {error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}), - {error,{invalid_handler_config,bad}} = logger:add_handler(h1,?MODULE,bad), + {error,{invalid_config,bad}} = logger:add_handler(h1,?MODULE,bad), {error,{invalid_filters,false}} = logger:add_handler(h1,?MODULE,#{filters=>false}), {error,{invalid_filter_default,true}} = @@ -625,7 +629,8 @@ handler_failed(cleanup,_Config) -> ok. config_sanity_check(_Config) -> - %% Logger config + %% Primary config + {error,{invalid_config,bad}} = logger:set_primary_config(bad), {error,{invalid_filter_default,bad}} = logger:set_primary_config(filter_default,bad), {error,{invalid_level,bad}} = logger:set_primary_config(level,bad), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 2ec4b243cf..8c13f0f908 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -765,6 +765,8 @@ check_config(_Config) -> %% Test that formatter config can be changed, and that the default %% template is updated accordingly update_config(_Config) -> + {error,{not_found,?MODULE}} = logger:update_formatter_config(?MODULE,#{}), + logger:add_handler_filter(default,silence,{fun(_,_) -> stop end,ok}), ok = logger:add_handler(?MODULE,?MODULE,#{}), D = lists:seq(1,1000), @@ -817,6 +819,11 @@ update_config(_Config) -> ct:log("~p",[C6]), ["=NOTICE REPORT==== "++_,_D6] = Lines6, + {error,{invalid_formatter_config,bad}} = + logger:update_formatter_config(?MODULE,bad), + {error,{invalid_formatter_config,logger_formatter,{depth,bad}}} = + logger:update_formatter_config(?MODULE,depth,bad), + ok. update_config(cleanup,_Config) -> -- cgit v1.2.3 From eb29e06488ded39e657db655e09f04e95568eb76 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 7 Sep 2018 14:38:46 +0200 Subject: [logger] Increase timetrap timer for handler_requests_under_load test --- lib/kernel/test/logger_disk_log_h_SUITE.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index ed441f7e65..a815db14e9 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -1186,7 +1186,7 @@ restart_after(cleanup, _Config) -> %% during high load to verify that sync, dropping and flushing is %% handled correctly. handler_requests_under_load() -> - [{timetrap,{minutes,3}}]. + [{timetrap,{minutes,5}}]. handler_requests_under_load(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = -- cgit v1.2.3 From a98ffe831d2a1cf44d0b7c53e2d72ade9d5a3dbb Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 7 Sep 2018 16:49:30 +0200 Subject: [logger] Fix spec for handler callbacks to always return ok --- lib/kernel/src/logger_disk_log_h.erl | 2 +- lib/kernel/src/logger_std_h.erl | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 3c12c9e68b..26375373aa 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -225,7 +225,7 @@ removing_handler(#{id:=Name}) -> %%%----------------------------------------------------------------- %%% Log a string or report --spec log(LogEvent, Config) -> ok | dropped when +-spec log(LogEvent, Config) -> ok when LogEvent :: logger:log_event(), Config :: logger:handler_config(). diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index b60e7cf587..5dc4bc91ad 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -210,7 +210,7 @@ removing_handler(#{id:=Name}) -> %%%----------------------------------------------------------------- %%% Log a string or report --spec log(LogEvent, Config) -> ok | dropped when +-spec log(LogEvent, Config) -> ok when LogEvent :: logger:log_event(), Config :: logger:handler_config(). -- cgit v1.2.3 From 7140fe7679c1ea0862961d2fc34f9d8283c04ca3 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 11 Sep 2018 14:11:29 +0200 Subject: [logger] Check for deadlock when removing filters If a filter fails, it is removed by a call to logger:remove_filter/1,2. If the log event that caused the failure was issued on the logger process itself, this would earlier cause a deadlock due to a gen_server:call to self(). This is now prevented. --- lib/kernel/src/logger_server.erl | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index e3827c6475..a1d40f1123 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -319,6 +319,7 @@ call(Request) -> case get(?LOGGER_SERVER_TAG) of true when Action == add_handler; Action == remove_handler; + Action == add_filter; Action == remove_filter; Action == update_config; Action == set_config -> {error,{attempting_syncronous_call_to_self,Request}}; _ -> -- cgit v1.2.3 From a4ff9f378ae7008e268d1c2facd44d049be6e930 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 12 Sep 2018 14:37:02 +0200 Subject: [logger] Include single_line option to report_cb If the report callback function has two arguments, the second argument is a map with options to limit the size of the log event. To even allow a better formatting when the event shall be printed on a single line, the new option single_line is now included in this argument. --- lib/kernel/doc/src/logger_chapter.xml | 11 +++++++---- lib/kernel/src/logger.erl | 3 ++- lib/kernel/src/logger_formatter.erl | 2 +- 3 files changed, 10 insertions(+), 6 deletions(-) diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 26066d0777..4a81cfa34a 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -209,10 +209,13 @@

fun((logger:report(),logger:report_cb_config()) -> unicode:chardata())
       

The fun must obey the depth and chars_limit - parameters provided in the second argument, as the formatter - can not do anything useful of these parameters with the - returned string. This variant is used when the formatting of - the report depends on the size parameters.

+ parameters provided in the second argument, as the formatter can + not do anything useful of these parameters with the returned + string. The extra data also contains a field named + single_line, indicating if the printed log message may + contain line breaks or not. This variant is used when the + formatting of the report depends on the size or single line + parameters.

Example, format string and arguments:

logger:error("The file does not exist: ~ts",[Filename])

Example, string:

diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 0ada8b4924..752dd8d493 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -78,7 +78,8 @@ -type report_cb() :: fun((report()) -> {io:format(),[term()]}) | fun((report(),report_cb_config()) -> unicode:chardata()). -type report_cb_config() :: #{depth := pos_integer() | unlimited, - chars_limit := pos_integer() | unlimited}. + chars_limit := pos_integer() | unlimited, + single_line := boolean()}. -type msg_fun() :: fun((term()) -> {io:format(),[term()]} | report() | unicode:chardata()). diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 59aa6ec3af..ded89bac9f 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -165,7 +165,7 @@ format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,1 Meta,Config) end; format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,2) -> - try Fun(Report,maps:with([depth,chars_limit],Config)) of + try Fun(Report,maps:with([depth,chars_limit,single_line],Config)) of Chardata when ?IS_STRING(Chardata) -> try chardata_to_list(Chardata) % already size limited by report_cb catch _:_ -> -- cgit v1.2.3 From 98bfd0c19ca1f563c18c252d58801c2c5731861a Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 12 Sep 2018 14:54:02 +0200 Subject: [proc_lib] Improve crash reports for single line logging --- lib/stdlib/src/proc_lib.erl | 91 ++++++++++++++++++++++++++++++++------------- 1 file changed, 65 insertions(+), 26 deletions(-) diff --git a/lib/stdlib/src/proc_lib.erl b/lib/stdlib/src/proc_lib.erl index d5c92c9a37..cfbaf8b242 100644 --- a/lib/stdlib/src/proc_lib.erl +++ b/lib/stdlib/src/proc_lib.erl @@ -757,6 +757,7 @@ check(Res) -> Res. report_cb(#{label:={proc_lib,crash}, report:=CrashReport}, Extra) -> Default = #{chars_limit => unlimited, depth => unlimited, + single_line => false, encoding => utf8}, do_format(CrashReport, maps:merge(Default,Extra)). @@ -780,33 +781,48 @@ format(CrashReport, Encoding) -> format(CrashReport, Encoding, Depth) -> do_format(CrashReport, #{chars_limit => unlimited, depth => Depth, - encoding => Encoding}). - -do_format([OwnReport,LinkReport], Extra) -> - MyIndent = " ", + encoding => Encoding, + single_line => false}). + +do_format([OwnReport,LinkReport], #{single_line:=Single}=Extra) -> + Indent = if Single -> ""; + true -> " " + end, + MyIndent = Indent ++ Indent, + Sep = nl(Single,"; "), OwnFormat = format_report(OwnReport, MyIndent, Extra), - LinkFormat = format_link_report(LinkReport, MyIndent, Extra), - Str = io_lib:format(" crasher:~n~ts neighbours:~n~ts", - [OwnFormat, LinkFormat]), + LinkFormat = lists:join(Sep,format_link_report(LinkReport, MyIndent, Extra)), + Nl = nl(Single," "), + Str = io_lib:format("~scrasher:"++Nl++"~ts"++Sep++"~sneighbours:"++Nl++"~ts", + [Indent,OwnFormat,Indent,LinkFormat]), lists:flatten(Str). -format_link_report([Link|Reps], Indent, Extra) -> +format_link_report([Link|Reps], Indent0, #{single_line:=Single}=Extra) -> Rep = case Link of {neighbour,Rep0} -> Rep0; _ -> Link end, + Indent = if Single -> ""; + true -> Indent0 + end, LinkIndent = [" ",Indent], - [Indent,"neighbour:\n",format_report(Rep, LinkIndent, Extra)| + [[Indent,"neighbour:",nl(Single," "),format_report(Rep, LinkIndent, Extra)]| format_link_report(Reps, Indent, Extra)]; format_link_report(Rep, Indent, Extra) -> format_report(Rep, Indent, Extra). -format_report(Rep, Indent, Extra) when is_list(Rep) -> - format_rep(Rep, Indent, Extra); -format_report(Rep, Indent, #{encoding:=Enc,depth:=unlimited}) -> - io_lib:format("~s~"++modifier(Enc)++"p~n", [Indent, Rep]); -format_report(Rep, Indent, #{encoding:=Enc,depth:=Depth}) -> - io_lib:format("~s~"++modifier(Enc)++"P~n", [Indent, Rep, Depth]). +format_report(Rep, Indent, #{single_line:=Single}=Extra) when is_list(Rep) -> + lists:join(nl(Single,", "),format_rep(Rep, Indent, Extra)); +format_report(Rep, Indent0, #{encoding:=Enc,depth:=Depth, + chars_limit:=Limit,single_line:=Single}) -> + {P,Tl} = p(Enc,Depth), + {Indent,Width} = if Single -> {"","0"}; + true -> {Indent0,""} + end, + Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; + true -> [] + end, + io_lib:format("~s~"++Width++P, [Indent, Rep | Tl], Opts). format_rep([{initial_call,InitialCall}|Rep], Indent, Extra) -> [format_mfa(Indent, InitialCall, Extra)|format_rep(Rep, Indent, Extra)]; @@ -818,19 +834,32 @@ format_rep([{Tag,Data}|Rep], Indent, Extra) -> format_rep(_, _, _Extra) -> []. -format_exception(Class, Reason, StackTrace, #{encoding:=Enc}=Extra) -> +format_exception(Class, Reason, StackTrace, + #{encoding:=Enc,depth:=Depth,chars_limit:=Limit, + single_line:=Single}=Extra) -> PF = pp_fun(Extra), StackFun = fun(M, _F, _A) -> (M =:= erl_eval) or (M =:= ?MODULE) end, - %% EI = " exception: ", - EI = " ", - [EI, erl_error:format_exception(1+length(EI), Class, Reason, - StackTrace, StackFun, PF, Enc), "\n"]. + if Single -> + {P,Tl} = p(Enc,Depth), + Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; + true -> [] + end, + [atom_to_list(Class), ": ", + io_lib:format("~0"++P,[{Reason,StackTrace}|Tl],Opts)]; + true -> + EI = " ", + [EI, erl_error:format_exception(1+length(EI), Class, Reason, + StackTrace, StackFun, PF, Enc)] + end. -format_mfa(Indent, {M,F,Args}=StartF, #{encoding:=Enc}=Extra) -> +format_mfa(Indent0, {M,F,Args}=StartF, #{encoding:=Enc,single_line:=Single}=Extra) -> + Indent = if Single -> ""; + true -> Indent0 + end, try A = length(Args), [Indent,"initial call: ",atom_to_list(M),$:,to_string(F, Enc),$/, - integer_to_list(A),"\n"] + integer_to_list(A)] catch error:_ -> format_tag(Indent, initial_call, StartF, Extra) @@ -841,21 +870,29 @@ to_string(A, latin1) -> to_string(A, _) -> io_lib:write_atom(A). -pp_fun(#{encoding:=Enc,depth:=Depth,chars_limit:=Limit}) -> +pp_fun(#{encoding:=Enc,depth:=Depth,chars_limit:=Limit,single_line:=Single}) -> {P,Tl} = p(Enc, Depth), + Width = if Single -> "0"; + true -> "" + end, Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; true -> [] end, fun(Term, I) -> - io_lib:format("~." ++ integer_to_list(I) ++ P, [Term|Tl], Opts) + io_lib:format("~" ++ Width ++ "." ++ integer_to_list(I) ++ P, + [Term|Tl], Opts) end. -format_tag(Indent, Tag, Data, #{encoding:=Enc,depth:=Depth,chars_limit:=Limit}) -> +format_tag(Indent0, Tag, Data, #{encoding:=Enc,depth:=Depth,chars_limit:=Limit,single_line:=Single}) -> {P,Tl} = p(Enc, Depth), + {Indent,Width} = if Single -> {"","0"}; + true -> {Indent0,""} + end, Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; true -> [] end, - io_lib:format("~s~p: ~80.18" ++ P ++ "\n", [Indent, Tag, Data|Tl], Opts). + io_lib:format("~s~" ++ Width ++ "p: ~" ++ Width ++ ".18" ++ P, + [Indent, Tag, Data|Tl], Opts). p(Encoding, Depth) -> {Letter, Tl} = case Depth of @@ -868,6 +905,8 @@ p(Encoding, Depth) -> modifier(latin1) -> ""; modifier(_) -> "t". +nl(true,Else) -> Else; +nl(false,_) -> "\n". %%% ----------------------------------------------------------- %%% Stop a process and wait for it to terminate -- cgit v1.2.3 From 48a1c458a46dcd1f031fd3b9689af80b32b4a6a2 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 11 Sep 2018 11:18:52 +0200 Subject: [error_logger] Handle report_cb with arity 2 --- lib/kernel/src/error_logger.erl | 29 +++++++++++++++++++++-------- 1 file changed, 21 insertions(+), 8 deletions(-) diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index ad8c937882..e324be5290 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -147,14 +147,27 @@ do_log(Level,{report,Msg},#{?MODULE:=#{tag:=Tag}}=Meta) -> _ -> %% From logger call which added error_logger data to %% obtain backwards compatibility with error_logger:*_msg/1,2 - RCBFun=maps:get(report_cb,Meta,fun logger:format_report/1), - try RCBFun(Msg) of - {F,A} when is_list(F), is_list(A) -> - {F,A}; - Other -> - {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} - catch C:R -> - {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + case maps:get(report_cb,Meta,fun logger:format_report/1) of + RCBFun when is_function(RCBFun,1) -> + try RCBFun(Msg) of + {F,A} when is_list(F), is_list(A) -> + {F,A}; + Other -> + {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} + catch C:R -> + {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + end; + RCBFun when is_function(RCBFun,2) -> + try RCBFun(Msg,#{depth=>get_format_depth(), + chars_limit=>unlimited, + single_line=>false}) of + Chardata when ?IS_STRING(Chardata) -> + {"~ts",[Chardata]}; + Other -> + {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} + catch C:R -> + {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + end end end, notify(Level,Tag,Format,Args,Meta); -- cgit v1.2.3 From 6073d37a5a0691704d0fa1a5ff9289ba9e35c8ed Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 14 Sep 2018 14:12:13 +0200 Subject: [logger] Read config before terminating handler process When a handler process is terminated due to overload, it reads its configuration from the configuration database, so it can be restarted with the same configuration after a small delay. This was earlier done in a different process, which was spawned off from the terminate function. This caused a race condition, where in some cases, the configuration was already removed before it could be read. The reason for spawning off a process, is to avoid a deadlock due to the call to logger:remove_handler/1. This commit moves the call to logger:get_handler_config/1 back to the handler process - to ensure that the data is still there, but keeps the call to logger:remove_handler/1 in the spawned off process - to avoid deadlock. --- lib/kernel/src/logger_disk_log_h.erl | 3 ++- lib/kernel/src/logger_h_common.erl | 3 ++- lib/kernel/src/logger_std_h.erl | 3 ++- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 26375373aa..a8f141f135 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -426,8 +426,9 @@ terminate(Reason, State = #{id := Name}) -> _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, undefined)), _ = close_disk_log(Name, normal), + ok = logger_h_common:stop_or_restart(Name, Reason, State), unregister(?name_to_reg_name(?MODULE, Name)), - logger_h_common:stop_or_restart(Name, Reason, State). + ok. code_change(_OldVsn, State, _Extra) -> {ok, State}. diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 2818a460f1..38ac7d8ffc 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -294,6 +294,7 @@ stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, %% and set a restart timer. A separate process must perform this %% in order to avoid deadlock. HandlerPid = self(), + ConfigResult = logger:get_handler_config(Name), RemoveAndRestart = fun() -> MRef = erlang:monitor(process, HandlerPid), @@ -304,7 +305,7 @@ stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, error_notify(Reason), exit(HandlerPid, kill) end, - case logger:get_handler_config(Name) of + case ConfigResult of {ok,#{module:=HMod}=HConfig} when is_integer(RestartAfter) -> _ = logger:remove_handler(Name), _ = timer:apply_after(RestartAfter, logger, add_handler, diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 5dc4bc91ad..66fa6b6ab6 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -415,8 +415,9 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, false -> ok end, + ok = logger_h_common:stop_or_restart(Name, Reason, State), unregister(?name_to_reg_name(?MODULE, Name)), - logger_h_common:stop_or_restart(Name, Reason, State). + ok. code_change(_OldVsn, State, _Extra) -> {ok, State}. -- cgit v1.2.3