%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2018. All Rights Reserved.
%%
%% Licensed under the Apache License, Version 2.0 (the "License");
%% you may not use this file except in compliance with the License.
%% You may obtain a copy of the License at
%%
%% http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing, software
%% distributed under the License is distributed on an "AS IS" BASIS,
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
%% See the License for the specific language governing permissions and
%% limitations under the License.
%%
%% %CopyrightEnd%
%%
-module(logger_disk_log_h_SUITE).
-compile(export_all).
-include_lib("common_test/include/ct.hrl").
-include_lib("kernel/include/logger.hrl").
-include_lib("kernel/src/logger_internal.hrl").
-include_lib("kernel/src/logger_h_common.hrl").
-include_lib("stdlib/include/ms_transform.hrl").
-include_lib("kernel/include/file.hrl").
-define(check_no_log, [] = test_server:messages_get()).
-define(check(Expected),
receive {log,Expected} ->
[] = test_server:messages_get()
after 1000 ->
ct:fail({report_not_received,
{line,?LINE},
{got,test_server:messages_get()}})
end).
-define(msg,"Log from "++atom_to_list(?FUNCTION_NAME)++
":"++integer_to_list(?LINE)).
-define(bin(Msg), list_to_binary(Msg++"\n")).
-define(log_no(File,N), lists:concat([File,".",N])).
-define(domain,#{domain=>[?MODULE]}).
-define(SYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500;
true -> ?FILESYNC_REPEAT_INTERVAL + 500
end).
suite() ->
[{timetrap,{seconds,30}},
{ct_hooks,[logger_test_lib]}].
init_per_suite(Config) ->
timer:start(), % to avoid progress report
Config.
end_per_suite(_Config) ->
ok.
init_per_group(_Group, Config) ->
Config.
end_per_group(_Group, _Config) ->
ok.
init_per_testcase(TestHooksCase, Config) when
TestHooksCase == write_failure;
TestHooksCase == sync_failure ->
if ?TEST_HOOKS_TAB == undefined ->
{skip,"Define the TEST_HOOKS macro to run this test"};
true ->
ct:print("********** ~w **********", [TestHooksCase]),
Config
end;
init_per_testcase(TestCase, Config) ->
ct:print("********** ~w **********", [TestCase]),
Config.
end_per_testcase(Case, Config) ->
try apply(?MODULE,Case,[cleanup,Config])
catch error:undef -> ok
end,
ok.
groups() ->
[].
all() ->
[start_stop_handler,
create_log,
open_existing_log,
disk_log_opts,
default_formatter,
logging,
errors,
formatter_fail,
config_fail,
bad_input,
info_and_reset,
reconfig,
sync,
disk_log_full,
disk_log_wrap,
disk_log_events,
write_failure,
sync_failure,
op_switch_to_sync,
op_switch_to_drop,
op_switch_to_flush,
limit_burst_disabled,
limit_burst_enabled_one,
limit_burst_enabled_period,
kill_disabled,
qlen_kill_new,
%% qlen_kill_std,
mem_kill_new,
%% mem_kill_std,
restart_after,
handler_requests_under_load
].
start_stop_handler(_Config) ->
ok = logger:add_handler(?MODULE, logger_disk_log_h, #{}),
{error,{already_exist,?MODULE}} =
logger:add_handler(?MODULE, logger_disk_log_h, #{}),
true = is_pid(whereis(h_proc_name())),
ok = logger:remove_handler(?MODULE),
timer:sleep(500),
undefined = whereis(h_proc_name()).
start_stop_handler(cleanup, _Config) ->
logger:remove_handler(?MODULE).
create_log(Config) ->
PrivDir = ?config(priv_dir,Config),
%% test new handler
Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_A"])),
LogFile1 = filename:join(PrivDir, Name1),
ok = start_and_add(Name1, #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("hello", ?domain),
logger_disk_log_h:filesync(Name1),
ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]),
try_read_file(?log_no(LogFile1,1), {ok,<<"hello\n">>}, 5000),
%% test second handler
Name2 = list_to_atom(lists:concat([?FUNCTION_NAME,"_B"])),
DLName = lists:concat([?FUNCTION_NAME,"_B_log"]),
LogFile2 = filename:join(PrivDir, DLName),
ok = start_and_add(Name2, #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}},
#{file=>LogFile2}),
logger:notice("dummy", ?domain),
logger_disk_log_h:filesync(Name2),
ct:pal("Checking contents of ~p", [?log_no(LogFile2,1)]),
try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000),
remove_and_stop(Name1),
remove_and_stop(Name2),
try_read_file(?log_no(LogFile1,1), {ok,<<"hello\ndummy\n">>}, 1),
try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000),
ok.
open_existing_log(Config) ->
PrivDir = ?config(priv_dir,Config),
%% test new handler
HName = ?FUNCTION_NAME,
DLName = lists:concat([?FUNCTION_NAME,"_log"]),
LogFile1 = filename:join(PrivDir, DLName),
ok = start_and_add(HName, #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("one", ?domain),
logger_disk_log_h:filesync(HName),
ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]),
try_read_file(?log_no(LogFile1,1), {ok,<<"one\n">>}, 5000),
logger:notice("two", ?domain),
ok = remove_and_stop(HName),
try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\n">>}, 5000),
logger:notice("two and a half", ?domain),
ok = start_and_add(HName, #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}},
#{file=>LogFile1}),
logger:notice("three", ?domain),
logger_disk_log_h:filesync(HName),
try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000),
remove_and_stop(HName),
try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000).
disk_log_opts(Config) ->
Get = fun(Key, PL) -> proplists:get_value(Key, PL) end,
PrivDir = ?config(priv_dir,Config),
WName = list_to_atom(lists:concat([?FUNCTION_NAME,"_W"])),
WFile = lists:concat([?FUNCTION_NAME,"_W_log"]),
Size = length("12345"),
ConfigW = #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter => {?MODULE,no_nl}},
WFileFull = filename:join(PrivDir, WFile),
DLOptsW = #{file => WFileFull,
type => wrap,
max_no_bytes => Size,
max_no_files => 2},
ok = start_and_add(WName, ConfigW, DLOptsW),
WInfo1 = disk_log:info(WName),
ct:log("Fullname = ~s", [WFileFull]),
{WFileFull,wrap,{Size,2},1} = {Get(file,WInfo1),Get(type,WInfo1),
Get(size,WInfo1),Get(current_file,WInfo1)},
logger:notice("123", ?domain),
logger_disk_log_h:filesync(WName),
timer:sleep(500),
1 = Get(current_file, disk_log:info(WName)),
logger:notice("45", ?domain),
logger_disk_log_h:filesync(WName),
timer:sleep(500),
1 = Get(current_file, disk_log:info(WName)),
logger:notice("6", ?domain),
logger_disk_log_h:filesync(WName),
timer:sleep(500),
2 = Get(current_file, disk_log:info(WName)),
logger:notice("7890", ?domain),
logger_disk_log_h:filesync(WName),
timer:sleep(500),
2 = Get(current_file, disk_log:info(WName)),
HName1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_H1"])),
HFile1 = lists:concat([?FUNCTION_NAME,"_H1_log"]),
ConfigH = #{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter => {?MODULE,no_nl}},
HFile1Full = filename:join(PrivDir, HFile1),
DLOptsH1 = #{file => HFile1Full,
type => halt},
ok = start_and_add(HName1, ConfigH, DLOptsH1),
HInfo1 = disk_log:info(HName1),
ct:log("Fullname = ~s", [HFile1Full]),
{HFile1Full,halt,infinity} = {Get(file,HInfo1),Get(type,HInfo1),
Get(size,HInfo1)},
logger:notice("12345", ?domain),
logger_disk_log_h:filesync(HName1),
timer:sleep(500),
1 = Get(no_written_items, disk_log:info(HName1)),
HName2 = list_to_atom(lists:concat([?FUNCTION_NAME,"_H2"])),
HFile2 = lists:concat([?FUNCTION_NAME,"_H2_log"]),
HFile2Full = filename:join(PrivDir, HFile2),
DLOptsH2 = DLOptsH1#{file => HFile2Full,
max_no_bytes => 1000},
ok = start_and_add(HName2, ConfigH, DLOptsH2),
HInfo3 = disk_log:info(HName2),
ct:log("Fullname = ~s", [HFile2Full]),
{HFile2Full,halt,1000} = {Get(file,HInfo3),Get(type,HInfo3),
Get(size,HInfo3)},
remove_and_stop(WName),
remove_and_stop(HName1),
remove_and_stop(HName2),
ok.
default_formatter(Config) ->
PrivDir = ?config(priv_dir,Config),
LogFile = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)),
HandlerConfig = #{config => #{file=>LogFile},
filter_default=>log},
ct:pal("Log: ~p", [LogFile]),
ok = logger:add_handler(?MODULE, logger_disk_log_h, HandlerConfig),
ok = logger:set_handler_config(?MODULE,formatter,
{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}),
LogName = lists:concat([LogFile, ".1"]),
logger:notice("dummy"),
wait_until_written(LogName),
{ok,Bin} = file:read_file(LogName),
match = re:run(Bin, "=NOTICE REPORT====.*\ndummy", [{capture,none}]),
ok.
default_formatter(cleanup, _Config) ->
logger:remove_handler(?MODULE).
logging(Config) ->
PrivDir = ?config(priv_dir,Config),
%% test new handler
Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])),
LogFile = filename:join(PrivDir, Name),
ok = start_and_add(Name, #{filter_default=>log,
formatter=>{?MODULE,self()}},
#{file => LogFile}),
MsgFormatter = fun(Term) -> {io_lib:format("Term:~p",[Term]),[]} end,
logger:notice([{x,y}], #{report_cb => MsgFormatter}),
logger:notice([{x,y}], #{}),
ct:pal("Checking contents of ~p", [?log_no(LogFile,1)]),
try_read_file(?log_no(LogFile,1), {ok,<<"Term:[{x,y}]\n x: y\n">>}, 5000).
logging(cleanup, _Config) ->
Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])),
remove_and_stop(Name).
errors(Config) ->
PrivDir = ?config(priv_dir,Config),
Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])),
LogFile1 = filename:join(PrivDir,Name1),
HandlerConfig = #{config=>#{file=>LogFile1},
filter_default=>log,
formatter=>{?MODULE,self()}},
ok = logger:add_handler(Name1, logger_disk_log_h, HandlerConfig),
{error,{already_exist,Name1}} =
logger:add_handler(Name1, logger_disk_log_h, #{}),
%%! TODO:
%%! Check how bad log_opts are handled!
{error,{illegal_config_change,_,_}} =
logger:set_handler_config(Name1,
config,
#{file=>LogFile1,
type=>halt}),
{error,{illegal_config_change,_,_}} =
logger:set_handler_config(Name1,id,new),
ok = logger:remove_handler(Name1),
{error,{not_found,Name1}} = logger:remove_handler(Name1),
ok.
errors(cleanup, _Config) ->
Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])),
_ = logger:remove_handler(Name1).
formatter_fail(Config) ->
PrivDir = ?config(priv_dir,Config),
Name = ?FUNCTION_NAME,
LogFile = filename:join(PrivDir,Name),
ct:pal("Log = ~p", [LogFile]),
HandlerConfig = #{config => #{file=>LogFile},
filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])},
%% no formatter!
logger:add_handler(Name, logger_disk_log_h, HandlerConfig),
Pid = whereis(h_proc_name(Name)),
true = is_pid(Pid),
H = logger:get_handler_ids(),
true = lists:member(Name,H),
%% Formatter is added automatically
{ok,#{formatter:={logger_formatter,_}}} = logger:get_handler_config(Name),
logger:notice(M1=?msg,?domain),
Got1 = try_match_file(?log_no(LogFile,1),"[0-9\\+\\-T:\\.]* notice: "++M1,5000),
ok = logger:set_handler_config(Name,formatter,{nonexistingmodule,#{}}),
logger:notice(M2=?msg,?domain),
Got2 = try_match_file(?log_no(LogFile,1),
escape(Got1)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M2,
5000),
ok = logger:set_handler_config(Name,formatter,{?MODULE,crash}),
logger:notice(M3=?msg,?domain),
Got3 = try_match_file(?log_no(LogFile,1),
escape(Got2)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M3,
5000),
ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}),
logger:notice(?msg,?domain),
try_match_file(?log_no(LogFile,1),
escape(Got3)++"FORMATTER ERROR: bad_return_value",
5000),
%% Check that handler is still alive and was never dead
Pid = whereis(h_proc_name(Name)),
H = logger:get_handler_ids(),
ok.
formatter_fail(cleanup,_Config) ->
_ = logger:remove_handler(?FUNCTION_NAME),
ok.
config_fail(_Config) ->
{error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{bad => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
{error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{drop_mode_qlen=>1}}),
{error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{sync_mode_qlen=>43,
drop_mode_qlen=>42}}),
{error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
#{config => #{drop_mode_qlen=>43,
flush_qlen=>42}}),
ok = logger:add_handler(?MODULE,logger_disk_log_h,
#{filter_default=>log,
formatter=>{?MODULE,self()}}),
%% can't change the disk log options for a log already in use
{error,{illegal_config_change,_,_}} =
logger:set_handler_config(?MODULE,config,
#{max_no_files=>2}),
%% can't change name of an existing handler
{error,{illegal_config_change,_,_}} =
logger:set_handler_config(?MODULE,id,bad),
%% incorrect values of OP params
{ok,#{config := HConfig}} = logger:get_handler_config(?MODULE),
{error,{invalid_levels,_}} =
logger:set_handler_config(?MODULE,config,
HConfig#{sync_mode_qlen=>100,
flush_qlen=>99}),
%% invalid name of config parameter
{error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} =
logger:set_handler_config(?MODULE, config,
HConfig#{filesync_rep_int => 2000}),
ok.
config_fail(cleanup,_Config) ->
logger:remove_handler(?MODULE).
bad_input(_Config) ->
{error,{badarg,{filesync,["BadType"]}}} =
logger_disk_log_h:filesync("BadType"),
{error,{badarg,{info,["BadType"]}}} = logger_disk_log_h:info("BadType"),
{error,{badarg,{reset,["BadType"]}}} = logger_disk_log_h:reset("BadType").
info_and_reset(_Config) ->
ok = logger:add_handler(?MODULE,logger_disk_log_h,
#{filter_default=>log,
formatter=>{?MODULE,self()}}),
#{id := ?MODULE} = logger_disk_log_h:info(?MODULE),
ok = logger_disk_log_h:reset(?MODULE).
info_and_reset(cleanup,_Config) ->
logger:remove_handler(?MODULE).
reconfig(Config) ->
Dir = ?config(priv_dir,Config),
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}}),
#{id := ?MODULE,
sync_mode_qlen := ?SYNC_MODE_QLEN,
drop_mode_qlen := ?DROP_MODE_QLEN,
flush_qlen := ?FLUSH_QLEN,
burst_limit_enable := ?BURST_LIMIT_ENABLE,
burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT,
burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME,
overload_kill_enable := ?OVERLOAD_KILL_ENABLE,
overload_kill_qlen := ?OVERLOAD_KILL_QLEN,
overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE,
overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER,
filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL,
log_opts := #{type := ?DISK_LOG_TYPE,
max_no_files := ?DISK_LOG_MAX_NO_FILES,
max_no_bytes := ?DISK_LOG_MAX_NO_BYTES,
file := _DiskLogFile}} =
logger_disk_log_h:info(?MODULE),
{ok,#{config := HConfig0}} = logger:get_handler_config(?MODULE),
HConfig1 = HConfig0#{sync_mode_qlen => 1,
drop_mode_qlen => 2,
flush_qlen => 3,
burst_limit_enable => false,
burst_limit_max_count => 10,
burst_limit_window_time => 10,
overload_kill_enable => true,
overload_kill_qlen => 100000,
overload_kill_mem_size => 10000000,
overload_kill_restart_after => never,
filesync_repeat_interval => no_repeat},
ok = logger:set_handler_config(?MODULE, config, HConfig1),
#{id := ?MODULE,
sync_mode_qlen := 1,
drop_mode_qlen := 2,
flush_qlen := 3,
burst_limit_enable := false,
burst_limit_max_count := 10,
burst_limit_window_time := 10,
overload_kill_enable := true,
overload_kill_qlen := 100000,
overload_kill_mem_size := 10000000,
overload_kill_restart_after := never,
filesync_repeat_interval := no_repeat} =
logger_disk_log_h:info(?MODULE),
ok = logger:remove_handler(?MODULE),
File = filename:join(Dir, "logfile"),
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()},
config=>
#{type => halt,
max_no_files => 1,
max_no_bytes => 1024,
file => File}}),
#{log_opts := #{type := halt,
max_no_files := 1,
max_no_bytes := 1024,
file := File}} =
logger_disk_log_h:info(?MODULE),
ok.
reconfig(cleanup, _Config) ->
logger:remove_handler(?MODULE).
sync(Config) ->
Dir = ?config(priv_dir,Config),
File = filename:join(Dir, ?FUNCTION_NAME),
Log = lists:concat([File,".1"]),
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{config => #{file => File},
filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,nl}}),
start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
[{disk_log,blog,<<"first\n">>},
{disk_log,sync}]),
logger:notice("first", ?domain),
%% wait for automatic disk_log_sync
check_tracer(?FILESYNC_REPEAT_INTERVAL*2),
start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
[{disk_log,blog,<<"second\n">>},
{disk_log,blog,<<"third\n">>},
{disk_log,sync}]),
%% two log requests in fast succession will make the handler skip
%% an automatic disk log sync
logger:notice("second", ?domain),
logger:notice("third", ?domain),
%% do explicit sync
logger_disk_log_h:filesync(?MODULE),
check_tracer(100),
%% check that if there's no repeated disk_log_sync active,
%% a disk_log_sync is still performed when handler goes idle
{ok,#{config := HConfig}} = logger:get_handler_config(?MODULE),
HConfig1 = HConfig#{filesync_repeat_interval => no_repeat},
ok = logger:set_handler_config(?MODULE, config, HConfig1),
no_repeat = maps:get(filesync_repeat_interval,
logger_disk_log_h:info(?MODULE)),
start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
[{disk_log,blog,<<"fourth\n">>},
{disk_log,blog,<<"fifth\n">>},
{disk_log,sync}]),
logger:notice("fourth", ?domain),
timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
logger:notice("fifth", ?domain),
%% wait for automatic disk_log_sync
check_tracer(?IDLE_DETECT_TIME_MSEC*2),
try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\nfifth\n">>}, 1000),
%% switch repeated disk_log_sync on and verify that the looping works
SyncInt = 1000,
WaitT = 4500,
OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync},
%% receive 1 initial repeated_disk_log_sync, then 1 per sec
start_tracer([{logger_disk_log_h,handle_cast,2}],
[OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
HConfig2 = HConfig#{filesync_repeat_interval => SyncInt},
ok = logger:set_handler_config(?MODULE, config, HConfig2),
SyncInt = maps:get(filesync_repeat_interval,
logger_disk_log_h:info(?MODULE)),
timer:sleep(WaitT),
HConfig3 = HConfig#{filesync_repeat_interval => no_repeat},
ok = logger:set_handler_config(?MODULE, config, HConfig3),
check_tracer(100),
ok.
sync(cleanup,_Config) ->
dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_wrap(Config) ->
Get = fun(Key, PL) -> proplists:get_value(Key, PL) end,
Dir = ?config(priv_dir,Config),
File = filename:join(Dir, ?FUNCTION_NAME),
ct:pal("Log = ~p", [File]),
MaxFiles = 3,
MaxBytes = 5,
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()},
config=>
#{type => wrap,
max_no_files => MaxFiles,
max_no_bytes => MaxBytes,
file => File}}),
Info = disk_log:info(?MODULE),
{File,wrap,{MaxBytes,MaxFiles},1} =
{Get(file,Info),Get(type,Info),Get(size,Info),Get(current_file,Info)},
Tester = self(),
TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) ->
Pid ! {trace,Mod,Func,Details},
Pid
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
{ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)],
ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]),
%% fill first file
lists:foreach(fun(N) ->
Log = lists:concat([File,".",N]),
logger:notice(Text, ?domain),
wait_until_written(Log),
ct:pal("N = ~w",
[N = Get(current_file,
disk_log:info(?MODULE))])
end, lists:seq(1,MaxFiles)),
%% wait for trace messages
timer:sleep(1000),
dbg:stop_clear(),
Received = lists:flatmap(fun({trace,_M,handle_info,
[{disk_log,_Node,_Name,What},_]}) ->
[{trace,What}];
({log,_}) ->
[]
end, test_server:messages_get()),
ct:pal("Trace =~n~p", [Received]),
Received = [{trace,{wrap,0}} || _ <- lists:seq(1,MaxFiles-1)],
ok.
disk_log_wrap(cleanup,_Config) ->
dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_full(Config) ->
Dir = ?config(priv_dir,Config),
File = filename:join(Dir, ?FUNCTION_NAME),
ct:pal("Log = ~p", [File]),
MaxBytes = 50,
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()},
config=>
#{type => halt,
max_no_files => 1,
max_no_bytes => MaxBytes,
file => File}}),
Tester = self(),
TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) ->
Pid ! {trace,Mod,Func,Details},
Pid
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
{ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
NoOfChars = 5,
Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)],
[logger:notice(Text, ?domain) || _ <- lists:seq(1,trunc(MaxBytes/NoOfChars)+1)],
%% wait for trace messages
timer:sleep(2000),
dbg:stop_clear(),
Received = lists:flatmap(fun({trace,_M,handle_info,
[{disk_log,_Node,_Name,What},_]}) ->
[{trace,What}];
({log,_}) ->
[]
end, test_server:messages_get()),
ct:pal("Trace =~n~p", [Received]),
[{trace,full},
{trace,{error_status,{error,{full,_}}}}] = Received,
ok.
disk_log_full(cleanup, _Config) ->
dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_events(Config) ->
Node = node(),
Log = ?MODULE,
ok = logger:add_handler(?MODULE,
logger_disk_log_h,
#{filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,self()}}),
%% Events copied from disk_log API
Events =
[{disk_log, Node, Log, {wrap, 0}},
{disk_log, Node, Log, {truncated, 0}},
{disk_log, Node, Log, {read_only, 42}},
{disk_log, Node, Log, {blocked_log, 42}},
{disk_log, Node, Log, {format_external, 42}},
{disk_log, Node, Log, full},
{disk_log, Node, Log, {error_status, ok}}],
Tester = self(),
TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) ->
Pid ! {trace,Mod,Func,Details},
Pid
end,
{ok,_} = dbg:tracer(process, {TraceFun, Tester}),
{ok,_} = dbg:p(whereis(h_proc_name()), [c]),
{ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
[whereis(h_proc_name()) ! E || E <- Events],
%% wait for trace messages
timer:sleep(2000),
dbg:stop_clear(),
Received = lists:map(fun({trace,_M,handle_info,
[Got,_]}) -> Got
end, test_server:messages_get()),
ct:pal("Trace =~n~p", [Received]),
NoOfEvents = length(Events),
NoOfEvents = length(Received),
lists:foreach(fun(Event) ->
true = lists:member(Event, Received)
end, Received),
ok.
disk_log_events(cleanup, _Config) ->
dbg:stop_clear(),
logger:remove_handler(?MODULE).
write_failure(Config) ->
Dir = ?config(priv_dir, Config),
File = filename:join(Dir, ?FUNCTION_NAME),
Log = lists:concat([File,".1"]),
ct:pal("Log = ~p", [Log]),
Node = start_h_on_new_node(Config, File),
false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])),
rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]),
rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]),
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]),
HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]),
ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]),
ok = log_on_remote_node(Node, "Logged1"),
rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
try_read_file(Log, {ok,<<"Logged1\n">>}, ?SYNC_REP_INT),
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}),
ok = log_on_remote_node(Node, "No second error printout"),
?check_no_log,
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,
{error,{full,?STANDARD_HANDLER}}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
?check({error,{?STANDARD_HANDLER,log,LogOpts,
{error,{full,?STANDARD_HANDLER}}}}),
rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]),
ok = log_on_remote_node(Node, "Logged2"),
rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]),
?check_no_log,
try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?SYNC_REP_INT),
ok.
write_failure(cleanup, _Config) ->
Nodes = nodes(),
[test_server:stop_node(Node) || Node <- Nodes].
sync_failure(Config) ->
Dir = ?config(priv_dir, Config),
FileName = lists:concat([?MODULE,"_",?FUNCTION_NAME]),
File = filename:join(Dir, FileName),
Node = start_h_on_new_node(Config, File),
false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])),
rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]),
rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]),
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]),
HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]),
LogOpts = maps:get(log_opts, HState),
SyncInt = 500,
ok = rpc:call(Node, logger, set_handler_config,
[?STANDARD_HANDLER, config,
#{filesync_repeat_interval => SyncInt}]),
Info = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]),
SyncInt = maps:get(filesync_repeat_interval, Info),
ok = log_on_remote_node(Node, "Logged1"),
?check_no_log,
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,no_such_log}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
?check({error,{?STANDARD_HANDLER,filesync,LogOpts,{error,no_such_log}}}),
ok = log_on_remote_node(Node, "No second error printout"),
?check_no_log,
rpc:call(Node, ?MODULE, set_result,
[disk_log_sync,{error,{blocked_log,?STANDARD_HANDLER}}]),
ok = log_on_remote_node(Node, "Cause simple error printout"),
?check({error,{?STANDARD_HANDLER,filesync,LogOpts,
{error,{blocked_log,?STANDARD_HANDLER}}}}),
rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]),
ok = log_on_remote_node(Node, "Logged2"),
?check_no_log,
ok.
sync_failure(cleanup, _Config) ->
Nodes = nodes(),
[test_server:stop_node(Node) || Node <- Nodes].
start_h_on_new_node(Config, File) ->
{ok,_,Node} =
logger_test_lib:setup(
Config,
[{logger,[{handler,default,logger_disk_log_h,
#{ config => #{ file => File }}}]}]),
ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter,
{?MODULE,nl}]),
Node.
log_on_remote_node(Node,Msg) ->
_ = spawn_link(Node,
fun() -> erlang:group_leader(whereis(user),self()),
logger:notice(Msg)
end),
ok.
%% functions for test hook macros to be called by rpc
set_internal_log(_Mod, _Func) ->
?set_internal_log({_Mod,_Func}).
set_result(_Op, _Result) ->
?set_result(_Op, _Result).
set_defaults() ->
?set_defaults().
%% internal log function that sends the term to the test case process
internal_log(Type, Term) ->
[{tester,Tester}] = ets:lookup(?TEST_HOOKS_TAB, tester),
Tester ! {log,{Type,Term}},
logger:internal_log(Type, Term),
ok.
%%%-----------------------------------------------------------------
%%% Overload protection tests
op_switch_to_sync(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NumOfReqs = 500,
NewHConfig =
HConfig#{config => DLHConfig#{sync_mode_qlen => 2,
drop_mode_qlen => NumOfReqs+1,
flush_qlen => 2*NumOfReqs,
burst_limit_enable => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Lines = count_lines(Log),
NumOfReqs = Lines,
ok = file_delete(Log),
ok.
op_switch_to_sync(cleanup, _Config) ->
ok = stop_handler(?MODULE).
op_switch_to_drop() ->
[{timetrap,{seconds,180}}].
op_switch_to_drop(Config) ->
Test =
fun() ->
{Log,HConfig,DLHConfig} =
start_handler(?MODULE, ?FUNCTION_NAME, Config),
NumOfReqs = 300,
Procs = 2,
Bursts = 10,
NewHConfig =
HConfig#{config =>
DLHConfig#{sync_mode_qlen => 1,
drop_mode_qlen => 2,
flush_qlen => Procs*NumOfReqs*Bursts,
burst_limit_enable => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
%% It sometimes happens that the handler either gets
%% the requests in a slow enough pace so that dropping
%% never occurs. Therefore, lets generate a number of
%% bursts to increase the chance of message buildup.
[send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) ||
_ <- lists:seq(1, Bursts)],
Logged = count_lines(Log),
ok = stop_handler(?MODULE),
ct:pal("Number of messages dropped = ~w (~w)",
[Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]),
true = (Logged < (Procs*NumOfReqs*Bursts)),
true = (Logged > 0),
_ = file_delete(Log),
ok
end,
%% As it's tricky to get the timing right in only one go, we perform the
%% test repeatedly, hoping that will generate a successful result.
case repeat_until_ok(Test, 10) of
{ok,{Failures,_Result}} ->
ct:log("Failed ~w times before success!", [Failures]);
{fails,Reason} ->
ct:fail(Reason)
end.
op_switch_to_drop(cleanup, _Config) ->
_ = stop_handler(?MODULE).
op_switch_to_flush() ->
[{timetrap,{minutes,3}}].
op_switch_to_flush(Config) ->
Test =
fun() ->
{Log,HConfig,DLHConfig} =
start_handler(?MODULE, ?FUNCTION_NAME, Config),
%% NOTE: it's important that both async and sync
%% requests have been queued when the flush happens
%% (verify with coverage of flush_log_requests/2)
NewHConfig =
HConfig#{config =>
DLHConfig#{sync_mode_qlen => 2,
%% disable drop mode
drop_mode_qlen => 300,
flush_qlen => 300,
burst_limit_enable => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
NumOfReqs = 1500,
Procs = 10,
Bursts = 10,
%% It sometimes happens that the handler either gets
%% the requests in a slow enough pace so that flushing
%% never occurs, or it gets all messages at once,
%% causing all messages to get flushed (no dropping of
%% sync messages gets tested). Therefore, lets
%% generate a number of bursts to increase the chance
%% of message buildup in some random fashion.
[send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) ||
_ <- lists:seq(1,Bursts)],
Logged = count_lines(Log),
ok= stop_handler(?MODULE),
ct:pal("Number of messages flushed/dropped = ~w (~w)",
[NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]),
true = (Logged < (NumOfReqs*Procs*Bursts)),
true = (Logged > 0),
_ = file_delete(Log),
ok
end,
%% As it's tricky to get the timing right in only one go, we perform the
%% test repeatedly, hoping that will generate a successful result.
case repeat_until_ok(Test, 10) of
{ok,{Failures,_Result}} ->
ct:log("Failed ~w times before success!", [Failures]);
{fails,Reason} ->
ct:fail(Reason)
end.
op_switch_to_flush(cleanup, _Config) ->
_ = stop_handler(?MODULE).
limit_burst_disabled(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig =
HConfig#{config => DLHConfig#{burst_limit_enable => false,
burst_limit_max_count => 10,
burst_limit_window_time => 2000,
drop_mode_qlen => 200,
flush_qlen => 300}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
NumOfReqs = 100,
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Logged = count_lines(Log),
ct:pal("Number of messages logged = ~w", [Logged]),
NumOfReqs = Logged,
ok = file_delete(Log),
ok.
limit_burst_disabled(cleanup, _Config) ->
ok = stop_handler(?MODULE).
limit_burst_enabled_one(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
ReqLimit = 10,
NewHConfig =
HConfig#{config => DLHConfig#{burst_limit_enable => true,
burst_limit_max_count => ReqLimit,
burst_limit_window_time => 2000,
drop_mode_qlen => 200,
flush_qlen => 300}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
NumOfReqs = 100,
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Logged = count_lines(Log),
ct:pal("Number of messages logged = ~w", [Logged]),
ReqLimit = Logged,
ok = file_delete(Log),
ok.
limit_burst_enabled_one(cleanup, _Config) ->
ok = stop_handler(?MODULE).
limit_burst_enabled_period(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
ReqLimit = 10,
BurstTWin = 1000,
NewHConfig =
HConfig#{config => DLHConfig#{burst_limit_enable => true,
burst_limit_max_count => ReqLimit,
burst_limit_window_time => BurstTWin,
drop_mode_qlen => 20000,
flush_qlen => 20001}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
Windows = 3,
Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice),
Logged = count_lines(Log),
ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w",
[Sent,Logged]),
true = (Logged > (ReqLimit*Windows)) andalso
(Logged < (ReqLimit*(Windows+2))),
ok = file_delete(Log),
ok.
limit_burst_enabled_period(cleanup, _Config) ->
ok = stop_handler(?MODULE).
kill_disabled(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig =
HConfig#{config=>DLHConfig#{overload_kill_enable=>false,
overload_kill_qlen=>10,
overload_kill_mem_size=>100}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
NumOfReqs = 100,
send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
Logged = count_lines(Log),
ct:pal("Number of messages logged = ~w", [Logged]),
ok = file_delete(Log),
true = is_pid(whereis(h_proc_name())),
ok.
kill_disabled(cleanup, _Config) ->
ok = stop_handler(?MODULE).
qlen_kill_new(Config) ->
{_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(h_proc_name()),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
NewHConfig =
HConfig#{config =>
DLHConfig#{overload_kill_enable=>true,
overload_kill_qlen=>10,
overload_kill_mem_size=>Mem0+50000,
overload_kill_restart_after=>RestartAfter}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
MRef = erlang:monitor(process, Pid0),
NumOfReqs = 100,
Procs = 2,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
%% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
receive
{'DOWN', MRef, _, _, Info} ->
case Info of
{shutdown,{overloaded,?MODULE,QLen,Mem}} ->
ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]);
killed ->
ct:pal("Slow shutdown, handler process was killed!", [])
end,
timer:sleep(RestartAfter + 2000),
true = is_pid(whereis(h_proc_name())),
ok
after
5000 ->
Info = logger_disk_log_h:info(?MODULE),
ct:pal("Handler state = ~p", [Info]),
ct:fail("Handler not dead! It should not have survived this!")
end.
qlen_kill_new(cleanup, _Config) ->
ok = stop_handler(?MODULE).
mem_kill_new(Config) ->
{_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(h_proc_name()),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
NewHConfig =
HConfig#{config =>
DLHConfig#{overload_kill_enable=>true,
overload_kill_qlen=>50000,
overload_kill_mem_size=>Mem0+500,
overload_kill_restart_after=>RestartAfter}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
MRef = erlang:monitor(process, Pid0),
NumOfReqs = 100,
Procs = 2,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
%% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
receive
{'DOWN', MRef, _, _, Info} ->
case Info of
{shutdown,{overloaded,?MODULE,QLen,Mem}} ->
ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]);
killed ->
ct:pal("Slow shutdown, handler process was killed!", [])
end,
timer:sleep(RestartAfter + 2000),
true = is_pid(whereis(h_proc_name())),
ok
after
5000 ->
Info = logger_disk_log_h:info(?MODULE),
ct:pal("Handler state = ~p", [Info]),
ct:fail("Handler not dead! It should not have survived this!")
end.
mem_kill_new(cleanup, _Config) ->
ok = stop_handler(?MODULE).
restart_after(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig1 =
HConfig#{config=>DLHConfig#{overload_kill_enable=>true,
overload_kill_qlen=>10,
overload_kill_restart_after=>never}},
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),
receive
{'DOWN', MRef1, _, _, _Info1} ->
timer:sleep(?OVERLOAD_KILL_RESTART_AFTER + 1000),
undefined = whereis(h_proc_name()),
ok
after
5000 ->
ct:fail("Handler not dead! It should not have survived this!")
end,
{Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
NewHConfig2 =
HConfig#{config=>DLHConfig#{overload_kill_enable=>true,
overload_kill_qlen=>10,
overload_kill_restart_after=>RestartAfter}},
ok = logger:set_handler_config(?MODULE, NewHConfig2),
Pid0 = whereis(h_proc_name()),
MRef2 = erlang:monitor(process, Pid0),
%% kill handler
send_burst({n,100}, {spawn,2,0}, {chars,79}, notice),
receive
{'DOWN', MRef2, _, _, _Info2} ->
timer:sleep(RestartAfter + 2000),
Pid1 = whereis(h_proc_name()),
true = is_pid(Pid1),
false = (Pid1 == Pid0),
ok
after
5000 ->
ct:fail("Handler not dead! It should not have survived this!")
end,
ok.
restart_after(cleanup, _Config) ->
ok = stop_handler(?MODULE).
%% send handler requests (sync, info, reset, change_config)
%% during high load to verify that sync, dropping and flushing is
%% handled correctly.
handler_requests_under_load() ->
[{timetrap,{minutes,3}}].
handler_requests_under_load(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig =
HConfig#{config => DLHConfig#{sync_mode_qlen => 2,
drop_mode_qlen => 1000,
flush_qlen => 2000,
burst_limit_enable => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]},
{info,[]},
{reset,[]},
{change_config,[]}])
end),
Procs = 100,
Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, notice),
Pid ! {self(),finish},
ReqResult = receive {Pid,Result} -> Result end,
Logged = count_lines(Log),
ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w",
[Sent,Logged]),
FindError = fun(Res) ->
[E || E <- Res,
is_tuple(E) andalso (element(1,E) == error)]
end,
Errors = [{Req,FindError(Res)} || {Req,Res} <- ReqResult],
NoOfReqs = lists:foldl(fun({_,Res}, N) -> N + length(Res) end, 0, ReqResult),
ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]),
ok = file_delete(Log).
handler_requests_under_load(cleanup, _Config) ->
ok = stop_handler(?MODULE).
send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) ->
receive
{From,finish} ->
From ! {self(),Reqs}
after
TO ->
Result =
case Req of
change_config ->
logger:set_handler_config(HName, logger_disk_log_h,
#{overload_kill_enable =>
false});
Func ->
logger_disk_log_h:Func(HName)
end,
send_requests(HName, TO, Rs ++ [{Req,[Result|Res]}])
end.
%%%-----------------------------------------------------------------
%%%
start_handler(Name, FuncName, Config) ->
Dir = ?config(priv_dir,Config),
File = filename:join(Dir, FuncName),
ct:pal("Logging to ~tp", [File]),
FullFile = lists:concat([File,".1"]),
_ = file_delete(FullFile),
ok = logger:add_handler(Name,
logger_disk_log_h,
#{config=>#{file => File,
max_no_files => 1,
max_no_bytes => 100000000},
filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([Name]),
formatter=>{?MODULE,op}}),
{ok,HConfig = #{config := DLHConfig}} = logger:get_handler_config(Name),
{FullFile,HConfig,DLHConfig}.
stop_handler(Name) ->
ct:pal("Stopping handler ~p!", [Name]),
logger:remove_handler(Name).
send_burst(NorT, Type, {chars,Sz}, Class) ->
Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)],
case NorT of
{n,N} ->
%% process_flag(priority, high),
send_n_burst(N, Type, Text, Class),
%% process_flag(priority, normal),
N;
{t,T} ->
ct:pal("Sending messages sequentially for ~w ms", [T]),
T0 = erlang:monotonic_time(millisecond),
send_t_burst(T0, T, Text, Class, 0)
end.
send_n_burst(0, _, _Text, _Class) ->
ok;
send_n_burst(N, seq, Text, Class) ->
ok = logger:Class(Text, ?domain),
send_n_burst(N-1, seq, Text, Class);
send_n_burst(N, {spawn,Ps,TO}, Text, Class) ->
ct:pal("~w processes each sending ~w messages", [Ps,N]),
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,
monitor(process,spawn_link(PerProc)) end ||
_ <- lists:seq(1,Ps)],
lists:foreach(fun(MRef) ->
receive
{'DOWN', MRef, _, _, _} ->
ok
end
end, MRefs),
ct:pal("Message burst sent", []),
ok.
send_t_burst(T0, T, Text, Class, N) ->
T1 = erlang:monotonic_time(millisecond),
if (T1-T0) > T ->
N;
true ->
ok = logger:Class(Text, ?domain),
send_t_burst(T0, T, Text, Class, N+1)
end.
%%%-----------------------------------------------------------------
%%% Formatter callback
%%% Using this to send the formatted string back to the test case
%%% process - so it can check for logged events.
format(_,bad_return) ->
bad_return;
format(_,crash) ->
erlang:error(formatter_crashed);
format(#{msg:={report,R},meta:=#{report_cb:=Fun}}=Log,Config) ->
format(Log#{msg=>Fun(R)},Config);
format(#{msg:={string,String0}},no_nl) ->
String = unicode:characters_to_list(String0),
String;
format(#{msg:={string,String0}},nl) ->
String = unicode:characters_to_list(String0),
String++"\n";
format(#{msg:={string,String0}},op) ->
String = unicode:characters_to_list(String0),
String++"\n";
format(#{msg:={report,#{label:={supervisor,progress}}}},op) ->
"";
format(#{msg:={report,#{label:={gen_server,terminate}}}},op) ->
"";
format(#{msg:={report,#{label:={proc_lib,crash}}}},op) ->
"";
format(#{msg:={F,A}},OpOrPid) when is_list(F), is_list(A) ->
String = lists:flatten(io_lib:format(F,A)),
if is_pid(OpOrPid) -> OpOrPid ! {log,String};
true -> ok
end,
String++"\n";
format(#{msg:={string,String0}},Pid) ->
String = unicode:characters_to_list(String0),
Pid ! {log,String},
String++"\n";
format(Msg,Tag) ->
Error = {unexpected_format,Msg,Tag},
erlang:display(Error),
exit(Error).
remove(Handler, LogName) ->
logger_disk_log_h:remove(Handler, LogName),
HState = #{log_names := Logs} = logger_disk_log_h:info(),
false = maps:is_key(LogName, HState),
false = lists:member(LogName, Logs),
false = logger_config:exist(?LOGGER_TABLE, LogName),
{error,no_such_log} = disk_log:info(LogName),
ok.
start_and_add(Name, Config, LogOpts) ->
HConfig = maps:get(config, Config, #{}),
HConfig1 = maps:merge(HConfig, LogOpts),
Config1 = Config#{config=>HConfig1},
ct:pal("Adding handler ~w with: ~p", [Name,Config1]),
ok = logger:add_handler(Name, logger_disk_log_h, Config1),
Pid = whereis(h_proc_name(Name)),
true = is_pid(Pid),
Name = proplists:get_value(name, disk_log:info(Name)),
ok.
remove_and_stop(Handler) ->
ok = logger:remove_handler(Handler),
timer:sleep(500),
undefined = whereis(h_proc_name(Handler)),
ok.
try_read_file(FileName, Expected, Time) ->
try_read_file(FileName, Expected, Time, undefined).
try_read_file(FileName, Expected, Time, _) when Time > 0 ->
case file:read_file(FileName) of
Expected ->
ok;
Error = {error,_Reason} ->
erlang:error(Error);
SomethingElse ->
ct:pal("try_read_file read unexpected: ~p~n", [SomethingElse]),
timer:sleep(500),
try_read_file(FileName, Expected, Time-500, SomethingElse)
end;
try_read_file(_, _, _, Incorrect) ->
ct:pal("try_read_file got incorrect pattern: ~p~n", [Incorrect]),
erlang:error({error,not_matching_pattern,Incorrect}).
try_match_file(FileName, Pattern, Time) ->
try_match_file(FileName, Pattern, Time, <<>>).
try_match_file(FileName, Pattern, Time, _) when Time > 0 ->
case file:read_file(FileName) of
{ok, Bin} ->
case re:run(Bin,Pattern,[{capture,none}]) of
match ->
unicode:characters_to_list(Bin);
_ ->
timer:sleep(100),
try_match_file(FileName, Pattern, Time-100, Bin)
end;
Error ->
erlang:error(Error)
end;
try_match_file(_,Pattern,_,Incorrect) ->
ct:pal("try_match_file did not match pattern: ~p~nGot: ~p~n",
[Pattern,Incorrect]),
erlang:error({error,not_matching_pattern,Pattern,Incorrect}).
count_lines(File) ->
wait_until_written(File),
count_lines1(File).
wait_until_written(File) ->
wait_until_written(File, -1).
wait_until_written(File, Sz) ->
timer:sleep(2000),
case file:read_file_info(File) of
{ok,#file_info{size = Sz}} ->
timer:sleep(1000),
case file:read_file_info(File) of
{ok,#file_info{size = Sz1}} ->
ok;
{ok,#file_info{size = Sz2}} ->
wait_until_written(File, Sz2)
end;
{ok,#file_info{size = Sz1}} ->
wait_until_written(File, Sz1)
end.
count_lines1(File) ->
{_,Dev} = file:open(File, [read]),
Lines = count_lines2(Dev, 0),
file:close(Dev),
Lines.
count_lines2(Dev, LC) ->
case file:read_line(Dev) of
{ok,"Handler logger_disk_log_h_SUITE " ++_} ->
%% Not counting handler info
count_lines2(Dev,LC);
{ok,_} ->
count_lines2(Dev,LC+1);
eof -> LC
end.
repeat_until_ok(Fun, N) ->
repeat_until_ok(Fun, 0, N, undefined).
repeat_until_ok(_Fun, Stop, Stop, Reason) ->
{fails,Reason};
repeat_until_ok(Fun, C, Stop, FirstReason) ->
if C > 0 -> timer:sleep(5000);
true -> ok
end,
try Fun() of
Result ->
{ok,{C,Result}}
catch
_:Reason:Stack ->
ct:pal("Test fails: ~p (~p)~n", [Reason,hd(Stack)]),
if FirstReason == undefined ->
repeat_until_ok(Fun, C+1, Stop, {Reason,Stack});
true ->
repeat_until_ok(Fun, C+1, Stop, FirstReason)
end
end.
start_tracer(Trace,Expected) ->
Pid = self(),
dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
dbg:p(h_proc_name(),[c]),
tpl(Trace),
ok.
tpl([{M,F,A}|Trace]) ->
{ok,Match} = dbg:tpl(M,F,A,[]),
case lists:keyfind(matched,1,Match) of
{_,_,1} ->
ok;
_ ->
dbg:stop_clear(),
throw({skip,"Can't trace "++atom_to_list(M)++":"++
atom_to_list(F)++"/"++integer_to_list(A)})
end,
tpl(Trace);
tpl([]) ->
ok.
tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]}},
{Pid,[{Mod,Func,Op}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func,Op});
tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]}}, {Pid,[{Mod,Func,Data}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func,Data});
tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func});
tracer({trace,_,call,Call}, {Pid,Expected}) ->
ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]),
Pid ! {tracer_got_unexpected,Call,Expected},
{Pid,Expected}.
maybe_tracer_done(Pid,[],Got) ->
ct:log("Tracer got: ~p~n",[Got]),
Pid ! tracer_done;
maybe_tracer_done(Pid,Expected,Got) ->
ct:log("Tracer got: ~p~n",[Got]),
{Pid,Expected}.
check_tracer(T) ->
receive
tracer_done ->
dbg:stop_clear(),
ok;
{tracer_got_unexpected,Got,Expected} ->
dbg:stop_clear(),
ct:fail({tracer_got_unexpected,Got,Expected})
after T ->
dbg:stop_clear(),
ct:fail({timeout,tracer})
end.
escape([$+|Rest]) ->
[$\\,$+|escape(Rest)];
escape([H|T]) ->
[H|escape(T)];
escape([]) ->
[].
h_proc_name() ->
h_proc_name(?MODULE).
h_proc_name(Name) ->
list_to_atom(lists:concat([logger_disk_log_h,"_",Name])).
file_delete(Log) ->
file:delete(Log).