309 lines
12 KiB
Diff
309 lines
12 KiB
Diff
|
|
From 68b3f7d18db789845a0027004b53e5051d5a6683 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 7846b356a542..e6161c367ba7 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 186c867e2fa9..3222686d9bcf 100644
|
||
|
|
--- a/lib/ssh/test/ssh_protocol_SUITE.erl
|
||
|
|
+++ b/lib/ssh/test/ssh_protocol_SUITE.erl
|
||
|
|
@@ -827,19 +827,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
|
||
|
|
@@ -863,9 +863,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]}]
|
||
|
|
@@ -891,12 +891,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 e364ab0baebb..04bfd122f98e 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 5a8f4b31187d..16bedf1763b3 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),
|