From 59e87972927c947353231d018217da696d03478c Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 31 Oct 2014 16:25:56 +0100 Subject: [ct_telnet] Don't send extra newline after password The telnet client used to send an extra newline after the password. This caused an extra prompt to be sent back from the server. Some test cases failed every now and then due to this - since the second promt was confusing. This is now corrected, i.e. the client does no longer send an extra newline after the password. --- lib/common_test/src/unix_telnet.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 -- cgit v1.2.3 From cc3200e4010e994529af659d41057e6587f36079 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 3 Nov 2014 12:07:15 +0100 Subject: [ct_telnet] Extend timeout in test from 1 to 2 sek This is for stabilizing test cases. --- .../ct_telnet_SUITE_data/ct_telnet_own_server_SUITE.erl | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) 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..6ec7947b3e 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. @@ -283,7 +285,7 @@ server_speaks(_) -> ok = ct_telnet:send(Handle, "echo_no_prompt This is the third message\r\n"), {ok,_} = ct_telnet:expect(Handle, ["the"], [no_prompt_check]), {error,timeout} = ct_telnet:expect(Handle, ["the"], [no_prompt_check, - {timeout,1000}]), + {timeout,?SHORT_TIME}]), ok = ct_telnet:send(Handle, "echo_no_prompt This is the fourth message\r\n"), %% give the server time to respond timer:sleep(2000), -- cgit v1.2.3 From fbe57ae10df43ea6015bac649ca5d72eb9b9e440 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 3 Nov 2014 12:34:55 +0100 Subject: [ct_telnet] Add timestamp to telnet_server debug printout This is the telnet server used when testing ct_telnet and friends. The telnet client itself is not changed. --- lib/common_test/test/telnet_server.erl | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) 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])). -- cgit v1.2.3 From 96aed0a4d6b6abc9893000eeb56ae664bc716451 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 3 Nov 2014 13:28:42 +0100 Subject: [ct_telnet] Improve debug printouts and logging ct_telnet_own_server_SUITE:large_string sometimes fail in the last attempt - where get_data is used to fetch smaller chunks - probably because one get_data message towards ct_telnet_client returns without having received any new data. This commit adds timestamps to debug printouts and improves the logging. --- lib/common_test/src/ct_telnet_client.erl | 44 +++++++++++++++++++++----------- 1 file changed, 29 insertions(+), 15 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. -- cgit v1.2.3 From 611394791acbe7ae98417b9115aeeaa7046e78a2 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 17 Nov 2014 10:39:19 +0100 Subject: [ct_telnet] Fix test case 'server_speaks' This test case simulates that the server spontaneously sends data. By changing ct_telnet:send to ct_telnet_client:send_data this simulations makes more sense - since client's buffers are not flushed. Also removed the newline at the end of "echo_no_prompt" command. Since newline is added automatically, the explicit newline at the end of the command causes a prompt to be sent which is not expected. --- .../ct_telnet_own_server_SUITE.erl | 28 ++++++++++++++++------ 1 file changed, 21 insertions(+), 7 deletions(-) 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 6ec7947b3e..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 @@ -276,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,?SHORT_TIME}]), - ok = ct_telnet:send(Handle, "echo_no_prompt This is the fourth message\r\n"), + 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 @@ -301,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), -- cgit v1.2.3