diff options
Diffstat (limited to 'lib/kernel/test/logger_disk_log_h_SUITE.erl')
| -rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 1668 |
1 files changed, 1668 insertions, 0 deletions
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..9bbec42de8 --- /dev/null +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -0,0 +1,1668 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2018. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% +-module(logger_disk_log_h_SUITE). + +-compile(export_all). + +-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_olp.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]}). + +suite() -> + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. + +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 -> + case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of + true -> + {skip,"Define the TEST_HOOKS macro to run this test"}; + false -> + 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, + filter_config, + errors, + formatter_fail, + config_fail, + bad_input, + reconfig, + 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(h_proc_name())), + ok = logger:remove_handler(?MODULE), + timer:sleep(500), + undefined = whereis(h_proc_name()). +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:notice("hello", ?domain), + logger_disk_log_h:filesync(Name1), + ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), + try_read_file(?log_no(LogFile1,1), {ok,<<"hello\n">>}, 5000), + + %% 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:notice("dummy", ?domain), + logger_disk_log_h:filesync(Name2), + ct:pal("Checking contents of ~p", [?log_no(LogFile2,1)]), + try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000), + + 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:notice("one", ?domain), + logger_disk_log_h:filesync(HName), + ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), + try_read_file(?log_no(LogFile1,1), {ok,<<"one\n">>}, 5000), + logger:notice("two", ?domain), + ok = remove_and_stop(HName), + try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\n">>}, 5000), + + logger:notice("two and a half", ?domain), + + ok = start_and_add(HName, #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}, + #{file=>LogFile1}), + logger:notice("three", ?domain), + logger_disk_log_h:filesync(HName), + try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000), + remove_and_stop(HName), + try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000). + +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:notice("123", ?domain), + logger_disk_log_h:filesync(WName), + timer:sleep(500), + 1 = Get(current_file, disk_log:info(WName)), + + logger:notice("45", ?domain), + logger_disk_log_h:filesync(WName), + timer:sleep(500), + 1 = Get(current_file, disk_log:info(WName)), + + logger:notice("6", ?domain), + logger_disk_log_h:filesync(WName), + timer:sleep(500), + 2 = Get(current_file, disk_log:info(WName)), + + logger:notice("7890", ?domain), + logger_disk_log_h:filesync(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:notice("12345", ?domain), + logger_disk_log_h:filesync(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)), + HandlerConfig = #{config => #{file=>LogFile}, + filter_default=>log}, + ct:pal("Log: ~p", [LogFile]), + ok = logger:add_handler(?MODULE, logger_disk_log_h, HandlerConfig), + ok = logger:set_handler_config(?MODULE,formatter, + {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), + LogName = lists:concat([LogFile, ".1"]), + logger:notice("dummy"), + wait_until_written(LogName), + {ok,Bin} = file:read_file(LogName), + match = re:run(Bin, "=NOTICE 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:notice([{x,y}], #{report_cb => MsgFormatter}), + logger:notice([{x,y}], #{}), + ct:pal("Checking contents of ~p", [?log_no(LogFile,1)]), + try_read_file(?log_no(LogFile,1), {ok,<<"Term:[{x,y}]\n x: y\n">>}, 5000). + +logging(cleanup, _Config) -> + Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + remove_and_stop(Name). + +filter_config(_Config) -> + ok = logger:add_handler(?MODULE,logger_disk_log_h,#{}), + {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), + HConfig = maps:without([olp],HConfig), + + FakeFullHConfig = HConfig#{olp=>{regname,self(),erlang:make_ref()}}, + #{config:=HConfig} = + logger_disk_log_h:filter_config(Config#{config=>FakeFullHConfig}), + ok. + +filter_config(cleanup,_Config) -> + logger:remove_handler(?MODULE), + ok. + +errors(Config) -> + PrivDir = ?config(priv_dir,Config), + Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), + LogFile1 = filename:join(PrivDir,Name1), + HandlerConfig = #{config=>#{file=>LogFile1}, + filter_default=>log, + formatter=>{?MODULE,self()}}, + ok = logger:add_handler(Name1, logger_disk_log_h, HandlerConfig), + {error,{already_exist,Name1}} = + logger:add_handler(Name1, logger_disk_log_h, #{}), + + %%! TODO: + %%! Check how bad log_opts are handled! + + {error,{illegal_config_change, + logger_disk_log_h, + #{type:=wrap}, + #{type:=halt}}} = + logger:update_handler_config(Name1, + config, + #{type=>halt, + file=>LogFile1}), + + {error,{illegal_config_change, + logger_disk_log_h, + #{file:=LogFile1}, + #{file:="newfilename"}}} = + logger:update_handler_config(Name1, + config, + #{file=>"newfilename"}), + + %% Read-only fields may (accidentially) be included in the change, + %% but it won't take effect + {ok,C} = logger:get_handler_config(Name1), + ok = logger:set_handler_config(Name1,config,#{olp=>dummyvalue}), + {ok,C} = logger:get_handler_config(Name1), + + + 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]), + HandlerConfig = #{config => #{file=>LogFile}, + filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}, + %% no formatter! + logger:add_handler(Name, logger_disk_log_h, HandlerConfig), + Pid = whereis(h_proc_name(Name)), + true = is_pid(Pid), + H = logger:get_handler_ids(), + true = lists:member(Name,H), + + %% Formatter is added automatically + {ok,#{formatter:={logger_formatter,_}}} = logger:get_handler_config(Name), + logger:notice(M1=?msg,?domain), + Got1 = try_match_file(?log_no(LogFile,1),"[0-9\\+\\-T:\\.]* notice: "++M1,5000), + + ok = logger:set_handler_config(Name,formatter,{nonexistingmodule,#{}}), + logger:notice(M2=?msg,?domain), + Got2 = try_match_file(?log_no(LogFile,1), + escape(Got1)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M2, + 5000), + + ok = logger:set_handler_config(Name,formatter,{?MODULE,crash}), + logger:notice(M3=?msg,?domain), + Got3 = try_match_file(?log_no(LogFile,1), + escape(Got2)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M3, + 5000), + + ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}), + logger:notice(?msg,?domain), + try_match_file(?log_no(LogFile,1), + escape(Got3)++"FORMATTER ERROR: bad return value", + 5000), + + %% Check that handler is still alive and was never dead + Pid = whereis(h_proc_name(Name)), + H = logger:get_handler_ids(), + 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, + #{config => #{bad => bad}, + filter_default=>log, + formatter=>{?MODULE,self()}}), + + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=1}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{config => #{drop_mode_qlen=>1}}), + {error,{handler_not_added,{invalid_olp_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{config => #{sync_mode_qlen=>43, + drop_mode_qlen=>42}}), + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{config => #{drop_mode_qlen=>43, + flush_qlen=>42}}), + + ok = logger:add_handler(?MODULE,logger_disk_log_h, + #{filter_default=>log, + formatter=>{?MODULE,self()}}), + %% can't change the disk log options for a log already in use + {error,{illegal_config_change,logger_disk_log_h,_,_}} = + logger:update_handler_config(?MODULE,config, + #{max_no_files=>2}), + %% incorrect values of OP params + {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), + {error,{invalid_olp_levels,_}} = + logger:update_handler_config(?MODULE,config, + HConfig#{sync_mode_qlen=>100, + flush_qlen=>99}), + %% invalid name of config parameter + {error,{invalid_config,logger_disk_log_h,#{filesync_rep_int:=2000}}} = + logger:update_handler_config(?MODULE, config, + HConfig#{filesync_rep_int => 2000}), + ok. +config_fail(cleanup,_Config) -> + logger:remove_handler(?MODULE). + +bad_input(_Config) -> + {error,{badarg,{filesync,["BadType"]}}} = + logger_disk_log_h:filesync("BadType"). + +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, + sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, + cb_state := + #{handler_state := + #{log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + file := DiskLogFile}}, + filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL}} = + logger_olp:info(h_proc_name()), + {ok,#{config := + #{sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, + file := DiskLogFile, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + type := wrap} = HConfig0}} = + logger:get_handler_config(?MODULE), + + HConfig1 = HConfig0#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => 3, + burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 10, + overload_kill_enable => true, + overload_kill_qlen => 100000, + overload_kill_mem_size => 10000000, + overload_kill_restart_after => infinity, + filesync_repeat_interval => no_repeat}, + ok = logger:set_handler_config(?MODULE, config, HConfig1), + #{%id := ?MODULE, + sync_mode_qlen := 1, + drop_mode_qlen := 2, + flush_qlen := 3, + burst_limit_enable := false, + burst_limit_max_count := 10, + burst_limit_window_time := 10, + overload_kill_enable := true, + overload_kill_qlen := 100000, + overload_kill_mem_size := 10000000, + overload_kill_restart_after := infinity, + cb_state := #{filesync_repeat_interval := no_repeat}} = + logger_olp:info(h_proc_name()), + {ok,#{config:=HConfig1}} = logger:get_handler_config(?MODULE), + + ok = logger:update_handler_config(?MODULE, config, + #{flush_qlen => ?FLUSH_QLEN}), + {ok,#{config:=C1}} = logger:get_handler_config(?MODULE), + ct:log("C1: ~p",[C1]), + C1 = HConfig1#{flush_qlen => ?FLUSH_QLEN}, + + ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C2}} = logger:get_handler_config(?MODULE), + ct:log("C2: ~p",[C2]), + C2 = HConfig0#{sync_mode_qlen => 1}, + + ok = logger:set_handler_config(?MODULE, config, #{drop_mode_qlen => 100}), + {ok,#{config:=C3}} = logger:get_handler_config(?MODULE), + ct:log("C3: ~p",[C3]), + C3 = HConfig0#{drop_mode_qlen => 100}, + + ok = logger:update_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C4}} = logger:get_handler_config(?MODULE), + ct:log("C4: ~p",[C4]), + C4 = HConfig0#{sync_mode_qlen => 1, + drop_mode_qlen => 100}, + + 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()}, + config=> + #{type => halt, + max_no_files => 1, + max_no_bytes => 1024, + file => File}}), + #{cb_state := + #{handler_state := + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := + #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}=HaltHConfig} = Config2} = + logger:get_handler_config(?MODULE), + + ok = logger:update_handler_config(?MODULE, level, notice), + {ok,C5} = logger:get_handler_config(?MODULE), + ct:log("C5: ~p",[C5]), + C5 = Config2#{level => notice}, + + ok = logger:set_handler_config(?MODULE, level, info), + {ok,C6} = logger:get_handler_config(?MODULE), + ct:log("C6: ~p",[C6]), + C6 = Config2#{level => info}, + + %% You are not allowed to actively set the write once fields + %% (type, max_no_files, max_no_bytes, file) in runtime. + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{type=>wrap}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{max_no_files=>2}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{max_no_bytes=>2048}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{file=>"otherfile.log"}), + {ok,C7} = logger:get_handler_config(?MODULE), + ct:log("C7: ~p",[C7]), + C7 = C6, + + %% ... but if you don't specify the write once fields, then + %% set_handler_config shall NOT reset them to their default value + ok = logger:set_handler_config(?MODULE,config,#{sync_mode_qlen=>1}), + {ok,#{config:=C8}} = logger:get_handler_config(?MODULE), + ct:log("C8: ~p",[C8]), + C8 = HaltHConfig#{sync_mode_qlen=>1}, + ok. + +reconfig(cleanup, _Config) -> + logger:remove_handler(?MODULE). + +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, + #{config => #{file => File}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,nl}}), + + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"first\n">>}, + {disk_log,sync}]), + + logger:notice("first", ?domain), + %% wait for automatic disk_log_sync + check_tracer(?FILESYNC_REPEAT_INTERVAL*2), + + %% check that if there's no repeated filesync active, + %% a disk_log_sync is still performed when handler goes idle + {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), + HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, + ok = logger:update_handler_config(?MODULE, config, HConfig1), + no_repeat = maps:get(filesync_repeat_interval, + maps:get(cb_state,logger_olp:info(h_proc_name()))), + + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"second\n">>}, + {disk_log,sync}, + {logger_disk_log_h,disk_log_write,<<"third\n">>}, + {disk_log,sync}]), + + logger:notice("second", ?domain), + timer:sleep(?IDLE_DETECT_TIME*2), + logger:notice("third", ?domain), + %% wait for automatic disk_log_sync + check_tracer(?IDLE_DETECT_TIME*2), + + try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), + + %% switch repeated filesync on and verify that the looping works + SyncInt = 1000, + WaitT = 4500, + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{{logger_h_common,handle_cast,2}, + [{[repeated_filesync,'_'],[],[{message,{caller}}]}]}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), + + HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, + ok = logger:update_handler_config(?MODULE, config, HConfig2), + + SyncInt = maps:get(filesync_repeat_interval, + maps:get(cb_state,logger_olp:info(h_proc_name()))), + timer:sleep(WaitT), + HConfig3 = HConfig#{filesync_repeat_interval => no_repeat}, + ok = logger:update_handler_config(?MODULE, config, HConfig3), + check_tracer(100), + ok. +sync(cleanup,_Config) -> + dbg:stop_clear(), + 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()}, + config=> + #{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(h_proc_name()), [c]), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), + + 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:notice(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) -> + dbg:stop_clear(), + 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()}, + config=> + #{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(h_proc_name()), [c]), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), + + NoOfChars = 5, + Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)], + [logger:notice(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]), + + %% The tail here could be an error_status notification, if the + %% last write was synchronous, but in most cases it will not be + [{trace,full}|_] = Received, + %% [{trace,full}, + %% {trace,{error_status,{error,{full,_}}}}] = Received, + ok. +disk_log_full(cleanup, _Config) -> + dbg:stop_clear(), + 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(h_proc_name()), [c]), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), + + [whereis(h_proc_name()) ! 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) -> + dbg:stop_clear(), + 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, 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_write,ok]), + HState = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + LogOpts = maps:get(log_opts, + maps:get(handler_state, + maps:get(cb_state,HState))), + ct:pal("LogOpts = ~p", [LogOpts]), + + %% ?check and ?check_no_log in this test only check for internal log events + ok = log_on_remote_node(Node, "Logged1"), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), + ?check_no_log, % no internal log when write ok + + SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of + true -> 5500; + false -> ?FILESYNC_REPEAT_INTERVAL + 500 + end, + + try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), + + rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + + %% this should have caused an internal log + ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), + + ok = log_on_remote_node(Node, "No second error printout"), + ?check_no_log, % but don't log same error twice + + rpc:call(Node, ?MODULE, set_result, [disk_log_write, + {error,{full,?STANDARD_HANDLER}}]), + ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this was a different error, so it should be logged + ?check({error,{?STANDARD_HANDLER,log,LogOpts, + {error,{full,?STANDARD_HANDLER}}}}), + + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), + ok = log_on_remote_node(Node, "Logged2"), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), + ?check_no_log, % no internal log when write ok + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), + 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), + + + Node = start_h_on_new_node(Config, File), + false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), + rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), + rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), + rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), + HState = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + LogOpts = maps:get(log_opts, maps:get(handler_state, + maps:get(cb_state,HState))), + + SyncInt = 500, + ok = rpc:call(Node, logger, update_handler_config, + [?STANDARD_HANDLER, config, + #{filesync_repeat_interval => SyncInt}]), + Info = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + SyncInt = maps:get(filesync_repeat_interval, maps:get(cb_state, 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,filesync,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,filesync,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, File) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger,[{handler,default,logger_disk_log_h, + #{ config => #{ file => File }}}]}]), + 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:notice(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), + NumOfReqs = 500, + NewHConfig = + HConfig#{config => DLHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => NumOfReqs+1, + flush_qlen => 2*NumOfReqs, + burst_limit_enable => false}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + Lines = count_lines(Log), + NumOfReqs = Lines, + ok = file_delete(Log), + ok. +op_switch_to_sync(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +op_switch_to_drop() -> + [{timetrap,{seconds,180}}]. +op_switch_to_drop(Config) -> + Test = + fun() -> + {Log,HConfig,DLHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + NumOfReqs = 300, + Procs = 2, + Bursts = 10, + NewHConfig = + HConfig#{config => + DLHConfig#{sync_mode_qlen => 1, + drop_mode_qlen => 2, + flush_qlen => Procs*NumOfReqs*Bursts, + burst_limit_enable => false}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + %% It sometimes happens that the handler either gets + %% the requests in a slow enough pace so that dropping + %% never occurs. Therefore, lets generate a number of + %% bursts to increase the chance of message buildup. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || + _ <- lists:seq(1, Bursts)], + Logged = count_lines(Log), + ok = stop_handler(?MODULE), + ct:pal("Number of messages dropped = ~w (~w)", + [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), + true = (Logged < (Procs*NumOfReqs*Bursts)), + true = (Logged > 0), + _ = file_delete(Log), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. +op_switch_to_drop(cleanup, _Config) -> + _ = stop_handler(?MODULE). + +op_switch_to_flush() -> + [{timetrap,{minutes,3}}]. +op_switch_to_flush(Config) -> + Test = + fun() -> + {Log,HConfig,DLHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + + %% NOTE: 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#{config => + DLHConfig#{sync_mode_qlen => 2, + %% disable drop mode + drop_mode_qlen => 300, + flush_qlen => 300, + burst_limit_enable => false}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + NumOfReqs = 1500, + Procs = 10, + Bursts = 10, + %% It sometimes happens that the handler either gets + %% the requests in a slow enough pace so that flushing + %% never occurs, or it gets all messages at once, + %% causing all messages to get flushed (no dropping of + %% sync messages gets tested). Therefore, lets + %% generate a number of bursts to increase the chance + %% of message buildup in some random fashion. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || + _ <- lists:seq(1,Bursts)], + Logged = count_lines(Log), + ok= stop_handler(?MODULE), + ct:pal("Number of messages flushed/dropped = ~w (~w)", + [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), + true = (Logged < (NumOfReqs*Procs*Bursts)), + true = (Logged > 0), + _ = file_delete(Log), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. +op_switch_to_flush(cleanup, _Config) -> + _ = stop_handler(?MODULE). + + +limit_burst_disabled(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig = + HConfig#{config => DLHConfig#{burst_limit_enable => false, + burst_limit_max_count => 10, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + NumOfReqs = Logged, + ok = file_delete(Log), + ok. +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#{config => DLHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => 2000, + drop_mode_qlen => 200, + flush_qlen => 300}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ReqLimit = Logged, + ok = file_delete(Log), + ok. +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#{config => DLHConfig#{burst_limit_enable => true, + burst_limit_max_count => ReqLimit, + burst_limit_window_time => BurstTWin, + drop_mode_qlen => 20000, + flush_qlen => 20001}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + + Windows = 3, + Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), + Logged = count_lines(Log), + ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", + [Sent,Logged]), + true = (Logged > (ReqLimit*Windows)) andalso + (Logged < (ReqLimit*(Windows+2))), + ok = file_delete(Log), + ok. +limit_burst_enabled_period(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +kill_disabled(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig = + HConfig#{config=>DLHConfig#{overload_kill_enable=>false, + overload_kill_qlen=>10, + overload_kill_mem_size=>100}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + NumOfReqs = 100, + send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + Logged = count_lines(Log), + ct:pal("Number of messages logged = ~w", [Logged]), + ok = file_delete(Log), + true = is_pid(whereis(h_proc_name())), + ok. +kill_disabled(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +qlen_kill_new(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Pid0 = whereis(h_proc_name()), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, + NewHConfig = + HConfig#{config => + DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_mem_size=>Mem0+50000, + overload_kill_restart_after=>RestartAfter}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + MRef = erlang:monitor(process, Pid0), + NumOfReqs = 100, + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), + ok + after + 5000 -> + Info = logger_olp:info(h_proc_name()), + 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(h_proc_name()), + {_,Mem0} = process_info(Pid0, memory), + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, + NewHConfig = + HConfig#{config => + DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>50000, + overload_kill_mem_size=>Mem0+500, + overload_kill_restart_after=>RestartAfter}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + MRef = erlang:monitor(process, Pid0), + NumOfReqs = 100, + Procs = 4, + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), + %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), + receive + {'DOWN', MRef, _, _, Info} -> + case Info of + {shutdown,{overloaded,QLen,Mem}} -> + ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); + killed -> + ct:pal("Slow shutdown, handler process was killed!", []) + end, + file_delete(Log), + {ok,_} = wait_for_process_up(RestartAfter * 3), + ok + after + 5000 -> + Info = logger_olp:info(h_proc_name()), + 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() -> + [{timetrap,{minutes,2}}]. +restart_after(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig1 = + HConfig#{config=>DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>infinity}}, + ok = logger:update_handler_config(?MODULE, NewHConfig1), + MRef1 = erlang:monitor(process, whereis(h_proc_name())), + %% kill handler + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), + receive + {'DOWN', MRef1, _, _, _Reason1} -> + file_delete(Log), + error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3), + ok + after + 5000 -> + Info1 = logger_olp:info(h_proc_name()), + ct:pal("Handler state = ~p", [Info1]), + ct:fail("Handler not dead! It should not have survived this!") + end, + + {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, + NewHConfig2 = + HConfig#{config=>DLHConfig#{overload_kill_enable=>true, + overload_kill_qlen=>10, + overload_kill_restart_after=>RestartAfter}}, + ok = logger:update_handler_config(?MODULE, NewHConfig2), + Pid0 = whereis(h_proc_name()), + MRef2 = erlang:monitor(process, Pid0), + %% kill handler + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), + receive + {'DOWN', MRef2, _, _, _Reason2} -> + file_delete(Log), + {ok,Pid1} = wait_for_process_up(RestartAfter * 3), + false = (Pid1 == Pid0), + ok + after + 5000 -> + Info2 = logger_olp:info(h_proc_name()), + ct:pal("Handler state = ~p", [Info2]), + ct:fail("Handler not dead! It should not have survived this!") + end, + ok. +restart_after(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +%% send handler requests (sync, info, reset, change_config) +%% during high load to verify that sync, dropping and flushing is +%% handled correctly. +handler_requests_under_load() -> + [{timetrap,{minutes,5}}]. +handler_requests_under_load(Config) -> + {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NewHConfig = + HConfig#{config => DLHConfig#{sync_mode_qlen => 2, + drop_mode_qlen => 1000, + flush_qlen => 2000, + burst_limit_enable => false}}, + ok = logger:update_handler_config(?MODULE, NewHConfig), + Pid = spawn_link( + fun() -> send_requests(1,[{logger_disk_log_h,filesync,[?MODULE],[]}, + {logger_olp,info,[h_proc_name()],[]}, + {logger_olp,reset,[h_proc_name()],[]}, + {logger,update_handler_config, + [?MODULE, config, + #{overload_kill_enable => false}], + []}]) + end), + Procs = 100, + Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, notice), + Pid ! {self(),finish}, + ReqResult = receive {Pid,Result} -> Result end, + Logged = count_lines(Log), + 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 = [{Func,FindError(Res)} || {_,Func,_,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(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> + receive + {From,finish} -> + From ! {self(),Reqs} + after + TO -> + Result = apply(Mod,Func,Args), + send_requests(TO, Rs ++ [{Mod,Func,Args,[Result|Res]}]) + end. + +%%%----------------------------------------------------------------- +%%% +start_handler(Name, FuncName, Config) -> + Dir = ?config(priv_dir,Config), + File = filename:join(Dir, FuncName), + ct:pal("Logging to ~tp", [File]), + FullFile = lists:concat([File,".1"]), + _ = file_delete(FullFile), + ok = logger:add_handler(Name, + logger_disk_log_h, + #{config=>#{file => File, + max_no_files => 1, + max_no_bytes => 100000000}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([Name]), + formatter=>{?MODULE,op}}), + {ok,HConfig = #{config := DLHConfig}} = logger:get_handler_config(Name), + {FullFile,HConfig,DLHConfig}. + +stop_handler(Name) -> + ct:pal("Stopping handler ~p!", [Name]), + logger:remove_handler(Name). + +send_burst(NorT, Type, {chars,Sz}, Class) -> + Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], + 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]), + MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, + monitor(process,spawn_link(per_proc_fun(N,Text,Class,X))) + end || X <- 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. + +per_proc_fun(N,Text,Class,X) when X rem 2 == 0 -> + fun() -> + process_flag(priority,high), + send_n_burst(N, seq, Text, Class) + end; +per_proc_fun(N,Text,Class,_) -> + fun() -> + send_n_burst(N, seq, Text, Class) + end. + +%%%----------------------------------------------------------------- +%%% Formatter callback +%%% Using this to send the formatted string back to the test case +%%% 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}},OpOrPid) when is_list(F), is_list(A) -> + String = lists:flatten(io_lib:format(F,A)), + if is_pid(OpOrPid) -> OpOrPid ! {log,String}; + true -> ok + end, + 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). + +start_and_add(Name, Config, LogOpts) -> + HConfig = maps:get(config, Config, #{}), + HConfig1 = maps:merge(HConfig, LogOpts), + Config1 = Config#{config=>HConfig1}, + ct:pal("Adding handler ~w with: ~p", [Name,Config1]), + ok = logger:add_handler(Name, logger_disk_log_h, Config1), + Pid = whereis(h_proc_name(Name)), + true = is_pid(Pid), + Name = proplists:get_value(name, disk_log:info(Name)), + ok. + +remove_and_stop(Handler) -> + ok = logger:remove_handler(Handler), + timer:sleep(500), + undefined = whereis(h_proc_name(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 = Sz}} -> + ok; + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) + end; + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) + end. + +count_lines1(File) -> + {_,Dev} = file:open(File, [read]), + Lines = count_lines2(Dev, 0), + file:close(Dev), + Lines. + +count_lines2(Dev, LC) -> + case file:read_line(Dev) of + {ok,"Handler logger_disk_log_h_SUITE " ++_} -> + %% Not counting handler info + count_lines2(Dev,LC); + {ok,_} -> + count_lines2(Dev,LC+1); + eof -> LC + end. + +repeat_until_ok(Fun, N) -> + repeat_until_ok(Fun, 0, N, undefined). + +repeat_until_ok(_Fun, Stop, Stop, Reason) -> + {fails,Reason}; + +repeat_until_ok(Fun, C, Stop, FirstReason) -> + if C > 0 -> timer:sleep(5000); + true -> ok + end, + try Fun() of + Result -> + {ok,{C,Result}} + catch + _:Reason:Stack -> + ct:pal("Test fails: ~p (~p)~n", [Reason,hd(Stack)]), + if FirstReason == undefined -> + repeat_until_ok(Fun, C+1, Stop, {Reason,Stack}); + true -> + repeat_until_ok(Fun, C+1, Stop, FirstReason) + end + end. + +start_tracer(Trace,Expected) -> + Pid = self(), + dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), + dbg:p(h_proc_name(),[c]), + tpl(Trace), + ok. + +tpl([{M,F,A}|Trace]) -> + tpl([{{M,F,A},c}|Trace]); +tpl([{{M,F,A},MS}|Trace]) -> + {ok,Match} = dbg:tpl(M,F,A,MS), + 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,{logger_h_common,handle_cast,[Op|_]},Caller}, + {Pid,[{Mod,Func,Op}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); +tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); +tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> + maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); +tracer({trace,_,call,Call,Caller}, {Pid,Expected}) -> + ct:log("Tracer got unexpected: ~p~nCaller: ~p~nExpected: ~p~n",[Call,Caller,Expected]), + Pid ! {tracer_got_unexpected,Call,Expected}, + {Pid,Expected}. + +maybe_tracer_done(Pid,[],Got,Caller) -> + ct:log("Tracer got: ~p~nCaller: ~p~n",[Got,Caller]), + Pid ! tracer_done; +maybe_tracer_done(Pid,Expected,Got,Caller) -> + ct:log("Tracer got: ~p~nCaller: ~p~n",[Got,Caller]), + {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 -> + dbg:stop_clear(), + ct:fail({timeout,tracer}) + end. + +escape([$+|Rest]) -> + [$\\,$+|escape(Rest)]; +escape([H|T]) -> + [H|escape(T)]; +escape([]) -> + []. + +h_proc_name() -> + h_proc_name(?MODULE). +h_proc_name(Name) -> + list_to_atom(lists:concat([logger_disk_log_h,"_",Name])). + +wait_for_process_up(T) -> + wait_for_process_up(?MODULE, h_proc_name(), T). + +wait_for_process_up(Name, RegName, T) -> + N = (T div 500) + 1, + wait_for_process_up1(Name, RegName, N). + +wait_for_process_up1(_Name, _RegName, 0) -> + error; +wait_for_process_up1(Name, RegName, N) -> + timer:sleep(500), + case whereis(RegName) of + Pid when is_pid(Pid) -> + case logger:get_handler_config(Name) of + {ok,_} -> + %% ct:pal("Process ~p up (~p tries left)",[Name,N]), + {ok,Pid}; + _ -> + wait_for_process_up1(Name, RegName, N-1) + end; + undefined -> + %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), + wait_for_process_up1(Name, RegName, N-1) + end. + +file_delete(Log) -> + file:delete(Log). |