From a9a72da93e9b93a1d7ee9936b8e223545277480e Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 6 Sep 2018 13:51:49 +0200 Subject: [logger] Refactor, and add error detection for configuration --- lib/kernel/doc/src/logger.xml | 2 +- lib/kernel/src/logger.erl | 153 +++++++++++--------- lib/kernel/test/logger_SUITE.erl | 222 +++++++++++++++++++++++++++++- lib/kernel/test/logger_simple_h_SUITE.erl | 3 +- 4 files changed, 310 insertions(+), 70 deletions(-) diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index a4d6efa2d8..464c65ba76 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -527,7 +527,7 @@ start(_, []) -> Error -> Error end.

This reads the logger configuration parameter from - the my_all application and starts the configured + the my_app application and starts the configured handlers. The contents of the configuration use the same rules as the logger handler configuration. diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index df96367d82..0ada8b4924 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -115,6 +115,11 @@ -type config_handler() :: {handler, handler_id(), module(), handler_config()}. +-type config_logger() :: [{handler,default,undefined} | + config_handler() | + {filters,log | stop,[{filter_id(),filter()}]} | + {module_level,level(),[module()]}]. + -export_type([log_event/0, level/0, report/0, @@ -582,19 +587,21 @@ get_config() -> %% tree is started. internal_init_logger() -> try + Env = get_logger_env(kernel), + check_logger_config(kernel,Env), ok = logger:set_primary_config(level, get_logger_level()), - ok = logger:set_primary_config(filter_default, get_primary_filter_default()), + ok = logger:set_primary_config(filter_default, + get_primary_filter_default(Env)), [case logger:add_primary_filter(Id, Filter) of ok -> ok; {error, Reason} -> throw(Reason) - end || {Id, Filter} <- get_primary_filters()], + end || {Id, Filter} <- get_primary_filters(Env)], - _ = [[case logger:set_module_level(Module, Level) of - ok -> ok; - {error, Reason} -> throw(Reason) - end || Module <- Modules] - || {module_level, Level, Modules} <- get_logger_env()], + [case logger:set_module_level(Modules, Level) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {module_level, Level, Modules} <- Env], case logger:set_handler_config(simple,filters, get_default_handler_filters()) of @@ -602,24 +609,24 @@ internal_init_logger() -> {error,{not_found,simple}} -> ok end, - init_kernel_handlers() + init_kernel_handlers(Env) catch throw:Reason -> ?LOG_ERROR("Invalid logger config: ~p", [Reason]), {error, {bad_config, {kernel, Reason}}} end. --spec init_kernel_handlers() -> ok | {error,term()}. +-spec init_kernel_handlers(config_logger()) -> ok | {error,term()}. %% Setup the kernel environment variables to be correct %% The actual handlers are started by a call to add_handlers. -init_kernel_handlers() -> +init_kernel_handlers(Env) -> try - case get_logger_type() of + case get_logger_type(Env) of {ok,silent} -> ok = logger:remove_handler(simple); {ok,false} -> ok; {ok,Type} -> - init_default_config(Type) + init_default_config(Type,Env) end catch throw:Reason -> ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), @@ -634,10 +641,13 @@ init_kernel_handlers() -> %% and then starting the correct handlers. This is done after the %% kernel supervisor tree has been started as it needs the logger_sup. add_handlers(App) when is_atom(App) -> - add_handlers(application:get_env(App, logger, [])); + add_handlers(App,get_logger_env(App)); add_handlers(HandlerConfig) -> + add_handlers(application:get_application(),HandlerConfig). + +add_handlers(App,HandlerConfig) -> try - check_logger_config(HandlerConfig), + check_logger_config(App,HandlerConfig), DefaultAdded = lists:foldl( fun({handler, default = Id, Module, Config}, _) @@ -651,17 +661,22 @@ add_handlers(HandlerConfig) -> ({handler, Id, Module, Config}, Default) -> setup_handler(Id, Module, Config), Default orelse Id == default; - (_, Default) -> Default + (_,Default) -> Default end, false, HandlerConfig), %% If a default handler was added we try to remove the simple_logger %% If the simple logger exists it will replay its log events %% to the handler(s) added in the fold above. - _ = [case logger:remove_handler(simple) of - ok -> ok; - {error,{not_found,simple}} -> ok - end || DefaultAdded], + [case logger:remove_handler(simple) of + ok -> ok; + {error,{not_found,simple}} -> ok + end || DefaultAdded], ok - catch throw:Reason -> + catch throw:Reason0 -> + Reason = + case App of + undefined -> Reason0; + _ -> {App,Reason0} + end, ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), {error, {bad_config, {handler, Reason}}} end. @@ -672,26 +687,35 @@ setup_handler(Id, Module, Config) -> {error, Reason} -> throw(Reason) end. -check_logger_config(_) -> - ok. - --spec get_logger_type() -> {ok, standard_io | false | silent | - {file, file:name_all()} | - {file, file:name_all(), [file:mode()]}}. -get_logger_type() -> +check_logger_config(_,[]) -> + ok; +check_logger_config(App,[{handler,_,_,_}|Env]) -> + check_logger_config(App,Env); +check_logger_config(kernel,[{handler,default,undefined}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{filters,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{module_level,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(_,Bad) -> + throw(Bad). + +-spec get_logger_type(config_logger()) -> + {ok, standard_io | false | silent | + {file, file:name_all()} | + {file, file:name_all(), [file:mode()]}}. +get_logger_type(Env) -> case application:get_env(kernel, error_logger) of {ok, tty} -> {ok, standard_io}; {ok, {file, File}} when is_list(File) -> {ok, {file, File}}; - {ok, {file, File, Modes}} when is_list(File), is_list(Modes) -> - {ok, {file, File, Modes}}; {ok, false} -> {ok, false}; {ok, silent} -> {ok, silent}; undefined -> - case lists:member({handler,default,undefined}, get_logger_env()) of + case lists:member({handler,default,undefined}, Env) of true -> {ok, false}; false -> @@ -709,56 +733,55 @@ get_logger_level() -> throw({logger_level, Level}) end. -get_primary_filter_default() -> - case lists:keyfind(filters,1,get_logger_env()) of +get_primary_filter_default(Env) -> + case lists:keyfind(filters,1,Env) of {filters,Default,_} -> Default; false -> log end. -get_primary_filters() -> - lists:foldl( - fun({filters, _, Filters}, _Acc) -> - Filters; - (_, Acc) -> - Acc - end, [], get_logger_env()). +get_primary_filters(Env) -> + case [F || F={filters,_,_} <- Env] of + [{filters,_,Filters}] -> + case lists:all(fun({_,_}) -> true; (_) -> false end,Filters) of + true -> Filters; + false -> throw({invalid_filters,Filters}) + end; + [] -> []; + _ -> throw({multiple_filters,Env}) + end. %% This function looks at the kernel logger environment %% and updates it so that the correct logger is configured -init_default_config(Type) when Type==standard_io; - Type==standard_error; - element(1,Type)==file -> - Env = get_logger_env(), +init_default_config(Type,Env) when Type==standard_io; + Type==standard_error; + element(1,Type)==file -> DefaultFormatter = #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}, DefaultConfig = DefaultFormatter#{config=>#{type=>Type}}, NewLoggerEnv = case lists:keyfind(default, 2, Env) of - {handler, default, Module, Config} -> - lists:map( - fun({handler, default, logger_std_h, _}) -> - %% Only want to add the logger_std_h config - %% if not configured by user AND the default - %% handler is still the logger_std_h. - {handler, default, Module, maps:merge(DefaultConfig,Config)}; - ({handler, default, logger_disk_log_h, _}) -> - %% Add default formatter. The point of this - %% is to get the expected formatter config - %% for the default handler, since this - %% differs from the default values that - %% logger_formatter itself adds. - {handler, default, logger_disk_log_h, maps:merge(DefaultFormatter,Config)}; - (Other) -> - Other - end, Env); + {handler, default, logger_std_h, Config} -> + %% Only want to add the logger_std_h config + %% if not configured by user AND the default + %% handler is still the logger_std_h. + lists:keyreplace(default, 2, Env, + {handler, default, logger_std_h, + maps:merge(DefaultConfig,Config)}); + {handler, default, Module,Config} -> + %% Add default formatter. The point of this + %% is to get the expected formatter config + %% for the default handler, since this + %% differs from the default values that + %% logger_formatter itself adds. + lists:keyreplace(default, 2, Env, + {handler, default, Module, + maps:merge(DefaultFormatter,Config)}); _ -> %% Nothing has been configured, use default [{handler, default, logger_std_h, DefaultConfig} | Env] end, - application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]); -init_default_config(Type) -> - throw({illegal_logger_type,Type}). + application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]). get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of @@ -768,8 +791,8 @@ get_default_handler_filters() -> ?DEFAULT_HANDLER_FILTERS([otp,sasl]) end. -get_logger_env() -> - application:get_env(kernel, logger, []). +get_logger_env(App) -> + application:get_env(App, logger, []). %%%----------------------------------------------------------------- %%% Internal diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 824c95d6df..49b76f03b2 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -37,7 +37,8 @@ suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> case logger:get_handler_config(?STANDARD_HANDLER) of @@ -98,7 +99,9 @@ all() -> via_logger_process, other_node, compare_levels, - process_metadata]. + process_metadata, + app_config, + kernel_config]. start_stop(_Config) -> S = whereis(logger), @@ -895,12 +898,227 @@ process_metadata(_Config) -> ok = logger:unset_process_metadata(), undefined = logger:get_process_metadata(), + ok = logger:update_process_metadata(#{custom=>added_again}), + {error,badarg} = ?TRY(logger:update_process_metadata(bad)), + #{custom:=added_again} = logger:get_process_metadata(), + ok. process_metadata(cleanup,_Config) -> logger:remove_handler(h1), ok. +app_config(Config) -> + %% Start a node with default configuration + {ok,_,Node} = logger_test_lib:setup(Config,[]), + + App1Name = app1, + App1 = {application, App1Name, + [{description, "Test of app with logger config"}, + {applications, [kernel]}]}, + ok = rpc:call(Node,application,load,[App1]), + ok = rpc:call(Node,application,set_env, + [App1Name,logger,[{handler,default,logger_std_h,#{}}]]), + + %% Try to add an own default handler + {error,{bad_config,{handler,{app1,{already_exist,default}}}}} = + rpc:call(Node,logger,add_handlers,[App1Name]), + + %% Add a different handler + ok = rpc:call(Node,application,set_env,[App1Name,logger, + [{handler,myh,logger_std_h,#{}}]]), + ok = rpc:call(Node,logger,add_handlers,[App1Name]), + + {ok,#{filters:=DF}} = rpc:call(Node,logger,get_handler_config,[default]), + {ok,#{filters:=[]}} = rpc:call(Node,logger,get_handler_config,[myh]), + + true = test_server:stop_node(Node), + + %% Start a node with no default handler, then add an own default handler + {ok,#{handlers:=[#{id:=simple}]},Node} = + logger_test_lib:setup(Config,[{logger,[{handler,default,undefined}]}]), + + ok = rpc:call(Node,application,load,[App1]), + ok = rpc:call(Node,application,set_env, + [App1Name,logger,[{handler,default,logger_std_h,#{}}]]), + ok = rpc:call(Node,logger,add_handlers,[App1Name]), + + #{handlers:=[#{id:=default,filters:=DF}]} = + rpc:call(Node,logger,get_config,[]), + + true = test_server:stop_node(Node), + + %% Start a silent node, then add an own default handler + {ok,#{handlers:=[]},Node} = + logger_test_lib:setup(Config,[{error_logger,silent}]), + + {error,{bad_config,{handler,[{some,bad,config}]}}} = + rpc:call(Node,logger,add_handlers,[[{some,bad,config}]]), + ok = rpc:call(Node,logger,add_handlers, + [[{handler,default,logger_std_h,#{}}]]), + + #{handlers:=[#{id:=default,filters:=DF}]} = + rpc:call(Node,logger,get_config,[]), + + ok. + +%% This test case is maintly to see code coverage. Note that +%% logger_env_var_SUITE tests a lot of the same, and checks the +%% functionality more thoroughly, but since it all happens at node +%% start, it is not possible to see code coverage in that test. +kernel_config(Config) -> + %% Start a node with simple handler only, then simulate kernel + %% start by calling internally exported + %% internal_init_logger(). This is to test all variants of kernel + %% config, including bad config, and see the code coverage. + {ok,#{handlers:=[#{id:=simple,filters:=DF}]}=LC,Node} = + logger_test_lib:setup(Config,[{error_logger,false}]), + + %% Same once more, to get coverage + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + LC = rpc:call(Node,logger,get_config,[]), + + %% This shall mean the same as above, but using 'logger' parameter + %% instead of 'error_logger' + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{handler,default,undefined}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + LC = rpc:call(Node,logger,get_config,[]), + + %% Silent + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,application,set_env,[kernel,error_logger,silent]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Default + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% error_logger=tty (same as default) + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,set_env,[kernel,error_logger,tty]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% error_logger={file,File} + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + F = filename:join(?config(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + ok = rpc:call(Node,application,set_env,[kernel,error_logger,{file,F}]), + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but using 'logger' parameter instead of 'error_logger' + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_std_h, + #{config=>#{type=>{file,F}}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but with type={file,File,Modes} + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + M = [raw,write,delayed_write], + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_std_h, + #{config=>#{type=>{file,F,M}}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,M}}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Same, but with disk_log handler + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + M = [raw,write,delayed_write], + ok = rpc:call(Node,application,set_env,[kernel,logger, + [{handler,default,logger_disk_log_h, + #{config=>#{file=>F}}}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=log,filters:=[]}, + handlers:=[#{id:=default,filters:=DF,config:=#{file:=F}}], + module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + + %% Set primary filters and module level. No default handler. + ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{handler,default,undefined}, + {filters,stop,[{f1,{fun(_,_) -> log end,ok}}]}, + {module_level,debug,[?MODULE]}]]), + ok = rpc:call(Node,logger,internal_init_logger,[]), + ok = rpc:call(Node,logger,add_handlers,[kernel]), + #{primary:=#{filter_default:=stop,filters:=[_]}, + handlers:=[], + module_levels:=[{?MODULE,debug}]} = rpc:call(Node,logger,get_config,[]), + + %% Bad config + ok = rpc:call(Node,application,unset_env,[kernel,logger]), + + ok = rpc:call(Node,application,set_env,[kernel,error_logger,bad]), + {error,{bad_config,{kernel,{error_logger,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), + ok = rpc:call(Node,application,set_env,[kernel,logger_level,bad]), + {error,{bad_config,{kernel,{logger_level,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,unset_env,[kernel,logger_level]), + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[bad]}]]), + {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[bad]}]]), + {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{filters,stop,[{f1,bad}]}]]), + {error,{bad_config,{kernel,{invalid_filter,{f1,bad}}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,MF=[{filters,stop,[]},{filters,log,[]}]]), + {error,{bad_config,{kernel,{multiple_filters,MF}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok = rpc:call(Node,application,set_env, + [kernel,logger,[{module_level,bad,[?MODULE]}]]), + {error,{bad_config,{kernel,{invalid_level,bad}}}} = + rpc:call(Node,logger,internal_init_logger,[]), + + ok. + %%%----------------------------------------------------------------- %%% Internal check_logged(Level,Format,Args,Meta) -> diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl index 79e5c057ad..e0ad792bdb 100644 --- a/lib/kernel/test/logger_simple_h_SUITE.erl +++ b/lib/kernel/test/logger_simple_h_SUITE.erl @@ -117,8 +117,7 @@ replace_default(Config) -> log(Node, critical, [?str,[?keyval_rep]]), log(Node, notice, [["fake",string,"line:",?LINE]]), - Env = rpc:call(Node, application, get_env, [kernel, logger, []]), - ok = rpc:call(Node, logger, add_handlers, [Env]), + ok = rpc:call(Node, logger, add_handlers, [kernel]), ok. -- cgit v1.2.1