From d6fb44e0575ecd022c30d5c6a7503c8849d98fa9 Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Fri, 7 Mar 2014 16:16:41 +0100 Subject: Change telnet logging behaviour OTP-11690 --- lib/common_test/src/ct_telnet.erl | 102 +++++++++++++++++++------------------- 1 file changed, 51 insertions(+), 51 deletions(-) diff --git a/lib/common_test/src/ct_telnet.erl b/lib/common_test/src/ct_telnet.erl index b4d82a53cf..fc71647edd 100644 --- a/lib/common_test/src/ct_telnet.erl +++ b/lib/common_test/src/ct_telnet.erl @@ -783,66 +783,66 @@ log(#state{name=Name,teln_pid=TelnPid,host=Host,port=Port}, true -> Name end, Silent = get(silent), - case ct_util:get_testdata({cth_conn_log,?MODULE}) of - Result when Result /= undefined, Result /= silent, Silent /= true -> - {PrintHeader,PreBR} = if Action==undefined -> - {false,""}; - true -> - {true,"\n"} - end, - error_logger:info_report(#conn_log{header=PrintHeader, - client=self(), - conn_pid=TelnPid, - address={Host,Port}, - name=Name1, - action=Action, - module=?MODULE}, - {PreBR++String,Args}); - Result when Result /= undefined -> - ok; - _ when Action == open; Action == close; Action == reconnect; - Action == info; Action == error -> - ct_gen_conn:log(heading(Action,Name1),String,Args); - _ when ForcePrint == false -> - case ct_util:is_silenced(telnet) of - true -> - ok; - false -> - ct_gen_conn:cont_log(String,Args) + + if Action == general_io -> + 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, + client=self(), + conn_pid=TelnPid, + address={Host,Port}, + name=Name1, + action=Action, + module=?MODULE}, + {PreBR++String,Args}); + _ -> %% hook inactive or silence requested + ok end; - _ when ForcePrint == true -> - case ct_util:is_silenced(telnet) of - true -> - %% call log/3 now instead of cont_log/2 since - %% start_gen_log/1 will not have been previously called + + true -> + if Action == open; Action == close; Action == reconnect; + Action == info; Action == error -> ct_gen_conn:log(heading(Action,Name1),String,Args); - false -> - ct_gen_conn:cont_log(String,Args) + + ForcePrint == false -> + case ct_util:is_silenced(telnet) of + true -> + ok; + false -> + ct_gen_conn:cont_log(String,Args) + end; + + ForcePrint == true -> + case ct_util:is_silenced(telnet) of + true -> + %% call log/3 now instead of cont_log/2 since + %% start_gen_log/1 will not have been previously + %% called + ct_gen_conn:log(heading(Action,Name1),String,Args); + false -> + ct_gen_conn:cont_log(String,Args) + end end end. start_gen_log(Heading) -> - case ct_util:get_testdata({cth_conn_log,?MODULE}) of - undefined -> - %% check if output is suppressed - case ct_util:is_silenced(telnet) of - true -> ok; - false -> ct_gen_conn:start_log(Heading) - end; - _ -> - ok + %% check if output is suppressed + case ct_util:is_silenced(telnet) of + true -> ok; + false -> ct_gen_conn:start_log(Heading) end. end_gen_log() -> - case ct_util:get_testdata({cth_conn_log,?MODULE}) of - undefined -> - %% check if output is suppressed - case ct_util:is_silenced(telnet) of - true -> ok; - false -> ct_gen_conn:end_log() - end; - _ -> - ok + %% check if output is suppressed + case ct_util:is_silenced(telnet) of + true -> ok; + false -> ct_gen_conn:end_log() end. %%% @hidden -- cgit v1.2.3 From 609349f6acac4b03b8cac53eb9ad456a2b2d5536 Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Mon, 10 Mar 2014 01:40:14 +0100 Subject: Get ct_telnet_client to print all data from server to log --- lib/common_test/src/ct_telnet.erl | 35 +++---- lib/common_test/src/ct_telnet_client.erl | 104 +++++++++++++++------ lib/common_test/src/unix_telnet.erl | 2 +- lib/common_test/test/ct_telnet_SUITE.erl | 2 + .../ct_telnet_own_server_SUITE.erl | 19 +++- lib/common_test/test/telnet_server.erl | 16 +++- 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) -> -- cgit v1.2.3 From 5667601be38a2e35fbbe59491f448f947bfcc73c Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Mon, 10 Mar 2014 16:22:25 +0100 Subject: Add test cases and fix some problems with logging and with the telnet client --- lib/common_test/src/ct_gen_conn.erl | 2 +- lib/common_test/src/ct_telnet.erl | 16 ++-- lib/common_test/src/ct_telnet_client.erl | 41 +++++++---- lib/common_test/src/unix_telnet.erl | 4 +- lib/common_test/test/ct_telnet_SUITE.erl | 34 ++++++--- .../ct_telnet_own_server_SUITE.erl | 33 +++++++-- lib/common_test/test/telnet_server.erl | 85 +++++++++++++++------- lib/test_server/src/ts.unix.config | 2 +- 8 files changed, 151 insertions(+), 66 deletions(-) diff --git a/lib/common_test/src/ct_gen_conn.erl b/lib/common_test/src/ct_gen_conn.erl index 078d6b1a44..239f5b5f25 100644 --- a/lib/common_test/src/ct_gen_conn.erl +++ b/lib/common_test/src/ct_gen_conn.erl @@ -344,7 +344,7 @@ loop(Opts) -> link(NewPid), put(conn_pid,NewPid), loop(Opts#gen_opts{conn_pid=NewPid, - cb_state=NewState}); + cb_state=NewState}); Error -> ct_util:unregister_connection(self()), log("Reconnect failed. Giving up!", diff --git a/lib/common_test/src/ct_telnet.erl b/lib/common_test/src/ct_telnet.erl index 096e893720..8c3ce03732 100644 --- a/lib/common_test/src/ct_telnet.erl +++ b/lib/common_test/src/ct_telnet.erl @@ -281,8 +281,16 @@ open(KeyOrName,ConnType,TargetMod,Extra) -> end, log(undefined,open,"Connecting to ~p(~p)", [KeyOrName,Addr1]), - ct_gen_conn:start(KeyOrName,full_addr(Addr1,ConnType), - {TargetMod,KeepAlive,Extra},?MODULE) + Reconnect = + case ct:get_config({telnet_settings,reconnection_attempts}) of + 0 -> false; + _ -> true + end, + ct_gen_conn:start(full_addr(Addr1,ConnType), + {TargetMod,KeepAlive,Extra}, + ?MODULE, [{name,KeyOrName}, + {reconnect,Reconnect}, + {old,true}]) end. %%%----------------------------------------------------------------- @@ -601,11 +609,9 @@ handle_msg({cmd,Cmd,Timeout},State) -> end_gen_log(), {Return,State#state{buffer=NewBuffer,prompt=Prompt}}; handle_msg({send,Cmd},State) -> - log(State,send,"Cmd: ~p",[Cmd]), - + log(State,send,"Sending: ~p",[Cmd]), debug_cont_gen_log("Throwing Buffer:",[]), debug_log_lines(State#state.buffer), - case {State#state.type,State#state.prompt} of {ts,_} -> silent_teln_expect(State#state.name, diff --git a/lib/common_test/src/ct_telnet_client.erl b/lib/common_test/src/ct_telnet_client.erl index f18496cdc2..ce30dcb74b 100644 --- a/lib/common_test/src/ct_telnet_client.erl +++ b/lib/common_test/src/ct_telnet_client.erl @@ -32,12 +32,11 @@ -module(ct_telnet_client). +%% -define(debug, true). + -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). @@ -105,7 +104,7 @@ get_data(Pid) -> Pid ! {get_data,self()}, receive {data,Data} -> - {ok, Data} + {ok,Data} end. @@ -116,7 +115,7 @@ init(Parent, Server, Port, Timeout, KeepAlive, ConnName) -> {ok,Sock} -> dbg("~p connected to: ~p (port: ~w, keep_alive: ~w)\n", [ConnName,Server,Port,KeepAlive]), - send([?IAC,?DO,?SUPPRESS_GO_AHEAD], Sock), + send([?IAC,?DO,?SUPPRESS_GO_AHEAD], Sock, ConnName), Parent ! {open,self()}, loop(#state{conn_name=ConnName, get_data=10, keep_alive=KeepAlive}, Sock, []), @@ -130,6 +129,7 @@ loop(State, Sock, Acc) -> {tcp_closed,_} -> dbg("Connection closed\n", []), Data = lists:reverse(lists:append(Acc)), + dbg("Printing queued messages: ~tp",[Data]), ct_telnet:log(State#state.conn_name, general_io, "~ts", [lists:sublist(Data, @@ -142,11 +142,11 @@ loop(State, Sock, Acc) -> ok end; {tcp,_,Msg0} -> - dbg("tcp msg: ~p~n",[Msg0]), + dbg("tcp msg: ~tp~n",[Msg0]), Msg = check_msg(Sock,Msg0,[]), loop(State, Sock, [Msg | Acc]); {send_data,Data} -> - send(Data, Sock), + send(Data, Sock, State#state.conn_name), loop(State, Sock, Acc); {get_data,Pid} -> NewState = @@ -162,7 +162,7 @@ loop(State, Sock, Acc) -> _ -> Data = lists:reverse(lists:append(Acc)), Len = length(Data), - dbg("get_data ~p\n",[Data]), + dbg("get_data ~tp\n",[Data]), ct_telnet:log(State#state.conn_name, general_io, "~ts", [lists:sublist(Data, @@ -176,7 +176,8 @@ loop(State, Sock, Acc) -> NewState = case State of #state{keep_alive = true, get_data = 0} -> - if Acc == [] -> send([?IAC,?NOP], Sock); + if Acc == [] -> send([?IAC,?NOP], Sock, + State#state.conn_name); true -> ok end, State#state{get_data=10}; @@ -185,10 +186,10 @@ loop(State, Sock, Acc) -> end, {NewAcc,Pos} = case erlang:is_process_alive(Pid) of - true -> + true when Acc /= [] -> Data = lists:reverse(lists:append(Acc)), Len = length(Data), - dbg("get_data_delayed ~p\n",[Data]), + dbg("get_data_delayed ~tp\n",[Data]), ct_telnet:log(State#state.conn_name, general_io, "~ts", [lists:sublist(Data, @@ -196,6 +197,10 @@ loop(State, Sock, Acc) -> Len)]), Pid ! {data,Data}, {[],1}; + true when Acc == [] -> + dbg("get_data_delayed nodata\n",[]), + Pid ! {data,[]}, + {[],1}; false -> {Acc,NewState#state.log_pos} end, @@ -206,6 +211,7 @@ loop(State, Sock, Acc) -> ok; true -> Data = lists:reverse(lists:append(Acc)), + dbg("Printing queued messages: ~tp",[Data]), ct_telnet:log(State#state.conn_name, general_io, "~ts", [lists:sublist(Data, @@ -218,11 +224,12 @@ loop(State, Sock, Acc) -> Data = lists:reverse(lists:append(Acc)), case Data of [] -> - send([?IAC,?NOP], Sock), + send([?IAC,?NOP], Sock, State#state.conn_name), loop(State, Sock, Acc); _ when State#state.log_pos == length(Data)+1 -> loop(State, Sock, Acc); _ -> + dbg("Idle timeout, printing ~tp\n",[Data]), Len = length(Data), ct_telnet:log(State#state.conn_name, general_io, "~ts", @@ -236,12 +243,18 @@ loop(State, Sock, Acc) -> wait(true, Time) -> Time; wait(false, _) -> infinity. -send(Data, Sock) -> +send(Data, Sock, ConnName) -> case Data of [?IAC|_] = Cmd -> cmd_dbg(Cmd); _ -> - dbg("Sending: ~p\n", [Data]) + dbg("Sending: ~tp\n", [Data]), + try io_lib:format("[~w] ~ts", [?MODULE,Data]) of + Str -> + ct_telnet:log(ConnName, general_io, Str, []) + catch + _:_ -> ok + end end, gen_tcp:send(Sock, Data), ok. diff --git a/lib/common_test/src/unix_telnet.erl b/lib/common_test/src/unix_telnet.erl index 5854725c17..b05386a5ab 100644 --- a/lib/common_test/src/unix_telnet.erl +++ b/lib/common_test/src/unix_telnet.erl @@ -143,13 +143,13 @@ connect1(Name,Ip,Port,Timeout,KeepAlive,Username,Password) -> {ok,[{prompt,_OtherPrompt1},{prompt,_OtherPrompt2}],_} -> {ok,Pid}; Error -> - log(Name,error, + log(Name,conn_error, "Did not get expected prompt from ~p:~p\n~p\n", [Ip,Port,Error]), {error,Error} end; Error -> - log(Name,error, + log(Name,conn_error, "Could not open telnet connection to ~p:~p\n~p\n", [Ip,Port,Error]), Error diff --git a/lib/common_test/test/ct_telnet_SUITE.erl b/lib/common_test/test/ct_telnet_SUITE.erl index 8163009409..f5cff76fd1 100644 --- a/lib/common_test/test/ct_telnet_SUITE.erl +++ b/lib/common_test/test/ct_telnet_SUITE.erl @@ -72,21 +72,32 @@ init_per_suite(Config) -> end_per_suite(Config) -> ct_test_support:end_per_suite(Config). -init_per_testcase(TestCase, Config) when TestCase=/=unix_telnet-> +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). - + ct:pal("Testcase ~p starting. Checking connection to telnet server...", + [TestCase]), + ct:require(testconn, {unix,[telnet]}), + case {os:type(),ct_telnet:open(testconn)} of + {_,{ok,Handle}} -> + ok = ct_telnet:close(Handle), + ct:pal("Connection ok, starting tests!", []), + ct_test_support:init_per_testcase(TestCase, Config); + {{unix,_},{error,Reason}} -> + ct:fail("No connection to telnet server! Reason: ~tp", [Reason]); + {_,{error,Reason}} -> + {skip,{no_access_to_telnet_server,Reason}} + end. + +end_per_testcase(TestCase, Config) when TestCase /= unix_telnet -> + ct:pal("Stopping the telnet_server now!", []), + telnet_server:stop(?config(telnet_server,Config)), + ct_test_support:end_per_testcase(TestCase, Config); end_per_testcase(TestCase, Config) -> - case ?config(telnet_server,Config) of - undefined -> ok; - TS -> telnet_server:stop(TS) - end, ct_test_support:end_per_testcase(TestCase, Config). @@ -181,7 +192,12 @@ telnet_config(_, LogType) -> {port, ?erl_telnet_server_port}, {username,?erl_telnet_server_user}, {password,?erl_telnet_server_pwd}, - {keep_alive,true}]} | + {keep_alive,true}]}, + {telnet_settings, [{connect_timeout,10000}, + {command_timeout,10000}, + {reconnection_attempts,0}, + {reconnection_interval,0}, + {keep_alive,true}]} | if LogType == legacy -> [{ct_conn_log,[]}]; true -> 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 0277dc2a44..394d64c2ed 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 @@ -29,7 +29,8 @@ all() -> ignore_prompt_repeat, ignore_prompt_sequence, ignore_prompt_timeout, - server_speaks]. + server_speaks, + server_disconnects]. groups() -> []. @@ -190,18 +191,36 @@ no_prompt_check_timeout(_) -> ok = ct_telnet:close(Handle), ok. -%% Let the server say things, to make sure it gets printed correctly -%% in the general IO log +%% The server says things. Manually check that 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"), + 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 timer:sleep(15000), - ok = ct_telnet:send(Handle, "echo This is the third message"), + 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}]), - ok = ct_telnet:send(Handle, "echo This is the fourth message"), + ok = ct_telnet:send(Handle, "echo_no_prompt This is the fourth message\r\n"), + %% give the server time to respond + timer:sleep(2000), + %% closing the connection should print last message in log ok = ct_telnet:close(Handle), ok. + +%% Let the server close the connection. Make sure buffered data gets printed +%% to the general IO log. +server_disconnects(_) -> + {ok, Handle} = ct_telnet:open(telnet_server_conn1), + ok = ct_telnet:send(Handle, "disconnect_after 1500"), + %% 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"), + %% when the server closes the connection, the last message should be + %% printed in the log + timer:sleep(3000), + _ = ct_telnet:close(Handle), + ok. diff --git a/lib/common_test/test/telnet_server.erl b/lib/common_test/test/telnet_server.erl index eb90f18320..3b0c3cbcb5 100644 --- a/lib/common_test/test/telnet_server.erl +++ b/lib/common_test/test/telnet_server.erl @@ -51,32 +51,51 @@ stop(Pid) -> init(Opts) -> Port = proplists:get_value(port,Opts), Users = proplists:get_value(users,Opts,[]), - {ok, LSock} = gen_tcp:listen(Port, [list, {packet, 0}, - {active, true}]), + {ok, LSock} = listen(5, Port, [list, {packet, 0}, + {active, true}, + {reuseaddr,true}]), State = #state{listen=LSock,users=Users}, accept(State), - ok = gen_tcp:close(LSock). + ok = gen_tcp:close(LSock), + dbg("telnet_server closed the listen socket ~p\n", [LSock]), + timer:sleep(1000), + ok. + +listen(0, _Port, _Opts) -> + {error,eaddrinuse}; +listen(Retries, Port, Opts) -> + case gen_tcp:listen(Port, Opts) of + {error,eaddrinuse} -> + dbg("Listen port not released, trying again..."), + timer:sleep(5000), + listen(Retries-1, Port, Opts); + Ok = {ok,_LSock} -> + Ok; + Error -> + exit(Error) + end. accept(#state{listen=LSock}=State) -> Server = self(), Acceptor = spawn_link(fun() -> do_accept(LSock,Server) end), receive {Acceptor,Sock} when is_port(Sock) -> + dbg("Connected to client on socket ~p\n", [Sock]), case init_client(State#state{client=Sock}) of stopped -> - io:format("[telnet_server] telnet_server stopped\n"), + dbg("telnet_server stopped\n"), ok; R -> - io:format("[telnet_server] connection to client " - "closed with reason ~p~n",[R]), + dbg("Connection to client " + "closed with reason ~p~n",[R]), accept(State) end; {Acceptor,closed} -> - io:format("[telnet_server] listen socket closed unexpectedly, " - "terminating telnet_server\n"), + dbg("Listen socket closed unexpectedly, " + "terminating telnet_server\n"), ok; stop -> - io:format("[telnet_server] telnet_server stopped\n"), + dbg("telnet_server stopped\n"), ok end. @@ -109,7 +128,9 @@ loop(State, N) -> {tcp,_,Data} -> try handle_data(Data,State) of {ok,State1} -> - loop(State1, N) + loop(State1, N); + closed -> + closed catch throw:Error -> Error @@ -118,16 +139,13 @@ loop(State, N) -> closed; {tcp_error,_,Error} -> {error,tcp,Error}; + disconnect -> + Sock = State#state.client, + dbg("Server closing connection on socket ~p~n", [Sock]), + ok = gen_tcp:close(Sock), + closed; 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) -> @@ -138,10 +156,16 @@ handle_data(Data,State) -> case get_line(Data,[]) of {Line,Rest} -> WholeLine = lists:flatten(lists:reverse(State#state.buffer,Line)), - {ok,State1} = do_handle_data(WholeLine,State), - case Rest of - [] -> {ok,State1}; - _ -> handle_data(Rest,State1) + case do_handle_data(WholeLine,State) of + {ok,State1} -> + case Rest of + [] -> {ok,State1}; + _ -> handle_data(Rest,State1) + end; + {close,State1} -> + dbg("Server closing connection~n",[]), + gen_tcp:close(State1#state.client), + closed end; false -> {ok,State#state{buffer=[Data|State#state.buffer]}} @@ -171,22 +195,29 @@ do_handle_data(Data,#state{authorized=false}=State) -> check_user(Data,State); do_handle_data(Data,#state{authorized={user,_}}=State) -> check_pwd(Data,State); -do_handle_data("echo "++ Data,State) -> +do_handle_data("echo " ++ Data,State) -> send(Data++"\r\n> ",State), {ok,State}; -do_handle_data("echo_no_prompt "++ Data,State) -> +do_handle_data("echo_no_prompt " ++ Data,State) -> send(Data,State), {ok,State}; -do_handle_data("echo_ml "++ Data,State) -> +do_handle_data("echo_ml " ++ Data,State) -> Lines = string:tokens(Data," "), ReturnData = string:join(Lines,"\n"), send(ReturnData++"\r\n> ",State), {ok,State}; -do_handle_data("echo_ml_no_prompt "++ Data,State) -> +do_handle_data("echo_ml_no_prompt " ++ Data,State) -> Lines = string:tokens(Data," "), ReturnData = string:join(Lines,"\n"), send(ReturnData,State), {ok,State}; +do_handle_data("disconnect_after " ++WaitStr,State) -> + Wait = list_to_integer(string:strip(WaitStr,right,$\n)), + dbg("Server will close connection in ~w ms...", [Wait]), + erlang:send_after(Wait,self(),disconnect), + {ok,State}; +do_handle_data("disconnect" ++_,State) -> + {close,State}; do_handle_data([],State) -> send("> ",State), {ok,State}; @@ -234,4 +265,4 @@ get_line([],_) -> dbg(_F) -> dbg(_F,[]). dbg(_F,_A) -> - io:format("[telnet_server] "++_F,_A). + io:format("[telnet_server] " ++ _F,_A). diff --git a/lib/test_server/src/ts.unix.config b/lib/test_server/src/ts.unix.config index a34857b9e5..1ba5d9033e 100644 --- a/lib/test_server/src/ts.unix.config +++ b/lib/test_server/src/ts.unix.config @@ -3,4 +3,4 @@ %% Always run a (VNC) X server on host %% {xserver, "xserver.example.com:66"}. -{unix,[{telnet,"belegost"},{username,"bofh"},{password,"root"},{keep_alive,true}]}. +{unix,[{telnet,"belegost"},{username,"telnet-test"},{password,"tset-tenlet"},{keep_alive,true}]}. -- cgit v1.2.3