diff options
Diffstat (limited to 'lib/kernel/test')
| -rw-r--r-- | lib/kernel/test/Makefile | 1 | ||||
| -rw-r--r-- | lib/kernel/test/error_logger_warn_SUITE.erl | 14 | ||||
| -rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 219 | ||||
| -rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 34 | ||||
| -rw-r--r-- | lib/kernel/test/logger_env_var_SUITE.erl | 815 | ||||
| -rw-r--r-- | lib/kernel/test/logger_filters_SUITE.erl | 25 | ||||
| -rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 142 | ||||
| -rw-r--r-- | lib/kernel/test/logger_simple_SUITE.erl | 203 | ||||
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 65 | ||||
| -rw-r--r-- | lib/kernel/test/logger_test_lib.erl | 82 |
10 files changed, 1003 insertions, 597 deletions
diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile index 8599a3d814..2f637ca9de 100644 --- a/lib/kernel/test/Makefile +++ b/lib/kernel/test/Makefile @@ -79,6 +79,7 @@ MODULES= \ logger_legacy_SUITE \ logger_simple_SUITE \ logger_std_h_SUITE \ + logger_test_lib \ os_SUITE \ pg2_SUITE \ seq_trace_SUITE \ diff --git a/lib/kernel/test/error_logger_warn_SUITE.erl b/lib/kernel/test/error_logger_warn_SUITE.erl index a8087e11f9..ef55a2d339 100644 --- a/lib/kernel/test/error_logger_warn_SUITE.erl +++ b/lib/kernel/test/error_logger_warn_SUITE.erl @@ -480,9 +480,12 @@ rb_utc() -> UtcLog=case application:get_env(sasl,utc_log) of {ok,true} -> true; - _AllOthers -> + {ok,false} -> application:set_env(sasl,utc_log,true), - false + false; + undefined -> + application:set_env(sasl,utc_log,true), + undefined end, application:start(sasl), rb:start([{report_dir, rd()}]), @@ -494,7 +497,12 @@ rb_utc() -> Sum=one_rb_findstr([],"UTC"), rb:stop(), application:stop(sasl), - application:set_env(sasl,utc_log,UtcLog), + case UtcLog of + undefined -> + application:unset_env(sasl,utc_log); + _ -> + application:set_env(sasl,utc_log,UtcLog) + end, stop_node(Node), ok. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index f311a9c7ed..e602fa2576 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -40,18 +40,18 @@ suite() -> [{timetrap,{seconds,30}}]. init_per_suite(Config) -> - case logger:get_handler_config(logger_std_h) of + case logger:get_handler_config(?STANDARD_HANDLER) of {ok,StdH} -> - ok = logger:remove_handler(logger_std_h), - [{logger_std_h,StdH}|Config]; + ok = logger:remove_handler(?STANDARD_HANDLER), + [{default_handler,StdH}|Config]; _ -> Config end. end_per_suite(Config) -> - case ?config(logger_std_h,Config) of + case ?config(default_handler,Config) of {HMod,HConfig} -> - ok = logger:add_handler(logger_std_h,HMod,HConfig); + ok = logger:add_handler(?STANDARD_HANDLER,HMod,HConfig); _ -> ok end. @@ -105,12 +105,12 @@ start_stop(_Config) -> add_remove_handler(_Config) -> register(callback_receiver,self()), - {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + #{handlers:=Hs0} = logger:i(), {error,{not_found,h1}} = logger:get_handler_config(h1), ok = logger:add_handler(h1,?MODULE,#{}), [add] = test_server:messages_get(), - {ok,#{handlers:=Hs}} = logger:get_logger_config(), - [h1|Hs0] = Hs, + #{handlers:=Hs} = logger:i(), + {value,_,Hs0} = lists:keytake(h1,1,Hs), {ok,{?MODULE,#{level:=info,filters:=[],filter_default:=log}}} = % defaults logger:get_handler_config(h1), ok = logger:set_handler_config(h1,filter_default,stop), @@ -124,7 +124,7 @@ add_remove_handler(_Config) -> ok = check_logged(info,"hello",[],?MY_LOC(1)), ok = logger:remove_handler(h1), [remove] = test_server:messages_get(), - {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + #{handlers:=Hs0} = logger:i(), {error,{not_found,h1}} = logger:get_handler_config(h1), {error,{not_found,h1}} = logger:remove_handler(h1), logger:info("hello",[]), @@ -218,33 +218,52 @@ change_config(_Config) -> {ok,{?MODULE,#{level:=info,filter_default:=stop}=C2}} = logger:get_handler_config(h1), false = maps:is_key(custom,C2), - {error,fail} = logger:set_handler_config(h1,#{fail=>true}), + {error,fail} = logger:set_handler_config(h1,#{conf_call=>fun() -> {error,fail} end}), {error,{attempting_syncronous_call_to_self,_}} = logger:set_handler_config( - h1,#{call=>fun() -> logger:set_module_level(?MODULE,debug) end}), + h1,#{conf_call=>fun() -> logger:set_handler_config(?MODULE,#{}) end}), + ok = + logger:set_handler_config( + h1,#{conf_call=>fun() -> logger:set_module_level(?MODULE,debug) end}), {ok,{?MODULE,C2}} = logger:get_handler_config(h1), - %% Change one key only - {error,fail} = logger:set_handler_config(h1,fail,true), + %% Change handler config: Single key + {error,fail} = logger:set_handler_config(h1,conf_call,fun() -> {error,fail} end), ok = logger:set_handler_config(h1,custom,custom), [changing_config] = test_server:messages_get(), {ok,{?MODULE,#{custom:=custom}=C3}} = logger:get_handler_config(h1), C2 = maps:remove(custom,C3), + %% Change handler config: Map + ok = logger:update_handler_config(h1,#{custom=>new_custom}), + [changing_config] = test_server:messages_get(), + {ok,{_,C4}} = logger:get_handler_config(h1), + C4 = C3#{custom:=new_custom}, + + %% Change logger config: Single key + {ok,LConfig0} = logger:get_logger_config(), + ok = logger:set_logger_config(level,warning), + {ok,LConfig1} = logger:get_logger_config(), + LConfig1 = LConfig0#{level:=warning}, + + %% Change logger config: Map + ok = logger:update_logger_config(#{level=>error}), + {ok,LConfig2} = logger:get_logger_config(), + LConfig2 = LConfig1#{level:=error}, + %% Overwrite logger config - check that defaults are added - {ok,LConfig} = logger:get_logger_config(), ok = logger:set_logger_config(#{filter_default=>stop}), - {ok,#{level:=info,filters:=[],handlers:=[],filter_default:=stop}=LC1} = - logger:get_logger_config(), - 4 = maps:size(LC1), - - %% Change one key only - ok = logger:set_logger_config(handlers,[h1]), - {ok,#{level:=info,filters:=[],handlers:=[h1],filter_default:=stop}} = + {ok,#{level:=info,filters:=[],filter_default:=stop}=LC1} = logger:get_logger_config(), + 3 = maps:size(LC1), + %% Check that internal 'handlers' field has not been changed + #{handlers:=HCs} = logger:i(), + HIds1 = [Id || {Id,_,_} <- HCs], + {ok,#{handlers:=HIds2}} = logger_config:get(?LOGGER_TABLE,logger), + HIds1 = lists:sort(HIds2), %% Cleanup - ok = logger:set_logger_config(LConfig), + ok = logger:set_logger_config(LConfig0), [] = test_server:messages_get(), ok. @@ -425,6 +444,7 @@ filter_failed(cleanup,_Config) -> ok. 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), @@ -434,26 +454,62 @@ handler_failed(_Config) -> logger:add_handler(h1,?MODULE,#{filter_default=>true}), {error,{invalid_formatter,[]}} = logger:add_handler(h1,?MODULE,#{formatter=>[]}), - ok = logger:add_handler(h1,nomodule,#{filter_default=>log}), + {error,{invalid_handler,_}} = logger:add_handler(h1,nomodule,#{filter_default=>log}), logger:info(?map_rep), check_no_log(), - #{logger:=#{handlers:=Ids1}, - handlers:=H1} = logger:i(), - false = lists:member(h1,Ids1), + #{handlers:=H1} = logger:i(), false = lists:keymember(h1,1,H1), {error,{not_found,h1}} = logger:remove_handler(h1), - ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,crash=>true}), + ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,log_call=>fun() -> a = b end}), {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}), + [add] = test_server:messages_get(), logger:info(?map_rep), - check_no_log(), - #{logger:=#{handlers:=Ids2}, - handlers:=H2} = logger:i(), - false = lists:member(h2,Ids2), + [remove] = test_server:messages_get(), + #{handlers:=H2} = logger:i(), false = lists:keymember(h2,1,H2), {error,{not_found,h2}} = logger:remove_handler(h2), + CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end, + CrashHandler = fun() -> a = b end, + KillHandler = fun() -> exit(self(), die) end, + + {error,{handler_not_added,{attempting_syncronous_call_to_self,_}}} = + logger:add_handler(h1,?MODULE,#{add_call=>CallAddHandler}), + {error,{handler_not_added,{callback_crashed,_}}} = + logger:add_handler(h1,?MODULE,#{add_call=>CrashHandler}), + {error,{handler_not_added,{logger_process_exited,_,die}}} = + logger:add_handler(h1,?MODULE,#{add_call=>KillHandler}), + + check_no_log(), + ok = logger:add_handler(h1,?MODULE,#{}), + {error,{attempting_syncronous_call_to_self,_}} = + logger:set_handler_config(h1,#{conf_call=>CallAddHandler}), + {error,{callback_crashed,_}} = + logger:set_handler_config(h1,#{conf_call=>CrashHandler}), + {error,{logger_process_exited,_,die}} = + logger:set_handler_config(h1,#{conf_call=>KillHandler}), + + {error,{attempting_syncronous_call_to_self,_}} = + logger:set_handler_config(h1,conf_call,CallAddHandler), + {error,{callback_crashed,_}} = + logger:set_handler_config(h1,conf_call,CrashHandler), + {error,{logger_process_exited,_,die}} = + logger:set_handler_config(h1,conf_call,KillHandler), + + ok = logger:remove_handler(h1), + [add,remove] = test_server:messages_get(), + + check_no_log(), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>CallAddHandler}), + ok = logger:remove_handler(h1), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>CrashHandler}), + ok = logger:remove_handler(h1), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>KillHandler}), + ok = logger:remove_handler(h1), + [add,add,add] = test_server:messages_get(), + ok. handler_failed(cleanup,_Config) -> @@ -466,10 +522,6 @@ config_sanity_check(_Config) -> {error,{invalid_filter_default,bad}} = logger:set_logger_config(filter_default,bad), {error,{invalid_level,bad}} = logger:set_logger_config(level,bad), - {error,{invalid_handlers,bad}} = logger:set_logger_config(handlers,bad), - {error,{invalid_id,{bad,bad}}} = - logger:set_logger_config(handlers,[{bad,bad}]), - {error,{invalid_id,"bad"}} = logger:set_logger_config(handlers,["bad"]), {error,{invalid_filters,bad}} = logger:set_logger_config(filters,bad), {error,{invalid_filter,bad}} = logger:set_logger_config(filters,[bad]), {error,{invalid_filter,{_,_}}} = @@ -499,29 +551,96 @@ config_sanity_check(_Config) -> logger:set_handler_config(h1,formatter,bad), {error,{invalid_module,{bad}}} = logger:set_handler_config(h1,formatter,{{bad},cfg}), - {error,{invalid_formatter_config,bad}} = + {error,{invalid_formatter_config,logger_formatter,bad}} = logger:set_handler_config(h1,formatter,{logger_formatter,bad}), - {error,{invalid_formatter_config,{bad,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{bad,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter,#{bad=>bad}}), - {error,{invalid_formatter_config,{template,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{template,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>bad}}), - {error,{invalid_formatter_template,[1]}} = + {error,{invalid_formatter_template,logger_formatter,[1]}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>[1]}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>[]}}), - {error,{invalid_formatter_config,{single_line,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{single_line,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{single_line=>bad}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{single_line=>true}}), - {error,{invalid_formatter_config,{legacy_header,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{legacy_header,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{legacy_header=>bad}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{legacy_header=>true}}), + {error,{invalid_formatter_config,logger_formatter,{report_cb,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{report_cb=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{report_cb=>fun(R) -> + {"~p",[R]} + end}}), + {error,{invalid_formatter_config,logger_formatter,{chars_limit,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>4}}), + {error,{invalid_formatter_config,logger_formatter,{depth,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>4}}), + {error,{invalid_formatter_config,logger_formatter,{max_size,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>4}}), + ok = logger:set_handler_config(h1,formatter,{module,config}), + {error,{callback_crashed,{error,{badmatch,3},[{?MODULE,check_config,1,_}]}}} = + logger:set_handler_config(h1,formatter,{?MODULE,crash}), ok = logger:set_handler_config(h1,custom,custom), + + %% Old utc parameter is no longer allowed (replaced by time_offset) + {error,{invalid_formatter_config,logger_formatter,{utc,true}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{utc=>true}}), + {error,{invalid_formatter_config,logger_formatter,{time_offset,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>""}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"Z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"-0:0"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+10:13"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_offset,"+0"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+0"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_designator,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>bad}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,"s"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>"s"}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,0}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>$\s}}), ok. config_sanity_check(cleanup,_Config) -> @@ -720,16 +839,19 @@ check_maps(Expected,Got,What) -> end. %% Handler +adding_handler(_Id,#{add_call:=Fun}) -> + Fun(); adding_handler(_Id,Config) -> maybe_send(add), {ok,Config}. + +removing_handler(_Id,#{rem_call:=Fun}) -> + Fun(); removing_handler(_Id,_Config) -> maybe_send(remove), ok. -changing_config(_Id,_Old,#{call:=Fun}) -> +changing_config(_Id,_Old,#{conf_call:=Fun}) -> Fun(); -changing_config(_Id,_Old,#{fail:=true}) -> - {error,fail}; changing_config(_Id,_Old,Config) -> maybe_send(changing_config), {ok,Config}. @@ -740,8 +862,8 @@ maybe_send(Msg) -> Pid -> Pid ! Msg end. -log(_Log,#{crash:=true}) -> - a=b; +log(_Log,#{log_call:=Fun}) -> + Fun(); log(Log,Config) -> TcProc = maps:get(tc_proc,Config,self()), TcProc ! {Log,Config}, @@ -829,3 +951,8 @@ test_macros(emergency=Level) -> %%% Called by macro ?TRY(X) my_try(Fun) -> try Fun() catch C:R -> {C,R} end. + +check_config(crash) -> + erlang:error({badmatch,3}); +check_config(_) -> + ok. diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 7c33c9130c..3aa1c3557b 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -31,7 +31,8 @@ end). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> timer:start(), % to avoid progress report @@ -327,7 +328,8 @@ formatter_fail(Config) -> logger:add_handler(Name, logger_disk_log_h, HConfig), Pid = whereis(Name), true = is_pid(Pid), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC1} = logger:i(), + H = [Id || {Id,_,_} <- HC1], true = lists:member(Name,H), %% Formatter is added automatically @@ -356,7 +358,8 @@ formatter_fail(Config) -> %% Check that handler is still alive and was never dead Pid = whereis(Name), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC2} = logger:i(), + H = [Id || {Id,_,_} <- HC2], ok. formatter_fail(cleanup,_Config) -> @@ -725,7 +728,7 @@ write_failure(Config) -> Log = lists:concat([File,".1"]), ct:pal("Log = ~p", [Log]), - Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + Node = start_h_on_new_node(Config, File), false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), @@ -769,7 +772,7 @@ sync_failure(Config) -> File = filename:join(Dir, FileName), - Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + Node = start_h_on_new_node(Config, File), false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), @@ -809,21 +812,12 @@ sync_failure(cleanup, _Config) -> Nodes = nodes(), [test_server:stop_node(Node) || Node <- Nodes]. -start_h_on_new_node(_Config, Func, File) -> - Pa = filename:dirname(code:which(?MODULE)), - Dest = - case os:type() of - {win32,_} -> - lists:concat([" {disk_log,\\\"",File,"\\\"}"]); - _ -> - lists:concat([" \'{disk_log,\"",File,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), - NodeName = lists:concat([?MODULE,"_",Func]), - ct:pal("Starting ~s with ~tp", [NodeName,Args]), - {ok,Node} = test_server:start_node(NodeName, peer, [{args, Args}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), - true = is_pid(Pid), +start_h_on_new_node(Config, File) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger,[{handler,default,logger_disk_log_h, + #{ disk_log_opts => #{ file => File }}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index c2d3364701..764f443634 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -1,4 +1,4 @@ -% +%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 2018. All Rights Reserved. @@ -21,83 +21,65 @@ -compile(export_all). --include_lib("common_test/include/ct.hrl"). -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). --define(all_vars,[{kernel,logger_dest}, - {kernel,logger_level}, - {kernel,logger_log_progress}, - {kernel,logger_sasl_compatible}, - {kernel,error_logger}]). +-import(logger_test_lib,[setup/2,log/3,sync_and_read/3]). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,60}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> - Env = [{App,Key,application:get_env(App,Key)} || {App,Key} <- ?all_vars], - Removed = cleanup(), - [{env,Env},{logger,Removed}|Config]. - -end_per_suite(Config) -> - [application:set_env(App,Key,Val) || - {App,Key,Val} <- ?config(env,Config), - Val =/= undefined], - Hs = ?config(logger,Config), - [ok = logger:add_handler(Id,Mod,C) || {Id,Mod,C} <- Hs], - ok. - -init_per_group(_Group, Config) -> - Config. - -end_per_group(_Group, _Config) -> - ok. - -init_per_testcase(_TestCase, Config) -> Config. -end_per_testcase(Case, Config) -> - try apply(?MODULE,Case,[cleanup,Config]) - catch error:undef -> ok - end, - cleanup(), +end_per_suite(_Config) -> ok. groups() -> - []. - -all() -> + [{error_logger,[],[error_logger_tty, + error_logger_tty_sasl_compatible, + error_logger_false, + error_logger_false_progress, + error_logger_false_sasl_compatible, + error_logger_silent, + error_logger_silent_sasl_compatible, + error_logger_file]}, + {logger,[],[logger_file, + logger_file_sasl_compatible, + logger_file_log_progress, + logger_file_no_filter, + logger_file_no_filter_level, + logger_file_formatter, + logger_filters, + logger_filters_stop, + logger_module_level, + logger_disk_log, + logger_disk_log_formatter, + logger_undefined, + logger_many_handlers_default_first, + logger_many_handlers_default_last, + logger_many_handlers_default_last_broken_filter + ]}, + {bad,[],[bad_error_logger, + bad_level, + bad_sasl_compatibility, + bad_progress]}]. + +all() -> [default, default_sasl_compatible, - dest_tty, - dest_tty_sasl_compatible, - dest_false, - dest_false_progress, - dest_false_sasl_compatible, - dest_silent, - dest_silent_sasl_compatible, - dest_file_old, - dest_file, - dest_disk_log, - %% disk_log_vars, % or test this in logger_disk_log_SUITE? sasl_compatible_false, sasl_compatible_false_no_progress, sasl_compatible, - bad_dest%% , - %% bad_level, - %% bad_sasl_compatibility, - %% bad_progress + {group,bad}, + {group,error_logger}, + {group,logger} ]. default(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - undefined, - undefined, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), + {ok,#{handlers:=Hs},_Node} = setup(Config,[]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = @@ -105,18 +87,12 @@ default(Config) -> true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), - false = is_pid(whereis(sasl_h)), ok. default_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - undefined, - undefined, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{logger_sasl_compatible,true}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = @@ -124,18 +100,11 @@ default_sasl_compatible(Config) -> false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_tty(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - tty, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), +error_logger_tty(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config,[{error_logger,tty}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = @@ -143,18 +112,13 @@ dest_tty(Config) -> true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), - false = is_pid(whereis(sasl_h)), ok. -dest_tty_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - tty, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), +error_logger_tty_sasl_compatible(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,tty}, + {logger_sasl_compatible,true}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = @@ -162,19 +126,17 @@ dest_tty_sasl_compatible(Config) -> false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_false(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), @@ -182,16 +144,16 @@ dest_false(Config) -> false = lists:keymember(sasl_h,1,Hs), ok. -dest_false_progress(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - undefined, % sasl comp (default=false) - true), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false_progress(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}, + {logger_log_progress,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), @@ -199,253 +161,496 @@ dest_false_progress(Config) -> false = lists:keymember(sasl_h,1,Hs), ok. -dest_false_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false_sasl_compatible(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}, + {logger_sasl_compatible,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = lists:keyfind(domain,1,SimpleFilters), false = lists:keymember(stop_progress,1,SimpleFilters), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_silent(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - silent, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_silent(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,silent}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + ok. + +error_logger_silent_sasl_compatible(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,silent}, + {logger_sasl_compatible,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + true = lists:keymember(sasl_h,1,Hs), + ok. + + +error_logger_file(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + ok. + + +logger_file(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), + ok. -dest_silent_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - silent, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +logger_file_sasl_compatible(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger_sasl_compatible,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), + + ok. + +logger_file_log_progress(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_no_filter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filter_default=>log,filters=>[], + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_no_filter_level(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[],level=>error, + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0,% progress in std logger + error),% level + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + error = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_formatter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_single_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_filters(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,logger:=Logger},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}, + {filters,log,[{stop_progress,{fun logger_filters:progress/2,stop}}]} + ]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + LoggerFilters = maps:get(filters,Logger), + true = lists:keymember(stop_progress,1,LoggerFilters), + + ok. + +logger_filters_stop(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,logger:=Logger},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[], + logger_std_h=>#{type=>{file,Log}}}}, + {filters,stop,[{log_error,{fun logger_filters:level/2,{log,gt,info}}}]} + ]}]), + check_default_log(Node,Log, + file,% dest + 0, + notice),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + LoggerFilters = maps:get(filters,Logger), + true = lists:keymember(log_error,1,LoggerFilters), + + ok. + +logger_module_level(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,module_levels:=ModuleLevels},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}, + {module_level,error,[supervisor]} + ]}]), + check_default_log(Node,Log, + file,% dest + 3),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + [{supervisor,error}] = ModuleLevels, + ok. + +logger_disk_log(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_disk_log_h, + #{disk_log_opts=>#{file=>Log}}}]}]), + check_default_log(Node,Log, + disk_log,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_disk_log_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + ok. +logger_disk_log_formatter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_disk_log_h, + #{filters=>[], + formatter=>{logger_formatter,#{}}, + disk_log_opts=>#{file=>Log}}}]}]), + check_single_log(Node,Log, + disk_log,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_disk_log_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), -dest_file_old(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - error_logger, - file, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - file, % dest - 0), % progress in std logger ok. - - -dest_file(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - file, % dest - 0), % progress in std logger + +logger_undefined(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config,[{logger,[{handler,?STANDARD_HANDLER,undefined}]}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), + info = maps:get(level,SimpleC), + info = maps:get(level,L), + SimpleFilters = maps:get(filters,SimpleC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,SimpleFilters), + true = lists:keymember(stop_progress,1,SimpleFilters), + false = lists:keymember(sasl_h,1,Hs), ok. - - -dest_disk_log(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - disk_log, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - disk_log, % dest - 0), % progress in std logger + + +%% Test that we can add multiple handlers with the default first +logger_many_handlers_default_first(Config) -> + LogErr = file(Config,logger_many_handlers_default_first_error), + LogInfo = file(Config,logger_many_handlers_default_first_info), + + logger_many_handlers( + Config,[{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + }, + {handler,info,logger_std_h, + #{level=>info, + filters=>[{level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + } + ]}], LogErr, LogInfo, 6). + +%% Test that we can add multiple handlers with the default last +logger_many_handlers_default_last(Config) -> + LogErr = file(Config,logger_many_handlers_default_last_error), + LogInfo = file(Config,logger_many_handlers_default_last_info), + logger_many_handlers( + Config,[{logger, + [{handler,info,logger_std_h, + #{level=>info, + filters=>[{level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + }, + {handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + } + ]}], LogErr, LogInfo, 7). + +%% Check that we can handle that an added logger has a broken filter +%% This used to cause a deadlock. +logger_many_handlers_default_last_broken_filter(Config) -> + LogErr = file(Config,logger_many_handlers_default_first_broken_filter_error), + LogInfo = file(Config,logger_many_handlers_default_first_broken_filter_info), + + logger_many_handlers( + Config,[{logger, + [{handler,info,logger_std_h, + #{level=>info, + filters=>[{broken,{fun logger_filters:level/2,broken_state}}, + {level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + }, + {handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + } + ]}], LogErr, LogInfo, 7). + +logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> + {ok,#{handlers:=Hs},Node} = setup(Config,Env), + check_single_log(Node,LogErr, + file,% dest + 0,% progress in std logger + error), % level + ok = rpc:call(Node,logger_std_h,filesync,[info]), + {ok, Bin} = file:read_file(LogInfo), + ct:log("Log content:~n~s",[Bin]), + match(Bin,<<"PROGRESS REPORT">>,NumProgress,info,info), + match(Bin,<<"ALERT REPORT">>,0,alert,info), + ok. - sasl_compatible_false(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - false, % sasl comp - true), % progress - check_log(Log, - file, % dest - 4), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}, + {logger_log_progress,true}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger ok. sasl_compatible_false_no_progress(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - false, % sasl comp - false), % progress - check_log(Log, - file, % dest - 0), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}, + {logger_log_progress,false}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger ok. sasl_compatible(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - true, % sasl comp - undefined), % progress - check_log(Log, - file, % dest - 0), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {sasl_compatible,true}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger ok. -bad_dest(Config) -> - {error,{bad_config,{kernel,{logger_dest,baddest}}}} = - setup(Config,?FUNCTION_NAME, - logger_dest, - baddest, - undefined, - undefined, - undefined). +bad_error_logger(Config) -> + error = setup(Config,[{error_logger,baddest}]). bad_level(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - badlevel, - undefined, - undefined). + error = setup(Config,[{logger_level,badlevel}]). bad_sasl_compatibility(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - info, - badcomp, - undefined). + error = setup(Config,[{logger_sasl_compatible,badcomp}]). bad_progress(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - info, - undefined, - badprogress). + error = setup(Config,[{logger_log_progress,badprogress}]). %%%----------------------------------------------------------------- %%% Internal -setup(Config,Func,DestVar,Dest,Level,SaslComp,Progress) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - Dir = ?config(priv_dir,Config), - File = lists:concat([?MODULE,"_",Func,".log"]), - Log = filename:join(Dir,File), - case Dest of - undefined -> - ok; - F when F==file; F==disk_log -> - application:set_env(kernel,DestVar,{Dest,Log}); - _ -> - application:set_env(kernel,DestVar,Dest) - end, - case Level of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_level,Level) - end, - case SaslComp of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_sasl_compatible,SaslComp) - end, - case Progress of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_log_progress,Progress) - end, - case logger:setup_standard_handler() of - ok -> - application:start(sasl), - StdH = case Dest of - NoH when NoH==false; NoH==silent -> false; - _ -> true - end, - StdH = is_pid(whereis(?STANDARD_HANDLER)), - SaslH = if SaslComp -> true; - true -> false - end, - SaslH = is_pid(whereis(sasl_h)), - {ok,{Log,maps:get(handlers,logger:i())}}; - Error -> - Error - end. +file(Config,Func) -> + filename:join(proplists:get_value(priv_dir,Config), + lists:concat([Func,".log"])). + +check_default_log(Node,Log,Dest,NumProgress) -> + check_default_log(Node,Log,Dest,NumProgress,info). +check_default_log(Node,Log,Dest,NumProgress,Level) -> + + {ok,Bin1,Bin2} = check_log(Node,Log,Dest), + + match(Bin1,<<"PROGRESS REPORT">>,NumProgress,info,Level), + match(Bin1,<<"ALERT REPORT">>,1,alert,Level), + match(Bin1,<<"INFO REPORT">>,0,info,Level), + match(Bin1,<<"DEBUG REPORT">>,0,debug,Level), + + match(Bin2,<<"INFO REPORT">>,1,info,Level), + match(Bin2,<<"DEBUG REPORT">>,0,debug,Level), + ok. + +check_single_log(Node,Log,Dest,NumProgress) -> + check_single_log(Node,Log,Dest,NumProgress,info). +check_single_log(Node,Log,Dest,NumProgress,Level) -> + + {ok,Bin1,Bin2} = check_log(Node,Log,Dest), -check_log(Log,Dest,NumProgress) -> - ok = logger:alert("dummy1"), - ok = logger:debug("dummy1"), + match(Bin1,<<"info:">>,NumProgress,info,Level), + match(Bin1,<<"alert:">>,1,alert,Level), + match(Bin1,<<"debug:">>,0,debug,Level), + + match(Bin2,<<"info:">>,NumProgress+1,info,Level), + match(Bin2,<<"debug:">>,0,debug,Level), + + ok. + +check_log(Node,Log,Dest) -> + + ok = log(Node,alert,["dummy1"]), + ok = log(Node,debug,["dummy1"]), %% Check that there are progress reports (supervisor and %% application_controller) and an error report (the call above) in %% the log. There should not be any info reports yet. - {ok,Bin1} = sync_and_read(Dest,Log), + {ok,Bin1} = sync_and_read(Node,Dest,Log), ct:log("Log content:~n~s",[Bin1]), - match(Bin1,<<"PROGRESS REPORT">>,NumProgress), - match(Bin1,<<"ALERT REPORT">>,1), - match(Bin1,<<"INFO REPORT">>,0), - match(Bin1,<<"DEBUG REPORT">>,0), %% Then stop sasl and see that the info report from %% application_controller is there - ok = application:stop(sasl), - {ok,Bin2} = sync_and_read(Dest,Log), + ok = rpc:call(Node,application,stop,[sasl]), + {ok,Bin2} = sync_and_read(Node,Dest,Log), ct:log("Log content:~n~s",[Bin2]), - match(Bin2,<<"INFO REPORT">>,1), - match(Bin1,<<"DEBUG REPORT">>,0), - ok. + {ok,Bin1,Bin2}. -match(Bin,Pattern,0) -> +match(Bin,Pattern,0,_,_) -> nomatch = re:run(Bin,Pattern,[{capture,none}]); -match(Bin,Pattern,N) -> - {match,M} = re:run(Bin,Pattern,[{capture,all},global]), - N = length(M). - -sync_and_read(disk_log,Log) -> - logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), - file:read_file(Log ++ ".1"); -sync_and_read(file,Log) -> - logger_std_h:filesync(?STANDARD_HANDLER), - file:read_file(Log). - -cleanup() -> - application:stop(sasl), - [application:unset_env(App,Key) || {App,Key} <- ?all_vars], - #{handlers:=Hs0} = logger:i(), - Hs = lists:keydelete(cth_log_redirect,1,Hs0), - [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], - Hs. +match(Bin,Pattern,N,LogLevel,ConfLevel) -> + case logger:compare_levels(LogLevel,ConfLevel) of + lt -> match(Bin,Pattern,0,LogLevel,ConfLevel); + _ -> + {match,M} = re:run(Bin,Pattern,[{capture,all},global]), + N = length(M) + end. diff --git a/lib/kernel/test/logger_filters_SUITE.erl b/lib/kernel/test/logger_filters_SUITE.erl index 21f14bbc02..c4b31370ff 100644 --- a/lib/kernel/test/logger_filters_SUITE.erl +++ b/lib/kernel/test/logger_filters_SUITE.erl @@ -81,6 +81,8 @@ domain(_Config) -> stop = logger_filters:domain(?dlog([]),{stop,starts_with,[]}), L3 = logger_filters:domain(L3=?dlog([]),{log,equals,[]}), stop = logger_filters:domain(?dlog([]),{stop,equals,[]}), + ignore = logger_filters:domain(?dlog([]),{log,differs,[]}), + ignore = logger_filters:domain(?dlog([]),{stop,differs,[]}), ignore = logger_filters:domain(?dlog([]),{log,no_domain,[]}), ignore = logger_filters:domain(?dlog([]),{stop,no_domain,[]}), @@ -90,15 +92,19 @@ domain(_Config) -> ignore = logger_filters:domain(?dlog([a]),{stop,starts_with,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{log,equals,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{stop,equals,[a,b]}), + L5 = logger_filters:domain(L5=?dlog([a]),{log,differs,[a,b]}), + stop = logger_filters:domain(?dlog([a]),{stop,differs,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{log,no_domain,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{stop,no_domain,[a,b]}), ignore = logger_filters:domain(?dlog([a,b]),{log,prefix_of,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,prefix_of,[a]}), - L5 = logger_filters:domain(L5=?dlog([a,b]),{log,starts_with,[a]}), + L6 = logger_filters:domain(L6=?dlog([a,b]),{log,starts_with,[a]}), stop = logger_filters:domain(?dlog([a,b]),{stop,starts_with,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{log,equals,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,equals,[a]}), + L7 = logger_filters:domain(L7=?dlog([a,b]),{log,differs,[a]}), + stop = logger_filters:domain(?dlog([a,b]),{stop,differs,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{log,no_domain,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,no_domain,[a]}), @@ -108,26 +114,33 @@ domain(_Config) -> ignore = logger_filters:domain(?ndlog,{stop,starts_with,[a]}), ignore = logger_filters:domain(?ndlog,{log,equals,[a]}), ignore = logger_filters:domain(?ndlog,{stop,equals,[a]}), - L6 = logger_filters:domain(L6=?ndlog,{log,no_domain,[a]}), + L8 = logger_filters:domain(L8=?ndlog,{log,differs,[a]}), + stop = logger_filters:domain(?ndlog,{stop,differs,[a]}), + L9 = logger_filters:domain(L9=?ndlog,{log,no_domain,[a]}), stop = logger_filters:domain(?ndlog,{stop,no_domain,[a]}), - L7 = logger_filters:domain(L7=?dlog([a,b,c,d]),{log,prefix_of,[a,b,c,d]}), + L10 = logger_filters:domain(L10=?dlog([a,b,c,d]),{log,prefix_of,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,prefix_of,[a,b,c,d]}), - L8 = logger_filters:domain(L8=?dlog([a,b,c,d]),{log,starts_with,[a,b,c,d]}), + L11 = logger_filters:domain(L11=?dlog([a,b,c,d]),{log,starts_with,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,starts_with,[a,b,c,d]}), - L9 = logger_filters:domain(L9=?dlog([a,b,c,d]),{log,equals,[a,b,c,d]}), + L12 = logger_filters:domain(L12=?dlog([a,b,c,d]),{log,equals,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,equals,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{log,differs,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{stop,differs,[a,b,c,d]}), ignore = logger_filters:domain(?dlog([a,b,c,d]),{log,no_domain,[a,b,c,d]}), ignore = logger_filters:domain(?dlog([a,b,c,d]),{stop,no_domain,[a,b,c,d]}), %% A domain field in meta which is not a list is allowed by the - %% filter, but it will never match. + %% filter, but since MatchDomain is always a list of atoms, only + %% Action=differs can ever match. ignore = logger_filters:domain(?dlog(dummy),{log,prefix_of,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,prefix_of,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,starts_with,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,starts_with,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,equals,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,equals,[a,b,c,d]}), + L13 = logger_filters:domain(L13=?dlog(dummy),{log,differs,[a,b,c,d]}), + stop = logger_filters:domain(?dlog(dummy),{stop,differs,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,no_domain,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,no_domain,[a,b,c,d]}), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 7d1f33746d..9baadfd65a 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -73,7 +73,7 @@ all() -> default(_Config) -> String1 = format(info,{"~p",[term]},#{},#{}), ct:log(String1), - [_Date,_Time,"info:","term\n"] = string:lexemes(String1," "), + [_DateTime,"info:","term\n"] = string:lexemes(String1," "), Time = timestamp(), ExpectedTimestamp = default_time_format(Time), @@ -297,22 +297,22 @@ max_size(_Config) -> single_line=>false}, "12345678901234567890" = format(info,{"12345678901234567890",[]},#{},Cfg), - application:set_env(kernel,logger_max_size,11), - "12345678901234567890" = % min value is 50, so this is not limited - format(info,{"12345678901234567890",[]},#{},Cfg), - "12345678901234567890123456789012345678901234567..." = % 50 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - Cfg), - application:set_env(kernel,logger_max_size,53), - "12345678901234567890123456789012345678901234567890..." = %53 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - Cfg), + %% application:set_env(kernel,logger_max_size,11), + %% "12345678901234567890" = % min value is 50, so this is not limited + %% format(info,{"12345678901234567890",[]},#{},Cfg), + %% "12345678901234567890123456789012345678901234567..." = % 50 + %% format(info, + %% {"123456789012345678901234567890123456789012345678901234567890", + %% []}, + %% #{}, + %% Cfg), + %% application:set_env(kernel,logger_max_size,53), + %% "12345678901234567890123456789012345678901234567890..." = %53 + %% format(info, + %% {"123456789012345678901234567890123456789012345678901234567890", + %% []}, + %% #{}, + %% Cfg), "123456789012..." = format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}), "12345678901234567890" = @@ -341,12 +341,6 @@ depth(_Config) -> {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, #{}, #{template=>Template}), - application:set_env(kernel,logger_format_depth,12), - "[1,2,3,4,5,6,7,8,9,0,1|...]" = - format(info, - {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, - #{}, - #{template=>Template}), "[1,2,3,4,5,6,7,8,9,0,1,2|...]" = format(info, {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, @@ -361,7 +355,7 @@ depth(_Config) -> depth=>unlimited}), ok. depth(cleanup,_Config) -> - application:unset_env(kernel,logger_format_depth), + application:unset_env(kernel,error_logger_format_depth), ok. chars_limit(_Config) -> @@ -370,7 +364,7 @@ chars_limit(_Config) -> lists:seq(1,100), maps:from_list(lists:zip(lists:seq(1,100), lists:duplicate(100,value)))]}, - Meta = #{time=>"2018-04-26 9:15:40.449879"}, + Meta = #{time=>timestamp()}, Template = [time," - ", msg, "\n"], FC = #{template=>Template, depth=>unlimited, @@ -382,7 +376,7 @@ chars_limit(_Config) -> L1 = string:length(String1), ct:log("String1: ~p~nLength1: ~p~n",[lists:flatten(String1),L1]), true = L1 > CL1, - true = L1 < CL1 + 10, + true = L1 < CL1 + 15, String2 = format(info,FA,Meta,FC#{chars_limit=>CL1,depth=>10}), L2 = string:length(String2), @@ -394,13 +388,13 @@ chars_limit(_Config) -> L3 = string:length(String3), ct:log("String3: ~p~nLength3: ~p~n",[lists:flatten(String3),L3]), true = L3 > CL3, - true = L3 < CL3 + 10, + true = L3 < CL3 + 15, String4 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10}), L4 = string:length(String4), ct:log("String4: ~p~nLength4: ~p~n",[lists:flatten(String4),L4]), true = L4 > CL3, - true = L4 < CL3 + 10, + true = L4 < CL3 + 15, %% Test that max_size truncates the string which is limited by %% depth and chars_limit @@ -439,29 +433,58 @@ format_mfa(_Config) -> ok. format_time(_Config) -> - Time1 = timestamp(), - ExpectedTimestamp1 = default_time_format(Time1), - String1 = format(info,{"~p",[term]},#{time=>Time1},#{}), - ct:log(String1), - " info: term\n" = string:prefix(String1,ExpectedTimestamp1), - - Time2 = timestamp(), - ExpectedTimestamp2 = default_time_format(Time2,true), - String2 = format(info,{"~p",[term]},#{time=>Time2},#{utc=>true}), - ct:log(String2), - " info: term\n" = string:prefix(String2,ExpectedTimestamp2), - - application:set_env(kernel,logger_utc,true), - Time3 = timestamp(), - ExpectedTimestamp3 = default_time_format(Time3,true), - String3 = format(info,{"~p",[term]},#{time=>Time3},#{}), - ct:log(String3), - " info: term\n" = string:prefix(String3,ExpectedTimestamp3), + Time = timestamp(), + Meta = #{time=>Time}, + FC = #{template=>[time]}, + Msg = {string,""}, + ExpectedLocal = default_time_format(Time,false), + ExpectedUtc = default_time_format(Time,true), + + %% default - local time + ExpectedLocal = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% stdlib utc_log works when time_offset parameter is not set + application:set_env(stdlib,utc_log,true), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedLocal = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,true), + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + + %% time_designator config parameter to formatter + ExpectedLocalS = default_time_format(Time,false,$\s), + ExpectedUtcS = default_time_format(Time,true,$\s), + + ExpectedLocalS = format(info,Msg,Meta,FC#{time_offset=>"", + time_designator=>$\s}), + ExpectedUtcS = format(info,Msg,Meta,FC#{time_offset=>"Z", + time_designator=>$\s}), ok. format_time(cleanup,_Config) -> - application:unset_env(kernel,logger_utc), + application:unset_env(sasl,utc_log), + application:unset_env(stdlib,utc_log), ok. level_or_msg_in_meta(_Config) -> @@ -520,22 +543,17 @@ format(Log,Config) -> default_time_format(Timestamp) -> default_time_format(Timestamp,false). -default_time_format(Timestamp0,Utc) when is_integer(Timestamp0) -> +default_time_format(Timestamp,Utc) -> + default_time_format(Timestamp,Utc,$T). + +default_time_format(Timestamp0,Utc,Sep) -> Timestamp=Timestamp0+erlang:time_offset(microsecond), - %% calendar:system_time_to_rfc3339(Time,[{unit,microsecond}]). - Micro = Timestamp rem 1000000, - Sec = Timestamp div 1000000, - UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - if Utc -> UniversalTime; - true -> erlang:universaltime_to_localtime(UniversalTime) - end, - default_time_format(Date,Time,Micro). - -default_time_format({Y,M,D},{H,Min,S},Micro) -> - lists:flatten( - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro])). + Offset = if Utc -> "Z"; + true -> "" + end, + calendar:system_time_to_rfc3339(Timestamp,[{unit,microsecond}, + {time_designator,Sep}, + {offset,Offset}]). integer(Str) -> is_integer(list_to_integer(Str)). diff --git a/lib/kernel/test/logger_simple_SUITE.erl b/lib/kernel/test/logger_simple_SUITE.erl index 5d8d32492d..0d505b14f5 100644 --- a/lib/kernel/test/logger_simple_SUITE.erl +++ b/lib/kernel/test/logger_simple_SUITE.erl @@ -25,6 +25,8 @@ -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). +-import(logger_test_lib, [setup/2, log/3, sync_and_read/3]). + -define(check_no_log,[] = test_server:messages_get()). -define(check(Expected), receive {log,Expected} -> @@ -42,15 +44,15 @@ -define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks, [logger_test_lib]}]. init_per_suite(Config) -> #{handlers:=Hs0} = logger:i(), Hs = lists:keydelete(cth_log_redirect,1,Hs0), [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], Env = [{App,Key,application:get_env(App,Key)} || - {App,Key} <- [{kernel,logger_dest}, - {kernel,logger_level}]], + {App,Key} <- [{kernel,logger_level}]], [{env,Env},{logger,Hs}|Config]. end_per_suite(Config) -> @@ -79,7 +81,7 @@ groups() -> all() -> [start_stop, - get_buffer, + replace_default, replace_file, replace_disk_log ]. @@ -100,99 +102,46 @@ start_stop(_Config) -> start_stop(cleanup,_Config) -> logger:remove_handler(logger_simple). -get_buffer(_Config) -> - %% Start simple without buffer - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log}), - logger:emergency(?str), - logger:alert(?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - {ok,[]} = logger_simple:get_buffer(), % no buffer - ok = logger:remove_handler(logger_simple), +%% This testcase just tests that it does not crash, the default handler prints +%% to stdout which we cannot read from in a detached slave. +replace_default(Config) -> - %% Start with buffer - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(M3=?map_rep), - logger:info(M4=?keyval_rep), - logger:info(M41=?keyval_rep++[not_key_val]), - error_logger:error_report(some_type,M5=?map_rep), - error_logger:warning_report("some_type",M6=?map_rep), - logger:critical(M7=?str,[A7=?keyval_rep]), - logger:notice(M8=["fake",string,"line:",?LINE]), - {ok,Buffered1} = logger_simple:get_buffer(), - [#{level:=emergency,msg:={string,M1}}, - #{level:=alert,msg:={M2,[]}}, - #{level:=error,msg:={report,M3}}, - #{level:=info,msg:={report,M4}}, - #{level:=info,msg:={report,M41}}, - #{level:=error,msg:={report,#{label:={error_logger,error_report}, - report:=M5}}}, - #{level:=warning,msg:={report,#{label:={error_logger,warning_report}, - report:=M6}}}, - #{level:=critical,msg:={M7,[A7]}}, - #{level:=notice,msg:={string,M8}}] = Buffered1, - - %% Keep logging - should not buffer any more - logger:emergency(?str), - logger:alert(?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - {ok,[]} = logger_simple:get_buffer(), - ok = logger:remove_handler(logger_simple), + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + rpc:call(Node, error_logger, error_report, [some_type,M5=?map_rep]), + rpc:call(Node, error_logger, warning_report, ["some_type",M6=?map_rep]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + Env = rpc:call(Node, application, get_env, [kernel, logger, []]), + ok = rpc:call(Node, logger, add_handlers, [Env]), - %% Fill buffer and drop - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M9=?str), - M10=?str, - [logger:info(M10) || _ <- lists:seq(1,8)], - logger:error(M11=?str), - logger:error(?str), - logger:error(?str), - {ok,Buffered3} = logger_simple:get_buffer(), - 11 = length(Buffered3), - [#{level:=emergency,msg:={string,M9}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=error,msg:={string,M11}}, - #{level:=info,msg:={"Simple handler buffer full, dropped ~w messages",[2]}}] - = Buffered3, ok. -get_buffer(cleanup,_Config) -> - logger:remove_handler(logger_simple). replace_file(Config) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - undefined = whereis(?STANDARD_HANDLER), - PrivDir = ?config(priv_dir,Config), - File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)++".log"), - - application:set_env(kernel,logger_dest,{file,File}), - application:set_env(kernel,logger_level,info), - - ok = logger:setup_standard_handler(), - true = is_pid(whereis(?STANDARD_HANDLER)), - ok = logger_std_h:filesync(?STANDARD_HANDLER), - {ok,Bin} = file:read_file(File), - Lines = [unicode:characters_to_list(L) || + + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + File = filename:join(proplists:get_value(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + + ok = rpc:call(Node, logger, add_handlers, + [[{handler, default, logger_std_h, + #{ logger_std_h => #{ type => {file, File} }}}]]), + + {ok,Bin} = sync_and_read(Node, file, File), + Lines = [unicode:characters_to_list(L) || L <- binary:split(Bin,<<"\n">>,[global,trim])], ["=EMERGENCY REPORT===="++_, M1, @@ -203,32 +152,38 @@ replace_file(Config) -> _, "=INFO REPORT===="++_, _, - _] = Lines, + _, + "=INFO REPORT===="++_, + _, + _, + _, + "=CRITICAL REPORT===="++_, + _, + _, + "=NOTICE REPORT===="++_, + _ + ] = Lines, ok. -replace_file(cleanup,_Config) -> - logger:remove_handler(?STANDARD_HANDLER), - logger:remove_handler(logger_simple). - + replace_disk_log(Config) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - undefined = whereis(?STANDARD_HANDLER), - PrivDir = ?config(priv_dir,Config), - File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)), - - application:set_env(kernel,logger_dest,{disk_log,File}), - application:set_env(kernel,logger_level,info), - - ok = logger:setup_standard_handler(), - true = is_pid(whereis(?STANDARD_HANDLER)), - ok = logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), - {ok,Bin} = file:read_file(File++".1"), - Lines = [unicode:characters_to_list(L) || + + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + File = filename:join(proplists:get_value(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + + ok = rpc:call(Node, logger, add_handlers, + [[{handler, default, logger_disk_log_h, + #{ disk_log_opts => #{ file => File }}}]]), + {ok,Bin} = sync_and_read(Node, disk_log, File), + Lines = [unicode:characters_to_list(L) || L <- binary:split(Bin,<<"\n">>,[global,trim])], ["=EMERGENCY REPORT===="++_, M1, @@ -239,9 +194,15 @@ replace_disk_log(Config) -> _, "=INFO REPORT===="++_, _, - _|_] = Lines, % the tail might be an info report about opening the disk log + _, + "=INFO REPORT===="++_, + _, + _, + _, + "=CRITICAL REPORT===="++_, + _, + _, + "=NOTICE REPORT===="++_, + _ + ] = Lines, ok. -replace_disk_log(cleanup,_Config) -> - logger:remove_handler(?STANDARD_HANDLER), - logger:remove_handler(logger_simple). - diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 34c3167960..fc59d393e0 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -50,11 +50,12 @@ end). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> timer:start(), % to avoid progress report - {ok,{?STANDARD_HANDLER,#{formatter:=OrigFormatter}}} = + {ok,{logger_std_h,#{formatter:=OrigFormatter}}} = logger:get_handler_config(?STANDARD_HANDLER), [{formatter,OrigFormatter}|Config]. @@ -241,7 +242,8 @@ formatter_fail(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), Pid = whereis(?MODULE), true = is_pid(Pid), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC1} = logger:i(), + H = [Id || {Id,_,_} <- HC1], true = lists:member(?MODULE,H), %% Formatter is added automatically @@ -270,7 +272,8 @@ formatter_fail(Config) -> %% Check that handler is still alive and was never dead Pid = whereis(?MODULE), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC2} = logger:i(), + H = [Id || {Id,_,_} <- HC2], ok. @@ -322,29 +325,32 @@ config_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). crash_std_h_to_file(Config) -> - crash_std_h(Config,?FUNCTION_NAME,logger_dest,file). + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), + crash_std_h(Config,?FUNCTION_NAME, + [{handler,default,logger_std_h, + #{ logger_std_h => #{ type => {file, Log} }}}], + file, Log). crash_std_h_to_file(cleanup,_Config) -> crash_std_h(cleanup). crash_std_h_to_disk_log(Config) -> - crash_std_h(Config,?FUNCTION_NAME,logger_dest,disk_log). + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), + crash_std_h(Config,?FUNCTION_NAME, + [{handler,default,logger_disk_log_h, + #{ disk_log_opts => #{ file => Log }}}], + disk_log,Log). crash_std_h_to_disk_log(cleanup,_Config) -> crash_std_h(cleanup). -crash_std_h(Config,Func,Var,Type) -> +crash_std_h(Config,Func,Var,Type,Log) -> Dir = ?config(priv_dir,Config), - File = lists:concat([?MODULE,"_",Func,".log"]), - Log = filename:join(Dir,File), + SysConfig = filename:join(Dir,lists:concat([?MODULE,"_",Func,".config"])), + ok = file:write_file(SysConfig, io_lib:format("[{kernel,[{logger,~p}]}].",[Var])), Pa = filename:dirname(code:which(?MODULE)), - TypeAndLog = - case os:type() of - {win32,_} -> - lists:concat([" {",Type,",\\\"",Log,"\\\"}"]); - _ -> - lists:concat([" \'{",Type,",\"",Log,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",Var,TypeAndLog," -pa ",Pa]), Name = lists:concat([?MODULE,"_",Func]), + Args = lists:concat([" -config ",filename:rootname(SysConfig)," -pa ",Pa]), ct:pal("Starting ~p with ~tp", [Name,Args]), %% Start a node which prints kernel logs to the destination specified by Type {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), @@ -585,7 +591,7 @@ write_failure(Config) -> Dir = ?config(priv_dir, Config), File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), Log = filename:join(Dir, File), - Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + Node = start_std_h_on_new_node(Config, Log), false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), @@ -622,7 +628,7 @@ sync_failure(Config) -> Dir = ?config(priv_dir, Config), File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), Log = filename:join(Dir, File), - Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + Node = start_std_h_on_new_node(Config, Log), false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), @@ -658,21 +664,12 @@ sync_failure(cleanup, _Config) -> Nodes = nodes(), [test_server:stop_node(Node) || Node <- Nodes]. -start_std_h_on_new_node(_Config, Func, Log) -> - Pa = filename:dirname(code:which(?MODULE)), - Dest = - case os:type() of - {win32,_} -> - lists:concat([" {file,\\\"",Log,"\\\"}"]); - _ -> - lists:concat([" \'{file,\"",Log,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), - Name = lists:concat([?MODULE,"_",Func]), - ct:pal("Starting ~s with ~tp", [Name,Args]), - {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), - true = is_pid(Pid), +start_std_h_on_new_node(Config, Log) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger,[{handler,default,logger_std_h, + #{ logger_std_h => #{ type => {file,Log}}}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. diff --git a/lib/kernel/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl new file mode 100644 index 0000000000..4ac05e6480 --- /dev/null +++ b/lib/kernel/test/logger_test_lib.erl @@ -0,0 +1,82 @@ +% +%% %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_test_lib). + +-include_lib("kernel/src/logger_internal.hrl"). + +-export([setup/2, log/3, sync_and_read/3]). + +-export([init/2, + pre_init_per_suite/3, pre_init_per_testcase/4, + post_end_per_testcase/5, post_end_per_suite/3]). + +setup(Config,Vars) -> + FuncStr = lists:concat([proplists:get_value(suite, Config), "_", + proplists:get_value(tc, Config)]), + ConfigFileName = filename:join(proplists:get_value(priv_dir, Config), FuncStr), + file:write_file(ConfigFileName ++ ".config", io_lib:format("[{kernel, ~p}].",[Vars])), + case test_server:start_node(proplists:get_value(tc, Config), slave, + [{args, ["-pa ",filename:dirname(code:which(?MODULE)), + " -boot start_sasl -kernel start_timer true " + "-config ",ConfigFileName]}]) of + {ok, Node} -> + L = rpc:call(Node, logger, i, []), + ct:log("~p",[L]), + {ok, L, Node}; + {error, Reason} -> + ct:log("Failed to start node: ~p",[Reason]), + error + end. + +log(Node, F, A) -> + log(Node, logger, F, A). +log(Node, M, F, A) -> + MD = #{ gl => rpc:call(Node, erlang, whereis, [logger]) }, + rpc:call(Node, M, F, A ++ [MD]). + +sync_and_read(Node,disk_log,Log) -> + rpc:call(Node,logger_disk_log_h,disk_log_sync,[?STANDARD_HANDLER]), + file:read_file(Log ++ ".1"); +sync_and_read(Node, file,Log) -> + ok = rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), + file:read_file(Log). + + +init(_, _) -> + {ok, []}. + +pre_init_per_suite(_Suite, Config, State) -> + {[{nodes, nodes()} | Config], State}. + +pre_init_per_testcase(Suite, TC, Config, State) -> + cleanup(Config), + {[{suite, Suite}, {tc, TC} | Config], State}. + +post_end_per_testcase(_, _TC, Config, Res, State) -> + cleanup(Config), + {Res, State}. + +post_end_per_suite(_, Config, State) -> + cleanup(Config), + {Config, State}. + +cleanup(Config) -> + [test_server:stop_node(N) || N <- nodes(), + not lists:member(N, proplists:get_value(nodes, Config))]. |