diff options
author | Siri Hansen <[email protected]> | 2018-04-24 14:26:31 +0200 |
---|---|---|
committer | Siri Hansen <[email protected]> | 2018-04-26 14:37:30 +0200 |
commit | 0deea4a8f369013ec00e231d0c2c37e4ab3f0ba1 (patch) | |
tree | 054b8465a9eb07b07fde4596f2209ee1df689a92 /lib/kernel/test | |
parent | 0183ddffb112d898d9b8c0396afa7f2210b9e169 (diff) | |
download | otp-0deea4a8f369013ec00e231d0c2c37e4ab3f0ba1.tar.gz otp-0deea4a8f369013ec00e231d0c2c37e4ab3f0ba1.tar.bz2 otp-0deea4a8f369013ec00e231d0c2c37e4ab3f0ba1.zip |
Add logger
Diffstat (limited to 'lib/kernel/test')
-rw-r--r-- | lib/kernel/test/Makefile | 14 | ||||
-rw-r--r-- | lib/kernel/test/kernel.spec | 1 | ||||
-rw-r--r-- | lib/kernel/test/logger.cover | 14 | ||||
-rw-r--r-- | lib/kernel/test/logger.spec | 11 | ||||
-rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 828 | ||||
-rw-r--r-- | lib/kernel/test/logger_bench_SUITE.erl | 500 | ||||
-rw-r--r-- | lib/kernel/test/logger_bench_SUITE_data/Emakefile | 1 | ||||
-rw-r--r-- | lib/kernel/test/logger_bench_SUITE_data/lager_helper.erl | 73 | ||||
-rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 1417 | ||||
-rw-r--r-- | lib/kernel/test/logger_env_var_SUITE.erl | 451 | ||||
-rw-r--r-- | lib/kernel/test/logger_filters_SUITE.erl | 214 | ||||
-rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 501 | ||||
-rw-r--r-- | lib/kernel/test/logger_legacy_SUITE.erl | 282 | ||||
-rw-r--r-- | lib/kernel/test/logger_simple_SUITE.erl | 247 | ||||
-rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 1396 |
15 files changed, 5948 insertions, 2 deletions
diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile index 03b6355056..8599a3d814 100644 --- a/lib/kernel/test/Makefile +++ b/lib/kernel/test/Makefile @@ -70,6 +70,15 @@ MODULES= \ interactive_shell_SUITE \ init_SUITE \ kernel_config_SUITE \ + logger_SUITE \ + logger_bench_SUITE \ + logger_disk_log_h_SUITE \ + logger_env_var_SUITE \ + logger_filters_SUITE \ + logger_formatter_SUITE \ + logger_legacy_SUITE \ + logger_simple_SUITE \ + logger_std_h_SUITE \ os_SUITE \ pg2_SUITE \ seq_trace_SUITE \ @@ -102,7 +111,7 @@ TARGET_FILES= $(MODULES:%=$(EBIN)/%.$(EMULATOR)) INSTALL_PROGS= $(TARGET_FILES) EMAKEFILE=Emakefile -COVERFILE=kernel.cover +COVERFILE=kernel.cover logger.cover # ---------------------------------------------------- # Release directory specification @@ -149,7 +158,8 @@ release_tests_spec: make_emakefile $(INSTALL_DIR) "$(RELSYSDIR)" $(INSTALL_DATA) $(ERL_FILES) "$(RELSYSDIR)" $(INSTALL_DATA) $(APP_FILES) "$(RELSYSDIR)" - $(INSTALL_DATA) kernel.spec kernel_smoke.spec kernel_bench.spec \ + $(INSTALL_DATA) \ + kernel.spec kernel_smoke.spec kernel_bench.spec logger.spec \ $(EMAKEFILE) $(COVERFILE) "$(RELSYSDIR)" chmod -R u+w "$(RELSYSDIR)" @tar cf - *_SUITE_data | (cd "$(RELSYSDIR)"; tar xf -) diff --git a/lib/kernel/test/kernel.spec b/lib/kernel/test/kernel.spec index 62afc9f97b..86d2155828 100644 --- a/lib/kernel/test/kernel.spec +++ b/lib/kernel/test/kernel.spec @@ -2,3 +2,4 @@ {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/logger.cover b/lib/kernel/test/logger.cover new file mode 100644 index 0000000000..b30bcfe920 --- /dev/null +++ b/lib/kernel/test/logger.cover @@ -0,0 +1,14 @@ +%% -*- erlang -*- +{incl_mods,[error_logger, + logger, + logger_backend, + logger_config, + logger_disk_log_h, + logger_h_common, + logger_filters, + logger_formatter, + logger_server, + logger_simple, + logger_std_h, + logger_sup]}. + diff --git a/lib/kernel/test/logger.spec b/lib/kernel/test/logger.spec new file mode 100644 index 0000000000..cd76a754a4 --- /dev/null +++ b/lib/kernel/test/logger.spec @@ -0,0 +1,11 @@ +%% -*-erlang-*- +{suites,"../kernel_test", [error_logger_SUITE, + error_logger_warn_SUITE, + logger_SUITE, + logger_disk_log_h_SUITE, + logger_env_var_SUITE, + logger_filters_SUITE, + logger_formatter_SUITE, + logger_legacy_SUITE, + logger_simple_SUITE, + logger_std_h_SUITE]}. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl new file mode 100644 index 0000000000..0edce3e34c --- /dev/null +++ b/lib/kernel/test/logger_SUITE.erl @@ -0,0 +1,828 @@ +%% +%% %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_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). + +-define(str,"Log from "++atom_to_list(?FUNCTION_NAME)++ + ":"++integer_to_list(?LINE)). +-define(map_rep,#{function=>?FUNCTION_NAME, line=>?LINE}). +-define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]). + +-define(MY_LOC(N),#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY}, + file=>?FILE, line=>?LINE-N}). + +-define(TRY(X), my_try(fun() -> X end)). + + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + case logger:get_handler_config(logger_std_h) of + {ok,StdH} -> + ok = logger:remove_handler(logger_std_h), + [{logger_std_h,StdH}|Config]; + _ -> + Config + end. + +end_per_suite(Config) -> + case ?config(logger_std_h,Config) of + {HMod,HConfig} -> + ok = logger:add_handler(logger_std_h,HMod,HConfig); + _ -> + ok + end. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + {ok,LC} = logger:get_logger_config(), + [{logger_config,LC}|Config]. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [start_stop, + add_remove_handler, + multiple_handlers, + add_remove_filter, + change_config, + set_formatter, + log_all_levels_api, + macros, + set_level, + set_level_module, + cache_level_module, + format_report, + filter_failed, + handler_failed, + config_sanity_check, + log_failed, + emulator, + via_logger_process, + other_node, + compare_levels, + process_metadata]. + +start_stop(_Config) -> + S = whereis(logger), + true = is_pid(S), + ok. + +add_remove_handler(_Config) -> + register(callback_receiver,self()), + {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + {error,{not_found,h1}} = logger:get_handler_config(h1), + ok = logger:add_handler(h1,?MODULE,#{}), + [add] = test_server:messages_get(), + {ok,#{handlers:=Hs}} = logger:get_logger_config(), + [h1|Hs0] = Hs, + {ok,{?MODULE,#{level:=info,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",[]), + 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 = logger:remove_handler(h1), + [remove] = test_server:messages_get(), + {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + {error,{not_found,h1}} = logger:get_handler_config(h1), + {error,{not_found,h1}} = logger:remove_handler(h1), + logger:info("hello",[]), + ok = check_no_log(), + ok. + +add_remove_handler(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +multiple_handlers(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,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)), + ok = check_no_log(), + ok. + +multiple_handlers(cleanup,_Config) -> + logger:remove_handler(h1), + logger:remove_handler(h2), + ok. + +add_remove_filter(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,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 = check_logged(error,"hello",[],?MY_LOC(1)), + ok = check_no_log(), + + ok = logger:add_handler(h2,?MODULE,#{level=>info,filter_default=>log}), + HF = {fun(#{level:=error}=Log,_) -> + Log#{level=>mylevel}; + (_,_) -> + ignore + end, + []}, + ok = logger:add_handler_filter(h1,hf,HF), + {error,{already_exist,hf}} = logger:add_handler_filter(h1,hf,HF), + {error,{already_exist,hf}} = logger:add_handler_filter(h1,hf,{fun(Log,_) -> + Log + end, []}), + ?LOG_INFO("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), + + ?LOG_INFO("hello",[]), + ok = check_logged(info,"hello",[],?MY_LOC(1)), + ok = check_logged(info,"hello",[],?MY_LOC(2)), + + ?LOG_ERROR("hello",[]), + ok = check_logged(mylevel,"hello",[],?MY_LOC(1)), + ok = check_logged(error,"hello",[],?MY_LOC(2)), + + 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_ERROR("hello",[]), + ok = check_logged(error,"hello",[],?MY_LOC(1)), + ok = check_logged(error,"hello",[],?MY_LOC(2)), + ok. + +add_remove_filter(cleanup,_Config) -> + logger:remove_logger_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}}} = + 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}} = + logger:get_handler_config(h1), + false = maps:is_key(custom,C2), + {error,fail} = logger:set_handler_config(h1,#{fail=>true}), + {error,{attempting_syncronous_call_to_self,_}} = + logger:set_handler_config( + h1,#{call=>fun() -> logger:set_module_level(?MODULE,debug) end}), + {ok,{?MODULE,C2}} = logger:get_handler_config(h1), + + %% Change one key only + {error,fail} = logger:set_handler_config(h1,fail,true), + ok = logger:set_handler_config(h1,custom,custom), + [changing_config] = test_server:messages_get(), + {ok,{?MODULE,#{custom:=custom}=C3}} = logger:get_handler_config(h1), + C2 = maps:remove(custom,C3), + + %% Overwrite logger config - check that defaults are added + {ok,LConfig} = logger:get_logger_config(), + ok = logger:set_logger_config(#{filter_default=>stop}), + {ok,#{level:=info,filters:=[],handlers:=[],filter_default:=stop}=LC1} = + logger:get_logger_config(), + 4 = maps:size(LC1), + + %% Change one key only + ok = logger:set_logger_config(handlers,[h1]), + {ok,#{level:=info,filters:=[],handlers:=[h1],filter_default:=stop}} = + logger:get_logger_config(), + + %% Cleanup + ok = logger:set_logger_config(LConfig), + [] = test_server:messages_get(), + + ok. + +change_config(cleanup,Config) -> + logger:remove_handler(h1), + LC = ?config(logger_config,Config), + logger:set_logger_config(LC), + 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:set_handler_config(h1,formatter,{?MODULE,[]}), + logger:info("hello",[]), + receive + {_Log,#{formatter:={?MODULE,[]}}} -> + ok + after 500 -> + ct:fail({timeout,no_log,process_info(self(),messages)}) + end, + ok. + +set_formatter(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +log_all_levels_api(_Config) -> + ok = logger:set_logger_config(level,debug), + ok = logger:add_handler(h1,?MODULE,#{level=>debug,filter_default=>log}), + test_api(emergency), + test_api(alert), + test_api(critical), + test_api(error), + test_api(warning), + test_api(notice), + test_api(info), + test_api(debug), + test_log_function(emergency), + ok. + +log_all_levels_api(cleanup,_Config) -> + logger:remove_handler(h1), + logger:set_logger_config(level,info), + ok. + +macros(_Config) -> + ok = logger:set_module_level(?MODULE,debug), + ok = logger:add_handler(h1,?MODULE,#{level=>debug,filter_default=>log}), + test_macros(emergency), + ok. + +macros(cleanup,_Config) -> + logger:remove_handler(h1), + logger:reset_module_level(?MODULE), + ok. + +set_level(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>debug,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:debug(M2=?map_rep), + ok = check_logged(debug,M2,#{}), + ok. + +set_level(cleanup,_Config) -> + logger:remove_handler(h1), + logger:set_logger_config(level,info), + ok. + +set_level_module(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), + {error,{invalid_level,bad}} = logger:set_module_level(?MODULE,bad), + {error,{not_a_module,{bad}}} = logger:set_module_level({bad},warning), + ok = logger:set_module_level(?MODULE,warning), + logger:info(?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:reset_module_level({bad}), + ok = logger:reset_module_level(?MODULE), + + ok. + +set_level_module(cleanup,_Config) -> + logger:remove_handler(h1), + logger:reset_module_level(?MODULE), + ok. + +cache_level_module(_Config) -> + ok = logger:reset_module_level(?MODULE), + [] = ets:lookup(logger,?MODULE), %dirty - add API in logger_config? + ?LOG_INFO(?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? + ok = logger:reset_module_level(?MODULE), + [] = ets:lookup(logger,?MODULE), %dirty - add API in logger_config? + ok. + +cache_level_module(cleanup,_Config) -> + logger:reset_module_level(?MODULE), + ok. + +format_report(_Config) -> + {"~ts",["string"]} = logger:format_report("string"), + {"~tp",[term]} = logger:format_report(term), + {"~tp",[[]]} = logger:format_report([]), + {" ~tp: ~tp",[key,value]} = logger:format_report([{key,value}]), + KeyVals = [{key1,value1},{key2,"value2"},{key3,[]}], + KeyValRes = + {" ~tp: ~tp\n ~tp: ~ts\n ~tp: ~tp", + [key1,value1,key2,"value2",key3,[]]} = + logger:format_report(KeyVals), + KeyValRes = logger:format_report(maps:from_list(KeyVals)), + KeyValRes = logger:format_otp_report(#{label=>{?MODULE,test},report=>KeyVals}), + {" ~tp: ~tp\n ~tp: ~tp", + [label,{?MODULE,test},report,KeyVals]} = + logger:format_report(#{label=>{?MODULE,test},report=>KeyVals}), + + {" ~tp: ~tp\n ~tp",[key1,value1,term]} = + logger:format_report([{key1,value1},term]), + + {" ~tp: ~tp\n ~tp",[key1,value1,[]]} = + logger:format_report([{key1,value1},[]]), + + {"~tp",[[]]} = logger:format_report([[],[],[]]), + + ok. + +filter_failed(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,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), + + %% Handler filters + {error,{not_found,h0}} = + logger:add_handler_filter(h0,hf,{fun(_,_) -> ignore end,args}), + {error,{not_found,h0}} = logger:remove_handler_filter(h0,hf), + {error,{invalid_filter,_}} = + logger:add_handler_filter(h1,hf,{fun(_) -> ok end,args}), + ok = logger:add_handler_filter(h1,hf,{fun(_,_) -> a=b end,args}), + {ok,{?MODULE,#{filters:=[_]}}} = logger:get_handler_config(h1), + ok = logger:info(M3=?map_rep), + ok = check_logged(info,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,#{}), + {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf), + + ok. + +filter_failed(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +handler_failed(_Config) -> + {error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}), + {error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}), + {error,{invalid_handler_config,bad}} = logger:add_handler(h1,?MODULE,bad), + {error,{invalid_filters,false}} = + logger:add_handler(h1,?MODULE,#{filters=>false}), + {error,{invalid_filter_default,true}} = + logger:add_handler(h1,?MODULE,#{filter_default=>true}), + {error,{invalid_formatter,[]}} = + logger:add_handler(h1,?MODULE,#{formatter=>[]}), + ok = logger:add_handler(h1,nomodule,#{filter_default=>log}), + logger:info(?map_rep), + check_no_log(), + #{logger:=#{handlers:=Ids1}, + handlers:=H1} = logger:i(), + false = lists:member(h1,Ids1), + false = lists:keymember(h1,1,H1), + {error,{not_found,h1}} = logger:remove_handler(h1), + + ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,crash=>true}), + {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}), + + logger:info(?map_rep), + check_no_log(), + #{logger:=#{handlers:=Ids2}, + handlers:=H2} = logger:i(), + false = lists:member(h2,Ids2), + false = lists:keymember(h2,1,H2), + {error,{not_found,h2}} = logger:remove_handler(h2), + + ok. + +handler_failed(cleanup,_Config) -> + logger:remove_handler(h1), + logger:remove_handler(h2), + ok. + +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_handlers,bad}} = logger:set_logger_config(handlers,bad), + {error,{invalid_id,{bad,bad}}} = + logger:set_logger_config(handlers,[{bad,bad}]), + {error,{invalid_id,"bad"}} = logger:set_logger_config(handlers,["bad"]), + {error,{invalid_filters,bad}} = logger:set_logger_config(filters,bad), + {error,{invalid_filter,bad}} = logger:set_logger_config(filters,[bad]), + {error,{invalid_filter,{_,_}}} = + logger:set_logger_config(filters,[{id,bad}]), + {error,{invalid_filter,{_,{_,_}}}} = + logger:set_logger_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), + + %% Handler config + {error,{not_found,h1}} = logger:set_handler_config(h1,a,b), + ok = logger:add_handler(h1,?MODULE,#{}), + {error,{invalid_filter_default,bad}} = + logger:set_handler_config(h1,filter_default,bad), + {error,{invalid_level,bad}} = logger:set_handler_config(h1,level,bad), + {error,{invalid_filters,bad}} = logger:set_handler_config(h1,filters,bad), + {error,{invalid_filter,bad}} = logger:set_handler_config(h1,filters,[bad]), + {error,{invalid_filter,{_,_}}} = + logger:set_handler_config(h1,filters,[{id,bad}]), + {error,{invalid_filter,{_,{_,_}}}} = + logger:set_handler_config(h1,filters,[{id,{bad,args}}]), + {error,{invalid_filter,{_,{_,_}}}} = + logger:set_handler_config(h1,filters,[{id,{fun() -> ok end,args}}]), + {error,{invalid_formatter,bad}} = + logger:set_handler_config(h1,formatter,bad), + {error,{invalid_module,{bad}}} = + logger:set_handler_config(h1,formatter,{{bad},cfg}), + {error,{invalid_formatter_config,bad}} = + logger:set_handler_config(h1,formatter,{logger_formatter,bad}), + {error,{invalid_formatter_config,{bad,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter,#{bad=>bad}}), + {error,{invalid_formatter_config,{template,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{template=>bad}}), + {error,{invalid_formatter_template,[1]}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{template=>[1]}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{template=>[]}}), + {error,{invalid_formatter_config,{single_line,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{single_line=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{single_line=>true}}), + {error,{invalid_formatter_config,{legacy_header,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{legacy_header=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{legacy_header=>true}}), + ok = logger:set_handler_config(h1,custom,custom), + ok. + +config_sanity_check(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +log_failed(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,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,#{})), + 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,#{}), + + %% Should we check report input more thoroughly? + ok = logger:log(info,M4=?keyval_rep++[other,stuff,in,list],#{}), + check_logged(info,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. + +log_failed(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +emulator(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + tc_proc=>self()}), + Msg = "Error in process ~p on node ~p with exit value:~n~p~n", + Error = {badmatch,4}, + Stack = [{module, function, 2, []}], + Pid = spawn(?MODULE, generate_error, [Error, Stack]), + check_logged(error, Msg, [Pid, node(), {Error, Stack}], + #{gl=>group_leader(), + error_logger=>#{tag=>error,emulator=>true}}), + ok. + +emulator(cleanup, _Config) -> + logger:remove_handler(h1), + ok. + +generate_error(Error, Stack) -> + erlang:raise(error, Error, Stack). + +via_logger_process(Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + tc_proc=>self()}), + + %% Explicitly send a message to the logger process + %% This is used by code_server, erl_prim_loader, init, prim_file, ... + Msg = ?str, + logger ! {log,error,Msg,[],#{}}, + check_logged(error, Msg, [], #{}), + + case os:type() of + {win32,_} -> + %% Skip this part on windows - cant change file mode" + ok; + _ -> + %% This should trigger the same thing from erl_prim_loader + Dir = filename:join(?config(priv_dir,Config),"dummydir"), + ok = file:make_dir(Dir), + ok = file:change_mode(Dir,8#0222), + error = erl_prim_loader:list_dir(Dir), + check_logged(error, + #{report=>"File operation error: eacces. Target: " ++ + Dir ++". Function: list_dir. "}, + #{pid=>self(), + gl=>group_leader(), + error_logger=>#{tag=>error_report, + type=>std_error}}), + ok + end. + +via_logger_process(cleanup, Config) -> + Dir = filename:join(?config(priv_dir,Config),"dummydir"), + _ = file:change_mode(Dir,8#0664), + _ = file:del_dir(Dir), + logger:remove_handler(h1), + ok. + +other_node(_Config) -> + ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log, + tc_proc=>self()}), + {ok,Node} = test_server:start_node(?FUNCTION_NAME,slave,[]), + rpc:call(Node,logger,error,[Msg=?str,#{}]), + check_logged(error,Msg,#{}), + ok. + +other_node(cleanup,_Config) -> + Nodes = nodes(), + [test_server:stop_node(Node) || Node <- Nodes], + logger:remove_handler(h1), + ok. + +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")), + ok. + +compare([L|Rest]) -> + eq = logger:compare_levels(L,L), + [gt = logger:compare_levels(L,L1) || L1 <- Rest], + [lt = logger:compare_levels(L1,L) || L1 <- Rest], + compare(Rest); +compare([]) -> + ok. + +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}), + Time = erlang:monotonic_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}), + + Time2 = erlang:monotonic_time(microsecond), + S2 = ?str, + ?LOG_INFO(S2,#{time=>Time2,line=>1,custom=>macro}), + check_logged(info,S2,#{time=>Time2,line=>1,custom=>macro}), + + logger:info(S3=?str,#{custom=>func}), + check_logged(info,S3,#{time=>Time,line=>0,custom=>func}), + + ProcMeta = logger:get_process_metadata(), + ok = logger:unset_process_metadata(), + undefined = logger:get_process_metadata(), + + ok. + +process_metadata(cleanup,_Config) -> + logger:remove_handler(h1), + ok. + +%%%----------------------------------------------------------------- +%%% Internal +check_logged(Level,Format,Args,Meta) -> + do_check_logged(Level,{Format,Args},Meta). + +check_logged(Level,Msg,Meta) when ?IS_REPORT(Msg) -> + do_check_logged(Level,{report,Msg},Meta); +check_logged(Level,Msg,Meta) when ?IS_STRING(Msg) -> + do_check_logged(Level,{string,Msg},Meta). + +do_check_logged(Level,Msg0,Meta0) -> + receive + {#{level:=Level,msg:=Msg,meta:=Meta},_} -> + check_msg(Msg0,Msg), + check_maps(Meta0,Meta,meta) + after 500 -> + ct:fail({timeout,no_log,process_info(self(),messages)}) + end. + +check_no_log() -> + receive + X -> ct:fail({got_unexpected_log,X}) + after 500 -> + ok + end. + +check_msg(Msg,Msg) -> + ok; +check_msg({report,Expected},{report,Got}) when is_map(Expected), is_map(Got) -> + check_maps(Expected,Got,msg); +check_msg(Expected,Got) -> + ct:fail({unexpected,msg,Expected,Got}). + +check_maps(Expected,Got,What) -> + case maps:merge(Got,Expected) of + Got -> + ok; + _ -> + ct:fail({unexpected,What,Expected,Got}) + end. + +%% Handler +adding_handler(_Id,Config) -> + maybe_send(add), + {ok,Config}. +removing_handler(_Id) -> + maybe_send(remove), + ok. +changing_config(_Id,_Old,#{call:=Fun}) -> + Fun(); +changing_config(_Id,_Old,#{fail:=true}) -> + {error,fail}; +changing_config(_Id,_Old,Config) -> + maybe_send(changing_config), + {ok,Config}. + +maybe_send(Msg) -> + case whereis(callback_receiver) of + undefined -> ok; + Pid -> Pid ! Msg + end. + +log(_Log,#{crash:=true}) -> + a=b; +log(Log,Config) -> + TcProc = maps:get(tc_proc,Config,self()), + TcProc ! {Log,Config}, + ok. + +test_api(Level) -> + logger:Level(#{Level=>rep}), + ok = check_logged(Level,#{Level=>rep},#{}), + logger:Level(#{Level=>rep},#{my=>meta}), + ok = check_logged(Level,#{Level=>rep},#{my=>meta}), + logger:Level("~w: ~w",[Level,fa]), + ok = check_logged(Level,"~w: ~w",[Level,fa],#{}), + logger:Level("~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + logger:Level(fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end,x, + #{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],#{my=>meta}), + logger:Level(fun(x) -> #{Level=>fun_to_r,meta=>true} end,x, + #{my=>meta}), + ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},#{my=>meta}), + logger:Level(fun(x) -> <<"fun_to_s">> end,x,#{}), + ok = check_logged(Level,<<"fun_to_s">>,#{}), + logger:Level(F1=fun(x) -> {fun_to_bad} end,x,#{}), + ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp", + [{F1,x},{fun_to_bad}],#{}), + logger:Level(F2=fun(x) -> erlang:error(fun_that_crashes) end,x,#{}), + ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp", + [{F2,x},{error,fun_that_crashes}],#{}), + ok. + +test_log_function(Level) -> + logger:log(Level,#{Level=>rep}), + ok = check_logged(Level,#{Level=>rep},#{}), + logger:log(Level,#{Level=>rep},#{my=>meta}), + ok = check_logged(Level,#{Level=>rep},#{my=>meta}), + logger:log(Level,"~w: ~w",[Level,fa]), + ok = check_logged(Level,"~w: ~w",[Level,fa],#{}), + logger:log(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + logger:log(Level,fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end, + x, #{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],#{my=>meta}), + logger:log(Level,fun(x) -> #{Level=>fun_to_r,meta=>true} end, + x, #{my=>meta}), + ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},#{my=>meta}), + logger:log(Level,fun(x) -> <<"fun_to_s">> end,x,#{}), + ok = check_logged(Level,<<"fun_to_s">>,#{}), + logger:log(Level,F1=fun(x) -> {fun_to_bad} end,x,#{}), + ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp", + [{F1,x},{fun_to_bad}],#{}), + logger:log(Level,F2=fun(x) -> erlang:error(fun_that_crashes) end,x,#{}), + ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp", + [{F2,x},{error,fun_that_crashes}],#{}), + ok. + +test_macros(emergency=Level) -> + ?LOG_EMERGENCY(#{Level=>rep}), + ok = check_logged(Level,#{Level=>rep},?MY_LOC(1)), + ?LOG_EMERGENCY(#{Level=>rep},#{my=>meta}), + ok = check_logged(Level,#{Level=>rep},(?MY_LOC(1))#{my=>meta}), + ?LOG_EMERGENCY("~w: ~w",[Level,fa]), + ok = check_logged(Level,"~w: ~w",[Level,fa],?MY_LOC(1)), + ?LOG_EMERGENCY("~w: ~w ~w",[Level,fa,meta],#{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],(?MY_LOC(1))#{my=>meta}), + ?LOG_EMERGENCY(fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end, + x, #{my=>meta}), + ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta], + (?MY_LOC(3))#{my=>meta}), + ?LOG_EMERGENCY(fun(x) -> #{Level=>fun_to_r,meta=>true} end, x, #{my=>meta}), + ok = check_logged(Level,#{Level=>fun_to_r,meta=>true}, + (?MY_LOC(2))#{my=>meta}), + ?LOG_EMERGENCY(fun(x) -> <<"fun_to_s">> end,x,#{}), + ok = check_logged(Level,<<"fun_to_s">>,?MY_LOC(1)), + F1=fun(x) -> {fun_to_bad} end, + ?LOG_EMERGENCY(F1,x,#{}), + ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp", + [{F1,x},{fun_to_bad}],#{}), + F2=fun(x) -> erlang:error(fun_that_crashes) end, + ?LOG_EMERGENCY(F2,x,#{}), + ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp", + [{F2,x},{error,fun_that_crashes}],#{}), + ok. + +%%%----------------------------------------------------------------- +%%% Called by macro ?TRY(X) +my_try(Fun) -> + try Fun() catch C:R -> {C,R} end. diff --git a/lib/kernel/test/logger_bench_SUITE.erl b/lib/kernel/test/logger_bench_SUITE.erl new file mode 100644 index 0000000000..d47122ea9d --- /dev/null +++ b/lib/kernel/test/logger_bench_SUITE.erl @@ -0,0 +1,500 @@ +%% +%% %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 new file mode 100644 index 0000000000..85c82bdaab --- /dev/null +++ b/lib/kernel/test/logger_bench_SUITE_data/Emakefile @@ -0,0 +1 @@ +{['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 new file mode 100644 index 0000000000..296ced4276 --- /dev/null +++ b/lib/kernel/test/logger_bench_SUITE_data/lager_helper.erl @@ -0,0 +1,73 @@ +-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 new file mode 100644 index 0000000000..c7c6137380 --- /dev/null +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -0,0 +1,1417 @@ +-module(logger_disk_log_h_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). +-include_lib("kernel/src/logger_h_common.hrl"). +-include_lib("stdlib/include/ms_transform.hrl"). +-include_lib("kernel/include/file.hrl"). + +-define(check_no_log, [] = test_server:messages_get()). + +-define(check(Expected), + receive {log,Expected} -> + [] = test_server:messages_get() + after 1000 -> + ct:fail({report_not_received, + {line,?LINE}, + {got,test_server:messages_get()}}) + end). + +-define(msg,"Log from "++atom_to_list(?FUNCTION_NAME)++ + ":"++integer_to_list(?LINE)). +-define(bin(Msg), list_to_binary(Msg++"\n")). +-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}}]. + +init_per_suite(Config) -> + timer:start(), % to avoid progress report + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(TestHooksCase, Config) when + TestHooksCase == write_failure; + TestHooksCase == sync_failure -> + if ?TEST_HOOKS_TAB == undefined -> + {skip,"Define the TEST_HOOKS macro to run this test"}; + true -> + ct:print("********** ~w **********", [TestHooksCase]), + Config + end; +init_per_testcase(TestCase, Config) -> + ct:print("********** ~w **********", [TestCase]), + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [start_stop_handler, + create_log, + open_existing_log, + disk_log_opts, + default_formatter, + logging, + errors, + formatter_fail, + config_fail, + bad_input, + info_and_reset, + reconfig, + disk_log_sync, + disk_log_full, + disk_log_wrap, + disk_log_events, + write_failure, + sync_failure, + op_switch_to_sync, + op_switch_to_drop, + op_switch_to_flush, + limit_burst_disabled, + limit_burst_enabled_one, + limit_burst_enabled_period, + kill_disabled, + qlen_kill_new, + %% qlen_kill_std, + mem_kill_new, + %% mem_kill_std, + restart_after, + handler_requests_under_load + ]. + +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)), + ok = logger:remove_handler(?MODULE), + timer:sleep(500), + undefined = whereis(?MODULE). +start_stop_handler(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +create_log(Config) -> + PrivDir = ?config(priv_dir,Config), + %% test new handler + Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_A"])), + LogFile1 = filename:join(PrivDir, Name1), + ok = start_and_add(Name1, #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}, + #{file=>LogFile1}), + logger:info("hello", ?domain), + logger_disk_log_h:disk_log_sync(Name1), + ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), + try_read_file(?log_no(LogFile1,1), {ok,<<"hello\n">>}, 5000), + + %% test second handler + Name2 = list_to_atom(lists:concat([?FUNCTION_NAME,"_B"])), + DLName = lists:concat([?FUNCTION_NAME,"_B_log"]), + LogFile2 = filename:join(PrivDir, DLName), + ok = start_and_add(Name2, #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}, + #{file=>LogFile2}), + logger:info("dummy", ?domain), + logger_disk_log_h:disk_log_sync(Name2), + ct:pal("Checking contents of ~p", [?log_no(LogFile2,1)]), + try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000), + + remove_and_stop(Name1), + remove_and_stop(Name2), + try_read_file(?log_no(LogFile1,1), {ok,<<"hello\ndummy\n">>}, 1), + try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000), + ok. + +open_existing_log(Config) -> + PrivDir = ?config(priv_dir,Config), + %% test new handler + HName = ?FUNCTION_NAME, + DLName = lists:concat([?FUNCTION_NAME,"_log"]), + LogFile1 = filename:join(PrivDir, DLName), + ok = start_and_add(HName, #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}, + #{file=>LogFile1}), + logger:info("one", ?domain), + logger_disk_log_h:disk_log_sync(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), + ok = remove_and_stop(HName), + try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\n">>}, 5000), + + logger:info("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), + 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). + +disk_log_opts(Config) -> + Get = fun(Key, PL) -> proplists:get_value(Key, PL) end, + PrivDir = ?config(priv_dir,Config), + WName = list_to_atom(lists:concat([?FUNCTION_NAME,"_W"])), + WFile = lists:concat([?FUNCTION_NAME,"_W_log"]), + Size = length("12345"), + ConfigW = #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter => {?MODULE,no_nl}}, + WFileFull = filename:join(PrivDir, WFile), + DLOptsW = #{file => WFileFull, + type => wrap, + max_no_bytes => Size, + max_no_files => 2}, + ok = start_and_add(WName, ConfigW, DLOptsW), + WInfo1 = disk_log:info(WName), + 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), + timer:sleep(500), + 1 = Get(current_file, disk_log:info(WName)), + + logger:info("45", ?domain), + logger_disk_log_h:disk_log_sync(WName), + timer:sleep(500), + 1 = Get(current_file, disk_log:info(WName)), + + logger:info("6", ?domain), + logger_disk_log_h:disk_log_sync(WName), + timer:sleep(500), + 2 = Get(current_file, disk_log:info(WName)), + + logger:info("7890", ?domain), + logger_disk_log_h:disk_log_sync(WName), + timer:sleep(500), + 2 = Get(current_file, disk_log:info(WName)), + + HName1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_H1"])), + HFile1 = lists:concat([?FUNCTION_NAME,"_H1_log"]), + ConfigH = #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter => {?MODULE,no_nl}}, + HFile1Full = filename:join(PrivDir, HFile1), + DLOptsH1 = #{file => HFile1Full, + type => halt}, + ok = start_and_add(HName1, ConfigH, DLOptsH1), + HInfo1 = disk_log:info(HName1), + 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), + timer:sleep(500), + 1 = Get(no_written_items, disk_log:info(HName1)), + + HName2 = list_to_atom(lists:concat([?FUNCTION_NAME,"_H2"])), + HFile2 = lists:concat([?FUNCTION_NAME,"_H2_log"]), + HFile2Full = filename:join(PrivDir, HFile2), + DLOptsH2 = DLOptsH1#{file => HFile2Full, + max_no_bytes => 1000}, + ok = start_and_add(HName2, ConfigH, DLOptsH2), + HInfo3 = disk_log:info(HName2), + ct:log("Fullname = ~s", [HFile2Full]), + {HFile2Full,halt,1000} = {Get(file,HInfo3),Get(type,HInfo3), + Get(size,HInfo3)}, + + remove_and_stop(WName), + remove_and_stop(HName1), + remove_and_stop(HName2), + ok. + +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}, + ct:pal("Log: ~p", [LogFile]), + ok = logger:add_handler(?MODULE, logger_disk_log_h, HConfig), + ok = logger:set_handler_config(?MODULE,formatter, + {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), + LogName = lists:concat([LogFile, ".1"]), + logger:info("dummy"), + wait_until_written(LogName), + {ok,Bin} = file:read_file(LogName), + match = re:run(Bin, "=INFO REPORT====.*\ndummy", [{capture,none}]), + ok. +default_formatter(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +logging(Config) -> + PrivDir = ?config(priv_dir,Config), + %% test new handler + Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + LogFile = filename:join(PrivDir, Name), + ok = start_and_add(Name, #{filter_default=>log, + 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}], #{}), + 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). + +logging(cleanup, _Config) -> + Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + remove_and_stop(Name). + +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), + {error,{already_exist,Name1}} = + logger:add_handler(Name1, logger_disk_log_h, #{}), + + %%! TODO: + %%! Check how bad log_opts are handled! + + {error,{illegal_config_change,_,_}} = + logger:set_handler_config(Name1, + disk_log_opts, + #{file=>LogFile1, + type=>halt}), + {error,{illegal_config_change,_,_}} = + logger:set_handler_config(Name1,id,new), + + ok = logger:remove_handler(Name1), + {error,{not_found,Name1}} = logger:remove_handler(Name1), + ok. + +errors(cleanup, _Config) -> + Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + _ = logger:remove_handler(Name1). + +formatter_fail(Config) -> + PrivDir = ?config(priv_dir,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])}, + %% no formatter! + logger:add_handler(Name, logger_disk_log_h, HConfig), + Pid = whereis(Name), + true = is_pid(Pid), + {ok,#{handlers:=H}} = logger:get_logger_config(), + 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),"=INFO REPORT====.*\n"++M1,5000), + + ok = logger:set_handler_config(Name,formatter,{nonexistingmodule,#{}}), + logger:info(M2=?msg,?domain), + Got2 = try_match_file(?log_no(LogFile,1), + Got1++"=INFO REPORT====.*\nFORMATTER CRASH: .*"++M2, + 5000), + + ok = logger:set_handler_config(Name,formatter,{?MODULE,crash}), + logger:info(M3=?msg,?domain), + Got3 = try_match_file(?log_no(LogFile,1), + Got2++"=INFO REPORT====.*\nFORMATTER CRASH: .*"++M3, + 5000), + + ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}), + logger:info(?msg,?domain), + try_match_file(?log_no(LogFile,1), + Got3++"FORMATTER ERROR: bad_return_value", + 5000), + + %% Check that handler is still alive and was never dead + Pid = whereis(Name), + {ok,#{handlers:=H}} = logger:get_logger_config(), + ok. + +formatter_fail(cleanup,_Config) -> + _ = logger:remove_handler(?FUNCTION_NAME), + ok. + +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}, + filter_default=>log, + formatter=>{?MODULE,self()}}), + {error,{handler_not_added,{invalid_levels,{42,42,_}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{logger_disk_log_h => #{toggle_sync_qlen=>42, + drop_new_reqs_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, + #{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 + {error,{invalid_levels,_}} = + logger:set_handler_config(?MODULE,logger_disk_log_h, + #{toggle_sync_qlen=>100, + flush_reqs_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}), + 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,{info,["BadType"]}}} = logger_disk_log_h:info("BadType"), + {error,{badarg,{reset,["BadType"]}}} = logger_disk_log_h:reset("BadType"). + +info_and_reset(_Config) -> + ok = logger:add_handler(?MODULE,logger_disk_log_h, + #{filter_default=>log, + formatter=>{?MODULE,self()}}), + #{id := ?MODULE} = logger_disk_log_h:info(?MODULE), + ok = logger_disk_log_h:reset(?MODULE). +info_and_reset(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +reconfig(Config) -> + Dir = ?config(priv_dir,Config), + ok = logger:add_handler(?MODULE, + logger_disk_log_h, + #{filter_default=>log, + 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, + filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, + log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + 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}), + #{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, + filesync_repeat_interval := no_repeat} = + logger_disk_log_h:info(?MODULE), + + ok = logger:remove_handler(?MODULE), + + File = filename:join(Dir, "logfile"), + ok = logger:add_handler(?MODULE, + logger_disk_log_h, + #{filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}, + disk_log_opts=> + #{type => halt, + max_no_files => 1, + max_no_bytes => 1024, + file => File}}), + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}} = + logger_disk_log_h:info(?MODULE), + ok. + +reconfig(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +disk_log_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}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,nl}}), + + start_tracer([{?MODULE,format,2}, + {disk_log,blog,2}, + {disk_log,sync,1}], + [{formatter,"first"}, + {disk_log,blog}, + {disk_log,sync}]), + + logger:info("first", ?domain), + %% wait for automatic disk_log_sync + check_tracer(?FILESYNC_REPEAT_INTERVAL*2), + + start_tracer([{?MODULE,format,2}, + {disk_log,blog,2}, + {disk_log,sync,1}], + [{formatter,"second"}, + {formatter,"third"}, + {disk_log,blog}, + {disk_log,blog}, + {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), + 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}), + no_repeat = maps:get(filesync_repeat_interval, + logger_disk_log_h:info(?MODULE)), + + start_tracer([{?MODULE,format,2}, + {disk_log,blog,2}, + {disk_log,sync,1}], + [{formatter,"fourth"}, + {disk_log,blog}, + {formatter,"fifth"}, + {disk_log,blog}, + {disk_log,sync}]), + + logger:info("fourth", ?domain), + timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + logger:info("fifth", ?domain), + %% wait for automatic disk_log_sync + check_tracer(?IDLE_DETECT_TIME_MSEC*2), + + try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\nfifth\n">>}, 1000), + + %% switch repeated disk_log_sync on and verify that the looping works + SyncInt = 1000, + WaitT = 4500, + OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync}, + %% receive 1 initial repeated_disk_log_sync, then 1 per sec + 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}), + 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}), + check_tracer(100), + ok. +disk_log_sync(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +disk_log_wrap(Config) -> + Get = fun(Key, PL) -> proplists:get_value(Key, PL) end, + Dir = ?config(priv_dir,Config), + File = filename:join(Dir, ?FUNCTION_NAME), + ct:pal("Log = ~p", [File]), + MaxFiles = 3, + MaxBytes = 5, + ok = logger:add_handler(?MODULE, + logger_disk_log_h, + #{filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}, + disk_log_opts=> + #{type => wrap, + max_no_files => MaxFiles, + max_no_bytes => MaxBytes, + file => File}}), + Info = disk_log:info(?MODULE), + {File,wrap,{MaxBytes,MaxFiles},1} = + {Get(file,Info),Get(type,Info),Get(size,Info),Get(current_file,Info)}, + Tester = self(), + TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) -> + Pid ! {trace,Mod,Func,Details}, + Pid + end, + {ok,_} = dbg:tracer(process, {TraceFun, Tester}), + {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + + Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], + ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]), + %% fill first file + lists:foreach(fun(N) -> + Log = lists:concat([File,".",N]), + logger:info(Text, ?domain), + wait_until_written(Log), + ct:pal("N = ~w", + [N = Get(current_file, + disk_log:info(?MODULE))]) + end, lists:seq(1,MaxFiles)), + + %% wait for trace messages + timer:sleep(1000), + dbg:stop_clear(), + Received = lists:flatmap(fun({trace,_M,handle_info, + [{disk_log,_Node,_Name,What},_]}) -> + [{trace,What}]; + ({log,_}) -> + [] + end, test_server:messages_get()), + ct:pal("Trace =~n~p", [Received]), + Received = [{trace,{wrap,0}} || _ <- lists:seq(1,MaxFiles-1)], + ok. + +disk_log_wrap(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +disk_log_full(Config) -> + Dir = ?config(priv_dir,Config), + File = filename:join(Dir, ?FUNCTION_NAME), + ct:pal("Log = ~p", [File]), + MaxBytes = 50, + ok = logger:add_handler(?MODULE, + logger_disk_log_h, + #{filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}, + disk_log_opts=> + #{type => halt, + max_no_files => 1, + max_no_bytes => MaxBytes, + file => File}}), + + Tester = self(), + TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) -> + Pid ! {trace,Mod,Func,Details}, + Pid + end, + {ok,_} = dbg:tracer(process, {TraceFun, Tester}), + {ok,_} = dbg:p(whereis(?MODULE), [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)], + + %% wait for trace messages + timer:sleep(2000), + dbg:stop_clear(), + Received = lists:flatmap(fun({trace,_M,handle_info, + [{disk_log,_Node,_Name,What},_]}) -> + [{trace,What}]; + ({log,_}) -> + [] + end, test_server:messages_get()), + ct:pal("Trace =~n~p", [Received]), + [{trace,full}, + {trace,{error_status,{error,{full,_}}}}] = Received, + ok. +disk_log_full(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +disk_log_events(Config) -> + Node = node(), + Log = ?MODULE, + ok = logger:add_handler(?MODULE, + logger_disk_log_h, + #{filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + %% Events copied from disk_log API + Events = + [{disk_log, Node, Log, {wrap, 0}}, + {disk_log, Node, Log, {truncated, 0}}, + {disk_log, Node, Log, {read_only, 42}}, + {disk_log, Node, Log, {blocked_log, 42}}, + {disk_log, Node, Log, {format_external, 42}}, + {disk_log, Node, Log, full}, + {disk_log, Node, Log, {error_status, ok}}], + + Tester = self(), + TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) -> + Pid ! {trace,Mod,Func,Details}, + Pid + end, + {ok,_} = dbg:tracer(process, {TraceFun, Tester}), + {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + + [whereis(?MODULE) ! E || E <- Events], + %% wait for trace messages + timer:sleep(2000), + dbg:stop_clear(), + Received = lists:map(fun({trace,_M,handle_info, + [Got,_]}) -> Got + end, test_server:messages_get()), + ct:pal("Trace =~n~p", [Received]), + NoOfEvents = length(Events), + NoOfEvents = length(Received), + lists:foreach(fun(Event) -> + true = lists:member(Event, Received) + end, Received), + ok. +disk_log_events(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +write_failure(Config) -> + Dir = ?config(priv_dir, Config), + File = filename:join(Dir, ?FUNCTION_NAME), + Log = lists:concat([File,".1"]), + ct:pal("Log = ~p", [Log]), + + Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), + rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), + rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), + rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), + 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]), + ?check_no_log, + try_read_file(Log, {ok,<<"Logged1\n">>}, ?SYNC_REP_INT), + + rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + + ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), + + ok = log_on_remote_node(Node, "No second error printout"), + ?check_no_log, + + rpc:call(Node, ?MODULE, set_result, [disk_log_blog, + {error,{full,?STANDARD_HANDLER}}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + ?check({error,{?STANDARD_HANDLER,log,LogOpts, + {error,{full,?STANDARD_HANDLER}}}}), + + 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]), + ?check_no_log, + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?SYNC_REP_INT), + ok. +write_failure(cleanup, _Config) -> + Nodes = nodes(), + [test_server:stop_node(Node) || Node <- Nodes]. + + +sync_failure(Config) -> + Dir = ?config(priv_dir, Config), + FileName = lists:concat([?MODULE,"_",?FUNCTION_NAME]), + File = filename:join(Dir, FileName), + Log = lists:concat([File,".1"]), + + Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), + rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), + rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), + rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), + HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), + LogOpts = maps:get(log_opts, HState), + + SyncInt = 500, + ok = rpc:call(Node, logger, set_handler_config, + [?STANDARD_HANDLER, logger_disk_log_h, + #{filesync_repeat_interval => SyncInt}]), + Info = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), + SyncInt = maps:get(filesync_repeat_interval, Info), + + ok = log_on_remote_node(Node, "Logged1"), + ?check_no_log, + + 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}}}), + + ok = log_on_remote_node(Node, "No second error printout"), + ?check_no_log, + + 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, + {error,{blocked_log,?STANDARD_HANDLER}}}}), + + rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), + ok = log_on_remote_node(Node, "Logged2"), + ?check_no_log, + ok. +sync_failure(cleanup, _Config) -> + Nodes = nodes(), + [test_server:stop_node(Node) || Node <- Nodes]. + +start_h_on_new_node(_Config, Func, File) -> + Pa = filename:dirname(code:which(?MODULE)), + Dest = + case os:type() of + {win32,_} -> + lists:concat([" {disk_log,\\\"",File,"\\\"}"]); + _ -> + lists:concat([" \'{disk_log,\"",File,"\"}\'"]) + end, + Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), + NodeName = lists:concat([?MODULE,"_",Func]), + ct:pal("Starting ~s with ~tp", [NodeName,Args]), + {ok,Node} = test_server:start_node(NodeName, peer, [{args, Args}]), + Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + true = is_pid(Pid), + ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, + {?MODULE,nl}]), + Node. + +log_on_remote_node(Node,Msg) -> + _ = spawn_link(Node, + fun() -> erlang:group_leader(whereis(user),self()), + logger:info(Msg) + end), + ok. + +%% 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_defaults() -> + ?set_defaults(). + +%% internal log function that sends the term to the test case process +internal_log(Type, Term) -> + [{tester,Tester}] = ets:lookup(?TEST_HOOKS_TAB, tester), + Tester ! {log,{Type,Term}}, + logger:internal_log(Type, Term), + ok. + + +%%%----------------------------------------------------------------- +%%% Overload protection tests + +op_switch_to_sync(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig = + HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 3, + drop_new_reqs_qlen => 501, + flush_reqs_qlen => 2000, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + NumOfReqs = count_lines(Log), + ok = file:delete(Log). +op_switch_to_sync(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_drop(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 => 3, + flush_reqs_qlen => 600, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages dropped = ~w (~w)", + [NumOfReqs-Logged,NumOfReqs]), + true = (Logged < NumOfReqs), + ok = file:delete(Log). +op_switch_to_drop(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_flush() -> + [{timetrap,{seconds,60}}]. +op_switch_to_flush(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + + %% it's important that both async and sync requests have been queued + %% when the flush happens (verify with coverage of flush_log_requests/2) + + NewHConfig = + HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => 99, + flush_reqs_qlen => 100, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 1000, + Procs = 500, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages flushed/dropped = ~w (~w)", + [(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]), + true = (Logged < (NumOfReqs*Procs)), + ok = file:delete(Log). +op_switch_to_flush(cleanup, _Config) -> + ok = stop_handler(?MODULE). + + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + NumOfReqs = Logged. +limit_burst_disabled(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + ReqLimit = Logged. +limit_burst_enabled_one(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +limit_burst_enabled_period(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, 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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + + Windows = 3, + Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, info), + 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))). +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + true = is_pid(whereis(?MODULE)), + 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), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = 2000, + NewHConfig = + HConfig#{logger_disk_log_h => + DLHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>10, + handler_overloaded_mem=>Mem0+50000, + handler_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), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + timer:sleep(RestartAfter + 1000), + true = is_pid(whereis(?MODULE)), + ok + after + 5000 -> + Info = logger_disk_log_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info]), + ct:fail("Handler not dead! It should not have survived this!") + end. +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), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = 2000, + NewHConfig = + HConfig#{logger_disk_log_h => + DLHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>50000, + handler_overloaded_mem=>Mem0+500, + handler_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), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + timer:sleep(RestartAfter * 2), + true = is_pid(whereis(?MODULE)), + ok + after + 5000 -> + Info = logger_disk_log_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info]), + ct:fail("Handler not dead! It should not have survived this!") + end. +mem_kill_new(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig1), + MRef1 = erlang:monitor(process, whereis(?MODULE)), + %% kill handler + send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + receive + {'DOWN', MRef1, _, _, _Info1} -> + timer:sleep(?HANDLER_RESTART_AFTER + 1000), + undefined = whereis(?MODULE), + ok + after + 5000 -> + ct:fail("Handler not dead! It should not have survived this!") + end, + + {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + RestartAfter = 2000, + NewHConfig2 = + HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>10, + handler_restart_after=>RestartAfter}}, + ok = logger:set_handler_config(?MODULE, NewHConfig2), + Pid0 = whereis(?MODULE), + MRef2 = erlang:monitor(process, Pid0), + %% kill handler + send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + receive + {'DOWN', MRef2, _, _, _Info2} -> + timer:sleep(RestartAfter + 1000), + Pid1 = whereis(?MODULE), + true = is_pid(Pid1), + false = (Pid1 == Pid0), + ok + after + 5000 -> + 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) +%% during high load to verify that sync, dropping and flushing is +%% handled correctly. +handler_requests_under_load() -> + [{timetrap,{seconds,60}}]. +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{disk_log_sync,[]}, + {info,[]}, + {reset,[]}, + {change_config,[]}]) + end), + Procs = 100, + Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, info), + Pid ! {self(),finish}, + ReqResult = receive {Pid,Result} -> Result end, + Logged = count_lines(Log), + ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", + [Sent,Logged]), + FindError = fun(Res) -> + [E || E <- Res, + is_tuple(E) andalso (element(1,E) == error)] + end, + 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). +handler_requests_under_load(cleanup, Config) -> + ok = stop_handler(?MODULE). + +send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> + receive + {From,finish} -> + From ! {self(),Reqs} + after + TO -> + Result = + case Req of + change_config -> + logger:set_handler_config(HName, logger_disk_log_h, + #{enable_kill_overloaded => + false}); + Func -> + logger_disk_log_h:Func(HName) + end, + send_requests(HName, TO, Rs ++ [{Req,[Result|Res]}]) + end. + +%%%----------------------------------------------------------------- +%%% +start_handler(Name, FuncName, Config) -> + Dir = ?config(priv_dir,Config), + File = filename:join(Dir, FuncName), + ct:pal("Logging to ~tp", [File]), + ok = logger:add_handler(Name, + logger_disk_log_h, + #{disk_log_opts=>#{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}. + +stop_handler(Name) -> + ok = logger:remove_handler(Name), + ct:pal("Handler ~p stopped!", [Name]). + +send_burst(NorT, Type, {chars,Sz}, Class) -> + Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], + case NorT of + {n,N} -> + %% process_flag(priority, high), + send_n_burst(N, Type, Text, Class), + %% process_flag(priority, normal), + N; + {t,T} -> + ct:pal("Sending messages sequentially for ~w ms", [T]), + T0 = erlang:monotonic_time(millisecond), + send_t_burst(T0, T, Text, Class, 0) + end. + +send_n_burst(0, _, _Text, _Class) -> + ok; +send_n_burst(N, seq, Text, Class) -> + ok = logger:Class(Text, ?domain), + 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)], + lists:foreach(fun(MRef) -> + receive + {'DOWN', MRef, _, _, _} -> + ok + end + end, MRefs), + ct:pal("Message burst sent", []), + ok. + +send_t_burst(T0, T, Text, Class, N) -> + T1 = erlang:monotonic_time(millisecond), + if (T1-T0) > T -> + N; + true -> + ok = logger:Class(Text, ?domain), + send_t_burst(T0, T, Text, Class, N+1) + end. + +%%%----------------------------------------------------------------- +%%% Formatter callback +%%% Using this to send the formatted string back to the test case +%%% process - so it can check for logged events. +format(_,bad_return) -> + bad_return; +format(_,crash) -> + erlang:error(formatter_crashed); +format(#{msg:={report,R},meta:=#{report_cb:=Fun}}=Log,Config) -> + format(Log#{msg=>Fun(R)},Config); +format(#{msg:={string,String0}},no_nl) -> + String = unicode:characters_to_list(String0), + String; +format(#{msg:={string,String0}},nl) -> + String = unicode:characters_to_list(String0), + String++"\n"; +format(#{msg:={string,String0}},op) -> + String = unicode:characters_to_list(String0), + String++"\n"; +format(#{msg:={report,#{label:={supervisor,progress}}}},op) -> + ""; +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) -> + String = lists:flatten(io_lib:format(F,A)), + Pid ! {log,String}, + String++"\n"; +format(#{msg:={string,String0}},Pid) -> + String = unicode:characters_to_list(String0), + Pid ! {log,String}, + String++"\n"; +format(Msg,Tag) -> + Error = {unexpected_format,Msg,Tag}, + erlang:display(Error), + exit(Error). + +remove(Handler, LogName) -> + logger_disk_log_h: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), + {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), + true = is_pid(Pid), + Name = proplists:get_value(name, disk_log:info(Name)), + ok. + +remove_and_stop(Handler) -> + ok = logger:remove_handler(Handler), + timer:sleep(500), + undefined = whereis(Handler), + ok. + +try_read_file(FileName, Expected, Time) -> + try_read_file(FileName, Expected, Time, undefined). + +try_read_file(FileName, Expected, Time, _) when Time > 0 -> + case file:read_file(FileName) of + Expected -> + ok; + Error = {error,_Reason} -> + erlang:error(Error); + SomethingElse -> + ct:pal("try_read_file read unexpected: ~p~n", [SomethingElse]), + timer:sleep(500), + try_read_file(FileName, Expected, Time-500, SomethingElse) + end; + +try_read_file(_, _, _, Incorrect) -> + ct:pal("try_read_file got incorrect pattern: ~p~n", [Incorrect]), + erlang:error({error,not_matching_pattern,Incorrect}). + +try_match_file(FileName, Pattern, Time) -> + try_match_file(FileName, Pattern, Time, <<>>). + +try_match_file(FileName, Pattern, Time, _) when Time > 0 -> + case file:read_file(FileName) of + {ok, Bin} -> + case re:run(Bin,Pattern,[{capture,none}]) of + match -> + unicode:characters_to_list(Bin); + _ -> + timer:sleep(100), + try_match_file(FileName, Pattern, Time-100, Bin) + end; + Error -> + erlang:error(Error) + end; +try_match_file(_,Pattern,_,Incorrect) -> + ct:pal("try_match_file did not match pattern: ~p~nGot: ~p~n", + [Pattern,Incorrect]), + erlang:error({error,not_matching_pattern,Pattern,Incorrect}). + +count_lines(File) -> + wait_until_written(File), + count_lines1(File). + +wait_until_written(File) -> + wait_until_written(File, -1). + +wait_until_written(File, Sz) -> + timer:sleep(2000), + case file:read_file_info(File) of + {ok,#file_info{size = Sz}} -> + timer:sleep(1000), + case file:read_file_info(File) of + {ok,#file_info{size = Sz1}} -> + ok; + {ok,#file_info{size = Sz2}} -> + wait_until_written(File, Sz2) + 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), + file:close(Dev), + Lines. + +start_tracer(Trace,Expected) -> + Pid = self(), + dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), + dbg:p(whereis(?MODULE),[c]), + dbg:p(Pid,[c]), + tpl(Trace), + ok. + +tpl([{M,F,A}|Trace]) -> + {ok,Match} = dbg:tpl(M,F,A,[]), + case lists:keyfind(matched,1,Match) of + {_,_,1} -> + ok; + _ -> + dbg:stop_clear(), + throw({skip,"Can't trace "++atom_to_list(M)++":"++ + atom_to_list(F)++"/"++integer_to_list(A)}) + end, + tpl(Trace); +tpl([]) -> + ok. + +tracer({trace,_,call,{?MODULE,format,[#{msg:={string,Msg}}|_]}}, {Pid,[{formatter,Msg}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{formatter,Msg}); +tracer({trace,_,call,{logger_disk_log_h,handle_cast,[{Op,_}|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); +tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func}); +tracer({trace,_,call,Call}, {Pid,Expected}) -> + Pid ! {tracer_got_unexpected,Call,Expected}, + {Pid,Expected}. + +maybe_tracer_done(Pid,[],Got) -> + ct:log("Tracer got: ~p~n",[Got]), + Pid ! tracer_done; +maybe_tracer_done(Pid,Expected,Got) -> + ct:log("Tracer got: ~p~n",[Got]), + {Pid,Expected}. + +check_tracer(T) -> + receive + tracer_done -> + dbg:stop_clear(), + ok; + {tracer_got_unexpected,Got,Expected} -> + dbg:stop_clear(), + ct:fail({tracer_got_unexpected,Got,Expected}) + after T -> + ct:fail({timeout,tracer}) + end. diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl new file mode 100644 index 0000000000..c2d3364701 --- /dev/null +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -0,0 +1,451 @@ +% +%% %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_env_var_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). + +-define(all_vars,[{kernel,logger_dest}, + {kernel,logger_level}, + {kernel,logger_log_progress}, + {kernel,logger_sasl_compatible}, + {kernel,error_logger}]). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + Env = [{App,Key,application:get_env(App,Key)} || {App,Key} <- ?all_vars], + Removed = cleanup(), + [{env,Env},{logger,Removed}|Config]. + +end_per_suite(Config) -> + [application:set_env(App,Key,Val) || + {App,Key,Val} <- ?config(env,Config), + Val =/= undefined], + Hs = ?config(logger,Config), + [ok = logger:add_handler(Id,Mod,C) || {Id,Mod,C} <- Hs], + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + cleanup(), + ok. + +groups() -> + []. + +all() -> + [default, + default_sasl_compatible, + dest_tty, + dest_tty_sasl_compatible, + dest_false, + dest_false_progress, + dest_false_sasl_compatible, + dest_silent, + dest_silent_sasl_compatible, + dest_file_old, + dest_file, + dest_disk_log, + %% disk_log_vars, % or test this in logger_disk_log_SUITE? + sasl_compatible_false, + sasl_compatible_false_no_progress, + sasl_compatible, + bad_dest%% , + %% bad_level, + %% bad_sasl_compatibility, + %% bad_progress + ]. + +default(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + undefined, + undefined, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), + true = is_pid(whereis(logger_std_h)), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + false = is_pid(whereis(sasl_h)), + ok. + +default_sasl_compatible(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + undefined, + undefined, % dest + undefined, % level + true, % sasl comp (default=false) + undefined), % progress (default=false) + {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), + true = is_pid(whereis(logger_std_h)), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + true = lists:keymember(sasl_h,1,Hs), + true = is_pid(whereis(sasl_h)), + ok. + +dest_tty(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + tty, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), + true = is_pid(whereis(logger_std_h)), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + false = is_pid(whereis(sasl_h)), + ok. + +dest_tty_sasl_compatible(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + tty, % dest + undefined, % level + true, % sasl comp (default=false) + undefined), % progress (default=false) + {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), + true = is_pid(whereis(logger_std_h)), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + true = lists:keymember(sasl_h,1,Hs), + true = is_pid(whereis(sasl_h)), + ok. + +dest_false(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + false, % dest + notice, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + false = lists:keymember(logger_std_h,1,Hs), + {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), + notice = maps:get(level,SimpleC), + SimpleFilters = maps:get(filters,SimpleC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,SimpleFilters), + true = lists:keymember(stop_progress,1,SimpleFilters), + false = lists:keymember(sasl_h,1,Hs), + ok. + +dest_false_progress(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + false, % dest + notice, % level + undefined, % sasl comp (default=false) + true), % progress (default=false) + false = lists:keymember(logger_std_h,1,Hs), + {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), + notice = maps:get(level,SimpleC), + SimpleFilters = maps:get(filters,SimpleC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,SimpleFilters), + false = lists:keymember(stop_progress,1,SimpleFilters), + false = lists:keymember(sasl_h,1,Hs), + ok. + +dest_false_sasl_compatible(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + false, % dest + notice, % level + true, % sasl comp (default=false) + undefined), % progress (default=false) + false = lists:keymember(logger_std_h,1,Hs), + {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), + notice = maps:get(level,SimpleC), + SimpleFilters = maps:get(filters,SimpleC), + {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = + lists:keyfind(domain,1,SimpleFilters), + false = lists:keymember(stop_progress,1,SimpleFilters), + true = lists:keymember(sasl_h,1,Hs), + true = is_pid(whereis(sasl_h)), + ok. + +dest_silent(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + silent, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + false = lists:keymember(logger_std_h,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + ok. + +dest_silent_sasl_compatible(Config) -> + {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + silent, % dest + undefined, % level + true, % sasl comp (default=false) + undefined), % progress (default=false) + false = lists:keymember(logger_std_h,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + true = lists:keymember(sasl_h,1,Hs), + true = is_pid(whereis(sasl_h)), + ok. + + +dest_file_old(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + error_logger, + file, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + check_log(Log, + file, % dest + 0), % progress in std logger + ok. + + +dest_file(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + file, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + check_log(Log, + file, % dest + 0), % progress in std logger + ok. + + +dest_disk_log(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + disk_log, % dest + undefined, % level + undefined, % sasl comp (default=false) + undefined), % progress (default=false) + check_log(Log, + disk_log, % dest + 0), % progress in std logger + ok. + + +sasl_compatible_false(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + file, % dest + undefined, % level + false, % sasl comp + true), % progress + check_log(Log, + file, % dest + 4), % progress in std logger + ok. + +sasl_compatible_false_no_progress(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + file, % dest + undefined, % level + false, % sasl comp + false), % progress + check_log(Log, + file, % dest + 0), % progress in std logger + ok. + +sasl_compatible(Config) -> + {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, + logger_dest, + file, % dest + undefined, % level + true, % sasl comp + undefined), % progress + check_log(Log, + file, % dest + 0), % progress in std logger + ok. + +bad_dest(Config) -> + {error,{bad_config,{kernel,{logger_dest,baddest}}}} = + setup(Config,?FUNCTION_NAME, + logger_dest, + baddest, + undefined, + undefined, + undefined). + +bad_level(Config) -> + error = + setup(Config,?FUNCTION_NAME, + logger_dest, + tty, + badlevel, + undefined, + undefined). + +bad_sasl_compatibility(Config) -> + error = + setup(Config,?FUNCTION_NAME, + logger_dest, + tty, + info, + badcomp, + undefined). + +bad_progress(Config) -> + error = + setup(Config,?FUNCTION_NAME, + logger_dest, + tty, + info, + undefined, + badprogress). + +%%%----------------------------------------------------------------- +%%% Internal +setup(Config,Func,DestVar,Dest,Level,SaslComp,Progress) -> + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log, + logger_simple=>#{buffer=>true}}), + Dir = ?config(priv_dir,Config), + File = lists:concat([?MODULE,"_",Func,".log"]), + Log = filename:join(Dir,File), + case Dest of + undefined -> + ok; + F when F==file; F==disk_log -> + application:set_env(kernel,DestVar,{Dest,Log}); + _ -> + application:set_env(kernel,DestVar,Dest) + end, + case Level of + undefined -> + ok; + _ -> + application:set_env(kernel,logger_level,Level) + end, + case SaslComp of + undefined -> + ok; + _ -> + application:set_env(kernel,logger_sasl_compatible,SaslComp) + end, + case Progress of + undefined -> + ok; + _ -> + application:set_env(kernel,logger_log_progress,Progress) + end, + case logger:setup_standard_handler() of + ok -> + application:start(sasl), + StdH = case Dest of + NoH when NoH==false; NoH==silent -> false; + _ -> true + end, + StdH = is_pid(whereis(?STANDARD_HANDLER)), + SaslH = if SaslComp -> true; + true -> false + end, + SaslH = is_pid(whereis(sasl_h)), + {ok,{Log,maps:get(handlers,logger:i())}}; + Error -> + Error + end. + +check_log(Log,Dest,NumProgress) -> + ok = logger:alert("dummy1"), + ok = logger:debug("dummy1"), + + %% Check that there are progress reports (supervisor and + %% application_controller) and an error report (the call above) in + %% the log. There should not be any info reports yet. + {ok,Bin1} = sync_and_read(Dest,Log), + ct:log("Log content:~n~s",[Bin1]), + match(Bin1,<<"PROGRESS REPORT">>,NumProgress), + match(Bin1,<<"ALERT REPORT">>,1), + match(Bin1,<<"INFO REPORT">>,0), + match(Bin1,<<"DEBUG REPORT">>,0), + + %% Then stop sasl and see that the info report from + %% application_controller is there + ok = application:stop(sasl), + {ok,Bin2} = sync_and_read(Dest,Log), + ct:log("Log content:~n~s",[Bin2]), + match(Bin2,<<"INFO REPORT">>,1), + match(Bin1,<<"DEBUG REPORT">>,0), + ok. + +match(Bin,Pattern,0) -> + nomatch = re:run(Bin,Pattern,[{capture,none}]); +match(Bin,Pattern,N) -> + {match,M} = re:run(Bin,Pattern,[{capture,all},global]), + N = length(M). + +sync_and_read(disk_log,Log) -> + logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), + file:read_file(Log ++ ".1"); +sync_and_read(file,Log) -> + logger_std_h:filesync(?STANDARD_HANDLER), + file:read_file(Log). + +cleanup() -> + application:stop(sasl), + [application:unset_env(App,Key) || {App,Key} <- ?all_vars], + #{handlers:=Hs0} = logger:i(), + Hs = lists:keydelete(cth_log_redirect,1,Hs0), + [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], + Hs. diff --git a/lib/kernel/test/logger_filters_SUITE.erl b/lib/kernel/test/logger_filters_SUITE.erl new file mode 100644 index 0000000000..21f14bbc02 --- /dev/null +++ b/lib/kernel/test/logger_filters_SUITE.erl @@ -0,0 +1,214 @@ +%% +%% %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_filters_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). + +-define(ndlog, + #{level=>info,msg=>{"Line: ~p",[?LINE]},meta=>#{}}). +-define(dlog(Domain), + #{level=>info,msg=>{"Line: ~p",[?LINE]},meta=>#{domain=>Domain}}). +-define(llog(Level), + #{level=>Level,msg=>{"Line: ~p",[?LINE]},meta=>#{}}). +-define(plog, + #{level=>info, + msg=>{report,#{label=>{?MODULE,progress}}}, + meta=>#{line=>?LINE}}). +-define(rlog(Node), + #{level=>info, + msg=>{"Line: ~p",[?LINE]}, + meta=>#{gl=>rpc:call(Node,erlang,whereis,[user])}}). + +-define(TRY(X), my_try(fun() -> X end)). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [domain, + level, + progress, + remote_gl]. + +domain(_Config) -> + L1 = logger_filters:domain(L1=?dlog([]),{log,prefix_of,[]}), + stop = logger_filters:domain(?dlog([]),{stop,prefix_of,[]}), + L2 = logger_filters:domain(L2=?dlog([]),{log,starts_with,[]}), + stop = logger_filters:domain(?dlog([]),{stop,starts_with,[]}), + L3 = logger_filters:domain(L3=?dlog([]),{log,equals,[]}), + stop = logger_filters:domain(?dlog([]),{stop,equals,[]}), + ignore = logger_filters:domain(?dlog([]),{log,no_domain,[]}), + ignore = logger_filters:domain(?dlog([]),{stop,no_domain,[]}), + + L4 = logger_filters:domain(L4=?dlog([a]),{log,prefix_of,[a,b]}), + stop = logger_filters:domain(?dlog([a]),{stop,prefix_of,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{log,starts_with,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{stop,starts_with,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{log,equals,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{stop,equals,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{log,no_domain,[a,b]}), + ignore = logger_filters:domain(?dlog([a]),{stop,no_domain,[a,b]}), + + ignore = logger_filters:domain(?dlog([a,b]),{log,prefix_of,[a]}), + ignore = logger_filters:domain(?dlog([a,b]),{stop,prefix_of,[a]}), + L5 = logger_filters:domain(L5=?dlog([a,b]),{log,starts_with,[a]}), + stop = logger_filters:domain(?dlog([a,b]),{stop,starts_with,[a]}), + ignore = logger_filters:domain(?dlog([a,b]),{log,equals,[a]}), + ignore = logger_filters:domain(?dlog([a,b]),{stop,equals,[a]}), + ignore = logger_filters:domain(?dlog([a,b]),{log,no_domain,[a]}), + ignore = logger_filters:domain(?dlog([a,b]),{stop,no_domain,[a]}), + + ignore = logger_filters:domain(?ndlog,{log,prefix_of,[a]}), + ignore = logger_filters:domain(?ndlog,{stop,prefix_of,[a]}), + ignore = logger_filters:domain(?ndlog,{log,starts_with,[a]}), + ignore = logger_filters:domain(?ndlog,{stop,starts_with,[a]}), + ignore = logger_filters:domain(?ndlog,{log,equals,[a]}), + ignore = logger_filters:domain(?ndlog,{stop,equals,[a]}), + L6 = logger_filters:domain(L6=?ndlog,{log,no_domain,[a]}), + stop = logger_filters:domain(?ndlog,{stop,no_domain,[a]}), + + L7 = logger_filters:domain(L7=?dlog([a,b,c,d]),{log,prefix_of,[a,b,c,d]}), + stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,prefix_of,[a,b,c,d]}), + L8 = logger_filters:domain(L8=?dlog([a,b,c,d]),{log,starts_with,[a,b,c,d]}), + stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,starts_with,[a,b,c,d]}), + L9 = logger_filters:domain(L9=?dlog([a,b,c,d]),{log,equals,[a,b,c,d]}), + stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,equals,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{log,no_domain,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{stop,no_domain,[a,b,c,d]}), + + %% A domain field in meta which is not a list is allowed by the + %% filter, but it will never match. + ignore = logger_filters:domain(?dlog(dummy),{log,prefix_of,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{stop,prefix_of,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{log,starts_with,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{stop,starts_with,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{log,equals,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{stop,equals,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{log,no_domain,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog(dummy),{stop,no_domain,[a,b,c,d]}), + + {error,badarg} = ?TRY(logger_filters:domain(?ndlog,bad)), + {error,badarg} = ?TRY(logger_filters:domain(?ndlog,{bad,prefix_of,[]})), + {error,badarg} = ?TRY(logger_filters:domain(?ndlog,{log,bad,[]})), + {error,badarg} = ?TRY(logger_filters:domain(?ndlog,{log,prefix_of,bad})), + + ok. + +level(_Config) -> + ignore = logger_filters:level(?llog(info),{log,lt,info}), + ignore = logger_filters:level(?llog(info),{stop,lt,info}), + ignore = logger_filters:level(?llog(info),{log,gt,info}), + ignore = logger_filters:level(?llog(info),{stop,gt,info}), + L1 = logger_filters:level(L1=?llog(info),{log,lteq,info}), + stop = logger_filters:level(?llog(info),{stop,lteq,info}), + L2 = logger_filters:level(L2=?llog(info),{log,gteq,info}), + stop = logger_filters:level(?llog(info),{stop,gteq,info}), + L3 = logger_filters:level(L3=?llog(info),{log,eq,info}), + stop = logger_filters:level(?llog(info),{stop,eq,info}), + ignore = logger_filters:level(?llog(info),{log,neq,info}), + ignore = logger_filters:level(?llog(info),{stop,neq,info}), + + ignore = logger_filters:level(?llog(error),{log,lt,info}), + ignore = logger_filters:level(?llog(error),{stop,lt,info}), + L4 = logger_filters:level(L4=?llog(error),{log,gt,info}), + stop = logger_filters:level(?llog(error),{stop,gt,info}), + ignore = logger_filters:level(?llog(error),{log,lteq,info}), + ignore = logger_filters:level(?llog(error),{stop,lteq,info}), + L5 = logger_filters:level(L5=?llog(error),{log,gteq,info}), + stop = logger_filters:level(?llog(error),{stop,gteq,info}), + ignore = logger_filters:level(?llog(error),{log,eq,info}), + ignore = logger_filters:level(?llog(error),{stop,eq,info}), + L6 = logger_filters:level(L6=?llog(error),{log,neq,info}), + stop = logger_filters:level(?llog(error),{stop,neq,info}), + + L7 = logger_filters:level(L7=?llog(info),{log,lt,error}), + stop = logger_filters:level(?llog(info),{stop,lt,error}), + ignore = logger_filters:level(?llog(info),{log,gt,error}), + ignore = logger_filters:level(?llog(info),{stop,gt,error}), + L8 = logger_filters:level(L8=?llog(info),{log,lteq,error}), + stop = logger_filters:level(?llog(info),{stop,lteq,error}), + ignore = logger_filters:level(?llog(info),{log,gteq,error}), + ignore = logger_filters:level(?llog(info),{stop,gteq,error}), + ignore = logger_filters:level(?llog(info),{log,eq,error}), + ignore = logger_filters:level(?llog(info),{stop,eq,error}), + L9 = logger_filters:level(L9=?llog(info),{log,neq,error}), + stop = logger_filters:level(?llog(info),{stop,neq,error}), + + {error,badarg} = ?TRY(logger_filters:level(?llog(info),bad)), + {error,badarg} = ?TRY(logger_filters:level(?llog(info),{bad,eq,info})), + {error,badarg} = ?TRY(logger_filters:level(?llog(info),{log,bad,info})), + {error,badarg} = ?TRY(logger_filters:level(?llog(info),{log,eq,bad})), + + ok. + +progress(_Config) -> + L1 = logger_filters:progress(L1=?plog,log), + stop = logger_filters:progress(?plog,stop), + ignore = logger_filters:progress(?ndlog,log), + ignore = logger_filters:progress(?ndlog,stop), + + {error,badarg} = ?TRY(logger_filters:progress(?plog,bad)), + + ok. + +remote_gl(_Config) -> + {ok,Node} = test_server:start_node(?FUNCTION_NAME,slave,[]), + L1 = logger_filters:remote_gl(L1=?rlog(Node),log), + stop = logger_filters:remote_gl(?rlog(Node),stop), + ignore = logger_filters:remote_gl(?ndlog,log), + ignore = logger_filters:remote_gl(?ndlog,stop), + + {error,badarg} = ?TRY(logger_filters:remote_gl(?rlog(Node),bad)), + ok. + +remote_gl(cleanup,_Config) -> + [test_server:stop_node(N) || N<-nodes()]. + +%%%----------------------------------------------------------------- +%%% Called by macro ?TRY(X) +my_try(Fun) -> + try Fun() catch C:R -> {C,R} end. diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl new file mode 100644 index 0000000000..44e12d2d2a --- /dev/null +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -0,0 +1,501 @@ +%% +%% %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_formatter_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). + +-define(TRY(X), my_try(fun() -> X end)). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [default, + legacy_header, + single_line, + template, + format_msg, + report_cb, + max_size, + depth, + format_mfa, + format_time, + level_or_msg_in_meta, + faulty_log, + faulty_config, + faulty_msg]. + +default(_Config) -> + String1 = format(info,{"~p",[term]},#{},#{}), + ct:log(String1), + [_Date,_Time,"info:\nterm\n"] = string:lexemes(String1," "), + + Time = timestamp(), + ExpectedTimestamp = default_time_format(Time), + String2 = format(info,{"~p",[term]},#{time=>Time},#{}), + ct:log(String2), + " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), + ok. + +legacy_header(_Config) -> + Time = timestamp(), + String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true}), + ct:log(String1), + "=INFO REPORT==== "++Rest = String1, + [Timestamp,"\nterm\n"] = string:lexemes(Rest," ="), + [D,M,Y,H,Min,S,Micro] = string:lexemes(Timestamp,"-:."), + integer(D,31), + integer(Y,2018,infinity), + integer(H,23), + integer(Min,59), + integer(S,59), + integer(Micro,999999), + true = lists:member(M,["Jan","Feb","Mar","Apr","May","Jun", + "Jul","Aug","Sep","Oct","Nov","Dec"]), + + String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false}), + ct:log(String2), + ExpectedTimestamp = default_time_format(Time), + " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), + + String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad}), + ct:log(String3), + String3 = String2, + + String4 = format(info,{"~p",[term]},#{time=>Time}, + #{legacy_header=>true, + single_line=>true}), % <---ignored + ct:log(String4), + String4 = String1, + + String5 = format(info,{"~p",[term]},#{}, % <--- no time + #{legacy_header=>true}), + ct:log(String5), + "=INFO REPORT==== "++_ = String5, + ok. + +single_line(_Config) -> + Time = timestamp(), + ExpectedTimestamp = default_time_format(Time), + String1 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>true}), + ct:log(String1), + " info: term\n" = string:prefix(String1,ExpectedTimestamp), + + String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>false}), + ct:log(String2), + " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), + + String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>bad}), + ok. + +template(_Config) -> + Time = timestamp(), + + Template1 = [msg], + String1 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template1}), + ct:log(String1), + "term" = String1, + + Template2 = [msg,unknown], + String2 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template2}), + ct:log(String2), + "term" = String2, + + Template3 = ["string"], + String3 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template3}), + ct:log(String3), + "string" = String3, + + Template4 = ["string\nnewline"], + String4 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template4, + single_line=>true}), + ct:log(String4), + "string\nnewline" = String4, + + Template5 = [], + String5 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template5}), + ct:log(String5), + "" = String5, + + Ref6 = erlang:make_ref(), + Meta6 = #{atom=>some_atom, + integer=>632, + list=>[list,"string",4321,#{},{tuple}], + mfa=>{mod,func,0}, + pid=>self(), + ref=>Ref6, + string=>"some string", + time=>Time, + tuple=>{1,atom,"list"}, + nested=>#{subkey=>subvalue}}, + Template6 = lists:join(";",maps:keys(maps:remove(nested,Meta6)) ++ + [{nested,subkey}]), + String6 = format(info,{"~p",[term]},Meta6,#{template=>Template6, + single_line=>true}), + ct:log(String6), + SelfStr = pid_to_list(self()), + RefStr6 = ref_to_list(Ref6), + ListStr = "[list,\"string\",4321,#{},{tuple}]", + ExpectedTime6 = default_time_format(Time), + ["some_atom", + "632", + ListStr, + "mod:func/0", + SelfStr, + RefStr6, + "some string", + ExpectedTime6, + "{1,atom,\"list\"}", + "subvalue"] = string:lexemes(String6,";"), + + Meta7 = #{time=>Time, + 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}]), + String7 = format(info,{"~p",[term]},Meta7,#{template=>Template7, + single_line=>true}), + ct:log(String7), + [MultipleKeysStr, + "#{subkey1 => value1}", + "value1", + "value2", + "", + "", + ""] = string:split(String7,";",all), + %% Order of keys is not fixed + case MultipleKeysStr of + "#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok; + "#{key1 => #{subkey1 => value1},key2 => value2}" -> ok; + _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr}) + end, + ok. + +format_msg(_Config) -> + Template = [msg], + + String1 = format(info,{"~p",[term]},#{},#{template=>Template}), + ct:log(String1), + "term" = String1, + + String2 = format(info,{"list",[term]},#{},#{template=>Template}), + ct:log(String2), + "FORMAT ERROR: \"list\" - [term]" = String2, + + String3 = format(info,{report,term},#{},#{template=>Template}), + ct:log(String3), + "term" = String3, + + String4 = format(info,{report,term}, + #{report_cb=>fun(_)-> {"formatted",[]} end}, + #{template=>Template}), + ct:log(String4), + "formatted" = String4, + + String5 = format(info,{report,term}, + #{report_cb=>fun(_)-> faulty_return end}, + #{template=>Template}), + ct:log(String5), + "REPORT_CB ERROR: term; Returned: faulty_return" = String5, + + String6 = format(info,{report,term}, + #{report_cb=>fun(_)-> erlang:error(fun_crashed) end}, + #{template=>Template}), + ct:log(String6), + "REPORT_CB CRASH: term; Reason: {error,fun_crashed}" = String6, + + %% strings are not formatted + String7 = format(info,{string,"string"}, + #{report_cb=>fun(_)-> {"formatted",[]} end}, + #{template=>Template}), + ct:log(String7), + "string" = String7, + + String8 = format(info,{string,['not',printable,list]}, + #{report_cb=>fun(_)-> {"formatted",[]} end}, + #{template=>Template}), + ct:log(String8), + "INVALID STRING: ['not',printable,list]" = String8, + + String9 = format(info,{string,"string"},#{},#{template=>Template}), + ct:log(String9), + "string" = String9, + + ok. + +report_cb(_Config) -> + Template = [msg], + MetaFun = fun(_) -> {"meta_rcb",[]} end, + ConfigFun = fun(_) -> {"config_rcb",[]} end, + "term" = format(info,{report,term},#{},#{template=>Template}), + "meta_rcb" = + format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template}), + "config_rcb" = + format(info,{report,term},#{},#{template=>Template, + report_cb=>ConfigFun}), + "config_rcb" = + format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template, + report_cb=>ConfigFun}), + ok. + +max_size(_Config) -> + Template = [msg], + "12345678901234567890" = + format(info,{"12345678901234567890",[]},#{},#{template=>Template}), + application:set_env(kernel,logger_max_size,11), + "12345678901234567890" = % min value is 50, so this is not limited + format(info,{"12345678901234567890",[]},#{},#{template=>Template}), + "12345678901234567890123456789012345678901234567..." = % 50 + format(info, + {"123456789012345678901234567890123456789012345678901234567890", + []}, + #{}, + #{template=>Template}), + application:set_env(kernel,logger_max_size,53), + "12345678901234567890123456789012345678901234567890..." = %53 + format(info, + {"123456789012345678901234567890123456789012345678901234567890", + []}, + #{}, + #{template=>Template}), + "1234567..." = + format(info,{"12345678901234567890",[]},#{},#{template=>Template, + max_size=>10}), + "12345678901234567890" = + format(info,{"12345678901234567890",[]},#{},#{template=>Template, + max_size=>unlimited}), + ok. +max_size(cleanup,_Config) -> + application:unset_env(kernel,logger_max_size), + ok. + +depth(_Config) -> + Template = [msg], + "[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" = + format(info, + {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, + #{}, + #{template=>Template}), + application:set_env(kernel,error_logger_format_depth,11), + "[1,2,3,4,5,6,7,8,9,0|...]" = + format(info, + {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, + #{}, + #{template=>Template}), + application:set_env(kernel,logger_format_depth,12), + "[1,2,3,4,5,6,7,8,9,0,1|...]" = + format(info, + {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, + #{}, + #{template=>Template}), + "[1,2,3,4,5,6,7,8,9,0,1,2|...]" = + format(info, + {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, + #{}, + #{template=>Template, + depth=>13}), + "[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" = + format(info, + {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, + #{}, + #{template=>Template, + depth=>unlimited}), + ok. +depth(cleanup,_Config) -> + application:unset_env(kernel,logger_format_depth), + ok. + +format_mfa(_Config) -> + Template = [mfa], + + Meta1 = #{mfa=>{mod,func,0}}, + String1 = format(info,{"~p",[term]},Meta1,#{template=>Template}), + ct:log(String1), + "mod:func/0" = String1, + + Meta2 = #{mfa=>{mod,func,[]}}, + String2 = format(info,{"~p",[term]},Meta2,#{template=>Template}), + ct:log(String2), + "mod:func/0" = String2, + + Meta3 = #{mfa=>"mod:func/0"}, + String3 = format(info,{"~p",[term]},Meta3,#{template=>Template}), + ct:log(String3), + "mod:func/0" = String3, + + Meta4 = #{mfa=>othermfa}, + String4 = format(info,{"~p",[term]},Meta4,#{template=>Template}), + ct:log(String4), + "othermfa" = String4, + + ok. + +format_time(_Config) -> + Time1 = timestamp(), + ExpectedTimestamp1 = default_time_format(Time1), + String1 = format(info,{"~p",[term]},#{time=>Time1},#{}), + ct:log(String1), + " info:\nterm\n" = string:prefix(String1,ExpectedTimestamp1), + + Time2 = timestamp(), + ExpectedTimestamp2 = default_time_format(Time2,true), + String2 = format(info,{"~p",[term]},#{time=>Time2},#{utc=>true}), + ct:log(String2), + " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp2), + + application:set_env(kernel,logger_utc,true), + Time3 = timestamp(), + ExpectedTimestamp3 = default_time_format(Time3,true), + String3 = format(info,{"~p",[term]},#{time=>Time3},#{}), + ct:log(String3), + " info:\nterm\n" = string:prefix(String3,ExpectedTimestamp3), + + ok. + +format_time(cleanup,_Config) -> + application:unset_env(kernel,logger_utc), + ok. + +level_or_msg_in_meta(_Config) -> + %% The template contains atoms to pick out values from meta, + %% or level/msg to add these from the log event. What if you have + %% a key named 'level' or 'msg' in meta and want to display + %% its value? + %% For now we simply ignore Meta on this and display the + %% actual level and msg from the log event. + + Meta = #{level=>mylevel, + msg=>"metamsg"}, + Template = [level,";",msg], + String = format(info,{"~p",[term]},Meta,#{template=>Template}), + ct:log(String), + "info;term" = String, % so mylevel and "metamsg" are ignored + + ok. + +faulty_log(_Config) -> + %% Unexpected log (should be type logger:log()) - print error + {error, + function_clause, + {logger_formatter,format,[_,_],_}} = + ?TRY(logger_formatter:format(unexp_log,#{})), + ok. + +faulty_config(_Config) -> + {error, + function_clause, + {logger_formatter,format,[_,_],_}} = + ?TRY(logger_formatter:format(#{level=>info, + msg=>{"~p",[term]}, + meta=>#{time=>timestamp()}}, + unexp_config)), + ok. + +faulty_msg(_Config) -> + {error, + function_clause, + {logger_formatter,_,[_,_],_}} = + ?TRY(logger_formatter:format(#{level=>info, + msg=>term, + meta=>#{time=>timestamp()}}, + #{})), + ok. + +%%%----------------------------------------------------------------- +%%% Internal +format(Level,Msg,Meta,Config) -> + format(#{level=>Level,msg=>Msg,meta=>add_time(Meta)},Config). + +format(Log,Config) -> + lists:flatten(logger_formatter:format(Log,Config)). + +default_time_format(Timestamp) -> + default_time_format(Timestamp,false). + +default_time_format(Timestamp0,Utc) when is_integer(Timestamp0) -> + Timestamp=Timestamp0+erlang:time_offset(microsecond), + %% calendar:system_time_to_rfc3339(Time,[{unit,microsecond}]). + Micro = Timestamp rem 1000000, + Sec = Timestamp div 1000000, + UniversalTime = erlang:posixtime_to_universaltime(Sec), + {Date,Time} = + if Utc -> UniversalTime; + true -> erlang:universaltime_to_localtime(UniversalTime) + end, + default_time_format(Date,Time,Micro). + +default_time_format({Y,M,D},{H,Min,S},Micro) -> + lists:flatten( + io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", + [Y,M,D,H,Min,S,Micro])). + +integer(Str) -> + is_integer(list_to_integer(Str)). +integer(Str,Max) -> + integer(Str,0,Max). +integer(Str,Min,Max) -> + Int = list_to_integer(Str), + Int >= Min andalso Int =<Max. + +%%%----------------------------------------------------------------- +%%% Called by macro ?TRY(X) +my_try(Fun) -> + try Fun() catch C:R:S -> {C,R,hd(S)} end. + +timestamp() -> + erlang:monotonic_time(microsecond). + +%% necessary? +add_time(#{time:=_}=Meta) -> + Meta; +add_time(Meta) -> + Meta#{time=>timestamp()}. diff --git a/lib/kernel/test/logger_legacy_SUITE.erl b/lib/kernel/test/logger_legacy_SUITE.erl new file mode 100644 index 0000000000..b59f5f7758 --- /dev/null +++ b/lib/kernel/test/logger_legacy_SUITE.erl @@ -0,0 +1,282 @@ +%% +%% %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_legacy_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). + +%%%----------------------------------------------------------------- +%%% This test suite test that log events from within OTP can be +%%% delivered to legacy error_logger event handlers on the same format +%%% as before 'logger' was introduced. +%%% +%%% Before changing the expected format of any of the log events in +%%% this suite, please make sure that the backwards incompatibility it +%%% introduces is ok. +%%% ----------------------------------------------------------------- + +-define(check(Expected), + receive Expected -> + [] = test_server:messages_get() + after 1000 -> + ct:fail({report_not_received, + {line,?LINE}, + {got,test_server:messages_get()}}) + end). +-define(check_no_flush(Expected), + receive Expected -> + ok + after 1000 -> + ct:fail({report_not_received, + {line,?LINE}, + {got,test_server:messages_get()}}) + end). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + logger:add_handler(error_logger,error_logger, + #{level=>info,filter_default=>stop}), + Config. + +end_per_suite(_Config) -> + logger:remove_handler(error_logger), + ok. + +init_per_group(std, Config) -> + ok = logger:set_handler_config( + error_logger,filters, + [{domain,{fun logger_filters:domain/2, + {log,prefix_of,[beam,erlang,otp]}}}]), + Config; +init_per_group(sasl, Config) -> + ok = logger:set_handler_config( + error_logger,filters, + [{domain,{fun logger_filters:domain/2, + {log,prefix_of,[beam,erlang,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; +init_per_group(_Group, Config) -> + Config. + +end_per_group(sasl, _Config) -> + application:stop(sasl), + ok; +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + error_logger:add_report_handler(?MODULE,{event_handler,self()}), + Config. + +end_per_testcase(Case, Config) -> + %% Using gen_event directly here, instead of + %% error_logger:delete_report_handler. This is to avoid + %% automatically stopping the error_logger process due to removing + %% the last handler. + gen_event:delete_handler(error_logger,?MODULE,[]), + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + [{std,[],[gen_server, + gen_event, + gen_fsm, + gen_statem]}, + {sasl,[],[sasl_reports, + supervisor_handle_info]}]. + +all() -> + [{group,std}, + {group,sasl}]. + +gen_server(_Config) -> + {ok,Pid} = gen_server:start(?MODULE,gen_server,[]), + Msg = fun() -> a=b end, + Pid ! Msg, + ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), + ok = gen_server:cast(Pid,Msg), + ?check({error,"** Generic server ~tp terminating"++_, + [Pid,{'$gen_cast',Msg},gen_server,{{badmatch,b},_}]}). + +gen_event(_Config) -> + {ok,Pid} = gen_event:start(), + ok = gen_event:add_handler(Pid,?MODULE,gen_event), + Msg = fun() -> a=b end, + Pid ! Msg, + ?check({warning_msg,"** Undefined handle_info in ~tp"++_,[?MODULE,Msg]}), + gen_event:notify(Pid,Msg), + ?check({error,"** gen_event handler ~p crashed."++_, + [?MODULE,Pid,Msg,gen_event,{{badmatch,b},_}]}). + +gen_fsm(_Config) -> + {ok,Pid} = gen_fsm:start(?MODULE,gen_fsm,[]), + Msg = fun() -> a=b end, + Pid ! Msg, + ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), + gen_fsm:send_all_state_event(Pid,Msg), + ?check({error,"** State machine ~tp terminating"++_, + [Pid,Msg,mystate,gen_fsm,{{badmatch,b},_}]}). + +gen_statem(_Config) -> + {ok,Pid} = gen_statem:start(?MODULE,gen_statem,[]), + Msg = fun() -> a=b end, + Pid ! Msg, + ?check({error,"** State machine ~tp terminating"++_, + [Pid,{info,Msg},{mystate,gen_statem},error,{badmatch,b}|_]}). + +sasl_reports(Config) -> + App = {application,?MODULE,[{description, ""}, + {vsn, "1.0"}, + {modules, [?MODULE]}, + {registered, []}, + {applications, []}, + {mod, {?MODULE, []}}]}, + AppStr = io_lib:format("~p.",[App]), + Dir = ?config(priv_dir,Config), + AppFile = filename:join(Dir,?MODULE_STRING++".app"), + ok = file:write_file(AppFile,AppStr), + true = code:add_patha(Dir), + ok = application:start(?MODULE), + SupName = sup_name(), + Pid = whereis(SupName), + [{ch,ChPid,_,_}] = supervisor:which_children(Pid), + Node = node(), + ?check_no_flush({info_report,progress,[{application,?MODULE}, + {started_at,Node}]}), + ?check({info_report,progress,[{supervisor,{local,SupName}}, + {started,[{pid,ChPid}|_]}]}), + ok = gen_server:cast(ChPid, fun() -> + spawn_link(fun() -> receive x->ok end end) + end), + Msg = fun() -> a=b end, + ok = gen_server:cast(ChPid,Msg), + ?check_no_flush({error,"** Generic server ~tp terminating"++_, + [ChPid,{'$gen_cast',Msg},gen_server,{{badmatch,b},_}]}), + ?check_no_flush({error_report,crash_report, + [[{initial_call,_}, + {pid,ChPid}, + {registered_name,[]}, + {error_info,{error,{badmatch,b},_}}, + {ancestors,_}, + {message_queue_len,_}, + {messages,_}, + {links,[Pid,Neighbour]}, + {dictionary,_}, + {trap_exit,_}, + {status,_}, + {heap_size,_}, + {stack_size,_}, + {reductions,_}], + [{neighbour,[{pid,Neighbour}, + {registered_name,_}, + {initial_call,_}, + {current_function,_}, + {ancestors,_}, + {message_queue_len,_}, + {links,[ChPid]}, + {trap_exit,_}, + {status,_}, + {heap_size,_}, + {stack_size,_}, + {reductions,_}, + {current_stacktrace,_}]}]]}), + ?check_no_flush({error_report,supervisor_report, + [{supervisor,{local,SupName}}, + {errorContext,child_terminated}, + {reason,{{badmatch,b},_}}, + {offender,[{pid,ChPid}|_]}]}), + ?check({info_report,progress,[{supervisor,{local,SupName}}, + {started,_}]}), + + ok = application:stop(?MODULE), + ?check({info_report,std_info,[{application,?MODULE}, + {exited,stopped}, + {type,temporary}]}). + +sasl_reports(cleanup,_Config) -> + application:stop(?MODULE). + +supervisor_handle_info(_Config) -> + {ok,Pid} = supervisor:start_link({local,sup_name()},?MODULE,supervisor), + ?check({info_report,progress,[{supervisor,_},{started,_}]}), + Pid ! msg, + ?check({error,"Supervisor received unexpected message: ~tp~n",[msg]}). + +supervisor_handle_info(cleanup,_Config) -> + Pid = whereis(sup_name()), + unlink(Pid), + exit(Pid,shutdown). + +%%%----------------------------------------------------------------- +%%% Callbacks for error_logger event handler, gen_server, gen_statem, +%%% gen_fsm, gen_event, supervisor and application. +start(_,_) -> + supervisor:start_link({local,sup_name()},?MODULE,supervisor). + +init(supervisor) -> + {ok,{#{},[#{id=>ch,start=>{gen_server,start_link,[?MODULE,gen_server,[]]}}]}}; +init(StateMachine) when StateMachine==gen_statem; StateMachine==gen_fsm -> + {ok,mystate,StateMachine}; +init(State) -> + {ok,State}. + +%% error_logger event handler +handle_event({Tag,_Gl,{_Pid,Type,Report}},{_,Pid}=State) -> + Pid ! {Tag,Type,Report}, + {ok,State}; +%% other gen_event +handle_event(Fun,State) when is_function(Fun) -> + Fun(), + {next_state,State}. + +%% gen_fsm +handle_event(Fun,State,Data) when is_function(Fun) -> + Fun(), + {next_state,State,Data}. + +%% gen_statem +handle_event(info,Fun,State,Data) when is_function(Fun) -> + Fun(), + {next_state,State,Data}. + +%% gen_server +handle_cast(Fun,State) when is_function(Fun) -> + Fun(), + {noreply,State}. + +%% gen_statem +callback_mode() -> + handle_event_function. + +%%%----------------------------------------------------------------- +%%% Internal +sup_name() -> + list_to_atom(?MODULE_STRING++"_sup"). diff --git a/lib/kernel/test/logger_simple_SUITE.erl b/lib/kernel/test/logger_simple_SUITE.erl new file mode 100644 index 0000000000..5d8d32492d --- /dev/null +++ b/lib/kernel/test/logger_simple_SUITE.erl @@ -0,0 +1,247 @@ +%% +%% %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_simple_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). + +-define(check_no_log,[] = test_server:messages_get()). +-define(check(Expected), + receive {log,Expected} -> + [] = test_server:messages_get() + after 1000 -> + ct:fail({report_not_received, + {line,?LINE}, + {expected,Expected}, + {got,test_server:messages_get()}}) + end). + +-define(str,"Log from "++atom_to_list(?FUNCTION_NAME)++ + ":"++integer_to_list(?LINE)). +-define(map_rep,#{function=>?FUNCTION_NAME, line=>?LINE}). +-define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + #{handlers:=Hs0} = logger:i(), + Hs = lists:keydelete(cth_log_redirect,1,Hs0), + [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], + Env = [{App,Key,application:get_env(App,Key)} || + {App,Key} <- [{kernel,logger_dest}, + {kernel,logger_level}]], + [{env,Env},{logger,Hs}|Config]. + +end_per_suite(Config) -> + [application:set_env(App,Key,Val) || {App,Key,Val} <- ?config(env,Config)], + Hs = ?config(logger,Config), + [ok = logger:add_handler(Id,Mod,C) || {Id,Mod,C} <- Hs], + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [start_stop, + get_buffer, + replace_file, + replace_disk_log + ]. + +start_stop(_Config) -> + undefined = whereis(logger_simple), + register(logger_simple,self()), + {error,_} = logger:add_handler(logger_simple, + logger_simple, + #{filter_default=>log}), + unregister(logger_simple), + ok = logger:add_handler(logger_simple,logger_simple,#{filter_default=>log}), + Pid = whereis(logger_simple), + true = is_pid(Pid), + ok = logger:remove_handler(logger_simple), + false = is_pid(whereis(logger_simple)), + ok. +start_stop(cleanup,_Config) -> + logger:remove_handler(logger_simple). + +get_buffer(_Config) -> + %% Start simple without buffer + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log}), + logger:emergency(?str), + logger:alert(?str,[]), + logger:error(?map_rep), + logger:info(?keyval_rep), + {ok,[]} = logger_simple:get_buffer(), % no buffer + ok = logger:remove_handler(logger_simple), + + %% Start with buffer + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log, + logger_simple=>#{buffer=>true}}), + logger:emergency(M1=?str), + logger:alert(M2=?str,[]), + logger:error(M3=?map_rep), + logger:info(M4=?keyval_rep), + logger:info(M41=?keyval_rep++[not_key_val]), + error_logger:error_report(some_type,M5=?map_rep), + error_logger:warning_report("some_type",M6=?map_rep), + logger:critical(M7=?str,[A7=?keyval_rep]), + logger:notice(M8=["fake",string,"line:",?LINE]), + {ok,Buffered1} = logger_simple:get_buffer(), + [#{level:=emergency,msg:={string,M1}}, + #{level:=alert,msg:={M2,[]}}, + #{level:=error,msg:={report,M3}}, + #{level:=info,msg:={report,M4}}, + #{level:=info,msg:={report,M41}}, + #{level:=error,msg:={report,#{label:={error_logger,error_report}, + report:=M5}}}, + #{level:=warning,msg:={report,#{label:={error_logger,warning_report}, + report:=M6}}}, + #{level:=critical,msg:={M7,[A7]}}, + #{level:=notice,msg:={string,M8}}] = Buffered1, + + %% Keep logging - should not buffer any more + logger:emergency(?str), + logger:alert(?str,[]), + logger:error(?map_rep), + logger:info(?keyval_rep), + {ok,[]} = logger_simple:get_buffer(), + ok = logger:remove_handler(logger_simple), + + %% Fill buffer and drop + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log, + logger_simple=>#{buffer=>true}}), + logger:emergency(M9=?str), + M10=?str, + [logger:info(M10) || _ <- lists:seq(1,8)], + logger:error(M11=?str), + logger:error(?str), + logger:error(?str), + {ok,Buffered3} = logger_simple:get_buffer(), + 11 = length(Buffered3), + [#{level:=emergency,msg:={string,M9}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=info,msg:={string,M10}}, + #{level:=error,msg:={string,M11}}, + #{level:=info,msg:={"Simple handler buffer full, dropped ~w messages",[2]}}] + = Buffered3, + ok. +get_buffer(cleanup,_Config) -> + logger:remove_handler(logger_simple). + +replace_file(Config) -> + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log, + logger_simple=>#{buffer=>true}}), + logger:emergency(M1=?str), + logger:alert(M2=?str,[]), + logger:error(?map_rep), + logger:info(?keyval_rep), + undefined = whereis(?STANDARD_HANDLER), + PrivDir = ?config(priv_dir,Config), + File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)++".log"), + + application:set_env(kernel,logger_dest,{file,File}), + application:set_env(kernel,logger_level,info), + + ok = logger:setup_standard_handler(), + true = is_pid(whereis(?STANDARD_HANDLER)), + ok = logger_std_h:filesync(?STANDARD_HANDLER), + {ok,Bin} = file:read_file(File), + Lines = [unicode:characters_to_list(L) || + L <- binary:split(Bin,<<"\n">>,[global,trim])], + ["=EMERGENCY REPORT===="++_, + M1, + "=ALERT REPORT===="++_, + M2, + "=ERROR REPORT===="++_, + _, + _, + "=INFO REPORT===="++_, + _, + _] = Lines, + ok. +replace_file(cleanup,_Config) -> + logger:remove_handler(?STANDARD_HANDLER), + logger:remove_handler(logger_simple). + +replace_disk_log(Config) -> + ok = logger:add_handler(logger_simple,logger_simple, + #{filter_default=>log, + logger_simple=>#{buffer=>true}}), + logger:emergency(M1=?str), + logger:alert(M2=?str,[]), + logger:error(?map_rep), + logger:info(?keyval_rep), + undefined = whereis(?STANDARD_HANDLER), + PrivDir = ?config(priv_dir,Config), + File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)), + + application:set_env(kernel,logger_dest,{disk_log,File}), + application:set_env(kernel,logger_level,info), + + ok = logger:setup_standard_handler(), + true = is_pid(whereis(?STANDARD_HANDLER)), + ok = logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), + {ok,Bin} = file:read_file(File++".1"), + Lines = [unicode:characters_to_list(L) || + L <- binary:split(Bin,<<"\n">>,[global,trim])], + ["=EMERGENCY REPORT===="++_, + M1, + "=ALERT REPORT===="++_, + M2, + "=ERROR REPORT===="++_, + _, + _, + "=INFO REPORT===="++_, + _, + _|_] = Lines, % the tail might be an info report about opening the disk log + ok. +replace_disk_log(cleanup,_Config) -> + logger:remove_handler(?STANDARD_HANDLER), + logger:remove_handler(logger_simple). + diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl new file mode 100644 index 0000000000..e940e0a026 --- /dev/null +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -0,0 +1,1396 @@ +%% +%% %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_std_h_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_internal.hrl"). +-include_lib("kernel/src/logger_h_common.hrl"). +-include_lib("stdlib/include/ms_transform.hrl"). +-include_lib("kernel/include/file.hrl"). + +-define(check_no_log, [] = test_server:messages_get()). +-define(check(Expected), + receive + {log,Expected} -> + [] = test_server:messages_get() + after 5000 -> + ct:fail({report_not_received, + {line,?LINE}, + {expected,Expected}, + {got,test_server:messages_get()}}) + end). + +-define(msg,"Log from "++atom_to_list(?FUNCTION_NAME)++ + ":"++integer_to_list(?LINE)). +-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}}]. + +init_per_suite(Config) -> + timer:start(), % to avoid progress report + {ok,{?STANDARD_HANDLER,#{formatter:=OrigFormatter}}} = + logger:get_handler_config(?STANDARD_HANDLER), + [{formatter,OrigFormatter}|Config]. + +end_per_suite(Config) -> + {OrigMod,OrigConf} = proplists:get_value(formatter,Config), + logger:set_handler_config(?STANDARD_HANDLER,formatter,{OrigMod,OrigConf}), + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(TestHooksCase, Config) when + TestHooksCase == write_failure; + TestHooksCase == sync_failure -> + if ?TEST_HOOKS_TAB == undefined -> + {skip,"Define the TEST_HOOKS macro to run this test"}; + true -> + ct:print("********** ~w **********", [TestHooksCase]), + Config + end; +init_per_testcase(TestCase, Config) -> + ct:print("********** ~w **********", [TestCase]), + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [add_remove_instance_tty, + add_remove_instance_standard_io, + add_remove_instance_standard_error, + add_remove_instance_file1, + add_remove_instance_file2, + default_formatter, + errors, + formatter_fail, + config_fail, + crash_std_h_to_file, + crash_std_h_to_disk_log, + bad_input, + info_and_reset, + reconfig, + file_opts, + filesync, + write_failure, + sync_failure, + op_switch_to_sync_file, + op_switch_to_sync_tty, + op_switch_to_drop_file, + op_switch_to_drop_tty, + op_switch_to_flush_file, + op_switch_to_flush_tty, + limit_burst_disabled, + limit_burst_enabled_one, + limit_burst_enabled_period, + kill_disabled, + qlen_kill_new, + qlen_kill_std, + mem_kill_new, + mem_kill_std, + restart_after, + handler_requests_under_load + ]. + +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}, + filter_default=>log, + formatter=>{?MODULE,self()}}), + ok. + +add_remove_instance_standard_io(_Config) -> + add_remove_instance_nofile(standard_io). +add_remove_instance_standard_io(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_standard_error(_Config) -> + add_remove_instance_nofile(standard_error). +add_remove_instance_standard_error(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file1(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog1.txt"), + Type = {file,Log}, + add_remove_instance_file(Log, Type). +add_remove_instance_file1(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file2(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog2.txt"), + Type = {file,Log,[raw,append]}, + add_remove_instance_file(Log, Type). +add_remove_instance_file2(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file(Log, Type) -> + ok = logger:add_handler(?MODULE, + logger_std_h, + #{logger_std_h => #{type => Type}, + filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + Pid = whereis(?MODULE), + true = is_pid(Pid), + logger:info(M1=?msg,?domain), + ?check(M1), + B1 = ?bin(M1), + try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + ok = logger:remove_handler(?MODULE), + timer:sleep(500), + undefined = whereis(?MODULE), + logger:info(?msg,?domain), + ?check_no_log, + 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), + timer:sleep(100), + ct:capture_stop(), + [Msg] = ct:capture_get(), + match = re:run(Msg,"=INFO REPORT====.*\n"++M1,[{capture,none}]), + ok. + +errors(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,?FUNCTION_NAME), + + ok = logger:add_handler(?MODULE,logger_std_h,#{}), + {error,{already_exist,?MODULE}} = + logger:add_handler(?MODULE,logger_std_h,#{}), + + {error,{not_found,no_such_name}} = logger:remove_handler(no_such_name), + + ok = logger:remove_handler(?MODULE), + {error,{not_found,?MODULE}} = logger:remove_handler(?MODULE), + + {error, + {handler_not_added, + {invalid_config,logger_std_h,{type,faulty_type}}}} = + logger:add_handler(?MODULE,logger_std_h, + #{logger_std_h => #{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}}}), + + {error, + {handler_not_added,{{open_failed,Log,_},_}}} = + logger:add_handler(myh3,logger_std_h, + #{logger_std_h=>#{type=>{file,Log,[bad_file_opt]}}}), + + ok = logger:info(?msg). + +errors(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +formatter_fail(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,?FUNCTION_NAME), + + %% no formatter + ok = logger:add_handler(?MODULE, + logger_std_h, + #{logger_std_h => #{type => {file,Log}}, + filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), + Pid = whereis(?MODULE), + true = is_pid(Pid), + {ok,#{handlers:=H}} = logger:get_logger_config(), + 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,"=INFO REPORT====.*\n"++M1,5000), + + ok = logger:set_handler_config(?MODULE,formatter,{nonexistingmodule,#{}}), + logger:info(M2=?msg,?domain), + Got2 = try_match_file(Log, + Got1++"=INFO REPORT====.*\nFORMATTER CRASH: .*"++M2, + 5000), + + ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,crash}), + logger:info(M3=?msg,?domain), + Got3 = try_match_file(Log, + Got2++"=INFO REPORT====.*\nFORMATTER CRASH: .*"++M3, + 5000), + + ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,bad_return}), + logger:info(?msg,?domain), + try_match_file(Log, + Got3++"FORMATTER ERROR: bad_return_value", + 5000), + + %% Check that handler is still alive and was never dead + Pid = whereis(?MODULE), + {ok,#{handlers:=H}} = logger:get_logger_config(), + + ok. + +formatter_fail(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +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}, + 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}, + filter_default=>log, + formatter=>{?MODULE,self()}}), + {error,{handler_not_added,{invalid_levels,{42,42,_}}}} = + logger:add_handler(?MODULE,logger_std_h, + #{logger_std_h => #{toggle_sync_qlen=>42, + drop_new_reqs_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, + #{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}), + {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = + logger:set_handler_config(?MODULE, logger_std_h, + #{filesync_rep_int => 2000}), + ok. + +config_fail(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +crash_std_h_to_file(Config) -> + crash_std_h(Config,?FUNCTION_NAME,logger_dest,file). +crash_std_h_to_file(cleanup,_Config) -> + crash_std_h(cleanup). + +crash_std_h_to_disk_log(Config) -> + crash_std_h(Config,?FUNCTION_NAME,logger_dest,disk_log). +crash_std_h_to_disk_log(cleanup,_Config) -> + crash_std_h(cleanup). + +crash_std_h(Config,Func,Var,Type) -> + Dir = ?config(priv_dir,Config), + File = lists:concat([?MODULE,"_",Func,".log"]), + Log = filename:join(Dir,File), + Pa = filename:dirname(code:which(?MODULE)), + TypeAndLog = + case os:type() of + {win32,_} -> + lists:concat([" {",Type,",\\\"",Log,"\\\"}"]); + _ -> + lists:concat([" \'{",Type,",\"",Log,"\"}\'"]) + end, + Args = lists:concat([" -kernel ",Var,TypeAndLog," -pa ",Pa]), + Name = lists:concat([?MODULE,"_",Func]), + 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]), + ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, + {?MODULE,self()}]), + ok = log_on_remote_node(Node,"dummy1"), + ?check("dummy1"), + {ok,Bin1} = sync_and_read(Node,Type,Log), + <<"dummy1\n">> = binary:part(Bin1,{byte_size(Bin1),-7}), + + %% Kill the logger_std_h process + exit(Pid, kill), + + %% Wait a bit, then check that it is gone + timer:sleep(2000), + undefined = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + + %% Check that file is not empty + {ok,Bin2} = sync_and_read(Node,Type,Log), + <<"dummy1\n">> = binary:part(Bin2,{byte_size(Bin2),-7}), + ok. + +%% Can not use rpc:call here, since the code would execute on a +%% process with group_leader on this (the calling) node, and thus +%% logger would send the log event to the logger process here instead +%% of logging it itself. +log_on_remote_node(Node,Msg) -> + _ = spawn_link(Node, + fun() -> erlang:group_leader(whereis(user),self()), + logger:info(Msg) + end), + ok. + + +crash_std_h(cleanup) -> + Nodes = nodes(), + [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]), + case file:read_file(Log ++ ".1") of + {ok,<<>>} -> + timer:sleep(5000), + file:read_file(Log ++ ".1"); + Ok -> + Ok + end; +sync_and_read(Node,file,Log) -> + rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), + case file:read_file(Log) of + {ok,<<>>} -> + timer:sleep(5000), + file:read_file(Log); + Ok -> + Ok + end. + +bad_input(_Config) -> + {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"), + {error,{badarg,{info,["BadType"]}}} = logger_std_h:info("BadType"), + {error,{badarg,{reset,["BadType"]}}} = logger_std_h:reset("BadType"). + + +info_and_reset(_Config) -> + #{id := ?STANDARD_HANDLER} = logger_std_h:info(?STANDARD_HANDLER), + ok = logger_std_h:reset(?STANDARD_HANDLER). + +reconfig(Config) -> + Dir = ?config(priv_dir,Config), + ok = logger:add_handler(?MODULE, + logger_std_h, + #{logger_std_h => #{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, + 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, + 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, + filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE), + ok. + +reconfig(cleanup, _Config) -> + logger:remove_handler(?MODULE). + + +file_opts(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), + BadFileOpts = [raw], + BadType = {file,Log,BadFileOpts}, + {error,{handler_not_added,{{open_failed,Log,enoent},_}}} = + logger:add_handler(?MODULE, logger_std_h, + #{logger_std_h => #{type => BadType}}), + + OkFileOpts = [raw,append], + OkType = {file,Log,OkFileOpts}, + ok = logger:add_handler(?MODULE, + logger_std_h, + #{logger_std_h => #{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), + ?check(M1), + B1 = ?bin(M1), + try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + ok. +file_opts(cleanup, _Config) -> + logger:remove_handler(?MODULE). + + +filesync(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}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + Tester = self(), + TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) -> + Pid ! {trace,Mod,Func,Details}, + Pid; + ({trace,TPid,'receive',Received}, Pid) -> + Pid ! {trace,TPid,Received}, + Pid + end, + {ok,_} = dbg:tracer(process, {TraceFun, Tester}), + FileCtrlPid = maps:get(file_ctrl_pid , logger_std_h:info(?MODULE)), + {ok,_} = dbg:p(FileCtrlPid, [c]), + {ok,_} = dbg:tpl(logger_std_h, write_to_dev, 5, []), + {ok,_} = dbg:tpl(logger_std_h, sync_dev, 4, []), + {ok,_} = dbg:tp(file, datasync, 1, []), + + logger:info("first", ?domain), + %% wait for automatic filesync + timer:sleep(?FILESYNC_REP_INT), + Expected1 = [{log,"first"}, {trace,logger_std_h,write_to_dev}, + {trace,logger_std_h,sync_dev}, {trace,file,datasync}], + + logger:info("second", ?domain), + %% do explicit filesync + logger_std_h:filesync(?MODULE), + %% a second filesync should be ignored + logger_std_h:filesync(?MODULE), + Expected2 = [{log,"second"}, {trace,logger_std_h,write_to_dev}, + {trace,logger_std_h,sync_dev}, {trace,file,datasync}], + + %% 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, + #{filesync_repeat_interval => no_repeat}), + no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), + logger:info("third", ?domain), + timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + logger:info("fourth", ?domain), + %% wait for automatic filesync + timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + Expected3 = [{log,"third"}, {trace,logger_std_h,write_to_dev}, + {log,"fourth"}, {trace,logger_std_h,write_to_dev}, + {trace,logger_std_h,sync_dev}, {trace,file,datasync}], + + dbg:stop_clear(), + + %% verify that filesync has been performed as expected + Received1 = lists:map(fun({trace,M,F,_}) -> {trace,M,F}; + (Other) -> Other + end, test_server:messages_get()), + ct:pal("Trace #1 =~n~p", [Received1]), + Received1 = Expected1 ++ Expected2 ++ Expected3, + + try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\n">>}, 1000), + + {ok,_} = dbg:tracer(process, {TraceFun, Tester}), + {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:tpl(logger_std_h, handle_cast, 2, []), + + %% switch repeated filesync on and verify that the looping works + SyncInt = 1000, + WaitT = 4500, + logger:set_handler_config(?MODULE, logger_std_h, + #{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, + #{filesync_repeat_interval => no_repeat}), + dbg:stop_clear(), + + Received2 = lists:map(fun({trace,_M,handle_cast,[{Op,_},_]}) -> {trace,Op}; + (Other) -> Other + end, test_server:messages_get()), + ct:pal("Trace #2 =~n~p", [Received2]), + OneSync = [{trace,repeated_filesync}], + %% receive 1 initial repeated_filesync, then 1 per sec + Received2 = + lists:flatten([OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + ok. +filesync(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +write_failure(Config) -> + Dir = ?config(priv_dir, Config), + File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), + Log = filename:join(Dir, File), + Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), + rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), + rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), + rpc:call(Node, ?MODULE, set_result, [file_write,ok]), + + 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), + + rpc:call(Node, ?MODULE, set_result, [file_write,{error,terminated}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + + ?check({error,{?STANDARD_HANDLER,write,Log,{error,terminated}}}), + + ok = log_on_remote_node(Node, "No second error printout"), + ?check_no_log, + + rpc:call(Node, ?MODULE, set_result, [file_write,{error,eacces}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + ?check({error,{?STANDARD_HANDLER,write,Log,{error,eacces}}}), + + rpc:call(Node, ?MODULE, set_result, [file_write,ok]), + 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), + ok. +write_failure(cleanup, _Config) -> + Nodes = nodes(), + [test_server:stop_node(Node) || Node <- Nodes]. + +sync_failure(Config) -> + Dir = ?config(priv_dir, Config), + File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), + Log = filename:join(Dir, File), + Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), + rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), + rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), + rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), + + SyncInt = 500, + ok = rpc:call(Node, logger, set_handler_config, + [?STANDARD_HANDLER, logger_std_h, + #{filesync_repeat_interval => SyncInt}]), + Info = rpc:call(Node, logger_std_h, info, [?STANDARD_HANDLER]), + SyncInt = maps:get(filesync_repeat_interval, Info), + + ok = log_on_remote_node(Node, "Logged1"), + ?check_no_log, + + rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,terminated}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + + ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,terminated}}}), + + ok = log_on_remote_node(Node, "No second error printout"), + ?check_no_log, + + rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,eacces}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,eacces}}}), + + rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), + ok = log_on_remote_node(Node, "Logged2"), + ?check_no_log, + ok. +sync_failure(cleanup, _Config) -> + Nodes = nodes(), + [test_server:stop_node(Node) || Node <- Nodes]. + +start_std_h_on_new_node(_Config, Func, Log) -> + Pa = filename:dirname(code:which(?MODULE)), + Dest = + case os:type() of + {win32,_} -> + lists:concat([" {file,\\\"",Log,"\\\"}"]); + _ -> + lists:concat([" \'{file,\"",Log,"\"}\'"]) + end, + Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), + Name = lists:concat([?MODULE,"_",Func]), + ct:pal("Starting ~s with ~tp", [Name,Args]), + {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), + Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + true = is_pid(Pid), + 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_defaults() -> + ?set_defaults(). + +%% internal log function that sends the term to the test case process +internal_log(Type, Term) -> + [{tester,Tester}] = ets:lookup(?TEST_HOOKS_TAB, tester), + Tester ! {log,{Type,Term}}, + logger:internal_log(Type, Term), + ok. + + +%%%----------------------------------------------------------------- +%%% Overload protection tests + +op_switch_to_sync_file(Config) -> + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3, + drop_new_reqs_qlen => 501, + flush_reqs_qlen => 2000, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + %% TRecvPid = start_op_trace(), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + NumOfReqs = count_lines(Log), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(async,Events) end), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(sync,Events) end), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_switch(async,sync,Events) end), + %% false = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(drop,Events) end), + %% false = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(flush,Events) end), + ok = file:delete(Log), + %% stop_op_trace(TRecvPid), + ok. +op_switch_to_sync_file(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_sync_tty(Config) -> + {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3, + drop_new_reqs_qlen => 501, + flush_reqs_qlen => 2000, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + ok. +op_switch_to_sync_tty(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_drop_file(Config) -> + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => 3, + flush_reqs_qlen => 600, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + %% TRecvPid = start_op_trace(), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages dropped = ~w (~w)", + [NumOfReqs-Logged,NumOfReqs]), + true = (Logged < NumOfReqs), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(async,Events) end), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(drop,Events) end), + %% false = analyse_trace(TRecvPid, + %% fun(Events) -> find_mode(flush,Events) end), + %% true = analyse_trace(TRecvPid, + %% fun(Events) -> find_switch(async,drop,Events) + %% orelse find_switch(sync,drop,Events) + %% end), + ok = file:delete(Log), + %% stop_op_trace(TRecvPid), + ok. +op_switch_to_drop_file(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_drop_tty(Config) -> + {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => 3, + flush_reqs_qlen => 600, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 500, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + ok. +op_switch_to_drop_tty(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_flush_file() -> + [{timetrap,{seconds,60}}]. +op_switch_to_flush_file(Config) -> + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + + %% it's important that both async and sync requests have been queued + %% when the flush happens (verify with coverage of flush_log_requests/2) + + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => 99, + flush_reqs_qlen => 100, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 10000, + Procs = 100, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages flushed/dropped = ~w (~w)", + [(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]), + true = (Logged < (NumOfReqs*Procs)), + + %%! --- Thu Apr 12 13:46:00 2018 --- peppe was here! + %%! TODO: Verify that handler has switched to flush mode + + ok = file:delete(Log), + ok. +op_switch_to_flush_file(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_flush_tty(Config) -> + {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), + + %% it's important that both async and sync requests have been queued + %% when the flush happens (verify with coverage of flush_log_requests/2) + + NewHConfig = + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => 99, + flush_reqs_qlen => 100, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 10000, + Procs = 10, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), + ok. +op_switch_to_flush_tty(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + NumOfReqs = Logged. +limit_burst_disabled(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + ReqLimit = Logged. +limit_burst_enabled_one(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +limit_burst_enabled_period(Config) -> + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, 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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + + Windows = 3, + Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, info), + 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))). +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, info), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file:delete(Log), + true = is_pid(whereis(?MODULE)), + 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), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = 2000, + NewHConfig = + HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>10, + handler_overloaded_mem=>Mem0+50000, + handler_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), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + timer:sleep(RestartAfter + 1000), + true = is_pid(whereis(?MODULE)), + ok + after + 5000 -> + Info = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info]), + ct:fail("Handler not dead! It should not have survived this!") + end. +qlen_kill_new(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +%% choke the standard handler on remote node to verify the termination +%% works as expected +qlen_kill_std(Config) -> + %%! HERE + %% Dir = ?config(priv_dir, Config), + %% File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), + %% Log = filename:join(Dir, File), + %% Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + %% 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}]), + {skip,"Not done yet"}. + +mem_kill_new(Config) -> + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(?MODULE), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = 2000, + NewHConfig = + HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>50000, + handler_overloaded_mem=>Mem0+500, + handler_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), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + timer:sleep(RestartAfter * 2), + true = is_pid(whereis(?MODULE)), + ok + after + 5000 -> + Info = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info]), + ct:fail("Handler not dead! It should not have survived this!") + end. +mem_kill_new(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +%% choke the standard handler on remote node to verify the termination +%% works as expected +mem_kill_std(Config) -> + {skip,"Not done yet"}. + +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}}, + ok = logger:set_handler_config(?MODULE, NewHConfig1), + MRef1 = erlang:monitor(process, whereis(?MODULE)), + %% kill handler + send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + receive + {'DOWN', MRef1, _, _, _Info1} -> + timer:sleep(?HANDLER_RESTART_AFTER + 1000), + undefined = whereis(?MODULE), + ok + after + 5000 -> + ct:fail("Handler not dead! It should not have survived this!") + end, + + {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + RestartAfter = 2000, + NewHConfig2 = + HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, + handler_overloaded_qlen=>10, + handler_restart_after=>RestartAfter}}, + ok = logger:set_handler_config(?MODULE, NewHConfig2), + Pid0 = whereis(?MODULE), + MRef2 = erlang:monitor(process, Pid0), + %% kill handler + send_burst({n,100}, {spawn,2,0}, {chars,79}, info), + receive + {'DOWN', MRef2, _, _, _Info2} -> + timer:sleep(RestartAfter + 1000), + Pid1 = whereis(?MODULE), + true = is_pid(Pid1), + false = (Pid1 == Pid0), + ok + after + 5000 -> + 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) +%% during high load to verify that sync, dropping and flushing is +%% handled correctly. +handler_requests_under_load() -> + [{timetrap,{seconds,60}}]. +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}}, + 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), + Pid ! {self(),finish}, + ReqResult = receive {Pid,Result} -> Result end, + Logged = count_lines(Log), + ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", + [Sent,Logged]), + FindError = fun(Res) -> + [E || E <- Res, + is_tuple(E) andalso (element(1,E) == error)] + end, + 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). +handler_requests_under_load(cleanup, Config) -> + ok = stop_handler(?MODULE). + +send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> + receive + {From,finish} -> + From ! {self(),Reqs} + after + TO -> + Result = + case Req of + change_config -> + logger:set_handler_config(HName, logger_std_h, + #{enable_kill_overloaded => + false}); + Func -> + logger_std_h:Func(HName) + end, + send_requests(HName, TO, Rs ++ [{Req,[Result|Res]}]) + end. + + +%%%----------------------------------------------------------------- +%%% +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}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([Name]), + formatter=>{?MODULE,op}}), + {ok,{_,HConfig = #{logger_std_h := StdHConfig}}} = + logger:get_handler_config(Name), + {HConfig,StdHConfig}; + +start_handler(Name, FuncName, Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir, lists:concat([FuncName,".log"])), + ct:pal("Logging to ~tp", [Log]), + Type = {file,Log}, + ok = logger:add_handler(Name, + logger_std_h, + #{logger_std_h => #{type => Type}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([Name]), + formatter=>{?MODULE,op}}), + {ok,{_,HConfig = #{logger_std_h := StdHConfig}}} = + logger:get_handler_config(Name), + {Log,HConfig,StdHConfig}. + +stop_handler(Name) -> + ok = logger:remove_handler(Name), + ct:pal("Handler ~p stopped!", [Name]). + +count_lines(File) -> + wait_until_written(File, -1), + count_lines1(File). + +wait_until_written(File, Sz) -> + timer:sleep(2000), + case file:read_file_info(File) of + {ok,#file_info{size = Sz}} -> + timer:sleep(1000), + case file:read_file_info(File) of + {ok,#file_info{size = Sz1}} -> + ok; + {ok,#file_info{size = Sz2}} -> + wait_until_written(File, Sz2) + 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), + file:close(Dev), + Lines. + +send_burst(NorT, Type, {chars,Sz}, Class) -> + Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], + case NorT of + {n,N} -> + %% process_flag(priority, high), + send_n_burst(N, Type, Text, Class), + %% process_flag(priority, normal), + N; + {t,T} -> + ct:pal("Sending messages sequentially for ~w ms", [T]), + T0 = erlang:monotonic_time(millisecond), + send_t_burst(T0, T, Text, Class, 0) + end. + +send_n_burst(0, _, _Text, _Class) -> + ok; +send_n_burst(N, seq, Text, Class) -> + ok = logger:Class(Text, ?domain), + 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)], + lists:foreach(fun(MRef) -> + receive + {'DOWN', MRef, _, _, _} -> + ok + end + end, MRefs), + ct:pal("Message burst sent", []), + ok. + +send_t_burst(T0, T, Text, Class, N) -> + T1 = erlang:monotonic_time(millisecond), + if (T1-T0) > T -> + N; + true -> + ok = logger:Class(Text, ?domain), + send_t_burst(T0, T, Text, Class, N+1) + end. + +%%%----------------------------------------------------------------- +%%% Formatter callback +%%% Using this to send the formatted string back to the test case +%%% process - so it can check for logged events. +format(_,bad_return) -> + bad_return; +format(_,crash) -> + erlang:error(formatter_crashed); +format(#{msg:={string,String0}},no_nl) -> + String = unicode:characters_to_list(String0), + String; +format(#{msg:={string,String0}},nl) -> + String = unicode:characters_to_list(String0), + String++"\n"; +format(#{msg:={string,String0}},op) -> + String = unicode:characters_to_list(String0), + String++"\n"; +format(#{msg:={report,#{label:={supervisor,progress}}}},op) -> + ""; +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) -> + String = lists:flatten(io_lib:format(F,A)), + Pid ! {log,String}, + String++"\n"; +format(#{msg:={string,String0}},Pid) -> + String = unicode:characters_to_list(String0), + Pid ! {log,String}, + String++"\n". + +add_remove_instance_nofile(Type) -> + ok = logger:add_handler(?MODULE,logger_std_h, + #{logger_std_h => #{type => Type}, + filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + Pid = whereis(?MODULE), + true = is_pid(Pid), + group_leader(group_leader(),Pid), % to get printouts in test log + logger:info(M1=?msg,?domain), + ?check(M1), + %% check that filesync 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), + ?check_no_log, + ok. + +logger_std_h_remove() -> + logger:remove_handler(?MODULE). +logger_std_h_remove(Id) -> + logger:remove_handler(Id). + +try_read_file(FileName, Expected, Time) when Time > 0 -> + case file:read_file(FileName) of + Expected -> + ok; + Error = {error,_Reason} -> + ct:pal("Can't read ~tp: ~tp", [FileName,Error]), + erlang:error(Error); + Got -> + ct:pal("try_read_file got ~tp", [Got]), + timer:sleep(500), + try_read_file(FileName, Expected, Time-500) + end; +try_read_file(FileName, Expected, _) -> + ct:pal("Missing pattern ~tp in ~tp", [Expected,FileName]), + erlang:error({error,missing_expected_pattern}). + +try_match_file(FileName, Pattern, Time) -> + try_match_file(FileName, Pattern, Time, <<>>). + +try_match_file(FileName, Pattern, Time, _) when Time > 0 -> + case file:read_file(FileName) of + {ok, Bin} -> + case re:run(Bin,Pattern,[{capture,none}]) of + match -> + unicode:characters_to_list(Bin); + _ -> + timer:sleep(100), + try_match_file(FileName, Pattern, Time-100, Bin) + end; + Error -> + erlang:error(Error) + end; +try_match_file(_,Pattern,_,Incorrect) -> + ct:pal("try_match_file did not match pattern: ~p~nGot: ~p~n", + [Pattern,Incorrect]), + erlang:error({error,not_matching_pattern,Pattern,Incorrect}). + +%%%----------------------------------------------------------------- +%%% +start_op_trace() -> + TraceFun = fun({trace,_,call,{_Mod,Func,Details}}, Pid) -> + Pid ! {trace_call,Func,Details}, + Pid; + ({trace,_,return_from,{_Mod,Func,_},RetVal}, Pid) -> + Pid ! {trace_return,Func,RetVal}, + Pid + end, + TRecvPid = spawn_link(fun() -> trace_receiver(5000) end), + {ok,_} = dbg:tracer(process, {TraceFun, TRecvPid}), + + {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(self(), [c]), + + MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), + {ok,_} = dbg:tp(logger_h_common, check_load, 1, MS1), + + {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), + + MS2 = dbg:fun2ms(fun([_,mode]) -> return_trace() end), + {ok,_} = dbg:tpl(ets, lookup, 2, MS2), + + ct:pal("Tracing started!", []), + TRecvPid. + +stop_op_trace(TRecvPid) -> + dbg:stop_clear(), + unlink(TRecvPid), + exit(TRecvPid, kill), + ok. + +find_mode(flush, Events) -> + lists:any(fun({trace_call,flush_log_requests,[_,_]}) -> true; + (_) -> false + end, Events); +find_mode(Mode, Events) -> + lists:keymember([{mode,Mode}], 3, Events). + +find_switch(From, To, Events) -> + try lists:foldl(fun({trace_return,check_load,{To,_,_,_}}, + {trace_call,check_load,[#{mode := From}]}) -> + throw(match); + (Event, _) -> + Event + end, undefined, Events) of + _ -> false + catch + throw:match -> true + end. + +analyse_trace(TRecvPid, TestFun) -> + TRecvPid ! {test,self(),TestFun}, + receive + {result,TRecvPid,Result} -> + Result + after + 60000 -> + fails + end. + +trace_receiver(IdleT) -> + Msgs = receive_until_idle(IdleT, 5, []), + ct:pal("~w trace events generated", [length(Msgs)]), + analyse(Msgs). + +receive_until_idle(IdleT, WaitN, Msgs) -> + receive + Msg = {trace_call,_,_} -> + receive_until_idle(IdleT, 5, [Msg | Msgs]); + Msg = {trace_return,_,_} -> + receive_until_idle(IdleT, 5, [Msg | Msgs]) + after + IdleT -> + if WaitN == 0 -> + Msgs; + true -> + receive_until_idle(IdleT, WaitN-1, Msgs) + end + end. + +analyse(Msgs) -> + receive + {test,From,TestFun} -> + From ! {result,self(),TestFun(Msgs)}, + analyse(Msgs) + end. |