From 2c50e61cee560951bfcb5a22aab42eaa81f29247 Mon Sep 17 00:00:00 2001 From: Andrew Mayorov Date: Fri, 23 Jun 2023 17:24:02 +0200 Subject: [PATCH] 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 | 26 ++++++++---- apps/emqx/test/emqx_cth_suite.erl | 64 ++++++++++++++++------------- 2 files changed, 54 insertions(+), 36 deletions(-) diff --git a/apps/emqx/test/emqx_cth_cluster.erl b/apps/emqx/test/emqx_cth_cluster.erl index c38d27a9b..8976b33cb 100644 --- a/apps/emqx/test/emqx_cth_cluster.erl +++ b/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] -> diff --git a/apps/emqx/test/emqx_cth_suite.erl b/apps/emqx/test/emqx_cth_suite.erl index 5e4600fcc..ff4cfee13 100644 --- a/apps/emqx/test/emqx_cth_suite.erl +++ b/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) ->