From 5da43ea582c134e5af8f030bcace93b8cedc1764 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Lo=C3=AFc=20Hoguin?= Date: Thu, 10 Oct 2024 17:39:54 +0200 Subject: [PATCH] Reduce the amount of printing to the terminal during tests --- .../src/rabbit_ct_broker_helpers.erl | 22 +++++----- .../src/rabbit_ct_helpers.erl | 40 ++++++++++--------- 2 files changed, 35 insertions(+), 27 deletions(-) diff --git a/deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl b/deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl index b01ea002842e..77c78cc98ac5 100644 --- a/deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl +++ b/deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl @@ -275,7 +275,7 @@ run_make_dist(Config) -> end; _ -> global:del_lock(LockId, [node()]), - ct:pal(?LOW_IMPORTANCE, "(skip `$MAKE test-dist`)", []), + ct:log(?LOW_IMPORTANCE, "(skip `$MAKE test-dist`)", []), Config end. @@ -819,7 +819,7 @@ query_node(Config, NodeConfig) -> %% 3.7.x node. If this is the case, we can ignore %% this and leave the `enabled_plugins_file` config %% variable unset. - ct:pal("NO RABBITMQ_FEATURE_FLAGS_FILE"), + ct:log("NO RABBITMQ_FEATURE_FLAGS_FILE"), Vars0 end, cover_add_node(Nodename), @@ -883,7 +883,7 @@ handle_nodes_in_parallel(NodeConfigs, Fun) -> T1 = erlang:monotonic_time(), Ret = Fun(NodeConfig), T2 = erlang:monotonic_time(), - ct:pal( + ct:log( ?LOW_IMPORTANCE, "Time to run ~tp for node ~ts: ~b us", [Fun, @@ -901,7 +901,7 @@ handle_nodes_in_parallel(NodeConfigs, Fun) -> wait_for_node_handling([], Fun, T0, Results) -> T3 = erlang:monotonic_time(), - ct:pal( + ct:log( ?LOW_IMPORTANCE, "Time to run ~tp for all nodes: ~b us", [Fun, erlang:convert_time_unit(T3 - T0, native, microsecond)]), @@ -956,7 +956,7 @@ configured_metadata_store(Config) -> end. configure_metadata_store(Config) -> - ct:pal("Configuring metadata store..."), + ct:log("Configuring metadata store..."), case configured_metadata_store(Config) of {khepri, FFs0} -> case enable_khepri_metadata_store(Config, FFs0) of @@ -967,12 +967,12 @@ configure_metadata_store(Config) -> Config1 end; mnesia -> - ct:pal("Enabling Mnesia metadata store"), + ct:log("Enabling Mnesia metadata store"), Config end. enable_khepri_metadata_store(Config, FFs0) -> - ct:pal("Enabling Khepri metadata store"), + ct:log("Enabling Khepri metadata store"), FFs = [khepri_db | FFs0], lists:foldl(fun(_FF, {skip, _Reason} = Skip) -> Skip; @@ -1143,7 +1143,7 @@ stop_rabbitmq_node(Config, NodeConfig) -> NodeConfig. find_crashes_in_logs(NodeConfigs, IgnoredCrashes) -> - ct:pal( + ct:log( "Looking up any crash reports in the nodes' log files. If we find " "some, they will appear below:"), CrashesCount = lists:foldl( @@ -1152,7 +1152,11 @@ find_crashes_in_logs(NodeConfigs, IgnoredCrashes) -> NodeConfig, IgnoredCrashes), Total + Count end, 0, NodeConfigs), - ct:pal("Found ~b crash report(s)", [CrashesCount]), + LogFn = case CrashesCount of + 0 -> log; + _ -> pal + end, + ct:LogFn("Found ~b crash report(s)", [CrashesCount]), ?assertEqual(0, CrashesCount). count_crashes_in_logs(NodeConfig, IgnoredCrashes) -> diff --git a/deps/rabbitmq_ct_helpers/src/rabbit_ct_helpers.erl b/deps/rabbitmq_ct_helpers/src/rabbit_ct_helpers.erl index d9e34cf38fa6..c9b351ddd6ab 100644 --- a/deps/rabbitmq_ct_helpers/src/rabbit_ct_helpers.erl +++ b/deps/rabbitmq_ct_helpers/src/rabbit_ct_helpers.erl @@ -66,7 +66,7 @@ log_environment() -> Vars = lists:sort(fun(A, B) -> A =< B end, os:getenv()), - ct:pal(?LOW_IMPORTANCE, "Environment variables:~n~ts", + ct:log(?LOW_IMPORTANCE, "Environment variables:~n~ts", [[io_lib:format(" ~ts~n", [V]) || V <- Vars]]). run_setup_steps(Config) -> @@ -152,7 +152,7 @@ run_steps(Config, []) -> Config. redirect_logger_to_ct_logs(Config) -> - ct:pal( + ct:log( ?LOW_IMPORTANCE, "Configuring logger to send logs to common_test logs"), ok = logger:set_handler_config(cth_log_redirect, level, debug), @@ -172,7 +172,7 @@ redirect_logger_to_ct_logs(Config) -> ok = logger:remove_handler(default), - ct:pal( + ct:log( ?LOW_IMPORTANCE, "Logger configured to send logs to common_test logs; you should see " "a message below saying so"), @@ -433,12 +433,12 @@ ensure_rabbitmqctl_cmd(Config) -> false -> find_script(Config, "rabbitmqctl"); R -> - ct:pal(?LOW_IMPORTANCE, + ct:log(?LOW_IMPORTANCE, "Using rabbitmqctl from RABBITMQCTL: ~tp~n", [R]), R end; R -> - ct:pal(?LOW_IMPORTANCE, + ct:log(?LOW_IMPORTANCE, "Using rabbitmqctl from rabbitmqctl_cmd: ~tp~n", [R]), R end, @@ -470,7 +470,7 @@ find_script(Config, Script) -> filelib:is_file(File)], case Locations of [Location | _] -> - ct:pal(?LOW_IMPORTANCE, "Using ~ts at ~tp~n", [Script, Location]), + ct:log(?LOW_IMPORTANCE, "Using ~ts at ~tp~n", [Script, Location]), Location; [] -> false @@ -555,7 +555,7 @@ ensure_rabbitmq_queues_cmd(Config) -> R -> R end; R -> - ct:pal(?LOW_IMPORTANCE, + ct:log(?LOW_IMPORTANCE, "Using rabbitmq-queues from rabbitmq_queues_cmd: ~tp~n", [R]), R end, @@ -654,12 +654,12 @@ symlink_priv_dir(Config) -> Target = filename:join([SrcDir, "logs", Name]), case exec(["ln", "-snf", PrivDir, Target]) of {ok, _} -> ok; - _ -> ct:pal(?LOW_IMPORTANCE, + _ -> ct:log(?LOW_IMPORTANCE, "Failed to symlink private_log directory.") end, Config; not_found -> - ct:pal(?LOW_IMPORTANCE, + ct:log(?LOW_IMPORTANCE, "Failed to symlink private_log directory."), Config end @@ -684,7 +684,7 @@ load_elixir(Config) -> {skip, _} = Skip -> Skip; ElixirLibDir -> - ct:pal(?LOW_IMPORTANCE, "Elixir lib dir: ~ts~n", [ElixirLibDir]), + ct:log(?LOW_IMPORTANCE, "Elixir lib dir: ~ts~n", [ElixirLibDir]), true = code:add_pathz(ElixirLibDir), {ok, _} = application:ensure_all_started(elixir), Config @@ -720,14 +720,18 @@ long_running_testsuite_monitor(TimerRef, Testcases) -> long_running_testsuite_monitor(TimerRef, Testcases1); ping_ct -> T1 = erlang:monotonic_time(seconds), - ct:pal(?STD_IMPORTANCE, "Testcases still in progress:~ts", - [[ + InProgress = [ begin TDiff = format_time_diff(T1, T0), rabbit_misc:format("~n - ~ts (~ts)", [TC, TDiff]) end || {TC, T0} <- Testcases - ]]), + ], + case InProgress of + [] -> ok; + _ -> ct:pal(?STD_IMPORTANCE, "Testcases still in progress:~ts", + [InProgress]) + end, long_running_testsuite_monitor(TimerRef, Testcases); stop -> timer:cancel(TimerRef) @@ -905,7 +909,7 @@ exec([Cmd | Args], Options) when is_list(Cmd) orelse is_binary(Cmd) -> %% Because Args1 may contain binaries, we don't use string:join(). %% Instead we do a list comprehension. ArgsIoList = [Cmd1, [[$\s, Arg] || Arg <- Args1]], - ct:pal(?LOW_IMPORTANCE, Log1, [ArgsIoList, self()]), + ct:log(?LOW_IMPORTANCE, Log1, [ArgsIoList, self()]), try Port = erlang:open_port( {spawn_executable, Cmd1}, [ @@ -951,10 +955,10 @@ port_receive_loop(Port, Stdout, Options, Until, DumpTimer) -> Stdout =:= "", if DropStdout -> - ct:pal(?LOW_IMPORTANCE, "Exit code: ~tp (pid ~tp)", + ct:log(?LOW_IMPORTANCE, "Exit code: ~tp (pid ~tp)", [X, self()]); true -> - ct:pal(?LOW_IMPORTANCE, "~ts~nExit code: ~tp (pid ~tp)", + ct:log(?LOW_IMPORTANCE, "~ts~nExit code: ~tp (pid ~tp)", [Stdout, X, self()]) end, case proplists:get_value(match_stdout, Options) of @@ -976,7 +980,7 @@ port_receive_loop(Port, Stdout, Options, Until, DumpTimer) -> DropStdout -> ok; true -> - ct:pal(?LOW_IMPORTANCE, "~ts~n[Command still in progress] (pid ~tp)", + ct:log(?LOW_IMPORTANCE, "~ts~n[Command still in progress] (pid ~tp)", [Stdout, self()]) end, port_receive_loop(Port, Stdout, Options, Until, stdout_dump_timer()); @@ -1101,7 +1105,7 @@ eventually({Line, Assertion} = TestObj, PollInterval, PollCount) ok -> ok; Err -> - ct:pal(?LOW_IMPORTANCE, + ct:log(?LOW_IMPORTANCE, "Retrying in ~bms for ~b more times due to failed assertion in line ~b: ~tp", [PollInterval, PollCount - 1, Line, Err]), timer:sleep(PollInterval),