diff options
Diffstat (limited to 'lib/kernel/test')
34 files changed, 1437 insertions, 1571 deletions
diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile index 2ad1e3107c..4a86265a4a 100644 --- a/lib/kernel/test/Makefile +++ b/lib/kernel/test/Makefile @@ -1,7 +1,7 @@ # # %CopyrightBegin% # -# Copyright Ericsson AB 1997-2016. All Rights Reserved. +# Copyright Ericsson AB 1997-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. @@ -71,7 +71,6 @@ MODULES= \ init_SUITE \ kernel_config_SUITE \ logger_SUITE \ - logger_bench_SUITE \ logger_disk_log_h_SUITE \ logger_env_var_SUITE \ logger_filters_SUITE \ diff --git a/lib/kernel/test/application_SUITE.erl b/lib/kernel/test/application_SUITE.erl index 988f26280f..5c35b82207 100644 --- a/lib/kernel/test/application_SUITE.erl +++ b/lib/kernel/test/application_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. @@ -37,7 +37,8 @@ -export([config_change/1, persistent_env/1, distr_changed_tc1/1, distr_changed_tc2/1, ensure_started/1, ensure_all_started/1, - shutdown_func/1, do_shutdown/1, shutdown_timeout/1, shutdown_deadlock/1]). + shutdown_func/1, do_shutdown/1, shutdown_timeout/1, shutdown_deadlock/1, + config_relative_paths/1]). -define(TESTCASE, testcase_name). -define(testcase, proplists:get_value(?TESTCASE, Config)). @@ -55,7 +56,7 @@ all() -> script_start, nodedown_start, permit_false_start_local, permit_false_start_dist, get_key, get_env, ensure_all_started, {group, distr_changed}, config_change, shutdown_func, shutdown_timeout, - shutdown_deadlock, + shutdown_deadlock, config_relative_paths, persistent_env]. groups() -> @@ -2075,6 +2076,42 @@ shutdown_deadlock(Config) when is_list(Config) -> %%----------------------------------------------------------------- +%% Relative paths in sys.config +%%----------------------------------------------------------------- +config_relative_paths(Config) -> + Dir = ?config(priv_dir,Config), + SubDir = filename:join(Dir,"subdir"), + Sys = filename:join(SubDir,"sys.config"), + ok = filelib:ensure_dir(Sys), + ok = file:write_file(Sys,"[\"../up.config\",\"current\"].\n"), + + Up = filename:join(Dir,"up.config"), + ok = file:write_file(Up,"[{app1,[{key1,value}]}].\n"), + + {ok,Cwd} = file:get_cwd(), + Current1 = filename:join(Cwd,"current.config"), + ok = file:write_file(Current1,"[{app1,[{key2,value1}]}].\n"), + + N1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + {ok,Node1} = start_node(N1,filename:rootname(Sys)), + ok = rpc:call(Node1, application, load, [app1()]), + {ok, value} = rpc:call(Node1, application, get_env,[app1,key1]), + {ok, value1} = rpc:call(Node1, application, get_env,[app1,key2]), + + Current2 = filename:join(SubDir,"current.config"), + ok = file:write_file(Current2,"[{app1,[{key2,value2}]}].\n"), + + N2 = list_to_atom(lists:concat([?FUNCTION_NAME,"_2"])), + {ok, Node2} = start_node(N2,filename:rootname(Sys)), + ok = rpc:call(Node2, application, load, [app1()]), + {ok, value} = rpc:call(Node2, application, get_env,[app1,key1]), + {ok, value2} = rpc:call(Node2, application, get_env,[app1,key2]), + + stop_node_nice([Node1,Node2]), + + ok. + +%%----------------------------------------------------------------- %% Utility functions %%----------------------------------------------------------------- app0() -> diff --git a/lib/kernel/test/code_SUITE.erl b/lib/kernel/test/code_SUITE.erl index 902196def2..1314316c13 100644 --- a/lib/kernel/test/code_SUITE.erl +++ b/lib/kernel/test/code_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. diff --git a/lib/kernel/test/erl_prim_loader_SUITE.erl b/lib/kernel/test/erl_prim_loader_SUITE.erl index 3502a4ad08..16a127aa3e 100644 --- a/lib/kernel/test/erl_prim_loader_SUITE.erl +++ b/lib/kernel/test/erl_prim_loader_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2016. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. diff --git a/lib/kernel/test/error_logger_SUITE.erl b/lib/kernel/test/error_logger_SUITE.erl index 6c4526d0cf..eab72e58a7 100644 --- a/lib/kernel/test/error_logger_SUITE.erl +++ b/lib/kernel/test/error_logger_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. @@ -33,7 +33,7 @@ off_heap/1, error_report/1, info_report/1, error/1, info/1, emulator/1, via_logger_process/1, other_node/1, - tty/1, logfile/1, add/1, delete/1]). + tty/1, logfile/1, add/1, delete/1, format_depth/1]). -export([generate_error/2]). @@ -48,7 +48,8 @@ suite() -> all() -> [off_heap, error_report, info_report, error, info, emulator, - via_logger_process, other_node, tty, logfile, add, delete]. + via_logger_process, other_node, tty, logfile, add, delete, + format_depth]. groups() -> []. @@ -309,6 +310,21 @@ delete(Config) when is_list(Config) -> ok. %%----------------------------------------------------------------- + +format_depth(_Config) -> + ok = application:set_env(kernel,error_logger_format_depth,30), + 30 = error_logger:get_format_depth(), + ok = application:set_env(kernel,error_logger_format_depth,3), + 10 = error_logger:get_format_depth(), + ok = application:set_env(kernel,error_logger_format_depth,11), + 11 = error_logger:get_format_depth(), + ok = application:set_env(kernel,error_logger_format_depth,unlimited), + unlimited = error_logger:get_format_depth(), + ok = application:unset_env(kernel,error_logger_format_depth), + unlimited = error_logger:get_format_depth(), + ok. + +%%----------------------------------------------------------------- %% Check that the report has been received. %%----------------------------------------------------------------- reported(Tag, Type, Report) -> diff --git a/lib/kernel/test/error_logger_warn_SUITE.erl b/lib/kernel/test/error_logger_warn_SUITE.erl index ef55a2d339..8f1eb2ba0a 100644 --- a/lib/kernel/test/error_logger_warn_SUITE.erl +++ b/lib/kernel/test/error_logger_warn_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2003-2016. All Rights Reserved. +%% Copyright Ericsson AB 2003-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. diff --git a/lib/kernel/test/file_SUITE.erl b/lib/kernel/test/file_SUITE.erl index ff93f25e25..23913ac56a 100644 --- a/lib/kernel/test/file_SUITE.erl +++ b/lib/kernel/test/file_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. diff --git a/lib/kernel/test/gen_sctp_SUITE.erl b/lib/kernel/test/gen_sctp_SUITE.erl index 9dde00652c..a0ae792ba9 100644 --- a/lib/kernel/test/gen_sctp_SUITE.erl +++ b/lib/kernel/test/gen_sctp_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2007-2016. All Rights Reserved. +%% Copyright Ericsson AB 2007-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. diff --git a/lib/kernel/test/gen_tcp_api_SUITE.erl b/lib/kernel/test/gen_tcp_api_SUITE.erl index 0fe44e8a88..1be016444f 100644 --- a/lib/kernel/test/gen_tcp_api_SUITE.erl +++ b/lib/kernel/test/gen_tcp_api_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2017. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/gen_tcp_misc_SUITE.erl b/lib/kernel/test/gen_tcp_misc_SUITE.erl index e47023d201..950f5bea6f 100644 --- a/lib/kernel/test/gen_tcp_misc_SUITE.erl +++ b/lib/kernel/test/gen_tcp_misc_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2016. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/gen_udp_SUITE.erl b/lib/kernel/test/gen_udp_SUITE.erl index 6a50239c2a..b39399b18a 100644 --- a/lib/kernel/test/gen_udp_SUITE.erl +++ b/lib/kernel/test/gen_udp_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2017. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/heart_SUITE.erl b/lib/kernel/test/heart_SUITE.erl index e95635b800..f5ca6d0e1d 100644 --- a/lib/kernel/test/heart_SUITE.erl +++ b/lib/kernel/test/heart_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2016. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. diff --git a/lib/kernel/test/inet_res_SUITE.erl b/lib/kernel/test/inet_res_SUITE.erl index 2a5b8d0044..df6e48abae 100644 --- a/lib/kernel/test/inet_res_SUITE.erl +++ b/lib/kernel/test/inet_res_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2009-2016. All Rights Reserved. +%% Copyright Ericsson AB 2009-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. diff --git a/lib/kernel/test/kernel.spec b/lib/kernel/test/kernel.spec index 86d2155828..62afc9f97b 100644 --- a/lib/kernel/test/kernel.spec +++ b/lib/kernel/test/kernel.spec @@ -2,4 +2,3 @@ {config, "../test_server/ts.unix.config"}. {suites,"../kernel_test", all}. -{skip_suites,"../kernel_test",[logger_bench_SUITE],"Not ready"}. diff --git a/lib/kernel/test/kernel_SUITE.erl b/lib/kernel/test/kernel_SUITE.erl index 7898988dbe..3e5ed855b5 100644 --- a/lib/kernel/test/kernel_SUITE.erl +++ b/lib/kernel/test/kernel_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2016. All Rights Reserved. +%% Copyright Ericsson AB 1997-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. diff --git a/lib/kernel/test/kernel_config_SUITE.erl b/lib/kernel/test/kernel_config_SUITE.erl index a21020ff97..9207025a2c 100644 --- a/lib/kernel/test/kernel_config_SUITE.erl +++ b/lib/kernel/test/kernel_config_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2016. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index f7ec59a7b7..b367b4dd54 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -50,7 +50,7 @@ init_per_suite(Config) -> end_per_suite(Config) -> case ?config(default_handler,Config) of - {HMod,HConfig} -> + #{module:=HMod} = HConfig -> ok = logger:add_handler(?STANDARD_HANDLER,HMod,HConfig); _ -> ok @@ -63,8 +63,8 @@ end_per_group(_Group, _Config) -> ok. init_per_testcase(_TestCase, Config) -> - {ok,LC} = logger:get_logger_config(), - [{logger_config,LC}|Config]. + PC = logger:get_primary_config(), + [{logger_config,PC}|Config]. end_per_testcase(Case, Config) -> try apply(?MODULE,Case,[cleanup,Config]) @@ -82,11 +82,12 @@ all() -> add_remove_filter, change_config, set_formatter, + log_no_levels, log_all_levels_api, macros, set_level, - set_level_module, - cache_level_module, + set_module_level, + cache_module_level, format_report, filter_failed, handler_failed, @@ -105,29 +106,29 @@ start_stop(_Config) -> add_remove_handler(_Config) -> register(callback_receiver,self()), - #{handlers:=Hs0} = logger:i(), + Hs0 = logger:get_handler_config(), {error,{not_found,h1}} = logger:get_handler_config(h1), ok = logger:add_handler(h1,?MODULE,#{}), [add] = test_server:messages_get(), - #{handlers:=Hs} = logger:i(), - {value,_,Hs0} = lists:keytake(h1,1,Hs), - {ok,{?MODULE,#{level:=info,filters:=[],filter_default:=log}}} = % defaults + Hs = logger:get_handler_config(), + Hs0 = lists:filter(fun(#{id:=h1}) -> false; (_) -> true end, Hs), + {ok,#{module:=?MODULE,level:=all,filters:=[],filter_default:=log}} = %defaults logger:get_handler_config(h1), ok = logger:set_handler_config(h1,filter_default,stop), [changing_config] = test_server:messages_get(), - ?LOG_INFO("hello",[]), + ?LOG_NOTICE("hello",[]), ok = check_no_log(), ok = logger:set_handler_config(h1,filter_default,log), [changing_config] = test_server:messages_get(), - {ok,{?MODULE,#{filter_default:=log}}} = logger:get_handler_config(h1), - ?LOG_INFO("hello",[]), - ok = check_logged(info,"hello",[],?MY_LOC(1)), + {ok,#{filter_default:=log}} = logger:get_handler_config(h1), + ?LOG_NOTICE("hello",[]), + ok = check_logged(notice,"hello",[],?MY_LOC(1)), ok = logger:remove_handler(h1), [remove] = test_server:messages_get(), - #{handlers:=Hs0} = logger:i(), + Hs0 = logger:get_handler_config(), {error,{not_found,h1}} = logger:get_handler_config(h1), {error,{not_found,h1}} = logger:remove_handler(h1), - logger:info("hello",[]), + logger:notice("hello",[]), ok = check_no_log(), ok. @@ -136,13 +137,13 @@ add_remove_handler(cleanup,_Config) -> ok. multiple_handlers(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), ok = logger:add_handler(h2,?MODULE,#{level=>error,filter_default=>log}), ?LOG_ERROR("hello",[]), ok = check_logged(error,"hello",[],?MY_LOC(1)), ok = check_logged(error,"hello",[],?MY_LOC(2)), - ?LOG_INFO("hello",[]), - ok = check_logged(info,"hello",[],?MY_LOC(1)), + ?LOG_NOTICE("hello",[]), + ok = check_logged(notice,"hello",[],?MY_LOC(1)), ok = check_no_log(), ok. @@ -152,18 +153,18 @@ multiple_handlers(cleanup,_Config) -> ok. add_remove_filter(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), LF = {fun(Log,_) -> Log#{level=>error} end, []}, - ok = logger:add_logger_filter(lf,LF), - {error,{already_exist,lf}} = logger:add_logger_filter(lf,LF), - {error,{already_exist,lf}} = logger:add_logger_filter(lf,{fun(Log,_) -> - Log - end, []}), - ?LOG_INFO("hello",[]), + ok = logger:add_primary_filter(lf,LF), + {error,{already_exist,lf}} = logger:add_primary_filter(lf,LF), + {error,{already_exist,lf}} = logger:add_primary_filter(lf,{fun(Log,_) -> + Log + end, []}), + ?LOG_NOTICE("hello",[]), ok = check_logged(error,"hello",[],?MY_LOC(1)), ok = check_no_log(), - ok = logger:add_handler(h2,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h2,?MODULE,#{level=>notice,filter_default=>log}), HF = {fun(#{level:=error}=Log,_) -> Log#{level=>mylevel}; (_,_) -> @@ -175,16 +176,16 @@ add_remove_filter(_Config) -> {error,{already_exist,hf}} = logger:add_handler_filter(h1,hf,{fun(Log,_) -> Log end, []}), - ?LOG_INFO("hello",[]), + ?LOG_NOTICE("hello",[]), ok = check_logged(mylevel,"hello",[],?MY_LOC(1)), ok = check_logged(error,"hello",[],?MY_LOC(2)), - ok = logger:remove_logger_filter(lf), - {error,{not_found,lf}} = logger:remove_logger_filter(lf), + ok = logger:remove_primary_filter(lf), + {error,{not_found,lf}} = logger:remove_primary_filter(lf), - ?LOG_INFO("hello",[]), - ok = check_logged(info,"hello",[],?MY_LOC(1)), - ok = check_logged(info,"hello",[],?MY_LOC(2)), + ?LOG_NOTICE("hello",[]), + ok = check_logged(notice,"hello",[],?MY_LOC(1)), + ok = check_logged(notice,"hello",[],?MY_LOC(2)), ?LOG_ERROR("hello",[]), ok = check_logged(mylevel,"hello",[],?MY_LOC(1)), @@ -192,9 +193,9 @@ add_remove_filter(_Config) -> ok = logger:remove_handler_filter(h1,hf), {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf), - ?LOG_INFO("hello",[]), - ok = check_logged(info,"hello",[],?MY_LOC(1)), - ok = check_logged(info,"hello",[],?MY_LOC(2)), + ?LOG_NOTICE("hello",[]), + ok = check_logged(notice,"hello",[],?MY_LOC(1)), + ok = check_logged(notice,"hello",[],?MY_LOC(2)), ?LOG_ERROR("hello",[]), ok = check_logged(error,"hello",[],?MY_LOC(1)), @@ -202,20 +203,20 @@ add_remove_filter(_Config) -> ok. add_remove_filter(cleanup,_Config) -> - logger:remove_logger_filter(lf), + logger:remove_primary_filter(lf), logger:remove_handler(h1), logger:remove_handler(h2), ok. change_config(_Config) -> %% Overwrite handler config - check that defaults are added - ok = logger:add_handler(h1,?MODULE,#{level=>debug,custom=>custom}), - {ok,{?MODULE,#{level:=debug,filter_default:=log,custom:=custom}}} = + ok = logger:add_handler(h1,?MODULE,#{level=>notice,custom=>custom}), + {ok,#{module:=?MODULE,level:=notice,filter_default:=log,custom:=custom}} = logger:get_handler_config(h1), register(callback_receiver,self()), ok = logger:set_handler_config(h1,#{filter_default=>stop}), [changing_config] = test_server:messages_get(), - {ok,{?MODULE,#{level:=info,filter_default:=stop}=C2}} = + {ok,#{module:=?MODULE,level:=all,filter_default:=stop}=C2} = logger:get_handler_config(h1), false = maps:is_key(custom,C2), {error,fail} = logger:set_handler_config(h1,#{conf_call=>fun() -> {error,fail} end}), @@ -225,60 +226,60 @@ change_config(_Config) -> ok = logger:set_handler_config( h1,#{conf_call=>fun() -> logger:set_module_level(?MODULE,debug) end}), - {ok,{?MODULE,C2}} = logger:get_handler_config(h1), + {ok,C2} = logger:get_handler_config(h1), %% 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), + {ok,#{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), + {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 = logger:set_logger_config(#{filter_default=>stop}), - {ok,#{level:=info,filters:=[],filter_default:=stop}=LC1} = - logger:get_logger_config(), - 3 = maps:size(LC1), + %% Change primary config: Single key + PConfig0 = logger:get_primary_config(), + ok = logger:set_primary_config(level,warning), + PConfig1 = logger:get_primary_config(), + PConfig1 = PConfig0#{level:=warning}, + + %% Change primary config: Map + ok = logger:update_primary_config(#{level=>error}), + PConfig2 = logger:get_primary_config(), + PConfig2 = PConfig1#{level:=error}, + + %% Overwrite primary config - check that defaults are added + ok = logger:set_primary_config(#{filter_default=>stop}), + #{level:=notice,filters:=[],filter_default:=stop}=PC1 = + logger:get_primary_config(), + 3 = maps:size(PC1), %% 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), + MS = [{{{?HANDLER_KEY,'$1'},'_','_','_'},[],['$1']}], + HIds1 = lists:sort(ets:select(?LOGGER_TABLE,MS)), % dirty, internal data + HIds2 = lists:sort(logger:get_handler_ids()), + HIds1 = HIds2, %% Cleanup - ok = logger:set_logger_config(LConfig0), + ok = logger:set_primary_config(PConfig0), [] = test_server:messages_get(), ok. change_config(cleanup,Config) -> logger:remove_handler(h1), - LC = ?config(logger_config,Config), - logger:set_logger_config(LC), + PC = ?config(logger_config,Config), + logger:set_primary_config(PC), ok. set_formatter(_Config) -> {error,{not_found,h1}}=logger:set_handler_config(h1,formatter,{?MODULE,[]}), - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), ok = logger:set_handler_config(h1,formatter,{?MODULE,[]}), - logger:info("hello",[]), + logger:notice("hello",[]), receive {_Log,#{formatter:={?MODULE,[]}}} -> ok @@ -291,9 +292,50 @@ set_formatter(cleanup,_Config) -> logger:remove_handler(h1), ok. +log_no_levels(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}), + logger:notice(M1=?map_rep), + ok = check_logged(notice,M1,#{}), + + Levels = [emergency,alert,critical,error,warning,notice,info,debug], + ok = logger:set_primary_config(level,none), + [logger:Level(#{Level=>rep}) || Level <- Levels], + ok = check_no_log(), + + ok = logger:set_primary_config(level,all), + M2 = ?map_rep, + ?LOG_NOTICE(M2), + ok = check_logged(notice,M2,#{}), + + ok = logger:set_module_level(?MODULE,none), + ?LOG_EMERGENCY(?map_rep), + ?LOG_ALERT(?map_rep), + ?LOG_CRITICAL(?map_rep), + ?LOG_ERROR(?map_rep), + ?LOG_WARNING(?map_rep), + ?LOG_NOTICE(?map_rep), + ?LOG_INFO(?map_rep), + ?LOG_DEBUG(?map_rep), + ok = check_no_log(), + + ok = logger:unset_module_level(?MODULE), + logger:notice(M3=?map_rep), + ok = check_logged(notice,M3,#{}), + + ok = logger:set_handler_config(h1,level,none), + [logger:Level(#{Level=>rep}) || Level <- Levels], + ok = check_no_log(), + + ok. +log_no_levels(cleanup,_Config) -> + logger:remove_handler(h1), + logger:set_primary_config(level,notice), + logger:unset_module_level(?MODULE), + ok. + log_all_levels_api(_Config) -> - ok = logger:set_logger_config(level,debug), - ok = logger:add_handler(h1,?MODULE,#{level=>debug,filter_default=>log}), + ok = logger:set_primary_config(level,all), + ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}), test_api(emergency), test_api(alert), test_api(critical), @@ -307,12 +349,11 @@ log_all_levels_api(_Config) -> log_all_levels_api(cleanup,_Config) -> logger:remove_handler(h1), - logger:set_logger_config(level,info), + logger:set_primary_config(level,notice), ok. macros(_Config) -> - ok = logger:set_module_level(?MODULE,debug), - ok = logger:add_handler(h1,?MODULE,#{level=>debug,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}), test_macros(emergency), ok. @@ -322,56 +363,77 @@ macros(cleanup,_Config) -> ok. set_level(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>debug,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}), logger:debug(?map_rep), ok = check_no_log(), - logger:info(M1=?map_rep), - ok = check_logged(info,M1,#{}), - ok = logger:set_logger_config(level,debug), + logger:notice(M1=?map_rep), + ok = check_logged(notice,M1,#{}), + ok = logger:set_primary_config(level,debug), logger:debug(M2=?map_rep), ok = check_logged(debug,M2,#{}), ok. set_level(cleanup,_Config) -> logger:remove_handler(h1), - logger:set_logger_config(level,info), + logger:set_primary_config(level,notice), ok. -set_level_module(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), +set_module_level(_Config) -> + [] = logger:get_module_level([?MODULE,other]), + [] = logger:get_module_level(?MODULE), + [] = logger:get_module_level(), + + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), {error,{invalid_level,bad}} = logger:set_module_level(?MODULE,bad), - {error,{not_a_module,{bad}}} = logger:set_module_level({bad},warning), + {error,{not_a_list_of_modules,{bad}}} = + logger:set_module_level({bad},warning), ok = logger:set_module_level(?MODULE,warning), - logger:info(?map_rep,?MY_LOC(0)), + [{?MODULE,warning}] = logger:get_module_level([?MODULE,other]), + [{?MODULE,warning}] = logger:get_module_level(?MODULE), + [{?MODULE,warning}] = logger:get_module_level(), + logger:notice(?map_rep,?MY_LOC(0)), ok = check_no_log(), logger:warning(M1=?map_rep,?MY_LOC(0)), ok = check_logged(warning,M1,?MY_LOC(1)), - ok = logger:set_module_level(?MODULE,info), - logger:info(M2=?map_rep,?MY_LOC(0)), - ok = check_logged(info,M2,?MY_LOC(1)), - - {error,{not_a_module,{bad}}} = logger:unset_module_level({bad}), + ok = logger:set_module_level(?MODULE,notice), + [{?MODULE,notice}] = logger:get_module_level([?MODULE,other]), + [{?MODULE,notice}] = logger:get_module_level(?MODULE), + [{?MODULE,notice}] = logger:get_module_level(), + logger:notice(M2=?map_rep,?MY_LOC(0)), + ok = check_logged(notice,M2,?MY_LOC(1)), + + {error,{not_a_list_of_modules,{bad}}} = logger:unset_module_level({bad}), ok = logger:unset_module_level(?MODULE), + [] = logger:get_module_level([?MODULE,other]), + [] = logger:get_module_level(?MODULE), + [] = logger:get_module_level(), + + ok = logger:set_module_level([m1,m2,m3],notice), + [{m1,notice},{m2,notice},{m3,notice}] = logger:get_module_level(), + ok = logger:unset_module_level(m2), + [{m1,notice},{m3,notice}] = logger:get_module_level(), + ok = logger:unset_module_level(), + [] = logger:get_module_level(), ok. -set_level_module(cleanup,_Config) -> +set_module_level(cleanup,_Config) -> logger:remove_handler(h1), logger:unset_module_level(?MODULE), ok. -cache_level_module(_Config) -> +cache_module_level(_Config) -> ok = logger:unset_module_level(?MODULE), - [] = ets:lookup(logger,?MODULE), %dirty - add API in logger_config? - ?LOG_INFO(?map_rep), + [] = ets:lookup(?LOGGER_TABLE,?MODULE), %dirty - add API in logger_config? + ?LOG_NOTICE(?map_rep), %% Caching is done asynchronously, so wait a bit for the update timer:sleep(100), - [_] = ets:lookup(logger,?MODULE), %dirty - add API in logger_config? + [_] = ets:lookup(?LOGGER_TABLE,?MODULE), %dirty - add API in logger_config? ok = logger:unset_module_level(?MODULE), - [] = ets:lookup(logger,?MODULE), %dirty - add API in logger_config? + [] = ets:lookup(?LOGGER_TABLE,?MODULE), %dirty - add API in logger_config? ok. -cache_level_module(cleanup,_Config) -> +cache_module_level(cleanup,_Config) -> logger:unset_module_level(?MODULE), ok. @@ -402,22 +464,22 @@ format_report(_Config) -> ok. filter_failed(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), %% Logger filters {error,{invalid_filter,_}} = - logger:add_logger_filter(lf,{fun(_) -> ok end,args}), - ok = logger:add_logger_filter(lf,{fun(_,_) -> a=b end,args}), - {ok,#{filters:=[_]}} = logger:get_logger_config(), - ok = logger:info(M1=?map_rep), - ok = check_logged(info,M1,#{}), - {error,{not_found,lf}} = logger:remove_logger_filter(lf), - - ok = logger:add_logger_filter(lf,{fun(_,_) -> faulty_return end,args}), - {ok,#{filters:=[_]}} = logger:get_logger_config(), - ok = logger:info(M2=?map_rep), - ok = check_logged(info,M2,#{}), - {error,{not_found,lf}} = logger:remove_logger_filter(lf), + logger:add_primary_filter(lf,{fun(_) -> ok end,args}), + ok = logger:add_primary_filter(lf,{fun(_,_) -> a=b end,args}), + #{filters:=[_]} = logger:get_primary_config(), + ok = logger:notice(M1=?map_rep), + ok = check_logged(notice,M1,#{}), + {error,{not_found,lf}} = logger:remove_primary_filter(lf), + + ok = logger:add_primary_filter(lf,{fun(_,_) -> faulty_return end,args}), + #{filters:=[_]} = logger:get_primary_config(), + ok = logger:notice(M2=?map_rep), + ok = check_logged(notice,M2,#{}), + {error,{not_found,lf}} = logger:remove_primary_filter(lf), %% Handler filters {error,{not_found,h0}} = @@ -426,15 +488,15 @@ filter_failed(_Config) -> {error,{invalid_filter,_}} = logger:add_handler_filter(h1,hf,{fun(_) -> ok end,args}), ok = logger:add_handler_filter(h1,hf,{fun(_,_) -> a=b end,args}), - {ok,{?MODULE,#{filters:=[_]}}} = logger:get_handler_config(h1), - ok = logger:info(M3=?map_rep), - ok = check_logged(info,M3,#{}), + {ok,#{filters:=[_]}} = logger:get_handler_config(h1), + ok = logger:notice(M3=?map_rep), + ok = check_logged(notice,M3,#{}), {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf), ok = logger:add_handler_filter(h1,hf,{fun(_,_) -> faulty_return end,args}), - {ok,{?MODULE,#{filters:=[_]}}} = logger:get_handler_config(h1), - ok = logger:info(M4=?map_rep), - ok = check_logged(info,M4,#{}), + {ok,#{filters:=[_]}} = logger:get_handler_config(h1), + ok = logger:notice(M4=?map_rep), + ok = check_logged(notice,M4,#{}), {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf), ok. @@ -455,20 +517,20 @@ handler_failed(_Config) -> {error,{invalid_formatter,[]}} = logger:add_handler(h1,?MODULE,#{formatter=>[]}), {error,{invalid_handler,_}} = logger:add_handler(h1,nomodule,#{filter_default=>log}), - logger:info(?map_rep), + logger:notice(?map_rep), check_no_log(), - #{handlers:=H1} = logger:i(), - false = lists:keymember(h1,1,H1), + H1 = logger:get_handler_config(), + false = lists:search(fun(#{id:=h1}) -> true; (_) -> false end,H1), {error,{not_found,h1}} = logger:remove_handler(h1), ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,log_call=>fun() -> a = b end}), {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}), [add] = test_server:messages_get(), - logger:info(?map_rep), + logger:notice(?map_rep), [remove] = test_server:messages_get(), - #{handlers:=H2} = logger:i(), - false = lists:keymember(h2,1,H2), + H2 = logger:get_handler_config(), + false = lists:search(fun(#{id:=h2}) -> true; (_) -> false end,H2), {error,{not_found,h2}} = logger:remove_handler(h2), CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end, @@ -520,18 +582,18 @@ handler_failed(cleanup,_Config) -> config_sanity_check(_Config) -> %% Logger 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_filters,bad}} = logger:set_logger_config(filters,bad), - {error,{invalid_filter,bad}} = logger:set_logger_config(filters,[bad]), + logger:set_primary_config(filter_default,bad), + {error,{invalid_level,bad}} = logger:set_primary_config(level,bad), + {error,{invalid_filters,bad}} = logger:set_primary_config(filters,bad), + {error,{invalid_filter,bad}} = logger:set_primary_config(filters,[bad]), {error,{invalid_filter,{_,_}}} = - logger:set_logger_config(filters,[{id,bad}]), + logger:set_primary_config(filters,[{id,bad}]), {error,{invalid_filter,{_,{_,_}}}} = - logger:set_logger_config(filters,[{id,{bad,args}}]), + logger:set_primary_config(filters,[{id,{bad,args}}]), {error,{invalid_filter,{_,{_,_}}}} = - logger:set_logger_config(filters,[{id,{fun() -> ok end,args}}]), - {error,{invalid_logger_config,{bad,bad}}} = - logger:set_logger_config(bad,bad), + logger:set_primary_config(filters,[{id,{fun() -> ok end,args}}]), + {error,{invalid_primary_config,{bad,bad}}} = + logger:set_primary_config(bad,bad), %% Handler config {error,{not_found,h1}} = logger:set_handler_config(h1,a,b), @@ -555,7 +617,7 @@ config_sanity_check(_Config) -> logger:set_handler_config(h1,formatter,{logger_formatter,bad}), {error,{invalid_formatter_config,logger_formatter,{bad,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter,#{bad=>bad}}), - {error,{invalid_formatter_config,logger_formatter,{template,bad}}} = + {error,{invalid_formatter_template,logger_formatter,bad}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>bad}}), {error,{invalid_formatter_template,logger_formatter,[1]}} = @@ -648,30 +710,30 @@ config_sanity_check(cleanup,_Config) -> ok. log_failed(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), {error,function_clause} = ?TRY(logger:log(bad,?map_rep)), - {error,function_clause} = ?TRY(logger:log(info,?map_rep,bad)), - {error,function_clause} = ?TRY(logger:log(info,fun() -> ?map_rep end,bad)), - {error,function_clause} = ?TRY(logger:log(info,fun() -> ?map_rep end,bad,#{})), - {error,function_clause} = ?TRY(logger:log(info,bad,bad,bad)), - {error,function_clause} = ?TRY(logger:log(info,bad,bad,#{})), + {error,function_clause} = ?TRY(logger:log(notice,?map_rep,bad)), + {error,function_clause} = ?TRY(logger:log(notice,fun() -> ?map_rep end,bad)), + {error,function_clause} = ?TRY(logger:log(notice,fun() -> ?map_rep end,bad,#{})), + {error,function_clause} = ?TRY(logger:log(notice,bad,bad,bad)), + {error,function_clause} = ?TRY(logger:log(notice,bad,bad,#{})), check_no_log(), - ok = logger:log(info,M1=?str,#{}), - check_logged(info,M1,#{}), - ok = logger:log(info,M2=?map_rep,#{}), - check_logged(info,M2,#{}), - ok = logger:log(info,M3=?keyval_rep,#{}), - check_logged(info,M3,#{}), + ok = logger:log(notice,M1=?str,#{}), + check_logged(notice,M1,#{}), + ok = logger:log(notice,M2=?map_rep,#{}), + check_logged(notice,M2,#{}), + ok = logger:log(notice,M3=?keyval_rep,#{}), + check_logged(notice,M3,#{}), %% Should we check report input more thoroughly? - ok = logger:log(info,M4=?keyval_rep++[other,stuff,in,list],#{}), - check_logged(info,M4,#{}), + ok = logger:log(notice,M4=?keyval_rep++[other,stuff,in,list],#{}), + check_logged(notice,M4,#{}), %% This might break a handler since it is assumed to be a format %% string and args, so it depends how the handler protects itself %% against something like io_lib:format("ok","ok") - ok = logger:log(info,"ok","ok",#{}), - check_logged(info,"ok","ok",#{}), + ok = logger:log(notice,"ok","ok",#{}), + check_logged(notice,"ok","ok",#{}), ok. @@ -680,7 +742,7 @@ log_failed(cleanup,_Config) -> ok. emulator(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log, tc_proc=>self()}), Msg = "Error in process ~p on node ~p with exit value:~n~p~n", Error = {badmatch,4}, @@ -699,7 +761,7 @@ generate_error(Error, Stack) -> erlang:raise(error, Error, Stack). via_logger_process(Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log, tc_proc=>self()}), %% Explicitly send a message to the logger process @@ -736,7 +798,7 @@ via_logger_process(cleanup, Config) -> ok. other_node(_Config) -> - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log, tc_proc=>self()}), {ok,Node} = test_server:start_node(?FUNCTION_NAME,slave,[]), rpc:call(Node,logger,error,[Msg=?str,#{}]), @@ -753,8 +815,8 @@ compare_levels(_Config) -> Levels = [emergency,alert,critical,error,warning,notice,info,debug], ok = compare(Levels), {error,badarg} = ?TRY(logger:compare_levels(bad,bad)), - {error,badarg} = ?TRY(logger:compare_levels({bad},info)), - {error,badarg} = ?TRY(logger:compare_levels(info,"bad")), + {error,badarg} = ?TRY(logger:compare_levels({bad},notice)), + {error,badarg} = ?TRY(logger:compare_levels(notice,"bad")), ok. compare([L|Rest]) -> @@ -768,21 +830,21 @@ compare([]) -> process_metadata(_Config) -> undefined = logger:get_process_metadata(), {error,badarg} = ?TRY(logger:set_process_metadata(bad)), - ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), Time = erlang:system_time(microsecond), ProcMeta = #{time=>Time,line=>0,custom=>proc}, ok = logger:set_process_metadata(ProcMeta), S1 = ?str, - ?LOG_INFO(S1,#{custom=>macro}), - check_logged(info,S1,#{time=>Time,line=>0,custom=>macro}), + ?LOG_NOTICE(S1,#{custom=>macro}), + check_logged(notice,S1,#{time=>Time,line=>0,custom=>macro}), Time2 = erlang:system_time(microsecond), S2 = ?str, - ?LOG_INFO(S2,#{time=>Time2,line=>1,custom=>macro}), - check_logged(info,S2,#{time=>Time2,line=>1,custom=>macro}), + ?LOG_NOTICE(S2,#{time=>Time2,line=>1,custom=>macro}), + check_logged(notice,S2,#{time=>Time2,line=>1,custom=>macro}), - logger:info(S3=?str,#{custom=>func}), - check_logged(info,S3,#{time=>Time,line=>0,custom=>func}), + logger:notice(S3=?str,#{custom=>func}), + check_logged(notice,S3,#{time=>Time,line=>0,custom=>func}), ProcMeta = logger:get_process_metadata(), ok = logger:update_process_metadata(#{custom=>changed,custom2=>added}), diff --git a/lib/kernel/test/logger_bench_SUITE.erl b/lib/kernel/test/logger_bench_SUITE.erl deleted file mode 100644 index d47122ea9d..0000000000 --- a/lib/kernel/test/logger_bench_SUITE.erl +++ /dev/null @@ -1,500 +0,0 @@ -%% -%% %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_bench_SUITE). - --compile(export_all). - -%%%----------------------------------------------------------------- -%%% To include lager tests, add paths to lager and goldrush -%%% (goldrush is a dependency inside the lager repo) -%%% -%%% To print data to .csv files, add the following to a config file: -%%% {print_csv,[{console_handler,[{path,"/some/dir/"}]}]}. -%%% -%%%----------------------------------------------------------------- - --include_lib("common_test/include/ct.hrl"). --include_lib("common_test/include/ct_event.hrl"). --include_lib("kernel/include/logger.hrl"). --include_lib("kernel/src/logger_internal.hrl"). - --define(msg,lists:flatten(string:pad("Log from "++atom_to_list(?FUNCTION_NAME)++ - ":"++integer_to_list(?LINE), - 80,trailing,$*))). --define(meta,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY}, - pid=>self()}). - --define(NO_COMPARE,[profile]). - --define(TIMES,100000). - -suite() -> - [{timetrap,{seconds,120}}]. - -init_per_suite(Config) -> - DataDir = ?config(data_dir,Config), - have_lager() andalso make(DataDir), - Config. - -end_per_suite(_Config) -> - ok. - -init_per_group(Group, Config) -> - H = remove_all_handlers(), - do_init_per_group(Group), - [{handlers,H}|Config]. - -do_init_per_group(minimal_handler) -> - ok = logger:add_handler(?MODULE,?MODULE,#{level=>error,filter_default=>log}); -do_init_per_group(console_handler) -> - ok = logger:add_handler(?MODULE,logger_std_h, - #{filter_default=>stop, - filters=>?DEFAULT_HANDLER_FILTERS, - logger_std_h=>#{type=>standard_io, - toggle_sync_qlen => ?TIMES+1, - drop_new_reqs_qlen => ?TIMES+2, - flush_reqs_qlen => ?TIMES+3, - enable_burst_limit => false}}), - have_lager() andalso lager_helper:start(), - ok. - -end_per_group(Group, Config) -> - case ?config(saved_config,Config) of - {_,[{bench,Bench}]} -> - print_compare_chart(Group,Bench); - _ -> - ok - end, - add_all_handlers(?config(handlers,Config)), - do_end_per_group(Group). - -do_end_per_group(minimal_handler) -> - ok = logger:remove_handler(?MODULE); -do_end_per_group(console_handler) -> - ok = logger:remove_handler(?MODULE), - have_lager() andalso lager_helper:stop(), - ok. - -init_per_testcase(_TestCase, Config) -> - Config. - -end_per_testcase(Case, Config) -> - try apply(?MODULE,Case,[cleanup,Config]) - catch error:undef -> ok - end, - wait_for_handlers(), - ok. - -wait_for_handlers() -> - wait_for_handler(?MODULE), - wait_for_handler(lager_event). - -wait_for_handler(Handler) -> - case whereis(Handler) of - undefined -> - io:format("~p: noproc1",[Handler]), - ok; - Pid -> - case process_info(Pid,message_queue_len) of - {_,0} -> - io:format("~p: queue=~p",[Handler,0]), - ok; - {_,Q} -> - io:format("~p: queue=~p",[Handler,Q]), - timer:sleep(2000), - wait_for_handler(Handler); - undefined -> - io:format("~p: noproc2",[Handler]), - ok - end - end. - -groups() -> - [{minimal_handler,[],[log, - log_drop, - log_drop_by_handler, - macro, - macro_drop, - macro_drop_by_handler, - error_logger, - error_logger_drop, - error_logger_drop_by_handler - ]}, - {console_handler,[],[%profile, - log, - log_drop, - log_drop_by_handler, - %% log_handler_complete, - macro, - macro_drop, - macro_drop_by_handler, - %% macro_handler_complete, - error_logger, - error_logger_drop, - error_logger_drop_by_handler%% , - %% error_logger_handler_complete - ] ++ lager_cases()} - ]. - -lager_cases() -> - case have_lager() of - true -> - [lager_log, - lager_log_drop, - lager_log_drop_by_handler, - %% lager_log_handler_complete, - lager_parsetrans, - lager_parsetrans_drop, - lager_parsetrans_drop_by_handler%% , - %% lager_parsetrans_handler_complete - ]; - false -> - [] - end. - - -all() -> - [{group,minimal_handler}, - {group,console_handler} - ]. - -log(Config) -> - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [error,?msg], Times). - -log_drop(Config) -> - Times = ?TIMES*100, - ok = logger:set_logger_config(level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times). - -log_drop(cleanup,_Config) -> - ok = logger:set_logger_config(level,info). - -log_drop_by_handler(Config) -> - Times = ?TIMES, - %% just ensure correct levels - ok = logger:set_logger_config(level,info), - ok = logger:set_handler_config(?MODULE,level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times). - -log_handler_complete(Config) -> - ok = logger:set_handler_config(?MODULE,formatter, - {?MODULE,?DEFAULT_FORMAT_CONFIG}), - handler_complete(Config, ?FUNCTION_NAME, fun do_log_func/2, [error,?msg]). - -log_handler_complete(cleanup,_Config) -> - ok=logger:set_handler_config(?MODULE,formatter, - {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}). - -macro(Config) -> - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2,[error,?msg], Times). - -macro_drop(Config) -> - Times = ?TIMES*100, - ok = logger:set_logger_config(level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2,[info,?msg], Times). - -macro_drop(cleanup,_Config) -> - ok = logger:set_logger_config(level,info). - -macro_drop_by_handler(Config) -> - Times = ?TIMES, - %% just ensure correct levels - ok = logger:set_logger_config(level,info), - ok = logger:set_handler_config(?MODULE,level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2, [info,?msg], Times). - -macro_handler_complete(Config) -> - ok = logger:set_handler_config(?MODULE,formatter, - {?MODULE,?DEFAULT_FORMAT_CONFIG}), - handler_complete(Config, ?FUNCTION_NAME, fun do_log_macro/2, [error,?msg]). - -macro_handler_complete(cleanup,_Config) -> - ok=logger:set_handler_config(?MODULE,formatter, - {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}). - -error_logger(Config) -> - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun do_error_logger/2, [error,?msg], Times). - -error_logger_drop(Config) -> - Times = ?TIMES*100, - ok = logger:set_logger_config(level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_error_logger/2, [info,?msg], Times). - -error_logger_drop(cleanup,_Config) -> - ok = logger:set_logger_config(level,info). - -error_logger_drop_by_handler(Config) -> - Times = ?TIMES, - %% just ensure correct levels - ok = logger:set_logger_config(level,info), - ok = logger:set_handler_config(?MODULE,level,error), - run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times). - -error_logger_handler_complete(Config) -> - ok = logger:set_handler_config(?MODULE,formatter, - {?MODULE,?DEFAULT_FORMAT_CONFIG}), - handler_complete(Config, ?FUNCTION_NAME, fun do_error_logger/2, [error,?msg]). - -error_logger_handler_complete(cleanup,_Config) -> - ok=logger:set_handler_config(?MODULE,formatter, - {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}). - -lager_log(Config) -> - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [error,?msg], Times). - -lager_log_drop(Config) -> - Times = ?TIMES*100, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [info,?msg], Times). - -lager_log_drop_by_handler(Config) -> - %% This concept does not exist, so doing same as lager_log_drop/1 - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [info,?msg], Times). - -lager_log_handler_complete(Config) -> - handler_complete(Config, ?FUNCTION_NAME, fun lager_helper:do_func/2, [error,?msg]). - -lager_parsetrans(Config) -> - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [error,?msg], Times). - -lager_parsetrans_drop(Config) -> - Times = ?TIMES*100, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [info,?msg], Times). - -lager_parsetrans_drop_by_handler(Config) -> - %% This concept does not exist, so doing same as lager_parsetrans_drop/1 - Times = ?TIMES, - run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [info,?msg], Times). - -lager_parsetrans_handler_complete(Config) -> - handler_complete(Config, ?FUNCTION_NAME, fun lager_helper:do_parsetrans/2, [error,?msg]). - - -profile(Config) -> - Times = ?TIMES, - %% fprof:apply(fun repeated_apply/3,[fun lager_helper:do_func/2,[error,?msg],Times]), - fprof:apply(fun repeated_apply/3,[fun do_log_func/2,[error,?msg],Times]), - ok = fprof:profile(), - ok = fprof:analyse(dest,"../fprof.analyse"), - ok. - -%%%----------------------------------------------------------------- -%%% Internal -%% Handler -log(_Log,_Config) -> - ok. - -format(Log=#{meta:=#{pid:=Pid}},Config) when is_pid(Pid) -> - String = ?DEFAULT_FORMATTER:format(Log,Config), - Pid ! done, - String; -format(Log=#{meta:=#{pid:=PidStr}},Config) when is_list(PidStr) -> - String = ?DEFAULT_FORMATTER:format(Log,Config), - list_to_pid(PidStr) ! done, - String. - -handler_complete(Config, TC, Fun, Args) -> - Times = ?TIMES, - Start = os:perf_counter(microsecond), - repeated_apply(Fun, Args, Times), - MSecs = wait_for_done(Start,Times), - calc_and_report(Config,TC,MSecs,Times). - -wait_for_done(Start,0) -> - os:perf_counter(microsecond) - Start; -wait_for_done(Start,N) -> - receive - done -> - wait_for_done(Start,N-1) - after 20000 -> - ct:fail("missing " ++ integer_to_list(N) ++ " replys") - end. - -%%%----------------------------------------------------------------- -%%% Benchmark stuff -run_benchmark(Config,Tag,Fun,Args,Times) -> - _ = erlang:apply(Fun, Args), % apply once to ensure level is cached - MSecs = measure_repeated_op(Fun, Args, Times), - %% fprof:profile(), - %% fprof:analyse(dest,"../"++atom_to_list(Tag)++".prof"), - calc_and_report(Config,Tag,MSecs,Times). - -measure_repeated_op(Fun, Args, Times) -> - Start = os:perf_counter(microsecond), - %% fprof:apply(fun repeated_apply/3, [Fun, Args, Times]), - repeated_apply(Fun, Args, Times), - os:perf_counter(microsecond) - Start. - -repeated_apply(_F, _Args, Times) when Times =< 0 -> - ok; -repeated_apply(F, Args, Times) -> - erlang:apply(F, Args), - repeated_apply(F, Args, Times - 1). - -calc_and_report(Config,Tag,MSecs,Times) -> - IOPS = trunc(Times * (1000000 / MSecs)), - ct_event:notify(#event{ name = benchmark_data, data = [{value,IOPS}] }), - ct:print("~p:~n~p IOPS, ~p us", [Tag, IOPS, MSecs]), - ct:comment("~p IOPS, ~p us", [IOPS, MSecs]), - Bench = case ?config(saved_config,Config) of - {_,[{bench,B}]} -> B; - undefined -> [] - end, - {save_config,[{bench,[{Tag,IOPS,MSecs}|Bench]}]}. - -remove_all_handlers() -> - #{handlers:=Hs} = logger:i(), - [logger:remove_handler(Id) || {Id,_,_} <- Hs], - Hs. - -add_all_handlers(Hs) -> - [logger:add_handler(Id,Mod,Config) || {Id,Mod,Config} <- Hs], - ok. - -%%%----------------------------------------------------------------- -%%% Call logger in different ways -do_log_func(Level,Msg) -> - logger:Level(Msg,[],?meta). - -do_log_macro(error,Msg) -> - ?LOG_ERROR(Msg,[]); -do_log_macro(info,Msg) -> - ?LOG_INFO(Msg,[]); -do_log_macro(debug,Msg) -> - ?LOG_DEBUG(Msg,[]). - -do_error_logger(error,Msg) -> - error_logger:error_msg(Msg,[]); -do_error_logger(info,Msg) -> - error_logger:info_msg(Msg,[]). - -%%%----------------------------------------------------------------- -%%% -print_compare_chart(Group,Bench) -> - io:format("~-20s~12s~12s~12s~12s", - ["Microseconds:","Log","Drop","HDrop","Complete"]), - io:format(user,"~-20s~12s~12s~12s~12s~n", - ["Microseconds:","Log","Drop","HDrop","Complete"]), - {Log,Drop,HDrop,Comp} = sort_bench(Bench,[],[],[],[]), - print_compare_chart(Log,Drop,HDrop,Comp), - io:format(user,"~n",[]), - maybe_print_csv_files(Group, - [{log,Log},{drop,Drop},{hdrop,HDrop},{comp,Comp}]). - -print_compare_chart([{What,LIOPS,LMSecs}|Log], - [{What,DIOPS,DMSecs}|Drop], - [{What,HIOPS,HMSecs}|HDrop], - [{What,CIOPS,CMSecs}|Comp]) -> - io:format("~-20w~12w~12w~12w~12w",[What,LMSecs,DMSecs,HMSecs,CMSecs]), - io:format(user,"~-20w~12w~12w~12w~12w~n",[What,LMSecs,DMSecs,HMSecs,CMSecs]), - print_compare_chart(Log,Drop,HDrop,Comp); -print_compare_chart([{What,LIOPS,LMSecs}|Log], - [{What,DIOPS,DMSecs}|Drop], - [{What,HIOPS,HMSecs}|HDrop], - []=Comp) -> - io:format("~-20w~12w~12w~12w",[What,LMSecs,DMSecs,HMSecs]), - io:format(user,"~-20w~12w~12w~12w~n",[What,LMSecs,DMSecs,HMSecs]), - print_compare_chart(Log,Drop,HDrop,Comp); -print_compare_chart([],[],[],[]) -> - ok; -print_compare_chart(Log,Drop,HDrop,Comp) -> - ct:fail({Log,Drop,HDrop,Comp}). - -sort_bench([{TC,IOPS,MSecs}|Bench],Log,Drop,HDrop,Comp) -> - case lists:member(TC,?NO_COMPARE) of - true -> - sort_bench(Bench,Log,Drop,HDrop,Comp); - false -> - TCStr = atom_to_list(TC), - {What,Type} = - case re:run(TCStr,"(.*)_(drop.*)", - [{capture,all_but_first,list}]) of - {match,[WhatStr,TypeStr]} -> - {list_to_atom(WhatStr),list_to_atom(TypeStr)}; - nomatch -> - case re:run(TCStr,"(.*)_(handler_complete.*)", - [{capture,all_but_first,list}]) of - {match,[WhatStr,TypeStr]} -> - {list_to_atom(WhatStr),list_to_atom(TypeStr)}; - nomatch -> - {TC,log} - end - end, - case Type of - log -> - sort_bench(Bench,[{What,IOPS,MSecs}|Log],Drop,HDrop,Comp); - drop -> - sort_bench(Bench,Log,[{What,IOPS,MSecs}|Drop],HDrop,Comp); - drop_by_handler -> - sort_bench(Bench,Log,Drop,[{What,IOPS,MSecs}|HDrop],Comp); - handler_complete -> - sort_bench(Bench,Log,Drop,HDrop,[{What,IOPS,MSecs}|Comp]) - end - end; -sort_bench([],Log,Drop,HDrop,Comp) -> - {lists:keysort(1,Log), - lists:keysort(1,Drop), - lists:keysort(1,HDrop), - lists:keysort(1,Comp)}. - -maybe_print_csv_files(Group,Data) -> - case ct:get_config({print_csv,Group}) of - undefined -> - ok; - Cfg -> - Path = proplists:get_value(path,Cfg,".."), - Files = [begin - File = filename:join(Path,F)++".csv", - case filelib:is_regular(File) of - true -> - {ok,Fd} = file:open(File,[append]), - Fd; - false -> - {ok,Fd} = file:open(File,[write]), - ok = file:write(Fd, - "error_logger,lager_log," - "lager_parsetrans,logger_log," - "logger_macro\n"), - Fd - end - end || {F,_} <- Data], - [print_csv_file(F,D) || {F,D} <- lists:zip(Files,Data)], - [file:close(Fd) || Fd <- Files], - ok - end. - -print_csv_file(Fd,{_,Data}) -> - AllIOPS = [integer_to_list(IOPS) || {_,IOPS,_} <- Data], - ok = file:write(Fd,lists:join(",",AllIOPS)++"\n"). - -have_lager() -> - code:ensure_loaded(lager) == {module,lager}. - -make(Dir) -> - {ok,Cwd} = file:get_cwd(), - ok = file:set_cwd(Dir), - up_to_date = make:all([load]), - ok = file:set_cwd(Cwd), - code:add_path(Dir). diff --git a/lib/kernel/test/logger_bench_SUITE_data/Emakefile b/lib/kernel/test/logger_bench_SUITE_data/Emakefile deleted file mode 100644 index 85c82bdaab..0000000000 --- a/lib/kernel/test/logger_bench_SUITE_data/Emakefile +++ /dev/null @@ -1 +0,0 @@ -{['lager_helper'],[{outdir,"."},debug_info,{i,"/home/uabshan/Work/git/otp/lib/kernel/src"},{i,"/home/uabshan/Work/git/otp/lib/kernel/include"}]}. diff --git a/lib/kernel/test/logger_bench_SUITE_data/lager_helper.erl b/lib/kernel/test/logger_bench_SUITE_data/lager_helper.erl deleted file mode 100644 index 296ced4276..0000000000 --- a/lib/kernel/test/logger_bench_SUITE_data/lager_helper.erl +++ /dev/null @@ -1,73 +0,0 @@ --module(lager_helper). - --compile(export_all). --compile({parse_transform,lager_transform}). - --include_lib("kernel/src/logger_internal.hrl"). - -start() -> - application:load(lager), - application:set_env(lager, error_logger_redirect, false), - application:set_env(lager, async_threshold, 100010), - application:set_env(lager, async_threshold_window, 100), - application:set_env(lager,handlers,[{?MODULE,[{level,error}]}]), - lager:start(). - -stop() -> - application:stop(lager). - -do_func(Level,Msg) -> - lager:log(Level,[{pid,self()}],Msg,[]). - -do_parsetrans(error,Msg) -> - lager:error(Msg,[]); -do_parsetrans(info,Msg) -> - lager:info(Msg,[]). - -%%%----------------------------------------------------------------- -%%% Dummy handler for lager --record(state, {level :: {'mask', integer()}, - formatter :: atom(), - format_config :: any()}). -init(Opts) -> - Level = proplists:get_value(level,Opts,info), - Formatter = proplists:get_value(formatter,Opts,logger_bench_SUITE), - FormatConfig = proplists:get_value(format_config,Opts,?DEFAULT_FORMAT_CONFIG), - {ok,#state{level=lager_util:config_to_mask(Level), - formatter=Formatter, - format_config=FormatConfig}}. - -handle_call(get_loglevel, #state{level=Level} = State) -> - {ok, Level, State}; -handle_call({set_loglevel, Level}, State) -> - try lager_util:config_to_mask(Level) of - Levels -> - {ok, ok, State#state{level=Levels}} - catch - _:_ -> - {ok, {error, bad_log_level}, State} - end; -handle_call(_Request, State) -> - {ok, ok, State}. - -handle_event({log, Message}, - #state{level=L,formatter=Formatter,format_config=FormatConfig} = State) -> - case lager_util:is_loggable(Message, L, ?MODULE) of - true -> - Metadata = - case maps:from_list(lager_msg:metadata(Message)) of - Meta = #{pid:=Pid} when is_pid(Pid) -> - Meta; - Meta = #{pid:=PidStr} when is_list(PidStr) -> - Meta - end, - Log = #{level=>lager_msg:severity(Message), - msg=>{report,lager_msg:message(Message)}, - meta=>Metadata}, - io:put_chars(user, Formatter:format(Log,FormatConfig)), - {ok, State}; - false -> - {ok, State} - end; -handle_event(_Event, State) -> - {ok, State}. diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 7a1736c814..7e5b574869 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -1,3 +1,22 @@ +%% +%% %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_disk_log_h_SUITE). -compile(export_all). @@ -26,10 +45,6 @@ -define(log_no(File,N), lists:concat([File,".",N])). -define(domain,#{domain=>[?MODULE]}). --define(SYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500; - true -> ?FILESYNC_REPEAT_INTERVAL + 500 - end). - suite() -> [{timetrap,{seconds,30}}, {ct_hooks,[logger_test_lib]}]. @@ -50,9 +65,10 @@ end_per_group(_Group, _Config) -> init_per_testcase(TestHooksCase, Config) when TestHooksCase == write_failure; TestHooksCase == sync_failure -> - if ?TEST_HOOKS_TAB == undefined -> + case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of + true -> {skip,"Define the TEST_HOOKS macro to run this test"}; - true -> + false -> ct:print("********** ~w **********", [TestHooksCase]), Config end; @@ -82,7 +98,7 @@ all() -> bad_input, info_and_reset, reconfig, - disk_log_sync, + sync, disk_log_full, disk_log_wrap, disk_log_events, @@ -107,10 +123,10 @@ start_stop_handler(_Config) -> ok = logger:add_handler(?MODULE, logger_disk_log_h, #{}), {error,{already_exist,?MODULE}} = logger:add_handler(?MODULE, logger_disk_log_h, #{}), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE). + undefined = whereis(h_proc_name()). start_stop_handler(cleanup, _Config) -> logger:remove_handler(?MODULE). @@ -123,8 +139,8 @@ create_log(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}, #{file=>LogFile1}), - logger:info("hello", ?domain), - logger_disk_log_h:disk_log_sync(Name1), + logger:notice("hello", ?domain), + logger_disk_log_h:filesync(Name1), ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), try_read_file(?log_no(LogFile1,1), {ok,<<"hello\n">>}, 5000), @@ -136,8 +152,8 @@ create_log(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}, #{file=>LogFile2}), - logger:info("dummy", ?domain), - logger_disk_log_h:disk_log_sync(Name2), + logger:notice("dummy", ?domain), + logger_disk_log_h:filesync(Name2), ct:pal("Checking contents of ~p", [?log_no(LogFile2,1)]), try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000), @@ -157,22 +173,22 @@ open_existing_log(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}, #{file=>LogFile1}), - logger:info("one", ?domain), - logger_disk_log_h:disk_log_sync(HName), + logger:notice("one", ?domain), + logger_disk_log_h:filesync(HName), ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), try_read_file(?log_no(LogFile1,1), {ok,<<"one\n">>}, 5000), - logger:info("two", ?domain), + logger:notice("two", ?domain), ok = remove_and_stop(HName), try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\n">>}, 5000), - logger:info("two and a half", ?domain), + logger:notice("two and a half", ?domain), ok = start_and_add(HName, #{filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}, #{file=>LogFile1}), - logger:info("three", ?domain), - logger_disk_log_h:disk_log_sync(HName), + logger:notice("three", ?domain), + logger_disk_log_h:filesync(HName), try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000), remove_and_stop(HName), try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000). @@ -196,23 +212,23 @@ disk_log_opts(Config) -> ct:log("Fullname = ~s", [WFileFull]), {WFileFull,wrap,{Size,2},1} = {Get(file,WInfo1),Get(type,WInfo1), Get(size,WInfo1),Get(current_file,WInfo1)}, - logger:info("123", ?domain), - logger_disk_log_h:disk_log_sync(WName), + logger:notice("123", ?domain), + logger_disk_log_h:filesync(WName), timer:sleep(500), 1 = Get(current_file, disk_log:info(WName)), - logger:info("45", ?domain), - logger_disk_log_h:disk_log_sync(WName), + logger:notice("45", ?domain), + logger_disk_log_h:filesync(WName), timer:sleep(500), 1 = Get(current_file, disk_log:info(WName)), - logger:info("6", ?domain), - logger_disk_log_h:disk_log_sync(WName), + logger:notice("6", ?domain), + logger_disk_log_h:filesync(WName), timer:sleep(500), 2 = Get(current_file, disk_log:info(WName)), - logger:info("7890", ?domain), - logger_disk_log_h:disk_log_sync(WName), + logger:notice("7890", ?domain), + logger_disk_log_h:filesync(WName), timer:sleep(500), 2 = Get(current_file, disk_log:info(WName)), @@ -229,8 +245,8 @@ disk_log_opts(Config) -> ct:log("Fullname = ~s", [HFile1Full]), {HFile1Full,halt,infinity} = {Get(file,HInfo1),Get(type,HInfo1), Get(size,HInfo1)}, - logger:info("12345", ?domain), - logger_disk_log_h:disk_log_sync(HName1), + logger:notice("12345", ?domain), + logger_disk_log_h:filesync(HName1), timer:sleep(500), 1 = Get(no_written_items, disk_log:info(HName1)), @@ -253,17 +269,17 @@ disk_log_opts(Config) -> default_formatter(Config) -> PrivDir = ?config(priv_dir,Config), LogFile = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)), - HConfig = #{disk_log_opts => #{file=>LogFile}, - filter_default=>log}, + HandlerConfig = #{config => #{file=>LogFile}, + filter_default=>log}, ct:pal("Log: ~p", [LogFile]), - ok = logger:add_handler(?MODULE, logger_disk_log_h, HConfig), + ok = logger:add_handler(?MODULE, logger_disk_log_h, HandlerConfig), ok = logger:set_handler_config(?MODULE,formatter, {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), LogName = lists:concat([LogFile, ".1"]), - logger:info("dummy"), + logger:notice("dummy"), wait_until_written(LogName), {ok,Bin} = file:read_file(LogName), - match = re:run(Bin, "=INFO REPORT====.*\ndummy", [{capture,none}]), + match = re:run(Bin, "=NOTICE REPORT====.*\ndummy", [{capture,none}]), ok. default_formatter(cleanup, _Config) -> logger:remove_handler(?MODULE). @@ -277,8 +293,8 @@ logging(Config) -> formatter=>{?MODULE,self()}}, #{file => LogFile}), MsgFormatter = fun(Term) -> {io_lib:format("Term:~p",[Term]),[]} end, - logger:info([{x,y}], #{report_cb => MsgFormatter}), - logger:info([{x,y}], #{}), + logger:notice([{x,y}], #{report_cb => MsgFormatter}), + logger:notice([{x,y}], #{}), ct:pal("Checking contents of ~p", [?log_no(LogFile,1)]), try_read_file(?log_no(LogFile,1), {ok,<<"Term:[{x,y}]\n x: y\n">>}, 5000). @@ -290,10 +306,10 @@ errors(Config) -> PrivDir = ?config(priv_dir,Config), Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), LogFile1 = filename:join(PrivDir,Name1), - HConfig = #{disk_log_opts=>#{file=>LogFile1}, - filter_default=>log, - formatter=>{?MODULE,self()}}, - ok = logger:add_handler(Name1, logger_disk_log_h, HConfig), + HandlerConfig = #{config=>#{file=>LogFile1}, + filter_default=>log, + formatter=>{?MODULE,self()}}, + ok = logger:add_handler(Name1, logger_disk_log_h, HandlerConfig), {error,{already_exist,Name1}} = logger:add_handler(Name1, logger_disk_log_h, #{}), @@ -302,7 +318,7 @@ errors(Config) -> {error,{illegal_config_change,_,_}} = logger:set_handler_config(Name1, - disk_log_opts, + config, #{file=>LogFile1, type=>halt}), {error,{illegal_config_change,_,_}} = @@ -321,45 +337,42 @@ formatter_fail(Config) -> Name = ?FUNCTION_NAME, LogFile = filename:join(PrivDir,Name), ct:pal("Log = ~p", [LogFile]), - HConfig = #{disk_log_opts => #{file=>LogFile}, - filter_default=>stop, - filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}, + HandlerConfig = #{config => #{file=>LogFile}, + filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}, %% no formatter! - logger:add_handler(Name, logger_disk_log_h, HConfig), - Pid = whereis(Name), + logger:add_handler(Name, logger_disk_log_h, HandlerConfig), + Pid = whereis(h_proc_name(Name)), true = is_pid(Pid), - #{handlers:=HC1} = logger:i(), - H = [Id || {Id,_,_} <- HC1], + H = logger:get_handler_ids(), true = lists:member(Name,H), %% Formatter is added automatically - {ok,{_,#{formatter:={logger_formatter,_}}}} = - logger:get_handler_config(Name), - logger:info(M1=?msg,?domain), - Got1 = try_match_file(?log_no(LogFile,1),"[0-9\\+\\-T:\\.]* info: "++M1,5000), + {ok,#{formatter:={logger_formatter,_}}} = logger:get_handler_config(Name), + logger:notice(M1=?msg,?domain), + Got1 = try_match_file(?log_no(LogFile,1),"[0-9\\+\\-T:\\.]* notice: "++M1,5000), ok = logger:set_handler_config(Name,formatter,{nonexistingmodule,#{}}), - logger:info(M2=?msg,?domain), + logger:notice(M2=?msg,?domain), Got2 = try_match_file(?log_no(LogFile,1), - escape(Got1)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M2, + escape(Got1)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M2, 5000), ok = logger:set_handler_config(Name,formatter,{?MODULE,crash}), - logger:info(M3=?msg,?domain), + logger:notice(M3=?msg,?domain), Got3 = try_match_file(?log_no(LogFile,1), - escape(Got2)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M3, + escape(Got2)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M3, 5000), ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}), - logger:info(?msg,?domain), + logger:notice(?msg,?domain), try_match_file(?log_no(LogFile,1), escape(Got3)++"FORMATTER ERROR: bad_return_value", 5000), %% Check that handler is still alive and was never dead - Pid = whereis(Name), - #{handlers:=HC2} = logger:i(), - H = [Id || {Id,_,_} <- HC2], + Pid = whereis(h_proc_name(Name)), + H = logger:get_handler_ids(), ok. formatter_fail(cleanup,_Config) -> @@ -369,48 +382,49 @@ formatter_fail(cleanup,_Config) -> config_fail(_Config) -> {error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} = logger:add_handler(?MODULE,logger_disk_log_h, - #{logger_disk_log_h => #{bad => bad}, + #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = logger:add_handler(?MODULE,logger_disk_log_h, - #{logger_disk_log_h => #{drop_new_reqs_qlen=>1}}), + #{config => #{drop_mode_qlen=>1}}), {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = logger:add_handler(?MODULE,logger_disk_log_h, - #{logger_disk_log_h => #{toggle_sync_qlen=>43, - drop_new_reqs_qlen=>42}}), + #{config => #{sync_mode_qlen=>43, + drop_mode_qlen=>42}}), {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = logger:add_handler(?MODULE,logger_disk_log_h, - #{logger_disk_log_h => #{drop_new_reqs_qlen=>43, - flush_reqs_qlen=>42}}), + #{config => #{drop_mode_qlen=>43, + flush_qlen=>42}}), ok = logger:add_handler(?MODULE,logger_disk_log_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), %% can't change the disk log options for a log already in use {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,disk_log_opts, + logger:set_handler_config(?MODULE,config, #{max_no_files=>2}), %% can't change name of an existing handler {error,{illegal_config_change,_,_}} = logger:set_handler_config(?MODULE,id,bad), - %% incorrect values of OP params + %% incorrect values of OP params + {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), {error,{invalid_levels,_}} = - logger:set_handler_config(?MODULE,logger_disk_log_h, - #{toggle_sync_qlen=>100, - flush_reqs_qlen=>99}), + logger:set_handler_config(?MODULE,config, + HConfig#{sync_mode_qlen=>100, + flush_qlen=>99}), %% invalid name of config parameter {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} = - logger:set_handler_config(?MODULE, logger_disk_log_h, - #{filesync_rep_int => 2000}), + logger:set_handler_config(?MODULE, config, + HConfig#{filesync_rep_int => 2000}), ok. config_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). bad_input(_Config) -> - {error,{badarg,{disk_log_sync,["BadType"]}}} = - logger_disk_log_h:disk_log_sync("BadType"), + {error,{badarg,{filesync,["BadType"]}}} = + logger_disk_log_h:filesync("BadType"), {error,{badarg,{info,["BadType"]}}} = logger_disk_log_h:info("BadType"), {error,{badarg,{reset,["BadType"]}}} = logger_disk_log_h:reset("BadType"). @@ -431,16 +445,16 @@ reconfig(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{id := ?MODULE, - toggle_sync_qlen := ?TOGGLE_SYNC_QLEN, - drop_new_reqs_qlen := ?DROP_NEW_REQS_QLEN, - flush_reqs_qlen := ?FLUSH_REQS_QLEN, - enable_burst_limit := ?ENABLE_BURST_LIMIT, - burst_limit_size := ?BURST_LIMIT_SIZE, - burst_window_time := ?BURST_WINDOW_TIME, - enable_kill_overloaded := ?ENABLE_KILL_OVERLOADED, - handler_overloaded_qlen := ?HANDLER_OVERLOADED_QLEN, - handler_overloaded_mem := ?HANDLER_OVERLOADED_MEM, - handler_restart_after := ?HANDLER_RESTART_AFTER, + sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, log_opts := #{type := ?DISK_LOG_TYPE, max_no_files := ?DISK_LOG_MAX_NO_FILES, @@ -448,29 +462,30 @@ reconfig(Config) -> file := _DiskLogFile}} = logger_disk_log_h:info(?MODULE), - ok = logger:set_handler_config(?MODULE, logger_disk_log_h, - #{toggle_sync_qlen => 1, - drop_new_reqs_qlen => 2, - flush_reqs_qlen => 3, - enable_burst_limit => false, - burst_limit_size => 10, - burst_window_time => 10, - enable_kill_overloaded => true, - handler_overloaded_qlen => 100000, - handler_overloaded_mem => 10000000, - handler_restart_after => never, - filesync_repeat_interval => no_repeat}), + {ok,#{config := HConfig0}} = logger:get_handler_config(?MODULE), + HConfig1 = HConfig0#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => 3, + burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 10, + overload_kill_enable => true, + overload_kill_qlen => 100000, + overload_kill_mem_size => 10000000, + overload_kill_restart_after => infinity, + filesync_repeat_interval => no_repeat}, + ok = logger:set_handler_config(?MODULE, config, HConfig1), #{id := ?MODULE, - toggle_sync_qlen := 1, - drop_new_reqs_qlen := 2, - flush_reqs_qlen := 3, - enable_burst_limit := false, - burst_limit_size := 10, - burst_window_time := 10, - enable_kill_overloaded := true, - handler_overloaded_qlen := 100000, - handler_overloaded_mem := 10000000, - handler_restart_after := never, + sync_mode_qlen := 1, + drop_mode_qlen := 2, + flush_qlen := 3, + burst_limit_enable := false, + burst_limit_max_count := 10, + burst_limit_window_time := 10, + overload_kill_enable := true, + overload_kill_qlen := 100000, + overload_kill_mem_size := 10000000, + overload_kill_restart_after := infinity, filesync_repeat_interval := no_repeat} = logger_disk_log_h:info(?MODULE), @@ -482,7 +497,7 @@ reconfig(Config) -> #{filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}, - disk_log_opts=> + config=> #{type => halt, max_no_files => 1, max_no_bytes => 1024, @@ -497,13 +512,13 @@ reconfig(Config) -> reconfig(cleanup, _Config) -> logger:remove_handler(?MODULE). -disk_log_sync(Config) -> +sync(Config) -> Dir = ?config(priv_dir,Config), File = filename:join(Dir, ?FUNCTION_NAME), Log = lists:concat([File,".1"]), ok = logger:add_handler(?MODULE, logger_disk_log_h, - #{disk_log_opts => #{file => File}, + #{config => #{file => File}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), @@ -513,7 +528,7 @@ disk_log_sync(Config) -> [{disk_log,blog,<<"first\n">>}, {disk_log,sync}]), - logger:info("first", ?domain), + logger:notice("first", ?domain), %% wait for automatic disk_log_sync check_tracer(?FILESYNC_REPEAT_INTERVAL*2), @@ -524,16 +539,18 @@ disk_log_sync(Config) -> {disk_log,sync}]), %% two log requests in fast succession will make the handler skip %% an automatic disk log sync - logger:info("second", ?domain), - logger:info("third", ?domain), - %% do explicit disk_log_sync - logger_disk_log_h:disk_log_sync(?MODULE), + logger:notice("second", ?domain), + logger:notice("third", ?domain), + %% do explicit sync + logger_disk_log_h:filesync(?MODULE), check_tracer(100), %% check that if there's no repeated disk_log_sync active, %% a disk_log_sync is still performed when handler goes idle - logger:set_handler_config(?MODULE, logger_disk_log_h, - #{filesync_repeat_interval => no_repeat}), + {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), + HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, + ok = logger:set_handler_config(?MODULE, config, HConfig1), + no_repeat = maps:get(filesync_repeat_interval, logger_disk_log_h:info(?MODULE)), @@ -543,9 +560,9 @@ disk_log_sync(Config) -> {disk_log,blog,<<"fifth\n">>}, {disk_log,sync}]), - logger:info("fourth", ?domain), + logger:notice("fourth", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - logger:info("fifth", ?domain), + logger:notice("fifth", ?domain), %% wait for automatic disk_log_sync check_tracer(?IDLE_DETECT_TIME_MSEC*2), @@ -559,16 +576,17 @@ disk_log_sync(Config) -> start_tracer([{logger_disk_log_h,handle_cast,2}], [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), - logger:set_handler_config(?MODULE, logger_disk_log_h, - #{filesync_repeat_interval => SyncInt}), + HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, + ok = logger:set_handler_config(?MODULE, config, HConfig2), + SyncInt = maps:get(filesync_repeat_interval, logger_disk_log_h:info(?MODULE)), timer:sleep(WaitT), - logger:set_handler_config(?MODULE, logger_disk_log_h, - #{filesync_repeat_interval => no_repeat}), + HConfig3 = HConfig#{filesync_repeat_interval => no_repeat}, + ok = logger:set_handler_config(?MODULE, config, HConfig3), check_tracer(100), ok. -disk_log_sync(cleanup,_Config) -> +sync(cleanup,_Config) -> dbg:stop_clear(), logger:remove_handler(?MODULE). @@ -584,7 +602,7 @@ disk_log_wrap(Config) -> #{filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}, - disk_log_opts=> + config=> #{type => wrap, max_no_files => MaxFiles, max_no_bytes => MaxBytes, @@ -598,7 +616,7 @@ disk_log_wrap(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], @@ -606,7 +624,7 @@ disk_log_wrap(Config) -> %% fill first file lists:foreach(fun(N) -> Log = lists:concat([File,".",N]), - logger:info(Text, ?domain), + logger:notice(Text, ?domain), wait_until_written(Log), ct:pal("N = ~w", [N = Get(current_file, @@ -640,7 +658,7 @@ disk_log_full(Config) -> #{filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}, - disk_log_opts=> + config=> #{type => halt, max_no_files => 1, max_no_bytes => MaxBytes, @@ -652,12 +670,12 @@ disk_log_full(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), NoOfChars = 5, Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)], - [logger:info(Text, ?domain) || _ <- lists:seq(1,trunc(MaxBytes/NoOfChars)+1)], + [logger:notice(Text, ?domain) || _ <- lists:seq(1,trunc(MaxBytes/NoOfChars)+1)], %% wait for trace messages timer:sleep(2000), @@ -701,10 +719,10 @@ disk_log_events(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), - [whereis(?MODULE) ! E || E <- Events], + [whereis(h_proc_name()) ! E || E <- Events], %% wait for trace messages timer:sleep(2000), dbg:stop_clear(), @@ -737,9 +755,15 @@ write_failure(Config) -> ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]), ok = log_on_remote_node(Node, "Logged1"), - rpc:call(Node, logger_disk_log_h, disk_log_sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\n">>}, ?SYNC_REP_INT), + + SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of + true -> 5500; + false -> ?FILESYNC_REPEAT_INTERVAL + 500 + end, + + try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), @@ -757,9 +781,9 @@ write_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), ok = log_on_remote_node(Node, "Logged2"), - rpc:call(Node, logger_disk_log_h, disk_log_sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?SYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> Nodes = nodes(), @@ -782,7 +806,7 @@ sync_failure(Config) -> SyncInt = 500, ok = rpc:call(Node, logger, set_handler_config, - [?STANDARD_HANDLER, logger_disk_log_h, + [?STANDARD_HANDLER, config, #{filesync_repeat_interval => SyncInt}]), Info = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), SyncInt = maps:get(filesync_repeat_interval, Info), @@ -793,7 +817,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,LogOpts,{error,no_such_log}}}), + ?check({error,{?STANDARD_HANDLER,filesync,LogOpts,{error,no_such_log}}}), ok = log_on_remote_node(Node, "No second error printout"), ?check_no_log, @@ -801,7 +825,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,{blocked_log,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,LogOpts, + ?check({error,{?STANDARD_HANDLER,filesync,LogOpts, {error,{blocked_log,?STANDARD_HANDLER}}}}), rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), @@ -817,7 +841,7 @@ start_h_on_new_node(Config, File) -> logger_test_lib:setup( Config, [{logger,[{handler,default,logger_disk_log_h, - #{ disk_log_opts => #{ file => File }}}]}]), + #{ config => #{ file => File }}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. @@ -825,7 +849,7 @@ start_h_on_new_node(Config, File) -> log_on_remote_node(Node,Msg) -> _ = spawn_link(Node, fun() -> erlang:group_leader(whereis(user),self()), - logger:info(Msg) + logger:notice(Msg) end), ok. @@ -852,15 +876,15 @@ op_switch_to_sync(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NumOfReqs = 500, NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => NumOfReqs+1, - flush_reqs_qlen => 2*NumOfReqs, - enable_burst_limit => false}}, + HConfig#{config => DLHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => NumOfReqs+1, + flush_qlen => 2*NumOfReqs, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), - ok = file:delete(Log), NumOfReqs = Lines, + ok = file_delete(Log), ok. op_switch_to_sync(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -876,25 +900,25 @@ op_switch_to_drop(Config) -> Procs = 2, Bursts = 10, NewHConfig = - HConfig#{logger_disk_log_h => - DLHConfig#{toggle_sync_qlen => 1, - drop_new_reqs_qlen => 2, - flush_reqs_qlen => Procs*NumOfReqs*Bursts, - enable_burst_limit => false}}, + HConfig#{config => + DLHConfig#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => Procs*NumOfReqs*Bursts, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), %% It sometimes happens that the handler either gets %% the requests in a slow enough pace so that dropping %% never occurs. Therefore, lets generate a number of %% bursts to increase the chance of message buildup. - [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || _ <- lists:seq(1, Bursts)], Logged = count_lines(Log), - ok= stop_handler(?MODULE), - _ = file:delete(Log), + ok = stop_handler(?MODULE), ct:pal("Number of messages dropped = ~w (~w)", [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), true = (Logged < (Procs*NumOfReqs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -921,12 +945,12 @@ op_switch_to_flush(Config) -> %% (verify with coverage of flush_log_requests/2) NewHConfig = - HConfig#{logger_disk_log_h => - DLHConfig#{toggle_sync_qlen => 2, + HConfig#{config => + DLHConfig#{sync_mode_qlen => 2, %% disable drop mode - drop_new_reqs_qlen => 300, - flush_reqs_qlen => 300, - enable_burst_limit => false}}, + drop_mode_qlen => 300, + flush_qlen => 300, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 1500, Procs = 10, @@ -938,15 +962,15 @@ op_switch_to_flush(Config) -> %% sync messages gets tested). Therefore, lets %% generate a number of bursts to increase the chance %% of message buildup in some random fashion. - [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || _ <- lists:seq(1,Bursts)], Logged = count_lines(Log), ok= stop_handler(?MODULE), - _ = file:delete(Log), ct:pal("Number of messages flushed/dropped = ~w (~w)", [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), true = (Logged < (NumOfReqs*Procs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -964,18 +988,19 @@ op_switch_to_flush(cleanup, _Config) -> limit_burst_disabled(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{enable_burst_limit => false, - burst_limit_size => 10, - burst_window_time => 2000, - drop_new_reqs_qlen => 200, - flush_reqs_qlen => 300}}, + HConfig#{config => DLHConfig#{burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - NumOfReqs = Logged. + NumOfReqs = Logged, + ok = file_delete(Log), + ok. limit_burst_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -983,18 +1008,19 @@ limit_burst_enabled_one(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), ReqLimit = 10, NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{enable_burst_limit => true, - burst_limit_size => ReqLimit, - burst_window_time => 2000, - drop_new_reqs_qlen => 200, - flush_reqs_qlen => 300}}, + HConfig#{config => DLHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - ReqLimit = Logged. + ReqLimit = Logged, + ok = file_delete(Log), + ok. limit_burst_enabled_one(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -1003,58 +1029,59 @@ limit_burst_enabled_period(Config) -> ReqLimit = 10, BurstTWin = 1000, NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{enable_burst_limit => true, - burst_limit_size => ReqLimit, - burst_window_time => BurstTWin, - drop_new_reqs_qlen => 20000, - flush_reqs_qlen => 20001}}, + HConfig#{config => DLHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => BurstTWin, + drop_mode_qlen => 20000, + flush_qlen => 20001}}, ok = logger:set_handler_config(?MODULE, NewHConfig), Windows = 3, - Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, info), + Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", [Sent,Logged]), - ok = file:delete(Log), true = (Logged > (ReqLimit*Windows)) andalso - (Logged < (ReqLimit*(Windows+2))). + (Logged < (ReqLimit*(Windows+2))), + ok = file_delete(Log), + ok. limit_burst_enabled_period(cleanup, _Config) -> ok = stop_handler(?MODULE). kill_disabled(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>false, - handler_overloaded_qlen=>10, - handler_overloaded_mem=>100}}, + HConfig#{config=>DLHConfig#{overload_kill_enable=>false, + overload_kill_qlen=>10, + overload_kill_mem_size=>100}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - true = is_pid(whereis(?MODULE)), + ok = file_delete(Log), + true = is_pid(whereis(h_proc_name())), ok. kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> - {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig = - HConfig#{logger_disk_log_h => - DLHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_overloaded_mem=>Mem0+50000, - handler_restart_after=>RestartAfter}}, + HConfig#{config => + DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_mem_size=>Mem0+50000, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - %% send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive {'DOWN', MRef, _, _, Info} -> case Info of @@ -1063,8 +1090,8 @@ qlen_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), ok after 5000 -> @@ -1076,22 +1103,22 @@ qlen_kill_new(cleanup, _Config) -> ok = stop_handler(?MODULE). mem_kill_new(Config) -> - {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig = - HConfig#{logger_disk_log_h => - DLHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>50000, - handler_overloaded_mem=>Mem0+500, - handler_restart_after=>RestartAfter}}, + HConfig#{config => + DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>50000, + overload_kill_mem_size=>Mem0+500, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - %% send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive {'DOWN', MRef, _, _, Info} -> case Info of @@ -1100,8 +1127,8 @@ mem_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), ok after 5000 -> @@ -1112,53 +1139,58 @@ mem_kill_new(Config) -> mem_kill_new(cleanup, _Config) -> ok = stop_handler(?MODULE). +restart_after() -> + [{timetrap,{minutes,2}}]. restart_after(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig1 = - HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_restart_after=>never}}, + HConfig#{config=>DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>infinity}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), - MRef1 = erlang:monitor(process, whereis(?MODULE)), + MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef1, _, _, _Info1} -> - timer:sleep(?HANDLER_RESTART_AFTER + 1000), - undefined = whereis(?MODULE), + {'DOWN', MRef1, _, _, _Reason1} -> + file_delete(Log), + error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3), ok after 5000 -> + Info1 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig2 = - HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_restart_after=>RestartAfter}}, + HConfig#{config=>DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig2), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef2, _, _, _Info2} -> - timer:sleep(RestartAfter + 2000), - Pid1 = whereis(?MODULE), - true = is_pid(Pid1), + {'DOWN', MRef2, _, _, _Reason2} -> + file_delete(Log), + {ok,Pid1} = wait_for_process_up(RestartAfter * 3), false = (Pid1 == Pid0), ok after 5000 -> + Info2 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info2]), ct:fail("Handler not dead! It should not have survived this!") end, ok. restart_after(cleanup, _Config) -> ok = stop_handler(?MODULE). -%% send handler requests (filesync, info, reset, change_config) +%% send handler requests (sync, info, reset, change_config) %% during high load to verify that sync, dropping and flushing is %% handled correctly. handler_requests_under_load() -> @@ -1166,18 +1198,18 @@ handler_requests_under_load() -> handler_requests_under_load(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 1000, - flush_reqs_qlen => 2000, - enable_burst_limit => false}}, + HConfig#{config => DLHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => 1000, + flush_qlen => 2000, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{disk_log_sync,[]}, + Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, {change_config,[]}]) end), Procs = 100, - Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, info), + Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, notice), Pid ! {self(),finish}, ReqResult = receive {Pid,Result} -> Result end, Logged = count_lines(Log), @@ -1190,7 +1222,7 @@ handler_requests_under_load(Config) -> Errors = [{Req,FindError(Res)} || {Req,Res} <- ReqResult], NoOfReqs = lists:foldl(fun({_,Res}, N) -> N + length(Res) end, 0, ReqResult), ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]), - ok = file:delete(Log). + ok = file_delete(Log). handler_requests_under_load(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -1204,7 +1236,7 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> case Req of change_config -> logger:set_handler_config(HName, logger_disk_log_h, - #{enable_kill_overloaded => + #{overload_kill_enable => false}); Func -> logger_disk_log_h:Func(HName) @@ -1218,21 +1250,22 @@ start_handler(Name, FuncName, Config) -> Dir = ?config(priv_dir,Config), File = filename:join(Dir, FuncName), ct:pal("Logging to ~tp", [File]), + FullFile = lists:concat([File,".1"]), + _ = file_delete(FullFile), ok = logger:add_handler(Name, logger_disk_log_h, - #{disk_log_opts=>#{file => File, - max_no_files => 1, - max_no_bytes => 100000000}, + #{config=>#{file => File, + max_no_files => 1, + max_no_bytes => 100000000}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([Name]), formatter=>{?MODULE,op}}), - {ok,{_,HConfig = #{logger_disk_log_h := DLHConfig}}} = - logger:get_handler_config(Name), - {lists:concat([File,".1"]),HConfig,DLHConfig}. + {ok,HConfig = #{config := DLHConfig}} = logger:get_handler_config(Name), + {FullFile,HConfig,DLHConfig}. stop_handler(Name) -> - ok = logger:remove_handler(Name), - ct:pal("Handler ~p stopped!", [Name]). + ct:pal("Stopping handler ~p!", [Name]), + logger:remove_handler(Name). send_burst(NorT, Type, {chars,Sz}, Class) -> Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], @@ -1255,12 +1288,9 @@ send_n_burst(N, seq, Text, Class) -> send_n_burst(N-1, seq, Text, Class); send_n_burst(N, {spawn,Ps,TO}, Text, Class) -> ct:pal("~w processes each sending ~w messages", [Ps,N]), - PerProc = fun() -> - send_n_burst(N, seq, Text, Class) - end, MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, - monitor(process,spawn_link(PerProc)) end || - _ <- lists:seq(1,Ps)], + monitor(process,spawn_link(per_proc_fun(N,Text,Class,X))) + end || X <- lists:seq(1,Ps)], lists:foreach(fun(MRef) -> receive {'DOWN', MRef, _, _, _} -> @@ -1279,6 +1309,16 @@ send_t_burst(T0, T, Text, Class, N) -> send_t_burst(T0, T, Text, Class, N+1) end. +per_proc_fun(N,Text,Class,X) when X rem 2 == 0 -> + fun() -> + process_flag(priority,high), + send_n_burst(N, seq, Text, Class) + end; +per_proc_fun(N,Text,Class,_) -> + fun() -> + send_n_burst(N, seq, Text, Class) + end. + %%%----------------------------------------------------------------- %%% Formatter callback %%% Using this to send the formatted string back to the test case @@ -1304,9 +1344,11 @@ format(#{msg:={report,#{label:={gen_server,terminate}}}},op) -> ""; format(#{msg:={report,#{label:={proc_lib,crash}}}},op) -> ""; -format(#{msg:={F,A}},Pid) when is_list(F), is_list(A) -> +format(#{msg:={F,A}},OpOrPid) when is_list(F), is_list(A) -> String = lists:flatten(io_lib:format(F,A)), - Pid ! {log,String}, + if is_pid(OpOrPid) -> OpOrPid ! {log,String}; + true -> ok + end, String++"\n"; format(#{msg:={string,String0}},Pid) -> String = unicode:characters_to_list(String0), @@ -1322,16 +1364,17 @@ remove(Handler, LogName) -> HState = #{log_names := Logs} = logger_disk_log_h:info(), false = maps:is_key(LogName, HState), false = lists:member(LogName, Logs), - false = logger_config:exist(logger, LogName), + false = logger_config:exist(?LOGGER_TABLE, LogName), {error,no_such_log} = disk_log:info(LogName), ok. start_and_add(Name, Config, LogOpts) -> - ct:pal("Adding handler ~w with: ~p", - [Name,Config#{disk_log_opts=>LogOpts}]), - ok = logger:add_handler(Name, logger_disk_log_h, - Config#{disk_log_opts=>LogOpts}), - Pid = whereis(Name), + HConfig = maps:get(config, Config, #{}), + HConfig1 = maps:merge(HConfig, LogOpts), + Config1 = Config#{config=>HConfig1}, + ct:pal("Adding handler ~w with: ~p", [Name,Config1]), + ok = logger:add_handler(Name, logger_disk_log_h, Config1), + Pid = whereis(h_proc_name(Name)), true = is_pid(Pid), Name = proplists:get_value(name, disk_log:info(Name)), ok. @@ -1339,7 +1382,7 @@ start_and_add(Name, Config, LogOpts) -> remove_and_stop(Handler) -> ok = logger:remove_handler(Handler), timer:sleep(500), - undefined = whereis(Handler), + undefined = whereis(h_proc_name(Handler)), ok. try_read_file(FileName, Expected, Time) -> @@ -1395,27 +1438,31 @@ wait_until_written(File, Sz) -> {ok,#file_info{size = Sz}} -> timer:sleep(1000), case file:read_file_info(File) of - {ok,#file_info{size = Sz1}} -> + {ok,#file_info{size = Sz}} -> ok; - {ok,#file_info{size = Sz2}} -> - wait_until_written(File, Sz2) + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) end; {ok,#file_info{size = Sz1}} -> wait_until_written(File, Sz1) end. count_lines1(File) -> - Counter = fun Cnt(Dev,LC) -> - case file:read_line(Dev) of - eof -> LC; - _ -> Cnt(Dev,LC+1) - end - end, {_,Dev} = file:open(File, [read]), - Lines = Counter(Dev, 0), + Lines = count_lines2(Dev, 0), file:close(Dev), Lines. +count_lines2(Dev, LC) -> + case file:read_line(Dev) of + {ok,"Handler logger_disk_log_h_SUITE " ++_} -> + %% Not counting handler info + count_lines2(Dev,LC); + {ok,_} -> + count_lines2(Dev,LC+1); + eof -> LC + end. + repeat_until_ok(Fun, N) -> repeat_until_ok(Fun, 0, N, undefined). @@ -1442,7 +1489,7 @@ repeat_until_ok(Fun, C, Stop, FirstReason) -> start_tracer(Trace,Expected) -> Pid = self(), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), - dbg:p(whereis(?MODULE),[c]), + dbg:p(h_proc_name(),[c]), tpl(Trace), ok. @@ -1498,3 +1545,31 @@ escape([H|T]) -> [H|escape(T)]; escape([]) -> []. + +h_proc_name() -> + h_proc_name(?MODULE). +h_proc_name(Name) -> + list_to_atom(lists:concat([logger_disk_log_h,"_",Name])). + +file_delete(Log) -> + file:delete(Log). + +wait_for_process_up(T) -> + wait_for_process_up(h_proc_name(),T). + +wait_for_process_up(Name,T) -> + N = (T div 500) + 1, + wait_for_process_up1(Name,N). + +wait_for_process_up1(Name,0) -> + error; +wait_for_process_up1(Name,N) -> + timer:sleep(500), + case whereis(Name) of + Pid when is_pid(Pid) -> + %% ct:pal("Process ~p up (~p tries left)",[Name,N]), + {ok,Pid}; + undefined -> + %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), + wait_for_process_up1(Name,N-1) + end. diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index 601d331fb0..04a4364947 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -63,8 +63,7 @@ groups() -> ]}, {bad,[],[bad_error_logger, bad_level, - bad_sasl_compatibility, - bad_progress]}]. + bad_sasl_compatibility]}]. all() -> [default, @@ -78,128 +77,126 @@ all() -> ]. default(Config) -> - {ok,#{handlers:=Hs},_Node} = setup(Config,[]), - {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), - info = maps:get(level,StdC), + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},_Node} = setup(Config,[]), + notice = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - true = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), + [] = ML, ok. default_sasl_compatible(Config) -> - {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), + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},_Node} = + setup(Config,[{logger_sasl_compatible,true}]), + info = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - true = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + true = exists(sasl,Hs), + [] = ML, ok. 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), + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},_Node} = + setup(Config,[{error_logger,tty}]), + notice = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - true = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), + [] = ML, ok. 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), + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},_Node} = + setup(Config, + [{error_logger,tty}, + {logger_sasl_compatible,true}]), + info = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - true = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + true = exists(sasl,Hs), + [] = ML, ok. error_logger_false(Config) -> - {ok,#{handlers:=Hs,logger:=L},_Node} = + {ok,#{handlers:=Hs,primary:=P,module_levels:=ML},_Node} = setup(Config, [{error_logger,false}, {logger_level,notice}]), - false = lists:keymember(?STANDARD_HANDLER,1,Hs), - {simple,logger_simple_h,SimpleC} = lists:keyfind(simple,1,Hs), - info = maps:get(level,SimpleC), - notice = maps:get(level,L), + false = exists(?STANDARD_HANDLER,Hs), + #{module:=logger_simple_h} = SimpleC = find(simple,Hs), + all = maps:get(level,SimpleC), + notice = maps:get(level,P), SimpleFilters = maps:get(filters,SimpleC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,SimpleFilters), - true = lists:keymember(stop_progress,1,SimpleFilters), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), + false = exists(sasl,Hs), + [] = ML, ok. error_logger_false_progress(Config) -> - {ok,#{handlers:=Hs,logger:=L},_Node} = + {ok,#{handlers:=Hs,primary:=P,module_levels:=ML},_Node} = setup(Config, [{error_logger,false}, - {logger_level,notice}, - {logger_progress_reports,log}]), - false = lists:keymember(?STANDARD_HANDLER,1,Hs), - {simple,logger_simple_h,SimpleC} = lists:keyfind(simple,1,Hs), - info = maps:get(level,SimpleC), - notice = maps:get(level,L), + {logger_level,notice}]), + false = exists(?STANDARD_HANDLER,Hs), + #{module:=logger_simple_h} = SimpleC = find(simple,Hs), + all = maps:get(level,SimpleC), + notice = maps:get(level,P), SimpleFilters = maps:get(filters,SimpleC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,SimpleFilters), - false = lists:keymember(stop_progress,1,SimpleFilters), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), + false = exists(sasl,Hs), + [] = ML, ok. error_logger_false_sasl_compatible(Config) -> - {ok,#{handlers:=Hs,logger:=L},_Node} = + {ok,#{handlers:=Hs,primary:=P,module_levels:=ML},_Node} = setup(Config, [{error_logger,false}, {logger_level,notice}, {logger_sasl_compatible,true}]), - false = lists:keymember(?STANDARD_HANDLER,1,Hs), - {simple,logger_simple_h,SimpleC} = lists:keyfind(simple,1,Hs), - info = maps:get(level,SimpleC), - notice = maps:get(level,L), + false = exists(?STANDARD_HANDLER,Hs), + #{module:=logger_simple_h} = SimpleC = find(simple,Hs), + all = maps:get(level,SimpleC), + info = maps:get(level,P), SimpleFilters = maps:get(filters,SimpleC), - {domain,{_,{log,super,[beam,erlang,otp]}}} = - lists:keyfind(domain,1,SimpleFilters), - false = lists:keymember(stop_progress,1,SimpleFilters), - true = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp]}}} = lists:keyfind(domain,1,SimpleFilters), + true = exists(sasl,Hs), + [] = ML, ok. error_logger_silent(Config) -> {ok,#{handlers:=Hs},_Node} = setup(Config, [{error_logger,silent}]), - false = lists:keymember(?STANDARD_HANDLER,1,Hs), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + false = exists(?STANDARD_HANDLER,Hs), + false = exists(simple,Hs), + false = exists(sasl,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(simple,1,Hs), - true = lists:keymember(sasl,1,Hs), + false = exists(?STANDARD_HANDLER,Hs), + false = exists(simple,Hs), + true = exists(sasl,Hs), ok. error_logger_file(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,_Hs,Node} = setup(Config, - [{error_logger,{file,Log}}]), + {ok,_,Node} = setup(Config, + [{error_logger,{file,Log}}]), check_default_log(Node,Log, file,% dest 0),% progress in std logger @@ -208,70 +205,68 @@ error_logger_file(Config) -> logger_file(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,#{handlers:=Hs},Node} + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},Node} = setup(Config, [{logger, [{handler,?STANDARD_HANDLER,logger_std_h, - #{logger_std_h=>#{type=>{file,Log}}}}]}]), + #{config=>#{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), + notice = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - true = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), - + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), + [] = ML, ok. logger_file_sasl_compatible(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,#{handlers:=Hs},Node} + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},Node} = setup(Config, [{logger_sasl_compatible,true}, {logger, [{handler,?STANDARD_HANDLER,logger_std_h, - #{logger_std_h=>#{type=>{file,Log}}}}]}]), + #{config=>#{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), + info = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - true = lists:keymember(sasl,1,Hs), - + {domain,{_,{log,super,[otp]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + true = exists(sasl,Hs), + [] = ML, ok. logger_file_log_progress(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,#{handlers:=Hs},Node} + {ok,#{primary:=P,handlers:=Hs,module_levels:=ML},Node} = setup(Config, - [{logger_progress_reports,log}, + [{logger_level,info}, {logger, [{handler,?STANDARD_HANDLER,logger_std_h, - #{logger_std_h=>#{type=>{file,Log}}}}]}]), + #{config=>#{type=>{file,Log}}}}]}]), check_default_log(Node,Log, file,% dest - 6),% progress in std logger + 6,% progress in std logger + info), - {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), - info = maps:get(level,StdC), + info = maps:get(level,P), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), - + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), + [] = ML, ok. logger_file_no_filter(Config) -> @@ -281,16 +276,16 @@ logger_file_no_filter(Config) -> [{logger, [{handler,?STANDARD_HANDLER,logger_std_h, #{filter_default=>log,filters=>[], - logger_std_h=>#{type=>{file,Log}}}}]}]), + config=>#{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), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), [] = maps:get(filters,StdC), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + false = exists(simple,Hs), + false = exists(sasl,Hs), ok. @@ -301,17 +296,17 @@ logger_file_no_filter_level(Config) -> [{logger, [{handler,?STANDARD_HANDLER,logger_std_h, #{filters=>[],level=>error, - logger_std_h=>#{type=>{file,Log}}}}]}]), + config=>#{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), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), error = maps:get(level,StdC), [] = maps:get(filters,StdC), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + false = exists(simple,Hs), + false = exists(sasl,Hs), ok. @@ -323,68 +318,67 @@ logger_file_formatter(Config) -> [{handler,?STANDARD_HANDLER,logger_std_h, #{filters=>[], formatter=>{logger_formatter,#{}}, - logger_std_h=>#{type=>{file,Log}}}}]}]), + config=>#{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), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), [] = maps:get(filters,StdC), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + false = exists(simple,Hs), + false = exists(sasl,Hs), ok. logger_filters(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,#{handlers:=Hs,logger:=Logger},Node} + {ok,#{handlers:=Hs,primary:=P},Node} = setup(Config, - [{logger_progress_reports,log}, + [{logger_level,info}, {logger, [{handler,?STANDARD_HANDLER,logger_std_h, - #{logger_std_h=>#{type=>{file,Log}}}}, + #{config=>#{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 + 0,% progress in std logger + info), - {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), - info = maps:get(level,StdC), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), - LoggerFilters = maps:get(filters,Logger), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), + LoggerFilters = maps:get(filters,P), true = lists:keymember(stop_progress,1,LoggerFilters), ok. logger_filters_stop(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,#{handlers:=Hs,logger:=Logger},Node} + {ok,#{handlers:=Hs,primary:=P},Node} = setup(Config, - [{logger_progress_reports,log}, + [{logger_level,info}, {logger, [{handler,?STANDARD_HANDLER,logger_std_h, #{filters=>[], - logger_std_h=>#{type=>{file,Log}}}}, + config=>#{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 + 0,% progress in std logger + info), - {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), - info = maps:get(level,StdC), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), [] = maps:get(filters,StdC), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), - LoggerFilters = maps:get(filters,Logger), + false = exists(simple,Hs), + false = exists(sasl,Hs), + LoggerFilters = maps:get(filters,P), true = lists:keymember(log_error,1,LoggerFilters), ok. @@ -393,24 +387,23 @@ logger_module_level(Config) -> Log = file(Config,?FUNCTION_NAME), {ok,#{handlers:=Hs,module_levels:=ModuleLevels},Node} = setup(Config, - [{logger_progress_reports,log}, + [{logger_level,info}, {logger, [{handler,?STANDARD_HANDLER,logger_std_h, - #{logger_std_h=>#{type=>{file,Log}}}}, + #{config=>#{type=>{file,Log}}}}, {module_level,error,[supervisor]} ]}]), check_default_log(Node,Log, file,% dest - 3),% progress in std logger + 3,% progress in std logger + info), - {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), - info = maps:get(level,StdC), + #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - false = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), [{supervisor,error}] = ModuleLevels, ok. @@ -420,19 +413,17 @@ logger_disk_log(Config) -> = setup(Config, [{logger, [{handler,?STANDARD_HANDLER,logger_disk_log_h, - #{disk_log_opts=>#{file=>Log}}}]}]), + #{config=>#{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), + #{module:=logger_disk_log_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,StdFilters), - true = lists:keymember(stop_progress,1,StdFilters), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,StdFilters), + false = exists(simple,Hs), + false = exists(sasl,Hs), ok. @@ -444,31 +435,29 @@ logger_disk_log_formatter(Config) -> [{handler,?STANDARD_HANDLER,logger_disk_log_h, #{filters=>[], formatter=>{logger_formatter,#{}}, - disk_log_opts=>#{file=>Log}}}]}]), + config=>#{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), + #{module:=logger_disk_log_h} = StdC = find(?STANDARD_HANDLER,Hs), + all = maps:get(level,StdC), [] = maps:get(filters,StdC), - false = lists:keymember(simple,1,Hs), - false = lists:keymember(sasl,1,Hs), + false = exists(simple,Hs), + false = exists(sasl,Hs), ok. logger_undefined(Config) -> - {ok,#{handlers:=Hs,logger:=L},_Node} = + {ok,#{handlers:=Hs,primary:=P},_Node} = setup(Config,[{logger,[{handler,?STANDARD_HANDLER,undefined}]}]), - false = lists:keymember(?STANDARD_HANDLER,1,Hs), - {simple,logger_simple_h,SimpleC} = lists:keyfind(simple,1,Hs), - info = maps:get(level,SimpleC), - info = maps:get(level,L), + false = exists(?STANDARD_HANDLER,Hs), + #{module:=logger_simple_h} = SimpleC = find(simple,Hs), + all = maps:get(level,SimpleC), + notice = maps:get(level,P), SimpleFilters = maps:get(filters,SimpleC), - {domain,{_,{log,super,[beam,erlang,otp,sasl]}}} = - lists:keyfind(domain,1,SimpleFilters), - true = lists:keymember(stop_progress,1,SimpleFilters), - false = lists:keymember(sasl,1,Hs), + {domain,{_,{log,super,[otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), + false = exists(sasl,Hs), ok. @@ -483,14 +472,15 @@ logger_many_handlers_default_first(Config) -> #{level=>error, filters=>[], formatter=>{logger_formatter,#{}}, - logger_std_h=>#{type=>{file,LogErr}}} + config=>#{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}}} + config=>#{type=>{file,LogInfo}}} } - ]}], LogErr, LogInfo, 6). + ]}, + {logger_level,info}], LogErr, LogInfo, 6). %% Test that we can add multiple handlers with the default last logger_many_handlers_default_last(Config) -> @@ -501,15 +491,16 @@ logger_many_handlers_default_last(Config) -> [{handler,info,logger_std_h, #{level=>info, filters=>[{level,{fun logger_filters:level/2,{stop,gteq,error}}}], - logger_std_h=>#{type=>{file,LogInfo}}} + config=>#{type=>{file,LogInfo}}} }, {handler,?STANDARD_HANDLER,logger_std_h, #{level=>error, filters=>[], formatter=>{logger_formatter,#{}}, - logger_std_h=>#{type=>{file,LogErr}}} + config=>#{type=>{file,LogErr}}} } - ]}], LogErr, LogInfo, 7). + ]}, + {logger_level,info}], LogErr, LogInfo, 7). %% Check that we can handle that an added logger has a broken filter %% This used to cause a deadlock. @@ -523,18 +514,19 @@ logger_many_handlers_default_last_broken_filter(Config) -> #{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}}} + config=>#{type=>{file,LogInfo}}} }, {handler,?STANDARD_HANDLER,logger_std_h, #{level=>error, filters=>[], formatter=>{logger_formatter,#{}}, - logger_std_h=>#{type=>{file,LogErr}}} + config=>#{type=>{file,LogErr}}} } - ]}], LogErr, LogInfo, 7). + ]}, + {logger_level,info}], LogErr, LogInfo, 7). logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> - {ok,#{handlers:=Hs},Node} = setup(Config,Env), + {ok,_,Node} = setup(Config,Env), check_single_log(Node,LogErr, file,% dest 0,% progress in std logger @@ -542,28 +534,29 @@ logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> ok = rpc:call(Node,logger_std_h,filesync,[info]), {ok, Bin} = file:read_file(LogInfo), ct:log("Log content:~n~s",[Bin]), - match(Bin,<<"info:">>,NumProgress+1,info,info), + match(Bin,<<"info:">>,NumProgress,info,info), + match(Bin,<<"notice:">>,1,notice,info), match(Bin,<<"alert:">>,0,alert,info), ok. sasl_compatible_false(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,_Hs,Node} = setup(Config, - [{error_logger,{file,Log}}, - {logger_sasl_compatible,false}, - {logger_progress_reports,log}]), + {ok,_,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}, + {logger_level,info}]), % to get progress check_default_log(Node,Log, file,% dest - 6),% progress in std logger + 6,% progress in std logger + info), ok. sasl_compatible_false_no_progress(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,_Hs,Node} = setup(Config, - [{error_logger,{file,Log}}, - {logger_sasl_compatible,false}, - {logger_progress_reports,stop}]), + {ok,_,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}]), check_default_log(Node,Log, file,% dest 0),% progress in std logger @@ -571,9 +564,9 @@ sasl_compatible_false_no_progress(Config) -> sasl_compatible(Config) -> Log = file(Config,?FUNCTION_NAME), - {ok,_Hs,Node} = setup(Config, - [{error_logger,{file,Log}}, - {sasl_compatible,true}]), + {ok,_,Node} = setup(Config, + [{error_logger,{file,Log}}, + {sasl_compatible,true}]), check_default_log(Node,Log, file,% dest 0),% progress in std logger @@ -588,9 +581,6 @@ bad_level(Config) -> bad_sasl_compatibility(Config) -> error = setup(Config,[{logger_sasl_compatible,badcomp}]). -bad_progress(Config) -> - error = setup(Config,[{logger_progress_reports,badprogress}]). - %%%----------------------------------------------------------------- %%% Internal file(Config,Func) -> @@ -598,22 +588,22 @@ file(Config,Func) -> 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,notice). 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,<<"INFO REPORT">>,0,notice,Level), match(Bin1,<<"DEBUG REPORT">>,0,debug,Level), - match(Bin2,<<"INFO REPORT">>,1,info,Level), + match(Bin2,<<"INFO REPORT">>,1,notice,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,notice). check_single_log(Node,Log,Dest,NumProgress,Level) -> {ok,Bin1,Bin2} = check_log(Node,Log,Dest), @@ -654,3 +644,21 @@ match(Bin,Pattern,N,LogLevel,ConfLevel) -> {match,M} = re:run(Bin,Pattern,[{capture,all},global]), N = length(M) end. + +find(Id,Handlers) -> + case lists:search(fun(#{id:=Id0}) when Id0=:=Id-> true; + (_) -> false end, + Handlers) of + {value,Config} -> + Config; + false -> + false + end. + +exists(Id,Handlers) -> + case find(Id,Handlers) of + false -> + false; + _ -> + true + end. diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 7a93f2ca79..8fe8d5199b 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -56,6 +56,7 @@ groups() -> all() -> [default, legacy_header, + error_logger_notice_header, single_line, template, format_msg, @@ -69,6 +70,7 @@ all() -> faulty_log, faulty_config, faulty_msg, + check_config, update_config]. default(_Config) -> @@ -124,6 +126,34 @@ legacy_header(_Config) -> "=INFO REPORT==== "++_ = String5, ok. +error_logger_notice_header(_Config) -> + Meta1 = #{error_logger=>#{tag => info_report,type => std_info}}, + String1 = format(notice,{"~p",[term]},Meta1, + #{legacy_header=>true, + error_logger_notice_header=>notice}), + ct:log(String1), + "=NOTICE REPORT==== "++_ = String1, + + String2 = format(notice,{"~p",[term]},Meta1, + #{legacy_header=>true, + error_logger_notice_header=>info}), + ct:log(String2), + "=INFO REPORT==== "++_ = String2, + + String3 = format(notice,{"~p",[term]},#{}, + #{legacy_header=>true, + error_logger_notice_header=>notice}), + ct:log(String3), + "=NOTICE REPORT==== "++_ = String3, + + String4 = format(notice,{"~p",[term]},#{}, + #{legacy_header=>true, + error_logger_notice_header=>info}), + ct:log(String4), + "=NOTICE REPORT==== "++_ = String4, + + ok. + single_line(_Config) -> Time = timestamp(), ExpectedTimestamp = default_time_format(Time), @@ -158,7 +188,7 @@ template(_Config) -> Template4 = ["string\nnewline"], String4 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template4, - single_line=>true}), + single_line=>true}), ct:log(String4), "string\nnewline" = String4, @@ -178,8 +208,8 @@ template(_Config) -> time=>Time, tuple=>{1,atom,"list"}, nested=>#{subkey=>subvalue}}, - Template6 = lists:join(";",maps:keys(maps:remove(nested,Meta6)) ++ - [{nested,subkey}]), + Template6 = lists:join(";",lists:sort(maps:keys(maps:remove(nested,Meta6))) ++ + [[nested,subkey]]), String6 = format(info,{"~p",[term]},Meta6,#{template=>Template6, single_line=>true}), ct:log(String6), @@ -202,16 +232,16 @@ template(_Config) -> nested=>#{key1=>#{subkey1=>value1}, key2=>value2}}, Template7 = lists:join(";",[nested, - {nested,key1}, - {nested,key1,subkey1}, - {nested,key2}, - {nested,key2,subkey2}, - {nested,key3}, - {nested,key3,subkey3}]), + [nested,key1], + [nested,key1,subkey1], + [nested,key2], + [nested,key2,subkey2], + [nested,key3], + [nested,key3,subkey3]]), String7 = format(info,{"~p",[term]},Meta7,#{template=>Template7, single_line=>true}), ct:log(String7), - [MultipleKeysStr, + [MultipleKeysStr7, "#{subkey1 => value1}", "value1", "value2", @@ -219,11 +249,42 @@ template(_Config) -> "", ""] = string:split(String7,";",all), %% Order of keys is not fixed - case MultipleKeysStr of + case MultipleKeysStr7 of "#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok; "#{key1 => #{subkey1 => value1},key2 => value2}" -> ok; - _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr}) + _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr7}) + end, + + Meta8 = #{time=>Time, + nested=>#{key1=>#{subkey1=>value1}, + key2=>value2}}, + Template8 = + lists:join( + ";", + [{nested,["exist:",nested],["noexist"]}, + {[nested,key1],["exist:",[nested,key1]],["noexist"]}, + {[nested,key1,subkey1],["exist:",[nested,key1,subkey1]],["noexist"]}, + {[nested,key2],["exist:",[nested,key2]],["noexist"]}, + {[nested,key2,subkey2],["exist:",[nested,key2,subkey2]],["noexist"]}, + {[nested,key3],["exist:",[nested,key3]],["noexist"]}, + {[nested,key3,subkey3],["exist:",[nested,key3,subkey3]],["noexist"]}]), + String8 = format(info,{"~p",[term]},Meta8,#{template=>Template8, + single_line=>true}), + ct:log(String8), + [MultipleKeysStr8, + "exist:#{subkey1 => value1}", + "exist:value1", + "exist:value2", + "noexist", + "noexist", + "noexist"] = string:split(String8,";",all), + %% Order of keys is not fixed + case MultipleKeysStr8 of + "exist:#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok; + "exist:#{key1 => #{subkey1 => value1},key2 => value2}" -> ok; + _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr8}) end, + ok. format_msg(_Config) -> @@ -541,23 +602,113 @@ faulty_msg(_Config) -> #{})), ok. +-define(cfgerr(X), {error,{invalid_formatter_config,logger_formatter,X}}). +check_config(_Config) -> + ok = logger_formatter:check_config(#{}), + ?cfgerr(bad) = logger_formatter:check_config(bad), + + C1 = #{chars_limit => 1, + depth => 1, + legacy_header => true, + error_logger_notice_header => info, + max_size => 1, + report_cb => fun(R) -> {"~p",[R]} end, + single_line => false, + template => [], + time_designator => $T, + time_offset => 0}, + ok = logger_formatter:check_config(C1), + + ok = logger_formatter:check_config(#{chars_limit => unlimited}), + ?cfgerr({chars_limit,bad}) = + logger_formatter:check_config(#{chars_limit => bad}), + + ok = logger_formatter:check_config(#{depth => unlimited}), + ?cfgerr({depth,bad}) = + logger_formatter:check_config(#{depth => bad}), + + ok = logger_formatter:check_config(#{legacy_header => false}), + ?cfgerr({legacy_header,bad}) = + logger_formatter:check_config(#{legacy_header => bad}), + + ok = logger_formatter:check_config(#{error_logger_notice_header => notice}), + ?cfgerr({error_logger_notice_header,bad}) = + logger_formatter:check_config(#{error_logger_notice_header => bad}), + + ok = logger_formatter:check_config(#{max_size => unlimited}), + ?cfgerr({max_size,bad}) = + logger_formatter:check_config(#{max_size => bad}), + + ?cfgerr({report_cb,F}) = + logger_formatter:check_config(#{report_cb => F=fun(_,_) -> {"",[]} end}), + ?cfgerr({report_cb,bad}) = + logger_formatter:check_config(#{report_cb => bad}), + + ok = logger_formatter:check_config(#{single_line => true}), + ?cfgerr({single_line,bad}) = + logger_formatter:check_config(#{single_line => bad}), + + Ts = [[key], + [[key1,key2]], + [{key,[key],[]}], + [{[key1,key2],[[key1,key2]],["noexist"]}], + ["string"]], + [begin + ct:log("check template: ~p",[T]), + ok = logger_formatter:check_config(#{template => T}) + end + || T <- Ts], + + ETs = [bad, + [{key,bad}], + [{key,[key],bad}], + [{key,[key],"bad"}], + "bad", + [[key,$a,$b,$c]], + [[$a,$b,$c,key]]], + [begin + ct:log("check template: ~p",[T]), + {error,{invalid_formatter_template,logger_formatter,T}} = + logger_formatter:check_config(#{template => T}) + end + || T <- ETs], + + ?cfgerr({time_designator,bad}) = + logger_formatter:check_config(#{time_designator => bad}), + ?cfgerr({time_designator,"b"}) = + logger_formatter:check_config(#{time_designator => "b"}), + + ok = logger_formatter:check_config(#{time_offset => -1}), + ok = logger_formatter:check_config(#{time_offset => "+02:00"}), + ok = logger_formatter:check_config(#{time_offset => "-23:59"}), + ok = logger_formatter:check_config(#{time_offset => "+24:00"}), + ok = logger_formatter:check_config(#{time_offset => "-25:00"}), + ?cfgerr({time_offset,bad}) = + logger_formatter:check_config(#{time_offset => bad}), + ?cfgerr({time_offset,"02:00"}) = + logger_formatter:check_config(#{time_offset => "02:00"}), + ?cfgerr({time_offset,"+02"}) = + logger_formatter:check_config(#{time_offset => "+02"}), + + ok. + %% Test that formatter config can be changed, and that the default %% template is updated accordingly update_config(_Config) -> logger:add_handler_filter(default,silence,{fun(_,_) -> stop end,ok}), ok = logger:add_handler(?MODULE,?MODULE,#{}), D = lists:seq(1,1000), - logger:info("~p~n",[D]), + logger:notice("~p~n",[D]), {Lines1,C1} = check_log(), [ct:log(L) || L <- Lines1], ct:log("~p",[C1]), [Line1] = Lines1, - [_Time,"info: "++D1] = string:split(Line1," "), + [_Time,"notice: "++D1] = string:split(Line1," "), true = length(D1)>3000, true = #{}==C1, ok = logger:update_formatter_config(?MODULE,single_line,false), - logger:info("~p~n",[D]), + logger:notice("~p~n",[D]), {Lines2,C2} = check_log(), [ct:log(L) || L <- Lines2], ct:log("~p",[C2]), @@ -565,23 +716,37 @@ update_config(_Config) -> true = #{single_line=>false}==C2, ok = logger:update_formatter_config(?MODULE,#{legacy_header=>true}), - logger:info("~p~n",[D]), + logger:notice("~p~n",[D]), {Lines3,C3} = check_log(), [ct:log(L) || L <- Lines3], ct:log("~p",[C3]), - ["=INFO REPORT==== "++_|D3] = Lines3, + ["=NOTICE REPORT==== "++_|D3] = Lines3, true = length(D3)>50, true = #{legacy_header=>true,single_line=>false}==C3, ok = logger:update_formatter_config(?MODULE,single_line,true), - logger:info("~p~n",[D]), + logger:notice("~p~n",[D]), {Lines4,C4} = check_log(), [ct:log(L) || L <- Lines4], ct:log("~p",[C4]), - ["=INFO REPORT==== "++_,D4] = Lines4, + ["=NOTICE REPORT==== "++_,D4] = Lines4, true = length(D4)>3000, true = #{legacy_header=>true,single_line=>true}==C4, + %% Finally, check that error_logger_notice_header works, default=info + error_logger:info_msg("~p",[D]), + {Lines5,C5} = check_log(), + [ct:log(L) || L <- Lines5], + ct:log("~p",[C5]), + ["=INFO REPORT==== "++_,_D5] = Lines5, + + ok=logger:update_formatter_config(?MODULE,error_logger_notice_header,notice), + error_logger:info_msg("~p",[D]), + {Lines6,C6} = check_log(), + [ct:log(L) || L <- Lines6], + ct:log("~p",[C6]), + ["=NOTICE REPORT==== "++_,_D6] = Lines6, + ok. update_config(cleanup,_Config) -> diff --git a/lib/kernel/test/logger_legacy_SUITE.erl b/lib/kernel/test/logger_legacy_SUITE.erl index cfba35e43f..c3cab07d81 100644 --- a/lib/kernel/test/logger_legacy_SUITE.erl +++ b/lib/kernel/test/logger_legacy_SUITE.erl @@ -20,6 +20,8 @@ -module(logger_legacy_SUITE). -compile(export_all). +-compile({nowarn_deprecated_function,[{gen_fsm,start,3}, + {gen_fsm,send_all_state_event,2}]}). -include_lib("common_test/include/ct.hrl"). -include_lib("kernel/include/logger.hrl"). @@ -67,25 +69,29 @@ end_per_suite(_Config) -> init_per_group(std, Config) -> ok = logger:set_handler_config( error_logger,filters, - [{domain,{fun logger_filters:domain/2, - {log,super,[beam,erlang,otp]}}}]), + [{domain,{fun logger_filters:domain/2,{log,super,[otp]}}}]), Config; init_per_group(sasl, Config) -> + %% Since default level is notice, and progress reports are info, + %% we need to raise the global logger level to info in order to + %% receive these. + ok = logger:set_primary_config(level,info), ok = logger:set_handler_config( error_logger,filters, - [{domain,{fun logger_filters:domain/2, - {log,super,[beam,erlang,otp,sasl]}}}]), + [{domain,{fun logger_filters:domain/2,{log,super,[otp,sasl]}}}]), %% cth_log_redirect checks if sasl is started before displaying %% any sasl reports - so just to see the real sasl reports in tc %% log: - application:start(sasl), - Config; + {ok,Apps} = application:ensure_all_started(sasl), + [{stop_apps,Apps}|Config]; init_per_group(_Group, Config) -> Config. -end_per_group(sasl, _Config) -> - application:stop(sasl), +end_per_group(sasl, Config) -> + Apps = ?config(stop_apps,Config), + [application:stop(App) || App <- Apps], + ok = logger:set_primary_config(level,notice), ok; end_per_group(_Group, _Config) -> ok. @@ -119,7 +125,7 @@ all() -> gen_server(_Config) -> {ok,Pid} = gen_server:start(?MODULE,gen_server,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), ok = gen_server:cast(Pid,Msg), @@ -129,7 +135,7 @@ gen_server(_Config) -> gen_event(_Config) -> {ok,Pid} = gen_event:start(), ok = gen_event:add_handler(Pid,?MODULE,gen_event), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~tp"++_,[?MODULE,Msg]}), gen_event:notify(Pid,Msg), @@ -138,7 +144,7 @@ gen_event(_Config) -> gen_fsm(_Config) -> {ok,Pid} = gen_fsm:start(?MODULE,gen_fsm,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), gen_fsm:send_all_state_event(Pid,Msg), @@ -147,7 +153,7 @@ gen_fsm(_Config) -> gen_statem(_Config) -> {ok,Pid} = gen_statem:start(?MODULE,gen_statem,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({error,"** State machine ~tp terminating"++_, [Pid,{info,Msg},{mystate,gen_statem},error,{badmatch,b}|_]}). @@ -176,7 +182,7 @@ sasl_reports(Config) -> ok = gen_server:cast(ChPid, fun() -> spawn_link(fun() -> receive x->ok end end) end), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, ok = gen_server:cast(ChPid,Msg), ?check_no_flush({error,"** Generic server ~tp terminating"++_, [ChPid,{'$gen_cast',Msg},gen_server,{{badmatch,b},_}]}), diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl index 271a2126de..79e5c057ad 100644 --- a/lib/kernel/test/logger_simple_h_SUITE.erl +++ b/lib/kernel/test/logger_simple_h_SUITE.erl @@ -48,7 +48,7 @@ suite() -> {ct_hooks, [logger_test_lib]}]. init_per_suite(Config) -> - #{handlers:=Hs0} = logger:i(), + Hs0 = logger:get_handler_config(), Hs = lists:keydelete(cth_log_redirect,1,Hs0), [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], Env = [{App,Key,application:get_env(App,Key)} || @@ -107,15 +107,15 @@ start_stop(cleanup,_Config) -> replace_default(Config) -> {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]]), + log(Node, emergency, [?str]), + log(Node, alert, [?str,[]]), + log(Node, error, [?map_rep]), + log(Node, info, [?keyval_rep]), + log(Node, info, [?keyval_rep++[not_key_val]]), + rpc:call(Node, error_logger, error_report, [some_type,?map_rep]), + rpc:call(Node, error_logger, warning_report, ["some_type",?map_rep]), + 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]), @@ -127,18 +127,18 @@ replace_file(Config) -> {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]]), + log(Node, error, [?map_rep]), + log(Node, warning, [?keyval_rep]), + log(Node, warning, [?keyval_rep++[not_key_val]]), + log(Node, critical, [?str,[?keyval_rep]]), + log(Node, notice, [["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} }, + #{ config => #{ type => {file, File} }, formatter => {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}}]]), {ok,Bin} = sync_and_read(Node, file, File), @@ -151,10 +151,10 @@ replace_file(Config) -> "=ERROR REPORT===="++_, _, _, - "=INFO REPORT===="++_, + "=WARNING REPORT===="++_, _, _, - "=INFO REPORT===="++_, + "=WARNING REPORT===="++_, _, _, _, @@ -171,18 +171,18 @@ replace_disk_log(Config) -> {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]]), + log(Node, error, [?map_rep]), + log(Node, warning, [?keyval_rep]), + log(Node, warning, [?keyval_rep++[not_key_val]]), + log(Node, critical, [?str,[?keyval_rep]]), + log(Node, notice, [["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 }, + #{ config => #{ file => File }, formatter => {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}}]]), {ok,Bin} = sync_and_read(Node, disk_log, File), Lines = [unicode:characters_to_list(L) || @@ -194,10 +194,10 @@ replace_disk_log(Config) -> "=ERROR REPORT===="++_, _, _, - "=INFO REPORT===="++_, + "=WARNING REPORT===="++_, _, _, - "=INFO REPORT===="++_, + "=WARNING REPORT===="++_, _, _, _, diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 5764abd063..ca54458ac1 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -45,17 +45,13 @@ -define(bin(Msg), list_to_binary(Msg++"\n")). -define(domain,#{domain=>[?MODULE]}). --define(FILESYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500; - true -> ?FILESYNC_REPEAT_INTERVAL + 500 - end). - suite() -> [{timetrap,{seconds,30}}, {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> timer:start(), % to avoid progress report - {ok,{logger_std_h,#{formatter:=OrigFormatter}}} = + {ok,#{formatter:=OrigFormatter}} = logger:get_handler_config(?STANDARD_HANDLER), [{formatter,OrigFormatter}|Config]. @@ -73,12 +69,25 @@ end_per_group(_Group, _Config) -> init_per_testcase(TestHooksCase, Config) when TestHooksCase == write_failure; TestHooksCase == sync_failure -> - if ?TEST_HOOKS_TAB == undefined -> + case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of + true -> {skip,"Define the TEST_HOOKS macro to run this test"}; - true -> + false -> ct:print("********** ~w **********", [TestHooksCase]), Config end; +init_per_testcase(OPCase, Config) when + OPCase == qlen_kill_new; + OPCase == restart_after -> + case re:run(erlang:system_info(system_version), + "dirty-schedulers-TEST", + [{capture,none}]) of + match -> + {skip,"Overload protection test skipped on dirty-schedulers-TEST"}; + nomatch -> + ct:print("********** ~w **********", [OPCase]), + Config + end; init_per_testcase(TestCase, Config) -> ct:print("********** ~w **********", [TestCase]), Config. @@ -108,7 +117,7 @@ all() -> info_and_reset, reconfig, file_opts, - filesync, + sync, write_failure, sync_failure, op_switch_to_sync_file, @@ -132,7 +141,7 @@ all() -> add_remove_instance_tty(_Config) -> {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{type => tty}, + #{config => #{type => tty}, filter_default=>log, formatter=>{?MODULE,self()}}), ok. @@ -166,33 +175,33 @@ add_remove_instance_file2(cleanup,_Config) -> add_remove_instance_file(Log, Type) -> ok = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => Type}, + #{config => #{type => Type}, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), - logger:info(M1=?msg,?domain), + logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE), - logger:info(?msg,?domain), + undefined = whereis(h_proc_name()), + logger:notice(?msg,?domain), ?check_no_log, - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok. default_formatter(_Config) -> ok = logger:set_handler_config(?STANDARD_HANDLER,formatter, {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), ct:capture_start(), - logger:info(M1=?msg), + logger:notice(M1=?msg), timer:sleep(100), ct:capture_stop(), [Msg] = ct:capture_get(), - match = re:run(Msg,"=INFO REPORT====.*\n"++M1,[{capture,none}]), + match = re:run(Msg,"=NOTICE REPORT====.*\n"++M1,[{capture,none}]), ok. errors(Config) -> @@ -212,20 +221,26 @@ errors(Config) -> {handler_not_added, {invalid_config,logger_std_h,{type,faulty_type}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{type => faulty_type}}), + #{config => #{type => faulty_type}}), - NoDir = lists:concat(["/",?MODULE,"_dir"]), - {error, - {handler_not_added,{{open_failed,NoDir,eacces},_}}} = - logger:add_handler(myh2,logger_std_h, - #{logger_std_h=>#{type=>{file,NoDir}}}), + case os:type() of + {win32,_} -> + %% No use in testing file access on windows + ok; + _ -> + NoDir = lists:concat(["/",?MODULE,"_dir"]), + {error, + {handler_not_added,{{open_failed,NoDir,eacces},_}}} = + logger:add_handler(myh2,logger_std_h, + #{config=>#{type=>{file,NoDir}}}) + end, {error, {handler_not_added,{{open_failed,Log,_},_}}} = logger:add_handler(myh3,logger_std_h, - #{logger_std_h=>#{type=>{file,Log,[bad_file_opt]}}}), + #{config=>#{type=>{file,Log,[bad_file_opt]}}}), - ok = logger:info(?msg). + ok = logger:notice(?msg). errors(cleanup,_Config) -> logger:remove_handler(?MODULE). @@ -237,43 +252,40 @@ formatter_fail(Config) -> %% no formatter ok = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => {file,Log}}, + #{config => #{type => {file,Log}}, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), - #{handlers:=HC1} = logger:i(), - H = [Id || {Id,_,_} <- HC1], + H = logger:get_handler_ids(), true = lists:member(?MODULE,H), %% Formatter is added automatically - {ok,{_,#{formatter:={logger_formatter,_}}}} = - logger:get_handler_config(?MODULE), - logger:info(M1=?msg,?domain), - Got1 = try_match_file(Log,"[0-9\\+\\-T:\\.]* info: "++M1,5000), + {ok,#{formatter:={logger_formatter,_}}} = logger:get_handler_config(?MODULE), + logger:notice(M1=?msg,?domain), + Got1 = try_match_file(Log,"[0-9\\+\\-T:\\.]* notice: "++M1,5000), ok = logger:set_handler_config(?MODULE,formatter,{nonexistingmodule,#{}}), - logger:info(M2=?msg,?domain), + logger:notice(M2=?msg,?domain), Got2 = try_match_file(Log, - escape(Got1)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M2, + escape(Got1)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M2, 5000), ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,crash}), - logger:info(M3=?msg,?domain), + logger:notice(M3=?msg,?domain), Got3 = try_match_file(Log, - escape(Got2)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M3, + escape(Got2)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M3, 5000), ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,bad_return}), - logger:info(?msg,?domain), + logger:notice(?msg,?domain), try_match_file(Log, escape(Got3)++"FORMATTER ERROR: bad_return_value", 5000), %% Check that handler is still alive and was never dead - Pid = whereis(?MODULE), - #{handlers:=HC2} = logger:i(), - H = [Id || {Id,_,_} <- HC2], + Pid = whereis(h_proc_name()), + H = logger:get_handler_ids(), ok. @@ -283,41 +295,41 @@ formatter_fail(cleanup,_Config) -> config_fail(_Config) -> {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{bad => bad}, + #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_config,logger_std_h, {restart_type,bad}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{restart_type => bad}, + #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{drop_new_reqs_qlen=>1}}), + #{config => #{drop_mode_qlen=>1}}), {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{toggle_sync_qlen=>43, - drop_new_reqs_qlen=>42}}), + #{config => #{sync_mode_qlen=>43, + drop_mode_qlen=>42}}), {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{drop_new_reqs_qlen=>43, - flush_reqs_qlen=>42}}), + #{config => #{drop_mode_qlen=>43, + flush_qlen=>42}}), ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,logger_std_h, + logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), {error,{illegal_config_change,_,_}} = logger:set_handler_config(?MODULE,id,bad), {error,{invalid_levels,_}} = - logger:set_handler_config(?MODULE,logger_std_h, - #{toggle_sync_qlen=>100, - flush_reqs_qlen=>99}), + logger:set_handler_config(?MODULE,config, + #{sync_mode_qlen=>100, + flush_qlen=>99}), {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = - logger:set_handler_config(?MODULE, logger_std_h, + logger:set_handler_config(?MODULE, config, #{filesync_rep_int => 2000}), ok. @@ -329,7 +341,7 @@ crash_std_h_to_file(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} }}}], + #{ config => #{ type => {file, Log} }}}], file, Log). crash_std_h_to_file(cleanup,_Config) -> crash_std_h(cleanup). @@ -339,7 +351,7 @@ crash_std_h_to_disk_log(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 }}}], + #{ config => #{ file => Log }}}], disk_log,Log). crash_std_h_to_disk_log(cleanup,_Config) -> crash_std_h(cleanup). @@ -354,7 +366,12 @@ crash_std_h(Config,Func,Var,Type,Log) -> 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}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + HProcName = + case Type of + file -> ?name_to_reg_name(logger_std_h,?STANDARD_HANDLER); + disk_log -> ?name_to_reg_name(logger_disk_log_h,?STANDARD_HANDLER) + end, + Pid = rpc:call(Node,erlang,whereis,[HProcName]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,self()}]), ok = log_on_remote_node(Node,"dummy1"), @@ -367,7 +384,7 @@ crash_std_h(Config,Func,Var,Type,Log) -> %% Wait a bit, then check that it is gone timer:sleep(2000), - undefined = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + undefined = rpc:call(Node,erlang,whereis,[HProcName]), %% Check that file is not empty {ok,Bin2} = sync_and_read(Node,Type,Log), @@ -381,7 +398,7 @@ crash_std_h(Config,Func,Var,Type,Log) -> log_on_remote_node(Node,Msg) -> _ = spawn_link(Node, fun() -> erlang:group_leader(whereis(user),self()), - logger:info(Msg) + logger:notice(Msg) end), ok. @@ -391,7 +408,7 @@ crash_std_h(cleanup) -> [test_server:stop_node(Node) || Node <- Nodes]. sync_and_read(Node,disk_log,Log) -> - rpc:call(Node,logger_disk_log_h,disk_log_sync,[?STANDARD_HANDLER]), + rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]), case file:read_file(Log ++ ".1") of {ok,<<>>} -> timer:sleep(5000), @@ -423,51 +440,51 @@ reconfig(Config) -> Dir = ?config(priv_dir,Config), ok = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => standard_io}, + #{config => #{type => standard_io}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{id := ?MODULE, type := standard_io, file_ctrl_pid := FileCtrlPid, - toggle_sync_qlen := ?TOGGLE_SYNC_QLEN, - drop_new_reqs_qlen := ?DROP_NEW_REQS_QLEN, - flush_reqs_qlen := ?FLUSH_REQS_QLEN, - enable_burst_limit := ?ENABLE_BURST_LIMIT, - burst_limit_size := ?BURST_LIMIT_SIZE, - burst_window_time := ?BURST_WINDOW_TIME, - enable_kill_overloaded := ?ENABLE_KILL_OVERLOADED, - handler_overloaded_qlen := ?HANDLER_OVERLOADED_QLEN, - handler_overloaded_mem := ?HANDLER_OVERLOADED_MEM, - handler_restart_after := ?HANDLER_RESTART_AFTER, + sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = logger_std_h:info(?MODULE), - ok = logger:set_handler_config(?MODULE, logger_std_h, - #{toggle_sync_qlen => 1, - drop_new_reqs_qlen => 2, - flush_reqs_qlen => 3, - enable_burst_limit => false, - burst_limit_size => 10, - burst_window_time => 10, - enable_kill_overloaded => true, - handler_overloaded_qlen => 100000, - handler_overloaded_mem => 10000000, - handler_restart_after => never, + ok = logger:set_handler_config(?MODULE, config, + #{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => 3, + burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 10, + overload_kill_enable => true, + overload_kill_qlen => 100000, + overload_kill_mem_size => 10000000, + overload_kill_restart_after => infinity, filesync_repeat_interval => no_repeat}), #{id := ?MODULE, type := standard_io, file_ctrl_pid := FileCtrlPid, - toggle_sync_qlen := 1, - drop_new_reqs_qlen := 2, - flush_reqs_qlen := 3, - enable_burst_limit := false, - burst_limit_size := 10, - burst_window_time := 10, - enable_kill_overloaded := true, - handler_overloaded_qlen := 100000, - handler_overloaded_mem := 10000000, - handler_restart_after := never, + sync_mode_qlen := 1, + drop_mode_qlen := 2, + flush_qlen := 3, + burst_limit_enable := false, + burst_limit_max_count := 10, + burst_limit_window_time := 10, + overload_kill_enable := true, + overload_kill_qlen := 100000, + overload_kill_mem_size := 10000000, + overload_kill_restart_after := infinity, filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE), ok. @@ -482,34 +499,34 @@ file_opts(Config) -> BadType = {file,Log,BadFileOpts}, {error,{handler_not_added,{{open_failed,Log,enoent},_}}} = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => BadType}}), + #{config => #{type => BadType}}), OkFileOpts = [raw,append], OkType = {file,Log,OkFileOpts}, ok = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => OkType}, + #{config => #{type => OkType}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{type := OkType} = logger_std_h:info(?MODULE), - logger:info(M1=?msg,?domain), + logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok. file_opts(cleanup, _Config) -> logger:remove_handler(?MODULE). -filesync(Config) -> +sync(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), Type = {file,Log}, ok = logger:add_handler(?MODULE, logger_std_h, - #{logger_std_h => #{type => Type}, + #{config => #{type => Type}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), @@ -522,9 +539,9 @@ filesync(Config) -> {logger_std_h, sync_dev}, {file,datasync}]), - logger:info("first", ?domain), + logger:notice("first", ?domain), %% wait for automatic filesync - check_tracer(?FILESYNC_REP_INT*2), + check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once start_tracer([{logger_std_h, write_to_dev, 5}, @@ -535,16 +552,16 @@ filesync(Config) -> {file,datasync}, {no_more,500} ]), - logger:info("second", ?domain), - %% do explicit filesync + logger:notice("second", ?domain), + %% do explicit sync logger_std_h:filesync(?MODULE), - %% a second filesync should be ignored + %% a second sync should be ignored logger_std_h:filesync(?MODULE), check_tracer(100), %% check that if there's no repeated filesync active, %% a filesync is still performed when handler goes idle - logger:set_handler_config(?MODULE, logger_std_h, + logger:set_handler_config(?MODULE, config, #{filesync_repeat_interval => no_repeat}), no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), %% The following timer is to make sure the time from last log @@ -560,10 +577,10 @@ filesync(Config) -> {logger_std_h, write_to_dev, <<"fourth\n">>}, {logger_std_h, sync_dev}, {file,datasync}]), - logger:info("third", ?domain), + logger:notice("third", ?domain), %% wait for automatic filesync timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - logger:info("fourth", ?domain), + logger:notice("fourth", ?domain), %% wait for automatic filesync check_tracer(?IDLE_DETECT_TIME_MSEC*2), @@ -575,15 +592,15 @@ filesync(Config) -> start_tracer([{logger_std_h,handle_cast,2}], [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), - logger:set_handler_config(?MODULE, logger_std_h, + logger:set_handler_config(?MODULE, config, #{filesync_repeat_interval => SyncInt}), SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), timer:sleep(WaitT), - logger:set_handler_config(?MODULE, logger_std_h, + logger:set_handler_config(?MODULE, config, #{filesync_repeat_interval => no_repeat}), check_tracer(100), ok. -filesync(cleanup, _Config) -> +sync(cleanup, _Config) -> dbg:stop_clear(), logger:remove_handler(?MODULE). @@ -600,7 +617,7 @@ write_failure(Config) -> ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\n">>}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\n">>}, filesync_rep_int()), rpc:call(Node, ?MODULE, set_result, [file_write,{error,terminated}]), ok = log_on_remote_node(Node, "Cause simple error printout"), @@ -618,7 +635,7 @@ write_failure(Config) -> ok = log_on_remote_node(Node, "Logged2"), rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, filesync_rep_int()), ok. write_failure(cleanup, _Config) -> Nodes = nodes(), @@ -636,7 +653,7 @@ sync_failure(Config) -> SyncInt = 500, ok = rpc:call(Node, logger, set_handler_config, - [?STANDARD_HANDLER, logger_std_h, + [?STANDARD_HANDLER, config, #{filesync_repeat_interval => SyncInt}]), Info = rpc:call(Node, logger_std_h, info, [?STANDARD_HANDLER]), SyncInt = maps:get(filesync_repeat_interval, Info), @@ -669,16 +686,16 @@ start_std_h_on_new_node(Config, Log) -> logger_test_lib:setup( Config, [{logger,[{handler,default,logger_std_h, - #{ logger_std_h => #{ type => {file,Log}}}}]}]), + #{ config => #{ type => {file,Log}}}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. %% functions for test hook macros to be called by rpc -set_internal_log(Mod, Func) -> - ?set_internal_log({Mod,Func}). -set_result(Op, Result) -> - ?set_result(Op, Result). +set_internal_log(_Mod, _Func) -> + ?set_internal_log({_Mod,_Func}). +set_result(_Op, _Result) -> + ?set_result(_Op, _Result). set_defaults() -> ?set_defaults(). @@ -697,15 +714,14 @@ op_switch_to_sync_file(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NumOfReqs = 500, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => NumOfReqs+1, - flush_reqs_qlen => 2*NumOfReqs, - enable_burst_limit => false}}, + HConfig#{config => StdHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => NumOfReqs+1, + flush_qlen => 2*NumOfReqs, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), %% TRecvPid = start_op_trace(), - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), - ok = file:delete(Log), %% true = analyse_trace(TRecvPid, %% fun(Events) -> find_mode(async,Events) end), %% true = analyse_trace(TRecvPid, @@ -718,6 +734,7 @@ op_switch_to_sync_file(Config) -> %% fun(Events) -> find_mode(flush,Events) end), %% stop_op_trace(TRecvPid), NumOfReqs = Lines, + ok = file_delete(Log), ok. op_switch_to_sync_file(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -726,12 +743,12 @@ op_switch_to_sync_tty(Config) -> {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), NumOfReqs = 500, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3, - drop_new_reqs_qlen => NumOfReqs+1, - flush_reqs_qlen => 2*NumOfReqs, - enable_burst_limit => false}}, + HConfig#{config => StdHConfig#{sync_mode_qlen => 3, + drop_mode_qlen => NumOfReqs+1, + flush_qlen => 2*NumOfReqs, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), ok. op_switch_to_sync_tty(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -747,26 +764,26 @@ op_switch_to_drop_file(Config) -> Procs = 2, Bursts = 10, NewHConfig = - HConfig#{logger_std_h => - StdHConfig#{toggle_sync_qlen => 1, - drop_new_reqs_qlen => 2, - flush_reqs_qlen => + HConfig#{config => + StdHConfig#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => Procs*NumOfReqs*Bursts, - enable_burst_limit => false}}, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), %% It sometimes happens that the handler gets the %% requests in a slow enough pace so that dropping %% never occurs. Therefore, lets generate a number of %% bursts to increase the chance of message buildup. - [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || _ <- lists:seq(1, Bursts)], Logged = count_lines(Log), ok = stop_handler(?MODULE), - _ = file:delete(Log), ct:pal("Number of messages dropped = ~w (~w)", [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), true = (Logged < (Procs*NumOfReqs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -785,19 +802,19 @@ op_switch_to_drop_tty(Config) -> NumOfReqs = 300, Procs = 2, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 1, - drop_new_reqs_qlen => 2, - flush_reqs_qlen => - Procs*NumOfReqs+1, - enable_burst_limit => false}}, + HConfig#{config => StdHConfig#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => + Procs*NumOfReqs+1, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), ok. op_switch_to_drop_tty(cleanup, _Config) -> ok = stop_handler(?MODULE). op_switch_to_flush_file() -> - [{timetrap,{minutes,3}}]. + [{timetrap,{minutes,5}}]. op_switch_to_flush_file(Config) -> Test = fun() -> @@ -809,12 +826,12 @@ op_switch_to_flush_file(Config) -> %% (verify with coverage of flush_log_requests/2) NewHConfig = - HConfig#{logger_std_h => - StdHConfig#{toggle_sync_qlen => 2, + HConfig#{config => + StdHConfig#{sync_mode_qlen => 2, %% disable drop mode - drop_new_reqs_qlen => 300, - flush_reqs_qlen => 300, - enable_burst_limit => false}}, + drop_mode_qlen => 300, + flush_qlen => 300, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 1500, Procs = 10, @@ -826,15 +843,15 @@ op_switch_to_flush_file(Config) -> %% sync messages gets tested). Therefore, lets %% generate a number of bursts to increase the chance %% of message buildup in some random fashion. - [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || _ <- lists:seq(1,Bursts)], Logged = count_lines(Log), ok = stop_handler(?MODULE), - _ = file:delete(Log), ct:pal("Number of messages flushed/dropped = ~w (~w)", [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), true = (Logged < (NumOfReqs*Procs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -848,6 +865,8 @@ op_switch_to_flush_file(Config) -> op_switch_to_flush_file(cleanup, _Config) -> _ = stop_handler(?MODULE). +op_switch_to_flush_tty() -> + [{timetrap,{minutes,5}}]. op_switch_to_flush_tty(Config) -> {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), @@ -855,15 +874,15 @@ op_switch_to_flush_tty(Config) -> %% when the flush happens (verify with coverage of flush_log_requests/2) NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - %% disable drop mode - drop_new_reqs_qlen => 100, - flush_reqs_qlen => 100, - enable_burst_limit => false}}, + HConfig#{config => StdHConfig#{sync_mode_qlen => 2, + %% disable drop mode + drop_mode_qlen => 100, + flush_qlen => 100, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 1000, Procs = 100, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), ok. op_switch_to_flush_tty(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -871,18 +890,19 @@ op_switch_to_flush_tty(cleanup, _Config) -> limit_burst_disabled(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_std_h => StdHConfig#{enable_burst_limit => false, - burst_limit_size => 10, - burst_window_time => 2000, - drop_new_reqs_qlen => 200, - flush_reqs_qlen => 300}}, + HConfig#{config => StdHConfig#{burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - NumOfReqs = Logged. + NumOfReqs = Logged, + ok = file_delete(Log), + ok. limit_burst_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -890,18 +910,19 @@ limit_burst_enabled_one(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), ReqLimit = 10, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{enable_burst_limit => true, - burst_limit_size => ReqLimit, - burst_window_time => 2000, - drop_new_reqs_qlen => 200, - flush_reqs_qlen => 300}}, + HConfig#{config => StdHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - ReqLimit = Logged. + ReqLimit = Logged, + ok = file_delete(Log), + ok. limit_burst_enabled_one(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -910,57 +931,58 @@ limit_burst_enabled_period(Config) -> ReqLimit = 10, BurstTWin = 1000, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{enable_burst_limit => true, - burst_limit_size => ReqLimit, - burst_window_time => BurstTWin, - drop_new_reqs_qlen => 20000, - flush_reqs_qlen => 20001}}, + HConfig#{config => StdHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => BurstTWin, + drop_mode_qlen => 20000, + flush_qlen => 20001}}, ok = logger:set_handler_config(?MODULE, NewHConfig), Windows = 3, - Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, info), + Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", [Sent,Logged]), - ok = file:delete(Log), true = (Logged > (ReqLimit*Windows)) andalso - (Logged < (ReqLimit*(Windows+2))). + (Logged < (ReqLimit*(Windows+2))), + ok = file_delete(Log), + ok. limit_burst_enabled_period(cleanup, _Config) -> ok = stop_handler(?MODULE). kill_disabled(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>false, - handler_overloaded_qlen=>10, - handler_overloaded_mem=>100}}, + HConfig#{config=>StdHConfig#{overload_kill_enable=>false, + overload_kill_qlen=>10, + overload_kill_mem_size=>100}}, ok = logger:set_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), - ok = file:delete(Log), - true = is_pid(whereis(?MODULE)), + ok = file_delete(Log), + true = is_pid(whereis(h_proc_name())), ok. kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> - {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig = - HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_overloaded_mem=>Mem0+50000, - handler_restart_after=>RestartAfter}}, + HConfig#{config=>StdHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_mem_size=>Mem0+50000, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - %% send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive {'DOWN', MRef, _, _, Info} -> case Info of @@ -969,8 +991,8 @@ qlen_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), ok after 5000 -> @@ -990,28 +1012,28 @@ qlen_kill_std(_Config) -> %% Log = filename:join(Dir, File), %% Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), %% ok = rpc:call(Node, logger, set_handler_config, - %% [?STANDARD_HANDLER, logger_std_h, - %% #{enable_kill_overloaded=>true, - %% handler_overloaded_qlen=>10, - %% handler_overloaded_mem=>100000}]), + %% [?STANDARD_HANDLER, config, + %% #{overload_kill_enable=>true, + %% overload_kill_qlen=>10, + %% overload_kill_mem_size=>100000}]), {skip,"Not done yet"}. mem_kill_new(Config) -> - {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig = - HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>50000, - handler_overloaded_mem=>Mem0+500, - handler_restart_after=>RestartAfter}}, + HConfig#{config=>StdHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>50000, + overload_kill_mem_size=>Mem0+500, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - %% send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive {'DOWN', MRef, _, _, Info} -> case Info of @@ -1020,8 +1042,8 @@ mem_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter * 3), - true = is_pid(whereis(?MODULE)), + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), ok after 5000 -> @@ -1037,53 +1059,58 @@ mem_kill_new(cleanup, _Config) -> mem_kill_std(_Config) -> {skip,"Not done yet"}. +restart_after() -> + [{timetrap,{minutes,2}}]. restart_after(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig1 = - HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_restart_after=>never}}, + HConfig#{config=>StdHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>infinity}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), - MRef1 = erlang:monitor(process, whereis(?MODULE)), + MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef1, _, _, _Info1} -> - timer:sleep(?HANDLER_RESTART_AFTER + 1000), - undefined = whereis(?MODULE), + {'DOWN', MRef1, _, _, _Reason1} -> + file_delete(Log), + error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3), ok after 5000 -> + Info1 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - RestartAfter = ?HANDLER_RESTART_AFTER, + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig2 = - HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, - handler_overloaded_qlen=>10, - handler_restart_after=>RestartAfter}}, + HConfig#{config=>StdHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig2), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef2, _, _, _Info2} -> - timer:sleep(RestartAfter + 2000), - Pid1 = whereis(?MODULE), - true = is_pid(Pid1), + {'DOWN', MRef2, _, _, _Reason2} -> + file_delete(Log), + {ok,Pid1} = wait_for_process_up(RestartAfter * 3), false = (Pid1 == Pid0), ok after 5000 -> + Info2 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info2]), ct:fail("Handler not dead! It should not have survived this!") end, ok. restart_after(cleanup, _Config) -> ok = stop_handler(?MODULE). -%% send handler requests (filesync, info, reset, change_config) +%% send handler requests (sync, info, reset, change_config) %% during high load to verify that sync, dropping and flushing is %% handled correctly. handler_requests_under_load() -> @@ -1092,17 +1119,17 @@ handler_requests_under_load(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 1000, - flush_reqs_qlen => 2000, - enable_burst_limit => false}}, + HConfig#{config => StdHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => 1000, + flush_qlen => 2000, + burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, {change_config,[]}]) end), - Sent = send_burst({t,10000}, seq, {chars,79}, info), + Sent = send_burst({t,10000}, seq, {chars,79}, notice), Pid ! {self(),finish}, ReqResult = receive {Pid,Result} -> Result end, Logged = count_lines(Log), @@ -1115,7 +1142,7 @@ handler_requests_under_load(Config) -> Errors = [{Req,FindError(Res)} || {Req,Res} <- ReqResult], NoOfReqs = lists:foldl(fun({_,Res}, N) -> N + length(Res) end, 0, ReqResult), ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]), - ok = file:delete(Log). + ok = file_delete(Log). handler_requests_under_load(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -1128,8 +1155,8 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> Result = case Req of change_config -> - logger:set_handler_config(HName, logger_std_h, - #{enable_kill_overloaded => + logger:set_handler_config(HName, config, + #{overload_kill_enable => false}); Func -> logger_std_h:Func(HName) @@ -1144,12 +1171,11 @@ start_handler(Name, TTY, Config) when TTY == standard_io; TTY == standard_error-> ok = logger:add_handler(Name, logger_std_h, - #{logger_std_h => #{type => TTY}, + #{config => #{type => TTY}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([Name]), formatter=>{?MODULE,op}}), - {ok,{_,HConfig = #{logger_std_h := StdHConfig}}} = - logger:get_handler_config(Name), + {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {HConfig,StdHConfig}; start_handler(Name, FuncName, Config) -> @@ -1157,14 +1183,14 @@ start_handler(Name, FuncName, Config) -> Log = filename:join(Dir, lists:concat([FuncName,".log"])), ct:pal("Logging to ~tp", [Log]), Type = {file,Log}, + _ = file_delete(Log), ok = logger:add_handler(Name, logger_std_h, - #{logger_std_h => #{type => Type}, + #{config => #{type => Type}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([Name]), formatter=>{?MODULE,op}}), - {ok,{_,HConfig = #{logger_std_h := StdHConfig}}} = - logger:get_handler_config(Name), + {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {Log,HConfig,StdHConfig}. stop_handler(Name) -> @@ -1182,27 +1208,31 @@ wait_until_written(File, Sz) -> {ok,#file_info{size = Sz}} -> timer:sleep(1000), case file:read_file_info(File) of - {ok,#file_info{size = Sz1}} -> + {ok,#file_info{size = Sz}} -> ok; - {ok,#file_info{size = Sz2}} -> - wait_until_written(File, Sz2) + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) end; {ok,#file_info{size = Sz1}} -> wait_until_written(File, Sz1) end. count_lines1(File) -> - Counter = fun Cnt(Dev,LC) -> - case file:read_line(Dev) of - eof -> LC; - _ -> Cnt(Dev,LC+1) - end - end, {_,Dev} = file:open(File, [read]), - Lines = Counter(Dev, 0), + Lines = count_lines2(Dev, 0), file:close(Dev), Lines. +count_lines2(Dev, LC) -> + case file:read_line(Dev) of + {ok,"Handler logger_std_h_SUITE " ++_} -> + %% Not counting handler info + count_lines2(Dev,LC); + {ok,_} -> + count_lines2(Dev,LC+1); + eof -> LC + end. + send_burst(NorT, Type, {chars,Sz}, Class) -> Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], case NorT of @@ -1224,12 +1254,9 @@ send_n_burst(N, seq, Text, Class) -> send_n_burst(N-1, seq, Text, Class); send_n_burst(N, {spawn,Ps,TO}, Text, Class) -> ct:pal("~w processes each sending ~w messages", [Ps,N]), - PerProc = fun() -> - send_n_burst(N, seq, Text, Class) - end, MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, - monitor(process,spawn_link(PerProc)) end || - _ <- lists:seq(1,Ps)], + monitor(process,spawn_link(per_proc_fun(N,Text,Class,X))) + end || X <- lists:seq(1,Ps)], lists:foreach(fun(MRef) -> receive {'DOWN', MRef, _, _, _} -> @@ -1248,6 +1275,16 @@ send_t_burst(T0, T, Text, Class, N) -> send_t_burst(T0, T, Text, Class, N+1) end. +per_proc_fun(N,Text,Class,X) when X rem 2 == 0 -> + fun() -> + process_flag(priority,high), + send_n_burst(N, seq, Text, Class) + end; +per_proc_fun(N,Text,Class,_) -> + fun() -> + send_n_burst(N, seq, Text, Class) + end. + %%%----------------------------------------------------------------- %%% Formatter callback %%% Using this to send the formatted string back to the test case @@ -1271,9 +1308,11 @@ format(#{msg:={report,#{label:={gen_server,terminate}}}},op) -> ""; format(#{msg:={report,#{label:={proc_lib,crash}}}},op) -> ""; -format(#{msg:={F,A}},Pid) when is_list(F), is_list(A) -> +format(#{msg:={F,A}},OpOrPid) when is_list(F), is_list(A) -> String = lists:flatten(io_lib:format(F,A)), - Pid ! {log,String}, + if is_pid(OpOrPid) -> OpOrPid ! {log,String}; + true -> ok + end, String++"\n"; format(#{msg:={string,String0}},Pid) -> String = unicode:characters_to_list(String0), @@ -1282,21 +1321,21 @@ format(#{msg:={string,String0}},Pid) -> add_remove_instance_nofile(Type) -> ok = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{type => Type}, + #{config => #{type => Type}, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), group_leader(group_leader(),Pid), % to get printouts in test log - logger:info(M1=?msg,?domain), + logger:notice(M1=?msg,?domain), ?check(M1), - %% check that filesync doesn't do damage even if not relevant + %% check that sync doesn't do damage even if not relevant ok = logger_std_h:filesync(?MODULE), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE), - logger:info(?msg,?domain), + undefined = whereis(h_proc_name()), + logger:notice(?msg,?domain), ?check_no_log, ok. @@ -1379,7 +1418,7 @@ start_op_trace() -> TRecvPid = spawn_link(fun() -> trace_receiver(5000) end), {ok,_} = dbg:tracer(process, {TraceFun, TRecvPid}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:p(self(), [c]), MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), @@ -1459,7 +1498,7 @@ start_tracer(Trace,Expected) -> Pid = self(), FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), - dbg:p(whereis(?MODULE),[c]), + dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), tpl(Trace), ok. @@ -1525,3 +1564,37 @@ escape([H|T]) -> [H|escape(T)]; escape([]) -> []. + +h_proc_name() -> + h_proc_name(?MODULE). +h_proc_name(Name) -> + ?name_to_reg_name(logger_std_h,Name). + +file_delete(Log) -> + file:delete(Log). + +wait_for_process_up(T) -> + wait_for_process_up(h_proc_name(),T). + +wait_for_process_up(Name,T) -> + N = (T div 500) + 1, + wait_for_process_up1(Name,N). + +wait_for_process_up1(_Name,0) -> + error; +wait_for_process_up1(Name,N) -> + timer:sleep(500), + case whereis(Name) of + Pid when is_pid(Pid) -> + %% ct:pal("Process ~p up (~p tries left)",[Name,N]), + {ok,Pid}; + undefined -> + %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), + wait_for_process_up1(Name,N-1) + end. + +filesync_rep_int() -> + case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of + true -> 5500; + false -> ?FILESYNC_REPEAT_INTERVAL + 500 + end. diff --git a/lib/kernel/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl index 4ac05e6480..81eb9ce5eb 100644 --- a/lib/kernel/test/logger_test_lib.erl +++ b/lib/kernel/test/logger_test_lib.erl @@ -37,7 +37,7 @@ setup(Config,Vars) -> " -boot start_sasl -kernel start_timer true " "-config ",ConfigFileName]}]) of {ok, Node} -> - L = rpc:call(Node, logger, i, []), + L = rpc:call(Node, logger, get_config, []), ct:log("~p",[L]), {ok, L, Node}; {error, Reason} -> @@ -52,7 +52,7 @@ log(Node, M, F, A) -> 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]), + rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]), file:read_file(Log ++ ".1"); sync_and_read(Node, file,Log) -> ok = rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), diff --git a/lib/kernel/test/os_SUITE.erl b/lib/kernel/test/os_SUITE.erl index abbc301360..710b9b115c 100644 --- a/lib/kernel/test/os_SUITE.erl +++ b/lib/kernel/test/os_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2017. All Rights Reserved. +%% Copyright Ericsson AB 1997-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. diff --git a/lib/kernel/test/pdict_SUITE.erl b/lib/kernel/test/pdict_SUITE.erl index a891451c82..3685e51c10 100644 --- a/lib/kernel/test/pdict_SUITE.erl +++ b/lib/kernel/test/pdict_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1999-2016. All Rights Reserved. +%% Copyright Ericsson AB 1999-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. diff --git a/lib/kernel/test/prim_file_SUITE.erl b/lib/kernel/test/prim_file_SUITE.erl index 5bb230d1c4..a02b5f87d1 100644 --- a/lib/kernel/test/prim_file_SUITE.erl +++ b/lib/kernel/test/prim_file_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2000-2017. All Rights Reserved. +%% Copyright Ericsson AB 2000-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. diff --git a/lib/kernel/test/seq_trace_SUITE.erl b/lib/kernel/test/seq_trace_SUITE.erl index aae8a83304..ceb4e9cc49 100644 --- a/lib/kernel/test/seq_trace_SUITE.erl +++ b/lib/kernel/test/seq_trace_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2016. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/wrap_log_reader_SUITE.erl b/lib/kernel/test/wrap_log_reader_SUITE.erl index b1ee29a11f..59b088ca73 100644 --- a/lib/kernel/test/wrap_log_reader_SUITE.erl +++ b/lib/kernel/test/wrap_log_reader_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2016. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/wrap_log_reader_SUITE_data/wrap_log_test.erl b/lib/kernel/test/wrap_log_reader_SUITE_data/wrap_log_test.erl index 2b24ccc66f..d2bac40192 100644 --- a/lib/kernel/test/wrap_log_reader_SUITE_data/wrap_log_test.erl +++ b/lib/kernel/test/wrap_log_reader_SUITE_data/wrap_log_test.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1998-2016. All Rights Reserved. +%% Copyright Ericsson AB 1998-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. diff --git a/lib/kernel/test/zlib_SUITE.erl b/lib/kernel/test/zlib_SUITE.erl index f203ef878f..52ae1b3ae6 100644 --- a/lib/kernel/test/zlib_SUITE.erl +++ b/lib/kernel/test/zlib_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2005-2016. All Rights Reserved. +%% Copyright Ericsson AB 2005-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. |