File 0990-ssh-reduce-KEX-strict-message-verbosity.patch of Package erlang

Overview Repositories Revisions Requests Users Attributes Meta

File 0990-ssh-reduce-KEX-strict-message-verbosity.patch of Package erlang (Revision 05e07e74e02c3c6851eb7fb2c2e0ef8b)

Currently displaying revision 05e07e74e02c3c6851eb7fb2c2e0ef8b , Show latest

From c41d91de326e55b1dbd8b49f60237909845d7fd7 Mon Sep 17 00:00:00 2001
From: Jakub Witczak <kuba@erlang.org>
Date: Fri, 23 Feb 2024 16:07:16 +0100
Subject: [PATCH] ssh: reduce KEX strict message verbosity

- emit "KEX strict" message as debug
- related test adjustments
---
 lib/ssh/src/ssh_transport.erl         |  3 +-
 lib/ssh/test/ssh_protocol_SUITE.erl   | 35 ++++++-------
 lib/ssh/test/ssh_test_lib.erl         | 73 ++++++++++++++++++++-------
 lib/ssh/test/ssh_to_openssh_SUITE.erl | 52 +++++++++++--------
 4 files changed, 103 insertions(+), 60 deletions(-)

diff --git a/lib/ssh/src/ssh_transport.erl b/lib/ssh/src/ssh_transport.erl
index 7846b356a5..e6161c367b 100644
--- a/lib/ssh/src/ssh_transport.erl
+++ b/lib/ssh/src/ssh_transport.erl
@@ -1097,8 +1097,7 @@ select_algorithm(Role, Client, Server,
                     end,
                 case Result of
                     true ->
-                        error_logger:info_report(
-                          lists:concat([Role, " will use strict KEX ordering"]));
+                        logger:debug(lists:concat([Role, " will use strict KEX ordering"]));
                     _ ->
                         ok
                 end,
diff --git a/lib/ssh/test/ssh_protocol_SUITE.erl b/lib/ssh/test/ssh_protocol_SUITE.erl
index 0d83238b92..6884c30cdc 100644
--- a/lib/ssh/test/ssh_protocol_SUITE.erl
+++ b/lib/ssh/test/ssh_protocol_SUITE.erl
@@ -828,19 +828,19 @@ ext_info_c(Config) ->
 %%%--------------------------------------------------------------------
 %%%
 kex_strict_negotiated(Config0) ->
-    {ok,Pid} = ssh_test_lib:add_report_handler(),
+    {ok, TestRef} = ssh_test_lib:add_log_handler(),
     Config = start_std_daemon(Config0, []),
     {Server, Host, Port} = proplists:get_value(server, Config),
-    #{level := Level} = logger:get_primary_config(),
-    logger:set_primary_config(level, notice),
+    Level = ssh_test_lib:get_log_level(),
+    ssh_test_lib:set_log_level(debug),
     {ok, ConnRef} = std_connect({Host, Port}, Config, []),
     {algorithms, _A} = ssh:connection_info(ConnRef, algorithms),
     ssh:stop_daemon(Server),
-    {ok, Reports} = ssh_test_lib:get_reports(Pid),
-    ct:log("Reports = ~p", [Reports]),
-    true = ssh_test_lib:kex_strict_negotiated(client, Reports),
-    true = ssh_test_lib:kex_strict_negotiated(server, Reports),
-    logger:set_primary_config(Level),
+    {ok, Events} = ssh_test_lib:get_log_events(TestRef),
+    true = ssh_test_lib:kex_strict_negotiated(client, Events),
+    true = ssh_test_lib:kex_strict_negotiated(server, Events),
+    ssh_test_lib:set_log_level(Level),
+    ssh_test_lib:rm_log_handler(),
     ok.
 
 %% Connect to an erlang server and inject unexpected SSH ignore
@@ -864,9 +864,9 @@ kex_strict_msg_unknown(Config) ->
     kex_strict_helper(Config, TestMessages, ExpectedReason).
 
 kex_strict_helper(Config, TestMessages, ExpectedReason) ->
-    {ok,HandlerPid} = ssh_test_lib:add_report_handler(),
-    #{level := Level} = logger:get_primary_config(),
-    logger:set_primary_config(level, notice),
+    {ok, TestRef} = ssh_test_lib:add_log_handler(),
+    Level = ssh_test_lib:get_log_level(),
+    ssh_test_lib:set_log_level(debug),
     %% Connect and negotiate keys
     {ok, InitialState} = ssh_trpt_test_lib:exec(
 			  [{set_options, [print_ops, print_seqnums, print_messages]}]
@@ -892,12 +892,13 @@ kex_strict_helper(Config, TestMessages, ExpectedReason) ->
               TestMessages,
           InitialState),
     ct:sleep(100),
-    {ok, Reports} = ssh_test_lib:get_reports(HandlerPid),
-    ct:log("HandlerPid = ~p~nReports = ~p", [HandlerPid, Reports]),
-    true = ssh_test_lib:kex_strict_negotiated(client, Reports),
-    true = ssh_test_lib:kex_strict_negotiated(server, Reports),
-    true = ssh_test_lib:event_logged(server, Reports, ExpectedReason),
-    logger:set_primary_config(Level),
+    {ok, Events} = ssh_test_lib:get_log_events(TestRef),
+    ssh_test_lib:rm_log_handler(),
+    ct:log("Events = ~p", [Events]),
+    true = ssh_test_lib:kex_strict_negotiated(client, Events),
+    true = ssh_test_lib:kex_strict_negotiated(server, Events),
+    true = ssh_test_lib:event_logged(server, Events, ExpectedReason),
+    ssh_test_lib:set_log_level(Level),
     ok.
 
 %%%----------------------------------------------------------------
diff --git a/lib/ssh/test/ssh_test_lib.erl b/lib/ssh/test/ssh_test_lib.erl
index f7355ba6a4..082ee760e9 100644
--- a/lib/ssh/test/ssh_test_lib.erl
+++ b/lib/ssh/test/ssh_test_lib.erl
@@ -122,11 +122,13 @@ setup_host_key/3,
 setup_known_host/3,
 get_addr_str/0,
 file_base_name/2,
-add_report_handler/0,
-get_reports/1,
 kex_strict_negotiated/2,
 event_logged/3
         ]).
+%% logger callbacks and related helpers
+-export([log/2,
+         get_log_level/0, set_log_level/1, add_log_handler/0,
+         rm_log_handler/0, get_log_events/1]).
 
 -include_lib("common_test/include/ct.hrl").
 -include("ssh_transport.hrl").
@@ -1271,15 +1273,10 @@ file_base_name(system_src, 'ecdsa-sha2-nistp521') -> "ssh_host_ecdsa_key521";
 file_base_name(system_src, Alg) -> file_base_name(system, Alg).
 
 %%%----------------------------------------------------------------
-add_report_handler() ->
-    ssh_eqc_event_handler:add_report_handler().
-
-get_reports(Pid) ->
-    ssh_eqc_event_handler:get_reports(Pid).
-
 -define(SEARCH_FUN(EXP),
         begin
-            fun({info_report, _, {_, std_info, EXP}}) ->
+            fun(#{msg := {string, EXP},
+                  level := debug}) ->
                     true;
                (_) ->
                     false
@@ -1287,19 +1284,20 @@ get_reports(Pid) ->
         end).
 -define(SEARCH_SUFFIX, " will use strict KEX ordering").
 
-kex_strict_negotiated(client, Reports) ->
-    kex_strict_negotiated(?SEARCH_FUN("client" ++ ?SEARCH_SUFFIX), Reports);
-kex_strict_negotiated(server, Reports) ->
-    kex_strict_negotiated(?SEARCH_FUN("server" ++ ?SEARCH_SUFFIX), Reports);
-kex_strict_negotiated(SearchFun, Reports) when is_function(SearchFun) ->
-    case lists:search(SearchFun, Reports) of
+kex_strict_negotiated(client, Events) ->
+    kex_strict_negotiated(?SEARCH_FUN("client" ++ ?SEARCH_SUFFIX), Events);
+kex_strict_negotiated(server, Events) ->
+    kex_strict_negotiated(?SEARCH_FUN("server" ++ ?SEARCH_SUFFIX), Events);
+kex_strict_negotiated(SearchFun, Events) when is_function(SearchFun) ->
+    %% FIXME use event_logged?
+    case lists:search(SearchFun, Events) of
         {value, _} -> true;
         _ -> false
     end.
 
-event_logged(Role, Reports, Reason) ->
+event_logged(Role, Events, Reason) ->
     SearchF =
-        fun({info_msg, _, {_, _Format, Args}}) ->
+        fun(#{msg := {report, #{args := Args}}}) ->
                 AnyF = fun (E) when is_list(E) ->
                                case string:find(E, Reason) of
                                    nomatch -> false;
@@ -1310,10 +1308,47 @@ event_logged(Role, Reports, Reason) ->
                        end,
                 lists:member(Role, Args) andalso
                     lists:any(AnyF, Args);
-           (_) ->
+           (_Event) ->
                 false
         end,
-    case lists:search(SearchF, Reports) of
+    case lists:search(SearchF, Events) of
         {value, _} -> true;
         _ -> false
     end.
+
+get_log_level() ->
+    #{level := Level} = logger:get_primary_config(),
+    Level.
+
+set_log_level(Level) ->
+    ok = logger:set_primary_config(level, Level).
+
+add_log_handler() ->
+    TestRef = make_ref(),
+    ok = logger:add_handler(?MODULE, ?MODULE,
+                            #{level => debug,
+                              filter_default => log,
+                              recipient => self(),
+                              test_ref => TestRef}),
+    {ok, TestRef}.
+
+rm_log_handler() ->
+    ok = logger:remove_handler(?MODULE).
+
+get_log_events(TestRef) ->
+    {ok, get_log_events(TestRef, [])}.
+
+get_log_events(TestRef, Acc) ->
+    receive
+        {TestRef, Event} ->
+            get_log_events(TestRef, [Event | Acc])
+    after
+        500 ->
+            Acc
+    end.
+
+%% logger callbacks
+log(LogEvent = #{level:=_Level,msg:=_Msg,meta:=_Meta},
+    #{test_ref := TestRef, recipient := Recipient}) ->
+    Recipient ! {TestRef, LogEvent},
+    ok.
diff --git a/lib/ssh/test/ssh_to_openssh_SUITE.erl b/lib/ssh/test/ssh_to_openssh_SUITE.erl
index 5a8f4b3118..16bedf1763 100644
--- a/lib/ssh/test/ssh_to_openssh_SUITE.erl
+++ b/lib/ssh/test/ssh_to_openssh_SUITE.erl
@@ -146,29 +146,32 @@ end_per_testcase(_TestCase, _Config) ->
 %% Test Cases --------------------------------------------------------
 %%--------------------------------------------------------------------
 erlang_shell_client_openssh_server(Config) when is_list(Config) ->
-    eclient_oserver_helper(Config).
+    eclient_oserver_helper2(eclient_oserver_helper1(), Config).
 
 eclient_oserver_kex_strict(Config) when is_list(Config)->
     case proplists:get_value(kex_strict, Config) of
         true ->
-            {ok, HandlerPid} = ssh_test_lib:add_report_handler(),
-            #{level := Level} = logger:get_primary_config(),
-            logger:set_primary_config(level, notice),
-            Result = eclient_oserver_helper(Config),
-            {ok, Reports} = ssh_test_lib:get_reports(HandlerPid),
-            ct:pal("Reports = ~p", [Reports]),
-            true = ssh_test_lib:kex_strict_negotiated(client, Reports),
-            logger:set_primary_config(Level),
-            Result;
+            {ok, TestRef} = ssh_test_lib:add_log_handler(),
+            Level = ssh_test_lib:get_log_level(),
+            ssh_test_lib:set_log_level(debug),
+            HelperParams = eclient_oserver_helper1(),
+            {ok, Events} = ssh_test_lib:get_log_events(TestRef),
+            true = ssh_test_lib:kex_strict_negotiated(client, Events),
+            ssh_test_lib:set_log_level(Level),
+            ssh_test_lib:rm_log_handler(),
+            eclient_oserver_helper2(HelperParams, Config);
         _ ->
             {skip, "KEX strict not support by local OpenSSH"}
     end.
 
-eclient_oserver_helper(Config) ->
+eclient_oserver_helper1() ->
     process_flag(trap_exit, true),
     IO = ssh_test_lib:start_io_server(),
     Prev = lists:usort(supervisor:which_children(sshc_sup)),
     Shell = ssh_test_lib:start_shell(?SSH_DEFAULT_PORT, IO),
+    {Shell, Prev, IO}.
+
+eclient_oserver_helper2({Shell, Prev, IO}, Config) ->
     IO ! {input, self(), "echo Hej\n"},
     case proplists:get_value(ptty_supported, Config) of
         true ->
@@ -253,25 +256,28 @@ exec_direct_with_io_in_sshc(Config) when is_list(Config) ->
 %%--------------------------------------------------------------------
 %% Test that the Erlang/OTP server can renegotiate with openSSH
 erlang_server_openssh_client_renegotiate(Config) ->
-    eserver_oclient_renegotiate_helper(Config).
+    eserver_oclient_renegotiate_helper2(
+      eserver_oclient_renegotiate_helper1(Config)).
 
 eserver_oclient_kex_strict(Config) ->
     case proplists:get_value(kex_strict, Config) of
         true ->
-            {ok, HandlerPid} = ssh_test_lib:add_report_handler(),
-            #{level := Level} = logger:get_primary_config(),
-            logger:set_primary_config(level, notice),
-            Result = eserver_oclient_renegotiate_helper(Config),
-            {ok, Reports} = ssh_test_lib:get_reports(HandlerPid),
-            ct:log("Reports = ~p", [Reports]),
-            true = ssh_test_lib:kex_strict_negotiated(server, Reports),
-            logger:set_primary_config(Level),
-            Result;
+            {ok, TestRef} = ssh_test_lib:add_log_handler(),
+            Level = ssh_test_lib:get_log_level(),
+            ssh_test_lib:set_log_level(debug),
+
+            HelperParams = eserver_oclient_renegotiate_helper1(Config),
+            {ok, Events} = ssh_test_lib:get_log_events(TestRef),
+            ct:log("Events = ~n~p", [Events]),
+            true = ssh_test_lib:kex_strict_negotiated(server, Events),
+            ssh_test_lib:set_log_level(Level),
+            ssh_test_lib:rm_log_handler(),
+            eserver_oclient_renegotiate_helper2(HelperParams);
         _ ->
             {skip, "KEX strict not support by local OpenSSH"}
     end.
 
-eserver_oclient_renegotiate_helper(Config) ->
+eserver_oclient_renegotiate_helper1(Config) ->
     _PubKeyAlg = ssh_rsa,
     SystemDir = proplists:get_value(data_dir, Config),
     PrivDir = proplists:get_value(priv_dir, Config),
@@ -295,7 +301,9 @@ eserver_oclient_renegotiate_helper(Config) ->
 
 
     OpenSsh = ssh_test_lib:open_port({spawn, Cmd++" < "++DataFile}),
+    {Data, OpenSsh, Pid}.
 
+eserver_oclient_renegotiate_helper2({Data, OpenSsh, Pid}) ->
     Expect = fun({data,R}) ->
 		     try
 			 NonAlphaChars = [C || C<-lists:seq(1,255),
-- 
2.35.3

Places

File 0990-ssh-reduce-KEX-strict-message-verbosity.patch of Package erlang (Revision 05e07e74e02c3c6851eb7fb2c2e0ef8b)

Places