diff options
-rw-r--r-- | lib/kernel/doc/src/logger.xml | 2 | ||||
-rw-r--r-- | lib/kernel/doc/src/logger_chapter.xml | 14 | ||||
-rw-r--r-- | lib/kernel/doc/src/logger_formatter.xml | 7 | ||||
-rw-r--r-- | lib/kernel/doc/src/logger_std_h.xml | 23 | ||||
-rw-r--r-- | lib/kernel/src/error_logger.erl | 29 | ||||
-rw-r--r-- | lib/kernel/src/logger.erl | 166 | ||||
-rw-r--r-- | lib/kernel/src/logger_backend.erl | 2 | ||||
-rw-r--r-- | lib/kernel/src/logger_config.erl | 23 | ||||
-rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 10 | ||||
-rw-r--r-- | lib/kernel/src/logger_formatter.erl | 68 | ||||
-rw-r--r-- | lib/kernel/src/logger_h_common.erl | 23 | ||||
-rw-r--r-- | lib/kernel/src/logger_server.erl | 79 | ||||
-rw-r--r-- | lib/kernel/src/logger_std_h.erl | 10 | ||||
-rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 233 | ||||
-rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 66 | ||||
-rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 7 | ||||
-rw-r--r-- | lib/kernel/test/logger_simple_h_SUITE.erl | 3 | ||||
-rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 2 | ||||
-rw-r--r-- | lib/stdlib/src/proc_lib.erl | 93 | ||||
-rw-r--r-- | system/doc/design_principles/des_princ.xml | 2 |
20 files changed, 566 insertions, 296 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.</code> <p>This reads the <c>logger</c> configuration parameter from - the <c>my_all</c> application and starts the configured + the <c>my_app</c> application and starts the configured handlers. The contents of the configuration use the same rules as the <seealso marker="logger_chapter#handler-configuration">logger handler configuration</seealso>. diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index d58c4a4d42..4a81cfa34a 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -208,12 +208,14 @@ 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>The fun must obey the <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. The extra data also contains a field named + <c>single_line</c>, 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.</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 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.</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 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 @@ <item> <p>This has the value <c>standard_io</c>, <c>standard_error</c>, <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>.</p> + <p>If <c>LogFileOpts</c> is specified, it replaces the default + list of options used when opening the log file. The default + list is <c>[raw,append,delayed_write]</c>. One reason to do + so can be to change <c>append</c> to, for + example, <c>write</c>, ensuring that the old log is + truncated when a node is restarted. See the reference manual + for <seealso marker="file#open-2"><c>file:open/2</c></seealso> + for more information about file options.</p> + <p>Log files are always UTF-8 encoded. The encoding can not be + changed by setting the option <c>{encoding,Encoding}</c> + in <c>LogFileOpts</c>.</p> + <p>Notice that the standard handler does not have support for + circular logging. Use the disk_log handler, + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>, + for this.</p> <p> Defaults to <c>standard_io</c>.</p> - <p>It is recommended not to specify <c>LogFileOpts</c> unless absolutely - necessary. The default options used by the handler to open a file for logging are - <c>raw</c>, <c>append</c>, and <c>delayed_write</c>. Notice that the standard - handler does not have support for circular logging. Use the disk_log handler, - <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>, - for this.</p> </item> <tag><c>filesync_repeat_interval</c></tag> <item> @@ -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.</p> - <p>Defaults to <c>5000</c> milliseconds.</p> <p>If <c>no_repeat</c> 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 <seealso marker="logger_std_h#filesync-1"><c>filesync/1</c></seealso> function to perform a file sync.</p> + <p>Defaults to <c>5000</c> milliseconds.</p> </item> </taglist> <p>Other configuration parameters exist, to be used for customizing 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); diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 0020fe220b..752dd8d493 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -77,9 +77,9 @@ -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 report_cb_config() :: #{depth := pos_integer() | unlimited, + chars_limit := pos_integer() | unlimited, + single_line := boolean()}. -type msg_fun() :: fun((term()) -> {io:format(),[term()]} | report() | unicode:chardata()). @@ -116,6 +116,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, @@ -434,12 +439,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(). @@ -588,19 +588,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 @@ -608,24 +610,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]), @@ -640,10 +642,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}, _) @@ -657,17 +662,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. @@ -678,26 +688,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 -> @@ -715,56 +734,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 @@ -774,8 +792,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/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..a8f141f135 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(). @@ -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), @@ -429,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_formatter.erl b/lib/kernel/src/logger_formatter.erl index b0d4adc14d..ded89bac9f 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,single_line],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..38ac7d8ffc 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}) -> @@ -284,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), @@ -294,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_server.erl b/lib/kernel/src/logger_server.erl index 644fdd5af2..a1d40f1123 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; _ -> @@ -309,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}}; _ -> @@ -316,26 +327,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 +354,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=>[], @@ -376,7 +373,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 @@ -421,8 +418,6 @@ check_mod(Mod) when is_atom(Mod) -> check_mod(Mod) -> throw({invalid_module,Mod}). -check_level({LevelInt,cached}) when LevelInt>=?EMERGENCY, LevelInt=<?DEBUG -> - ok; check_level(Level) -> case lists:member(Level,?LEVELS) of true -> diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 9a2a1443b3..66fa6b6ab6 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(). @@ -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), @@ -418,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}. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 6bd9b20c35..36c093d7f4 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), @@ -211,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), @@ -259,7 +263,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, @@ -389,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), @@ -405,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), @@ -547,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}} = @@ -622,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), @@ -895,12 +903,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_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index a4b15c841b..a815db14e9 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 @@ -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, @@ -1194,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 = @@ -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) -> 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) -> 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. 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..cfbaf8b242 100644 --- a/lib/stdlib/src/proc_lib.erl +++ b/lib/stdlib/src/proc_lib.erl @@ -757,7 +757,8 @@ check(Res) -> Res. report_cb(#{label:={proc_lib,crash}, report:=CrashReport}, Extra) -> Default = #{chars_limit => unlimited, depth => unlimited, - encoding => latin1}, + single_line => false, + encoding => utf8}, do_format(CrashReport, maps:merge(Default,Extra)). -spec format(CrashReport) -> string() when @@ -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 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.</p> + finite-state machines, or event handlers.</p> <p><em>Behaviours</em> 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 |