aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel/test/logger_std_h_SUITE.erl
diff options
context:
space:
mode:
authorPeter Andersson <[email protected]>2018-06-15 11:04:43 +0200
committerPeter Andersson <[email protected]>2018-06-15 11:04:43 +0200
commit4a25e214ae24292246155cb26d27831550a02922 (patch)
tree74e1e477654914c877e8279ef1db9f1941087831 /lib/kernel/test/logger_std_h_SUITE.erl
parent6a82d689a583145ef4c39beb9d4608e583d5f478 (diff)
parent343298ef2ef349e7b74265751fd6151ada224470 (diff)
downloadotp-4a25e214ae24292246155cb26d27831550a02922.tar.gz
otp-4a25e214ae24292246155cb26d27831550a02922.tar.bz2
otp-4a25e214ae24292246155cb26d27831550a02922.zip
Merge branch 'peppe/kernel/logger_updates'
* peppe/kernel/logger_updates: [logger] Correct documentation [logger] Update handler documentation [logger] Fix test suite compilation warnings [logger] Fix failing tests [logger] Change overload_kill_restart_after value to infinity [logger] Change name of function sync/1 to filesync/1 [logger] Reset logger config after tests [logger] Don't delete log file of failing test cases [logger] Set up priority for processes generatig test bursts [logger] Stress overload_kill tests a bit more [logger] Remove some compiler warnings in test suites [logger] Sort keys when testing formatter template [logger] Skip test involving file access rights on windows [logger] Skip some overload protection tests when using dirty schedulers
Diffstat (limited to 'lib/kernel/test/logger_std_h_SUITE.erl')
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl172
1 files changed, 109 insertions, 63 deletions
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index 36b123b07d..134358bb64 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -45,10 +45,6 @@
-define(bin(Msg), list_to_binary(Msg++"\n")).
-define(domain,#{domain=>[?MODULE]}).
--define(FILESYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500;
- true -> ?FILESYNC_REPEAT_INTERVAL + 500
- end).
-
suite() ->
[{timetrap,{seconds,30}},
{ct_hooks,[logger_test_lib]}].
@@ -73,12 +69,25 @@ end_per_group(_Group, _Config) ->
init_per_testcase(TestHooksCase, Config) when
TestHooksCase == write_failure;
TestHooksCase == sync_failure ->
- if ?TEST_HOOKS_TAB == undefined ->
+ case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of
+ true ->
{skip,"Define the TEST_HOOKS macro to run this test"};
- true ->
+ false ->
ct:print("********** ~w **********", [TestHooksCase]),
Config
end;
+init_per_testcase(OPCase, Config) when
+ OPCase == qlen_kill_new;
+ OPCase == restart_after ->
+ case re:run(erlang:system_info(system_version),
+ "dirty-schedulers-TEST",
+ [{capture,none}]) of
+ match ->
+ {skip,"Overload protection test skipped on dirty-schedulers-TEST"};
+ nomatch ->
+ ct:print("********** ~w **********", [OPCase]),
+ Config
+ end;
init_per_testcase(TestCase, Config) ->
ct:print("********** ~w **********", [TestCase]),
Config.
@@ -175,13 +184,13 @@ add_remove_instance_file(Log, Type) ->
logger:notice(M1=?msg,?domain),
?check(M1),
B1 = ?bin(M1),
- try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT),
+ try_read_file(Log, {ok,B1}, filesync_rep_int()),
ok = logger:remove_handler(?MODULE),
timer:sleep(500),
undefined = whereis(h_proc_name()),
logger:notice(?msg,?domain),
?check_no_log,
- try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT),
+ try_read_file(Log, {ok,B1}, filesync_rep_int()),
ok.
default_formatter(_Config) ->
@@ -214,11 +223,17 @@ errors(Config) ->
logger:add_handler(?MODULE,logger_std_h,
#{config => #{type => faulty_type}}),
- NoDir = lists:concat(["/",?MODULE,"_dir"]),
- {error,
- {handler_not_added,{{open_failed,NoDir,eacces},_}}} =
- logger:add_handler(myh2,logger_std_h,
- #{config=>#{type=>{file,NoDir}}}),
+ case os:type() of
+ {win32,_} ->
+ %% No use in testing file access on windows
+ ok;
+ _ ->
+ NoDir = lists:concat(["/",?MODULE,"_dir"]),
+ {error,
+ {handler_not_added,{{open_failed,NoDir,eacces},_}}} =
+ logger:add_handler(myh2,logger_std_h,
+ #{config=>#{type=>{file,NoDir}}})
+ end,
{error,
{handler_not_added,{{open_failed,Log,_},_}}} =
@@ -393,7 +408,7 @@ crash_std_h(cleanup) ->
[test_server:stop_node(Node) || Node <- Nodes].
sync_and_read(Node,disk_log,Log) ->
- rpc:call(Node,logger_disk_log_h,sync,[?STANDARD_HANDLER]),
+ rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]),
case file:read_file(Log ++ ".1") of
{ok,<<>>} ->
timer:sleep(5000),
@@ -402,7 +417,7 @@ sync_and_read(Node,disk_log,Log) ->
Ok
end;
sync_and_read(Node,file,Log) ->
- rpc:call(Node,logger_std_h,sync,[?STANDARD_HANDLER]),
+ rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]),
case file:read_file(Log) of
{ok,<<>>} ->
timer:sleep(5000),
@@ -412,7 +427,7 @@ sync_and_read(Node,file,Log) ->
end.
bad_input(_Config) ->
- {error,{badarg,{sync,["BadType"]}}} = logger_std_h:sync("BadType"),
+ {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").
@@ -455,7 +470,7 @@ reconfig(Config) ->
overload_kill_enable => true,
overload_kill_qlen => 100000,
overload_kill_mem_size => 10000000,
- overload_kill_restart_after => never,
+ overload_kill_restart_after => infinity,
filesync_repeat_interval => no_repeat}),
#{id := ?MODULE,
type := standard_io,
@@ -469,7 +484,7 @@ reconfig(Config) ->
overload_kill_enable := true,
overload_kill_qlen := 100000,
overload_kill_mem_size := 10000000,
- overload_kill_restart_after := never,
+ overload_kill_restart_after := infinity,
filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE),
ok.
@@ -499,7 +514,7 @@ file_opts(Config) ->
logger:notice(M1=?msg,?domain),
?check(M1),
B1 = ?bin(M1),
- try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT),
+ try_read_file(Log, {ok,B1}, filesync_rep_int()),
ok.
file_opts(cleanup, _Config) ->
logger:remove_handler(?MODULE).
@@ -526,7 +541,7 @@ sync(Config) ->
logger:notice("first", ?domain),
%% wait for automatic filesync
- check_tracer(?FILESYNC_REP_INT*2),
+ check_tracer(filesync_rep_int()*2),
%% check that explicit filesync is only done once
start_tracer([{logger_std_h, write_to_dev, 5},
@@ -539,9 +554,9 @@ sync(Config) ->
]),
logger:notice("second", ?domain),
%% do explicit sync
- logger_std_h:sync(?MODULE),
+ logger_std_h:filesync(?MODULE),
%% a second sync should be ignored
- logger_std_h:sync(?MODULE),
+ logger_std_h:filesync(?MODULE),
check_tracer(100),
%% check that if there's no repeated filesync active,
@@ -600,9 +615,9 @@ write_failure(Config) ->
rpc:call(Node, ?MODULE, set_result, [file_write,ok]),
ok = log_on_remote_node(Node, "Logged1"),
- rpc:call(Node, logger_std_h, sync, [?STANDARD_HANDLER]),
+ rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
- try_read_file(Log, {ok,<<"Logged1\n">>}, ?FILESYNC_REP_INT),
+ try_read_file(Log, {ok,<<"Logged1\n">>}, filesync_rep_int()),
rpc:call(Node, ?MODULE, set_result, [file_write,{error,terminated}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
@@ -618,9 +633,9 @@ write_failure(Config) ->
rpc:call(Node, ?MODULE, set_result, [file_write,ok]),
ok = log_on_remote_node(Node, "Logged2"),
- rpc:call(Node, logger_std_h, sync, [?STANDARD_HANDLER]),
+ rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
- try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?FILESYNC_REP_INT),
+ try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, filesync_rep_int()),
ok.
write_failure(cleanup, _Config) ->
Nodes = nodes(),
@@ -649,14 +664,14 @@ sync_failure(Config) ->
rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,terminated}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
- ?check({error,{?STANDARD_HANDLER,sync,Log,{error,terminated}}}),
+ ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,terminated}}}),
ok = log_on_remote_node(Node, "No second error printout"),
?check_no_log,
rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,eacces}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
- ?check({error,{?STANDARD_HANDLER,sync,Log,{error,eacces}}}),
+ ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,eacces}}}),
rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]),
ok = log_on_remote_node(Node, "Logged2"),
@@ -677,10 +692,10 @@ start_std_h_on_new_node(Config, Log) ->
Node.
%% functions for test hook macros to be called by rpc
-set_internal_log(Mod, Func) ->
- ?set_internal_log({Mod,Func}).
-set_result(Op, Result) ->
- ?set_result(Op, Result).
+set_internal_log(_Mod, _Func) ->
+ ?set_internal_log({_Mod,_Func}).
+set_result(_Op, _Result) ->
+ ?set_result(_Op, _Result).
set_defaults() ->
?set_defaults().
@@ -707,7 +722,6 @@ op_switch_to_sync_file(Config) ->
%% TRecvPid = start_op_trace(),
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Lines = count_lines(Log),
- ok = file_delete(Log),
%% true = analyse_trace(TRecvPid,
%% fun(Events) -> find_mode(async,Events) end),
%% true = analyse_trace(TRecvPid,
@@ -720,6 +734,7 @@ op_switch_to_sync_file(Config) ->
%% fun(Events) -> find_mode(flush,Events) end),
%% stop_op_trace(TRecvPid),
NumOfReqs = Lines,
+ ok = file_delete(Log),
ok.
op_switch_to_sync_file(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -764,11 +779,11 @@ op_switch_to_drop_file(Config) ->
_ <- lists:seq(1, Bursts)],
Logged = count_lines(Log),
ok = stop_handler(?MODULE),
- _ = file_delete(Log),
ct:pal("Number of messages dropped = ~w (~w)",
[Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]),
true = (Logged < (Procs*NumOfReqs*Bursts)),
true = (Logged > 0),
+ _ = file_delete(Log),
ok
end,
%% As it's tricky to get the timing right in only one go, we perform the
@@ -832,11 +847,11 @@ op_switch_to_flush_file(Config) ->
_ <- lists:seq(1,Bursts)],
Logged = count_lines(Log),
ok = stop_handler(?MODULE),
- _ = file_delete(Log),
ct:pal("Number of messages flushed/dropped = ~w (~w)",
[NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]),
true = (Logged < (NumOfReqs*Procs*Bursts)),
true = (Logged > 0),
+ _ = file_delete(Log),
ok
end,
%% As it's tricky to get the timing right in only one go, we perform the
@@ -885,8 +900,9 @@ limit_burst_disabled(Config) ->
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),
- NumOfReqs = Logged.
+ ok.
limit_burst_disabled(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -904,8 +920,9 @@ limit_burst_enabled_one(Config) ->
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),
- ReqLimit = Logged.
+ ok.
limit_burst_enabled_one(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -926,9 +943,10 @@ limit_burst_enabled_period(Config) ->
Logged = count_lines(Log),
ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w",
[Sent,Logged]),
- ok = file_delete(Log),
true = (Logged > (ReqLimit*Windows)) andalso
- (Logged < (ReqLimit*(Windows+2))).
+ (Logged < (ReqLimit*(Windows+2))),
+ ok = file_delete(Log),
+ ok.
limit_burst_enabled_period(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -950,7 +968,7 @@ kill_disabled(cleanup, _Config) ->
ok = stop_handler(?MODULE).
qlen_kill_new(Config) ->
- {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(h_proc_name()),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
@@ -962,7 +980,7 @@ qlen_kill_new(Config) ->
ok = logger:set_handler_config(?MODULE, NewHConfig),
MRef = erlang:monitor(process, Pid0),
NumOfReqs = 100,
- Procs = 2,
+ Procs = 4,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
%% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
receive
@@ -973,8 +991,8 @@ qlen_kill_new(Config) ->
killed ->
ct:pal("Slow shutdown, handler process was killed!", [])
end,
- timer:sleep(RestartAfter + 2000),
- true = is_pid(whereis(h_proc_name())),
+ file_delete(Log),
+ {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3),
ok
after
5000 ->
@@ -1001,7 +1019,7 @@ qlen_kill_std(_Config) ->
{skip,"Not done yet"}.
mem_kill_new(Config) ->
- {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(h_proc_name()),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
@@ -1013,7 +1031,7 @@ mem_kill_new(Config) ->
ok = logger:set_handler_config(?MODULE, NewHConfig),
MRef = erlang:monitor(process, Pid0),
NumOfReqs = 100,
- Procs = 2,
+ Procs = 4,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
%% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
receive
@@ -1024,8 +1042,8 @@ mem_kill_new(Config) ->
killed ->
ct:pal("Slow shutdown, handler process was killed!", [])
end,
- timer:sleep(RestartAfter * 3),
- true = is_pid(whereis(h_proc_name())),
+ file_delete(Log),
+ {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3),
ok
after
5000 ->
@@ -1041,23 +1059,27 @@ mem_kill_new(cleanup, _Config) ->
mem_kill_std(_Config) ->
{skip,"Not done yet"}.
+restart_after() ->
+ [{timetrap,{minutes,2}}].
restart_after(Config) ->
{Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig1 =
HConfig#{config=>StdHConfig#{overload_kill_enable=>true,
overload_kill_qlen=>10,
- overload_kill_restart_after=>never}},
+ overload_kill_restart_after=>infinity}},
ok = logger:set_handler_config(?MODULE, NewHConfig1),
MRef1 = erlang:monitor(process, whereis(h_proc_name())),
%% kill handler
- send_burst({n,100}, {spawn,2,0}, {chars,79}, notice),
+ send_burst({n,100}, {spawn,4,0}, {chars,79}, notice),
receive
- {'DOWN', MRef1, _, _, _Info1} ->
- timer:sleep(?OVERLOAD_KILL_RESTART_AFTER + 1000),
- undefined = whereis(h_proc_name()),
+ {'DOWN', MRef1, _, _, _Reason1} ->
+ file_delete(Log),
+ error = wait_for_process_up(h_proc_name(),?OVERLOAD_KILL_RESTART_AFTER * 3),
ok
after
5000 ->
+ Info1 = logger_std_h:info(?MODULE),
+ ct:pal("Handler state = ~p", [Info1]),
ct:fail("Handler not dead! It should not have survived this!")
end,
@@ -1071,16 +1093,17 @@ restart_after(Config) ->
Pid0 = whereis(h_proc_name()),
MRef2 = erlang:monitor(process, Pid0),
%% kill handler
- send_burst({n,100}, {spawn,2,0}, {chars,79}, notice),
+ send_burst({n,100}, {spawn,4,0}, {chars,79}, notice),
receive
- {'DOWN', MRef2, _, _, _Info2} ->
- timer:sleep(RestartAfter + 2000),
- Pid1 = whereis(h_proc_name()),
- true = is_pid(Pid1),
+ {'DOWN', MRef2, _, _, _Reason2} ->
+ file_delete(Log),
+ {ok,Pid1} = wait_for_process_up(h_proc_name(),RestartAfter * 3),
false = (Pid1 == Pid0),
ok
after
5000 ->
+ Info2 = logger_std_h:info(?MODULE),
+ ct:pal("Handler state = ~p", [Info2]),
ct:fail("Handler not dead! It should not have survived this!")
end,
ok.
@@ -1101,7 +1124,7 @@ handler_requests_under_load(Config) ->
flush_qlen => 2000,
burst_limit_enable => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{sync,[]},
+ Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]},
{info,[]},
{reset,[]},
{change_config,[]}])
@@ -1160,6 +1183,7 @@ start_handler(Name, FuncName, Config) ->
Log = filename:join(Dir, lists:concat([FuncName,".log"])),
ct:pal("Logging to ~tp", [Log]),
Type = {file,Log},
+ _ = file_delete(Log),
ok = logger:add_handler(Name,
logger_std_h,
#{config => #{type => Type},
@@ -1184,10 +1208,10 @@ wait_until_written(File, Sz) ->
{ok,#file_info{size = Sz}} ->
timer:sleep(1000),
case file:read_file_info(File) of
- {ok,#file_info{size = Sz1}} ->
+ {ok,#file_info{size = Sz}} ->
ok;
- {ok,#file_info{size = Sz2}} ->
- wait_until_written(File, Sz2)
+ {ok,#file_info{size = Sz1}} ->
+ wait_until_written(File, Sz1)
end;
{ok,#file_info{size = Sz1}} ->
wait_until_written(File, Sz1)
@@ -1230,7 +1254,8 @@ send_n_burst(N, seq, Text, Class) ->
send_n_burst(N-1, seq, Text, Class);
send_n_burst(N, {spawn,Ps,TO}, Text, Class) ->
ct:pal("~w processes each sending ~w messages", [Ps,N]),
- PerProc = fun() ->
+ PerProc = fun() ->
+ process_flag(priority,high),
send_n_burst(N, seq, Text, Class)
end,
MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end,
@@ -1300,7 +1325,7 @@ add_remove_instance_nofile(Type) ->
logger:notice(M1=?msg,?domain),
?check(M1),
%% check that sync doesn't do damage even if not relevant
- ok = logger_std_h:sync(?MODULE),
+ ok = logger_std_h:filesync(?MODULE),
ok = logger:remove_handler(?MODULE),
timer:sleep(500),
undefined = whereis(h_proc_name()),
@@ -1541,3 +1566,24 @@ h_proc_name(Name) ->
file_delete(Log) ->
file:delete(Log).
+
+wait_for_process_up(Name,T) ->
+ N = (T div 500) + 1,
+ wait_for_process_up1(Name,N).
+
+wait_for_process_up1(_Name,0) ->
+ error;
+wait_for_process_up1(Name,N) ->
+ timer:sleep(500),
+ case whereis(Name) of
+ Pid when is_pid(Pid) ->
+ {ok,Pid};
+ undefined ->
+ wait_for_process_up1(Name,N-1)
+ end.
+
+filesync_rep_int() ->
+ case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of
+ true -> 5500;
+ false -> ?FILESYNC_REPEAT_INTERVAL + 500
+ end.