diff options
Diffstat (limited to 'lib/kernel/test/logger_std_h_SUITE.erl')
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 819 |
1 files changed, 673 insertions, 146 deletions
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index ca54458ac1..0c5516f82b 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -25,10 +25,15 @@ -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). -include_lib("kernel/src/logger_h_common.hrl"). +-include_lib("kernel/src/logger_olp.hrl"). -include_lib("stdlib/include/ms_transform.hrl"). -include_lib("kernel/include/file.hrl"). --define(check_no_log, [] = test_server:messages_get()). +-define(check_no_log, + begin + timer:sleep(?IDLE_DETECT_TIME*2), + [] = test_server:messages_get() + end). -define(check(Expected), receive {log,Expected} -> @@ -107,14 +112,16 @@ all() -> add_remove_instance_standard_error, add_remove_instance_file1, add_remove_instance_file2, + add_remove_instance_file3, + add_remove_instance_file4, default_formatter, + filter_config, errors, formatter_fail, config_fail, crash_std_h_to_file, crash_std_h_to_disk_log, bad_input, - info_and_reset, reconfig, file_opts, sync, @@ -135,11 +142,18 @@ all() -> mem_kill_new, mem_kill_std, restart_after, - handler_requests_under_load + handler_requests_under_load, + recreate_deleted_log, + reopen_changed_log, + rotate_size, + rotate_size_compressed, + rotate_size_reopen, + rotation_opts, + rotation_opts_restart_handler ]. add_remove_instance_tty(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => tty}, filter_default=>log, @@ -172,10 +186,27 @@ add_remove_instance_file2(Config) -> add_remove_instance_file2(cleanup,_Config) -> logger_std_h_remove(). -add_remove_instance_file(Log, Type) -> +add_remove_instance_file3(_Config) -> + Log = atom_to_list(?MODULE), + StdHConfig = #{type=>file}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file3(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file4(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog4.txt"), + StdHConfig = #{file=>Log,modes=>[]}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file4(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file(Log, Type) when not is_map(Type) -> + add_remove_instance_file(Log,#{type=>Type}); +add_remove_instance_file(Log, StdHConfig) when is_map(StdHConfig) -> ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => StdHConfig, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), @@ -204,6 +235,20 @@ default_formatter(_Config) -> match = re:run(Msg,"=NOTICE REPORT====.*\n"++M1,[{capture,none}]), ok. +filter_config(_Config) -> + ok = logger:add_handler(?MODULE,logger_std_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_std_h:filter_config(Config#{config=>FakeFullHConfig}), + ok. + +filter_config(cleanup,_Config) -> + logger:remove_handler(?MODULE), + ok. + errors(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir,?FUNCTION_NAME), @@ -219,7 +264,7 @@ errors(Config) -> {error, {handler_not_added, - {invalid_config,logger_std_h,{type,faulty_type}}}} = + {invalid_config,logger_std_h,#{type:=faulty_type}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => faulty_type}}), @@ -230,15 +275,16 @@ errors(Config) -> _ -> NoDir = lists:concat(["/",?MODULE,"_dir"]), {error, - {handler_not_added,{{open_failed,NoDir,eacces},_}}} = + {handler_not_added,{open_failed,NoDir,eacces}}} = logger:add_handler(myh2,logger_std_h, #{config=>#{type=>{file,NoDir}}}) end, {error, - {handler_not_added,{{open_failed,Log,_},_}}} = + {handler_not_added, + {invalid_config,logger_std_h,#{modes:=bad_file_opt}}}} = logger:add_handler(myh3,logger_std_h, - #{config=>#{type=>{file,Log,[bad_file_opt]}}}), + #{config=>#{type=>{file,Log,bad_file_opt}}}), ok = logger:notice(?msg). @@ -280,7 +326,7 @@ formatter_fail(Config) -> ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,bad_return}), logger:notice(?msg,?domain), try_match_file(Log, - escape(Got3)++"FORMATTER ERROR: bad_return_value", + escape(Got3)++"FORMATTER ERROR: bad return value", 5000), %% Check that handler is still alive and was never dead @@ -293,25 +339,27 @@ formatter_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_config,logger_std_h, - {restart_type,bad}}}} = + #{restart_type:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=1}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -319,18 +367,24 @@ config_fail(_Config) -> ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{illegal_config_change,_,_}} = + {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} = logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,id,bad), - {error,{invalid_levels,_}} = + + {error,{invalid_olp_levels,_}} = logger:set_handler_config(?MODULE,config, #{sync_mode_qlen=>100, flush_qlen=>99}), - {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} = logger:set_handler_config(?MODULE, config, #{filesync_rep_int => 2000}), + + %% Read-only fields may (accidentially) be included in the change, + %% but it won't take effect + {ok,C} = logger:get_handler_config(?MODULE), + ok = logger:set_handler_config(?MODULE,config,#{olp=>dummyvalue}), + {ok,C} = logger:get_handler_config(?MODULE), + ok. config_fail(cleanup,_Config) -> @@ -396,10 +450,13 @@ crash_std_h(Config,Func,Var,Type,Log) -> %% logger would send the log event to the logger process here instead %% of logging it itself. log_on_remote_node(Node,Msg) -> + Pid = self(), _ = spawn_link(Node, fun() -> erlang:group_leader(whereis(user),self()), - logger:notice(Msg) + logger:notice(Msg), + Pid ! done end), + receive done -> ok end, ok. @@ -427,14 +484,7 @@ sync_and_read(Node,file,Log) -> 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). + {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"). reconfig(Config) -> Dir = ?config(priv_dir,Config), @@ -444,9 +494,10 @@ reconfig(Config) -> filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + #{%id := ?MODULE, + cb_state:=#{handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, + filesync_repeat_interval := no_repeat}, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -456,9 +507,25 @@ reconfig(Config) -> overload_kill_enable := ?OVERLOAD_KILL_ENABLE, overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = - logger_std_h:info(?MODULE), + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER} = + logger_olp:info(h_proc_name()), + + {ok, + #{config:= + #{type := standard_io, + 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 := no_repeat} = + DefaultHConf}} + = logger:get_handler_config(?MODULE), ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1, @@ -471,10 +538,11 @@ reconfig(Config) -> overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, overload_kill_restart_after => infinity, - filesync_repeat_interval => no_repeat}), - #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + filesync_repeat_interval => 5000}), + #{%id := ?MODULE, + cb_state := #{handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, + filesync_repeat_interval := no_repeat}, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -484,8 +552,77 @@ reconfig(Config) -> overload_kill_enable := true, overload_kill_qlen := 100000, overload_kill_mem_size := 10000000, - overload_kill_restart_after := infinity, - filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE), + overload_kill_restart_after := infinity} = logger_olp:info(h_proc_name()), + + {ok,#{config := + #{type := standard_io, + 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} = HConf}} = + 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 = HConf#{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 = DefaultHConf#{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 = DefaultHConf#{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 = DefaultHConf#{sync_mode_qlen => 1, + drop_mode_qlen => 100}, + + ok = logger:remove_handler(?MODULE), + + File = filename:join(Dir,lists:concat([?FUNCTION_NAME,".log"])), + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => {file,File}}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + {ok,#{config:=#{filesync_repeat_interval:=FSI}=FileHConfig}} = + logger:get_handler_config(?MODULE), + ok = logger:update_handler_config(?MODULE,config, + #{filesync_repeat_interval=>FSI+2000}), + {ok,#{config:=C5}} = logger:get_handler_config(?MODULE), + ct:log("C5: ~p",[C5]), + C5 = FileHConfig#{filesync_repeat_interval=>FSI+2000}, + + %% You are not allowed to actively set 'type' in runtime, since + %% this is a write once field. + {error, {illegal_config_change,logger_std_h,_,_}} = + logger:set_handler_config(?MODULE,config,#{type=>standard_io}), + {ok,#{config:=C6}} = logger:get_handler_config(?MODULE), + ct:log("C6: ~p",[C6]), + C6 = C5, + + %% ... but if you don't specify 'type', then set_handler_config shall + %% NOT reset it to its default value + ok = logger:set_handler_config(?MODULE,config,#{sync_mode_qlen=>1}), + {ok,#{config:=C7}} = logger:get_handler_config(?MODULE), + ct:log("C7: ~p",[C7]), + C7 = FileHConfig#{sync_mode_qlen=>1}, ok. reconfig(cleanup, _Config) -> @@ -495,22 +632,51 @@ reconfig(cleanup, _Config) -> 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, - #{config => #{type => BadType}}), + MissingOpts = [raw], + Type1 = {file,Log,MissingOpts}, + ok = logger:add_handler(?MODULE, logger_std_h, + #{config => #{type => Type1}}), + {ok,#{config:=#{type:=file,file:=Log,modes:=Modes1}}} = + logger:get_handler_config(?MODULE), + [append,delayed_write,raw] = lists:sort(Modes1), + ok = logger:remove_handler(?MODULE), OkFileOpts = [raw,append], OkType = {file,Log,OkFileOpts}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => OkType}, + #{config => #{type => OkType}, % old format filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{type := OkType} = logger_std_h:info(?MODULE), + ModOpts = [delayed_write|OkFileOpts], + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => file, + file => Log, + modes => OkFileOpts}, % new format + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger:get_handler_config(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -526,17 +692,16 @@ sync(Config) -> Type = {file,Log}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => #{type => Type, + file_check => 10000}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), %% check repeated filesync happens - start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("first", ?domain), @@ -544,11 +709,9 @@ sync(Config) -> check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once - start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {no_more,500} ]), @@ -561,43 +724,39 @@ sync(Config) -> %% check that if there's no repeated filesync active, %% a filesync is still performed when handler goes idle - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => no_repeat}), - no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), - %% The following timer is to make sure the time from last log - %% ("second") to next ("third") is long enough, so the a flush is - %% triggered by the idle timeout between "thrid" and "fourth". - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => no_repeat}), + no_repeat = maps:get(filesync_repeat_interval, + maps:get(cb_state, logger_olp:info(h_proc_name()))), + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {logger_std_h, write_to_dev, <<"fourth\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("third", ?domain), %% wait for automatic filesync - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + timer:sleep(?IDLE_DETECT_TIME*2), logger:notice("fourth", ?domain), %% wait for automatic filesync - check_tracer(?IDLE_DETECT_TIME_MSEC*2), + check_tracer(?IDLE_DETECT_TIME*2), %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_std_h,handle_cast,repeated_filesync}, - %% receive 1 initial repeated_filesync, then 1 per sec - start_tracer([{logger_std_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), - - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => SyncInt}), - SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{{logger_h_common,handle_cast,2}, + [{[repeated_filesync,'_'],[],[]}]}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), + + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => SyncInt}), + SyncInt = maps:get(filesync_repeat_interval, + maps:get(cb_state,logger_olp:info(h_proc_name()))), timer:sleep(WaitT), - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => no_repeat}), + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => no_repeat}), check_tracer(100), ok. sync(cleanup, _Config) -> @@ -652,11 +811,9 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), SyncInt = 500, - ok = rpc:call(Node, logger, set_handler_config, + ok = rpc:call(Node, logger, update_handler_config, [?STANDARD_HANDLER, config, #{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, @@ -718,7 +875,7 @@ op_switch_to_sync_file(Config) -> drop_mode_qlen => NumOfReqs+1, flush_qlen => 2*NumOfReqs, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), %% TRecvPid = start_op_trace(), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), @@ -747,7 +904,7 @@ op_switch_to_sync_tty(Config) -> drop_mode_qlen => NumOfReqs+1, flush_qlen => 2*NumOfReqs, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), ok. op_switch_to_sync_tty(cleanup, _Config) -> @@ -770,7 +927,7 @@ op_switch_to_drop_file(Config) -> flush_qlen => Procs*NumOfReqs*Bursts, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), %% It sometimes happens that the handler gets the %% requests in a slow enough pace so that dropping %% never occurs. Therefore, lets generate a number of @@ -807,7 +964,7 @@ op_switch_to_drop_tty(Config) -> flush_qlen => Procs*NumOfReqs+1, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), ok. op_switch_to_drop_tty(cleanup, _Config) -> @@ -832,7 +989,7 @@ op_switch_to_flush_file(Config) -> drop_mode_qlen => 300, flush_qlen => 300, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 1500, Procs = 10, Bursts = 10, @@ -879,7 +1036,7 @@ op_switch_to_flush_tty(Config) -> drop_mode_qlen => 100, flush_qlen => 100, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 1000, Procs = 100, send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), @@ -895,7 +1052,7 @@ limit_burst_disabled(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -915,7 +1072,7 @@ limit_burst_enabled_one(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -936,7 +1093,7 @@ limit_burst_enabled_period(Config) -> burst_limit_window_time => BurstTWin, drop_mode_qlen => 20000, flush_qlen => 20001}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), Windows = 3, Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), @@ -956,7 +1113,7 @@ kill_disabled(Config) -> HConfig#{config=>StdHConfig#{overload_kill_enable=>false, overload_kill_qlen=>10, overload_kill_mem_size=>100}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -977,7 +1134,7 @@ qlen_kill_new(Config) -> overload_kill_qlen=>10, overload_kill_mem_size=>Mem0+50000, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -986,7 +1143,7 @@ qlen_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -996,7 +1153,7 @@ qlen_kill_new(Config) -> ok after 5000 -> - Info = logger_std_h:info(?MODULE), + 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. @@ -1011,7 +1168,7 @@ qlen_kill_std(_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, + %% ok = rpc:call(Node, logger, update_handler_config, %% [?STANDARD_HANDLER, config, %% #{overload_kill_enable=>true, %% overload_kill_qlen=>10, @@ -1028,7 +1185,7 @@ mem_kill_new(Config) -> overload_kill_qlen=>50000, overload_kill_mem_size=>Mem0+500, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -1037,7 +1194,7 @@ mem_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -1047,7 +1204,7 @@ mem_kill_new(Config) -> ok after 5000 -> - Info = logger_std_h:info(?MODULE), + 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. @@ -1067,7 +1224,7 @@ restart_after(Config) -> HConfig#{config=>StdHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>infinity}}, - ok = logger:set_handler_config(?MODULE, NewHConfig1), + 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), @@ -1078,18 +1235,19 @@ restart_after(Config) -> ok after 5000 -> - Info1 = logger_std_h:info(?MODULE), + 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=>StdHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig2), + ok = logger:update_handler_config(?MODULE, NewHConfig2), Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler @@ -1102,7 +1260,7 @@ restart_after(Config) -> ok after 5000 -> - Info2 = logger_std_h:info(?MODULE), + 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, @@ -1123,12 +1281,16 @@ handler_requests_under_load(Config) -> drop_mode_qlen => 1000, flush_qlen => 2000, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, - {info,[]}, - {reset,[]}, - {change_config,[]}]) - end), + ok = logger:update_handler_config(?MODULE, NewHConfig), + Pid = spawn_link( + fun() -> send_requests(1,[{logger_std_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), Sent = send_burst({t,10000}, seq, {chars,79}, notice), Pid ! {self(),finish}, ReqResult = receive {Pid,Result} -> Result end, @@ -1139,41 +1301,390 @@ handler_requests_under_load(Config) -> [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), + 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(HName, TO, Reqs = [{Req,Res}|Rs]) -> +recreate_deleted_log(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + logger:notice("first",?domain), + logger_std_h:filesync(?MODULE), + ok = file:rename(Log,Log++".old"), + logger:notice("second",?domain), + logger_std_h:filesync(?MODULE), + {ok,<<"first\n">>} = file:read_file(Log++".old"), + {ok,<<"second\n">>} = file:read_file(Log), + ok. +recreate_deleted_log(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +reopen_changed_log(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + logger:notice("first",?domain), + logger_std_h:filesync(?MODULE), + ok = file:rename(Log,Log++".old"), + ok = file:write_file(Log,""), + logger:notice("second",?domain), + logger_std_h:filesync(?MODULE), + {ok,<<"first\n">>} = file:read_file(Log++".old"), + {ok,<<"second\n">>} = file:read_file(Log), + ok. +reopen_changed_log(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +rotate_size(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".1"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1005}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + ok. +rotate_size(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_compressed(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + #{config=>#{max_no_bytes=>1000, + max_no_files=>2, + compress_on_rotate=>true}}), + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".0.gz"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".1.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=38}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + ok. +rotate_size_compressed(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_reopen(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + {ok,HConfig} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler(?MODULE,maps:get(module,HConfig),HConfig), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=580}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + ok. +rotate_size_reopen(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts(Config) -> + {Log,_HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + #{max_no_bytes:=infinity, + max_no_files:=0, + compress_on_rotate:=false} = StdHConfig, + + %% Test bad rotation config + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_bytes=>0}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_files=>infinity}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config, + #{compress_on_rotate=>undefined}), + + + %% Test good rotation config - start with no rotation + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=200}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Turn on rotation, check that existing file is rotated since its + %% size exceeds max_no_bytes + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0 = Log++".0", + {ok,#file_info{size=200}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Extend size and count and check that nothing changes with existing files + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>200, + max_no_files=>3}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Add more log events and see that extended size and count works + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".2"), + [_,_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and check that archive files that exceed the new + %% count are moved + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Extend size and count again, and turn on compression. Check + %% that archives are compressed + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2, + compress_on_rotate=>true}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0gz = Log0++".gz", + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + [Log0gz] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + {ok,#file_info{size=29}} = file:read_file_info(Log++".1.gz"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and turn off compression. Check that archives that + %% exceeds the new count are removed, and the rest are + %% uncompressed. + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1, + compress_on_rotate=>false}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Check that config and handler state agree on the current rotation settings + {ok,#{config:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger:get_handler_config(?MODULE), + #{cb_state:=#{handler_state:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger_olp:info(h_proc_name()), + ok. +rotation_opts(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts_restart_handler(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + + %% Fill all logs + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,15)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=60}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off rotation. Check that archives are removed. + {ok,#{config:=StdHConfig1}=HConfig1} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig1#{config=>StdHConfig1#{max_no_bytes=>infinity}}), + timer:sleep(100), + {ok,#file_info{size=60}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Add some log events and check that file is no longer rotated. + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=260}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and trun on rotation. Check that file is rotated. + {ok,#{config:=StdHConfig2}=HConfig2} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig2#{config=>StdHConfig2#{max_no_bytes=>100, + max_no_files=>2}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=260}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=80}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=260}} = file:read_file_info(Log++".1"), + + %% Stop/start handler, reduce count and turn on compression. Check + %% that excess archives are removed, and the rest compressed. + {ok,#{config:=StdHConfig3}=HConfig3} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig3#{config=>StdHConfig3#{max_no_bytes=>75, + max_no_files=>1, + compress_on_rotate=>true}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log++".0.gz"), + [_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off compression. Check that achives + %% are decompressed. + {ok,#{config:=StdHConfig4}=HConfig4} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig4#{config=>StdHConfig4#{compress_on_rotate=>false}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=80}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + ok. +rotation_opts_restart_handler(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +%%%----------------------------------------------------------------- +%%% +send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> receive {From,finish} -> From ! {self(),Reqs} after TO -> - Result = - case Req of - change_config -> - logger:set_handler_config(HName, config, - #{overload_kill_enable => - false}); - Func -> - logger_std_h:Func(HName) - end, - send_requests(HName, TO, Rs ++ [{Req,[Result|Res]}]) + Result = apply(Mod,Func,Args), + send_requests(TO, Rs ++ [{Mod,Func,Args,[Result|Res]}]) end. %%%----------------------------------------------------------------- %%% -start_handler(Name, TTY, Config) when TTY == standard_io; - TTY == standard_error-> +start_handler(Name, TTY, _Config) when TTY == standard_io; + TTY == standard_error-> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {HConfig,StdHConfig}; @@ -1187,12 +1698,17 @@ start_handler(Name, FuncName, Config) -> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => Type}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {Log,HConfig,StdHConfig}. + +filter_only_this_domain(Name) -> + [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, + {domain,{fun logger_filters:domain/2,{log,super,[Name]}}}]. + stop_handler(Name) -> R = logger:remove_handler(Name), ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), @@ -1422,7 +1938,7 @@ start_op_trace() -> {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, check_load, 1, MS1), {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), @@ -1496,7 +2012,10 @@ analyse(Msgs) -> start_tracer(Trace,Expected) -> Pid = self(), - FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), + FileCtrlPid = maps:get(file_ctrl_pid, + maps:get(handler_state, + maps:get(cb_state, + logger_olp:info(h_proc_name())))), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), @@ -1504,7 +2023,9 @@ start_tracer(Trace,Expected) -> ok. tpl([{M,F,A}|Trace]) -> - {ok,Match} = dbg:tpl(M,F,A,[]), + tpl([{{M,F,A},[]}|Trace]); +tpl([{{M,F,A},MS}|Trace]) -> + {ok,Match} = dbg:tpl(M,F,A,MS), case lists:keyfind(matched,1,Match) of {_,_,1} -> ok; @@ -1517,10 +2038,10 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_std_h,handle_cast,[Op|_]}}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); -tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, +tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[Data,_]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> @@ -1570,27 +2091,29 @@ h_proc_name() -> h_proc_name(Name) -> ?name_to_reg_name(logger_std_h,Name). -file_delete(Log) -> - file:delete(Log). - wait_for_process_up(T) -> - wait_for_process_up(h_proc_name(),T). + wait_for_process_up(?MODULE, h_proc_name(), T). -wait_for_process_up(Name,T) -> +wait_for_process_up(Name, RegName, T) -> N = (T div 500) + 1, - wait_for_process_up1(Name,N). + wait_for_process_up1(Name, RegName, N). -wait_for_process_up1(_Name,0) -> +wait_for_process_up1(_Name, _RegName, 0) -> error; -wait_for_process_up1(Name,N) -> +wait_for_process_up1(Name, RegName, N) -> timer:sleep(500), - case whereis(Name) of + case whereis(RegName) of Pid when is_pid(Pid) -> - %% ct:pal("Process ~p up (~p tries left)",[Name,N]), - {ok,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,N-1) + wait_for_process_up1(Name, RegName, N-1) end. filesync_rep_int() -> @@ -1598,3 +2121,7 @@ filesync_rep_int() -> true -> 5500; false -> ?FILESYNC_REPEAT_INTERVAL + 500 end. + + +file_delete(Log) -> + file:delete(Log). |