Skip to content

Commit

Permalink
Reduce the amount of printing to the terminal during tests
Browse files Browse the repository at this point in the history
  • Loading branch information
@lhoguin
lhoguin committed Oct 10, 2024
1 parent 0384a82 commit 5da43ea
Show file tree
Hide file tree
Showing 2 changed files with 35 additions and 27 deletions.
22 changes: 13 additions & 9 deletions deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.

Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -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,
Expand All @@ -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)]),
Expand Down Expand Up @@ -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
Expand All @@ -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;
Expand Down Expand Up @@ -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(
Expand All @@ -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) ->
Expand Down
40 changes: 22 additions & 18 deletions deps/rabbitmq_ct_helpers/src/rabbit_ct_helpers.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) ->
Expand Down Expand Up @@ -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),
Expand All @@ -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"),
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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}, [
Expand Down Expand Up @@ -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
Expand All @@ -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());
Expand Down Expand Up @@ -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),
Expand Down

0 comments on commit 5da43ea

Please sign in to comment.