From 68b3f7d18db789845a0027004b53e5051d5a6683 Mon Sep 17 00:00:00 2001 From: Jakub Witczak 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),