From ab95786ce0dc29f330de6e0c3565a30948ba799b Mon Sep 17 00:00:00 2001 From: Hans Nilsson Date: Wed, 25 May 2016 14:51:55 +0200 Subject: ssh: logging in test helper ssh_echo_server --- lib/ssh/test/ssh_connection_SUITE.erl | 30 ++++++++++++++++++++++-------- lib/ssh/test/ssh_echo_server.erl | 35 ++++++++++++++++++++++++++++------- 2 files changed, 50 insertions(+), 15 deletions(-) diff --git a/lib/ssh/test/ssh_connection_SUITE.erl b/lib/ssh/test/ssh_connection_SUITE.erl index a52633a269..a6e2f0fba9 100644 --- a/lib/ssh/test/ssh_connection_SUITE.erl +++ b/lib/ssh/test/ssh_connection_SUITE.erl @@ -366,19 +366,21 @@ interrupted_send(Config) -> UserDir = filename:join(PrivDir, nopubkey), % to make sure we don't use public-key-auth file:make_dir(UserDir), SysDir = proplists:get_value(data_dir, Config), + EchoSS_spec = {ssh_echo_server, [4000000,[{dbg,true}]]}, {Pid, Host, Port} = ssh_test_lib:daemon([{system_dir, SysDir}, {user_dir, UserDir}, {password, "morot"}, - {subsystems, [{"echo_n", {ssh_echo_server, [4000000]}}]}]), - + {subsystems, [{"echo_n",EchoSS_spec}]}]), + + ct:log("connect", []), ConnectionRef = ssh_test_lib:connect(Host, Port, [{silently_accept_hosts, true}, {user, "foo"}, {password, "morot"}, {user_interaction, false}, {user_dir, UserDir}]), - + ct:log("connected", []), {ok, ChannelId} = ssh_connection:session_channel(ConnectionRef, infinity), - + ct:log("start subsystem", []), success = ssh_connection:subsystem(ConnectionRef, ChannelId, "echo_n", infinity), %% build 10MB binary @@ -388,15 +390,21 @@ interrupted_send(Config) -> <> = Data, %% pre-adjust receive window so the other end doesn't block + ct:log("adjust window", []), ssh_connection:adjust_window(ConnectionRef, ChannelId, size(ExpectedData) + 1), + ct:log("going to send ~p bytes", [size(Data)]), case ssh_connection:send(ConnectionRef, ChannelId, Data, 10000) of {error, closed} -> + ct:log("{error,closed} - That's what we expect :)", []), ok; Msg -> + ct:log("Got ~p - that's bad, very bad indeed",[Msg]), ct:fail({expected,{error,closed}, got, Msg}) end, + ct:log("going to receive data", []), receive_data(ExpectedData, ConnectionRef, ChannelId), + ct:log("back from receive data", []), ssh:close(ConnectionRef), ssh:stop_daemon(Pid). @@ -860,15 +868,21 @@ receive_data(ExpectedData, ConnectionRef, ChannelId) -> ExpectedData = collect_data(ConnectionRef, ChannelId). collect_data(ConnectionRef, ChannelId) -> - collect_data(ConnectionRef, ChannelId, []). + ct:pal("Listener ~p running!",[self()]), + collect_data(ConnectionRef, ChannelId, [], 0). -collect_data(ConnectionRef, ChannelId, Acc) -> +collect_data(ConnectionRef, ChannelId, Acc, Sum) -> receive {ssh_cm, ConnectionRef, {data, ChannelId, 0, Data}} -> - collect_data(ConnectionRef, ChannelId, [Data | Acc]); + ct:pal("collect_data: received ~p bytes. total ~p bytes",[size(Data),Sum+size(Data)]), + collect_data(ConnectionRef, ChannelId, [Data | Acc], Sum+size(Data)); {ssh_cm, ConnectionRef, {eof, ChannelId}} -> - iolist_to_binary(lists:reverse(Acc)) + ct:pal("collect_data: received eof",[]), + R = iolist_to_binary(lists:reverse(Acc)), + ct:pal("Got in total ~p bytes",[size(R)]), + R after 5000 -> + ct:pal("collect_data: timeout",[]), timeout end. diff --git a/lib/ssh/test/ssh_echo_server.erl b/lib/ssh/test/ssh_echo_server.erl index ed9bbe1b67..3702630cb4 100644 --- a/lib/ssh/test/ssh_echo_server.erl +++ b/lib/ssh/test/ssh_echo_server.erl @@ -26,15 +26,29 @@ -record(state, { n, id, - cm + cm, + dbg = false }). -export([init/1, handle_msg/2, handle_ssh_msg/2, terminate/2]). +-define(DBG(State,Fmt,Args), + case State#state.dbg of + true -> ct:log("~p:~p ~p "++Fmt, [?MODULE,?LINE,self()|Args]); + false -> ok + end). + + init([N]) -> - ct:pal("Echo server: ~p",[self()]), - {ok, #state{n = N}}. + {ok, #state{n = N}}; +init([N,Opts]) -> + State = #state{n = N, + dbg = proplists:get_value(dbg,Opts,false) + }, + ?DBG(State, "init([~p])",[N]), + {ok, State}. handle_msg({ssh_channel_up, ChannelId, ConnectionManager}, State) -> + ?DBG(State, "ssh_channel_up Cid=~p ConnMngr=~p",[ChannelId,ConnectionManager]), {ok, State#state{id = ChannelId, cm = ConnectionManager}}. @@ -42,32 +56,39 @@ handle_ssh_msg({ssh_cm, CM, {data, ChannelId, 0, Data}}, #state{n = N} = State) M = N - size(Data), case M > 0 of true -> + ?DBG(State, "ssh_cm data Cid=~p size(Data)=~p M=~p",[ChannelId,size(Data),M]), ssh_connection:send(CM, ChannelId, Data), {ok, State#state{n = M}}; false -> <> = Data, + ?DBG(State, "ssh_cm data Cid=~p size(Data)=~p M=~p size(SendData)=~p",[ChannelId,size(Data),M,size(SendData)]), ssh_connection:send(CM, ChannelId, SendData), ssh_connection:send_eof(CM, ChannelId), {stop, ChannelId, State} end; handle_ssh_msg({ssh_cm, _ConnectionManager, {data, _ChannelId, 1, Data}}, State) -> + ?DBG(State, "stderr: ~p",[Data]), error_logger:format(standard_error, " ~p~n", [binary_to_list(Data)]), {ok, State}; handle_ssh_msg({ssh_cm, _ConnectionManager, {eof, _ChannelId}}, State) -> + ?DBG(State, "{eof ~p}",[_ChannelId]), {ok, State}; -handle_ssh_msg({ssh_cm, _, {signal, _, _}}, State) -> +handle_ssh_msg({ssh_cm, _, _Sig={signal, _, _}}, State) -> %% Ignore signals according to RFC 4254 section 6.9. + ?DBG(State, "~p",[_Sig]), {ok, State}; -handle_ssh_msg({ssh_cm, _, {exit_signal, ChannelId, _, _Error, _}}, - State) -> +handle_ssh_msg({ssh_cm, _, _Sig={exit_signal, ChannelId, _, _Error, _}}, State) -> + ?DBG(State, "~p",[_Sig]), {stop, ChannelId, State}; -handle_ssh_msg({ssh_cm, _, {exit_status, ChannelId, _Status}}, State) -> +handle_ssh_msg({ssh_cm, _, _Sig={exit_status, ChannelId, _Status}}, State) -> + ?DBG(State, "~p",[_Sig]), {stop, ChannelId, State}. terminate(_Reason, _State) -> + ?DBG(_State, "terminate ~p",[_Reason]), ok. -- cgit v1.2.3