Merge branch 'siri/ct_telnet/unstable-tests/OTP-12329' into maint

* siri/ct_telnet/unstable-tests/OTP-12329:
  [ct_telnet] Fix test case 'server_speaks'
  [ct_telnet] Improve debug printouts and logging
  [ct_telnet] Add timestamp to telnet_server debug printout
  [ct_telnet] Extend timeout in test from 1 to 2 sek
  [ct_telnet] Don't send extra newline after password

4 files changed, 72 insertions, 32 deletions

diff --git a/lib/common_test/src/ct_telnet_client.erl b/lib/common_test/src/ct_telnet_client.erl
index 3ae373e433..36d33522a3 100644
--- a/lib/common_test/src/ct_telnet_client.erl
+++ b/lib/common_test/src/ct_telnet_client.erl
@@ -250,7 +250,13 @@ wait(false, _) -> infinity.
 send(Data, Sock, ConnName) ->
     case Data of
 	[?IAC|_] = Cmd ->
-	    cmd_dbg(Cmd);
+	    cmd_dbg("Sending",Cmd),
+	    try io_lib:format("[~w] ~w", [?MODULE,Data]) of
+		Str ->
+		    ct_telnet:log(ConnName, general_io, Str, [])
+	    catch
+		_:_ -> ok
+	    end;
 	_ ->
 	    dbg("Sending: ~tp\n", [Data]),
 	    try io_lib:format("[~w] ~ts", [?MODULE,Data]) of
@@ -271,8 +277,7 @@ check_msg(Sock, [?IAC,?IAC | T], Acc) ->
 check_msg(Sock, [?IAC | Cs], Acc) ->
     case get_cmd(Cs) of
 	{Cmd,Cs1} ->
-	    dbg("Got ", []), 
-	    cmd_dbg(Cmd),
+	    cmd_dbg("Got",Cmd),
 	    respond_cmd(Cmd, Sock),
 	    check_msg(Sock, Cs1, Acc); 
 	error ->
@@ -291,12 +296,12 @@ check_msg(_Sock, [], Acc) ->
 
 respond_cmd([?WILL,?ECHO], Sock) ->
     R = [?IAC,?DO,?ECHO],
-    cmd_dbg(R),
+    cmd_dbg("Responding",R),
     gen_tcp:send(Sock, R);
 
 respond_cmd([?DO,?ECHO], Sock) ->
     R = [?IAC,?WILL,?ECHO],
-    cmd_dbg(R),
+    cmd_dbg("Responding",R),
     gen_tcp:send(Sock, R);
 
 %% Answers from server
@@ -316,12 +321,12 @@ respond_cmd([?WONT | _Opt], _Sock) ->		% server ack?
 
 respond_cmd([?WILL,Opt], Sock) ->
     R = [?IAC,?DONT,Opt],
-    cmd_dbg(R),
+    cmd_dbg("Responding",R),
     gen_tcp:send(Sock, R);
 
 respond_cmd([?DO | Opt], Sock) ->
     R = [?IAC,?WONT | Opt],
-    cmd_dbg(R),
+    cmd_dbg("Responding",R),
     gen_tcp:send(Sock, R);
 
 %% Commands without options (which we ignore)
@@ -357,13 +362,14 @@ get_subcmd([Opt | Rest], Acc) ->
     get_subcmd(Rest, [Opt | Acc]).
 
 -ifdef(debug).
-dbg(_Str,_Args) ->
-    io:format(_Str,_Args).
+dbg(Str,Args) ->
+    TS = timestamp(),
+    io:format("[~p ct_telnet_client, ~s]\n" ++ Str,[self(),TS|Args]).
 
-cmd_dbg(_Cmd) ->
-    case _Cmd of
+cmd_dbg(Prefix,Cmd) ->
+    case Cmd of
 	[?IAC|Cmd1] ->
-	    cmd_dbg(Cmd1);
+	    cmd_dbg(Prefix,Cmd1);
 	[Ctrl|Opts] ->
 	    CtrlStr =
 		case Ctrl of
@@ -379,15 +385,23 @@ cmd_dbg(_Cmd) ->
 		    [Opt] -> Opt;
 		    _ -> Opts
 		end,
-	    io:format("~ts(~w): ~w\n", [CtrlStr,Ctrl,Opts1]);
+	    dbg("~ts: ~ts(~w): ~w\n", [Prefix,CtrlStr,Ctrl,Opts1]);
 	Any  ->
-	    io:format("Unexpected in cmd_dbg:~n~w~n",[Any])
+	    dbg("Unexpected in cmd_dbg:~n~w~n",[Any])
     end.
 
+timestamp() ->
+    {MS,S,US} = now(),
+    {{Year,Month,Day}, {Hour,Min,Sec}} =
+        calendar:now_to_local_time({MS,S,US}),
+    MilliSec = trunc(US/1000),
+    lists:flatten(io_lib:format("~4.10.0B-~2.10.0B-~2.10.0B "
+                                "~2.10.0B:~2.10.0B:~2.10.0B.~3.10.0B",
+                                [Year,Month,Day,Hour,Min,Sec,MilliSec])).
 -else.
 dbg(_Str,_Args) ->
     ok.
 
-cmd_dbg(_Cmd) ->
+cmd_dbg(_Prefix,_Cmd) ->
     ok.
 -endif.
diff --git a/lib/common_test/src/unix_telnet.erl b/lib/common_test/src/unix_telnet.erl
index 10666b979d..09b6fd1510 100644
--- a/lib/common_test/src/unix_telnet.erl
+++ b/lib/common_test/src/unix_telnet.erl
@@ -1,7 +1,7 @@
 %%
 %% %CopyrightBegin%
 %%
-%% Copyright Ericsson AB 2004-2013. All Rights Reserved.
+%% Copyright Ericsson AB 2004-2014. All Rights Reserved.
 %%
 %% The contents of this file are subject to the Erlang Public License,
 %% Version 1.1, (the "License"); you may not use this file except in
@@ -122,7 +122,7 @@ connect1(Name,Ip,Port,Timeout,KeepAlive,Username,Password) ->
 				ok = ct_telnet_client:send_data(Pid,Password),
 				Stars = lists:duplicate(length(Password),$*),
 				log(Name,send,"Password: ~s",[Stars]),
-				ok = ct_telnet_client:send_data(Pid,""),
+%				ok = ct_telnet_client:send_data(Pid,""),
 				case ct_telnet:silent_teln_expect(Name,Pid,[],
 								  prompt,
 								  ?prx,[]) of
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 9afe545b26..0ddb4e9b00 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
@@ -22,6 +22,8 @@
 -define(DONT,	254).
 -define(IAC,	255).
 
+-define(SHORT_TIME,2000).
+
 %%--------------------------------------------------------------------
 %% TEST SERVER CALLBACK FUNCTIONS
 %%--------------------------------------------------------------------
@@ -115,7 +117,7 @@ expect_error_prompt(_) ->
 expect_error_timeout1(_) ->
     {ok, Handle} = ct_telnet:open(telnet_server_conn1),
     ok = ct_telnet:send(Handle, "echo_no_prompt xxx"),
-    {error,timeout} = ct_telnet:expect(Handle, ["xxx"], [{timeout,1000}]),
+    {error,timeout} = ct_telnet:expect(Handle, ["xxx"], [{timeout,?SHORT_TIME}]),
     ok = ct_telnet:close(Handle),
     ok.
 
@@ -178,16 +180,16 @@ ignore_prompt_timeout(_) ->
     {ok, Handle} = ct_telnet:open(telnet_server_conn1),
     ok = ct_telnet:send(Handle, "echo xxx"),
     {error,timeout} = ct_telnet:expect(Handle, ["yyy"], [ignore_prompt,
-							 {timeout,1000}]),
+							 {timeout,?SHORT_TIME}]),
     ok = ct_telnet:send(Handle, "echo xxx"), % sends prompt and newline
     {ok,["xxx"]} = ct_telnet:expect(Handle, ["xxx"], [ignore_prompt,
-						      {timeout,1000}]),
+						      {timeout,?SHORT_TIME}]),
     ok = ct_telnet:send(Handle, "echo_no_prompt xxx\n"), % no prompt, but newline
     {ok,["xxx"]} = ct_telnet:expect(Handle, ["xxx"], [ignore_prompt,
-						      {timeout,1000}]),
+						      {timeout,?SHORT_TIME}]),
     ok = ct_telnet:send(Handle, "echo_no_prompt xxx"), % no prompt, no newline
     {error,timeout} = ct_telnet:expect(Handle, ["xxx"], [ignore_prompt,
-							 {timeout,1000}]),
+							 {timeout,?SHORT_TIME}]),
     ok = ct_telnet:close(Handle),
     ok.
 
@@ -233,7 +235,7 @@ no_prompt_check_timeout(_) ->
     {ok, Handle} = ct_telnet:open(telnet_server_conn1),
     ok = ct_telnet:send(Handle, "echo xxx"),
     {error,timeout} = ct_telnet:expect(Handle, ["yyy"], [no_prompt_check,
-							 {timeout,1000}]),
+							 {timeout,?SHORT_TIME}]),
     ok = ct_telnet:close(Handle),
     ok.
 
@@ -274,17 +276,31 @@ large_string(_) ->
 
 %% The server says things. Manually check that it gets printed correctly
 %% in the general IO log.
+%%
+%% In this test case we simulate data sent spontaneously from the
+%% server. We use ct_telnet_client:send_data instead of ct_telnet:send
+%% to avoid flushing of buffers in the client, and we use
+%% echo_no_prompt since the server would normally not send a prompt in
+%% this case.
 server_speaks(_) ->
     {ok, Handle} = ct_telnet:open(telnet_server_conn1),
-    ok = ct_telnet:send(Handle, "echo_no_prompt This is the first message\r\n"),
-    ok = ct_telnet:send(Handle, "echo_no_prompt This is the second message\r\n"),
-    %% let ct_telnet_client get an idle timeout
+
+    Backdoor = ct_gen_conn:get_conn_pid(Handle),
+    ok = ct_telnet_client:send_data(Backdoor,
+				    "echo_no_prompt This is the first message"),
+    ok = ct_telnet_client:send_data(Backdoor,
+				    "echo_no_prompt This is the second message"),
+    %% Let ct_telnet_client get an idle timeout. This should print the
+    %% two messages to the log. Note that the buffers are not flushed here!
     timer:sleep(15000),
-    ok = ct_telnet:send(Handle, "echo_no_prompt This is the third message\r\n"),
-    {ok,_} = ct_telnet:expect(Handle, ["the"], [no_prompt_check]),
+    ok = ct_telnet_client:send_data(Backdoor,
+				    "echo_no_prompt This is the third message"),
+    {ok,_} = ct_telnet:expect(Handle, ["first.*second.*third"],
+			      [no_prompt_check, sequence]),
     {error,timeout} = ct_telnet:expect(Handle, ["the"], [no_prompt_check,
-							 {timeout,1000}]),
-    ok = ct_telnet:send(Handle, "echo_no_prompt This is the fourth message\r\n"),
+							 {timeout,?SHORT_TIME}]),
+    ok = ct_telnet_client:send_data(Backdoor,
+				    "echo_no_prompt This is the fourth message"),
     %% give the server time to respond
     timer:sleep(2000),
     %% closing the connection should print last message in log
@@ -299,7 +315,7 @@ server_disconnects(_) ->
     %% wait until the get_data operation (triggered by send/2) times out
     %% before sending the msg
     timer:sleep(500),
-    ok = ct_telnet:send(Handle, "echo_no_prompt This is the message\r\n"),
+    ok = ct_telnet:send(Handle, "echo_no_prompt This is the message"),
     %% when the server closes the connection, the last message should be
     %% printed in the log
     timer:sleep(3000),
diff --git a/lib/common_test/test/telnet_server.erl b/lib/common_test/test/telnet_server.erl
index 0a23a66324..d25ee62d38 100644
--- a/lib/common_test/test/telnet_server.erl
+++ b/lib/common_test/test/telnet_server.erl
@@ -310,4 +310,14 @@ get_line([],_) ->
 dbg(_F) ->
     dbg(_F,[]).
 dbg(_F,_A) ->
-    io:format("[telnet_server] " ++ _F,_A).
+    TS = timestamp(),
+    io:format("[telnet_server, ~s]\n" ++ _F,[TS|_A]).
+
+timestamp() ->
+    {MS,S,US} = now(),
+    {{Year,Month,Day}, {Hour,Min,Sec}} =
+        calendar:now_to_local_time({MS,S,US}),
+    MilliSec = trunc(US/1000),
+    lists:flatten(io_lib:format("~4.10.0B-~2.10.0B-~2.10.0B "
+                                "~2.10.0B:~2.10.0B:~2.10.0B.~3.10.0B",
+                                [Year,Month,Day,Hour,Min,Sec,MilliSec])).