path: root/lib/kernel/test/logger_disk_log_h_SUITE.erl

%%
%% %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]}).

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 ->
    case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of
        true ->
            {skip,"Define the TEST_HOOKS macro to run this test"};
        false ->
            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 => infinity,
                         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 := infinity,
      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,

    SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of
                     true -> 5500;
                     false -> ?FILESYNC_REPEAT_INTERVAL + 500
                 end,

    try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt),

    rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]),
    ok = log_on_remote_node(Node, "Cause simple error printout"),

    ?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">>}, SyncRepInt),
    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 = 4,
    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,
            file_delete(Log),
            {ok,_} = wait_for_process_up(RestartAfter * 3),
            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 = 4,
    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,
            file_delete(Log),
            {ok,_} = wait_for_process_up(RestartAfter * 3),
            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() ->
    [{timetrap,{minutes,2}}].
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=>infinity}},
    ok = logger:set_handler_config(?MODULE, NewHConfig1),
    MRef1 = erlang:monitor(process, whereis(h_proc_name())),
    %% kill handler
    send_burst({n,100}, {spawn,4,0}, {chars,79}, notice),
    receive
        {'DOWN', MRef1, _, _, _Reason1} ->
            file_delete(Log),
            error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3),
            ok
    after
        5000 ->
            Info1 = logger_std_h:info(?MODULE),
            ct:pal("Handler state = ~p", [Info1]),
            ct:fail("Handler not dead! It should not have survived this!")
    end,
    
    {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,4,0}, {chars,79}, notice),
    receive
        {'DOWN', MRef2, _, _, _Reason2} ->
            file_delete(Log),
            {ok,Pid1} = wait_for_process_up(RestartAfter * 3),
            false = (Pid1 == Pid0),
            ok
    after
        5000 ->
            Info2 = logger_std_h:info(?MODULE),
            ct:pal("Handler state = ~p", [Info2]),
            ct:fail("Handler not dead! It should not have survived this!")
    end,
    ok.
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]),
    MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end,
                   monitor(process,spawn_link(per_proc_fun(N,Text,Class,X)))
             end || X <- 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.

per_proc_fun(N,Text,Class,X) when X rem 2 == 0 ->
    fun() ->
            process_flag(priority,high),
            send_n_burst(N, seq, Text, Class)
    end;
per_proc_fun(N,Text,Class,_) ->
    fun() ->
            send_n_burst(N, seq, Text, Class)
    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 = Sz}} ->
                    ok;
                {ok,#file_info{size = Sz1}} ->
                    wait_until_written(File, Sz1)
            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])).

wait_for_process_up(T) ->
    wait_for_process_up(?MODULE, h_proc_name(), T).

wait_for_process_up(Name, RegName, T) ->
    N = (T div 500) + 1,
    wait_for_process_up1(Name, RegName, N).

wait_for_process_up1(_Name, _RegName, 0) ->
    error;
wait_for_process_up1(Name, RegName, N) ->
    timer:sleep(500),
    case whereis(RegName) of
        Pid when is_pid(Pid) ->
            case logger:get_handler_config(Name) of
                {ok,_} ->
                    %% ct:pal("Process ~p up (~p tries left)",[Name,N]),
                    {ok,Pid};
                _ ->
                    wait_for_process_up1(Name, RegName, N-1)
            end;
        undefined ->
            %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]),
            wait_for_process_up1(Name, RegName, N-1)
    end.

file_delete(Log) ->
   file:delete(Log).