Fix error with duplicated printouts by ct_telnet:expect/3

OTP-13730

4 files changed, 69 insertions, 48 deletions

diff --git a/lib/common_test/src/ct_gen_conn.erl b/lib/common_test/src/ct_gen_conn.erl
index e46fd77383..e28c89ab1d 100644
--- a/lib/common_test/src/ct_gen_conn.erl
+++ b/lib/common_test/src/ct_gen_conn.erl
@@ -27,7 +27,7 @@
 
 -export([start/4, stop/1, get_conn_pid/1, check_opts/1]).
 -export([call/2, call/3, return/2, do_within_time/2]).
--export([log/3, start_log/1, cont_log/2, end_log/0]).
+-export([log/3, start_log/1, cont_log/2, cont_log_no_timestamp/2, end_log/0]).
 
 %%----------------------------------------------------------------------
 %% Exported types
@@ -175,6 +175,14 @@ cont_log(Format,Args) ->
     log(cont_log,[Format,Args]).
 
 %%%-----------------------------------------------------------------
+%%% @spec cont_log_no_timestamp(Format,Args) -> ok
+%%%
+%%% @doc Log activities on the current connection (tool-internal use only).
+%%% @see ct_logs:cont_log/2
+cont_log_no_timestamp(Format,Args) ->
+    log(cont_log_no_timestamp,[Format,Args]).
+
+%%%-----------------------------------------------------------------
 %%% @spec end_log() -> ok
 %%%
 %%% @doc Log activities on the current connection (tool-internal use only).
diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index a9ad571bfc..d87d26e5ba 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -32,7 +32,7 @@
 -export([init/2, close/2, init_tc/1, end_tc/1]).
 -export([register_groupleader/2, unregister_groupleader/1]).
 -export([get_log_dir/0, get_log_dir/1]).
--export([log/3, start_log/1, cont_log/2, end_log/0]).
+-export([log/3, start_log/1, cont_log/2, cont_log_no_timestamp/2, end_log/0]).
 -export([set_stylesheet/2, clear_stylesheet/1]).
 -export([add_external_logs/1, add_link/3]).
 -export([make_last_run_index/0]).
@@ -358,6 +358,20 @@ cont_log(Format,Args) ->
     ok.
 
 %%%-----------------------------------------------------------------
+%%% @spec cont_log_no_timestamp(Format,Args) -> ok
+%%% 
+%%% @doc Adds information about an activity (tool-internal use only).
+%%%
+%%% @see start_log/1
+%%% @see end_log/0
+cont_log_no_timestamp([],[]) ->
+    ok;
+cont_log_no_timestamp(Format,Args) ->
+    cast({log,sync,self(),group_leader(),ct_internal,?MAX_IMPORTANCE,
+	  [{Format,Args}],true}),
+    ok.
+
+%%%-----------------------------------------------------------------
 %%% @spec end_log() -> ok
 %%% 
 %%% @doc Ends the logging of an activity (tool-internal use only).
@@ -580,7 +594,6 @@ div_header(Class,Printer) ->
 div_footer() ->
     "</pre></div>\n<pre>".
 
-
 maybe_log_timestamp() ->
     {MS,S,US} = ?now,
     case get(log_timestamp) of
diff --git a/lib/common_test/src/ct_telnet.erl b/lib/common_test/src/ct_telnet.erl
index f5f4f648f4..715eb1bbbd 100644
--- a/lib/common_test/src/ct_telnet.erl
+++ b/lib/common_test/src/ct_telnet.erl
@@ -954,7 +954,7 @@ log(#state{name=Name,teln_pid=TelnPid,host=Host,port=Port},
 			true  ->
 			    ok;
 			false ->
-			    ct_gen_conn:cont_log(String,Args)
+			    ct_gen_conn:cont_log_no_timestamp(String,Args)
 		    end;
 	       
 	       ForcePrint == true ->
@@ -965,7 +965,7 @@ log(#state{name=Name,teln_pid=TelnPid,host=Host,port=Port},
 			    %% called
 			    ct_gen_conn:log(heading(Action,Name1),String,Args);
 			false ->
-			    ct_gen_conn:cont_log(String,Args)
+			    ct_gen_conn:cont_log_no_timestamp(String,Args)
 		    end
 	    end
     end.
@@ -1224,7 +1224,6 @@ teln_expect1(Name,Pid,Data,Pattern,Acc,EO=#eo{idle_timeout=IdleTO,
     EOMod = if TotalTO /= infinity -> EO#eo{total_timeout=trunc(TotalTO)};
 	       true                -> EO
 	    end,
-
     ExpectFun = case EOMod#eo.seq of
 		    true -> fun() ->
 				    seq_expect(Name,Pid,Data,Pattern,Acc,EOMod)
@@ -1247,38 +1246,34 @@ teln_expect1(Name,Pid,Data,Pattern,Acc,EO=#eo{idle_timeout=IdleTO,
 			    true ->
 				 IdleTO
 			 end,
+	    {PatOrPats1,Acc1,Rest1} = case NotFinished of
+					 {nomatch,Rest0} ->
+					     %% one expect
+					     {Pattern,[],Rest0};
+					 {continue,Pats0,Acc0,Rest0} ->
+					     %% sequence
+					     {Pats0,Acc0,Rest0}
+				     end,
 	    case timer:tc(ct_gen_conn, do_within_time, [Fun,BreakAfter]) of
-		{_,{error,Reason}} -> 
+		{_,{error,Reason}} ->
 		    %% A timeout will occur when the telnet connection
 		    %% is idle for EO#eo.idle_timeout milliseconds.
+		    if Rest1 /= [] ->
+			    log(name_or_pid(Name,Pid),"       ~ts",[Rest1]);
+		       true ->
+			    ok
+		    end,
 		    {error,Reason};
 		{_,{ok,Data1}} when TotalTO == infinity ->
-		    case NotFinished of
-			{nomatch,Rest} ->
-			    %% One expect
-			    teln_expect1(Name,Pid,Rest++Data1,
-					 Pattern,[],EOMod);
-			{continue,Patterns1,Acc1,Rest} ->
-			    %% Sequence
-			    teln_expect1(Name,Pid,Rest++Data1,
-					 Patterns1,Acc1,EOMod)
-		    end;
+		    teln_expect1(Name,Pid,Rest1++Data1,PatOrPats1,Acc1,EOMod);
 		{Elapsed,{ok,Data1}} ->
 		    TVal = TotalTO - (Elapsed/1000),
 		    if TVal =< 0 ->
 			    {error,timeout};
 		       true ->
 			    EO1 = EO#eo{total_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
+			    teln_expect1(Name,Pid,Rest1++Data1,
+					 PatOrPats1,Acc1,EO1)
 		    end
 	    end
     end.
@@ -1416,14 +1411,14 @@ match_lines(Name,Pid,Data,Patterns,EO) ->
     case one_line(Data,[]) of
 	{noline,Rest} when FoundPrompt=/=false ->
 	    %% This is the line including the prompt
-	    case match_line(Name,Pid,Rest,Patterns,FoundPrompt,EO) of
+	    case match_line(Name,Pid,Rest,Patterns,FoundPrompt,false,EO) of
 		nomatch ->
 		    {nomatch,prompt};
 		{Tag,Match} ->
 		    {Tag,Match,[]}
 	    end;
 	{noline,Rest} when EO#eo.prompt_check==false ->
-	    case match_line(Name,Pid,Rest,Patterns,false,EO) of
+	    case match_line(Name,Pid,Rest,Patterns,false,false,EO) of
 		nomatch ->
 		    {nomatch,Rest};
 		{Tag,Match} ->
@@ -1432,7 +1427,7 @@ match_lines(Name,Pid,Data,Patterns,EO) ->
 	{noline,Rest} ->
 	    {nomatch,Rest};
 	{Line,Rest} ->
-	    case match_line(Name,Pid,Line,Patterns,false,EO) of
+	    case match_line(Name,Pid,Line,Patterns,false,true,EO) of
 		nomatch ->
 		    match_lines(Name,Pid,Rest,Patterns,EO);
 		{Tag,Match} ->
@@ -1440,45 +1435,50 @@ match_lines(Name,Pid,Data,Patterns,EO) ->
 	    end
     end.
     
-
 %% For one line, match each pattern
-match_line(Name,Pid,Line,Patterns,FoundPrompt,EO) ->
-    match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,match).
+match_line(Name,Pid,Line,Patterns,FoundPrompt,Terminated,EO) ->
+    match_line(Name,Pid,Line,Patterns,FoundPrompt,Terminated,EO,match).
 
-match_line(Name,Pid,Line,[prompt|Patterns],false,EO,RetTag) ->
-    match_line(Name,Pid,Line,Patterns,false,EO,RetTag);
-match_line(Name,Pid,Line,[prompt|_Patterns],FoundPrompt,_EO,RetTag) ->
+match_line(Name,Pid,Line,[prompt|Patterns],false,Term,EO,RetTag) ->
+    match_line(Name,Pid,Line,Patterns,false,Term,EO,RetTag);
+match_line(Name,Pid,Line,[prompt|_Patterns],FoundPrompt,_Term,_EO,RetTag) ->
     log(name_or_pid(Name,Pid),"       ~ts",[Line]),
     log(name_or_pid(Name,Pid),"PROMPT: ~ts",[FoundPrompt]),
     {RetTag,{prompt,FoundPrompt}};
-match_line(Name,Pid,Line,[{prompt,PromptType}|_Patterns],FoundPrompt,_EO,RetTag) 
-  when PromptType==FoundPrompt ->
+match_line(Name,Pid,Line,[{prompt,PromptType}|_Patterns],FoundPrompt,_Term,
+	   _EO,RetTag) when PromptType==FoundPrompt ->
     log(name_or_pid(Name,Pid),"       ~ts",[Line]),
     log(name_or_pid(Name,Pid),"PROMPT: ~ts",[FoundPrompt]),
     {RetTag,{prompt,FoundPrompt}};
-match_line(Name,Pid,Line,[{prompt,PromptType}|Patterns],FoundPrompt,EO,RetTag) 
+match_line(Name,Pid,Line,[{prompt,PromptType}|Patterns],FoundPrompt,Term,
+	   EO,RetTag) 
   when PromptType=/=FoundPrompt ->
-    match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag);
-match_line(Name,Pid,Line,[{Tag,Pattern}|Patterns],FoundPrompt,EO,RetTag) ->
+    match_line(Name,Pid,Line,Patterns,FoundPrompt,Term,EO,RetTag);
+match_line(Name,Pid,Line,[{Tag,Pattern}|Patterns],FoundPrompt,Term,EO,RetTag) ->
     case re:run(Line,Pattern,[{capture,all,list}]) of
 	nomatch ->
-	    match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag);
+	    match_line(Name,Pid,Line,Patterns,FoundPrompt,Term,EO,RetTag);
 	{match,Match} ->
 	    log(name_or_pid(Name,Pid),"MATCH: ~ts",[Line]),
 	    {RetTag,{Tag,Match}}
     end;
-match_line(Name,Pid,Line,[Pattern|Patterns],FoundPrompt,EO,RetTag) ->
+match_line(Name,Pid,Line,[Pattern|Patterns],FoundPrompt,Term,EO,RetTag) ->
     case re:run(Line,Pattern,[{capture,all,list}]) of
 	nomatch ->
-	    match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag);
+	    match_line(Name,Pid,Line,Patterns,FoundPrompt,Term,EO,RetTag);
 	{match,Match} ->
 	    log(name_or_pid(Name,Pid),"MATCH: ~ts",[Line]),
 	    {RetTag,Match}
     end;
-match_line(Name,Pid,Line,[],FoundPrompt,EO,match) ->
-    match_line(Name,Pid,Line,EO#eo.haltpatterns,FoundPrompt,EO,halt);
-match_line(Name,Pid,Line,[],_FoundPrompt,_EO,halt) ->
+match_line(Name,Pid,Line,[],FoundPrompt,Term,EO,match) ->
+    match_line(Name,Pid,Line,EO#eo.haltpatterns,FoundPrompt,Term,EO,halt);
+%% print any terminated line that can not be matched
+match_line(Name,Pid,Line,[],_FoundPrompt,true,_EO,halt) ->
     log(name_or_pid(Name,Pid),"       ~ts",[Line]),
+    nomatch;
+%% if there's no line termination, Line is saved as Rest (above) and will
+%% be printed later
+match_line(_Name,_Pid,_Line,[],_FoundPrompt,false,_EO,halt) ->
     nomatch.
 
 one_line([$\n|Rest],Line) ->
diff --git a/lib/common_test/vsn.mk b/lib/common_test/vsn.mk
index f33fd658e8..c6e5148716 100644
--- a/lib/common_test/vsn.mk
+++ b/lib/common_test/vsn.mk
@@ -1 +1 @@
-COMMON_TEST_VSN = 1.12.1
+COMMON_TEST_VSN = 1.12.1.1