Merge branch 'siri/common_test/unexpected_io/OTP-10494' into maint

* siri/common_test/unexpected_io/OTP-10494:
  [common_test] Add test for unexpected I/O
  [common_test] Send unexpected logging to test_server's unexpected_io.log
  [test_server] Add test_server_io:print_unexpected/1

7 files changed, 102 insertions, 31 deletions

diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index 0b204a681a..752033fdff 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -639,20 +639,21 @@ logger_loop(State) ->
 			    case erlang:is_process_alive(TCGL) of
 				true ->
 				    State1 = print_to_log(SyncOrAsync, Pid,
+							  Category,
 							  TCGL, List, State),
 				    logger_loop(State1#logger_state{
 						  tc_groupleaders = TCGLs});
 				false ->
 				    %% Group leader is dead, so write to the
-				    %% CtLog instead
-				    Fd = State#logger_state.ct_log_fd,
-				    [begin io:format(Fd,Str,Args),
-					   io:nl(Fd) end || {Str,Args} <- List],
+				    %% CtLog or unexpected_io log instead
+				    unexpected_io(Pid,Category,List,State),
 				    logger_loop(State)			    
 			    end;
-			{ct_log,Fd,TCGLs} ->
-			    [begin io:format(Fd,Str,Args),io:nl(Fd) end ||
-				{Str,Args} <- List],
+			{ct_log,_Fd,TCGLs} ->
+			    %% If category is ct_internal then write
+			    %% to ct_log, else write to unexpected_io
+			    %% log
+			    unexpected_io(Pid,Category,List,State),
 			    logger_loop(State#logger_state{
 					  tc_groupleaders = TCGLs})
 		    end;
@@ -746,27 +747,32 @@ create_io_fun(FromPid, State) ->
 	    end
     end.
 
-print_to_log(sync, FromPid, TCGL, List, State) ->
-    IoFun = create_io_fun(FromPid, State),
+print_to_log(sync, FromPid, Category, TCGL, List, State) ->
     %% in some situations (exceptions), the printout is made from the
     %% test server IO process and there's no valid group leader to send to
-    IoProc = if FromPid /= TCGL -> TCGL;
-		true -> State#logger_state.ct_log_fd
-	     end,
-    io:format(IoProc, "~ts", [lists:foldl(IoFun, [], List)]),
+    if FromPid /= TCGL ->
+	    IoFun = create_io_fun(FromPid, State),
+	    io:format(TCGL,"~ts", [lists:foldl(IoFun, [], List)]);
+       true ->
+	    unexpected_io(FromPid,Category,List,State)
+    end,
     State;
 
-print_to_log(async, FromPid, TCGL, List, State) ->
-    IoFun = create_io_fun(FromPid, State),
+print_to_log(async, FromPid, Category, TCGL, List, State) ->
     %% in some situations (exceptions), the printout is made from the
     %% test server IO process and there's no valid group leader to send to
-    IoProc = if FromPid /= TCGL -> TCGL;
-		true -> State#logger_state.ct_log_fd
-	     end,
-    Printer = fun() ->
-		      test_server:permit_io(IoProc, self()),
-		      io:format(IoProc, "~ts", [lists:foldl(IoFun, [], List)])
-	      end,
+    Printer =
+	if FromPid /= TCGL ->
+		IoFun = create_io_fun(FromPid, State),
+		fun() ->
+			test_server:permit_io(TCGL, self()),
+			io:format(TCGL, "~ts", [lists:foldl(IoFun, [], List)])
+		end;
+	   true ->
+		fun() ->
+			unexpected_io(FromPid,Category,List,State)
+		end
+	end,
     case State#logger_state.async_print_jobs of
 	[] ->
 	    {_Pid,Ref} = spawn_monitor(Printer),
@@ -2514,3 +2520,11 @@ html_encoding(latin1) ->
     "iso-8859-1";
 html_encoding(utf8) ->
     "utf-8".
+
+unexpected_io(Pid,ct_internal,List,#logger_state{ct_log_fd=Fd}=State) ->
+    IoFun = create_io_fun(Pid,State),
+    io:format(Fd, "~ts", [lists:foldl(IoFun, [], List)]);
+unexpected_io(Pid,_Category,List,State) ->
+    IoFun = create_io_fun(Pid,State),
+    Data = io_lib:format("~ts", [lists:foldl(IoFun, [], List)]),
+    test_server_io:print_unexpected(Data).
diff --git a/lib/common_test/test/ct_group_leader_SUITE.erl b/lib/common_test/test/ct_group_leader_SUITE.erl
index cde3061d6a..6d54a4c004 100644
--- a/lib/common_test/test/ct_group_leader_SUITE.erl
+++ b/lib/common_test/test/ct_group_leader_SUITE.erl
@@ -1,7 +1,7 @@
 %%
 %% %CopyrightBegin%
 %%
-%% Copyright Ericsson AB 2012. All Rights Reserved.
+%% Copyright Ericsson AB 2012-2013. 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
@@ -176,6 +176,10 @@ events_to_check(_Test) ->
 		{?eh,tc_done,{group_leader_SUITE,cap1,ok}},
 		{?eh,tc_start,{group_leader_SUITE,cap2}},
 		{?eh,tc_done,{group_leader_SUITE,cap2,ok}}]},
+     {parallel,[{?eh,tc_start,{group_leader_SUITE,unexp1}},
+		{?eh,tc_done,{group_leader_SUITE,unexp1,ok}},
+		{?eh,tc_start,{group_leader_SUITE,unexp2}},
+		{?eh,tc_done,{group_leader_SUITE,unexp2,ok}}]},
      {?eh,test_done,{'DEF','STOP_TIME'}},
      {?eh,stop_logging,[]}
     ].
diff --git a/lib/common_test/test/ct_group_leader_SUITE_data/group_leader_SUITE.erl b/lib/common_test/test/ct_group_leader_SUITE_data/group_leader_SUITE.erl
index 3f1844b4ae..804f722081 100644
--- a/lib/common_test/test/ct_group_leader_SUITE_data/group_leader_SUITE.erl
+++ b/lib/common_test/test/ct_group_leader_SUITE_data/group_leader_SUITE.erl
@@ -1,7 +1,7 @@
 %%
 %% %CopyrightBegin%
 %%
-%% Copyright Ericsson AB 2012. All Rights Reserved.
+%% Copyright Ericsson AB 2012-2013. 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
@@ -112,7 +112,8 @@ groups() ->
      {seq,[],[s1,s2,s3]},
      {seq2,[],[s4,s5]},
      {seq_in_par,[parallel],[p10,p11,{group,seq},p12,{group,seq2},p13]},
-     {capture_io,[parallel],[cap1,cap2]}].
+     {capture_io,[parallel],[cap1,cap2]},
+     {unexpected_io,[parallel],[unexp1,unexp2]}].
 
 %%--------------------------------------------------------------------
 %% @spec all() -> GroupsAndTestCases | {skip,Reason}
@@ -126,7 +127,8 @@ all() ->
     [tc1,{group,p},{group,p_restart},p3,
      {group,seq_in_par},
      cap1,cap2,
-     {group,capture_io}].
+     {group,capture_io},
+     {group,unexpected_io}].
 
 tc1(_C) ->
     ok.
@@ -250,3 +252,36 @@ gen_io(Label, N, Acc) ->
     S = lists:flatten(io_lib:format("~s: ~p\n", [Label,N])),
     io:put_chars(S),
     gen_io(Label, N-1, [S|Acc]).
+
+%% Test that unexpected I/O is sent to test_server's unexpeced_io log.
+%% To trigger this, run two test cases in parallel and send a printout
+%% (via ct logging functions) from an external process which has a
+%% different group leader than the test cases.
+unexp1(Config) ->
+    timer:sleep(1000),
+    gen_unexp_io(),
+    timer:sleep(1000),
+    check_unexp_io(Config),
+    ok.
+
+unexp2(_) ->
+    timer:sleep(2000),
+    ok.
+
+gen_unexp_io() ->
+    spawn(fun() ->
+		  group_leader(whereis(user),self()),
+		  ct:log("-x- Unexpected io ct:log -x-",[]),
+		  ct:pal("-x- Unexpected io ct:pal -x-",[]),
+		  ok
+	  end).
+
+check_unexp_io(Config) ->
+    SuiteLog = ?config(tc_logfile,Config),
+    Dir = filename:dirname(SuiteLog),
+    UnexpLog = filename:join(Dir,"unexpected_io.log.html"),
+    {ok,SuiteBin} = file:read_file(SuiteLog),
+    nomatch = re:run(SuiteBin,"-x- Unexpected io ",[global,{capture,none}]),
+    {ok,UnexpBin} = file:read_file(UnexpLog),
+    {match,[_,_]} = re:run(UnexpBin,"-x- Unexpected io ",[global]),
+    ok.
diff --git a/lib/test_server/src/test_server_gl.erl b/lib/test_server/src/test_server_gl.erl
index 2e4f223811..1f7317c51d 100644
--- a/lib/test_server/src/test_server_gl.erl
+++ b/lib/test_server/src/test_server_gl.erl
@@ -166,7 +166,7 @@ handle_info({'DOWN',Ref,process,_,Reason}=D, #st{minor_monitor=Ref}=St) ->
 	    Data = io_lib:format("=== WARNING === TC: ~w\n"
 				 "Got down from minor Fd ~w: ~w\n\n",
 				 [St#st.tc,St#st.minor,D]),
-	    test_server_io:print(xxxFrom, unexpected_io, Data)
+	    test_server_io:print_unexpected(Data)
     end,
     {noreply,St#st{minor=none,minor_monitor=none}};
 handle_info({permit_io,Pid}, #st{permit_io=P}=St) ->
diff --git a/lib/test_server/src/test_server_io.erl b/lib/test_server/src/test_server_io.erl
index 242c08f765..a979deffc3 100644
--- a/lib/test_server/src/test_server_io.erl
+++ b/lib/test_server/src/test_server_io.erl
@@ -30,7 +30,8 @@
 
 -module(test_server_io).
 -export([start_link/0,stop/0,get_gl/1,set_fd/2,
-	 start_transaction/0,end_transaction/0,print_buffered/1,print/3,
+	 start_transaction/0,end_transaction/0,
+	 print_buffered/1,print/3,print_unexpected/1,
 	 set_footer/1,set_job_name/1,set_gl_props/1]).
 
 -export([init/1,handle_call/3,handle_info/2,terminate/2]).
@@ -124,6 +125,14 @@ print(From, Tag, Msg) ->
 print_buffered(Pid) ->
     req({print_buffered,Pid}).
 
+%% print_unexpected(Msg)
+%%  Msg = string or iolist
+%%
+%%  Print the given string in the unexpected_io log.
+
+print_unexpected(Msg) ->
+    print(xxxFrom,unexpected_io,Msg).
+
 %% set_footer(IoData)
 %%
 %%  Set a footer for the file associated with the 'html' tag.
diff --git a/lib/test_server/test/test_server_SUITE.erl b/lib/test_server/test/test_server_SUITE.erl
index cf1df6df34..3db2f5f9f1 100644
--- a/lib/test_server/test/test_server_SUITE.erl
+++ b/lib/test_server/test/test_server_SUITE.erl
@@ -104,7 +104,7 @@ test_server_SUITE(Config) ->
 %    rpc:call(Node,dbg, tpl,[test_server_ctrl,x]),
     run_test_server_tests("test_server_SUITE",
 			  [{test_server_SUITE,skip_case7,"SKIPPED!"}],
-			  39, 1, 31, 20, 9, 1, 11, 2, 26, Config).
+			  40, 1, 32, 21, 9, 1, 11, 2, 27, Config).
 
 test_server_parallel01_SUITE(Config) ->
     run_test_server_tests("test_server_parallel01_SUITE", [],
diff --git a/lib/test_server/test/test_server_SUITE_data/test_server_SUITE.erl b/lib/test_server/test/test_server_SUITE_data/test_server_SUITE.erl
index 6c50efa712..541e8fdefc 100644
--- a/lib/test_server/test/test_server_SUITE_data/test_server_SUITE.erl
+++ b/lib/test_server/test/test_server_SUITE_data/test_server_SUITE.erl
@@ -39,7 +39,7 @@
 	 check_old_conf/1, conf_init_fail/1, start_stop_node/1,
 	 cleanup_nodes_init/1, check_survive_nodes/1, cleanup_nodes_fin/1,
 	 commercial/1,
-	 io_invalid_data/1]).
+	 io_invalid_data/1, print_unexpected/1]).
 
 -export([dummy_function/0,dummy_function/1,doer/1]).
 
@@ -48,7 +48,7 @@ all(suite) ->
     [config, comment, timetrap, timetrap_cancel, multiply_timetrap,
      init_per_s, init_per_tc, end_per_tc,
      timeconv, msgs, capture, timecall, do_times, skip_cases,
-     commercial, io_invalid_data,
+     commercial, io_invalid_data, print_unexpected,
      {conf, conf_init, [check_new_conf], conf_cleanup},
      check_old_conf,
      {conf, conf_init_fail,[conf_member_skip],conf_cleanup_skip},
@@ -503,3 +503,12 @@ io_invalid_data(Config) when is_list(Config) ->
     %% OTP-10991 caused this to hang and produce a timetrap timeout:
     {'EXIT',{badarg,_}} = (catch io:put_chars("invalid: " ++ [42.0])),
     ok.
+
+print_unexpected(Config) when is_list(Config) ->
+    Str = "-x-x-x- test_server_SUITE:print_unexpected -> Unexpected data -x-x-x-",
+    test_server_io:print_unexpected(Str),
+    UnexpectedLog = filename:join(filename:dirname(?config(tc_logfile,Config)),
+				  "unexpected_io.log.html"),
+    {ok,Bin} = file:read_file(UnexpectedLog),
+    match = re:run(Bin, Str, [global,{capture,none}]),
+    ok.