aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel/test
diff options
context:
space:
mode:
Diffstat (limited to 'lib/kernel/test')
-rw-r--r--lib/kernel/test/logger_SUITE.erl2
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl108
-rw-r--r--lib/kernel/test/logger_env_var_SUITE.erl5
-rw-r--r--lib/kernel/test/logger_formatter_SUITE.erl2
-rw-r--r--lib/kernel/test/logger_legacy_SUITE.erl13
-rw-r--r--lib/kernel/test/logger_simple_h_SUITE.erl38
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl172
-rw-r--r--lib/kernel/test/logger_test_lib.erl4
8 files changed, 211 insertions, 133 deletions
diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl
index f837c31e64..b367b4dd54 100644
--- a/lib/kernel/test/logger_SUITE.erl
+++ b/lib/kernel/test/logger_SUITE.erl
@@ -329,7 +329,7 @@ log_no_levels(_Config) ->
ok.
log_no_levels(cleanup,_Config) ->
logger:remove_handler(h1),
- logger:set_primary_config(level,info),
+ logger:set_primary_config(level,notice),
logger:unset_module_level(?MODULE),
ok.
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index 5f7b505ecb..4c6fa1b5af 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -1,3 +1,22 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 2018. All Rights Reserved.
+%%
+%% Licensed under the Apache License, Version 2.0 (the "License");
+%% you may not use this file except in compliance with the License.
+%% You may obtain a copy of the License at
+%%
+%% http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing, software
+%% distributed under the License is distributed on an "AS IS" BASIS,
+%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+%% See the License for the specific language governing permissions and
+%% limitations under the License.
+%%
+%% %CopyrightEnd%
+%%
-module(logger_disk_log_h_SUITE).
-compile(export_all).
@@ -26,10 +45,6 @@
-define(log_no(File,N), lists:concat([File,".",N])).
-define(domain,#{domain=>[?MODULE]}).
--define(SYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500;
- true -> ?FILESYNC_REPEAT_INTERVAL + 500
- end).
-
suite() ->
[{timetrap,{seconds,30}},
{ct_hooks,[logger_test_lib]}].
@@ -50,9 +65,10 @@ end_per_group(_Group, _Config) ->
init_per_testcase(TestHooksCase, Config) when
TestHooksCase == write_failure;
TestHooksCase == sync_failure ->
- if ?TEST_HOOKS_TAB == undefined ->
+ case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of
+ true ->
{skip,"Define the TEST_HOOKS macro to run this test"};
- true ->
+ false ->
ct:print("********** ~w **********", [TestHooksCase]),
Config
end;
@@ -124,7 +140,7 @@ create_log(Config) ->
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("hello", ?domain),
- logger_disk_log_h:sync(Name1),
+ 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),
@@ -137,7 +153,7 @@ create_log(Config) ->
formatter=>{?MODULE,self()}},
#{file=>LogFile2}),
logger:notice("dummy", ?domain),
- logger_disk_log_h:sync(Name2),
+ 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),
@@ -158,7 +174,7 @@ open_existing_log(Config) ->
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("one", ?domain),
- logger_disk_log_h:sync(HName),
+ 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),
@@ -172,7 +188,7 @@ open_existing_log(Config) ->
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("three", ?domain),
- logger_disk_log_h:sync(HName),
+ 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).
@@ -197,22 +213,22 @@ disk_log_opts(Config) ->
{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:sync(WName),
+ 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:sync(WName),
+ 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:sync(WName),
+ 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:sync(WName),
+ logger_disk_log_h:filesync(WName),
timer:sleep(500),
2 = Get(current_file, disk_log:info(WName)),
@@ -230,7 +246,7 @@ disk_log_opts(Config) ->
{HFile1Full,halt,infinity} = {Get(file,HInfo1),Get(type,HInfo1),
Get(size,HInfo1)},
logger:notice("12345", ?domain),
- logger_disk_log_h:sync(HName1),
+ logger_disk_log_h:filesync(HName1),
timer:sleep(500),
1 = Get(no_written_items, disk_log:info(HName1)),
@@ -407,8 +423,8 @@ config_fail(cleanup,_Config) ->
logger:remove_handler(?MODULE).
bad_input(_Config) ->
- {error,{badarg,{sync,["BadType"]}}} =
- logger_disk_log_h:sync("BadType"),
+ {error,{badarg,{filesync,["BadType"]}}} =
+ logger_disk_log_h:filesync("BadType"),
{error,{badarg,{info,["BadType"]}}} = logger_disk_log_h:info("BadType"),
{error,{badarg,{reset,["BadType"]}}} = logger_disk_log_h:reset("BadType").
@@ -456,7 +472,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},
ok = logger:set_handler_config(?MODULE, config, HConfig1),
#{id := ?MODULE,
@@ -469,7 +485,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_disk_log_h:info(?MODULE),
@@ -526,7 +542,7 @@ sync(Config) ->
logger:notice("second", ?domain),
logger:notice("third", ?domain),
%% do explicit sync
- logger_disk_log_h:sync(?MODULE),
+ logger_disk_log_h:filesync(?MODULE),
check_tracer(100),
%% check that if there's no repeated disk_log_sync active,
@@ -739,9 +755,15 @@ write_failure(Config) ->
ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]),
ok = log_on_remote_node(Node, "Logged1"),
- rpc:call(Node, logger_disk_log_h, sync, [?STANDARD_HANDLER]),
+ rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
- try_read_file(Log, {ok,<<"Logged1\n">>}, ?SYNC_REP_INT),
+
+ SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of
+ true -> 5500;
+ false -> ?FILESYNC_REPEAT_INTERVAL + 500
+ end,
+
+ try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt),
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
@@ -759,9 +781,9 @@ write_failure(Config) ->
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]),
ok = log_on_remote_node(Node, "Logged2"),
- rpc:call(Node, logger_disk_log_h, sync, [?STANDARD_HANDLER]),
+ rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
- try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?SYNC_REP_INT),
+ try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt),
ok.
write_failure(cleanup, _Config) ->
Nodes = nodes(),
@@ -795,7 +817,7 @@ sync_failure(Config) ->
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,no_such_log}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
- ?check({error,{?STANDARD_HANDLER,sync,LogOpts,{error,no_such_log}}}),
+ ?check({error,{?STANDARD_HANDLER,filesync,LogOpts,{error,no_such_log}}}),
ok = log_on_remote_node(Node, "No second error printout"),
?check_no_log,
@@ -803,7 +825,7 @@ sync_failure(Config) ->
rpc:call(Node, ?MODULE, set_result,
[disk_log_sync,{error,{blocked_log,?STANDARD_HANDLER}}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
- ?check({error,{?STANDARD_HANDLER,sync,LogOpts,
+ ?check({error,{?STANDARD_HANDLER,filesync,LogOpts,
{error,{blocked_log,?STANDARD_HANDLER}}}}),
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]),
@@ -861,8 +883,8 @@ op_switch_to_sync(Config) ->
ok = logger:set_handler_config(?MODULE, NewHConfig),
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Lines = count_lines(Log),
- ok = file_delete(Log),
NumOfReqs = Lines,
+ ok = file_delete(Log),
ok.
op_switch_to_sync(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -892,11 +914,11 @@ op_switch_to_drop(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
@@ -944,11 +966,11 @@ op_switch_to_flush(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
@@ -976,8 +998,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).
@@ -995,8 +1018,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).
@@ -1017,9 +1041,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).
@@ -1119,7 +1144,7 @@ restart_after(Config) ->
NewHConfig1 =
HConfig#{config=>DLHConfig#{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
@@ -1173,7 +1198,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,[]}])
@@ -1220,6 +1245,8 @@ 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,
@@ -1229,7 +1256,7 @@ start_handler(Name, FuncName, Config) ->
filters=>?DEFAULT_HANDLER_FILTERS([Name]),
formatter=>{?MODULE,op}}),
{ok,HConfig = #{config := DLHConfig}} = logger:get_handler_config(Name),
- {lists:concat([File,".1"]),HConfig,DLHConfig}.
+ {FullFile,HConfig,DLHConfig}.
stop_handler(Name) ->
ct:pal("Stopping handler ~p!", [Name]),
@@ -1256,7 +1283,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,
@@ -1399,10 +1427,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)
diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl
index 6e182d4bca..04a4364947 100644
--- a/lib/kernel/test/logger_env_var_SUITE.erl
+++ b/lib/kernel/test/logger_env_var_SUITE.erl
@@ -214,6 +214,7 @@ logger_file(Config) ->
file,% dest
0),% progress in std logger
+ notice = maps:get(level,P),
#{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs),
all = maps:get(level,StdC),
StdFilters = maps:get(filters,StdC),
@@ -525,12 +526,12 @@ logger_many_handlers_default_last_broken_filter(Config) ->
{logger_level,info}], LogErr, LogInfo, 7).
logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) ->
- {ok,#{handlers:=Hs},Node} = setup(Config,Env),
+ {ok,_,Node} = setup(Config,Env),
check_single_log(Node,LogErr,
file,% dest
0,% progress in std logger
error), % level
- ok = rpc:call(Node,logger_std_h,sync,[info]),
+ ok = rpc:call(Node,logger_std_h,filesync,[info]),
{ok, Bin} = file:read_file(LogInfo),
ct:log("Log content:~n~s",[Bin]),
match(Bin,<<"info:">>,NumProgress,info,info),
diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl
index 864a40b618..8fe8d5199b 100644
--- a/lib/kernel/test/logger_formatter_SUITE.erl
+++ b/lib/kernel/test/logger_formatter_SUITE.erl
@@ -208,7 +208,7 @@ template(_Config) ->
time=>Time,
tuple=>{1,atom,"list"},
nested=>#{subkey=>subvalue}},
- Template6 = lists:join(";",maps:keys(maps:remove(nested,Meta6)) ++
+ Template6 = lists:join(";",lists:sort(maps:keys(maps:remove(nested,Meta6))) ++
[[nested,subkey]]),
String6 = format(info,{"~p",[term]},Meta6,#{template=>Template6,
single_line=>true}),
diff --git a/lib/kernel/test/logger_legacy_SUITE.erl b/lib/kernel/test/logger_legacy_SUITE.erl
index de73b6152a..c3cab07d81 100644
--- a/lib/kernel/test/logger_legacy_SUITE.erl
+++ b/lib/kernel/test/logger_legacy_SUITE.erl
@@ -20,6 +20,8 @@
-module(logger_legacy_SUITE).
-compile(export_all).
+-compile({nowarn_deprecated_function,[{gen_fsm,start,3},
+ {gen_fsm,send_all_state_event,2}]}).
-include_lib("common_test/include/ct.hrl").
-include_lib("kernel/include/logger.hrl").
@@ -89,6 +91,7 @@ init_per_group(_Group, Config) ->
end_per_group(sasl, Config) ->
Apps = ?config(stop_apps,Config),
[application:stop(App) || App <- Apps],
+ ok = logger:set_primary_config(level,notice),
ok;
end_per_group(_Group, _Config) ->
ok.
@@ -122,7 +125,7 @@ all() ->
gen_server(_Config) ->
{ok,Pid} = gen_server:start(?MODULE,gen_server,[]),
- Msg = fun() -> a=b end,
+ Msg = fun() -> erlang:error({badmatch,b}) end,
Pid ! Msg,
?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}),
ok = gen_server:cast(Pid,Msg),
@@ -132,7 +135,7 @@ gen_server(_Config) ->
gen_event(_Config) ->
{ok,Pid} = gen_event:start(),
ok = gen_event:add_handler(Pid,?MODULE,gen_event),
- Msg = fun() -> a=b end,
+ Msg = fun() -> erlang:error({badmatch,b}) end,
Pid ! Msg,
?check({warning_msg,"** Undefined handle_info in ~tp"++_,[?MODULE,Msg]}),
gen_event:notify(Pid,Msg),
@@ -141,7 +144,7 @@ gen_event(_Config) ->
gen_fsm(_Config) ->
{ok,Pid} = gen_fsm:start(?MODULE,gen_fsm,[]),
- Msg = fun() -> a=b end,
+ Msg = fun() -> erlang:error({badmatch,b}) end,
Pid ! Msg,
?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}),
gen_fsm:send_all_state_event(Pid,Msg),
@@ -150,7 +153,7 @@ gen_fsm(_Config) ->
gen_statem(_Config) ->
{ok,Pid} = gen_statem:start(?MODULE,gen_statem,[]),
- Msg = fun() -> a=b end,
+ Msg = fun() -> erlang:error({badmatch,b}) end,
Pid ! Msg,
?check({error,"** State machine ~tp terminating"++_,
[Pid,{info,Msg},{mystate,gen_statem},error,{badmatch,b}|_]}).
@@ -179,7 +182,7 @@ sasl_reports(Config) ->
ok = gen_server:cast(ChPid, fun() ->
spawn_link(fun() -> receive x->ok end end)
end),
- Msg = fun() -> a=b end,
+ Msg = fun() -> erlang:error({badmatch,b}) end,
ok = gen_server:cast(ChPid,Msg),
?check_no_flush({error,"** Generic server ~tp terminating"++_,
[ChPid,{'$gen_cast',Msg},gen_server,{{badmatch,b},_}]}),
diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl
index e4e48b538a..79e5c057ad 100644
--- a/lib/kernel/test/logger_simple_h_SUITE.erl
+++ b/lib/kernel/test/logger_simple_h_SUITE.erl
@@ -107,15 +107,15 @@ start_stop(cleanup,_Config) ->
replace_default(Config) ->
{ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]),
- log(Node, emergency, [M1=?str]),
- log(Node, alert, [M2=?str,[]]),
- log(Node, error, [M3=?map_rep]),
- log(Node, info, [M4=?keyval_rep]),
- log(Node, info, [M41=?keyval_rep++[not_key_val]]),
- rpc:call(Node, error_logger, error_report, [some_type,M5=?map_rep]),
- rpc:call(Node, error_logger, warning_report, ["some_type",M6=?map_rep]),
- log(Node, critical, [M7=?str,[A7=?keyval_rep]]),
- log(Node, notice, [M8=["fake",string,"line:",?LINE]]),
+ log(Node, emergency, [?str]),
+ log(Node, alert, [?str,[]]),
+ log(Node, error, [?map_rep]),
+ log(Node, info, [?keyval_rep]),
+ log(Node, info, [?keyval_rep++[not_key_val]]),
+ rpc:call(Node, error_logger, error_report, [some_type,?map_rep]),
+ rpc:call(Node, error_logger, warning_report, ["some_type",?map_rep]),
+ log(Node, critical, [?str,[?keyval_rep]]),
+ log(Node, notice, [["fake",string,"line:",?LINE]]),
Env = rpc:call(Node, application, get_env, [kernel, logger, []]),
ok = rpc:call(Node, logger, add_handlers, [Env]),
@@ -127,11 +127,11 @@ replace_file(Config) ->
{ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]),
log(Node, emergency, [M1=?str]),
log(Node, alert, [M2=?str,[]]),
- log(Node, error, [M3=?map_rep]),
- log(Node, warning, [M4=?keyval_rep]),
- log(Node, warning, [M41=?keyval_rep++[not_key_val]]),
- log(Node, critical, [M7=?str,[A7=?keyval_rep]]),
- log(Node, notice, [M8=["fake",string,"line:",?LINE]]),
+ log(Node, error, [?map_rep]),
+ log(Node, warning, [?keyval_rep]),
+ log(Node, warning, [?keyval_rep++[not_key_val]]),
+ log(Node, critical, [?str,[?keyval_rep]]),
+ log(Node, notice, [["fake",string,"line:",?LINE]]),
File = filename:join(proplists:get_value(priv_dir,Config),
atom_to_list(?FUNCTION_NAME)++".log"),
@@ -171,11 +171,11 @@ replace_disk_log(Config) ->
{ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]),
log(Node, emergency, [M1=?str]),
log(Node, alert, [M2=?str,[]]),
- log(Node, error, [M3=?map_rep]),
- log(Node, warning, [M4=?keyval_rep]),
- log(Node, warning, [M41=?keyval_rep++[not_key_val]]),
- log(Node, critical, [M7=?str,[A7=?keyval_rep]]),
- log(Node, notice, [M8=["fake",string,"line:",?LINE]]),
+ log(Node, error, [?map_rep]),
+ log(Node, warning, [?keyval_rep]),
+ log(Node, warning, [?keyval_rep++[not_key_val]]),
+ log(Node, critical, [?str,[?keyval_rep]]),
+ log(Node, notice, [["fake",string,"line:",?LINE]]),
File = filename:join(proplists:get_value(priv_dir,Config),
atom_to_list(?FUNCTION_NAME)++".log"),
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.
diff --git a/lib/kernel/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl
index 9097453c10..81eb9ce5eb 100644
--- a/lib/kernel/test/logger_test_lib.erl
+++ b/lib/kernel/test/logger_test_lib.erl
@@ -52,10 +52,10 @@ log(Node, M, F, A) ->
rpc:call(Node, M, F, A ++ [MD]).
sync_and_read(Node,disk_log,Log) ->
- rpc:call(Node,logger_disk_log_h,sync,[?STANDARD_HANDLER]),
+ rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]),
file:read_file(Log ++ ".1");
sync_and_read(Node, file,Log) ->
- ok = rpc:call(Node,logger_std_h,sync,[?STANDARD_HANDLER]),
+ ok = rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]),
file:read_file(Log).
generated by cgit v1.2.3 (git 2.25.1) at 2024-11-15 19:11:02 +0000