Merge pull request #13947 from rabbitmq/ik-rabbit_ct_hook

Run rabbit_ct_hook before cth_styledout so that removing default logger handler works

Author: michaelklishin

deps/rabbit/Makefile

@@ -151,6 +151,7 @@ MANPAGES     = $(wildcard $(DOCS_DIR)/*.[0-9])
 WEB_MANPAGES = $(patsubst %,%.html,$(MANPAGES))
 MD_MANPAGES  = $(patsubst %,%.md,$(MANPAGES))
 
+CT_HOOKS = rabbit_ct_hook
 DEP_EARLY_PLUGINS = rabbit_common/mk/rabbitmq-early-plugin.mk
 DEP_PLUGINS = rabbit_common/mk/rabbitmq-plugin.mk
 
@@ -221,8 +222,6 @@ ct-fast:
 ct-slow:
 	$(MAKE) ct CT_SUITES='$(SLOW_CT_SUITES)'
 
-CT_OPTS += -ct_hooks rabbit_ct_hook []
-
 # Parallel CT.
 #
 # @todo We must ensure that the CT_OPTS also apply to ct-master

deps/rabbit/test/amqp_utils.erl

@@ -61,7 +61,7 @@ web_amqp(Config) ->
 flush(Prefix) ->
     receive
         Msg ->
-            ct:pal("~p flushed: ~p~n", [Prefix, Msg]),
+            ct:log("~p flushed: ~p~n", [Prefix, Msg]),
             flush(Prefix)
     after 1 ->
               ok

deps/rabbit/test/peer_discovery_tmp_hidden_node_SUITE.erl

@@ -82,10 +82,10 @@ long_names_work(_Config) ->
 ipv6_works(Config) ->
     PrivDir = ?config(priv_dir, Config),
     InetrcFilename = filename:join(PrivDir, "inetrc-ipv6.erl"),
-    ct:pal("Inetrc filename:~n~0p", [InetrcFilename]),
+    ct:log("Inetrc filename:~n~0p", [InetrcFilename]),
     Inetrc = [{inet6, true}],
     InetrcContent = [io_lib:format("~p.~n", [Param]) || Param <- Inetrc],
-    ct:pal("Inetrc file content:~n---8<---~n~s---8<---", [InetrcContent]),
+    ct:log("Inetrc file content:~n---8<---~n~s---8<---", [InetrcContent]),
     ok = file:write_file(InetrcFilename, InetrcContent),
     InetrcArg = rabbit_misc:format("~0p", [InetrcFilename]),
 
@@ -106,10 +106,10 @@ inetrc_file_as_atom_works(_Config) ->
     %% might not be defined).
     TmpDir = os:getenv("TEMP", os:getenv("TMP", os:getenv("TMPDIR", "/tmp"))),
     InetrcFilename = filename:join(TmpDir, "inetrc-ipv6.erl"),
-    ct:pal("Inetrc filename:~n~0p", [InetrcFilename]),
+    ct:log("Inetrc filename:~n~0p", [InetrcFilename]),
     Inetrc = [{inet6, true}],
     InetrcContent = [io_lib:format("~p.~n", [Param]) || Param <- Inetrc],
-    ct:pal("Inetrc file content:~n---8<---~n~s---8<---", [InetrcContent]),
+    ct:log("Inetrc file content:~n---8<---~n~s---8<---", [InetrcContent]),
     ok = file:write_file(InetrcFilename, InetrcContent),
     InetrcArg = rabbit_misc:format("~0p", [list_to_atom(InetrcFilename)]),
 
@@ -138,27 +138,27 @@ tls_dist_works(Config) ->
 
     PrivDir = ?config(priv_dir, Config),
     SslOptFilename = filename:join(PrivDir, "ssl-options.erl"),
-    ct:pal("SSL options filename:~n~0p", [SslOptFilename]),
+    ct:log("SSL options filename:~n~0p", [SslOptFilename]),
     SslOptContent = rabbit_misc:format("~p.~n", [SslOptions]),
-    ct:pal("SSL options file content:~n---8<---~n~s---8<---", [SslOptContent]),
+    ct:log("SSL options file content:~n---8<---~n~s---8<---", [SslOptContent]),
     ok = file:write_file(SslOptFilename, SslOptContent),
 
     %% We need to read the certificate's Subject ID to see what hostname is
     %% used in the certificate and use the same to start the test Erlang nodes.
     %% We also need to pay attention if the name is short or long.
     {ok, ServerCertBin} = file:read_file(ServerCert),
-    ct:pal("ServerCertBin = ~p", [ServerCertBin]),
+    ct:log("ServerCertBin = ~p", [ServerCertBin]),
     [DecodedCert] = public_key:pem_decode(ServerCertBin),
-    ct:pal("DecodedCert = ~p", [DecodedCert]),
+    ct:log("DecodedCert = ~p", [DecodedCert]),
     DecodedCert1 = element(2, DecodedCert),
     {_SerialNr, {rdnSequence, IssuerAttrs}} = public_key:pkix_subject_id(
                                                 DecodedCert1),
-    ct:pal("IssuerAttrs = ~p", [IssuerAttrs]),
+    ct:log("IssuerAttrs = ~p", [IssuerAttrs]),
     [ServerName] = [Value
                     || [#'AttributeTypeAndValue'{type = {2, 5, 4, 3},
                                                  value = {utf8String, Value}}]
                        <- IssuerAttrs],
-    ct:pal("ServerName = ~p", [ServerName]),
+    ct:log("ServerName = ~p", [ServerName]),
     UseLongnames = re:run(ServerName, "\\.", [{capture, none}]) =:= match,
 
     PeerOptions = #{host => binary_to_list(ServerName),
@@ -188,7 +188,7 @@ do_test_query_node_props(Peers) ->
             NodeAPid,
             rabbit_peer_discovery, query_node_props, [[NodeB]],
             infinity),
-    ct:pal("Discovered nodes properties:~n~p", [Ret]),
+    ct:log("Discovered nodes properties:~n~p", [Ret]),
     ?assertMatch([{NodeB, [NodeB], _, false}], Ret),
 
     %% Ensure no connection exists after the query.
@@ -236,23 +236,23 @@ start_test_nodes(Testcase, NodeNumber, NodeCount, PeerOptions, Peers)
                        _ ->
                            PeerOptions1
                    end,
-    ct:pal("Starting peer with options: ~p", [PeerOptions2]),
+    ct:log("Starting peer with options: ~p", [PeerOptions2]),
     case catch peer:start(PeerOptions2) of
         {ok, PeerPid, PeerName} ->
-            ct:pal("Configuring peer '~ts'", [PeerName]),
+            ct:log("Configuring peer '~ts'", [PeerName]),
             setup_test_node(PeerPid, PeerOptions2),
             Peers1 = Peers#{PeerName => PeerPid},
             start_test_nodes(
               Testcase, NodeNumber + 1, NodeCount, PeerOptions, Peers1);
         Error ->
-            ct:pal("Failed to started peer node:~n"
+            ct:log("Failed to started peer node:~n"
                    "Options: ~p~n"
                    "Error: ~p", [PeerOptions2, Error]),
             stop_test_nodes(Peers),
             erlang:throw(Error)
     end;
 start_test_nodes(_Testcase, _NodeNumber, _Count, _PeerOptions, Peers) ->
-    ct:pal("Peers: ~p", [Peers]),
+    ct:log("Peers: ~p", [Peers]),
     Peers.
 
 setup_test_node(PeerPid, PeerOptions) ->

deps/rabbit/test/policy_SUITE.erl

@@ -449,7 +449,7 @@ get_messages(Number, Ch, Q) ->
     end.
 
 check_policy_value(Server, QName, Value) ->
-    ct:pal("QUEUES ~p",
+    ct:log("QUEUES ~p",
            [rpc:call(Server, rabbit_amqqueue, list, [])]),
     {ok, Q} = rpc:call(Server, rabbit_amqqueue, lookup, [rabbit_misc:r(<<"/">>, queue, QName)]),
     case rpc:call(Server, rabbit_policy, effective_definition, [Q]) of

deps/rabbit_common/mk/rabbitmq-early-plugin.mk

@@ -38,7 +38,7 @@ CT_OPTS += -kernel net_ticktime 5
 #   This hook will change the output of common_test to something more
 #   concise and colored.
 
-CT_HOOKS ?= cth_styledout
+CT_HOOKS += cth_styledout
 TEST_DEPS += cth_styledout
 
 ifdef CONCOURSE

deps/rabbitmq_ct_helpers/src/ct_master_fork.erl

@@ -368,7 +368,7 @@ run_all([{Node,Run,Skip}|Rest],TSRec=#testspec{label = Labels,
 	  {cover_stop, CoverStop},
 	  {config, ConfigFiles},
 	  {event_handler, EvHandlers},
-	  {ct_hooks, FiltCTHooks},
+	  {ct_hooks, [rabbit_ct_hook, cth_styledout] ++ FiltCTHooks},
 %      {ct_hooks_order, CTHooksOrder},
 	  {enable_builtin_hooks, EnableBuiltinHooks},
 	  {auto_compile, AutoCompile},

deps/rabbitmq_ct_helpers/src/rabbit_control_helper.erl

@@ -43,7 +43,7 @@ command_with_output(Command, Node, Args, Opts) ->
     Mod = 'Elixir.RabbitMQCtl', %% To silence a Dialyzer warning.
     CommandResult = Mod:exec_command(
         Formatted, fun(Output,_,_) -> Output end),
-    ct:pal("Executed command ~tp against node ~tp~nResult: ~tp~n", [Formatted, Node, CommandResult]),
+    ct:log("Executed command ~tp against node ~tp~nResult: ~tp~n", [Formatted, Node, CommandResult]),
     CommandResult.
 
 format_command(Command, Node, Args, Opts) ->

deps/rabbitmq_ct_helpers/src/rabbit_ct_broker_helpers.erl

@@ -944,7 +944,7 @@ does_use_expected_metadata_store(Config, NodeConfig) ->
                             true  -> khepri;
                             false -> mnesia
                         end,
-    ct:pal(
+    ct:log(
       "Metadata store on ~s: expected=~s, used=~s",
       [Nodename, ExpectedMetadataStore, UsedMetadataStore]),
     {ExpectedMetadataStore, UsedMetadataStore}.
@@ -975,7 +975,7 @@ cluster_nodes(Config, Nodes) when is_list(Nodes) ->
         {value, SecNodeConfig} ->
             NodeConfigs1 = NodeConfigs -- [SecNodeConfig],
             Nodename = ?config(nodename, SecNodeConfig),
-            ct:pal(
+            ct:log(
               "Using secondary-umbrella-based node ~s as the cluster seed "
               "node",
               [Nodename]),
@@ -984,7 +984,7 @@ cluster_nodes(Config, Nodes) when is_list(Nodes) ->
             case NodeConfigs of
                 [NodeConfig, SeedNodeConfig | NodeConfigs1] ->
                     Nodename = ?config(nodename, SeedNodeConfig),
-                    ct:pal(
+                    ct:log(
                       "Using node ~s as the cluster seed node",
                       [Nodename]),
                     cluster_nodes1(
@@ -1184,7 +1184,7 @@ ra_last_applied(ServerId) ->
 
 do_nodes_run_same_ra_machine_version(Config, RaMachineMod) ->
     [MacVer1 | MacVerN] = MacVers = rpc_all(Config, RaMachineMod, version, []),
-    ct:pal("Ra machine versions of ~s: ~0p", [RaMachineMod, MacVers]),
+    ct:log("Ra machine versions of ~s: ~0p", [RaMachineMod, MacVers]),
     is_integer(MacVer1) andalso
     lists:all(fun(MacVer) -> MacVer =:= MacVer1 end, MacVerN).
 
@@ -1403,7 +1403,7 @@ capture_gen_server_termination(
       lists:reverse(Acc), Rest, Count, IgnoredCrashes).
 
 found_gen_server_termiation(Message, Lines, Count, IgnoredCrashes) ->
-    ct:pal("gen_server termination:~n~n~s", [Message]),
+    ct:log("gen_server termination:~n~n~s", [Message]),
     count_gen_server_terminations(Lines, Count + 1, IgnoredCrashes).
 
 %% -------------------------------------------------------------------

deps/rabbit/test/rabbit_ct_hook.erl renamed to deps/rabbitmq_ct_helpers/src/rabbit_ct_hook.erl

@@ -31,6 +31,7 @@ LOCAL_DEPS += ranch ssl crypto public_key
 # See rabbitmq-components.mk.
 BUILD_DEPS += ranch
 
+CT_HOOKS = rabbit_ct_hook
 DEP_EARLY_PLUGINS = rabbit_common/mk/rabbitmq-early-plugin.mk
 DEP_PLUGINS = rabbit_common/mk/rabbitmq-plugin.mk