ssh: logging in test helper ssh_echo_server

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) ->
     <<ExpectedData:4000000/binary, _/binary>> = 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 ->
 	    <<SendData:N/binary, _/binary>> = 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.