Get ct_telnet_client to print all data from server to log

6 files changed, 128 insertions, 50 deletions

diff --git a/lib/common_test/src/ct_telnet.erl b/lib/common_test/src/ct_telnet.erl
index fc71647edd..096e893720 100644
--- a/lib/common_test/src/ct_telnet.erl
+++ b/lib/common_test/src/ct_telnet.erl
@@ -788,19 +788,14 @@ log(#state{name=Name,teln_pid=TelnPid,host=Host,port=Port},
 	    case ct_util:get_testdata({cth_conn_log,?MODULE}) of
 		HookMode when HookMode /= undefined, HookMode /= silent,
 			      Silent /= true ->
-		    {PrintHeader,PreBR} = if Action==undefined ->
-						  {false,""};
-					     true ->
-						  {true,"\n"}
-					  end,
-		    error_logger:info_report(#conn_log{header=PrintHeader,
+		    error_logger:info_report(#conn_log{header=false,
 						       client=self(),
 						       conn_pid=TelnPid,
 						       address={Host,Port},
 						       name=Name1,
 						       action=Action,
 						       module=?MODULE},
-					     {PreBR++String,Args});
+					     {String,Args});
 		_ -> %% hook inactive or silence requested
 		    ok
 	    end;
@@ -1027,19 +1022,25 @@ teln_expect1(Name,Pid,Data,Pattern,Acc,EO) ->
 	NotFinished ->
 	    %% Get more data
 	    Fun = fun() -> get_data1(EO#eo.teln_pid) end,
-	    case ct_gen_conn:do_within_time(Fun, EO#eo.timeout) of
-		{error,Reason} -> 
+	    case timer:tc(ct_gen_conn, do_within_time, [Fun, EO#eo.timeout]) of
+		{_,{error,Reason}} -> 
 		    %% A timeout will occur when the telnet connection
 		    %% is idle for EO#eo.timeout milliseconds.
 		    {error,Reason};
-		{ok,Data1} ->
-		    case NotFinished of
-			{nomatch,Rest} ->
-			    %% One expect
-			    teln_expect1(Name,Pid,Rest++Data1,Pattern,[],EO);
-			{continue,Patterns1,Acc1,Rest} ->
-			    %% Sequence
-			    teln_expect1(Name,Pid,Rest++Data1,Patterns1,Acc1,EO)
+		{Elapsed,{ok,Data1}} ->
+		    TVal = trunc(EO#eo.timeout - (Elapsed/1000)),
+		    if TVal =< 0 ->
+			    {error,timeout};
+		       true ->
+			    EO1 = EO#eo{timeout = TVal},
+			    case NotFinished of
+				{nomatch,Rest} ->
+				    %% One expect
+				    teln_expect1(Name,Pid,Rest++Data1,Pattern,[],EO1);
+				{continue,Patterns1,Acc1,Rest} ->
+				    %% Sequence
+				    teln_expect1(Name,Pid,Rest++Data1,Patterns1,Acc1,EO1)
+			    end
 		    end
 	    end
     end.
diff --git a/lib/common_test/src/ct_telnet_client.erl b/lib/common_test/src/ct_telnet_client.erl
index 2cbcba9c77..f18496cdc2 100644
--- a/lib/common_test/src/ct_telnet_client.erl
+++ b/lib/common_test/src/ct_telnet_client.erl
@@ -32,9 +32,12 @@
 
 -module(ct_telnet_client).
 
--export([open/1, open/2, open/3, open/4, close/1]).
+-export([open/2, open/3, open/4, open/5, close/1]).
 -export([send_data/2, get_data/1]).
 
+%%! --- Sun Mar  9 22:03:49 2014 --- peppe was here!
+-define(debug, true).
+
 -define(TELNET_PORT, 23).
 -define(OPEN_TIMEOUT,10000).
 -define(IDLE_TIMEOUT,10000).
@@ -64,20 +67,23 @@
 -define(TERMINAL_TYPE,     24).  
 -define(WINDOW_SIZE,       31).
 
--record(state,{get_data, keep_alive=true}).
+-record(state,{conn_name, get_data, keep_alive=true, log_pos=1}).
 
-open(Server) ->
-    open(Server, ?TELNET_PORT, ?OPEN_TIMEOUT, true).
+open(Server, ConnName) ->
+    open(Server, ?TELNET_PORT, ?OPEN_TIMEOUT, true, ConnName).
 
-open(Server, Port) ->
-    open(Server, Port, ?OPEN_TIMEOUT, true).
+open(Server, Port, ConnName) ->
+    open(Server, Port, ?OPEN_TIMEOUT, true, ConnName).
 
-open(Server, Port, Timeout) ->
-    open(Server, Port, Timeout, true).
+open(Server, Port, Timeout, ConnName) ->
+    open(Server, Port, Timeout, true, ConnName).
 
-open(Server, Port, Timeout, KeepAlive) ->
+open(Server, Port, Timeout, KeepAlive, ConnName) ->
     Self = self(),
-    Pid = spawn(fun() -> init(Self, Server, Port, Timeout, KeepAlive) end),
+    Pid = spawn(fun() ->
+			init(Self, Server, Port, Timeout,
+			     KeepAlive, ConnName)
+		end),
     receive 
 	{open,Pid} ->
 	    {ok,Pid};
@@ -86,14 +92,17 @@ open(Server, Port, Timeout, KeepAlive) ->
     end.
 
 close(Pid) ->
-    Pid ! close.
+    Pid ! {close,self()},
+    receive closed -> ok 
+    after 5000 -> ok
+    end.	    
 
 send_data(Pid, Data) ->
     Pid ! {send_data, Data++"\n"},
     ok.
 
 get_data(Pid) ->
-    Pid ! {get_data, self()},
+    Pid ! {get_data,self()},
     receive 
 	{data,Data} ->
 	    {ok, Data}
@@ -102,13 +111,15 @@ get_data(Pid) ->
 
 %%%-----------------------------------------------------------------
 %%% Internal functions
-init(Parent, Server, Port, Timeout, KeepAlive) ->
+init(Parent, Server, Port, Timeout, KeepAlive, ConnName) ->
     case gen_tcp:connect(Server, Port, [list,{packet,0}], Timeout) of
 	{ok,Sock} ->
-	    dbg("Connected to: ~p (port: ~w, keep_alive: ~w)\n", [Server,Port,KeepAlive]),
+	    dbg("~p connected to: ~p (port: ~w, keep_alive: ~w)\n",
+		[ConnName,Server,Port,KeepAlive]),
 	    send([?IAC,?DO,?SUPPRESS_GO_AHEAD], Sock),	      
 	    Parent ! {open,self()},
-	    loop(#state{get_data=10, keep_alive=KeepAlive}, Sock, []),
+	    loop(#state{conn_name=ConnName, get_data=10, keep_alive=KeepAlive},
+		 Sock, []),
 	    gen_tcp:close(Sock);
         Error ->
 	    Parent ! {Error,self()}
@@ -118,6 +129,12 @@ loop(State, Sock, Acc) ->
     receive
 	{tcp_closed,_} ->
 	    dbg("Connection closed\n", []),
+	    Data = lists:reverse(lists:append(Acc)),
+	    ct_telnet:log(State#state.conn_name,
+			  general_io, "~ts",
+			  [lists:sublist(Data,
+					 State#state.log_pos,
+					 length(Data))]),
 	    receive
 		{get_data,Pid} ->
 		    Pid ! closed
@@ -144,9 +161,15 @@ loop(State, Sock, Acc) ->
 			end;
 		    _ ->
 			Data = lists:reverse(lists:append(Acc)),
+			Len = length(Data),
 			dbg("get_data ~p\n",[Data]),
+			ct_telnet:log(State#state.conn_name,
+				      general_io, "~ts",
+				      [lists:sublist(Data,
+						     State#state.log_pos,
+						     Len)]),
 			Pid ! {data,Data},
-			State
+			State#state{log_pos = 1}
 		end,
 	    loop(NewState, Sock, []);
 	{get_data_delayed,Pid} ->
@@ -160,27 +183,54 @@ loop(State, Sock, Acc) ->
 		    _ ->
 			State
 		end,
-	    NewAcc = 
+	    {NewAcc,Pos} = 
 		case erlang:is_process_alive(Pid) of
 		    true ->
 			Data = lists:reverse(lists:append(Acc)),
+			Len = length(Data),
 			dbg("get_data_delayed ~p\n",[Data]),
+			ct_telnet:log(State#state.conn_name,
+				      general_io, "~ts",
+				      [lists:sublist(Data,
+						     State#state.log_pos,
+						     Len)]),
 			Pid ! {data,Data},
-			[];
+			{[],1};
 		    false ->
-			Acc
+			{Acc,NewState#state.log_pos}
 		end,
-	    loop(NewState, Sock, NewAcc);			       
-	close ->
+	    loop(NewState#state{log_pos=Pos}, Sock, NewAcc);			       
+	{close,Pid} ->
 	    dbg("Closing connection\n", []),
+	    if Acc == [] ->
+		    ok;
+	       true ->
+		    Data = lists:reverse(lists:append(Acc)),
+		    ct_telnet:log(State#state.conn_name,
+				  general_io, "~ts",
+				  [lists:sublist(Data,
+						 State#state.log_pos,
+						 length(Data))])
+	    end,
 	    gen_tcp:close(Sock),
-	    ok
+	    Pid ! closed
     after wait(State#state.keep_alive,?IDLE_TIMEOUT) ->
-	    if 
-		Acc == [] -> send([?IAC,?NOP], Sock);
-		true -> ok
-	    end,
-	    loop(State, Sock, Acc)
+	    Data = lists:reverse(lists:append(Acc)),
+	    case Data of
+		[] ->
+		    send([?IAC,?NOP], Sock),
+		    loop(State, Sock, Acc);
+		_ when State#state.log_pos == length(Data)+1 ->
+		    loop(State, Sock, Acc);
+		_ ->
+		    Len = length(Data),
+		    ct_telnet:log(State#state.conn_name,
+				  general_io, "~ts",
+				  [lists:sublist(Data,
+						 State#state.log_pos,
+						 Len)]),
+		    loop(State#state{log_pos = Len+1}, Sock, Acc)
+	    end
     end.
 
 wait(true, Time) -> Time;
diff --git a/lib/common_test/src/unix_telnet.erl b/lib/common_test/src/unix_telnet.erl
index e049c3bf39..5854725c17 100644
--- a/lib/common_test/src/unix_telnet.erl
+++ b/lib/common_test/src/unix_telnet.erl
@@ -109,7 +109,7 @@ connect(ConnName,Ip,Port,Timeout,KeepAlive,Extra) ->
 connect1(Name,Ip,Port,Timeout,KeepAlive,Username,Password) ->
     start_gen_log("unix_telnet connect"),
     Result = 
-	case ct_telnet_client:open(Ip,Port,Timeout,KeepAlive) of
+	case ct_telnet_client:open(Ip,Port,Timeout,KeepAlive,Name) of
 	    {ok,Pid} ->
 		case ct_telnet:silent_teln_expect(Name,Pid,[],
 						  [prompt],?prx,[]) of
diff --git a/lib/common_test/test/ct_telnet_SUITE.erl b/lib/common_test/test/ct_telnet_SUITE.erl
index acce4eca14..8163009409 100644
--- a/lib/common_test/test/ct_telnet_SUITE.erl
+++ b/lib/common_test/test/ct_telnet_SUITE.erl
@@ -73,11 +73,13 @@ end_per_suite(Config) ->
     ct_test_support:end_per_suite(Config).
 
 init_per_testcase(TestCase, Config) when TestCase=/=unix_telnet->
+    ct:pal("Testcase ~p starting!", [TestCase]),
     TS = telnet_server:start([{port,?erl_telnet_server_port},
 			      {users,[{?erl_telnet_server_user,
 				       ?erl_telnet_server_pwd}]}]),
     ct_test_support:init_per_testcase(TestCase, [{telnet_server,TS}|Config]);
 init_per_testcase(TestCase, Config) ->
+    ct:pal("Testcase ~p starting!", [TestCase]),
     ct_test_support:init_per_testcase(TestCase, Config).
 
 end_per_testcase(TestCase, Config) ->
diff --git a/lib/common_test/test/ct_telnet_SUITE_data/ct_telnet_own_server_SUITE.erl b/lib/common_test/test/ct_telnet_SUITE_data/ct_telnet_own_server_SUITE.erl
index 8d142e85a8..0277dc2a44 100644
--- a/lib/common_test/test/ct_telnet_SUITE_data/ct_telnet_own_server_SUITE.erl
+++ b/lib/common_test/test/ct_telnet_SUITE_data/ct_telnet_own_server_SUITE.erl
@@ -28,7 +28,8 @@ all() ->
      ignore_prompt,
      ignore_prompt_repeat,
      ignore_prompt_sequence,
-     ignore_prompt_timeout].
+     ignore_prompt_timeout,
+     server_speaks].
 
 groups() ->
     [].
@@ -188,3 +189,19 @@ no_prompt_check_timeout(_) ->
 							 {timeout,1000}]),
     ok = ct_telnet:close(Handle),
     ok.
+
+%% Let the server say things, to make sure it gets printed correctly
+%% in the general IO log
+server_speaks(_) ->
+    {ok, Handle} = ct_telnet:open(telnet_server_conn1),
+    ok = ct_telnet:send(Handle, "echo This is the first message"),
+    ok = ct_telnet:send(Handle, "echo This is the second message"),
+    %% let ct_telnet_client get an idle timeout
+    timer:sleep(15000),
+    ok = ct_telnet:send(Handle, "echo This is the third message"),
+    {ok,_} = ct_telnet:expect(Handle, ["the"], [no_prompt_check]),
+    {error,timeout} = ct_telnet:expect(Handle, ["the"], [no_prompt_check,
+							 {timeout,1000}]),
+    ok = ct_telnet:send(Handle, "echo This is the fourth message"),
+    ok = ct_telnet:close(Handle),
+    ok.  
diff --git a/lib/common_test/test/telnet_server.erl b/lib/common_test/test/telnet_server.erl
index 1760100d8e..eb90f18320 100644
--- a/lib/common_test/test/telnet_server.erl
+++ b/lib/common_test/test/telnet_server.erl
@@ -67,7 +67,7 @@ accept(#state{listen=LSock}=State) ->
 		    io:format("[telnet_server] telnet_server stopped\n"),
 		    ok;
 		R ->
-		    io:format("[telnet_server] connection to client" 
+		    io:format("[telnet_server] connection to client " 
 			      "closed with reason ~p~n",[R]),
 		    accept(State)
 	    end;
@@ -97,19 +97,19 @@ init_client(#state{client=Sock}=State) ->
     dbg("Server sending: ~p~n",["login: "]),
     R = case gen_tcp:send(Sock,"login: ") of
 	    ok ->
-		loop(State);
+		loop(State, 1);
 	    Error ->
 		Error
 	end,
     _ = gen_tcp:close(Sock),
     R.
 
-loop(State) ->
+loop(State, N) ->
     receive
 	{tcp,_,Data} ->
 	    try handle_data(Data,State) of
 		{ok,State1} ->
-		    loop(State1)
+		    loop(State1, N)
 	    catch 
 		throw:Error ->
 		    Error
@@ -120,6 +120,14 @@ loop(State) ->
 	    {error,tcp,Error};
 	stop ->
 	    stopped
+    after
+	500 ->
+	    Report = lists:flatten(
+		       io_lib:format("The CT Telnet Server says: "
+				     "Iteration no ~w\r\n", [N])),
+	    dbg("Server sending: ~s~n", [Report]),
+	    gen_tcp:send(State#state.client, Report),
+	    loop(State, N+1)
     end.
 
 handle_data([?IAC|Cmd],State) ->