diff options
26 files changed, 705 insertions, 269 deletions
diff --git a/lib/common_test/src/cth_log_redirect.erl b/lib/common_test/src/cth_log_redirect.erl index 99c484de48..4980d1ee4b 100644 --- a/lib/common_test/src/cth_log_redirect.erl +++ b/lib/common_test/src/cth_log_redirect.erl @@ -184,21 +184,12 @@ handle_call({log,#{meta:=#{gl:=GL}},_}, _From, {reply, ok, State}; handle_call({log, - #{msg:=Msg0, - meta:=#{?MODULE:=#{category:=Category}}=Meta}=Log, + #{meta:=#{?MODULE:=#{category:=Category}}}=Log, #{formatter:={Formatter,FConfig}}}, _From, #eh_state{log_func=LogFunc}=State) -> Header = format_header(State), - Msg = - case Msg0 of - {report,R} -> - Fun=maps:get(report_cb,Meta,fun logger:format_report/1), - Fun(R); - _ -> - Msg0 - end, - String = Formatter:format(Log#{msg=>Msg},FConfig), + String = Formatter:format(Log,FConfig), case LogFunc of tc_log -> ct_logs:tc_log(Category, ?STD_IMPORTANCE, diff --git a/lib/kernel/doc/src/.gitignore b/lib/kernel/doc/src/.gitignore new file mode 100644 index 0000000000..c2813ac866 --- /dev/null +++ b/lib/kernel/doc/src/.gitignore @@ -0,0 +1 @@ +*.eps
\ No newline at end of file diff --git a/lib/kernel/doc/src/Makefile b/lib/kernel/doc/src/Makefile index f34eee71ba..fceba14515 100644 --- a/lib/kernel/doc/src/Makefile +++ b/lib/kernel/doc/src/Makefile @@ -84,6 +84,7 @@ XML_CHAPTER_FILES = \ BOOK_FILES = book.xml +# The .png file is generated from a .dia file with target 'update_png' IMAGE_FILES = \ logger_arch.png @@ -112,6 +113,17 @@ SPECS_FILES = $(XML_REF3_FILES:%.xml=$(SPECDIR)/specs_%.xml) TOP_SPECS_FILE = specs.xml # ---------------------------------------------------- +# FIGURES +# ---------------------------------------------------- +# In order to update the figures you have to have both dia +# and imagemagick installed. +# The generated .png file must be committed. + +update_png: + dia --export=logger_arch.eps logger_arch.dia + convert logger_arch.eps -resize 65% logger_arch.png + +# ---------------------------------------------------- # FLAGS # ---------------------------------------------------- XML_FLAGS += @@ -147,7 +159,7 @@ clean clean_docs: rm -f $(MAN6DIR)/* rm -f $(TOP_PDF_FILE) $(TOP_PDF_FILE:%.pdf=%.fo) rm -f $(SPECDIR)/* - rm -f errs core *~ + rm -f errs core *~ *.eps $(SPECDIR)/specs_erl_prim_loader_stub.xml: $(gen_verbose)escript $(SPECS_EXTRACTOR) $(SPECS_FLAGS) \ diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 33f1919de0..f1830a8224 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -98,46 +98,6 @@ logger:error("error happened because: ~p", [Reason]). % Without macro <datatypes> <datatype> - <name name="primary_config"/> - <desc> - <p>Primary configuration data for Logger. The following - default values apply:</p> - <list> - <item><c>level => info</c></item> - <item><c>filter_default => log</c></item> - <item><c>filters => []</c></item> - </list> - </desc> - </datatype> - <datatype> - <name name="handler_config"/> - <desc> - <p>Handler configuration data for Logger. The following - default values apply:</p> - <list> - <item><c>level => all</c></item> - <item><c>filter_default => log</c></item> - <item><c>filters => []</c></item> - <item><c>formatter => {logger_formatter, DefaultFormatterConfig</c>}</item> - </list> - <p>In addition to these, the following fields are - automatically inserted by Logger, values taken from the - two first parameters - to <seealso marker="#add_handler-3"><c>add_handler/3</c></seealso>:</p> - <list> - <item><c>id => HandlerId</c></item> - <item><c>module => Module</c></item> - </list> - <p>Handler specific configuration data is inserted by the - handler callback itself, in a sub structure associated with - the field named <c>config</c>.</p> - <p>See the <seealso marker="logger_formatter#type-config"> - <c>logger_formatter(3)</c></seealso> manual page for - information about the default configuration for this - formatter.</p> - </desc> - </datatype> - <datatype> <name name="filter"/> <desc> <p>A filter which can be installed as a handler filter, or as @@ -172,6 +132,39 @@ logger:error("error happened because: ~p", [Reason]). % Without macro </desc> </datatype> <datatype> + <name name="handler_config"/> + <desc> + <p>Handler configuration data for Logger. The following + default values apply:</p> + <list> + <item><c>level => all</c></item> + <item><c>filter_default => log</c></item> + <item><c>filters => []</c></item> + <item><c>formatter => {logger_formatter, DefaultFormatterConfig</c>}</item> + </list> + <p>In addition to these, the following fields are + automatically inserted by Logger, values taken from the + two first parameters + to <seealso marker="#add_handler-3"><c>add_handler/3</c></seealso>:</p> + <list> + <item><c>id => HandlerId</c></item> + <item><c>module => Module</c></item> + </list> + <p>These are read-only and cannot be changed in runtime.</p> + <p>Handler specific configuration data is inserted by the + handler callback itself, in a sub structure associated with + the field named <c>config</c>. See + the <seealso marker="logger_std_h"><c>logger_std_h(3)</c></seealso> + and <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso> + manual pages for information about the specifc configuration + for these handlers.</p> + <p>See the <seealso marker="logger_formatter#type-config"> + <c>logger_formatter(3)</c></seealso> manual page for + information about the default configuration for this + formatter.</p> + </desc> + </datatype> + <datatype> <name name="handler_id"/> <desc> <p>A unique identifier for a handler instance.</p> @@ -234,7 +227,10 @@ logger:error("error happened because: ~p", [Reason]). % Without macro a <seealso marker="#type-report"><c>report()</c></seealso>, the <c>report_cb</c> 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 <seealso marker="#type-report_cb"><c>report_cb()</c></seealso>, + and section <seealso marker="logger_chapter#log_message">Log Message</seealso> in the User's Guide for more information about report callbacks.</p> @@ -249,12 +245,40 @@ logger:error("error happened because: ~p", [Reason]). % Without macro </desc> </datatype> <datatype> + <name name="primary_config"/> + <desc> + <p>Primary configuration data for Logger. The following + default values apply:</p> + <list> + <item><c>level => info</c></item> + <item><c>filter_default => log</c></item> + <item><c>filters => []</c></item> + </list> + </desc> + </datatype> + <datatype> <name name="report"/> <desc> <p></p> </desc> </datatype> <datatype> + <name name="report_cb"/> + <desc> + <p>A fun which converts a <seealso marker="#type-report"><c>report()</c> + </seealso> to a format string and arguments, or directly to a string. + See section <seealso marker="logger_chapter#log_message">Log + Message</seealso> in the User's Guide for more + information.</p> + </desc> + </datatype> + <datatype> + <name name="report_cb_config"/> + <desc> + <p></p> + </desc> + </datatype> + <datatype> <name name="timestamp"/> <desc> <p>A timestamp produced @@ -285,13 +309,16 @@ logger:error("error happened because: ~p", [Reason]). % Without macro <item><c>?LOG_INFO(FunOrFormat,Args[,Metadata])</c></item> <item><c>?LOG_DEBUG(StringOrReport[,Metadata])</c></item> <item><c>?LOG_DEBUG(FunOrFormat,Args[,Metadata])</c></item> + <item><c>?LOG(Level,StringOrReport[,Metadata])</c></item> + <item><c>?LOG(Level,FunOrFormat,Args[,Metadata])</c></item> </list> <p>All macros expand to a call to Logger, where <c>Level</c> is - taken from the macro name, and location data is added to the - metadata. See the description of + taken from the macro name, or from the first argument in the + case of the <c>?LOG</c> macro. Location data is added to the + metadata as described under the <seealso marker="#type-metadata"><c>metadata()</c></seealso> - type for more information about the location data.</p> + type definition.</p> <p>The call is wrapped in a case statement and will be evaluated only if <c>Level</c> is equal to or below the configured log @@ -690,15 +717,30 @@ start(_, []) -> </func> <func> - <name name="set_handler_config" arity="3"/> + <name name="set_handler_config" arity="3" clause_i="1"/> + <name name="set_handler_config" arity="3" clause_i="2"/> + <name name="set_handler_config" arity="3" clause_i="3"/> + <name name="set_handler_config" arity="3" clause_i="4"/> + <name name="set_handler_config" arity="3" clause_i="5"/> <fsummary>Add or update configuration data for the specified handler.</fsummary> + <type variable="HandlerId"/> + <type variable="Level" name_i="1"/> + <type variable="FilterDefault" name_i="2"/> + <type variable="Filters" name_i="3"/> + <type variable="Formatter" name_i="4"/> + <type variable="Config" name_i="5"/> + <type variable="Return"/> <desc> <p>Add or update configuration data for the specified handler. If the given <c><anno>Key</anno></c> already exists, its associated value will be changed - to <c><anno>Value</anno></c>. If it does not exist, it will + to the given value. If it does not exist, it will be added.</p> + <p>See the definition of + the <seealso marker="#type-handler_config"> + <c>handler_config()</c></seealso> type for more + information about the different parameters.</p> </desc> </func> @@ -721,13 +763,18 @@ start(_, []) -> </func> <func> - <name name="set_primary_config" arity="2"/> + <name name="set_primary_config" arity="2" clause_i="1"/> + <name name="set_primary_config" arity="2" clause_i="2"/> + <name name="set_primary_config" arity="2" clause_i="3"/> <fsummary>Add or update primary configuration data for Logger.</fsummary> + <type variable="Level" name_i="1"/> + <type variable="FilterDefault" name_i="2"/> + <type variable="Filters" name_i="3"/> <desc> <p>Add or update primary configuration data for Logger. If the given <c><anno>Key</anno></c> already exists, its associated - value will be changed to <c><anno>Value</anno></c>. If it - does not exist, it will be added.</p> + value will be changed to the given value. If it does not + exist, it will be added.</p> </desc> </func> diff --git a/lib/kernel/doc/src/logger_arch.dia b/lib/kernel/doc/src/logger_arch.dia Binary files differnew file mode 100644 index 0000000000..97be31856e --- /dev/null +++ b/lib/kernel/doc/src/logger_arch.dia diff --git a/lib/kernel/doc/src/logger_arch.png b/lib/kernel/doc/src/logger_arch.png Binary files differindex a3a863c511..70933a5a41 100644 --- a/lib/kernel/doc/src/logger_arch.png +++ b/lib/kernel/doc/src/logger_arch.png diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index f4a752bde9..dc68d5c761 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -69,6 +69,8 @@ figure shows two log handlers, but any number of handlers can be installed.</p> + <!-- The image is edited with dia in logger_arch.dia file, + and .png file generated with make target 'png'. --> <image file="logger_arch.png"> <icaption>Conceptual Overview</icaption> </image> @@ -192,10 +194,26 @@ the log event's <seealso marker="#metadata">metadata</seealso>. The report callback is a convenience function that the <seealso marker="#formatters">formatter</seealso> 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.</p> + <p>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:</p> + <pre>fun((<seealso marker="logger#type-report"><c>logger:report()</c></seealso>) -> {<seealso marker="stdlib:io#type-format"><c>io:format()</c></seealso>,[term()]})</pre> + <p>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:</p> + <pre>fun((<seealso marker="logger#type-report"><c>logger:report()</c></seealso>,<seealso marker="logger#type-report_cb_config"><c>logger:report_cb_config()</c></seealso>) -> <seealso marker="stdlib:unicode#type-chardata"><c>unicode:chardata()</c></seealso>) + </pre> + <p>The fun must obey the <c>encoding</c>, <c>depth</c> + and <c>chars_limit</c> 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.</p> <p>Example, format string and arguments:</p> <code>logger:error("The file does not exist: ~ts",[Filename])</code> <p>Example, string:</p> diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index e777afaf86..9226d19834 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -78,10 +78,17 @@ format controls ~p and ~w are replaced with ~P and ~W, respectively, and the value is used as the depth parameter. For details, see - <seealso marker="stdlib:io#format-2">io:format/2,3</seealso> + <seealso marker="stdlib:io#format-2"><c>io:format/2,3</c></seealso> in STDLIB.</p> <p>Defaults to <c>unlimited</c>.</p> </item> + <tag><c>encoding = </c><seealso marker="stdlib:unicode#type-encoding"> + <c>unicode:encoding()</c></seealso></tag> + <item> + <p>This parameter must reflect the encoding of the device + that the handler prints to.</p> + <p>Defaults to <c>utf8</c></p> + </item> <tag><c>legacy_header = boolean()</c></tag> <item> <p>If set to <c>true</c> a header field is added to @@ -105,7 +112,8 @@ by <c>chars_limit</c> or <c>depth</c>, it is truncated.</p> <p>Defaults to <c>unlimited</c>.</p> </item> - <tag><c>report_cb = fun((</c><seealso marker="logger#type-report"><c>logger:report()</c></seealso><c>) -> {</c><seealso marker="stdlib:io#type-format"><c>io:format()</c></seealso><c>, [term()]})</c></tag> + <tag><c>report_cb = </c><seealso marker="logger#type-report_cb"> + <c>logger:report_cb()</c></seealso></tag> <item> <p>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.</p> - <p>The value must be a function with arity 1, - returning <c>{Format,Args}</c>, and it will be called - with a report as only argument.</p> </item> <tag><c>single_line = boolean()</c></tag> <item> diff --git a/lib/kernel/include/logger.hrl b/lib/kernel/include/logger.hrl index 2143ccd297..b09977e0f2 100644 --- a/lib/kernel/include/logger.hrl +++ b/lib/kernel/include/logger.hrl @@ -32,6 +32,10 @@ -define(LOG_DEBUG(A,B),?DO_LOG(debug,[A,B])). -define(LOG_DEBUG(A,B,C),?DO_LOG(debug,[A,B,C])). +-define(LOG(L,A),?DO_LOG(L,[A])). +-define(LOG(L,A,B),?DO_LOG(L,[A,B])). +-define(LOG(L,A,B,C),?DO_LOG(L,[A,B,C])). + -define(LOCATION,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY}, line=>?LINE, file=>?FILE}). diff --git a/lib/kernel/src/Makefile b/lib/kernel/src/Makefile index c595c25341..57f17defc8 100644 --- a/lib/kernel/src/Makefile +++ b/lib/kernel/src/Makefile @@ -112,7 +112,8 @@ MODULES = \ logger \ logger_backend \ logger_config \ - logger_std_h \ + logger_handler_watcher \ + logger_std_h \ logger_disk_log_h \ logger_h_common \ logger_filters \ diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index a7e7f19167..ad8c937882 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -74,8 +74,8 @@ start() -> type => worker, modules => dynamic}, case supervisor:start_child(logger_sup, ErrorLogger) of - {ok,_} -> - ok; + {ok,Pid} -> + ok = logger_handler_watcher:register_handler(?MODULE,Pid); Error -> Error end; @@ -95,9 +95,14 @@ start_link() -> %%% Stop the event manager -spec stop() -> ok. stop() -> - _ = supervisor:terminate_child(logger_sup,?MODULE), - _ = supervisor:delete_child(logger_sup,?MODULE), - ok. + case whereis(?MODULE) of + undefined -> + ok; + _Pid -> + _ = gen_event:stop(?MODULE,{shutdown,stopped},infinity), + _ = supervisor:delete_child(logger_sup,?MODULE), + ok + end. %%%----------------------------------------------------------------- %%% Callbacks for logger diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index 47dd7c03d5..4933eae76f 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -67,6 +67,7 @@ logger_filters, logger_formatter, logger_h_common, + logger_handler_watcher, logger_server, logger_simple_h, logger_std_h, @@ -129,6 +130,7 @@ kernel_refc, kernel_sup, logger, + logger_handler_watcher, logger_sup, net_kernel, net_sup, diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 0a9b1672ec..ffc90f4fc5 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 @@ -352,9 +369,12 @@ add_handler(HandlerId,Module,Config) -> remove_handler(HandlerId) -> logger_server:remove_handler(HandlerId). --spec set_primary_config(Key,Value) -> ok | {error,term()} when - Key :: atom(), - Value :: term(). +-spec set_primary_config(level,Level) -> ok | {error,term()} when + Level :: level() | all | none; + (filter_default,FilterDefault) -> ok | {error,term()} when + FilterDefault :: log | stop; + (filters,Filters) -> ok | {error,term()} when + Filters :: [{filter_id(),filter()}]. set_primary_config(Key,Value) -> logger_server:set_config(primary,Key,Value). @@ -363,10 +383,26 @@ set_primary_config(Key,Value) -> set_primary_config(Config) -> logger_server:set_config(primary,Config). --spec set_handler_config(HandlerId,Key,Value) -> ok | {error,term()} when +-spec set_handler_config(HandlerId,level,Level) -> Return when HandlerId :: handler_id(), - Key :: atom(), - Value :: term(). + Level :: level() | all | none, + Return :: ok | {error,term()}; + (HandlerId,filter_default,FilterDefault) -> Return when + HandlerId :: handler_id(), + FilterDefault :: log | stop, + Return :: ok | {error,term()}; + (HandlerId,filters,Filters) -> Return when + HandlerId :: handler_id(), + Filters :: [{filter_id(),filter()}], + Return :: ok | {error,term()}; + (HandlerId,formatter,Formatter) -> Return when + HandlerId :: handler_id(), + Formatter :: {module(), formatter_config()}, + Return :: ok | {error,term()}; + (HandlerId,config,Config) -> Return when + HandlerId :: handler_id(), + Config :: term(), + Return :: ok | {error,term()}. set_handler_config(HandlerId,Key,Value) -> logger_server:set_config(HandlerId,Key,Value). @@ -651,7 +687,7 @@ get_logger_type() -> get_logger_level() -> case application:get_env(kernel,logger_level,info) of - Level when ?IS_LEVEL(Level) -> + Level when ?IS_LEVEL(Level); Level=:=all; Level=:=none -> Level; Level -> throw({logger_level, Level}) diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 0a72654e11..e56531c3cb 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -488,7 +488,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,_Pid,Config1} -> + {ok,Pid,Config1} -> + ok = logger_handler_watcher:register_handler(Name,Pid), {ok,Config1}; Error -> Error @@ -506,8 +507,11 @@ stop(Name) -> %% system termination in order to avoid circular attempts %% at removing the handler (implying deadlocks and %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. _ = gen_server:call(Pid, stop), - _ = supervisor:delete_child(logger_sup, Name), ok end. diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 456b0c9e8d..a5c6984bc6 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()]. %%%----------------------------------------------------------------- @@ -76,7 +77,7 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) %% Trim leading and trailing whitespaces, and replace %% newlines with ", " re:replace(string:trim(MsgStr0),",?\r?\n\s*",", ", - [{return,list},global]); + [{return,list},global,unicode]); _false -> MsgStr0 end; @@ -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/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index a40345dddc..854e5479b9 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -309,19 +309,6 @@ stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, end, spawn(RemoveAndRestart), ok; - -stop_or_restart(Name, shutdown, _State) -> - %% Probably terminated by supervisor. Remove the handler to avoid - %% error printouts due to failing handler. - _ = case logger:get_handler_config(Name) of - {ok,_} -> - %% Spawning to avoid deadlock - spawn(logger,remove_handler,[Name]); - _ -> - ok - end, - ok; - stop_or_restart(_Name, _Reason, _State) -> ok. diff --git a/lib/kernel/src/logger_handler_watcher.erl b/lib/kernel/src/logger_handler_watcher.erl new file mode 100644 index 0000000000..b75c74c643 --- /dev/null +++ b/lib/kernel/src/logger_handler_watcher.erl @@ -0,0 +1,113 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 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. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% +-module(logger_handler_watcher). + +-behaviour(gen_server). + +%% API +-export([start_link/0]). +-export([register_handler/2]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]). + +-define(SERVER, ?MODULE). + +-record(state, {handlers}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +-spec start_link() -> {ok, Pid :: pid()} | + {error, Error :: {already_started, pid()}} | + {error, Error :: term()} | + ignore. +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). + +-spec register_handler(Id::logger:handler_id(),Pid::pid()) -> ok. +register_handler(Id,Pid) -> + gen_server:call(?SERVER,{register,Id,Pid}). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +-spec init(Args :: term()) -> {ok, State :: term()} | + {ok, State :: term(), Timeout :: timeout()} | + {ok, State :: term(), hibernate} | + {stop, Reason :: term()} | + ignore. +init([]) -> + process_flag(trap_exit, true), + {ok, #state{handlers=[]}}. + +-spec handle_call(Request :: term(), From :: {pid(), term()}, State :: term()) -> + {reply, Reply :: term(), NewState :: term()} | + {reply, Reply :: term(), NewState :: term(), Timeout :: timeout()} | + {reply, Reply :: term(), NewState :: term(), hibernate} | + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: term(), Reply :: term(), NewState :: term()} | + {stop, Reason :: term(), NewState :: term()}. +handle_call({register,Id,Pid}, _From, #state{handlers=Hs}=State) -> + Ref = erlang:monitor(process,Pid), + Hs1 = lists:keystore(Id,1,Hs,{Id,Ref}), + {reply, ok, State#state{handlers=Hs1}}. + +-spec handle_cast(Request :: term(), State :: term()) -> + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: term(), NewState :: term()}. +handle_cast(_Request, State) -> + {noreply, State}. + +-spec handle_info(Info :: timeout() | term(), State :: term()) -> + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: normal | term(), NewState :: term()}. +handle_info({'DOWN',Ref,process,_,shutdown}, #state{handlers=Hs}=State) -> + case lists:keytake(Ref,2,Hs) of + {value,{Id,Ref},Hs1} -> + %% Probably terminated by supervisor. Remove the handler to avoid + %% error printouts due to failing handler. + _ = case logger:get_handler_config(Id) of + {ok,_} -> + logger:remove_handler(Id); + _ -> + ok + end, + {noreply,State#state{handlers=Hs1}}; + false -> + {noreply, State} + end; +handle_info({'DOWN',Ref,process,_,_OtherReason}, #state{handlers=Hs}=State) -> + {noreply,State#state{handlers=lists:keydelete(Ref,2,Hs)}}; +handle_info(_Other,State) -> + {noreply,State}. + +-spec terminate(Reason :: normal | shutdown | {shutdown, term()} | term(), + State :: term()) -> any(). +terminate(_Reason, _State) -> + ok. diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 480fafd6d8..9a2a1443b3 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -467,7 +467,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,_Pid,Config1} -> + {ok,Pid,Config1} -> + ok = logger_handler_watcher:register_handler(Name,Pid), {ok,Config1}; Error -> Error @@ -485,8 +486,11 @@ stop(Name) -> %% system termination in order to avoid circular attempts %% at removing the handler (implying deadlocks and %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. _ = gen_server:call(Pid, stop), - _ = supervisor:delete_child(logger_sup, Name), ok end. diff --git a/lib/kernel/src/logger_sup.erl b/lib/kernel/src/logger_sup.erl index dcdcdad0bd..3d6f482e20 100644 --- a/lib/kernel/src/logger_sup.erl +++ b/lib/kernel/src/logger_sup.erl @@ -46,7 +46,11 @@ init([]) -> intensity => 1, period => 5}, - {ok, {SupFlags, []}}. + Watcher = #{id => logger_handler_watcher, + start => {logger_handler_watcher, start_link, []}, + shutdown => brutal_kill}, + + {ok, {SupFlags, [Watcher]}}. %%%=================================================================== %%% Internal functions diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index b367b4dd54..8f74ebdc47 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -355,6 +355,7 @@ log_all_levels_api(cleanup,_Config) -> macros(_Config) -> ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}), test_macros(emergency), + test_log_macro(alert), ok. macros(cleanup,_Config) -> @@ -469,7 +470,11 @@ filter_failed(_Config) -> %% Logger filters {error,{invalid_filter,_}} = logger:add_primary_filter(lf,{fun(_) -> ok end,args}), - ok = logger:add_primary_filter(lf,{fun(_,_) -> a=b end,args}), + ok = logger:add_primary_filter(lf, + {fun(_,_) -> + erlang:error({badmatch,b}) + end, + args}), #{filters:=[_]} = logger:get_primary_config(), ok = logger:notice(M1=?map_rep), ok = check_logged(notice,M1,#{}), @@ -487,7 +492,11 @@ filter_failed(_Config) -> {error,{not_found,h0}} = logger:remove_handler_filter(h0,hf), {error,{invalid_filter,_}} = logger:add_handler_filter(h1,hf,{fun(_) -> ok end,args}), - ok = logger:add_handler_filter(h1,hf,{fun(_,_) -> a=b end,args}), + ok = logger:add_handler_filter(h1,hf, + {fun(_,_) -> + erlang:error({badmatch,b}) + end, + args}), {ok,#{filters:=[_]}} = logger:get_handler_config(h1), ok = logger:notice(M3=?map_rep), ok = check_logged(notice,M3,#{}), @@ -523,7 +532,11 @@ handler_failed(_Config) -> false = lists:search(fun(#{id:=h1}) -> true; (_) -> false end,H1), {error,{not_found,h1}} = logger:remove_handler(h1), - ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,log_call=>fun() -> a = b end}), + ok = logger:add_handler(h2,?MODULE, + #{filter_default => log, + log_call => fun() -> + erlang:error({badmatch,b}) + end}), {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}), [add] = test_server:messages_get(), @@ -534,7 +547,7 @@ handler_failed(_Config) -> {error,{not_found,h2}} = logger:remove_handler(h2), CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end, - CrashHandler = fun() -> a = b end, + CrashHandler = fun() -> erlang:error({badmatch,b}) end, KillHandler = fun() -> exit(self(), die) end, {error,{handler_not_added,{attempting_syncronous_call_to_self,_}}} = @@ -1009,6 +1022,34 @@ test_macros(emergency=Level) -> [{F2,x},{error,fun_that_crashes}],#{}), ok. +test_log_macro(Level) -> + ?LOG(Level,#{Level=>rep}), + ok = check_logged(Level,#{Level=>rep},?MY_LOC(1)), + ?LOG(Level,#{Level=>rep},#{my=>meta}), + ok = check_logged(Level,#{Level=>rep},(?MY_LOC(1))#{my=>meta}), + ?LOG(Level,"~w: ~w",[Level,fa]), + ok = check_logged(Level,"~w: ~w",[Level,fa],?MY_LOC(1)), + ?LOG(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],(?MY_LOC(1))#{my=>meta}), + ?LOG(Level,fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end, + x, #{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta], + (?MY_LOC(3))#{my=>meta}), + ?LOG(Level,fun(x) -> #{Level=>fun_to_r,meta=>true} end, x, #{my=>meta}), + ok = check_logged(Level,#{Level=>fun_to_r,meta=>true}, + (?MY_LOC(2))#{my=>meta}), + ?LOG(Level,fun(x) -> <<"fun_to_s">> end,x,#{}), + ok = check_logged(Level,<<"fun_to_s">>,?MY_LOC(1)), + F1=fun(x) -> {fun_to_bad} end, + ?LOG(Level,F1,x,#{}), + ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp", + [{F1,x},{fun_to_bad}],#{}), + F2=fun(x) -> erlang:error(fun_that_crashes) end, + ?LOG(Level,F2,x,#{}), + ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp", + [{F2,x},{error,fun_that_crashes}],#{}), + ok. + %%%----------------------------------------------------------------- %%% Called by macro ?TRY(X) my_try(Fun) -> diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 7e5b574869..a4b15c841b 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -1551,25 +1551,30 @@ h_proc_name() -> h_proc_name(Name) -> list_to_atom(lists:concat([logger_disk_log_h,"_",Name])). -file_delete(Log) -> - file:delete(Log). - wait_for_process_up(T) -> - wait_for_process_up(h_proc_name(),T). + wait_for_process_up(?MODULE, h_proc_name(), T). -wait_for_process_up(Name,T) -> +wait_for_process_up(Name, RegName, T) -> N = (T div 500) + 1, - wait_for_process_up1(Name,N). + wait_for_process_up1(Name, RegName, N). -wait_for_process_up1(Name,0) -> +wait_for_process_up1(_Name, _RegName, 0) -> error; -wait_for_process_up1(Name,N) -> +wait_for_process_up1(Name, RegName, N) -> timer:sleep(500), - case whereis(Name) of + case whereis(RegName) of Pid when is_pid(Pid) -> - %% ct:pal("Process ~p up (~p tries left)",[Name,N]), - {ok,Pid}; + case logger:get_handler_config(Name) of + {ok,_} -> + %% ct:pal("Process ~p up (~p tries left)",[Name,N]), + {ok,Pid}; + _ -> + wait_for_process_up1(Name, RegName, N-1) + end; undefined -> %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), - wait_for_process_up1(Name,N-1) + wait_for_process_up1(Name, RegName, N-1) end. + +file_delete(Log) -> + file:delete(Log). diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index 04a4364947..e8d1a313dc 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -71,6 +71,7 @@ all() -> sasl_compatible_false, sasl_compatible_false_no_progress, sasl_compatible, + all_logger_level, {group,bad}, {group,error_logger}, {group,logger} @@ -572,6 +573,24 @@ sasl_compatible(Config) -> 0),% progress in std logger ok. +all_logger_level(Config) -> + [all_logger_level(Config,Level) || Level <- [none, + emergency, + alert, + critical, + error, + warning, + notice, + info, + debug, + all]], + ok. + +all_logger_level(Config,Level) -> + {ok,#{primary:=#{level:=Level}},Node} = setup(Config,[{logger_level,Level}]), + true = test_server:stop_node(Node), + ok. + bad_error_logger(Config) -> error = setup(Config,[{error_logger,baddest}]). 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}), diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index ca54458ac1..0930cd4211 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -1570,27 +1570,29 @@ h_proc_name() -> h_proc_name(Name) -> ?name_to_reg_name(logger_std_h,Name). -file_delete(Log) -> - file:delete(Log). - wait_for_process_up(T) -> - wait_for_process_up(h_proc_name(),T). + wait_for_process_up(?MODULE, h_proc_name(), T). -wait_for_process_up(Name,T) -> +wait_for_process_up(Name, RegName, T) -> N = (T div 500) + 1, - wait_for_process_up1(Name,N). + wait_for_process_up1(Name, RegName, N). -wait_for_process_up1(_Name,0) -> +wait_for_process_up1(_Name, _RegName, 0) -> error; -wait_for_process_up1(Name,N) -> +wait_for_process_up1(Name, RegName, N) -> timer:sleep(500), - case whereis(Name) of + case whereis(RegName) of Pid when is_pid(Pid) -> - %% ct:pal("Process ~p up (~p tries left)",[Name,N]), - {ok,Pid}; + case logger:get_handler_config(Name) of + {ok,_} -> + %% ct:pal("Process ~p up (~p tries left)",[Name,N]), + {ok,Pid}; + _ -> + wait_for_process_up1(Name, RegName, N-1) + end; undefined -> %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), - wait_for_process_up1(Name,N-1) + wait_for_process_up1(Name, RegName, N-1) end. filesync_rep_int() -> @@ -1598,3 +1600,8 @@ filesync_rep_int() -> true -> 5500; false -> ?FILESYNC_REPEAT_INTERVAL + 500 end. + + +file_delete(Log) -> + file:delete(Log). + diff --git a/lib/sasl/test/sasl_report_SUITE.erl b/lib/sasl/test/sasl_report_SUITE.erl index 863b765645..a03932133e 100644 --- a/lib/sasl/test/sasl_report_SUITE.erl +++ b/lib/sasl/test/sasl_report_SUITE.erl @@ -21,6 +21,7 @@ -export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, init_per_group/2,end_per_group/2]). -export([gen_server_crash/1, gen_server_crash_unicode/1]). +-export([legacy_gen_server_crash/1, legacy_gen_server_crash_unicode/1]). -export([crash_me/0,start_link/0,init/1,handle_cast/2,terminate/2]). @@ -29,7 +30,10 @@ suite() -> [{ct_hooks,[ts_install_cth]}]. all() -> - [gen_server_crash, gen_server_crash_unicode]. + [gen_server_crash, + gen_server_crash_unicode, + legacy_gen_server_crash, + legacy_gen_server_crash_unicode]. groups() -> []. @@ -52,17 +56,77 @@ gen_server_crash(Config) -> gen_server_crash_unicode(Config) -> gen_server_crash(Config, unicode). +legacy_gen_server_crash(Config) -> + legacy_gen_server_crash(Config,latin1). + +legacy_gen_server_crash_unicode(Config) -> + legacy_gen_server_crash(Config,unicode). + gen_server_crash(Config, Encoding) -> + TC = list_to_atom(lists:concat([?FUNCTION_NAME,"_",Encoding])), + PrivDir = filename:join(?config(priv_dir,Config),?MODULE), + ConfigFileName = filename:join(PrivDir,TC), + KernelLog = filename:join(PrivDir,lists:concat([TC,"_kernel.log"])), + SaslLog = filename:join(PrivDir,lists:concat([TC,"_sasl.log"])), + KernelConfig = [{logger,[{handler,default,logger_std_h, + #{config=>#{type=>{file,KernelLog}}}}]}, + {logger_sasl_compatible,true}], + Modes = [write, {encoding, Encoding}], + SaslConfig = [{sasl_error_logger,{file,SaslLog,Modes}}], + ok = filelib:ensure_dir(SaslLog), + + ok = file:write_file(ConfigFileName ++ ".config", + io_lib:format("[{kernel, ~p},~n{sasl, ~p}].", + [KernelConfig,SaslConfig])), + {ok,Node} = + test_server:start_node( + TC, peer, + [{args, ["-pa ",filename:dirname(code:which(?MODULE)), + " -boot start_sasl -kernel start_timer true " + "-config ",ConfigFileName]}]), + + %% Set depth + ok = rpc:call(Node,logger,update_formatter_config,[default,depth,30]), + ok = rpc:call(Node,logger,update_formatter_config,[sasl,depth,30]), + + %% Make sure remote node logs it's own logs, and current node does + %% not log them. + ok = rpc:call(Node,logger,remove_handler_filter,[default,remote_gl]), + ok = rpc:call(Node,logger,remove_handler_filter,[sasl,remote_gl]), + ok = logger:add_primary_filter(no_remote,{fun(#{meta:=#{pid:=Pid}},_) + when node(Pid)=/=node() -> stop; + (_,_) -> ignore + end,[]}), + ct:log("Local node Logger config:~n~p", + [rpc:call(Node,logger,get_config,[])]), + ct:log("Remote node Logger config:~n~p", + [rpc:call(Node,logger,get_config,[])]), + ct:log("Remote node error_logger handlers: ~p", + [rpc:call(Node,error_logger,which_report_handlers,[])]), + + ok = rpc:call(Node,?MODULE,crash_me,[]), + + test_server:stop_node(Node), + ok = logger:remove_primary_filter(no_remote), + + check_file(KernelLog, utf8, 70000, 150000), + check_file(SaslLog, Encoding, 70000, 150000), + + ok = file:delete(KernelLog), + ok = file:delete(SaslLog), + + ok. + +legacy_gen_server_crash(Config, Encoding) -> StopFilter = {fun(_,_) -> stop end, ok}, logger:add_handler_filter(default,stop_all,StopFilter), + logger:add_handler_filter(sasl,stop_all,StopFilter), logger:add_handler_filter(cth_log_redirect,stop_all,StopFilter), try do_gen_server_crash(Config, Encoding) after - ok = application:unset_env(kernel, logger_sasl_compatible), - ok = application:unset_env(sasl, sasl_error_logger), - ok = application:unset_env(kernel, error_logger_format_depth), logger:remove_handler_filter(default,stop_all), + logger:remove_handler_filter(sasl,stop_all), logger:remove_handler_filter(cth_log_redirect,stop_all) end, ok. @@ -74,22 +138,17 @@ do_gen_server_crash(Config, Encoding) -> SaslLog = filename:join(LogDir, "sasl.log"), ok = filelib:ensure_dir(SaslLog), - application:stop(sasl), Modes = [write, {encoding, Encoding}], - ok = application:set_env(kernel, logger_sasl_compatible, true), - ok = application:set_env(sasl, sasl_error_logger, {file,SaslLog,Modes}, - [{persistent,true}]), application:set_env(kernel, error_logger_format_depth, 30), error_logger:logfile({open,KernelLog}), - application:start(sasl), + error_logger:add_report_handler(sasl_report_file_h,{SaslLog,Modes,all}), ct:log("Logger config:~n~p",[logger:get_config()]), ct:log("error_logger handlers: ~p",[error_logger:which_report_handlers()]), crash_me(), - error_logger:logfile(close), - application:stop(sasl), + error_logger:delete_report_handler(sasl_report_file_h), check_file(KernelLog, utf8, 70000, 150000), check_file(SaslLog, Encoding, 70000, 150000), diff --git a/lib/stdlib/src/proc_lib.erl b/lib/stdlib/src/proc_lib.erl index 89a840be2d..d07c62500b 100644 --- a/lib/stdlib/src/proc_lib.erl +++ b/lib/stdlib/src/proc_lib.erl @@ -30,7 +30,7 @@ start/3, start/4, start/5, start_link/3, start_link/4, start_link/5, hibernate/3, init_ack/1, init_ack/2, - init_p/3,init_p/5,format/1,format/2,format/3,report_cb/1, + init_p/3,init_p/5,format/1,format/2,format/3,report_cb/2, initial_call/1, translate_initial_call/1, stop/1, stop/3]). @@ -509,7 +509,7 @@ crash_report(Class, Reason, StartF, Stacktrace) -> report=>[my_info(Class, Reason, StartF, Stacktrace), linked_info(self())]}, #{domain=>[otp,sasl], - report_cb=>fun proc_lib:report_cb/1, + report_cb=>fun proc_lib:report_cb/2, logger_formatter=>#{title=>"CRASH REPORT"}, error_logger=>#{tag=>error_report,type=>crash_report}}). @@ -750,14 +750,15 @@ check(Res) -> Res. %%% Format a generated crash info structure. %%% ----------------------------------------------------------- --spec report_cb(CrashReport) -> {Format,Args} when - CrashReport :: #{label=>{proc_lib,crash},report=>[term()]}, - Format :: io:format(), - Args :: [term()]. -report_cb(#{label:={proc_lib,crash}, - report:=CrashReport}) -> - Depth = error_logger:get_format_depth(), - get_format_and_args(CrashReport, utf8, Depth). +-spec report_cb(CrashReport,FormatOpts) -> unicode:chardata() when + CrashReport :: #{label => {proc_lib,crash}, + report => [term()]}, + FormatOpts :: logger:report_cb_config(). +report_cb(#{label:={proc_lib,crash}, report:=CrashReport}, Extra) -> + Default = #{chars_limit => unlimited, + depth => unlimited, + encoding => latin1}, + do_format(CrashReport, maps:merge(Default,Extra)). -spec format(CrashReport) -> string() when CrashReport :: [term()]. @@ -777,66 +778,47 @@ format(CrashReport, Encoding) -> Depth :: unlimited | pos_integer(). format(CrashReport, Encoding, Depth) -> - {F,A} = get_format_and_args(CrashReport, Encoding, Depth), - lists:flatten(io_lib:format(F,A)). + do_format(CrashReport, #{chars_limit => unlimited, + depth => Depth, + encoding => Encoding}). -get_format_and_args([OwnReport,LinkReport], Encoding, Depth) -> - Extra = {Encoding,Depth}, +do_format([OwnReport,LinkReport], Extra) -> MyIndent = " ", - {OwnFormat,OwnArgs} = format_report(OwnReport, MyIndent, Extra, [], []), - {LinkFormat,LinkArgs} = format_link_report(LinkReport, MyIndent, Extra, [], []), - {" crasher:~n"++OwnFormat++" neighbours:~n"++LinkFormat,OwnArgs++LinkArgs}. + 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]), + lists:flatten(Str). -format_link_report([], _Indent, _Extra, Format, Args) -> - {lists:flatten(lists:reverse(Format)),lists:append(lists:reverse(Args))}; -format_link_report([Link|Reps], Indent, Extra, Format, Args) -> +format_link_report([Link|Reps], Indent, Extra) -> Rep = case Link of {neighbour,Rep0} -> Rep0; _ -> Link end, LinkIndent = [" ",Indent], - {LinkFormat,LinkArgs} = format_report(Rep, LinkIndent, Extra, [], []), - F = "~sneighbour:\n"++LinkFormat, - A = [Indent|LinkArgs], - format_link_report(Reps, Indent, Extra, [F|Format], [A|Args]); -format_link_report(Rep, Indent, Extra, Format, Args) -> - {F,A} = format_report(Rep, Indent, Extra, [], []), - format_link_report([], Indent, Extra, [F|Format],[A|Args]). - -format_report([], _Indent, _Extra, Format, Args) -> - {lists:flatten(lists:reverse(Format)),lists:append(lists:reverse(Args))}; -format_report([Rep|Reps], Indent, Extra, Format, Args) -> - {F,A} = format_rep(Rep, Indent, Extra), - format_report(Reps, Indent, Extra, [F|Format], [A|Args]); -format_report(Rep, Indent, {Enc,unlimited}=Extra, Format, Args) -> - {F,A} = {"~s~"++modifier(Enc)++"p~n", [Indent, Rep]}, - format_report([], Indent, Extra, [F|Format], [A|Args]); -format_report(Rep, Indent, {Enc,Depth}=Extra, Format, Args) -> - {F,A} = {"~s~"++modifier(Enc)++"P~n", [Indent, Rep, Depth]}, - format_report([], Indent, Extra, [F|Format], [A|Args]). - -format_rep({initial_call,InitialCall}, Indent, Extra) -> - format_mfa(Indent, InitialCall, Extra); -format_rep({error_info,{Class,Reason,StackTrace}}, _Indent, Extra) -> - {lists:flatten(format_exception(Class, Reason, StackTrace, Extra)),[]}; -format_rep({Tag,Data}, Indent, Extra) -> - format_tag(Indent, Tag, Data, Extra). - -format_mfa(Indent, {M,F,Args}=StartF, {Enc,_}=Extra) -> - try - A = length(Args), - {lists:flatten([Indent,"initial call: ",atom_to_list(M), - $:,to_string(F, Enc),$/,integer_to_list(A),"\n"]),[]} - catch - error:_ -> - format_tag(Indent, initial_call, StartF, Extra) - end. - -format_tag(Indent, Tag, Data, {Enc,Depth}) -> - {P,Tl} = p(Enc, Depth), - {"~s~p: ~80.18" ++ P ++ "\n", [Indent, Tag, Data|Tl]}. + [Indent,"neighbour:\n",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_rep([{initial_call,InitialCall}|Rep], Indent, Extra) -> + [format_mfa(Indent, InitialCall, Extra)|format_rep(Rep, Indent, Extra)]; +format_rep([{error_info,{Class,Reason,StackTrace}}|Rep], Indent, Extra) -> + [format_exception(Class, Reason, StackTrace, Extra)| + format_rep(Rep, Indent, Extra)]; +format_rep([{Tag,Data}|Rep], Indent, Extra) -> + [format_tag(Indent, Tag, Data, Extra)|format_rep(Rep, Indent, Extra)]; +format_rep(_, _, _Extra) -> + []. -format_exception(Class, Reason, StackTrace, {Enc,_}=Extra) -> +format_exception(Class, Reason, StackTrace, #{encoding:=Enc}=Extra) -> PF = pp_fun(Extra), StackFun = fun(M, _F, _A) -> (M =:= erl_eval) or (M =:= ?MODULE) end, %% EI = " exception: ", @@ -844,17 +826,37 @@ format_exception(Class, Reason, StackTrace, {Enc,_}=Extra) -> [EI, erl_error:format_exception(1+length(EI), Class, Reason, StackTrace, StackFun, PF, Enc), "\n"]. +format_mfa(Indent, {M,F,Args}=StartF, #{encoding:=Enc}=Extra) -> + try + A = length(Args), + [Indent,"initial call: ",atom_to_list(M),$:,to_string(F, Enc),$/, + integer_to_list(A),"\n"] + catch + error:_ -> + format_tag(Indent, initial_call, StartF, Extra) + end. + to_string(A, latin1) -> io_lib:write_atom_as_latin1(A); to_string(A, _) -> io_lib:write_atom(A). -pp_fun({Enc,Depth}) -> +pp_fun(#{encoding:=Enc,depth:=Depth,chars_limit:=Limit}) -> {P,Tl} = p(Enc, Depth), + Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; + true -> [] + end, fun(Term, I) -> - io_lib:format("~." ++ integer_to_list(I) ++ P, [Term|Tl]) + io_lib:format("~." ++ integer_to_list(I) ++ P, [Term|Tl], Opts) end. +format_tag(Indent, Tag, Data, #{encoding:=Enc,depth:=Depth,chars_limit:=Limit}) -> + {P,Tl} = p(Enc, Depth), + Opts = if is_integer(Limit) -> [{chars_limit,Limit}]; + true -> [] + end, + io_lib:format("~s~p: ~80.18" ++ P ++ "\n", [Indent, Tag, Data|Tl], Opts). + p(Encoding, Depth) -> {Letter, Tl} = case Depth of unlimited -> {"p", []}; |
