From 270d909696a753af022df72a404c73f2895b4a02 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 28 Jun 2018 14:52:11 +0200 Subject: [logger] Allow report callback with two arguments returning a string If the report callback is a fun of arity 2, then the second argument is a map with the keys 'encoding', 'depth' and 'chars_limit', and the fun must return a string which is size limited according to the given depth and chars_limit. If the report callback is a fun of arity 1, then it must return a tuple containing a format string and a list of arguments. The formatter will produce the string, and limit it's size. --- lib/kernel/doc/src/logger.xml | 21 +++- lib/kernel/doc/src/logger_chapter.xml | 18 +++- lib/kernel/doc/src/logger_formatter.xml | 13 ++- lib/kernel/src/logger.erl | 27 +++++- lib/kernel/src/logger_formatter.erl | 151 +++++++++++++++++++---------- lib/kernel/test/logger_formatter_SUITE.erl | 44 ++++++--- 6 files changed, 200 insertions(+), 74 deletions(-) diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 8bf62a6b39..f1830a8224 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -227,7 +227,10 @@ logger:error("error happened because: ~p", [Reason]). % Without macro a report(), the report_cb key can be associated with a fun (report callback) that converts the report to a format - string and arguments. See + string and arguments, or directly to a string. See the + type definition + of report_cb(), + and section Log Message in the User's Guide for more information about report callbacks.

@@ -259,6 +262,22 @@ logger:error("error happened because: ~p", [Reason]). % Without macro

+ + + +

A fun which converts a report() + to a format string and arguments, or directly to a string. + See section Log + Message in the User's Guide for more + information.

+ + + + + +

+ + diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 23a289f2ee..dc68d5c761 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -194,10 +194,26 @@ the log event's metadata. The report callback is a convenience function that the formatter can use - to convert the report to a format string and arguments. The + to convert the report to a format string and arguments, or + directly to a string. The formatter can also use its own conversion function, if no callback is provided, or if a customized formatting is desired.

+

The report callback must be a fun with one or two + arguments. If it takes one argument, this is the report + itself, and the fun returns a format string and arguments:

+ 
fun((logger:report()) -> {io:format(),[term()]})
+

If it takes two arguments, the first is the report, and the + second is a map containing extra data that allows direct + 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.

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 a482d02293..9226d19834 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -82,6 +82,13 @@ 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 @@ -105,7 +112,8 @@ by chars_limit or depth, it is truncated.

Defaults to unlimited.

 - report_cb = fun((logger:report()) -> {io:format(), [term()]}) + report_cb = + logger:report_cb()

A report callback is used by the formatter to transform log messages on report form to a format string and @@ -119,9 +127,6 @@ both the default report callback, and any report callback found in metadata. That is, all reports are converted by this configured function.

-

The value must be a function with arity 1, - returning {Format,Args}, and it will be called - with a report as only argument.

 single_line = boolean() diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index c78f5372f0..4924c6cb4f 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -74,6 +74,11 @@ -type level() :: emergency | alert | critical | error | warning | notice | info | debug. -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, + chars_limit := pos_integer() | unlimited}. -type msg_fun() :: fun((term()) -> {io:format(),[term()]} | report() | unicode:chardata()). @@ -84,7 +89,7 @@ file => file:filename(), line => non_neg_integer(), domain => [atom()], - report_cb => fun((report()) -> {io:format(),[term()]}), + report_cb => report_cb(), atom() => term()}. -type location() :: #{mfa := {module(),atom(),non_neg_integer()}, file := file:filename(), @@ -110,10 +115,22 @@ -type config_handler() :: {handler, handler_id(), module(), handler_config()}. --export_type([log_event/0,level/0,report/0,msg_fun/0,metadata/0, - primary_config/0,handler_config/0,handler_id/0, - filter_id/0,filter/0,filter_arg/0,filter_return/0, - config_handler/0,formatter_config/0]). +-export_type([log_event/0, + level/0, + report/0, + report_cb/0, + report_cb_config/0, + msg_fun/0, + metadata/0, + primary_config/0, + handler_config/0, + handler_id/0, + filter_id/0, + filter/0, + filter_arg/0, + filter_return/0, + config_handler/0, + formatter_config/0]). %%%----------------------------------------------------------------- %%% API diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 456b0c9e8d..937e7f859b 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -26,16 +26,17 @@ %%%----------------------------------------------------------------- %%% 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() :: [metakey()|{metakey(),template(),template()}|string()]. +-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(), + single_line => boolean(), + template => template(), + time_designator => byte(), + time_offset => integer() | [byte()]}. +-type template() :: [metakey() | {metakey(),template(),template()} | string()]. -type metakey() :: atom() | [atom()]. %%%----------------------------------------------------------------- @@ -119,65 +120,96 @@ value(_,_) -> to_string(time,Time,Config) -> format_time(Time,Config); -to_string(mfa,MFA,_Config) -> - format_mfa(MFA); -to_string(_,Value,_Config) -> - to_string(Value). +to_string(mfa,MFA,Config) -> + format_mfa(MFA,Config); +to_string(_,Value,Config) -> + to_string(Value,Config). -to_string(X) when is_atom(X) -> +to_string(X,_) when is_atom(X) -> atom_to_list(X); -to_string(X) when is_integer(X) -> +to_string(X,_) when is_integer(X) -> integer_to_list(X); -to_string(X) when is_pid(X) -> +to_string(X,_) when is_pid(X) -> pid_to_list(X); -to_string(X) when is_reference(X) -> +to_string(X,_) when is_reference(X) -> ref_to_list(X); -to_string(X) when is_list(X) -> - case io_lib:printable_unicode_list(lists:flatten(X)) of +to_string(X,Config) when is_list(X) -> + case printable_list(lists:flatten(X)) of true -> X; - _ -> io_lib:format("~tp",[X]) + _ -> io_lib:format(p(Config),[X]) end; -to_string(X) -> - io_lib:format("~tp",[X]). +to_string(X,Config) -> + io_lib:format(p(Config),[X]). + +printable_list([]) -> + false; +printable_list(X) -> + io_lib:printable_list(X). format_msg({string,Chardata},Meta,Config) -> - format_msg({"~ts",[Chardata]},Meta,Config); -format_msg({report,_}=Msg,Meta,#{report_cb:=Fun}=Config) when is_function(Fun,1) -> + format_msg({s(Config),[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)); format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,1) -> try Fun(Report) of {Format,Args} when is_list(Format), is_list(Args) -> format_msg({Format,Args},maps:remove(report_cb,Meta),Config); Other -> - format_msg({"REPORT_CB ERROR: ~tp; Returned: ~tp", + P = p(Config), + format_msg({"REPORT_CB/1 ERROR: "++P++"; Returned: "++P, + [Report,Other]},Meta,Config) + catch C:R:S -> + P = p(Config), + format_msg({"REPORT_CB/1 CRASH: "++P++"; Reason: "++P, + [Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]}, + 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) + catch _:_ -> + P = p(Config), + format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, + [Report,String]},Meta,Config) + end; + Other -> + P = p(Config), + format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, [Report,Other]},Meta,Config) - catch C:R -> - format_msg({"REPORT_CB CRASH: ~tp; Reason: ~tp", - [Report,{C,R}]},Meta,Config) + catch C:R:S -> + P = p(Config), + format_msg({"REPORT_CB/2 CRASH: "++P++"; Reason: "++P, + [Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]}, + Meta,Config) end; format_msg({report,Report},Meta,Config) -> format_msg({report,Report}, Meta#{report_cb=>fun logger:format_report/1}, Config); -format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit}) -> - limit_size(Msg, Depth, CharsLimit). - -limit_size(Msg,Depth,unlimited) -> - limit_size(Msg,Depth,[]); -limit_size(Msg,Depth,CharsLimit) when is_integer(CharsLimit) -> - limit_size(Msg,Depth,[{chars_limit,CharsLimit}]); -limit_size({Format,Args},unlimited,Opts) when is_list(Opts) -> +format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit,encoding:=Enc}) -> + limit_size(Msg, Depth, CharsLimit, Enc). + +limit_size(Msg,Depth,unlimited,Enc) -> + limit_size(Msg,Depth,[],Enc); +limit_size(Msg,Depth,CharsLimit,Enc) when is_integer(CharsLimit) -> + limit_size(Msg,Depth,[{chars_limit,CharsLimit}],Enc); +limit_size({Format,Args},unlimited,Opts,Enc) when is_list(Opts) -> try io_lib:format(Format,Args,Opts) catch _:_ -> - io_lib:format("FORMAT ERROR: ~tp - ~tp",[Format,Args],Opts) + P = p(Enc), + io_lib:format("FORMAT ERROR: "++P++" - "++P,[Format,Args],Opts) end; -limit_size({Format0,Args},Depth,Opts) when is_integer(Depth) -> +limit_size({Format0,Args},Depth,Opts,Enc) when is_integer(Depth) -> try Format1 = io_lib:scan_format(Format0, Args), Format = limit_format(Format1, Depth), io_lib:build_text(Format,Opts) catch _:_ -> - limit_size({"FORMAT ERROR: ~tp - ~tp",[Format0,Args]},Depth,Opts) + P = p(Enc), + limit_size({"FORMAT ERROR: "++P++" - "++P,[Format0,Args]}, + Depth,Opts,Enc) end. limit_format([#{control_char:=C0}=M0|T], Depth) when C0 =:= $p; @@ -225,22 +257,23 @@ timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> end, {Date,Time,Micro,UtcStr}. -format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_integer(A) -> +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); -format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_list(A) -> - format_mfa({M,F,length(A)}); -format_mfa(MFA) -> - to_string(MFA). +format_mfa({M,F,A},Config) when is_atom(M), is_atom(F), is_list(A) -> + format_mfa({M,F,length(A)},Config); +format_mfa(MFA,Config) -> + to_string(MFA,Config). 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,S},Micro,UtcStr} = + {{Y,Mo,D},{H,Mi,Sec},Micro,UtcStr} = timestamp_to_datetimemicro(Timestamp,Config), + S = s(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]), + 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]), Meta#{?MODULE=>MyMeta#{header=>Header}}; maybe_add_legacy_header(_,Meta,_) -> Meta. @@ -280,10 +313,11 @@ month(12) -> "Dec". %% configuration map add_default_config(Config0) -> Default = - #{legacy_header=>false, + #{chars_limit=>unlimited, + encoding=>utf8, error_logger_notice_header=>info, + legacy_header=>false, single_line=>true, - chars_limit=>unlimited, time_designator=>$T}, MaxSize = get_max_size(maps:get(max_size,Config0,undefined)), Depth = get_depth(maps:get(depth,Config0,undefined)), @@ -369,7 +403,8 @@ do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> do_check_config([{error_logger_notice_header,ELNH}|Config]) when ELNH == info; ELNH == notice -> do_check_config(Config); -do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1) -> +do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1); + is_function(RCB,2) -> do_check_config(Config); do_check_config([{template,T}|Config]) -> case check_template(T) of @@ -456,3 +491,17 @@ check_timezone(Tz) -> catch _:_ -> error end. + +p(#{encoding:=Enc}) -> + p(Enc); +p(latin1) -> + "~p"; +p(_) -> + "~tp". + +s(#{encoding:=Enc}) -> + s(Enc); +s(latin1) -> + "~s"; +s(_) -> + "~ts". diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 8fe8d5199b..aa8dc42691 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -312,30 +312,48 @@ format_msg(_Config) -> #{report_cb=>fun(_)-> faulty_return end}, #{template=>Template}), ct:log(String5), - "REPORT_CB ERROR: term; Returned: faulty_return" = String5, + "REPORT_CB/1 ERROR: term; Returned: faulty_return" = String5, String6 = format(info,{report,term}, #{report_cb=>fun(_)-> erlang:error(fun_crashed) end}, #{template=>Template}), ct:log(String6), - "REPORT_CB CRASH: term; Reason: {error,fun_crashed}" = String6, + "REPORT_CB/1 CRASH: term; Reason: {error,fun_crashed,"++_ = String6, + + String7 = format(info,{report,term}, + #{report_cb=>fun(_,_)-> ['not',a,string] end}, + #{template=>Template}), + ct:log(String7), + "REPORT_CB/2 ERROR: term; Returned: ['not',a,string]" = String7, + + String8 = format(info,{report,term}, + #{report_cb=>fun(_,_)-> faulty_return end}, + #{template=>Template}), + ct:log(String8), + "REPORT_CB/2 ERROR: term; Returned: faulty_return" = String8, + + String9 = format(info,{report,term}, + #{report_cb=>fun(_,_)-> erlang:error(fun_crashed) end}, + #{template=>Template}), + ct:log(String9), + "REPORT_CB/2 CRASH: term; Reason: {error,fun_crashed,"++_ = String9, %% strings are not formatted - String7 = format(info,{string,"string"}, + String10 = format(info,{string,"string"}, #{report_cb=>fun(_)-> {"formatted",[]} end}, #{template=>Template}), - ct:log(String7), - "string" = String7, + ct:log(String10), + "string" = String10, - String8 = format(info,{string,['not',printable,list]}, + String11 = format(info,{string,['not',printable,list]}, #{report_cb=>fun(_)-> {"formatted",[]} end}, #{template=>Template}), - ct:log("~ts",[String8]), % avoiding ct_log crash - "FORMAT ERROR: \"~ts\" - [['not',printable,list]]" = String8, + ct:log("~ts",[String11]), % avoiding ct_log crash + "FORMAT ERROR: \"~ts\" - [['not',printable,list]]" = String11, - String9 = format(info,{string,"string"},#{},#{template=>Template}), - ct:log(String9), - "string" = String9, + String12 = format(info,{string,"string"},#{},#{template=>Template}), + ct:log(String12), + "string" = String12, ok. @@ -639,8 +657,10 @@ check_config(_Config) -> ?cfgerr({max_size,bad}) = logger_formatter:check_config(#{max_size => bad}), + ok = + logger_formatter:check_config(#{report_cb => fun(_,_) -> "" end}), ?cfgerr({report_cb,F}) = - logger_formatter:check_config(#{report_cb => F=fun(_,_) -> {"",[]} end}), + logger_formatter:check_config(#{report_cb => F=fun(_,_,_) -> {"",[]} end}), ?cfgerr({report_cb,bad}) = logger_formatter:check_config(#{report_cb => bad}), -- cgit v1.2.3