aboutsummaryrefslogblamecommitdiffstats
path: root/lib/kernel/test/logger_disk_log_h_SUITE.erl
blob: 7a1736c8148d199faabee3ae4e1c68f2b33e544d (plain) (tree)
































                                                                    

                                   






































































































































































































































































































                                                                                 

                                  





                                                 
                                                                                  



                                                                           
                                                                                          




                                                                   
                                                                                          




                                                                        
                                                                     



                                                           

                                  











                                                                              




                                                                             
                                                     
                                                                         
                                                                              



                                                                           



























































































































                                                                              
                                    
                                     
                                                





                                              
                                    
                                     

                                                 















                                                                        
                                    
                                     

                                                 



























                                                                               
                     
























































                                                                              
                     












































                                                                                  
                     












































                                                                           
                     







                                              
                                             








































                                                                             
 
 
                                             






































                                                                             





                                                                 











                                                                              



                                    















                                                                             
                    
                


                                                                                   

                                                                               
                                                     



                             


                                      

                               
                            




































                                                                                      
                                      
                               

                       
                             
                             







                                                                   
    




































                                                                                
                                       
                               















































































                                                                                
                                                                              

                                          
                                          



















                                                                              
                                             











                                                                          
                                                                              

                                          
                                          



















                                                                              
                                             































                                                                              
                                          










                                                                                     
                                             















                                                                          
                             



























                                                                                  
                                                































































































































































































































                                                                             






















                                                                    



                                                      
















                                                                 

                                                             
                                                  

                                                                                             


                                                                   
                                                                        


















                                                         
                             

                                     






                          
-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,
     disk_log_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(?MODULE)),
    ok = logger:remove_handler(?MODULE),
    timer:sleep(500),
    undefined = whereis(?MODULE).
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:info("hello", ?domain),
    logger_disk_log_h:disk_log_sync(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:info("dummy", ?domain),
    logger_disk_log_h:disk_log_sync(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:info("one", ?domain),
    logger_disk_log_h:disk_log_sync(HName),
    ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]),
    try_read_file(?log_no(LogFile1,1), {ok,<<"one\n">>}, 5000),
    logger:info("two", ?domain),
    ok = remove_and_stop(HName),
    try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\n">>}, 5000),

    logger:info("two and a half", ?domain),

    ok = start_and_add(HName, #{filter_default=>stop,
                                filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
                                formatter=>{?MODULE,self()}},
                       #{file=>LogFile1}),
    logger:info("three", ?domain),
    logger_disk_log_h:disk_log_sync(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:info("123", ?domain),
    logger_disk_log_h:disk_log_sync(WName),
    timer:sleep(500),
    1 = Get(current_file, disk_log:info(WName)),

    logger:info("45", ?domain),
    logger_disk_log_h:disk_log_sync(WName),
    timer:sleep(500),
    1 = Get(current_file, disk_log:info(WName)),

    logger:info("6", ?domain),
    logger_disk_log_h:disk_log_sync(WName),
    timer:sleep(500),
    2 = Get(current_file, disk_log:info(WName)),

    logger:info("7890", ?domain),
    logger_disk_log_h:disk_log_sync(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:info("12345", ?domain),
    logger_disk_log_h:disk_log_sync(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)),
    HConfig = #{disk_log_opts => #{file=>LogFile},
                filter_default=>log},
    ct:pal("Log: ~p", [LogFile]),
    ok = logger:add_handler(?MODULE, logger_disk_log_h, HConfig),
    ok = logger:set_handler_config(?MODULE,formatter,
                                   {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}),
    LogName = lists:concat([LogFile, ".1"]),
    logger:info("dummy"),
    wait_until_written(LogName),
    {ok,Bin} = file:read_file(LogName),
    match = re:run(Bin, "=INFO 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:info([{x,y}], #{report_cb => MsgFormatter}),
    logger:info([{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),
    HConfig = #{disk_log_opts=>#{file=>LogFile1},
                filter_default=>log,
                formatter=>{?MODULE,self()}},
    ok = logger:add_handler(Name1, logger_disk_log_h, HConfig),
    {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,
                                  disk_log_opts,
                                  #{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]),
    HConfig = #{disk_log_opts => #{file=>LogFile},
                filter_default=>stop,
                filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])},
    %% no formatter!
    logger:add_handler(Name, logger_disk_log_h, HConfig),
    Pid = whereis(Name),
    true = is_pid(Pid),
    #{handlers:=HC1} = logger:i(),
    H = [Id || {Id,_,_} <- HC1],
    true = lists:member(Name,H),

    %% Formatter is added automatically
    {ok,{_,#{formatter:={logger_formatter,_}}}} =
        logger:get_handler_config(Name),
    logger:info(M1=?msg,?domain),
    Got1 = try_match_file(?log_no(LogFile,1),"[0-9\\+\\-T:\\.]* info: "++M1,5000),

    ok = logger:set_handler_config(Name,formatter,{nonexistingmodule,#{}}),
    logger:info(M2=?msg,?domain),
    Got2 = try_match_file(?log_no(LogFile,1),
                          escape(Got1)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M2,
                          5000),

    ok = logger:set_handler_config(Name,formatter,{?MODULE,crash}),
    logger:info(M3=?msg,?domain),
    Got3 = try_match_file(?log_no(LogFile,1),
                          escape(Got2)++"[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*"++M3,
                          5000),

    ok = logger:set_handler_config(Name,formatter,{?MODULE,bad_return}),
    logger:info(?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(Name),
    #{handlers:=HC2} = logger:i(),
    H = [Id || {Id,_,_} <- HC2],
    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,
                           #{logger_disk_log_h => #{bad => bad},
                             filter_default=>log,
                             formatter=>{?MODULE,self()}}),

    {error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
        logger:add_handler(?MODULE,logger_disk_log_h,
                           #{logger_disk_log_h => #{drop_new_reqs_qlen=>1}}),
    {error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
        logger:add_handler(?MODULE,logger_disk_log_h,
                           #{logger_disk_log_h => #{toggle_sync_qlen=>43,
                                                    drop_new_reqs_qlen=>42}}),
    {error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
        logger:add_handler(?MODULE,logger_disk_log_h,
                           #{logger_disk_log_h => #{drop_new_reqs_qlen=>43,
                                                    flush_reqs_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,disk_log_opts,
                                  #{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  
    {error,{invalid_levels,_}} =
        logger:set_handler_config(?MODULE,logger_disk_log_h,
                                  #{toggle_sync_qlen=>100,
                                    flush_reqs_qlen=>99}),
    %% invalid name of config parameter
    {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} =
        logger:set_handler_config(?MODULE, logger_disk_log_h,
                                  #{filesync_rep_int => 2000}),
    ok.
config_fail(cleanup,_Config) ->
    logger:remove_handler(?MODULE).

bad_input(_Config) ->
    {error,{badarg,{disk_log_sync,["BadType"]}}} =
        logger_disk_log_h:disk_log_sync("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,
      toggle_sync_qlen := ?TOGGLE_SYNC_QLEN,
      drop_new_reqs_qlen := ?DROP_NEW_REQS_QLEN,
      flush_reqs_qlen := ?FLUSH_REQS_QLEN,
      enable_burst_limit := ?ENABLE_BURST_LIMIT,
      burst_limit_size := ?BURST_LIMIT_SIZE,
      burst_window_time := ?BURST_WINDOW_TIME,
      enable_kill_overloaded := ?ENABLE_KILL_OVERLOADED,
      handler_overloaded_qlen := ?HANDLER_OVERLOADED_QLEN,
      handler_overloaded_mem := ?HANDLER_OVERLOADED_MEM,
      handler_restart_after := ?HANDLER_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 = logger:set_handler_config(?MODULE, logger_disk_log_h,
                                   #{toggle_sync_qlen => 1,
                                     drop_new_reqs_qlen => 2,
                                     flush_reqs_qlen => 3,
                                     enable_burst_limit => false,
                                     burst_limit_size => 10,
                                     burst_window_time => 10,
                                     enable_kill_overloaded => true,
                                     handler_overloaded_qlen => 100000,
                                     handler_overloaded_mem => 10000000,
                                     handler_restart_after => never,
                                     filesync_repeat_interval => no_repeat}),
    #{id := ?MODULE,
      toggle_sync_qlen := 1,
      drop_new_reqs_qlen := 2,
      flush_reqs_qlen := 3,
      enable_burst_limit := false,
      burst_limit_size := 10,
      burst_window_time := 10,
      enable_kill_overloaded := true,
      handler_overloaded_qlen := 100000,
      handler_overloaded_mem := 10000000,
      handler_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()},
                              disk_log_opts=>
                                  #{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).

disk_log_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,
                            #{disk_log_opts => #{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:info("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:info("second", ?domain),
    logger:info("third", ?domain),
    %% do explicit disk_log_sync
    logger_disk_log_h:disk_log_sync(?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
    logger:set_handler_config(?MODULE, logger_disk_log_h,
                              #{filesync_repeat_interval => no_repeat}),
    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:info("fourth", ?domain),
    timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
    logger:info("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))]),

    logger:set_handler_config(?MODULE, logger_disk_log_h,
                              #{filesync_repeat_interval => SyncInt}),
    SyncInt = maps:get(filesync_repeat_interval,
                       logger_disk_log_h:info(?MODULE)),
    timer:sleep(WaitT),
    logger:set_handler_config(?MODULE, logger_disk_log_h,
                              #{filesync_repeat_interval => no_repeat}),    
    check_tracer(100),
    ok.
disk_log_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()},
                              disk_log_opts=>
                                  #{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(?MODULE), [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:info(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()},
                              disk_log_opts=>
                                  #{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(?MODULE), [c]),
    {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),

    NoOfChars = 5,
    Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)],
    [logger:info(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(?MODULE), [c]),
    {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []),
    
    [whereis(?MODULE) ! 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, disk_log_sync, [?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, disk_log_sync, [?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, logger_disk_log_h,
                   #{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,sync,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,sync,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,
                     #{ disk_log_opts => #{ 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:info(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#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2,
                                                 drop_new_reqs_qlen => NumOfReqs+1,
                                                 flush_reqs_qlen => 2*NumOfReqs,
                                                 enable_burst_limit => false}},
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    Lines = count_lines(Log),
    ok = file:delete(Log),
    NumOfReqs = Lines,
    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#{logger_disk_log_h =>
                                 DLHConfig#{toggle_sync_qlen => 1,
                                            drop_new_reqs_qlen => 2,
                                            flush_reqs_qlen => Procs*NumOfReqs*Bursts,
                                            enable_burst_limit => 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}, info) ||
                    _ <- 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),
                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#{logger_disk_log_h =>
                                 DLHConfig#{toggle_sync_qlen => 2,
                                            %% disable drop mode
                                            drop_new_reqs_qlen => 300,
                                            flush_reqs_qlen => 300,
                                            enable_burst_limit => 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}, info) ||
                    _ <- 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),
                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#{logger_disk_log_h => DLHConfig#{enable_burst_limit => false,
                                                 burst_limit_size => 10,
                                                 burst_window_time => 2000,
                                                 drop_new_reqs_qlen => 200,
                                                 flush_reqs_qlen => 300}},
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    NumOfReqs = 100,
    send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    Logged = count_lines(Log),
    ct:pal("Number of messages logged = ~w", [Logged]),
    ok = file:delete(Log),
    NumOfReqs = Logged.
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#{logger_disk_log_h => DLHConfig#{enable_burst_limit => true,
                                                 burst_limit_size => ReqLimit,
                                                 burst_window_time => 2000,
                                                 drop_new_reqs_qlen => 200,
                                                 flush_reqs_qlen => 300}},
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    NumOfReqs = 100,
    send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    Logged = count_lines(Log),
    ct:pal("Number of messages logged = ~w", [Logged]),
    ok = file:delete(Log),
    ReqLimit = Logged.
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#{logger_disk_log_h => DLHConfig#{enable_burst_limit => true,
                                                 burst_limit_size => ReqLimit,
                                                 burst_window_time => BurstTWin,
                                                 drop_new_reqs_qlen => 20000,
                                                 flush_reqs_qlen => 20001}},
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    
    Windows = 3,
    Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, info),
    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))).
limit_burst_enabled_period(cleanup, _Config) ->
    ok = stop_handler(?MODULE).

kill_disabled(Config) ->
    {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
    NewHConfig =
        HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>false,
                                               handler_overloaded_qlen=>10,
                                               handler_overloaded_mem=>100}},
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    NumOfReqs = 100,
    send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    Logged = count_lines(Log),
    ct:pal("Number of messages logged = ~w", [Logged]),
    ok = file:delete(Log),
    true = is_pid(whereis(?MODULE)),
    ok.
kill_disabled(cleanup, _Config) ->
    ok = stop_handler(?MODULE).

qlen_kill_new(Config) ->
    {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
    Pid0 = whereis(?MODULE),
    {_,Mem0} = process_info(Pid0, memory),
    RestartAfter = ?HANDLER_RESTART_AFTER,
    NewHConfig =
        HConfig#{logger_disk_log_h =>
                     DLHConfig#{enable_kill_overloaded=>true,
                                handler_overloaded_qlen=>10,
                                handler_overloaded_mem=>Mem0+50000,
                                handler_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}, info),
    %% send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    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(?MODULE)),
            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(?MODULE),
    {_,Mem0} = process_info(Pid0, memory),
    RestartAfter = ?HANDLER_RESTART_AFTER,
    NewHConfig =
        HConfig#{logger_disk_log_h =>
                     DLHConfig#{enable_kill_overloaded=>true,
                                handler_overloaded_qlen=>50000,
                                handler_overloaded_mem=>Mem0+500,
                                handler_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}, info),
    %% send_burst({n,NumOfReqs}, seq, {chars,79}, info),
    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(?MODULE)),
            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#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true,
                                               handler_overloaded_qlen=>10,
                                               handler_restart_after=>never}},
    ok = logger:set_handler_config(?MODULE, NewHConfig1),
    MRef1 = erlang:monitor(process, whereis(?MODULE)),
    %% kill handler
    send_burst({n,100}, {spawn,2,0}, {chars,79}, info),
    receive
        {'DOWN', MRef1, _, _, _Info1} ->
            timer:sleep(?HANDLER_RESTART_AFTER + 1000),
            undefined = whereis(?MODULE),
            ok
    after
        5000 ->
            ct:fail("Handler not dead! It should not have survived this!")
    end,
    
    {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
    RestartAfter = ?HANDLER_RESTART_AFTER,
    NewHConfig2 =
        HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true,
                                               handler_overloaded_qlen=>10,
                                               handler_restart_after=>RestartAfter}},
    ok = logger:set_handler_config(?MODULE, NewHConfig2),
    Pid0 = whereis(?MODULE),
    MRef2 = erlang:monitor(process, Pid0),
    %% kill handler
    send_burst({n,100}, {spawn,2,0}, {chars,79}, info),
    receive
        {'DOWN', MRef2, _, _, _Info2} ->
            timer:sleep(RestartAfter + 2000),
            Pid1 = whereis(?MODULE),
            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 (filesync, 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#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2,
                                                 drop_new_reqs_qlen => 1000,
                                                 flush_reqs_qlen => 2000,
                                                 enable_burst_limit => false}},   
    ok = logger:set_handler_config(?MODULE, NewHConfig),
    Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{disk_log_sync,[]},
                                                         {info,[]},
                                                         {reset,[]},
                                                         {change_config,[]}])
                     end),
    Procs = 100,
    Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, info),
    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,
                                                  #{enable_kill_overloaded =>
                                                        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]),
    ok = logger:add_handler(Name,
                            logger_disk_log_h,
                            #{disk_log_opts=>#{file => File,
                                               max_no_files => 1,
                                               max_no_bytes => 100000000},
                              filter_default=>log,
                              filters=>?DEFAULT_HANDLER_FILTERS([Name]),
                              formatter=>{?MODULE,op}}),
    {ok,{_,HConfig = #{logger_disk_log_h := DLHConfig}}} =
        logger:get_handler_config(Name),
    {lists:concat([File,".1"]),HConfig,DLHConfig}.
    
stop_handler(Name) ->
    ok = logger:remove_handler(Name),
    ct:pal("Handler ~p stopped!", [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() -> 
                      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}},Pid) when is_list(F), is_list(A) ->
    String = lists:flatten(io_lib:format(F,A)),
    Pid ! {log,String},
    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, LogName),
    {error,no_such_log} = disk_log:info(LogName),
    ok.

start_and_add(Name, Config, LogOpts) ->
    ct:pal("Adding handler ~w with: ~p",
           [Name,Config#{disk_log_opts=>LogOpts}]),
    ok = logger:add_handler(Name, logger_disk_log_h,
                            Config#{disk_log_opts=>LogOpts}),
    Pid = whereis(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(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) ->
    Counter = fun Cnt(Dev,LC) ->
                      case file:read_line(Dev) of
                          eof -> LC;
                          _   -> Cnt(Dev,LC+1)
                      end
              end,
    {_,Dev} = file:open(File, [read]),
    Lines = Counter(Dev, 0),
    file:close(Dev),
    Lines.

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(whereis(?MODULE),[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([]) ->
    [].