diff options
Diffstat (limited to 'lib/kernel/test')
| -rw-r--r-- | lib/kernel/test/application_SUITE.erl | 97 | ||||
| -rw-r--r-- | lib/kernel/test/inet_SUITE.erl | 31 | ||||
| -rw-r--r-- | lib/kernel/test/kernel.spec | 1 | ||||
| -rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 18 | ||||
| -rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 2 | ||||
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 428 | ||||
| -rw-r--r-- | lib/kernel/test/logger_stress_SUITE.erl | 94 |
7 files changed, 638 insertions, 33 deletions
diff --git a/lib/kernel/test/application_SUITE.erl b/lib/kernel/test/application_SUITE.erl index 5c35b82207..94d7c17712 100644 --- a/lib/kernel/test/application_SUITE.erl +++ b/lib/kernel/test/application_SUITE.erl @@ -31,6 +31,7 @@ otp_3002/1, otp_3184/1, otp_4066/1, otp_4227/1, otp_5363/1, otp_5606/1, start_phases/1, get_key/1, get_env/1, + set_env/1, set_env_persistent/1, set_env_errors/1, permit_false_start_local/1, permit_false_start_dist/1, script_start/1, nodedown_start/1, init2973/0, loop2973/0, loop5606/1]). @@ -55,6 +56,7 @@ all() -> load_use_cache, ensure_started, {group, reported_bugs}, start_phases, script_start, nodedown_start, permit_false_start_local, permit_false_start_dist, get_key, get_env, ensure_all_started, + set_env, set_env_persistent, set_env_errors, {group, distr_changed}, config_change, shutdown_func, shutdown_timeout, shutdown_deadlock, config_relative_paths, persistent_env]. @@ -1944,6 +1946,101 @@ get_appls([_ | T], Res) -> get_appls([], Res) -> Res. +%% Test set_env/1. +set_env(Conf) when is_list(Conf) -> + ok = application:set_env([{appinc, [{own2, persist}, {not_in_app, persist}]}, + {unknown_app, [{key, persist}]}]), + + %% own_env1 and own2 are set in appinc + undefined = application:get_env(appinc, own_env1), + {ok, persist} = application:get_env(appinc, own2), + {ok, persist} = application:get_env(appinc, not_in_app), + {ok, persist} = application:get_env(unknown_app, key), + + ok = application:load(appinc()), + {ok, value1} = application:get_env(appinc, own_env1), + {ok, val2} = application:get_env(appinc, own2), + {ok, persist} = application:get_env(appinc, not_in_app), + {ok, persist} = application:get_env(unknown_app, key), + + %% On reload, values are lost + ok = application:unload(appinc), + ok = application:load(appinc()), + {ok, value1} = application:get_env(appinc, own_env1), + {ok, val2} = application:get_env(appinc, own2), + undefined = application:get_env(appinc, not_in_app), + + %% Clean up + ok = application:unload(appinc). + +%% Test set_env/2 with persistent true. +set_env_persistent(Conf) when is_list(Conf) -> + Opts = [{persistent, true}], + ok = application:set_env([{appinc, [{own2, persist}, {not_in_app, persist}]}, + {unknown_app, [{key, persist}]}], Opts), + + %% own_env1 and own2 are set in appinc + undefined = application:get_env(appinc, own_env1), + {ok, persist} = application:get_env(appinc, own2), + {ok, persist} = application:get_env(appinc, not_in_app), + {ok, persist} = application:get_env(unknown_app, key), + + ok = application:load(appinc()), + {ok, value1} = application:get_env(appinc, own_env1), + {ok, persist} = application:get_env(appinc, own2), + {ok, persist} = application:get_env(appinc, not_in_app), + {ok, persist} = application:get_env(unknown_app, key), + + %% On reload, values are not lost + ok = application:unload(appinc), + ok = application:load(appinc()), + {ok, value1} = application:get_env(appinc, own_env1), + {ok, persist} = application:get_env(appinc, own2), + {ok, persist} = application:get_env(appinc, not_in_app), + + %% Clean up + ok = application:unload(appinc). + +set_env_errors(Conf) when is_list(Conf) -> + "application: 1; application name must be an atom" = + badarg_msg(fun() -> application:set_env([{1, []}]) end), + + "application: foo; parameters must be a list" = + badarg_msg(fun() -> application:set_env([{foo, bar}]) end), + + "invalid application config: foo_bar" = + badarg_msg(fun() -> application:set_env([foo_bar]) end), + + "application: foo; invalid parameter name: 1" = + badarg_msg(fun() -> application:set_env([{foo, [{1, 2}]}]) end), + + "application: foo; invalid parameter: config" = + badarg_msg(fun() -> application:set_env([{foo, [config]}]) end), + + "application: kernel; erroneous parameter: distributed" = + badarg_msg(fun() -> application:set_env([{kernel, [{distributed, config}]}]) end), + + %% This will raise in the future + ct:capture_start(), + _ = application:set_env([{foo, []}, {foo, []}]), + timer:sleep(100), + ct:capture_stop(), + [_ | _] = string:find(ct:capture_get(), "duplicate application config: foo"), + + ct:capture_start(), + _ = application:set_env([{foo, [{bar, baz}, {bar, bat}]}]), + timer:sleep(100), + ct:capture_stop(), + [_ | _] = string:find(ct:capture_get(), "application: foo; duplicate parameter: bar"), + + ok. + +badarg_msg(Fun) -> + try Fun() of + _ -> ct:fail(try_succeeded) + catch + error:{badarg, Msg} -> Msg + end. %% Test set_env/4 and unset_env/3 with persistent true. persistent_env(Conf) when is_list(Conf) -> diff --git a/lib/kernel/test/inet_SUITE.erl b/lib/kernel/test/inet_SUITE.erl index 8b33f4a679..44ec7e7076 100644 --- a/lib/kernel/test/inet_SUITE.erl +++ b/lib/kernel/test/inet_SUITE.erl @@ -21,6 +21,7 @@ -include_lib("common_test/include/ct.hrl"). -include_lib("kernel/include/inet.hrl"). +-include_lib("kernel/src/inet_res.hrl"). -include_lib("kernel/src/inet_dns.hrl"). -export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, @@ -34,7 +35,7 @@ ipv4_to_ipv6/0, ipv4_to_ipv6/1, host_and_addr/0, host_and_addr/1, t_gethostnative/1, - gethostnative_parallell/1, cname_loop/1, + gethostnative_parallell/1, cname_loop/1, missing_hosts_reload/1, gethostnative_soft_restart/0, gethostnative_soft_restart/1, gethostnative_debug_level/0, gethostnative_debug_level/1, lookup_bad_search_option/1, @@ -56,7 +57,7 @@ all() -> [t_gethostbyaddr, t_gethostbyname, t_getaddr, t_gethostbyaddr_v6, t_gethostbyname_v6, t_getaddr_v6, ipv4_to_ipv6, host_and_addr, {group, parse}, - t_gethostnative, gethostnative_parallell, cname_loop, + t_gethostnative, gethostnative_parallell, cname_loop, missing_hosts_reload, gethostnative_debug_level, gethostnative_soft_restart, lookup_bad_search_option, getif, getif_ifr_name_overflow, getservbyname_overflow, @@ -840,6 +841,32 @@ cname_loop(Config) when is_list(Config) -> ok. +%% Test that hosts file gets reloaded correctly in case when it +% was missing during initial startup +missing_hosts_reload(Config) when is_list(Config) -> + RootDir = proplists:get_value(priv_dir,Config), + HostsFile = filename:join(RootDir, atom_to_list(?MODULE) ++ ".hosts"), + InetRc = filename:join(RootDir, "inetrc"), + ok = file:write_file(InetRc, "{hosts_file, \"" ++ HostsFile ++ "\"}.\n"), + {error, enoent} = file:read_file_info(HostsFile), + % start a node + Pa = filename:dirname(code:which(?MODULE)), + {ok, TestNode} = test_server:start_node(?MODULE, slave, + [{args, "-pa " ++ Pa ++ " -kernel inetrc '\"" ++ InetRc ++ "\"'"}]), + % ensure it has our RC + Rc = rpc:call(TestNode, inet_db, get_rc, []), + {hosts_file, HostsFile} = lists:keyfind(hosts_file, 1, Rc), + % ensure it does not resolve + {error, nxdomain} = rpc:call(TestNode, inet_hosts, gethostbyname, ["somehost"]), + % write hosts file + ok = file:write_file(HostsFile, "1.2.3.4 somehost"), + % wait for cached timestamp to expire + timer:sleep(?RES_FILE_UPDATE_TM * 1000 + 100), + % ensure it DOES resolve + {ok,{hostent,"somehost",[],inet,4,[{1,2,3,4}]}} = + rpc:call(TestNode, inet_hosts, gethostbyname, ["somehost"]), + % cleanup + true = test_server:stop_node(TestNode). %% These must be run in the whole suite since they need %% the host list and require inet_gethost_native to be started. diff --git a/lib/kernel/test/kernel.spec b/lib/kernel/test/kernel.spec index 62afc9f97b..eaa17f3a59 100644 --- a/lib/kernel/test/kernel.spec +++ b/lib/kernel/test/kernel.spec @@ -2,3 +2,4 @@ {config, "../test_server/ts.unix.config"}. {suites,"../kernel_test", all}. +{skip_suites,"../kernel_test",[logger_stress_SUITE],"Benchmarks only"}. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 2dad651f9c..035e5d8974 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -899,14 +899,14 @@ process_metadata(_Config) -> undefined = logger:get_process_metadata(), {error,badarg} = ?TRY(logger:set_process_metadata(bad)), ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}), - Time = erlang:system_time(microsecond), + Time = logger:timestamp(), ProcMeta = #{time=>Time,line=>0,custom=>proc}, ok = logger:set_process_metadata(ProcMeta), S1 = ?str, ?LOG_NOTICE(S1,#{custom=>macro}), check_logged(notice,S1,#{time=>Time,line=>0,custom=>macro}), - Time2 = erlang:system_time(microsecond), + Time2 = logger:timestamp(), S2 = ?str, ?LOG_NOTICE(S2,#{time=>Time2,line=>1,custom=>macro}), check_logged(notice,S2,#{time=>Time2,line=>1,custom=>macro}), @@ -1048,8 +1048,11 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + [append,delayed_write,raw] = lists:sort(Modes), + %% Same, but using 'logger' parameter instead of 'error_logger' ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again @@ -1060,26 +1063,27 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with type={file,File,Modes} ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], + M = [raw,write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_std_h, #{config=>#{type=>{file,F,M}}}}]]), ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,M}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=[delayed_write|M]}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with disk_log handler ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_disk_log_h, #{config=>#{file=>F}}}]]), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 8c13f0f908..83e3e6c40a 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -867,7 +867,7 @@ my_try(Fun) -> try Fun() catch C:R:S -> {C,R,hd(S)} end. timestamp() -> - erlang:system_time(microsecond). + logger:timestamp(). %% necessary? add_time(#{time:=_}=Meta) -> diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index b2c2c8ba67..0c5516f82b 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -112,6 +112,8 @@ all() -> add_remove_instance_standard_error, add_remove_instance_file1, add_remove_instance_file2, + add_remove_instance_file3, + add_remove_instance_file4, default_formatter, filter_config, errors, @@ -142,7 +144,12 @@ all() -> restart_after, handler_requests_under_load, recreate_deleted_log, - reopen_changed_log + reopen_changed_log, + rotate_size, + rotate_size_compressed, + rotate_size_reopen, + rotation_opts, + rotation_opts_restart_handler ]. add_remove_instance_tty(_Config) -> @@ -179,10 +186,27 @@ add_remove_instance_file2(Config) -> add_remove_instance_file2(cleanup,_Config) -> logger_std_h_remove(). -add_remove_instance_file(Log, Type) -> +add_remove_instance_file3(_Config) -> + Log = atom_to_list(?MODULE), + StdHConfig = #{type=>file}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file3(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file4(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog4.txt"), + StdHConfig = #{file=>Log,modes=>[]}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file4(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file(Log, Type) when not is_map(Type) -> + add_remove_instance_file(Log,#{type=>Type}); +add_remove_instance_file(Log, StdHConfig) when is_map(StdHConfig) -> ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => StdHConfig, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), @@ -257,9 +281,10 @@ errors(Config) -> end, {error, - {handler_not_added,{open_failed,Log,_}}} = + {handler_not_added, + {invalid_config,logger_std_h,#{modes:=bad_file_opt}}}} = logger:add_handler(myh3,logger_std_h, - #{config=>#{type=>{file,Log,[bad_file_opt]}}}), + #{config=>#{type=>{file,Log,bad_file_opt}}}), ok = logger:notice(?msg). @@ -607,24 +632,51 @@ reconfig(cleanup, _Config) -> file_opts(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), - BadFileOpts = [raw], - BadType = {file,Log,BadFileOpts}, - {error,{handler_not_added,{open_failed,Log,enoent}}} = - logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => BadType}}), + MissingOpts = [raw], + Type1 = {file,Log,MissingOpts}, + ok = logger:add_handler(?MODULE, logger_std_h, + #{config => #{type => Type1}}), + {ok,#{config:=#{type:=file,file:=Log,modes:=Modes1}}} = + logger:get_handler_config(?MODULE), + [append,delayed_write,raw] = lists:sort(Modes1), + ok = logger:remove_handler(?MODULE), OkFileOpts = [raw,append], OkType = {file,Log,OkFileOpts}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => OkType}, + #{config => #{type => OkType}, % old format filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{cb_state := #{handler_state := #{type := OkType}}} = + ModOpts = [delayed_write|OkFileOpts], + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger_olp:info(h_proc_name()), - {ok,#{config := #{type := OkType}}} = logger:get_handler_config(?MODULE), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => file, + file => Log, + modes => OkFileOpts}, % new format + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger:get_handler_config(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -640,13 +692,14 @@ sync(Config) -> Type = {file,Log}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => #{type => Type, + file_check => 10000}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), %% check repeated filesync happens - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, {file,datasync}]), @@ -656,7 +709,7 @@ sync(Config) -> check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, {file,datasync}, @@ -675,7 +728,7 @@ sync(Config) -> #{filesync_repeat_interval => no_repeat}), no_repeat = maps:get(filesync_repeat_interval, maps:get(cb_state, logger_olp:info(h_proc_name()))), - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, {file,datasync}, @@ -1285,6 +1338,331 @@ reopen_changed_log(Config) -> reopen_changed_log(cleanup, _Config) -> ok = stop_handler(?MODULE). +rotate_size(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".1"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1005}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + ok. +rotate_size(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_compressed(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + #{config=>#{max_no_bytes=>1000, + max_no_files=>2, + compress_on_rotate=>true}}), + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".0.gz"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".1.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=38}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + ok. +rotate_size_compressed(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_reopen(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + {ok,HConfig} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler(?MODULE,maps:get(module,HConfig),HConfig), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=580}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + ok. +rotate_size_reopen(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts(Config) -> + {Log,_HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + #{max_no_bytes:=infinity, + max_no_files:=0, + compress_on_rotate:=false} = StdHConfig, + + %% Test bad rotation config + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_bytes=>0}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_files=>infinity}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config, + #{compress_on_rotate=>undefined}), + + + %% Test good rotation config - start with no rotation + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=200}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Turn on rotation, check that existing file is rotated since its + %% size exceeds max_no_bytes + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0 = Log++".0", + {ok,#file_info{size=200}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Extend size and count and check that nothing changes with existing files + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>200, + max_no_files=>3}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Add more log events and see that extended size and count works + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".2"), + [_,_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and check that archive files that exceed the new + %% count are moved + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Extend size and count again, and turn on compression. Check + %% that archives are compressed + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2, + compress_on_rotate=>true}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0gz = Log0++".gz", + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + [Log0gz] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + {ok,#file_info{size=29}} = file:read_file_info(Log++".1.gz"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and turn off compression. Check that archives that + %% exceeds the new count are removed, and the rest are + %% uncompressed. + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1, + compress_on_rotate=>false}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Check that config and handler state agree on the current rotation settings + {ok,#{config:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger:get_handler_config(?MODULE), + #{cb_state:=#{handler_state:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger_olp:info(h_proc_name()), + ok. +rotation_opts(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts_restart_handler(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + + %% Fill all logs + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,15)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=60}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off rotation. Check that archives are removed. + {ok,#{config:=StdHConfig1}=HConfig1} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig1#{config=>StdHConfig1#{max_no_bytes=>infinity}}), + timer:sleep(100), + {ok,#file_info{size=60}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Add some log events and check that file is no longer rotated. + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=260}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and trun on rotation. Check that file is rotated. + {ok,#{config:=StdHConfig2}=HConfig2} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig2#{config=>StdHConfig2#{max_no_bytes=>100, + max_no_files=>2}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=260}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=80}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=260}} = file:read_file_info(Log++".1"), + + %% Stop/start handler, reduce count and turn on compression. Check + %% that excess archives are removed, and the rest compressed. + {ok,#{config:=StdHConfig3}=HConfig3} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig3#{config=>StdHConfig3#{max_no_bytes=>75, + max_no_files=>1, + compress_on_rotate=>true}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log++".0.gz"), + [_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off compression. Check that achives + %% are decompressed. + {ok,#{config:=StdHConfig4}=HConfig4} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig4#{config=>StdHConfig4#{compress_on_rotate=>false}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=80}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + ok. +rotation_opts_restart_handler(cleanup,_Config) -> + ok = stop_handler(?MODULE). + %%%----------------------------------------------------------------- %%% send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> @@ -1305,8 +1683,8 @@ start_handler(Name, TTY, _Config) when TTY == standard_io; ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {HConfig,StdHConfig}; @@ -1320,12 +1698,17 @@ start_handler(Name, FuncName, Config) -> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => Type}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {Log,HConfig,StdHConfig}. + +filter_only_this_domain(Name) -> + [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, + {domain,{fun logger_filters:domain/2,{log,super,[Name]}}}]. + stop_handler(Name) -> R = logger:remove_handler(Name), ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), @@ -1658,7 +2041,7 @@ tpl([]) -> tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); -tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, +tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[Data,_]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> @@ -1742,4 +2125,3 @@ filesync_rep_int() -> file_delete(Log) -> file:delete(Log). - diff --git a/lib/kernel/test/logger_stress_SUITE.erl b/lib/kernel/test/logger_stress_SUITE.erl index 4072e8c86a..1a278fb1b2 100644 --- a/lib/kernel/test/logger_stress_SUITE.erl +++ b/lib/kernel/test/logger_stress_SUITE.erl @@ -67,6 +67,10 @@ all() -> reject_events, std_handler, disk_log_handler, + std_handler_time, + std_handler_time_big, + disk_log_handler_time, + disk_log_handler_time_big, emulator_events, remote_events, remote_to_disk_log, @@ -123,6 +127,20 @@ std_handler(cleanup,_Config) -> _ = file:delete("default.log"), ok. +%% Disable overload protection and just print a lot - measure time. +%% The IOPS reported is the number of log events written per millisecond. +std_handler_time(Config) -> + measure_handler_time(logger_std_h,#{type=>{file,"default.log"}},Config). +std_handler_time(cleanup,_Config) -> + _ = file:delete("default.log"), + ok. + +std_handler_time_big(Config) -> + measure_handler_time_big(logger_std_h,#{type=>{file,"default.log"}},Config). +std_handler_time_big(cleanup,_Config) -> + _ = file:delete("default.log"), + ok. + %% Cascading failure that produce gen_server and proc_lib reports - %% how many of the produced log events are actually written to a log %% with logger_disk_log_h wrap file handler. @@ -140,6 +158,20 @@ disk_log_handler(cleanup,_Config) -> [_ = file:delete(F) || F <- Files], ok. +%% Disable overload protection and just print a lot - measure time. +%% The IOPS reported is the number of log events written per millisecond. +disk_log_handler_time(Config) -> + measure_handler_time(logger_disk_log_h,#{type=>halt},Config). +disk_log_handler_time(cleanup,_Config) -> + _ = file:delete("default"), + ok. + +disk_log_handler_time_big(Config) -> + measure_handler_time_big(logger_disk_log_h,#{type=>halt},Config). +disk_log_handler_time_big(cleanup,_Config) -> + _ = file:delete("default"), + ok. + %% Cascading failure that produce log events from the emulator - how %% many of the produced log events pass through the proxy. emulator_events(Config) -> @@ -221,6 +253,68 @@ remote_emulator_to_disk_log(cleanup,_Config) -> %%%----------------------------------------------------------------- %%% Internal functions +measure_handler_time(Module,HCfg,Config) -> + measure_handler_time(Module,100000,small_fa(),millisecond,HCfg,#{},Config). + +measure_handler_time_big(Module,HCfg,Config) -> + FCfg = #{chars_limit=>4096, max_size=>1024}, + measure_handler_time(Module,100,big_fa(),second,HCfg,FCfg,Config). + +measure_handler_time(Module,N,FA,Unit,HCfg,FCfg,Config) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger, + [{handler,default,Module, + #{formatter => {logger_formatter, + maps:merge(#{legacy_header=>false, + single_line=>true},FCfg)}, + config=>maps:merge(#{sync_mode_qlen => N+1, + drop_mode_qlen => N+1, + flush_qlen => N+1, + burst_limit_enable => false, + filesync_repeat_interval => no_repeat}, + HCfg)}}]}]), + %% HPid = rpc:call(Node,erlang,whereis,[?name_to_reg_name(Module,default)]), + %% {links,[_,FCPid]} = rpc:call(Node,erlang,process_info,[HPid,links]), + T0 = erlang:monotonic_time(millisecond), + ok = rpc:call(Node,?MODULE,nlogs_wait,[N,FA,Module]), + %% ok = rpc:call(Node,fprof,apply,[fun ?MODULE:nlogs_wait/2,[N div 10,FA,Module],[{procs,[HPid,FCPid]}]]), + T1 = erlang:monotonic_time(millisecond), + T = T1-T0, + M = case Unit of + millisecond -> 1; + second -> 1000 + end, + IOPS = M*N/T, + ct:pal("N: ~p~nT: ~p~nIOPS: ~.2f events pr ~w",[N,T,IOPS,Unit]), + %% Stats = rpc:call(Node,logger_olp,info,[?name_to_reg_name(Module,default)]), + %% ct:pal("Stats: ~p",[Stats]), + ct_event:notify(#event{name = benchmark_data, + data = [{value,IOPS}]}), + {comment,io_lib:format("~.2f events written pr ~w",[IOPS,Unit])}. + +nlogs_wait(N,{F,A},Module) -> + group_leader(whereis(user),self()), + [?LOG_NOTICE(F,A) || _ <- lists:seq(1,N)], + wait(Module). + +wait(Module) -> + case Module:filesync(default) of + {error,handler_busy} -> + wait(Module); + ok -> + ok + end. + +small_fa() -> + Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ" + "[\\]^_`abcdefghijklmnopqr", + {"~ts",[Str]}. + +big_fa() -> + {"~p",[lists:duplicate(1048576,"a")]}. + nlogs(N) -> group_leader(whereis(user),self()), Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ" |