diff options
Diffstat (limited to 'lib/kernel/test')
28 files changed, 2173 insertions, 382 deletions
diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile index 4a86265a4a..6763a04d9f 100644 --- a/lib/kernel/test/Makefile +++ b/lib/kernel/test/Makefile @@ -57,6 +57,7 @@ MODULES= \ prim_file_SUITE \ ram_file_SUITE \ gen_tcp_api_SUITE \ + gen_tcp_dist \ gen_tcp_echo_SUITE \ gen_tcp_misc_SUITE \ gen_udp_SUITE \ @@ -76,8 +77,11 @@ MODULES= \ logger_filters_SUITE \ logger_formatter_SUITE \ logger_legacy_SUITE \ + logger_olp_SUITE \ + logger_proxy_SUITE \ logger_simple_h_SUITE \ logger_std_h_SUITE \ + logger_stress_SUITE \ logger_test_lib \ os_SUITE \ pg2_SUITE \ @@ -127,11 +131,17 @@ ERL_COMPILE_FLAGS += EBIN = . +TARGETS = $(MODULES:%=$(EBIN)/%.$(EMULATOR)) + + # ---------------------------------------------------- # Targets # ---------------------------------------------------- -make_emakefile: +gen_tcp_dist.erl: ../examples/gen_tcp_dist/src/gen_tcp_dist.erl + cp $< $@ + +make_emakefile: $(ERL_FILES) $(ERL_TOP)/make/make_emakefile $(ERL_COMPILE_FLAGS) -o$(EBIN) '*_SUITE_make' \ > $(EMAKEFILE) $(ERL_TOP)/make/make_emakefile $(ERL_COMPILE_FLAGS) -o$(EBIN) $(MODULES) \ @@ -147,6 +157,9 @@ clean: docs: +targets: $(TARGETS) + + # ---------------------------------------------------- # Release Target # ---------------------------------------------------- diff --git a/lib/kernel/test/application_SUITE.erl b/lib/kernel/test/application_SUITE.erl index 5c35b82207..1ab554db7c 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,94 @@ 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), + + "duplicate application config: foo" = + badarg_msg(fun() -> application:set_env([{foo, []}, {foo, []}]) end), + + "application: foo; duplicate parameter: bar" = + badarg_msg(fun() -> application:set_env([{foo, [{bar, baz}, {bar, bat}]}]) end), + + 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/code_SUITE.erl b/lib/kernel/test/code_SUITE.erl index 1314316c13..4f0847084f 100644 --- a/lib/kernel/test/code_SUITE.erl +++ b/lib/kernel/test/code_SUITE.erl @@ -25,8 +25,8 @@ -export([all/0, suite/0,groups/0,init_per_group/2,end_per_group/2]). -export([set_path/1, get_path/1, add_path/1, add_paths/1, del_path/1, replace_path/1, load_file/1, load_abs/1, ensure_loaded/1, - delete/1, purge/1, purge_many_exits/1, soft_purge/1, is_loaded/1, - all_loaded/1, + delete/1, purge/1, purge_many_exits/0, purge_many_exits/1, + soft_purge/1, is_loaded/1, all_loaded/1, load_binary/1, dir_req/1, object_code/1, set_path_file/1, upgrade/1, sticky_dir/1, pa_pz_option/1, add_del_path/1, @@ -55,7 +55,7 @@ suite() -> [{ct_hooks,[ts_install_cth]}, - {timetrap,{minutes,5}}]. + {timetrap,{seconds,30}}]. all() -> [set_path, get_path, add_path, add_paths, del_path, @@ -140,6 +140,11 @@ end_per_testcase(on_load_embedded, Config) -> LinkName = proplists:get_value(link_name, Config), _ = del_link(LinkName), end_per_testcase(Config); +end_per_testcase(upgrade, Config) -> + %% Make sure tracing is turned off even if the test times out. + erlang:trace_pattern({error_handler,undefined_function,3}, false, [global]), + erlang:trace(self(), false, [call]), + end_per_testcase(Config); end_per_testcase(_Func, Config) -> end_per_testcase(Config). @@ -391,6 +396,9 @@ purge(Config) when is_list(Config) -> process_flag(trap_exit, OldFlag), ok. +purge_many_exits() -> + [{timetrap, {minutes, 2}}]. + purge_many_exits(Config) when is_list(Config) -> OldFlag = process_flag(trap_exit, true), @@ -525,7 +533,7 @@ upgrade(Config) -> T = [beam, hipe], [upgrade_do(DataDir, Client, T) || Client <- T], - case hipe:llvm_support_available() of + case hipe:erllvm_is_supported() of false -> ok; true -> T2 = [beam, hipe_llvm], @@ -1021,6 +1029,13 @@ mult_lib_remove_prefix([H|T1], [H|T2]) -> mult_lib_remove_prefix([$/|T], []) -> T. bad_erl_libs(Config) when is_list(Config) -> + %% Preserve ERL_LIBS if set. + BadLibs0 = "/no/such/dir", + BadLibs = + case os:getenv("ERL_LIBS") of + false -> BadLibs0; + Libs -> BadLibs0 ++ ":" ++ Libs + end, {ok,Node} = test_server:start_node(bad_erl_libs, slave, []), Code = rpc:call(Node,code,get_path,[]), @@ -1028,10 +1043,9 @@ bad_erl_libs(Config) when is_list(Config) -> {ok,Node2} = test_server:start_node(bad_erl_libs, slave, - [{args,"-env ERL_LIBS /no/such/dir"}]), + [{args,"-env ERL_LIBS " ++ BadLibs}]), Code2 = rpc:call(Node,code,get_path,[]), test_server:stop_node(Node2), - %% Test that code path is not affected by the faulty ERL_LIBS Code = Code2, @@ -1550,6 +1564,11 @@ on_load_update_code_1(3, Mod) -> %% Test -on_load while trace feature 'on_load' is enabled (OTP-14612) on_load_trace_on_load(Config) -> + %% 'on_load' enables tracing for all newly loaded modules, so we make a dry + %% run to ensure that ancillary modules like 'merl' won't be loaded during + %% the actual test. + on_load_update(Config), + Papa = self(), Tracer = spawn_link(fun F() -> receive M -> Papa ! M end, F() end), {tracer,[]} = erlang:trace_info(self(),tracer), diff --git a/lib/kernel/test/erl_distribution_SUITE.erl b/lib/kernel/test/erl_distribution_SUITE.erl index 5a8bbd56c4..8dd4ef1987 100644 --- a/lib/kernel/test/erl_distribution_SUITE.erl +++ b/lib/kernel/test/erl_distribution_SUITE.erl @@ -40,7 +40,8 @@ monitor_nodes_errors/1, monitor_nodes_combinations/1, monitor_nodes_cleanup/1, - monitor_nodes_many/1]). + monitor_nodes_many/1, + dist_ctrl_proc_smoke/1]). %% Performs the test at another node. -export([get_socket_priorities/0, @@ -52,7 +53,7 @@ -export([init_per_testcase/2, end_per_testcase/2]). --export([start_node/2]). +-export([dist_cntrlr_output_test/2]). -export([pinger/1]). @@ -67,10 +68,11 @@ suite() -> [{ct_hooks,[ts_install_cth]}, - {timetrap,{minutes,4}}]. + {timetrap,{minutes,12}}]. all() -> - [tick, tick_change, nodenames, hostnames, illegal_nodenames, + [dist_ctrl_proc_smoke, + tick, tick_change, nodenames, hostnames, illegal_nodenames, connect_node, hidden_node, setopts, table_waste, net_setuptime, inet_dist_options_options, @@ -116,10 +118,12 @@ connect_node(Config) when is_list(Config) -> ok. tick(Config) when is_list(Config) -> - PaDir = filename:dirname(code:which(erl_distribution_SUITE)), + run_dist_configs(fun tick/2, Config). +tick(DCfg, _Config) -> %% First check that the normal case is OK! - {ok, Node} = start_node(dist_test, "-pa " ++ PaDir), + [Name1, Name2] = get_nodenames(2, dist_test), + {ok, Node} = start_node(DCfg, Name1), rpc:call(Node, erl_distribution_SUITE, tick_cli_test, [node()]), erlang:monitor_node(Node, true), @@ -143,14 +147,12 @@ tick(Config) when is_list(Config) -> %% Set the ticktime on the server node to 100 secs so the server %% node doesn't tick the client node within the interval ... - {ok, ServNode} = start_node(dist_test_server, - "-kernel net_ticktime 100 " - "-pa " ++ PaDir), + {ok, ServNode} = start_node(DCfg, Name2, + "-kernel net_ticktime 100"), rpc:call(ServNode, erl_distribution_SUITE, tick_serv_test, [Node, node()]), - {ok, _} = start_node(dist_test, - "-kernel net_ticktime 12 " - "-pa " ++ PaDir), + {ok, Node} = start_node(DCfg, Name1, + "-kernel net_ticktime 12"), rpc:call(Node, erl_distribution_SUITE, tick_cli_test, [ServNode]), spawn_link(erl_distribution_SUITE, keep_conn, [Node]), @@ -180,6 +182,9 @@ tick(Config) when is_list(Config) -> %% Checks that pinging nonexistyent nodes does not waste space in distribution table. table_waste(Config) when is_list(Config) -> + run_dist_configs(fun table_waste/2, Config). + +table_waste(DCfg, _Config) -> {ok, HName} = inet:gethostname(), F = fun(0,_F) -> []; (N,F) -> @@ -189,7 +194,7 @@ table_waste(Config) when is_list(Config) -> F(N-1,F) end, F(256,F), - {ok, N} = start_node(erl_distribution_300,""), + {ok, N} = start_node(DCfg, erl_distribution_300), stop_node(N), ok. @@ -295,13 +300,16 @@ gethostname() -> %% Test that pinging an illegal nodename does not kill the node. illegal_nodenames(Config) when is_list(Config) -> - PaDir = filename:dirname(code:which(erl_distribution_SUITE)), - {ok, Node}=start_node(illegal_nodenames, "-pa " ++ PaDir), + run_dist_configs(fun illegal_nodenames/2, Config). + +illegal_nodenames(DCfg, _Config) -> + {ok, Node}=start_node(DCfg, illegal_nodenames), monitor_node(Node, true), RPid=rpc:call(Node, erlang, spawn, [?MODULE, pinger, [self()]]), receive {RPid, pinged} -> + monitor_node(Node, false), ok; {nodedown, Node} -> ct:fail("Remote node died.") @@ -318,22 +326,25 @@ pinger(Starter) -> %% Test that you can set the net_setuptime properly. net_setuptime(Config) when is_list(Config) -> + run_dist_configs(fun net_setuptime/2, Config). + +net_setuptime(DCfg, _Config) -> + %% In this test case, we reluctantly accept shorter times than the given %% setup time, because the connection attempt can end in a %% "Host unreachable" error before the timeout fires. - Res0 = do_test_setuptime("2"), + Res0 = do_test_setuptime(DCfg, "2"), io:format("Res0 = ~p", [Res0]), true = (Res0 =< 4000), - Res1 = do_test_setuptime("0.3"), + Res1 = do_test_setuptime(DCfg, "0.3"), io:format("Res1 = ~p", [Res1]), true = (Res1 =< 500), ok. -do_test_setuptime(Setuptime) when is_list(Setuptime) -> - PaDir = filename:dirname(code:which(?MODULE)), - {ok, Node} = start_node(dist_setuptime_test, "-pa " ++ PaDir ++ - " -kernel net_setuptime " ++ Setuptime), +do_test_setuptime(DCfg, Setuptime) when is_list(Setuptime) -> + {ok, Node} = start_node(DCfg, dist_setuptime_test, + "-kernel net_setuptime " ++ Setuptime), Res = rpc:call(Node,?MODULE,time_ping,[?DUMMY_NODE]), stop_node(Node), Res. @@ -399,32 +410,36 @@ tick_cli_test1(Node) -> end. setopts(Config) when is_list(Config) -> + run_dist_configs(fun setopts/2, Config). + +setopts(DCfg, _Config) -> register(setopts_regname, self()), [N1,N2,N3,N4] = get_nodenames(4, setopts), - {_N1F,Port1} = start_node_unconnected(N1, ?MODULE, run_remote_test, + {_N1F,Port1} = start_node_unconnected(DCfg, N1, ?MODULE, run_remote_test, ["setopts_do", atom_to_list(node()), "1", "ping"]), 0 = wait_for_port_exit(Port1), - {_N2F,Port2} = start_node_unconnected(N2, ?MODULE, run_remote_test, + {_N2F,Port2} = start_node_unconnected(DCfg, N2, ?MODULE, run_remote_test, ["setopts_do", atom_to_list(node()), "2", "ping"]), 0 = wait_for_port_exit(Port2), {ok, LSock} = gen_tcp:listen(0, [{packet,2}, {active,false}]), {ok, LTcpPort} = inet:port(LSock), - {N3F,Port3} = start_node_unconnected(N3, ?MODULE, run_remote_test, + {N3F,Port3} = start_node_unconnected(DCfg, N3, ?MODULE, run_remote_test, ["setopts_do", atom_to_list(node()), "1", integer_to_list(LTcpPort)]), wait_and_connect(LSock, N3F, Port3), 0 = wait_for_port_exit(Port3), - {N4F,Port4} = start_node_unconnected(N4, ?MODULE, run_remote_test, + {N4F,Port4} = start_node_unconnected(DCfg, N4, ?MODULE, run_remote_test, ["setopts_do", atom_to_list(node()), "2", integer_to_list(LTcpPort)]), wait_and_connect(LSock, N4F, Port4), 0 = wait_for_port_exit(Port4), + unregister(setopts_regname), ok. wait_and_connect(LSock, NodeName, NodePort) -> @@ -518,9 +533,9 @@ opt_from_nr("2") -> {nodelay, false}. change_val(true) -> false; change_val(false) -> true. -start_node_unconnected(Name, Mod, Func, Args) -> +start_node_unconnected(DCfg, Name, Mod, Func, Args) -> FullName = full_node_name(Name), - CmdLine = mk_node_cmdline(Name,Mod,Func,Args), + CmdLine = mk_node_cmdline(DCfg, Name,Mod,Func,Args), io:format("Starting node ~p: ~s~n", [FullName, CmdLine]), case open_port({spawn, CmdLine}, [exit_status]) of Port when is_port(Port) -> @@ -534,7 +549,7 @@ full_node_name(PreName) -> atom_to_list(node())), list_to_atom(atom_to_list(PreName) ++ HostSuffix). -mk_node_cmdline(Name,Mod,Func,Args) -> +mk_node_cmdline(DCfg, Name,Mod,Func,Args) -> Static = "-noinput", Pa = filename:dirname(code:which(?MODULE)), Prog = case catch init:get_argument(progname) of @@ -551,6 +566,7 @@ mk_node_cmdline(Name,Mod,Func,Args) -> Prog ++ " " ++ Static ++ " " ++ NameSw ++ " " ++ NameStr + ++ " " ++ DCfg ++ " -pa " ++ Pa ++ " -env ERL_CRASH_DUMP " ++ Pwd ++ "/erl_crash_dump." ++ NameStr ++ " -setcookie " ++ atom_to_list(erlang:get_cookie()) @@ -560,7 +576,9 @@ mk_node_cmdline(Name,Mod,Func,Args) -> %% OTP-4255. tick_change(Config) when is_list(Config) -> - PaDir = filename:dirname(code:which(?MODULE)), + run_dist_configs(fun tick_change/2, Config). + +tick_change(DCfg, _Config) -> [BN, CN] = get_nodenames(2, tick_change), DefaultTT = net_kernel:get_net_ticktime(), unchanged = net_kernel:set_net_ticktime(DefaultTT, 60), @@ -577,14 +595,13 @@ tick_change(Config) when is_list(Config) -> end, wait_until(fun () -> 10 == net_kernel:get_net_ticktime() end), - {ok, B} = start_node(BN, "-kernel net_ticktime 10 -pa " ++ PaDir), - {ok, C} = start_node(CN, "-kernel net_ticktime 10 -hidden -pa " - ++ PaDir), + {ok, B} = start_node(DCfg, BN, "-kernel net_ticktime 10"), + {ok, C} = start_node(DCfg, CN, "-kernel net_ticktime 10 -hidden"), OTE = process_flag(trap_exit, true), case catch begin - run_tick_change_test(B, C, 10, 1, PaDir), - run_tick_change_test(B, C, 1, 10, PaDir) + run_tick_change_test(DCfg, B, C, 10, 1), + run_tick_change_test(DCfg, B, C, 1, 10) end of {'EXIT', Reason} -> stop_node(B), @@ -626,7 +643,7 @@ wait_for_nodedowns(Tester, Ref) -> end, wait_for_nodedowns(Tester, Ref). -run_tick_change_test(B, C, PrevTT, TT, PaDir) -> +run_tick_change_test(DCfg, B, C, PrevTT, TT) -> [DN, EN] = get_nodenames(2, tick_change), Tester = self(), @@ -640,8 +657,8 @@ run_tick_change_test(B, C, PrevTT, TT, PaDir) -> wait_for_nodedowns(Tester, Ref) end, - {ok, D} = start_node(DN, "-kernel net_ticktime " - ++ integer_to_list(PrevTT) ++ " -pa " ++ PaDir), + {ok, D} = start_node(DCfg, DN, "-kernel net_ticktime " + ++ integer_to_list(PrevTT)), NMA = spawn_link(fun () -> MonitorNodes([B, C, D]) end), NMB = spawn_link(B, fun () -> MonitorNodes([node(), C, D]) end), @@ -674,8 +691,8 @@ run_tick_change_test(B, C, PrevTT, TT, PaDir) -> sleep(7), change_initiated = rpc:call(C,net_kernel,set_net_ticktime,[TT,10]), - {ok, E} = start_node(EN, "-kernel net_ticktime " - ++ integer_to_list(TT) ++ " -pa " ++ PaDir), + {ok, E} = start_node(DCfg, EN, "-kernel net_ticktime " + ++ integer_to_list(TT)), NME = spawn_link(E, fun () -> MonitorNodes([node(), B, C, D]) end), NMA2 = spawn_link(fun () -> MonitorNodes([E]) end), NMB2 = spawn_link(B, fun () -> MonitorNodes([E]) end), @@ -735,12 +752,13 @@ run_tick_change_test(B, C, PrevTT, TT, PaDir) -> %% %% Basic test of hidden node. hidden_node(Config) when is_list(Config) -> - PaDir = filename:dirname(code:which(?MODULE)), - VArgs = "-pa " ++ PaDir, - HArgs = "-hidden -pa " ++ PaDir, - {ok, V} = start_node(visible_node, VArgs), + run_dist_configs(fun hidden_node/2, Config). + +hidden_node(DCfg, _Config) -> + HArgs = "-hidden", + {ok, V} = start_node(DCfg, visible_node), VMN = start_monitor_nodes_proc(V), - {ok, H} = start_node(hidden_node, HArgs), + {ok, H} = start_node(DCfg, hidden_node, HArgs), %% Connect visible_node -> hidden_node connect_nodes(V, H), test_nodes(V, H), @@ -748,9 +766,9 @@ hidden_node(Config) when is_list(Config) -> sleep(5), check_monitor_nodes_res(VMN, H), stop_node(V), - {ok, H} = start_node(hidden_node, HArgs), + {ok, H} = start_node(DCfg, hidden_node, HArgs), HMN = start_monitor_nodes_proc(H), - {ok, V} = start_node(visible_node, VArgs), + {ok, V} = start_node(DCfg, visible_node), %% Connect hidden_node -> visible_node connect_nodes(H, V), test_nodes(V, H), @@ -850,9 +868,9 @@ do_inet_dist_options_options(Prio) -> "-kernel inet_dist_connect_options "++PriorityString++" " "-kernel inet_dist_listen_options "++PriorityString, {ok,Node1} = - start_node(inet_dist_options_1, InetDistOptions), + start_node("", inet_dist_options_1, InetDistOptions), {ok,Node2} = - start_node(inet_dist_options_2, InetDistOptions), + start_node("", inet_dist_options_2, InetDistOptions), %% pong = rpc:call(Node1, net_adm, ping, [Node2]), @@ -885,6 +903,9 @@ get_socket_priorities() -> %% monitor_nodes_nodedown_reason(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_nodedown_reason/2, Config). + +monitor_nodes_nodedown_reason(DCfg, _Config) -> MonNodeState = monitor_node_state(), ok = net_kernel:monitor_nodes(true), ok = net_kernel:monitor_nodes(true, [nodedown_reason]), @@ -892,10 +913,10 @@ monitor_nodes_nodedown_reason(Config) when is_list(Config) -> Names = get_numbered_nodenames(5, node), [NN1, NN2, NN3, NN4, NN5] = Names, - {ok, N1} = start_node(NN1), - {ok, N2} = start_node(NN2), - {ok, N3} = start_node(NN3), - {ok, N4} = start_node(NN4, "-hidden"), + {ok, N1} = start_node(DCfg, NN1), + {ok, N2} = start_node(DCfg, NN2), + {ok, N3} = start_node(DCfg, NN3), + {ok, N4} = start_node(DCfg, NN4, "-hidden"), receive {nodeup, N1} -> ok end, receive {nodeup, N2} -> ok end, @@ -925,7 +946,7 @@ monitor_nodes_nodedown_reason(Config) when is_list(Config) -> ok = net_kernel:monitor_nodes(false, [nodedown_reason]), - {ok, N5} = start_node(NN5), + {ok, N5} = start_node(DCfg, NN5), stop_node(N5), receive {nodeup, N5} -> ok end, @@ -938,11 +959,14 @@ monitor_nodes_nodedown_reason(Config) when is_list(Config) -> monitor_nodes_complex_nodedown_reason(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_complex_nodedown_reason/2, Config). + +monitor_nodes_complex_nodedown_reason(DCfg, _Config) -> MonNodeState = monitor_node_state(), Me = self(), ok = net_kernel:monitor_nodes(true, [nodedown_reason]), [Name] = get_nodenames(1, monitor_nodes_complex_nodedown_reason), - {ok, Node} = start_node(Name, ""), + {ok, Node} = start_node(DCfg, Name, ""), Pid = spawn(Node, fun() -> Me ! {stuff, @@ -981,16 +1005,19 @@ monitor_nodes_complex_nodedown_reason(Config) when is_list(Config) -> %% monitor_nodes_node_type(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_node_type/2, Config). + +monitor_nodes_node_type(DCfg, _Config) -> MonNodeState = monitor_node_state(), ok = net_kernel:monitor_nodes(true), ok = net_kernel:monitor_nodes(true, [{node_type, all}]), Names = get_numbered_nodenames(9, node), [NN1, NN2, NN3, NN4, NN5, NN6, NN7, NN8, NN9] = Names, - {ok, N1} = start_node(NN1), - {ok, N2} = start_node(NN2), - {ok, N3} = start_node(NN3, "-hidden"), - {ok, N4} = start_node(NN4, "-hidden"), + {ok, N1} = start_node(DCfg, NN1), + {ok, N2} = start_node(DCfg, NN2), + {ok, N3} = start_node(DCfg, NN3, "-hidden"), + {ok, N4} = start_node(DCfg, NN4, "-hidden"), receive {nodeup, N1} -> ok end, receive {nodeup, N2} -> ok end, @@ -1014,15 +1041,15 @@ monitor_nodes_node_type(Config) when is_list(Config) -> receive {nodedown, N4, [{node_type, hidden}]} -> ok end, ok = net_kernel:monitor_nodes(false, [{node_type, all}]), - {ok, N5} = start_node(NN5), + {ok, N5} = start_node(DCfg, NN5), receive {nodeup, N5} -> ok end, stop_node(N5), receive {nodedown, N5} -> ok end, ok = net_kernel:monitor_nodes(true, [{node_type, hidden}]), - {ok, N6} = start_node(NN6), - {ok, N7} = start_node(NN7, "-hidden"), + {ok, N6} = start_node(DCfg, NN6), + {ok, N7} = start_node(DCfg, NN7, "-hidden"), receive {nodeup, N6} -> ok end, @@ -1037,8 +1064,8 @@ monitor_nodes_node_type(Config) when is_list(Config) -> ok = net_kernel:monitor_nodes(false, [{node_type, hidden}]), ok = net_kernel:monitor_nodes(false), - {ok, N8} = start_node(NN8), - {ok, N9} = start_node(NN9, "-hidden"), + {ok, N8} = start_node(DCfg, NN8), + {ok, N9} = start_node(DCfg, NN9, "-hidden"), receive {nodeup, N8, [{node_type, visible}]} -> ok end, stop_node(N8), @@ -1058,6 +1085,9 @@ monitor_nodes_node_type(Config) when is_list(Config) -> %% monitor_nodes_misc(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_misc/2, Config). + +monitor_nodes_misc(DCfg, _Config) -> MonNodeState = monitor_node_state(), ok = net_kernel:monitor_nodes(true), ok = net_kernel:monitor_nodes(true, [{node_type, all}, nodedown_reason]), @@ -1065,8 +1095,8 @@ monitor_nodes_misc(Config) when is_list(Config) -> Names = get_numbered_nodenames(3, node), [NN1, NN2, NN3] = Names, - {ok, N1} = start_node(NN1), - {ok, N2} = start_node(NN2, "-hidden"), + {ok, N1} = start_node(DCfg, NN1), + {ok, N2} = start_node(DCfg, NN2, "-hidden"), receive {nodeup, N1} -> ok end, @@ -1092,7 +1122,7 @@ monitor_nodes_misc(Config) when is_list(Config) -> ok = net_kernel:monitor_nodes(false, [{node_type, all}, nodedown_reason]), - {ok, N3} = start_node(NN3), + {ok, N3} = start_node(DCfg, NN3), receive {nodeup, N3} -> ok end, stop_node(N3), receive {nodedown, N3} -> ok end, @@ -1107,15 +1137,18 @@ monitor_nodes_misc(Config) when is_list(Config) -> %% messages from Node and that {nodedown, Node} messages are %% received after messages from Node. monitor_nodes_otp_6481(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_otp_6481/2, Config). + +monitor_nodes_otp_6481(DCfg, Config) -> io:format("Testing nodedown...~n"), - monitor_nodes_otp_6481_test(Config, nodedown), + monitor_nodes_otp_6481_test(DCfg, Config, nodedown), io:format("ok~n"), io:format("Testing nodeup...~n"), - monitor_nodes_otp_6481_test(Config, nodeup), + monitor_nodes_otp_6481_test(DCfg, Config, nodeup), io:format("ok~n"), ok. -monitor_nodes_otp_6481_test(Config, TestType) when is_list(Config) -> +monitor_nodes_otp_6481_test(DCfg, Config, TestType) when is_list(Config) -> MonNodeState = monitor_node_state(), NodeMsg = make_ref(), Me = self(), @@ -1164,7 +1197,7 @@ monitor_nodes_otp_6481_test(Config, TestType) when is_list(Config) -> end ++ MonNodeState, - {ok, Node} = start_node(Name, "", this), + {ok, Node} = start_node(DCfg, Name, "", this), receive {nodeup, Node} -> ok end, RemotePid = spawn(Node, @@ -1249,17 +1282,20 @@ monitor_nodes_errors(Config) when is_list(Config) -> ok. monitor_nodes_combinations(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_combinations/2, Config). + +monitor_nodes_combinations(DCfg, _Config) -> MonNodeState = monitor_node_state(), monitor_nodes_all_comb(true), [VisibleName, HiddenName] = get_nodenames(2, monitor_nodes_combinations), - {ok, Visible} = start_node(VisibleName, ""), + {ok, Visible} = start_node(DCfg, VisibleName, ""), receive_all_comb_nodeup_msgs(visible, Visible), no_msgs(), stop_node(Visible), receive_all_comb_nodedown_msgs(visible, Visible, connection_closed), no_msgs(), - {ok, Hidden} = start_node(HiddenName, "-hidden"), + {ok, Hidden} = start_node(DCfg, HiddenName, "-hidden"), receive_all_comb_nodeup_msgs(hidden, Hidden), no_msgs(), stop_node(Hidden), @@ -1395,6 +1431,9 @@ monitor_nodes_cleanup(Config) when is_list(Config) -> ok. monitor_nodes_many(Config) when is_list(Config) -> + run_dist_configs(fun monitor_nodes_many/2, Config). + +monitor_nodes_many(DCfg, _Config) -> MonNodeState = monitor_node_state(), [Name] = get_nodenames(1, monitor_nodes_many), %% We want to perform more than 2^16 net_kernel:monitor_nodes @@ -1402,7 +1441,7 @@ monitor_nodes_many(Config) when is_list(Config) -> No = (1 bsl 16) + 17, repeat(fun () -> ok = net_kernel:monitor_nodes(true) end, No), No = length(monitor_node_state()) - length(MonNodeState), - {ok, Node} = start_node(Name), + {ok, Node} = start_node(DCfg, Name), repeat(fun () -> receive {nodeup, Node} -> ok end end, No), stop_node(Node), repeat(fun () -> receive {nodedown, Node} -> ok end end, No), @@ -1411,8 +1450,118 @@ monitor_nodes_many(Config) when is_list(Config) -> MonNodeState = monitor_node_state(), ok. +dist_ctrl_proc_smoke(Config) when is_list(Config) -> + ThisNode = node(), + [Name1, Name2] = get_nodenames(2, dist_ctrl_proc_example_smoke), + GetSizeArg = " -gen_tcp_dist_output_loop " + ++ atom_to_list(?MODULE) ++ " " + ++ "dist_cntrlr_output_test", + {ok, Node1} = start_node("", Name1, "-proto_dist gen_tcp"), + {ok, Node2} = start_node("", Name2, "-proto_dist gen_tcp" ++ GetSizeArg), + pong = rpc:call(Node1, net_adm, ping, [Node2]), + NL1 = lists:sort([ThisNode, Node2]), + NL2 = lists:sort([ThisNode, Node1]), + NL1 = lists:sort(rpc:call(Node1, erlang, nodes, [])), + NL2 = lists:sort(rpc:call(Node2, erlang, nodes, [])), + + %% Verify that we actually are executing the distribution + %% module we expect and also massage message passing over + %% it a bit... + Ps1 = rpc:call(Node1, erlang, processes, []), + try + lists:foreach( + fun (P) -> + case rpc:call(Node1, erlang, process_info, [P, current_stacktrace]) of + undefined -> + ok; + {current_stacktrace, StkTrace} -> + lists:foreach(fun ({gen_tcp_dist, + dist_cntrlr_output_loop, + 2, _}) -> + io:format("~p ~p~n", [P, StkTrace]), + throw(found_it); + (_) -> + ok + end, StkTrace) + end + end, Ps1), + exit({missing, dist_cntrlr_output_loop}) + catch + throw:found_it -> ok + end, + + Ps2 = rpc:call(Node2, erlang, processes, []), + try + lists:foreach( + fun (P) -> + case rpc:call(Node2, erlang, process_info, [P, current_stacktrace]) of + undefined -> + ok; + {current_stacktrace, StkTrace} -> + lists:foreach(fun ({erl_distribution_SUITE, + dist_cntrlr_output_loop, + 2, _}) -> + io:format("~p ~p~n", [P, StkTrace]), + throw(found_it); + (_) -> + ok + end, StkTrace) + end + end, Ps2), + exit({missing, dist_cntrlr_output_loop}) + catch + throw:found_it -> ok + end, + + stop_node(Node1), + stop_node(Node2), + ok. + %% Misc. functions +run_dist_configs(Func, Config) -> + GetSizeArg = " -gen_tcp_dist_output_loop " + ++ atom_to_list(?MODULE) ++ " " + ++ "dist_cntrlr_output_test", + lists:map(fun ({DCfgName, DCfg}) -> + io:format("~n~n=== Running ~s configuration ===~n~n", + [DCfgName]), + Func(DCfg, Config) + end, + [{"default", ""}, + {"gen_tcp_dist", "-proto_dist gen_tcp"}, + {"gen_tcp_dist (get_size)", "-proto_dist gen_tcp" ++ GetSizeArg}]). + +dist_cntrlr_output_test(DHandle, Socket) -> + false = erlang:dist_ctrl_get_opt(DHandle, get_size), + false = erlang:dist_ctrl_set_opt(DHandle, get_size, true), + true = erlang:dist_ctrl_get_opt(DHandle, get_size), + true = erlang:dist_ctrl_set_opt(DHandle, get_size, false), + false = erlang:dist_ctrl_get_opt(DHandle, get_size), + false = erlang:dist_ctrl_set_opt(DHandle, get_size, true), + true = erlang:dist_ctrl_get_opt(DHandle, get_size), + dist_cntrlr_output_loop(DHandle, Socket). + +dist_cntrlr_send_data(DHandle, Socket) -> + case erlang:dist_ctrl_get_data(DHandle) of + none -> + erlang:dist_ctrl_get_data_notification(DHandle); + {Size, Data} -> + Size = erlang:iolist_size(Data), + ok = gen_tcp:send(Socket, Data), + dist_cntrlr_send_data(DHandle, Socket) + end. + +dist_cntrlr_output_loop(DHandle, Socket) -> + receive + dist_data -> + %% Outgoing data from this node... + dist_cntrlr_send_data(DHandle, Socket); + _ -> + ok %% Drop garbage message... + end, + dist_cntrlr_output_loop(DHandle, Socket). + monitor_node_state() -> erts_debug:set_internal_state(available_internal_state, true), MonitoringNodes = erts_debug:get_internal_state(monitoring_nodes), @@ -1438,25 +1587,25 @@ print_my_messages() -> sleep(T) -> receive after T * 1000 -> ok end. -start_node(Name, Param, this) -> +start_node(DCfg, Name, Param, this) -> NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)), test_server:start_node(Name, peer, [{args, NewParam}, {erl, [this]}]); -start_node(Name, Param, "this") -> - NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)), +start_node(DCfg, Name, Param, "this") -> + NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)) ++ " " ++ DCfg, test_server:start_node(Name, peer, [{args, NewParam}, {erl, [this]}]); -start_node(Name, Param, Rel) when is_atom(Rel) -> - NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)), +start_node(DCfg, Name, Param, Rel) when is_atom(Rel) -> + NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)) ++ " " ++ DCfg, test_server:start_node(Name, peer, [{args, NewParam}, {erl, [{release, atom_to_list(Rel)}]}]); -start_node(Name, Param, Rel) when is_list(Rel) -> - NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)), +start_node(DCfg, Name, Param, Rel) when is_list(Rel) -> + NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)) ++ " " ++ DCfg, test_server:start_node(Name, peer, [{args, NewParam}, {erl, [{release, Rel}]}]). -start_node(Name, Param) -> - NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)), +start_node(DCfg, Name, Param) -> + NewParam = Param ++ " -pa " ++ filename:dirname(code:which(?MODULE)) ++ " " ++ DCfg, test_server:start_node(Name, slave, [{args, NewParam}]). -start_node(Name) -> - start_node(Name, ""). +start_node(DCfg, Name) -> + start_node(DCfg, Name, ""). stop_node(Node) -> test_server:stop_node(Node). diff --git a/lib/kernel/test/erl_distribution_wb_SUITE.erl b/lib/kernel/test/erl_distribution_wb_SUITE.erl index 8256444bdc..f3db6705a2 100644 --- a/lib/kernel/test/erl_distribution_wb_SUITE.erl +++ b/lib/kernel/test/erl_distribution_wb_SUITE.erl @@ -47,6 +47,9 @@ R end). +-define(EPMD_DIST_HIGH, 6). +-define(EPMD_DIST_LOW, 5). + -define(DFLAG_PUBLISHED,1). -define(DFLAG_ATOM_CACHE,2). -define(DFLAG_EXTENDED_REFERENCES,4). @@ -57,15 +60,18 @@ -define(DFLAG_NEW_FUN_TAGS,16#80). -define(DFLAG_EXTENDED_PIDS_PORTS,16#100). -define(DFLAG_UTF8_ATOMS, 16#10000). +-define(DFLAG_BIG_CREATION, 16#40000). %% From R9 and forward extended references is compulsory %% From R10 and forward extended pids and ports are compulsory %% From R20 and forward UTF8 atoms are compulsory %% From R21 and forward NEW_FUN_TAGS is compulsory (no more tuple fallback {fun, ...}) +%% From R22 and forward BIG_CREATION is compulsory -define(COMPULSORY_DFLAGS, (?DFLAG_EXTENDED_REFERENCES bor ?DFLAG_EXTENDED_PIDS_PORTS bor ?DFLAG_UTF8_ATOMS bor - ?DFLAG_NEW_FUN_TAGS)). + ?DFLAG_NEW_FUN_TAGS bor + ?DFLAG_BIG_CREATION)). -define(PASS_THROUGH, $p). @@ -208,9 +214,9 @@ pending_up_md5(Node,OurName,Cookie) -> {ok, SocketA} = gen_tcp:connect(atom_to_list(NB),PortNo, [{active,false}, {packet,2}]), - send_name(SocketA,OurName,5), + send_name(SocketA,OurName, ?EPMD_DIST_HIGH), ok = recv_status(SocketA), - {hidden,Node,5,HisChallengeA} = recv_challenge(SocketA), % See 1) + {hidden,Node,?EPMD_DIST_HIGH,HisChallengeA} = recv_challenge(SocketA), % See 1) OurChallengeA = gen_challenge(), OurDigestA = gen_digest(HisChallengeA, Cookie), send_challenge_reply(SocketA, OurChallengeA, OurDigestA), @@ -224,11 +230,11 @@ pending_up_md5(Node,OurName,Cookie) -> {ok, SocketB} = gen_tcp:connect(atom_to_list(NB),PortNo, [{active,false}, {packet,2}]), - send_name(SocketB,OurName,5), + send_name(SocketB,OurName, ?EPMD_DIST_HIGH), alive = recv_status(SocketB), send_status(SocketB, true), gen_tcp:close(SocketA), - {hidden,Node,5,HisChallengeB} = recv_challenge(SocketB), % See 1) + {hidden,Node,?EPMD_DIST_HIGH,HisChallengeB} = recv_challenge(SocketB), % See 1) OurChallengeB = gen_challenge(), OurDigestB = gen_digest(HisChallengeB, Cookie), send_challenge_reply(SocketB, OurChallengeB, OurDigestB), @@ -254,7 +260,7 @@ simultaneous_md5(Node, OurName, Cookie) when OurName < Node -> Else -> exit(Else) end, - EpmdSocket = register(OurName, LSocket, 1, 5), + EpmdSocket = register_node(OurName, LSocket, ?EPMD_DIST_LOW, ?EPMD_DIST_HIGH), {NA, NB} = split(Node), rpc:cast(Node, net_adm, ping, [OurName]), receive after 1000 -> ok end, @@ -262,7 +268,7 @@ simultaneous_md5(Node, OurName, Cookie) when OurName < Node -> {ok, SocketA} = gen_tcp:connect(atom_to_list(NB),PortNo, [{active,false}, {packet,2}]), - send_name(SocketA,OurName,5), + send_name(SocketA,OurName, ?EPMD_DIST_HIGH), %% We are still not marked up on the other side, as our first message %% is not sent. SocketB = case gen_tcp:accept(LSocket) of @@ -275,11 +281,11 @@ simultaneous_md5(Node, OurName, Cookie) when OurName < Node -> %% Now we are expected to close A gen_tcp:close(SocketA), %% But still Socket B will continue - {normal,Node,5} = recv_name(SocketB), % See 1) + {normal,Node,?EPMD_DIST_HIGH} = recv_name(SocketB), % See 1) send_status(SocketB, ok_simultaneous), MyChallengeB = gen_challenge(), - send_challenge(SocketB, OurName, MyChallengeB,5), - HisChallengeB = recv_challenge_reply(SocketB, MyChallengeB, Cookie), + send_challenge(SocketB, OurName, MyChallengeB, ?EPMD_DIST_HIGH), + {ok,HisChallengeB} = recv_challenge_reply(SocketB, MyChallengeB, Cookie), DigestB = gen_digest(HisChallengeB,Cookie), send_challenge_ack(SocketB, DigestB), inet:setopts(SocketB, [{active, false}, @@ -301,7 +307,8 @@ simultaneous_md5(Node, OurName, Cookie) when OurName > Node -> Else -> exit(Else) end, - EpmdSocket = register(OurName, LSocket, 1, 5), + EpmdSocket = register_node(OurName, LSocket, + ?EPMD_DIST_LOW, ?EPMD_DIST_HIGH), {NA, NB} = split(Node), rpc:cast(Node, net_adm, ping, [OurName]), receive after 1000 -> ok end, @@ -315,16 +322,16 @@ simultaneous_md5(Node, OurName, Cookie) when OurName > Node -> Else2 -> exit(Else2) end, - send_name(SocketA,OurName,5), + send_name(SocketA,OurName, ?EPMD_DIST_HIGH), ok_simultaneous = recv_status(SocketA), %% Socket B should die during this case catch begin - {normal,Node,5} = recv_name(SocketB), % See 1) + {normal,Node,?EPMD_DIST_HIGH} = recv_name(SocketB), % See 1) send_status(SocketB, ok_simultaneous), MyChallengeB = gen_challenge(), send_challenge(SocketB, OurName, MyChallengeB, 5), - HisChallengeB = recv_challenge_reply( + {ok,HisChallengeB} = recv_challenge_reply( SocketB, MyChallengeB, Cookie), @@ -346,7 +353,7 @@ simultaneous_md5(Node, OurName, Cookie) when OurName > Node -> end, gen_tcp:close(SocketB), %% But still Socket A will continue - {hidden,Node,5,HisChallengeA} = recv_challenge(SocketA), % See 1) + {hidden,Node,?EPMD_DIST_HIGH,HisChallengeA} = recv_challenge(SocketA), % See 1) OurChallengeA = gen_challenge(), OurDigestA = gen_digest(HisChallengeA, Cookie), send_challenge_reply(SocketA, OurChallengeA, OurDigestA), @@ -372,7 +379,7 @@ missing_compulsory_dflags(Config) when is_list(Config) -> [{active,false}, {packet,2}]), BadNode = list_to_atom(atom_to_list(Name2)++"@"++atom_to_list(NB)), - send_name(SocketA,BadNode,5,0), + send_name(SocketA,BadNode, ?EPMD_DIST_HIGH, 0), not_allowed = recv_status(SocketA), gen_tcp:close(SocketA), stop_node(Node), @@ -516,16 +523,16 @@ send_challenge_reply(Socket, Challenge, Digest) -> recv_challenge_reply(Socket, ChallengeA, Cookie) -> case gen_tcp:recv(Socket, 0) of - {ok,[$r,CB3,CB2,CB1,CB0 | SumB]} when length(SumB) == 16 -> + {ok,[$r,CB3,CB2,CB1,CB0 | SumB]=Data} when length(SumB) == 16 -> SumA = gen_digest(ChallengeA, Cookie), ChallengeB = ?u32(CB3,CB2,CB1,CB0), if SumB == SumA -> - ChallengeB; + {ok,ChallengeB}; true -> - ?shutdown(bad_challenge_reply) + {error,Data} end; - _ -> - ?shutdown(no_node) + Err -> + {error,Err} end. send_challenge_ack(Socket, Digest) -> @@ -620,6 +627,13 @@ wait_for_reg_reply(Socket, SoFar) -> receive {tcp, Socket, Data0} -> case SoFar ++ Data0 of + [$v, Result, A, B, C, D] -> + case Result of + 0 -> + {alive, Socket, ?u32(A, B, C, D)}; + _ -> + {error, duplicate_name} + end; [$y, Result, A, B] -> case Result of 0 -> @@ -640,7 +654,7 @@ wait_for_reg_reply(Socket, SoFar) -> end. -register(NodeName, ListenSocket, VLow, VHigh) -> +register_node(NodeName, ListenSocket, VLow, VHigh) -> {ok,{_,TcpPort}} = inet:sockname(ListenSocket), case do_register_node(NodeName, TcpPort, VLow, VHigh) of {alive, Socket, _Creation} -> diff --git a/lib/kernel/test/file_SUITE.erl b/lib/kernel/test/file_SUITE.erl index a51025cba6..3bc8e6e828 100644 --- a/lib/kernel/test/file_SUITE.erl +++ b/lib/kernel/test/file_SUITE.erl @@ -2191,6 +2191,9 @@ unc_paths(Config) when is_list(Config) -> {ok, _} = file:read_file_info("C:\\Windows\\explorer.exe"), {ok, _} = file:read_file_info("\\\\localhost\\c$\\Windows\\explorer.exe"), + {ok, Files} = file:list_dir("C:\\Windows\\"), + {ok, Files} = file:list_dir("\\\\localhost\\c$\\Windows\\"), + {ok, Cwd} = file:get_cwd(), try @@ -3741,19 +3744,33 @@ otp_10852(Config) when is_list(Config) -> ok = rpc_call(Node, read_file, [B]), ok = rpc_call(Node, make_link, [B,B]), case rpc_call(Node, make_symlink, [B,B]) of - ok -> ok; - {error, E} when (E =:= enotsup) or (E =:= eperm) -> - {win32,_} = os:type() + {error, eilseq} -> + %% Some versions of OS X refuse to create files with illegal names. + {unix,darwin} = os:type(); + {error, eperm} -> + %% The test user might not have permission to create symlinks. + {win32,_} = os:type(); + ok -> + ok end, ok = rpc_call(Node, delete, [B]), - ok = rpc_call(Node, make_dir, [B]), + case rpc_call(Node, make_dir, [B]) of + {error, eilseq} -> + {unix,darwin} = os:type(); + ok -> + ok + end, ok = rpc_call(Node, del_dir, [B]), - ok = rpc_call(Node, write_file, [B,B]), - {ok, Fd} = rpc_call(Node, open, [B,[read]]), - ok = rpc_call(Node, close, [Fd]), - {ok,0} = rpc_call(Node, copy, [B,B]), - {ok, Fd2, B} = rpc_call(Node, path_open, [["."], B, [read]]), - ok = rpc_call(Node, close, [Fd2]), + case rpc_call(Node, write_file, [B,B]) of + {error, eilseq} -> + {unix,darwin} = os:type(); + ok -> + {ok, Fd} = rpc_call(Node, open, [B,[read]]), + ok = rpc_call(Node, close, [Fd]), + {ok,0} = rpc_call(Node, copy, [B,B]), + {ok, Fd2, B} = rpc_call(Node, path_open, [["."], B, [read]]), + ok = rpc_call(Node, close, [Fd2]) + end, true = test_server:stop_node(Node), ok. @@ -4497,15 +4514,18 @@ run_large_file_test(Config, Run, Name) -> {{unix,sunos},OsVersion} when OsVersion < {5,5,1} -> {skip,"Only supported on Win32, Unix or SunOS >= 5.5.1"}; {{unix,_},_} -> - N = disc_free(proplists:get_value(priv_dir, Config)), - io:format("Free disk: ~w KByte~n", [N]), - if N < 5 * (1 bsl 20) -> - %% Less than 5 GByte free - {skip,"Less than 5 GByte free"}; - true -> - do_run_large_file_test(Config, Run, Name) - end; - _ -> + case disc_free(proplists:get_value(priv_dir, Config)) of + error -> + {skip, "Failed to query disk space for priv_dir. " + "Is it on a remote file system?~n"}; + N when N >= 5 * (1 bsl 20) -> + ct:pal("Free disk: ~w KByte~n", [N]), + do_run_large_file_test(Config, Run, Name); + N when N < 5 * (1 bsl 20) -> + ct:pal("Free disk: ~w KByte~n", [N]), + {skip,"Less than 5 GByte free"} + end; + _ -> {skip,"Only supported on Win32, Unix or SunOS >= 5.5.1"} end. @@ -4539,12 +4559,18 @@ do_run_large_file_test(Config, Run, Name0) -> disc_free(Path) -> Data = disksup:get_disk_data(), - {_,Tot,Perc} = hd(lists:filter( - fun({P,_Size,_Full}) -> - lists:prefix(filename:nativename(P), - filename:nativename(Path)) - end, lists:reverse(lists:sort(Data)))), - round(Tot * (1-(Perc/100))). + + %% What partitions could Data be mounted on? + Partitions = + [D || {P, _Tot, _Perc}=D <- Data, + lists:prefix(filename:nativename(P), filename:nativename(Path))], + + %% Sorting in descending order places the partition with the most specific + %% path first. + case lists:sort(fun erlang:'>='/2, Partitions) of + [{_,Tot, Perc} | _] -> round(Tot * (1-(Perc/100))); + [] -> error + end. memsize() -> {Tot,_Used,_} = memsup:get_memory_data(), diff --git a/lib/kernel/test/file_name_SUITE.erl b/lib/kernel/test/file_name_SUITE.erl index 3afc647081..26cfd187c7 100644 --- a/lib/kernel/test/file_name_SUITE.erl +++ b/lib/kernel/test/file_name_SUITE.erl @@ -632,10 +632,13 @@ make_icky_dir(Mod, IckyDirName) -> hopeless_darwin() -> case {os:type(),os:version()} of - {{unix,darwin},{Major,_,_}} when Major < 9 -> - true; - _ -> - false + {{unix,darwin},{Major,_,_}} -> + %% icky file names worked between 10 and 17, but started returning + %% EILSEQ in 18. The check against 18 is exact in case newer + %% versions of Darwin support them again. + Major < 9 orelse Major =:= 18; + _ -> + false end. make_very_icky_dir(Mod, DirName) -> diff --git a/lib/kernel/test/gen_sctp_SUITE.erl b/lib/kernel/test/gen_sctp_SUITE.erl index a0ae792ba9..e4c489bd10 100644 --- a/lib/kernel/test/gen_sctp_SUITE.erl +++ b/lib/kernel/test/gen_sctp_SUITE.erl @@ -1459,11 +1459,11 @@ do_open_and_connect(ServerAddresses, AddressToConnectTo) -> do_open_and_connect(ServerAddresses, AddressToConnectTo, Fun). %% do_open_and_connect(ServerAddresses, AddressToConnectTo, Fun) -> - ServerFamily = get_family_by_addrs(ServerAddresses), + {ServerFamily, ServerOpts} = get_family_by_addrs(ServerAddresses), io:format("Serving ~p addresses: ~p~n", [ServerFamily, ServerAddresses]), S1 = ok(gen_sctp:open(0, [{ip,Addr} || Addr <- ServerAddresses] ++ - [ServerFamily])), + [ServerFamily|ServerOpts])), ok = gen_sctp:listen(S1, true), P1 = ok(inet:port(S1)), ClientFamily = get_family_by_addr(AddressToConnectTo), @@ -1493,9 +1493,9 @@ do_open_and_connect(ServerAddresses, AddressToConnectTo, Fun) -> %% If at least one of the addresses is an ipv6 address, return inet6, else inet. get_family_by_addrs(Addresses) -> case lists:usort([get_family_by_addr(Addr) || Addr <- Addresses]) of - [inet, inet6] -> inet6; - [inet] -> inet; - [inet6] -> inet6 + [inet, inet6] -> {inet6, [{ipv6_v6only, false}]}; + [inet] -> {inet, []}; + [inet6] -> {inet6, []} end. get_family_by_addr(Addr) when tuple_size(Addr) =:= 4 -> inet; diff --git a/lib/kernel/test/gen_tcp_api_SUITE_data/gen_tcp_api_SUITE.c b/lib/kernel/test/gen_tcp_api_SUITE_data/gen_tcp_api_SUITE.c index b91dca61d4..96938f9071 100644 --- a/lib/kernel/test/gen_tcp_api_SUITE_data/gen_tcp_api_SUITE.c +++ b/lib/kernel/test/gen_tcp_api_SUITE_data/gen_tcp_api_SUITE.c @@ -30,6 +30,7 @@ #define sock_close(s) closesocket(s) #else #include <sys/socket.h> +#include <unistd.h> #define sock_close(s) close(s) #endif diff --git a/lib/kernel/test/gen_tcp_misc_SUITE.erl b/lib/kernel/test/gen_tcp_misc_SUITE.erl index 244bd7e2a0..edf30448c4 100644 --- a/lib/kernel/test/gen_tcp_misc_SUITE.erl +++ b/lib/kernel/test/gen_tcp_misc_SUITE.erl @@ -53,7 +53,7 @@ active_once_closed/1, send_timeout/1, send_timeout_active/1, otp_7731/1, zombie_sockets/1, otp_7816/1, otp_8102/1, wrapping_oct/0, wrapping_oct/1, otp_9389/1, otp_13939/1, - otp_12242/1]). + otp_12242/1, delay_send_error/1]). %% Internal exports. -export([sender/3, not_owner/1, passive_sockets_server/2, priority_server/1, @@ -97,7 +97,7 @@ all() -> active_once_closed, send_timeout, send_timeout_active, otp_7731, wrapping_oct, zombie_sockets, otp_7816, otp_8102, otp_9389, - otp_12242]. + otp_12242, delay_send_error]. groups() -> []. @@ -2086,8 +2086,39 @@ test_pktoptions(Family, Spec, CheckConnect, OSType, OSVer) -> %%% {ok,<<"hi">>} = gen_tcp:recv(S1, 2, Timeout), %% %% Verify returned remote options - {ok,[{pktoptions,OptsVals1}]} = inet:getopts(S1, [pktoptions]), - {ok,[{pktoptions,OptsVals2}]} = inet:getopts(S2, [pktoptions]), + VerifyRemOpts = + fun(S, Role) -> + case inet:getopts(S, [pktoptions]) of + {ok, [{pktoptions, PktOpts1}]} -> + PktOpts1; + {ok, UnexpOK1} -> + io:format("Unexpected OK (~w): " + "~n ~p" + "~n", [Role, UnexpOK1]), + exit({unexpected_getopts_ok, + Role, + Spec, + TrueRecvOpts, + OptsVals, + OptsValsDefault, + UnexpOK1}); + {error, UnexpERR1} -> + io:format("Unexpected ERROR (~w): " + "~n ~p" + "~n", [Role, UnexpERR1]), + exit({unexpected_getopts_failure, + Role, + Spec, + TrueRecvOpts, + OptsVals, + OptsValsDefault, + UnexpERR1}) + end + end, + OptsVals1 = VerifyRemOpts(S1, dest), + OptsVals2 = VerifyRemOpts(S2, orig), + %% {ok,[{pktoptions,OptsVals1}]} = inet:getopts(S1, [pktoptions]), + %% {ok,[{pktoptions,OptsVals2}]} = inet:getopts(S2, [pktoptions]), (Result1 = sets_eq(OptsVals1, OptsVals)) orelse io:format( "Accept differs: ~p neq ~p~n", [OptsVals1,OptsVals]), @@ -3427,3 +3458,32 @@ otp_12242(Addr) when tuple_size(Addr) =:= 4 -> wait(Mref) -> receive {'DOWN',Mref,_,_,Reason} -> Reason end. + +%% OTP-15536 +%% Test that send error works correctly for delay_send +delay_send_error(_Config) -> + {ok, LS} = gen_tcp:listen(0, [{reuseaddr, true}, {packet, 1}, {active, false}]), + {ok,{{0,0,0,0},PortNum}}=inet:sockname(LS), + P = spawn_link( + fun() -> + {ok, S} = gen_tcp:accept(LS), + receive die -> gen_tcp:close(S) end + end), + erlang:monitor(process, P), + {ok, S} = gen_tcp:connect("localhost", PortNum, + [{packet, 1}, {active, false}, {delay_send, true}]), + + %% Do a couple of sends first to see that it works + ok = gen_tcp:send(S, "hello"), + ok = gen_tcp:send(S, "hello"), + ok = gen_tcp:send(S, "hello"), + + %% Make the receiver close + P ! die, + receive _Down -> ok end, + + ok = gen_tcp:send(S, "hello"), + timer:sleep(500), %% Sleep in order for delay_send to have time to trigger + + %% This used to result in a double free + {error, closed} = gen_tcp:send(S, "hello"). diff --git a/lib/kernel/test/inet_SUITE.erl b/lib/kernel/test/inet_SUITE.erl index f436eafad3..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, @@ -97,7 +98,7 @@ end_per_group(_GroupName, Config) -> init_per_testcase(lookup_bad_search_option, Config) -> Db = inet_db, Key = res_lookup, - %% The bad option can not enter through inet_db:set_lookup/1, + %% The bad option cannot enter through inet_db:set_lookup/1, %% but through e.g .inetrc. Prev = ets:lookup(Db, Key), ets:delete(Db, Key), @@ -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/inet_res_SUITE.erl b/lib/kernel/test/inet_res_SUITE.erl index df6e48abae..cbec8d430c 100644 --- a/lib/kernel/test/inet_res_SUITE.erl +++ b/lib/kernel/test/inet_res_SUITE.erl @@ -531,7 +531,7 @@ edns0(Config) when is_list(Config) -> case os:version() of {M,V,_} when M < 5; M == 5, V =< 8 -> %% In our test park only known platform - %% with an DNS resolver that can not do + %% with an DNS resolver that cannot do %% EDNS0. {comment,"No EDNS0"} end diff --git a/lib/kernel/test/init_SUITE.erl b/lib/kernel/test/init_SUITE.erl index 6a006cdc01..a0154b2694 100644 --- a/lib/kernel/test/init_SUITE.erl +++ b/lib/kernel/test/init_SUITE.erl @@ -295,7 +295,7 @@ is_real_system(KernelVsn, StdlibVsn) -> %% before restart. %% ------------------------------------------------ many_restarts() -> - [{timetrap,{minutes,8}}]. + [{timetrap,{minutes,16}}]. many_restarts(Config) when is_list(Config) -> {ok, Node} = loose_node:start(init_test, "", ?DEFAULT_TIMEOUT_SEC), @@ -315,7 +315,7 @@ loop_restart(N,Node,EHPid) -> loose_node:stop(Node), ct:fail(not_stopping) end, - ok = wait_for(30, Node, EHPid), + ok = wait_for(60, Node, EHPid), loop_restart(N-1,Node,rpc:call(Node,erlang,whereis,[logger])). wait_for(0,Node,_) -> @@ -367,7 +367,8 @@ restart(Config) when is_list(Config) -> SysProcs0 = rpc:call(Node, ?MODULE, find_system_processes, []), io:format("SysProcs0=~p~n", [SysProcs0]), [InitPid, PurgerPid, LitCollectorPid, - DirtySigNPid, DirtySigHPid, DirtySigMPid] = SysProcs0, + DirtySigNPid, DirtySigHPid, DirtySigMPid, + PrimFilePid] = SysProcs0, InitPid = rpc:call(Node, erlang, whereis, [init]), PurgerPid = rpc:call(Node, erlang, whereis, [erts_code_purger]), Procs = rpc:call(Node, erlang, processes, []), @@ -385,7 +386,8 @@ restart(Config) when is_list(Config) -> SysProcs1 = rpc:call(Node, ?MODULE, find_system_processes, []), io:format("SysProcs1=~p~n", [SysProcs1]), [InitPid1, PurgerPid1, LitCollectorPid1, - DirtySigNPid1, DirtySigHPid1, DirtySigMPid1] = SysProcs1, + DirtySigNPid1, DirtySigHPid1, DirtySigMPid1, + PrimFilePid1] = SysProcs1, %% Still the same init process! InitPid1 = rpc:call(Node, erlang, whereis, [init]), @@ -411,6 +413,10 @@ restart(Config) when is_list(Config) -> DirtySigMP = pid_to_list(DirtySigMPid), DirtySigMP = pid_to_list(DirtySigMPid1), + %% and same prim_file helper process! + PrimFileP = pid_to_list(PrimFilePid), + PrimFileP = pid_to_list(PrimFilePid1), + NewProcs0 = rpc:call(Node, erlang, processes, []), NewProcs = NewProcs0 -- SysProcs1, case check_processes(NewProcs, MaxPid) of @@ -437,7 +443,8 @@ restart(Config) when is_list(Config) -> literal_collector, dirty_sig_handler_normal, dirty_sig_handler_high, - dirty_sig_handler_max}). + dirty_sig_handler_max, + prim_file}). find_system_processes() -> find_system_procs(processes(), #sys_procs{}). @@ -448,10 +455,11 @@ find_system_procs([], SysProcs) -> SysProcs#sys_procs.literal_collector, SysProcs#sys_procs.dirty_sig_handler_normal, SysProcs#sys_procs.dirty_sig_handler_high, - SysProcs#sys_procs.dirty_sig_handler_max]; + SysProcs#sys_procs.dirty_sig_handler_max, + SysProcs#sys_procs.prim_file]; find_system_procs([P|Ps], SysProcs) -> case process_info(P, [initial_call, priority]) of - [{initial_call,{otp_ring0,start,2}},_] -> + [{initial_call,{erl_init,start,2}},_] -> undefined = SysProcs#sys_procs.init, find_system_procs(Ps, SysProcs#sys_procs{init = P}); [{initial_call,{erts_code_purger,start,0}},_] -> @@ -472,6 +480,9 @@ find_system_procs([P|Ps], SysProcs) -> {priority,max}] -> undefined = SysProcs#sys_procs.dirty_sig_handler_max, find_system_procs(Ps, SysProcs#sys_procs{dirty_sig_handler_max = P}); + [{initial_call,{prim_file,start,0}},_] -> + undefined = SysProcs#sys_procs.prim_file, + find_system_procs(Ps, SysProcs#sys_procs{prim_file = P}); _ -> find_system_procs(Ps, SysProcs) end. 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/kernel_bench.spec b/lib/kernel/test/kernel_bench.spec index 4de133f21b..898ceb59e0 100644 --- a/lib/kernel/test/kernel_bench.spec +++ b/lib/kernel/test/kernel_bench.spec @@ -1,2 +1,3 @@ {groups,"../kernel_test",zlib_SUITE,[bench]}. {groups,"../kernel_test",file_SUITE,[bench]}. +{suites,"../kernel_test",[logger_stress_SUITE]}. diff --git a/lib/kernel/test/kernel_config_SUITE.erl b/lib/kernel/test/kernel_config_SUITE.erl index 9207025a2c..57c44c2498 100644 --- a/lib/kernel/test/kernel_config_SUITE.erl +++ b/lib/kernel/test/kernel_config_SUITE.erl @@ -21,7 +21,8 @@ -include_lib("common_test/include/ct.hrl"). --export([all/0, suite/0,groups/0,init_per_group/2,end_per_group/2, sync/1]). +-export([all/0, suite/0,groups/0,init_per_group/2,end_per_group/2, + start_distribution_false/1, sync/1]). -export([init_per_suite/1, end_per_suite/1]). @@ -30,7 +31,7 @@ suite() -> {timetrap,{minutes,2}}]. all() -> - [sync]. + [sync, start_distribution_false]. groups() -> []. @@ -59,12 +60,9 @@ from(H, [H | T]) -> T; from(H, [_ | T]) -> from(H, T); from(_, []) -> []. -%%----------------------------------------------------------------- -%% Test suite for sync_nodes. This is quite tricky. -%% +%% Test sync_nodes. This is quite tricky. %% Should be started in a CC view with: %% erl -sname XXX where XX not in [cp1, cp2] -%%----------------------------------------------------------------- sync(Conf) when is_list(Conf) -> %% Write a config file Dir = proplists:get_value(priv_dir,Conf), @@ -106,9 +104,18 @@ wait_for_node(Node) -> _Other -> wait_for_node(Node) end. - stop_node(Node) -> M = list_to_atom(lists:concat([Node, [$@], from($@,atom_to_list(node()))])), rpc:cast(M, erlang, halt, []). + +start_distribution_false(Config) when is_list(Config) -> + %% When distribution is disabled, -sname/-name has no effect + Str = os:cmd(ct:get_progname() + ++ " -kernel start_distribution false" + ++ " -sname no_distribution" + ++ " -eval \"erlang:display(node())\"" + ++ " -noshell -s erlang halt"), + "'nonode@nohost'" ++ _ = Str, + ok. diff --git a/lib/kernel/test/logger.cover b/lib/kernel/test/logger.cover index 960bc0abff..9691aa295e 100644 --- a/lib/kernel/test/logger.cover +++ b/lib/kernel/test/logger.cover @@ -4,9 +4,12 @@ logger_backend, logger_config, logger_disk_log_h, - logger_h_common, logger_filters, logger_formatter, + logger_handler_watcher, + logger_h_common, + logger_olp, + logger_proxy, logger_server, logger_simple_h, logger_std_h, diff --git a/lib/kernel/test/logger.spec b/lib/kernel/test/logger.spec index 1ab90b3e93..3aec37951d 100644 --- a/lib/kernel/test/logger.spec +++ b/lib/kernel/test/logger.spec @@ -7,5 +7,7 @@ logger_filters_SUITE, logger_formatter_SUITE, logger_legacy_SUITE, + logger_olp_SUITE, + logger_proxy_SUITE, logger_simple_h_SUITE, logger_std_h_SUITE]}. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index d831d0d108..035e5d8974 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -101,7 +101,8 @@ all() -> compare_levels, process_metadata, app_config, - kernel_config]. + kernel_config, + pretty_print]. start_stop(_Config) -> S = whereis(logger), @@ -898,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}), @@ -1047,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 @@ -1059,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}}}]]), @@ -1141,6 +1146,61 @@ kernel_config(Config) -> ok. +pretty_print(Config) -> + ok = logger:add_handler(?FUNCTION_NAME,logger_std_h,#{}), + ok = logger:set_module_level([module1,module2],debug), + + ct:capture_start(), + logger:i(), + ct:capture_stop(), + I0 = ct:capture_get(), + + ct:capture_start(), + logger:i(primary), + ct:capture_stop(), + IPrim = ct:capture_get(), + + ct:capture_start(), + logger:i(handlers), + ct:capture_stop(), + IHs = ct:capture_get(), + + ct:capture_start(), + logger:i(proxy), + ct:capture_stop(), + IProxy = ct:capture_get(), + + ct:capture_start(), + logger:i(modules), + ct:capture_stop(), + IMs = ct:capture_get(), + + I02 = lists:append([IPrim,IHs,IProxy,IMs]), + %% ct:log("~p~n",[I0]), + %% ct:log("~p~n",[I02]), + I0 = I02, + + ct:capture_start(), + logger:i(handlers), + ct:capture_stop(), + IHs = ct:capture_get(), + + Ids = logger:get_handler_ids(), + IHs2 = + lists:append( + [begin + ct:capture_start(), + logger:i(Id), + ct:capture_stop(), + [_|IH] = ct:capture_get(), + IH + end || Id <- Ids]), + + %% ct:log("~p~n",[IHs]), + %% ct:log("~p~n",[["Handler configuration: \n"|IHs2]]), + IHs = ["Handler configuration: \n"|IHs2], + ok. + %%%----------------------------------------------------------------- %%% Internal check_logged(Level,Format,Args,Meta) -> diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 87b8250781..36d98eaa25 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -24,6 +24,7 @@ -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_olp.hrl"). -include_lib("kernel/src/logger_h_common.hrl"). -include_lib("stdlib/include/ms_transform.hrl"). -include_lib("kernel/include/file.hrl"). @@ -97,7 +98,6 @@ all() -> formatter_fail, config_fail, bad_input, - info_and_reset, reconfig, sync, disk_log_full, @@ -293,7 +293,7 @@ logging(Config) -> ok = start_and_add(Name, #{filter_default=>log, formatter=>{?MODULE,self()}}, #{file => LogFile}), - MsgFormatter = fun(Term) -> {io_lib:format("Term:~p",[Term]),[]} end, + MsgFormatter = fun(Term) -> {"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)]), @@ -306,9 +306,9 @@ logging(cleanup, _Config) -> filter_config(_Config) -> ok = logger:add_handler(?MODULE,logger_disk_log_h,#{}), {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), - HConfig = maps:without([handler_pid,mode_tab],HConfig), + HConfig = maps:without([olp],HConfig), - FakeFullHConfig = HConfig#{handler_pid=>self(),mode_tab=>erlang:make_ref()}, + FakeFullHConfig = HConfig#{olp=>{regname,self(),erlang:make_ref()}}, #{config:=HConfig} = logger_disk_log_h:filter_config(Config#{config=>FakeFullHConfig}), ok. @@ -351,9 +351,7 @@ errors(Config) -> %% Read-only fields may (accidentially) be included in the change, %% but it won't take effect {ok,C} = logger:get_handler_config(Name1), - ok = logger:set_handler_config(Name1,config, - #{handler_pid=>self(), - mode_tab=>erlang:make_ref()}), + ok = logger:set_handler_config(Name1,config,#{olp=>dummyvalue}), {ok,C} = logger:get_handler_config(Name1), @@ -419,19 +417,16 @@ config_fail(_Config) -> filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_config,logger_disk_log_h, - {invalid_levels,#{drop_mode_qlen:=1}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=1}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_config,logger_disk_log_h, - {invalid_levels,#{sync_mode_qlen:=43, - drop_mode_qlen:=42}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_config,logger_disk_log_h, - {invalid_levels,#{drop_mode_qlen:=43, - flush_qlen:=42}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -445,7 +440,7 @@ config_fail(_Config) -> #{max_no_files=>2}), %% incorrect values of OP params {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), - {error,{invalid_config,logger_disk_log_h,{invalid_levels,_}}} = + {error,{invalid_olp_levels,_}} = logger:update_handler_config(?MODULE,config, HConfig#{sync_mode_qlen=>100, flush_qlen=>99}), @@ -459,18 +454,7 @@ config_fail(cleanup,_Config) -> 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). + logger_disk_log_h:filesync("BadType"). reconfig(Config) -> Dir = ?config(priv_dir,Config), @@ -479,7 +463,7 @@ reconfig(Config) -> #{filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{id := ?MODULE, + #{%id := ?MODULE, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -490,13 +474,14 @@ reconfig(Config) -> 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, - handler_state := - #{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), + cb_state := + #{handler_state := + #{log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + file := DiskLogFile}}, + filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL}} = + logger_olp:info(h_proc_name()), {ok,#{config := #{sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, @@ -527,7 +512,7 @@ reconfig(Config) -> overload_kill_restart_after => infinity, filesync_repeat_interval => no_repeat}, ok = logger:set_handler_config(?MODULE, config, HConfig1), - #{id := ?MODULE, + #{%id := ?MODULE, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -538,8 +523,8 @@ reconfig(Config) -> 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), + cb_state := #{filesync_repeat_interval := no_repeat}} = + logger_olp:info(h_proc_name()), {ok,#{config:=HConfig1}} = logger:get_handler_config(?MODULE), ok = logger:update_handler_config(?MODULE, config, @@ -577,12 +562,13 @@ reconfig(Config) -> max_no_files => 1, max_no_bytes => 1024, file => File}}), - #{handler_state := - #{log_opts := #{type := halt, - max_no_files := 1, - max_no_bytes := 1024, - file := File}}} = - logger_disk_log_h:info(?MODULE), + #{cb_state := + #{handler_state := + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}}}} = + logger_olp:info(h_proc_name()), {ok,#{config := #{type := halt, max_no_files := 1, @@ -650,13 +636,8 @@ sync(Config) -> {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, ok = logger:update_handler_config(?MODULE, config, HConfig1), - no_repeat = maps:get(filesync_repeat_interval, - logger_disk_log_h:info(?MODULE)), - %% The following timer is to make sure the time from last log - %% ("first") to next ("second") is long enough, so the a flush is - %% triggered by the idle timeout between "fourth" and "fifth". - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + maps:get(cb_state,logger_olp:info(h_proc_name()))), start_tracer([{logger_disk_log_h,disk_log_write,3}, {disk_log,sync,1}], @@ -666,10 +647,10 @@ sync(Config) -> {disk_log,sync}]), logger:notice("second", ?domain), - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + timer:sleep(?IDLE_DETECT_TIME*2), logger:notice("third", ?domain), %% wait for automatic disk_log_sync - check_tracer(?IDLE_DETECT_TIME_MSEC*2), + check_tracer(?IDLE_DETECT_TIME*2), try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), @@ -678,14 +659,15 @@ sync(Config) -> WaitT = 4500, OneSync = {logger_h_common,handle_cast,repeated_filesync}, %% receive 1 repeated_filesync per sec - start_tracer([{logger_h_common,handle_cast,2}], + start_tracer([{{logger_h_common,handle_cast,2}, + [{[repeated_filesync,'_'],[],[{message,{caller}}]}]}], [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, ok = logger:update_handler_config(?MODULE, config, HConfig2), SyncInt = maps:get(filesync_repeat_interval, - logger_disk_log_h:info(?MODULE)), + maps:get(cb_state,logger_olp:info(h_proc_name()))), timer:sleep(WaitT), HConfig3 = HConfig#{filesync_repeat_interval => no_repeat}, ok = logger:update_handler_config(?MODULE, config, HConfig3), @@ -803,7 +785,7 @@ disk_log_full(cleanup, _Config) -> dbg:stop_clear(), logger:remove_handler(?MODULE). -disk_log_events(Config) -> +disk_log_events(_Config) -> Node = node(), Log = ?MODULE, ok = logger:add_handler(?MODULE, @@ -860,10 +842,12 @@ write_failure(Config) -> 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_write,ok]), - HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, - maps:get(handler_state,HState))]), - + HState = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + LogOpts = maps:get(log_opts, + maps:get(handler_state, + maps:get(cb_state,HState))), + ct:pal("LogOpts = ~p", [LogOpts]), + %% ?check and ?check_no_log in this test only check for internal log events ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), @@ -914,15 +898,16 @@ sync_failure(Config) -> 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, maps:get(handler_state,HState)), + HState = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + LogOpts = maps:get(log_opts, maps:get(handler_state, + maps:get(cb_state,HState))), SyncInt = 500, ok = rpc:call(Node, logger, update_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), + Info = rpc:call(Node, logger_olp, info, [h_proc_name(?STANDARD_HANDLER)]), + SyncInt = maps:get(filesync_repeat_interval, maps:get(cb_state, Info)), ok = log_on_remote_node(Node, "Logged1"), ?check_no_log, @@ -1198,7 +1183,7 @@ qlen_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -1208,7 +1193,7 @@ qlen_kill_new(Config) -> ok after 5000 -> - Info = logger_disk_log_h:info(?MODULE), + Info = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info]), ct:fail("Handler not dead! It should not have survived this!") end. @@ -1235,7 +1220,7 @@ mem_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -1245,7 +1230,7 @@ mem_kill_new(Config) -> ok after 5000 -> - Info = logger_disk_log_h:info(?MODULE), + Info = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info]), ct:fail("Handler not dead! It should not have survived this!") end. @@ -1258,12 +1243,12 @@ 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_qlen=>4, overload_kill_restart_after=>infinity}}, ok = logger:update_handler_config(?MODULE, NewHConfig1), MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler - send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), + send_burst({n,100}, {spawn,5,0}, {chars,79}, notice), receive {'DOWN', MRef1, _, _, _Reason1} -> file_delete(Log), @@ -1271,7 +1256,7 @@ restart_after(Config) -> ok after 5000 -> - Info1 = logger_std_h:info(?MODULE), + Info1 = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, @@ -1280,13 +1265,13 @@ restart_after(Config) -> RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, NewHConfig2 = HConfig#{config=>DLHConfig#{overload_kill_enable=>true, - overload_kill_qlen=>10, + overload_kill_qlen=>4, overload_kill_restart_after=>RestartAfter}}, ok = logger:update_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), + send_burst({n,100}, {spawn,5,0}, {chars,79}, notice), receive {'DOWN', MRef2, _, _, _Reason2} -> file_delete(Log), @@ -1295,7 +1280,7 @@ restart_after(Config) -> ok after 5000 -> - Info2 = logger_std_h:info(?MODULE), + Info2 = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info2]), ct:fail("Handler not dead! It should not have survived this!") end, @@ -1316,11 +1301,15 @@ handler_requests_under_load(Config) -> flush_qlen => 2000, burst_limit_enable => false}}, ok = logger:update_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, - {info,[]}, - {reset,[]}, - {change_config,[]}]) - end), + Pid = spawn_link( + fun() -> send_requests(1,[{logger_disk_log_h,filesync,[?MODULE],[]}, + {logger_olp,info,[h_proc_name()],[]}, + {logger_olp,reset,[h_proc_name()],[]}, + {logger,update_handler_config, + [?MODULE, config, + #{overload_kill_enable => false}], + []}]) + end), Procs = 100, Sent = Procs * send_burst({n,5000}, {spawn,Procs,10}, {chars,79}, notice), Pid ! {self(),finish}, @@ -1332,29 +1321,22 @@ handler_requests_under_load(Config) -> [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), + Errors = [{Func,FindError(Res)} || {_,Func,_,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]) -> +send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> receive {From,finish} -> From ! {self(),Reqs} after TO -> - Result = - case Req of - change_config -> - logger:update_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]}]) + Result = apply(Mod,Func,Args), + send_requests(TO, Rs ++ [{Mod,Func,Args,[Result|Res]}]) end. %%%----------------------------------------------------------------- @@ -1472,15 +1454,6 @@ 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), @@ -1607,7 +1580,9 @@ start_tracer(Trace,Expected) -> ok. tpl([{M,F,A}|Trace]) -> - {ok,Match} = dbg:tpl(M,F,A,c), + tpl([{{M,F,A},c}|Trace]); +tpl([{{M,F,A},MS}|Trace]) -> + {ok,Match} = dbg:tpl(M,F,A,MS), case lists:keyfind(matched,1,Match) of {_,_,1} -> ok; diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index e8d1a313dc..9d2ad11be8 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -59,7 +59,8 @@ groups() -> logger_undefined, logger_many_handlers_default_first, logger_many_handlers_default_last, - logger_many_handlers_default_last_broken_filter + logger_many_handlers_default_last_broken_filter, + logger_proxy ]}, {bad,[],[bad_error_logger, bad_level, @@ -541,6 +542,19 @@ logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> ok. +logger_proxy(Config) -> + %% assume current node runs with default settings + DefOpts = logger_olp:get_opts(logger_proxy), + {ok,_,Node} = setup(Config, + [{logger,[{proxy,#{sync_mode_qlen=>0, + drop_mode_qlen=>2}}]}]), + Expected = DefOpts#{sync_mode_qlen:=0, + drop_mode_qlen:=2}, + Expected = rpc:call(Node,logger_olp,get_opts,[logger_proxy]), + Expected = rpc:call(Node,logger,get_proxy_config,[]), + + ok. + sasl_compatible_false(Config) -> Log = file(Config,?FUNCTION_NAME), {ok,_,Node} = setup(Config, 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_olp_SUITE.erl b/lib/kernel/test/logger_olp_SUITE.erl new file mode 100644 index 0000000000..ea3eec89f5 --- /dev/null +++ b/lib/kernel/test/logger_olp_SUITE.erl @@ -0,0 +1,90 @@ +%% +%% %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_olp_SUITE). + +-compile(export_all). + +-include_lib("kernel/src/logger_olp.hrl"). + +suite() -> + [{timetrap,{seconds,30}}]. + +init_per_suite(Config) -> + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [idle_timer]. + +%%%----------------------------------------------------------------- +%%% Test cases +idle_timer(_Config) -> + {ok,_Pid,Olp} = logger_olp:start_link(?MODULE,?MODULE,self(),#{}), + [logger_olp:load(Olp,{msg,N}) || N<-lists:seq(1,3)], + timer:sleep(?IDLE_DETECT_TIME*2), + [{load,{msg,1}}, + {load,{msg,2}}, + {load,{msg,3}}, + {notify,idle}] = test_server:messages_get(), + logger_olp:cast(Olp,hello), + timer:sleep(?IDLE_DETECT_TIME*2), + [{cast,hello}] = test_server:messages_get(), + ok. +idle_timer(cleanup,_Config) -> + unlink(whereis(?MODULE)), + logger_olp:stop(?MODULE), + ok. + +%%%----------------------------------------------------------------- +%%% Olp callbacks +init(P) -> + {ok,P}. + +handle_load(M,P) -> + P ! {load,M}, + P. + +handle_cast(M,P) -> + P ! {cast,M}, + {noreply,P}. + +notify(N,P) -> + P ! {notify,N}, + P. diff --git a/lib/kernel/test/logger_proxy_SUITE.erl b/lib/kernel/test/logger_proxy_SUITE.erl new file mode 100644 index 0000000000..777531e4ed --- /dev/null +++ b/lib/kernel/test/logger_proxy_SUITE.erl @@ -0,0 +1,274 @@ +%% +%% %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_proxy_SUITE). + +-compile(export_all). + +%% -include_lib("common_test/include/ct.hrl"). +%% -include_lib("kernel/include/logger.hrl"). +%% -include_lib("kernel/src/logger_internal.hrl"). + +%% -define(str,"Log from "++atom_to_list(?FUNCTION_NAME)++ +%% ":"++integer_to_list(?LINE)). +%% -define(map_rep,#{function=>?FUNCTION_NAME, line=>?LINE}). +%% -define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]). + +%% -define(MY_LOC(N),#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY}, +%% file=>?FILE, line=>?LINE-N}). + +%% -define(TRY(X), my_try(fun() -> X end)). + + +-define(HNAME,list_to_atom(lists:concat([?MODULE,"_",?FUNCTION_NAME]))). +-define(LOC,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY},line=>?LINE}). +-define(ENSURE_TIME,5000). + +suite() -> + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. + +init_per_suite(Config) -> + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [basic, + emulator, + remote, + remote_emulator, + config, + restart_after, + terminate]. + +%%%----------------------------------------------------------------- +%%% Test cases +basic(_Config) -> + ok = logger:add_handler(?HNAME,?MODULE,#{config=>self()}), + logger_proxy ! {log,notice,"Log from: ~p; ~p",[?FUNCTION_NAME,?LINE],L1=?LOC}, + ok = ensure(L1), + logger_proxy ! {log,notice,[{test_case,?FUNCTION_NAME},{line,?LINE}],L2=?LOC}, + ok = ensure(L2), + logger_proxy:log({remote,node(),{log,notice, + "Log from: ~p; ~p", + [?FUNCTION_NAME,?LINE], + L3=?LOC}}), + ok = ensure(L3), + logger_proxy:log({remote,node(),{log,notice, + [{test_case,?FUNCTION_NAME}, + {line,?LINE}], + L4=?LOC}}), + ok = ensure(L4), + ok. +basic(cleanup,_Config) -> + ok = logger:remove_handler(?HNAME). + +emulator(_Config) -> + ok = logger:add_handler(?HNAME,?MODULE,#{config=>self()}), + Pid = spawn(fun() -> erlang:error(some_reason) end), + ok = ensure(#{pid=>Pid}), + ok. +emulator(cleanup,_Config) -> + ok = logger:remove_handler(?HNAME). + +remote(Config) -> + {ok,_,Node} = logger_test_lib:setup(Config,[{logger,[{proxy,#{}}]}]), + ok = logger:add_handler(?HNAME,?MODULE,#{config=>self()}), + L1 = ?LOC, spawn(Node,fun() -> logger:notice("Log from ~p; ~p",[?FUNCTION_NAME,?LINE],L1) end), + ok = ensure(L1), + L2 = ?LOC, spawn(Node,fun() -> logger:notice([{test_case,?FUNCTION_NAME},{line,?LINE}],L2) end), + ok = ensure(L2), + ok. +remote(cleanup,_Config) -> + ok = logger:remove_handler(?HNAME). + +remote_emulator(Config) -> + {ok,_,Node} = logger_test_lib:setup(Config,[{logger,[{proxy,#{}}]}]), + ok = logger:add_handler(?HNAME,?MODULE,#{config=>self()}), + Pid = spawn(Node,fun() -> erlang:error(some_reason) end), + ok = ensure(#{pid=>Pid}), + ok. +remote_emulator(cleanup,_Config) -> + ok = logger:remove_handler(?HNAME). + +config(_Config) -> + C1 = #{sync_mode_qlen:=SQ, + drop_mode_qlen:=DQ} = logger:get_proxy_config(), + C1 = logger_olp:get_opts(logger_proxy), + + %% Update the existing config with these two values + SQ1 = SQ+1, + DQ1 = DQ+1, + ok = logger:update_proxy_config(#{sync_mode_qlen=>SQ1, + drop_mode_qlen=>DQ1}), + C2 = logger:get_proxy_config(), % reads from ets table + C2 = logger_olp:get_opts(logger_proxy), % ensure consistency with process opts + C2 = C1#{sync_mode_qlen:=SQ1, + drop_mode_qlen:=DQ1}, + + %% Update the existing again with only one value + SQ2 = SQ+2, + ok = logger:update_proxy_config(#{sync_mode_qlen=>SQ2}), + C3 = logger:get_proxy_config(), + C3 = logger_olp:get_opts(logger_proxy), + C3 = C2#{sync_mode_qlen:=SQ2}, + + %% Set the config, i.e. merge with defaults + ok = logger:set_proxy_config(#{sync_mode_qlen=>SQ1}), + C4 = logger:get_proxy_config(), + C4 = logger_olp:get_opts(logger_proxy), + C4 = C1#{sync_mode_qlen:=SQ1}, + + %% Reset to default + ok = logger:set_proxy_config(#{}), + C5 = logger:get_proxy_config(), + C5 = logger_olp:get_opts(logger_proxy), + C5 = logger_proxy:get_default_config(), + + %% Errors + {error,{invalid_olp_config,_}} = + logger:set_proxy_config(#{faulty_key=>1}), + {error,{invalid_olp_config,_}} = + logger:set_proxy_config(#{sync_mode_qlen=>infinity}), + {error,{invalid_config,[]}} = logger:set_proxy_config([]), + + {error,{invalid_olp_config,_}} = + logger:update_proxy_config(#{faulty_key=>1}), + {error,{invalid_olp_config,_}} = + logger:update_proxy_config(#{sync_mode_qlen=>infinity}), + {error,{invalid_config,[]}} = logger:update_proxy_config([]), + + C5 = logger:get_proxy_config(), + C5 = logger_olp:get_opts(logger_proxy), + + ok. +config(cleanup,_Config) -> + _ = logger:set_logger_proxy(logger_proxy:get_default_config()), + ok. + +restart_after(_Config) -> + Restart = 3000, + ok = logger:update_proxy_config(#{overload_kill_enable => true, + overload_kill_qlen => 10, + overload_kill_restart_after => Restart}), + Proxy = whereis(logger_proxy), + Proxy = erlang:system_info(system_logger), + ProxyConfig = logger:get_proxy_config(), + ProxyConfig = logger_olp:get_opts(logger_proxy), + + Ref = erlang:monitor(process,Proxy), + spawn(fun() -> + [logger_proxy ! {log,debug, + [{test_case,?FUNCTION_NAME}, + {line,?LINE}], + ?LOC} || _ <- lists:seq(1,100)] + end), + receive + {'DOWN',Ref,_,_,_Reason} -> + undefined = erlang:system_info(system_logger), + timer:sleep(Restart), + poll_restarted(10) + after 5000 -> + ct:fail(proxy_not_terminated) + end, + + Proxy1 = whereis(logger_proxy), + Proxy1 = erlang:system_info(system_logger), + ProxyConfig = logger:get_proxy_config(), + ProxyConfig = logger_olp:get_opts(logger_proxy), + + ok. +restart_after(cleanup,_Config) -> + _ = logger:set_logger_proxy(logger_proxy:get_default_config()), + ok. + +%% Test that system_logger flag is set to logger process if +%% logger_proxy terminates for other reason than overloaded. +terminate(_Config) -> + Logger = whereis(logger), + Proxy = whereis(logger_proxy), + Proxy = erlang:system_info(system_logger), + ProxyConfig = logger:get_proxy_config(), + ProxyConfig = logger_olp:get_opts(logger_proxy), + + Ref = erlang:monitor(process,Proxy), + ok = logger_olp:stop(Proxy), + receive + {'DOWN',Ref,_,_,_Reason} -> + Logger = erlang:system_info(system_logger), + logger_proxy:restart(), + poll_restarted(10) + after 5000 -> + ct:fail(proxy_not_terminated) + end, + + Proxy1 = whereis(logger_proxy), + Proxy1 = erlang:system_info(system_logger), + ProxyConfig = logger:get_proxy_config(), + ProxyConfig = logger_olp:get_opts(logger_proxy), + + ok. + +%%%----------------------------------------------------------------- +%%% Internal functions + +poll_restarted(0) -> + ct:fail(proxy_not_restarted); +poll_restarted(N) -> + timer:sleep(1000), + case whereis(logger_proxy) of + undefined -> + poll_restarted(N-1); + _Pid -> + ok + end. + +%% Logger handler callback +log(#{meta:=Meta},#{config:=Pid}) -> + Pid ! {logged,Meta}. + +%% Check that the log from the logger callback function log/2 is received +ensure(Match) -> + receive {logged,Meta} -> + case maps:with(maps:keys(Match),Meta) of + Match -> ok; + _NoMatch -> {error,Match,Meta,test_server:messages_get()} + end + after ?ENSURE_TIME -> {error,Match,test_server:messages_get()} + end. diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index eb17a6d857..0c5516f82b 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -25,10 +25,15 @@ -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). -include_lib("kernel/src/logger_h_common.hrl"). +-include_lib("kernel/src/logger_olp.hrl"). -include_lib("stdlib/include/ms_transform.hrl"). -include_lib("kernel/include/file.hrl"). --define(check_no_log, [] = test_server:messages_get()). +-define(check_no_log, + begin + timer:sleep(?IDLE_DETECT_TIME*2), + [] = test_server:messages_get() + end). -define(check(Expected), receive {log,Expected} -> @@ -107,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, @@ -115,7 +122,6 @@ all() -> crash_std_h_to_file, crash_std_h_to_disk_log, bad_input, - info_and_reset, reconfig, file_opts, sync, @@ -137,7 +143,13 @@ all() -> mem_kill_std, restart_after, handler_requests_under_load, - recreate_deleted_log + recreate_deleted_log, + reopen_changed_log, + rotate_size, + rotate_size_compressed, + rotate_size_reopen, + rotation_opts, + rotation_opts_restart_handler ]. add_remove_instance_tty(_Config) -> @@ -174,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()}}), @@ -209,9 +238,9 @@ default_formatter(_Config) -> filter_config(_Config) -> ok = logger:add_handler(?MODULE,logger_std_h,#{}), {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), - HConfig = maps:without([handler_pid,mode_tab],HConfig), + HConfig = maps:without([olp],HConfig), - FakeFullHConfig = HConfig#{handler_pid=>self(),mode_tab=>erlang:make_ref()}, + FakeFullHConfig = HConfig#{olp=>{regname,self(),erlang:make_ref()}}, #{config:=HConfig} = logger_std_h:filter_config(Config#{config=>FakeFullHConfig}), ok. @@ -246,15 +275,16 @@ errors(Config) -> _ -> NoDir = lists:concat(["/",?MODULE,"_dir"]), {error, - {handler_not_added,{{open_failed,NoDir,eacces},_}}} = + {handler_not_added,{open_failed,NoDir,eacces}}} = logger:add_handler(myh2,logger_std_h, #{config=>#{type=>{file,NoDir}}}) end, {error, - {handler_not_added,{{open_failed,Log,_},_}}} = + {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). @@ -320,19 +350,16 @@ config_fail(_Config) -> #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_config,logger_std_h, - {invalid_levels,#{drop_mode_qlen:=1}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=1}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_config,logger_std_h, - {invalid_levels,#{sync_mode_qlen:=43, - drop_mode_qlen:=42}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_config,logger_std_h, - {invalid_levels,#{drop_mode_qlen:=43, - flush_qlen:=42}}}}} = + {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -344,7 +371,7 @@ config_fail(_Config) -> logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), - {error,{invalid_config,logger_std_h,{invalid_levels,_}}} = + {error,{invalid_olp_levels,_}} = logger:set_handler_config(?MODULE,config, #{sync_mode_qlen=>100, flush_qlen=>99}), @@ -355,9 +382,7 @@ config_fail(_Config) -> %% Read-only fields may (accidentially) be included in the change, %% but it won't take effect {ok,C} = logger:get_handler_config(?MODULE), - ok = logger:set_handler_config(?MODULE,config, - #{handler_pid=>self(), - mode_tab=>erlang:make_ref()}), + ok = logger:set_handler_config(?MODULE,config,#{olp=>dummyvalue}), {ok,C} = logger:get_handler_config(?MODULE), ok. @@ -425,10 +450,13 @@ crash_std_h(Config,Func,Var,Type,Log) -> %% logger would send the log event to the logger process here instead %% of logging it itself. log_on_remote_node(Node,Msg) -> + Pid = self(), _ = spawn_link(Node, fun() -> erlang:group_leader(whereis(user),self()), - logger:notice(Msg) + logger:notice(Msg), + Pid ! done end), + receive done -> ok end, ok. @@ -456,14 +484,7 @@ sync_and_read(Node,file,Log) -> end. bad_input(_Config) -> - {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"), - {error,{badarg,{info,["BadType"]}}} = logger_std_h:info("BadType"), - {error,{badarg,{reset,["BadType"]}}} = logger_std_h:reset("BadType"). - - -info_and_reset(_Config) -> - #{id := ?STANDARD_HANDLER} = logger_std_h:info(?STANDARD_HANDLER), - ok = logger_std_h:reset(?STANDARD_HANDLER). + {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"). reconfig(Config) -> Dir = ?config(priv_dir,Config), @@ -473,9 +494,10 @@ reconfig(Config) -> filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{id := ?MODULE, - handler_state := #{type := standard_io, - file_ctrl_pid := FileCtrlPid}, + #{%id := ?MODULE, + cb_state:=#{handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, + filesync_repeat_interval := no_repeat}, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -485,9 +507,8 @@ reconfig(Config) -> 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 := no_repeat} = DefaultInfo = - logger_std_h:info(?MODULE), + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER} = + logger_olp:info(h_proc_name()), {ok, #{config:= @@ -518,9 +539,10 @@ reconfig(Config) -> overload_kill_mem_size => 10000000, overload_kill_restart_after => infinity, filesync_repeat_interval => 5000}), - #{id := ?MODULE, - handler_state := #{type := standard_io, - file_ctrl_pid := FileCtrlPid}, + #{%id := ?MODULE, + cb_state := #{handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, + filesync_repeat_interval := no_repeat}, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -530,8 +552,7 @@ reconfig(Config) -> overload_kill_enable := true, overload_kill_qlen := 100000, overload_kill_mem_size := 10000000, - overload_kill_restart_after := infinity, - filesync_repeat_interval := no_repeat} = Info = logger_std_h:info(?MODULE), + overload_kill_restart_after := infinity} = logger_olp:info(h_proc_name()), {ok,#{config := #{type := standard_io, @@ -611,22 +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()}}), - #{handler_state := #{type := OkType}} = logger_std_h:info(?MODULE), + ModOpts = [delayed_write|OkFileOpts], + #{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), + 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), @@ -642,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}]), @@ -658,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,12 +726,9 @@ sync(Config) -> %% a filesync is still performed when handler goes idle ok = logger:update_handler_config(?MODULE, config, #{filesync_repeat_interval => no_repeat}), - no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), - %% The following timer is to make sure the time from last log - %% ("second") to next ("third") is long enough, so the a flush is - %% triggered by the idle timeout between "thrid" and "fourth". - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{logger_std_h, write_to_dev, 5}, + 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, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, {file,datasync}, @@ -688,22 +736,24 @@ sync(Config) -> {file,datasync}]), logger:notice("third", ?domain), %% wait for automatic filesync - timer:sleep(?IDLE_DETECT_TIME_MSEC*2), + timer:sleep(?IDLE_DETECT_TIME*2), logger:notice("fourth", ?domain), %% wait for automatic filesync - check_tracer(?IDLE_DETECT_TIME_MSEC*2), + check_tracer(?IDLE_DETECT_TIME*2), %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, OneSync = {logger_h_common,handle_cast,repeated_filesync}, %% receive 1 repeated_filesync per sec - start_tracer([{logger_h_common,handle_cast,2}], + start_tracer([{{logger_h_common,handle_cast,2}, + [{[repeated_filesync,'_'],[],[]}]}], [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), ok = logger:update_handler_config(?MODULE, config, #{filesync_repeat_interval => SyncInt}), - SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), + SyncInt = maps:get(filesync_repeat_interval, + maps:get(cb_state,logger_olp:info(h_proc_name()))), timer:sleep(WaitT), ok = logger:update_handler_config(?MODULE, config, #{filesync_repeat_interval => no_repeat}), @@ -764,8 +814,6 @@ sync_failure(Config) -> ok = rpc:call(Node, logger, update_handler_config, [?STANDARD_HANDLER, config, #{filesync_repeat_interval => SyncInt}]), - Info = rpc:call(Node, logger_std_h, info, [?STANDARD_HANDLER]), - SyncInt = maps:get(filesync_repeat_interval, Info), ok = log_on_remote_node(Node, "Logged1"), ?check_no_log, @@ -1095,7 +1143,7 @@ qlen_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -1105,7 +1153,7 @@ qlen_kill_new(Config) -> ok after 5000 -> - Info = logger_std_h:info(?MODULE), + Info = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info]), ct:fail("Handler not dead! It should not have survived this!") end. @@ -1146,7 +1194,7 @@ mem_kill_new(Config) -> receive {'DOWN', MRef, _, _, Info} -> case Info of - {shutdown,{overloaded,?MODULE,QLen,Mem}} -> + {shutdown,{overloaded,QLen,Mem}} -> ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); killed -> ct:pal("Slow shutdown, handler process was killed!", []) @@ -1156,7 +1204,7 @@ mem_kill_new(Config) -> ok after 5000 -> - Info = logger_std_h:info(?MODULE), + Info = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info]), ct:fail("Handler not dead! It should not have survived this!") end. @@ -1187,7 +1235,7 @@ restart_after(Config) -> ok after 5000 -> - Info1 = logger_std_h:info(?MODULE), + Info1 = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, @@ -1212,7 +1260,7 @@ restart_after(Config) -> ok after 5000 -> - Info2 = logger_std_h:info(?MODULE), + Info2 = logger_olp:info(h_proc_name()), ct:pal("Handler state = ~p", [Info2]), ct:fail("Handler not dead! It should not have survived this!") end, @@ -1234,11 +1282,15 @@ handler_requests_under_load(Config) -> flush_qlen => 2000, burst_limit_enable => false}}, ok = logger:update_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, - {info,[]}, - {reset,[]}, - {change_config,[]}]) - end), + Pid = spawn_link( + fun() -> send_requests(1,[{logger_std_h,filesync,[?MODULE],[]}, + {logger_olp,info,[h_proc_name()],[]}, + {logger_olp,reset,[h_proc_name()],[]}, + {logger,update_handler_config, + [?MODULE, config, + #{overload_kill_enable => false}], + []}]) + end), Sent = send_burst({t,10000}, seq, {chars,79}, notice), Pid ! {self(),finish}, ReqResult = receive {Pid,Result} -> Result end, @@ -1249,8 +1301,9 @@ handler_requests_under_load(Config) -> [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), + Errors = [{Func,FindError(Res)} || {_,Func,_,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) -> @@ -1270,24 +1323,356 @@ recreate_deleted_log(Config) -> recreate_deleted_log(cleanup, _Config) -> ok = stop_handler(?MODULE). +reopen_changed_log(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + logger:notice("first",?domain), + logger_std_h:filesync(?MODULE), + ok = file:rename(Log,Log++".old"), + ok = file:write_file(Log,""), + logger:notice("second",?domain), + logger_std_h:filesync(?MODULE), + {ok,<<"first\n">>} = file:read_file(Log++".old"), + {ok,<<"second\n">>} = file:read_file(Log), + ok. +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(HName, TO, Reqs = [{Req,Res}|Rs]) -> +send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> receive {From,finish} -> From ! {self(),Reqs} after TO -> - Result = - case Req of - change_config -> - logger:update_handler_config(HName, config, - #{overload_kill_enable => - false}); - Func -> - logger_std_h:Func(HName) - end, - send_requests(HName, TO, Rs ++ [{Req,[Result|Res]}]) + Result = apply(Mod,Func,Args), + send_requests(TO, Rs ++ [{Mod,Func,Args,[Result|Res]}]) end. @@ -1298,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}; @@ -1313,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]), @@ -1624,7 +2014,8 @@ start_tracer(Trace,Expected) -> Pid = self(), FileCtrlPid = maps:get(file_ctrl_pid, maps:get(handler_state, - logger_std_h:info(?MODULE))), + maps:get(cb_state, + logger_olp:info(h_proc_name())))), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), @@ -1632,7 +2023,9 @@ start_tracer(Trace,Expected) -> ok. tpl([{M,F,A}|Trace]) -> - {ok,Match} = dbg:tpl(M,F,A,[]), + tpl([{{M,F,A},[]}|Trace]); +tpl([{{M,F,A},MS}|Trace]) -> + {ok,Match} = dbg:tpl(M,F,A,MS), case lists:keyfind(matched,1,Match) of {_,_,1} -> ok; @@ -1648,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]}) -> @@ -1732,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 new file mode 100644 index 0000000000..1a278fb1b2 --- /dev/null +++ b/lib/kernel/test/logger_stress_SUITE.erl @@ -0,0 +1,550 @@ +%% +%% %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_stress_SUITE). + +-compile(export_all). + +-include_lib("common_test/include/ct_event.hrl"). +-include_lib("kernel/include/logger.hrl"). +-include_lib("kernel/src/logger_h_common.hrl"). + +-ifdef(SAVE_STATS). + -define(COLLECT_STATS(_All_,_Procs_), + ct:pal("~p",[stats(_All_,_Procs_)])). +-else. + -define(COLLECT_STATS(_All_,_Procs__), ok). +-endif. + +-define(TEST_DURATION,120). % seconds + +suite() -> + [{timetrap,{minutes,3}}, + {ct_hooks,[logger_test_lib]}]. + +init_per_suite(Config) -> + Config. + +end_per_suite(_Config) -> + ok. + +init_per_group(_Group, Config) -> + Config. + +end_per_group(_Group, _Config) -> + ok. + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(Case, Config) -> + try apply(?MODULE,Case,[cleanup,Config]) + catch error:undef -> ok + end, + ok. + +groups() -> + []. + +all() -> + [allow_events, + 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, + remote_emulator_events, + remote_emulator_to_disk_log]. + +%%%----------------------------------------------------------------- +%%% Test cases +%%%----------------------------------------------------------------- +%% Time from log macro call to handler callback +allow_events(Config) -> + {ok,_,Node} = + logger_test_lib:setup(Config, + [{logger, + [{handler,default,?MODULE,#{}}]}, + {logger_level,notice}]), + N = 100000, + {T,_} = timer:tc(fun() -> rpc:call(Node,?MODULE,nlogs,[N]) end), + IOPS = N * 1000/T, % log events allowed per millisecond + ct_event:notify(#event{name = benchmark_data, + data = [{value,IOPS}]}), + {comment,io_lib:format("~.2f accepted events pr millisecond", + [IOPS])}. + +%% Time from log macro call to reject (log level) +reject_events(Config) -> + {ok,_,Node} = + logger_test_lib:setup(Config, + [{logger, + [{handler,default,?MODULE,#{}}]}, + {logger_level,error}]), + N = 1000000, + {T,_} = timer:tc(fun() -> rpc:call(Node,?MODULE,nlogs,[N]) end), + IOPS = N * 1000/T, % log events rejected per millisecond + ct_event:notify(#event{name = benchmark_data, + data = [{value,IOPS}]}), + {comment,io_lib:format("~.2f rejected events pr millisecond", + [IOPS])}. + +%% 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_std_h file handler. +std_handler(Config) -> + {ok,_,Node} = + logger_test_lib:setup(Config, + [{logger, + [{handler,default,logger_std_h, + #{config=>#{type=>{file,"default.log"}}}}]}]), + + cascade({Node,{logger_backend,log_allowed,2},[]}, + {Node,{logger_std_h,write,4},[{default,logger_std_h_default}]}, + fun otp_cascading/0). +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. +disk_log_handler(Config) -> + {ok,_,Node} = + logger_test_lib:setup(Config, + [{logger, + [{handler,default,logger_disk_log_h,#{}}]}]), + cascade({Node,{logger_backend,log_allowed,2},[]}, + {Node,{logger_disk_log_h,write,4}, + [{default,logger_disk_log_h_default}]}, + fun otp_cascading/0). +disk_log_handler(cleanup,_Config) -> + Files = filelib:wildcard("default.log.*"), + [_ = 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) -> + {ok,_,Node} = + logger_test_lib:setup(Config, + [{logger, + [{handler,default,?MODULE,#{}}]}]), + cascade({Node,{?MODULE,producer,0},[]}, + {Node,{?MODULE,log,2},[{proxy,logger_proxy}]}, + fun em_cascading/0). + +%% Cascading failure that produce gen_server and proc_lib reports on +%% remote node - how many of the produced log events pass through the +%% proxy. +remote_events(Config) -> + {ok,_,Node1} = + logger_test_lib:setup([{postfix,1}|Config], + [{logger, + [{handler,default,?MODULE,#{}}]}]), + {ok,_,Node2} = + logger_test_lib:setup([{postfix,2}|Config],[]), + cascade({Node2,{logger_backend,log_allowed,2},[{remote_proxy,logger_proxy}]}, + {Node1,{?MODULE,log,2},[{local_proxy,logger_proxy}]}, + fun otp_cascading/0). + +%% Cascading failure that produce gen_server and proc_lib reports on +%% remote node - how many of the produced log events are actually +%% written to a log with logger_disk_log_h wrap file handler. +remote_to_disk_log(Config) -> + {ok,_,Node1} = + logger_test_lib:setup([{postfix,1}|Config], + [{logger, + [{handler,default,logger_disk_log_h,#{}}]}]), + {ok,_,Node2} = + logger_test_lib:setup([{postfix,2}|Config],[]), + cascade({Node2,{logger_backend,log_allowed,2},[{remote_proxy,logger_proxy}]}, + {Node1,{logger_disk_log_h,write,4}, + [{local_proxy,logger_proxy}, + {local_default,logger_disk_log_h_default}]}, + fun otp_cascading/0). +remote_to_disk_log(cleanup,_Config) -> + Files = filelib:wildcard("default.log.*"), + [_ = file:delete(F) || F <- Files], + ok. + +%% Cascading failure that produce log events from the emulator on +%% remote node - how many of the produced log events pass through the +%% proxy. +remote_emulator_events(Config) -> + {ok,_,Node1} = + logger_test_lib:setup([{postfix,1}|Config], + [{logger, + [{handler,default,?MODULE,#{}}]}]), + {ok,_,Node2} = + logger_test_lib:setup([{postfix,2}|Config],[]), + cascade({Node2,{?MODULE,producer,0},[{remote_proxy,logger_proxy}]}, + {Node1,{?MODULE,log,2},[{local_proxy,logger_proxy}]}, + fun em_cascading/0). + +%% Cascading failure that produce log events from the emulator on +%% remote node - how many of the produced log events are actually +%% written to a log with logger_disk_log_h wrap file handler. +remote_emulator_to_disk_log(Config) -> + {ok,_,Node1} = + logger_test_lib:setup([{postfix,1}|Config], + [{logger, + [{handler,default,logger_disk_log_h,#{}}]}]), + {ok,_,Node2} = + logger_test_lib:setup([{postfix,2}|Config],[]), + cascade({Node2,{?MODULE,producer,0},[{remote_proxy,logger_proxy}]}, + {Node1,{logger_disk_log_h,write,4}, + [{local_proxy,logger_proxy}, + {local_default,logger_disk_log_h_default}]}, + fun em_cascading/0). +remote_emulator_to_disk_log(cleanup,_Config) -> + Files = filelib:wildcard("default.log.*"), + [_ = file:delete(F) || F <- Files], + ok. + +%%%----------------------------------------------------------------- +%%% 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" + "[\\]^_`abcdefghijklmnopqr", + [?LOG_NOTICE(Str) || _ <- lists:seq(1,N)], + ok. + +%% cascade(ProducerInfo,ConsumerInfo,TestFun) +cascade({PNode,PMFA,_PStatProcs},{CNode,CMFA,_CStatProcs},TestFun) -> + Tab = ets:new(counter,[set,public]), + ets:insert(Tab,{producer,0}), + ets:insert(Tab,{consumer,0}), + dbg:tracer(process,{fun tracer/2,{Tab,PNode,CNode}}), + dbg:n(PNode), + dbg:n(CNode), + dbg:cn(node()), + dbg:p(all,[call,arity]), + dbg:tpl(PMFA,[]), + dbg:tpl(CMFA,[]), + + Pid = rpc:call(CNode,?MODULE,wrap_test,[PNode,TestFun]), + MRef = erlang:monitor(process,Pid), + TO = ?TEST_DURATION*1000, + receive {'DOWN',MRef,_,_,Reason} -> + ct:fail({remote_pid_down,Reason}) + after TO -> + All = ets:lookup_element(Tab,producer,2), + Written = ets:lookup_element(Tab,consumer,2), + dbg:stop_clear(), + ?COLLECT_STATS(All, + [{PNode,P,Id} || {Id,P} <- _PStatProcs] ++ + [{CNode,P,Id} || {Id,P} <- _CStatProcs]), + Ratio = Written/All * 100, + ct_event:notify(#event{name = benchmark_data, + data = [{value,Ratio}]}), + {comment,io_lib:format("~p % (~p written, ~p produced)", + [round(Ratio),Written,All])} + end. + +wrap_test(Fun) -> + wrap_test(node(),Fun). +wrap_test(Node,Fun) -> + reset(), + group_leader(whereis(user),self()), + rpc:call(Node,?MODULE,do_fun,[Fun]). + +do_fun(Fun) -> + reset(), + Fun(). + +reset() -> + reset([logger_std_h_default, logger_disk_log_h_default, logger_proxy]). +reset([P|Ps]) -> + is_pid(whereis(P)) andalso logger_olp:reset(P), + reset(Ps); +reset([]) -> + ok. + + +tracer({trace,_,call,{?MODULE,producer,_}},{Tab,_PNode,_CNode}=S) -> + ets:update_counter(Tab,producer,1), + S; +tracer({trace,Pid,call,{logger_backend,log_allowed,_}},{Tab,PNode,_CNode}=S) when node(Pid)=:=PNode -> + ets:update_counter(Tab,producer,1), + S; +tracer({trace,_,call,{?MODULE,log,_}},{Tab,_PNode,_CNode}=S) -> + ets:update_counter(Tab,consumer,1), + S; +tracer({trace,_,call,{_,write,_}},{Tab,_PNode,_CNode}=S) -> + ets:update_counter(Tab,consumer,1), + S; +tracer(_,S) -> + S. + + +%%%----------------------------------------------------------------- +%%% Collect statistics +-define(STAT_KEYS, + [burst_drops, + calls, + casts, + drops, + flushed, + flushes, + freq, + last_qlen, + max_qlen, + time, + writes]). +-define(EVENT_KEYS, + [calls,casts,flushed]). + +stats(All,Procs) -> + NI = [{Id,rpc:call(N,logger_olp,info,[P])} || {N,P,Id}<-Procs], + [{all,All}|[stats(Id,I,All) || {Id,I} <- NI]]. + +stats(Id,Info,All) -> + S = maps:with(?STAT_KEYS,Info), + AllOnProc = lists:sum(maps:values(maps:with(?EVENT_KEYS,S))), + if All>0 -> + Writes = maps:get(writes,S), + {_,ActiveTime} = maps:get(time,S), + Rate = round(100*Writes/All), + RateOnProc = + if AllOnProc>0 -> + round(100*Writes/AllOnProc); + true -> + 0 + end, + AvFreq = + if ActiveTime>0 -> + round(Writes/ActiveTime); + true -> + 0 + end, + {Id, + {stats,S}, + {rate,Rate}, + {rate_on_proc,RateOnProc}, + {av_freq,AvFreq}}; + true -> + {Id,none} + end. + +%%%----------------------------------------------------------------- +%%% Spawn a lot of processes that crash repeatedly, causing a lot of +%%% error reports from the emulator. +em_cascading() -> + spawn(fun() -> super() end). + +super() -> + process_flag(trap_exit,true), + spawn_link(fun server/0), + [spawn_link(fun client/0) || _<-lists:seq(1,10000)], + super_loop(). + +super_loop() -> + receive + {'EXIT',_,server} -> + spawn_link(fun server/0), + super_loop(); + {'EXIT',_,_} -> + _L = lists:sum(lists:seq(1,10000)), + spawn_link(fun client/0), + super_loop() + end. + +client() -> + receive + after 1 -> + case whereis(server) of + Pid when is_pid(Pid) -> + ok; + undefined -> + producer(), + erlang:error(some_exception) + end + end, + client(). + +server() -> + register(server,self()), + receive + after 3000 -> + exit(server) + end. + + +%%%----------------------------------------------------------------- +%%% Create a supervisor tree with processes that crash repeatedly, +%%% causing a lot of supervisor reports and crashreports +otp_cascading() -> + {ok,Pid} = supervisor:start_link({local,otp_super}, ?MODULE, [otp_super]), + unlink(Pid), + Pid. + +otp_server_sup() -> + supervisor:start_link({local,otp_server_sup},?MODULE,[otp_server_sup]). + +otp_client_sup(N) -> + supervisor:start_link({local,otp_client_sup},?MODULE,[otp_client_sup,N]). + +otp_server() -> + gen_server:start_link({local,otp_server},?MODULE,[otp_server],[]). + +otp_client() -> + gen_server:start_link(?MODULE,[otp_client],[]). + +init([otp_super]) -> + {ok, {{one_for_one, 200, 10}, + [{client_sup, + {?MODULE, otp_client_sup, [10000]}, + permanent, 1000, supervisor, [?MODULE]}, + {server_sup, + {?MODULE, otp_server_sup, []}, + permanent, 1000, supervisor, [?MODULE]} + ]}}; +init([otp_server_sup]) -> + {ok, {{one_for_one, 2, 10}, + [{server, + {?MODULE, otp_server, []}, + permanent, 1000, worker, [?MODULE]} + ]}}; +init([otp_client_sup,N]) -> + spawn(fun() -> + [supervisor:start_child(otp_client_sup,[]) + || _ <- lists:seq(1,N)] + end), + {ok, {{simple_one_for_one, N*10, 1}, + [{client, + {?MODULE, otp_client, []}, + permanent, 1000, worker, [?MODULE]} + ]}}; +init([otp_server]) -> + {ok, server, 10000}; +init([otp_client]) -> + {ok, client,1}. + +handle_info(timeout, client) -> + true = is_pid(whereis(otp_server)), + {noreply,client,1}; +handle_info(timeout, server) -> + exit(self(), some_error). + +%%%----------------------------------------------------------------- +%%% Logger callbacks +log(_LogEvent,_Config) -> + ok. + +%%%----------------------------------------------------------------- +%%% Function to trace on for counting produced emulator messages +producer() -> + ok. diff --git a/lib/kernel/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl index 81eb9ce5eb..be4bc427fb 100644 --- a/lib/kernel/test/logger_test_lib.erl +++ b/lib/kernel/test/logger_test_lib.erl @@ -28,11 +28,17 @@ post_end_per_testcase/5, post_end_per_suite/3]). setup(Config,Vars) -> + Postfix = case proplists:get_value(postfix, Config) of + undefined -> ""; + P -> ["_",P] + end, FuncStr = lists:concat([proplists:get_value(suite, Config), "_", - proplists:get_value(tc, Config)]), + proplists:get_value(tc, Config)| + Postfix]), ConfigFileName = filename:join(proplists:get_value(priv_dir, Config), FuncStr), file:write_file(ConfigFileName ++ ".config", io_lib:format("[{kernel, ~p}].",[Vars])), - case test_server:start_node(proplists:get_value(tc, Config), slave, + Sname = lists:concat([proplists:get_value(tc,Config)|Postfix]), + case test_server:start_node(Sname, slave, [{args, ["-pa ",filename:dirname(code:which(?MODULE)), " -boot start_sasl -kernel start_timer true " "-config ",ConfigFileName]}]) of diff --git a/lib/kernel/test/seq_trace_SUITE.erl b/lib/kernel/test/seq_trace_SUITE.erl index ee8f4e94f8..663f910751 100644 --- a/lib/kernel/test/seq_trace_SUITE.erl +++ b/lib/kernel/test/seq_trace_SUITE.erl @@ -19,6 +19,9 @@ %% -module(seq_trace_SUITE). +%% label_capability_mismatch needs to run a part of the test on an OTP 20 node. +-compile(r20). + -export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, init_per_group/2,end_per_group/2, init_per_testcase/2,end_per_testcase/2]). @@ -358,7 +361,7 @@ do_incompatible_labels(Rel) -> Mdir = filename:dirname(Dir), true = rpc:call(Node,code,add_patha,[Mdir]), seq_trace:reset_trace(), - rpc:call(Node,?MODULE,start_tracer,[]), + true = is_pid(rpc:call(Node,?MODULE,start_tracer,[])), Receiver = spawn(Node,?MODULE,one_time_receiver,[]), %% This node does not support arbitrary labels, so it must fail with a @@ -385,7 +388,7 @@ do_compatible_labels(Rel) -> Mdir = filename:dirname(Dir), true = rpc:call(Node,code,add_patha,[Mdir]), seq_trace:reset_trace(), - rpc:call(Node,?MODULE,start_tracer,[]), + true = is_pid(rpc:call(Node,?MODULE,start_tracer,[])), Receiver = spawn(Node,?MODULE,one_time_receiver,[]), %% This node does not support arbitrary labels, but small integers should |