fix(cth): reduce amount of logging + streamline logging

Also make sure that code running on `emqx_cth_cluster` nodes don't
crash when using `ct:pal` and friends.

apps/emqx/test/emqx_cth_cluster.erl

@@ -19,6 +19,8 @@
 -export([start/2]).
 -export([stop/1]).
 
+-export([share_load_module/2]).
+
 -define(APPS_CLUSTERING, [gen_rpc, mria, ekka]).
 
 -define(TIMEOUT_NODE_START_MS, 15000).
@@ -81,8 +83,7 @@ when
     }.
 start(Nodes, ClusterOpts) ->
     NodeSpecs = mk_nodespecs(Nodes, ClusterOpts),
-    % ct:pal("starting cluster: ~p", [NodeSpecs]),
-    io:format(user, "starting cluster: ~p~n", [NodeSpecs]),
+    ct:pal("Starting cluster: ~p", [NodeSpecs]),
     % 1. Start bare nodes with only basic applications running
     _ = emqx_utils:pmap(fun start_node_init/1, NodeSpecs, ?TIMEOUT_NODE_START_MS),
     % 2. Start applications needed to enable clustering
@@ -92,7 +93,6 @@ start(Nodes, ClusterOpts) ->
     % 3. Start applications after cluster is formed
     % Cluster-joins are complete, so they shouldn't restart in the background anymore.
     _ = emqx_utils:pmap(fun run_node_phase_apps/1, NodeSpecs, ?TIMEOUT_APPS_START_MS),
-    % _ = lists:foreach(fun run_node_phase_apps/1, NodeSpecs),
     [Node || #{name := Node} <- NodeSpecs].
 
 mk_nodespecs(Nodes, ClusterOpts) ->
@@ -256,7 +256,11 @@ start_node_init(Spec = #{name := Node}) ->
     Node = start_bare_node(Node, Spec),
     pong = net_adm:ping(Node),
     % ok = set_work_dir(Node, Opts),
+    % Preserve node spec right on the remote node
     ok = set_node_opts(Node, Spec),
+    % Make it possible to call `ct:pal` and friends (if running under rebar3)
+    _ = share_load_module(Node, cthr),
+    % Enable snabbkaffe trace forwarding
     ok = snabbkaffe:forward_trace(Node),
     ok.
 
@@ -264,7 +268,6 @@ run_node_phase_cluster(Spec = #{name := Node}) ->
     ok = load_apps(Node, Spec),
     ok = start_apps_clustering(Node, Spec),
     ok = maybe_join_cluster(Node, Spec),
-    % ?HERE("cluster view @ ~p: ~p", [Node, erpc:call(Node, mria, info, [])]),
     ok.
 
 run_node_phase_apps(Spec = #{name := Node}) ->
@@ -286,15 +289,13 @@ load_apps(Node, #{apps := Apps}) ->
 start_apps_clustering(Node, #{apps := Apps} = Spec) ->
     SuiteOpts = maps:with([work_dir], Spec),
     AppsClustering = [lists:keyfind(App, 1, Apps) || App <- ?APPS_CLUSTERING],
-    Started = erpc:call(Node, emqx_cth_suite, start, [AppsClustering, SuiteOpts]),
-    ct:pal("[start_apps_clustering] started apps on ~p: ~p", [Node, Started]),
+    _Started = erpc:call(Node, emqx_cth_suite, start, [AppsClustering, SuiteOpts]),
     ok.
 
 start_apps(Node, #{apps := Apps} = Spec) ->
     SuiteOpts = maps:with([work_dir], Spec),
     AppsRest = [AppSpec || AppSpec = {App, _} <- Apps, not lists:member(App, ?APPS_CLUSTERING)],
-    Started = erpc:call(Node, emqx_cth_suite, start_apps, [AppsRest, SuiteOpts]),
-    ct:pal("[start_apps] started apps on ~p: ~p", [Node, Started]),
+    _Started = erpc:call(Node, emqx_cth_suite, start_apps, [AppsRest, SuiteOpts]),
     ok.
 
 maybe_join_cluster(_Node, #{role := replicant}) ->
@@ -392,6 +393,15 @@ is_lib(Path) ->
     string:prefix(Path, code:lib_dir()) =:= nomatch andalso
         string:str(Path, "_build/default/plugins") =:= 0.
 
+share_load_module(Node, Module) ->
+    case code:get_object_code(Module) of
+        {Module, Code, Filename} ->
+            {module, Module} = erpc:call(Node, code, load_binary, [Module, Filename, Code]),
+            ok;
+        error ->
+            error
+    end.
+
 node_name(Name) ->
     case string:tokens(atom_to_list(Name), "@") of
         [_Name, _Host] ->

apps/emqx/test/emqx_cth_suite.erl

@@ -16,6 +16,7 @@
 
 -module(emqx_cth_suite).
 
+-include_lib("common_test/include/ct.hrl").
 -include_lib("emqx/include/emqx_authentication.hrl").
 
 -export([start/2]).
@@ -35,10 +36,14 @@
 -define(NOW,
     (calendar:system_time_to_rfc3339(erlang:system_time(millisecond), [{unit, millisecond}]))
 ).
--define(HERE(FMT, ARGS),
-    io:format(user, "~s [~p] ~p/~p:~p " FMT "~n", [
-        ?NOW, node(), ?FUNCTION_NAME, ?FUNCTION_ARITY, ?LINE | ARGS
-    ])
+
+-define(PAL(IMPORTANCE, FMT, ARGS),
+    case erlang:whereis(ct_logs) of
+        undefined ->
+            io:format("*** " ?MODULE_STRING " ~s @ ~p ***~n" ++ FMT ++ "~n", [?NOW, node() | ARGS]);
+        _ ->
+            ct:pal(?MODULE, IMPORTANCE, FMT, ARGS, [{heading, ?MODULE_STRING}])
+    end
 ).
 
 %%
@@ -153,44 +158,52 @@ init_spec(Config) when is_list(Config); is_binary(Config) ->
     #{config => [Config, "\n"]}.
 
 start_appspec(App, StartOpts) ->
-    ?HERE("~p StartOpts=~0p", [App, StartOpts]),
+    _ = log_appspec(App, StartOpts),
     _ = maybe_configure_app(App, StartOpts),
-    ?HERE("<- maybe_configure_app/2", []),
     _ = maybe_override_env(App, StartOpts),
-    ?HERE("<- maybe_override_env/2", []),
     _ = maybe_before_start(App, StartOpts),
-    ?HERE("<- maybe_before_start/2", []),
     case maybe_start(App, StartOpts) of
         {ok, Started} ->
-            ?HERE("<- maybe_start/1 = ~0p", [Started]),
+            ?PAL(?STD_IMPORTANCE, "Started applications: ~0p", [Started]),
             _ = maybe_after_start(App, StartOpts),
-            ?HERE("<- maybe_after_start/2", []),
             Started;
         {error, Reason} ->
             error({failed_to_start_app, App, Reason})
     end.
 
+log_appspec(App, StartOpts) when map_size(StartOpts) > 0 ->
+    Fmt = lists:flatmap(
+        fun(Opt) -> "~n * ~p: " ++ spec_fmt(fc, Opt) end,
+        maps:keys(StartOpts)
+    ),
+    Args = lists:flatmap(
+        fun({Opt, V}) -> [Opt, spec_fmt(ffun, {Opt, V})] end,
+        maps:to_list(StartOpts)
+    ),
+    ?PAL(?STD_IMPORTANCE, "Starting ~p with:" ++ Fmt, [App | Args]);
+log_appspec(App, #{}) ->
+    ?PAL(?STD_IMPORTANCE, "Starting ~p", [App]).
+
+spec_fmt(fc, config) -> "~n~ts";
+spec_fmt(fc, _) -> "~p";
+spec_fmt(ffun, {config, C}) -> render_config(C);
+spec_fmt(ffun, {_, X}) -> X.
+
 maybe_configure_app(_App, #{config := false}) ->
     ok;
 maybe_configure_app(App, #{config := Config}) ->
     case app_schema(App) of
         {ok, SchemaModule} ->
-            configure_app(App, SchemaModule, Config);
+            configure_app(SchemaModule, Config);
         {error, Reason} ->
             error({failed_to_configure_app, App, Reason})
     end;
 maybe_configure_app(_App, #{}) ->
     ok.
 
-configure_app(_App, SchemaModule, Config) ->
-    ok = load_app_config(SchemaModule, Config),
-    % ?HERE("-- roots = ~p", [
-    %     % App,
-    %     [
-    %         emqx_config:get_root([binary_to_atom(Root)])
-    %      || Root <- hocon_schema:root_names(SchemaModule)
-    %     ]
-    % ]),
+configure_app(SchemaModule, Config) ->
+    ok = emqx_config:init_load(SchemaModule, render_config(Config)),
+    % ?PAL(?LOW_IMPORTANCE, "Configured ~p roots: ~p", [SchemaModule, config_roots(SchemaModule)]),
     ok.
 
 maybe_override_env(App, #{override_env := Env = [{_, _} | _]}) ->
@@ -198,8 +211,6 @@ maybe_override_env(App, #{override_env := Env = [{_, _} | _]}) ->
 maybe_override_env(_App, #{}) ->
     ok.
 
-% maybe_before_start(_App, #{start := false}) ->
-%     ok;
 maybe_before_start(App, #{before_start := Fun}) when is_function(Fun, 1) ->
     Fun(App);
 maybe_before_start(_App, #{before_start := Fun}) when is_function(Fun, 0) ->
@@ -216,8 +227,6 @@ maybe_start(App, #{start := Fun}) when is_function(Fun, 1) ->
 maybe_start(App, #{}) ->
     application:ensure_all_started(App).
 
-% maybe_after_start(_App, #{start := false}) ->
-%     ok;
 maybe_after_start(App, #{after_start := Fun}) when is_function(Fun, 1) ->
     Fun(App);
 maybe_after_start(_App, #{after_start := Fun}) when is_function(Fun, 0) ->
@@ -346,6 +355,9 @@ clean_suite_state() ->
 
 %%
 
+% config_roots(SchemaMod) ->
+%     [emqx_config:get_root([binary_to_atom(Root)]) || Root <- hocon_schema:root_names(SchemaMod)].
+
 app_schema(App) ->
     Mod = list_to_atom(atom_to_list(App) ++ "_schema"),
     try is_list(Mod:roots()) of
@@ -356,10 +368,6 @@ app_schema(App) ->
             {error, schema_not_found}
     end.
 
-load_app_config(SchemaModule, Config) ->
-    ?HERE("~p ~ts", [SchemaModule, render_config(Config)]),
-    emqx_config:init_load(SchemaModule, render_config(Config)).
-
 render_config(Config = #{}) ->
     unicode:characters_to_binary(hocon_pp:do(Config, #{}));
 render_config(Config) ->