Merge remote branch 'origin/peppe/common_test/cth_ctrl' into maint

* origin/peppe/common_test/cth_ctrl:
  Find and fix minor bugs
  Add test suite
  Fix timing related problem
  Fix problem with start order of hooks and stopping of ct_util_server
  Introduce pre- and post-test i/o log

OTP-11272

4 files changed, 127 insertions, 31 deletions

diff --git a/lib/common_test/src/ct_hooks.erl b/lib/common_test/src/ct_hooks.erl
index 3d87a82e24..e845e9e908 100644
--- a/lib/common_test/src/ct_hooks.erl
+++ b/lib/common_test/src/ct_hooks.erl
@@ -50,9 +50,8 @@
 -spec init(State :: term()) -> ok |
 			       {fail, Reason :: term()}.
 init(Opts) ->
-    call(get_new_hooks(Opts, undefined) ++ get_builtin_hooks(Opts),
+    call(get_builtin_hooks(Opts) ++ get_new_hooks(Opts, undefined),
 	 ok, init, []).
-		      
 
 %% @doc Called after all suites are done.
 -spec terminate(Hooks :: term()) ->
@@ -276,8 +275,10 @@ get_new_hooks(Config, Fun) ->
 		end, get_new_hooks(Config)).
 
 get_new_hooks(Config) when is_list(Config) ->
-    lists:flatmap(fun({?config_name, HookConfigs}) ->
+    lists:flatmap(fun({?config_name, HookConfigs}) when is_list(HookConfigs) ->
 			  HookConfigs;
+		     ({?config_name, HookConfig}) when is_atom(HookConfig) ->
+			  [HookConfig];
 		     (_) ->
 			  []
 		  end, Config);
diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index bd37b690b6..1a6e4d31a8 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -61,6 +61,7 @@
 -define(index_name, "index.html").
 -define(totals_name, "totals.info").
 -define(log_cache_name, "ct_log_cache").
+-define(misc_io_log, "misc_io.log.html").
 
 -define(table_color1,"#ADD8E6").
 -define(table_color2,"#E4F0FE").
@@ -523,7 +524,7 @@ int_footer() ->
 div_header(Class) ->
     div_header(Class,"User").
 div_header(Class,Printer) ->
-    "<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** " ++ Printer ++
+    "\n<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** " ++ Printer ++
     " " ++ log_timestamp(now()) ++ " ***</b>".
 div_footer() ->
     "</div>".
@@ -617,6 +618,34 @@ logger(Parent, Mode, Verbosity) ->
 		    end
 	    end
     end,
+
+    test_server_io:start_link(),
+    MiscIoName = filename:join(Dir, ?misc_io_log),
+    {ok,MiscIoFd} = file:open(MiscIoName,
+			      [write,{encoding,utf8}]),
+    test_server_io:set_fd(unexpected_io, MiscIoFd),
+
+    {MiscIoHeader,MiscIoFooter} =
+	case get_ts_html_wrapper("Pre/post-test I/O log", Dir, false,
+				 Dir, undefined, utf8) of
+	    {basic_html,UH,UF} ->
+		{UH,UF};
+	    {xhtml,UH,UF} ->
+		{UH,UF}
+	end,
+    io:put_chars(MiscIoFd,
+		 [MiscIoHeader,
+		  "<a name=\"pretest\"></a>\n",
+		  xhtml("<br>\n<h2>Pre-test Log</h2>",
+			"<br />\n<h3>PRE-TEST LOG</h3>"),
+		  "\n<pre>\n"]),
+    MiscIoDivider =
+	"\n<a name=\"posttest\"></a>\n"++
+	xhtml("</pre>\n<br><h2>Post-test Log</h2>\n<pre>\n",
+	      "</pre>\n<br />\n<h3>POST-TEST LOG</h3>\n<pre>\n"),
+    ct_util:set_testdata_async({misc_io_log,{filename:absname(MiscIoName),
+					     MiscIoDivider,MiscIoFooter}}),
+
     ct_event:notify(#event{name=start_logging,node=node(),
 			   data=AbsDir}),
     make_all_runs_index(start),
@@ -627,7 +656,7 @@ logger(Parent, Mode, Verbosity) ->
     end,
     file:set_cwd(Dir),
     make_last_run_index(Time),
-    CtLogFd = open_ctlog(),
+    CtLogFd = open_ctlog(?misc_io_log),
     io:format(CtLogFd,int_header()++int_footer(),
 	      [log_timestamp(now()),"Common Test Logger started"]),
     Parent ! {started,self(),{Time,filename:absname("")}},
@@ -922,7 +951,7 @@ set_evmgr_gl(GL) ->
 	EvMgrPid -> group_leader(GL,EvMgrPid)
     end.
 
-open_ctlog() ->
+open_ctlog(MiscIoName) ->
     {ok,Fd} = file:open(?ct_log_name,[write,{encoding,utf8}]),
     io:format(Fd, header("Common Test Framework Log", {[],[1,2],[]}), []),
     case file:consult(ct_run:variables_file_name("../")) of
@@ -937,10 +966,21 @@ open_ctlog() ->
 		      "No configuration found for test!!\n",
 		      [Variables,Reason])
     end,
+    io:format(Fd, 
+	      xhtml("<br><br><h2>Pre/post-test I/O Log</h2>\n",
+		    "<br /><br />\n<h4>PRE/POST TEST I/O LOG</h4>\n"), []),    
+    io:format(Fd,
+	      "\n<ul>\n"
+	      "<li><a href=\"~ts#pretest\">"
+	      "View I/O logged before the test run</a></li>\n"
+	      "<li><a href=\"~ts#posttest\">"
+	      "View I/O logged after the test run</a></li>\n</ul>\n",
+	      [MiscIoName,MiscIoName]),
+
     print_style(Fd,undefined),
     io:format(Fd, 
-	      xhtml("<br><br><h2>Progress Log</h2>\n<pre>\n",
-		    "<br /><br /><h4>PROGRESS LOG</h4>\n<pre>\n"), []),
+	      xhtml("<br><h2>Progress Log</h2>\n<pre>\n",
+		    "<br />\n<h4>PROGRESS LOG</h4>\n<pre>\n"), []),
     Fd.
 
 print_style(Fd,undefined) ->
@@ -2856,6 +2896,9 @@ make_relative1(DirTs, CwdTs) ->
 %%% @doc
 %%%
 get_ts_html_wrapper(TestName, PrintLabel, Cwd, TableCols, Encoding) ->
+    get_ts_html_wrapper(TestName, undefined, PrintLabel, Cwd, TableCols, Encoding).
+
+get_ts_html_wrapper(TestName, Logdir, PrintLabel, Cwd, TableCols, Encoding) ->
     TestName1 = if is_list(TestName) ->
 			lists:flatten(TestName);
 		   true ->
@@ -2876,7 +2919,12 @@ get_ts_html_wrapper(TestName, PrintLabel, Cwd, TableCols, Encoding) ->
 		end
 	end,
     CTPath = code:lib_dir(common_test),
-    {ok,CtLogdir} = get_log_dir(true),
+
+    {ok,CtLogdir} =
+	if Logdir == undefined -> get_log_dir(true);
+	   true -> {ok,Logdir}
+	end,
+
     AllRuns = make_relative(filename:join(filename:dirname(CtLogdir),
 					  ?all_runs_name), Cwd),
     TestIndex = make_relative(filename:join(filename:dirname(CtLogdir),
@@ -3074,16 +3122,8 @@ unexpected_io(Pid,ct_internal,_Importance,List,State) ->
     IoFun = create_io_fun(Pid,State),
     io:format(State#logger_state.ct_log_fd, "~ts",
 	      [lists:foldl(IoFun, [], List)]);
-unexpected_io(Pid,Category,Importance,List,State) ->
+unexpected_io(Pid,_Category,_Importance,List,State) ->
     IoFun = create_io_fun(Pid,State),
     Data = io_lib:format("~ts", [lists:foldl(IoFun, [], List)]),
-    %% if unexpected io comes in during startup or shutdown, test_server
-    %% might not be running - if so (noproc exit), simply print to
-    %% stdout instead (will result in double printouts when pal is used)
-    try test_server_io:print_unexpected(Data) of
-	_ ->
-	    ok
-    catch
-	_:{noproc,_} -> tc_print(Category,Importance,Data,[]);
-	_:Reason     -> exit(Reason)
-    end.
+    test_server_io:print_unexpected(Data),
+    ok.
diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl
index abda87c2cd..bcc4caa62e 100644
--- a/lib/common_test/src/ct_util.erl
+++ b/lib/common_test/src/ct_util.erl
@@ -187,6 +187,7 @@ do_start(Parent, Mode, LogDir, Verbosity) ->
 	false ->
 	    ok
     end,
+
     {StartTime,TestLogDir} = ct_logs:init(Mode, Verbosity),
 
     ct_event:notify(#event{name=test_start,
@@ -198,12 +199,26 @@ do_start(Parent, Mode, LogDir, Verbosity) ->
 	ok ->
 	    Parent ! {self(),started};
 	{fail,CTHReason} ->
-	    ct_logs:tc_print('Suite Callback',CTHReason,[]),
+	    ErrorInfo = if is_atom(CTHReason) ->
+				io_lib:format("{~p,~p}",
+					      [CTHReason,
+					       erlang:get_stacktrace()]);
+			   true ->
+				CTHReason
+			end,
+	    ct_logs:tc_print('Suite Callback',ErrorInfo,[]),
 	    self() ! {{stop,{self(),{user_error,CTHReason}}},
 		      {Parent,make_ref()}}
     catch
 	_:CTHReason ->
-	    ct_logs:tc_print('Suite Callback',CTHReason,[]),
+	    ErrorInfo = if is_atom(CTHReason) ->
+				io_lib:format("{~p,~p}",
+					      [CTHReason,
+					       erlang:get_stacktrace()]);
+			   true ->
+				CTHReason
+			end,
+	    ct_logs:tc_print('Suite Callback',ErrorInfo,[]),
 	    self() ! {{stop,{self(),{user_error,CTHReason}}},
 		      {Parent,make_ref()}}
     end,
@@ -392,19 +407,38 @@ loop(Mode,TestData,StartDir) ->
 	    return(From,StartDir),
 	    loop(From,TestData,StartDir);
 	{{stop,Info},From} ->
+	    test_server_io:reset_state(),
+	    {MiscIoName,MiscIoDivider,MiscIoFooter} =
+		proplists:get_value(misc_io_log,TestData),
+	    {ok,MiscIoFd} = file:open(MiscIoName,
+				      [append,{encoding,utf8}]),
+	    io:put_chars(MiscIoFd, MiscIoDivider),
+	    test_server_io:set_fd(unexpected_io, MiscIoFd),
+
 	    Time = calendar:local_time(),
 	    ct_event:sync_notify(#event{name=test_done,
 					node=node(),
 					data=Time}),
-	    Callbacks = ets:lookup_element(?suite_table,
-					   ct_hooks,
-					   #suite_data.value),
+	    Callbacks =
+		try ets:lookup_element(?suite_table,
+				       ct_hooks,
+				       #suite_data.value) of
+		    CTHMods -> CTHMods
+		catch
+		    %% this is because ct_util failed in init
+		    error:badarg -> []
+		end,
 	    ct_hooks:terminate(Callbacks),
 	    close_connections(ets:tab2list(?conn_table)),
 	    ets:delete(?conn_table),
 	    ets:delete(?board_table),
 	    ets:delete(?suite_table),
 	    ets:delete(?verbosity_table),
+
+	    io:put_chars(MiscIoFd, "\n</pre>\n"++MiscIoFooter),
+	    test_server_io:stop([unexpected_io]),
+	    test_server_io:finish(),
+
 	    ct_logs:close(Info, StartDir),
 	    ct_event:stop(),
 	    ct_config:stop(),
@@ -679,8 +713,14 @@ reset_silent_connections() ->
 %%% @see ct
 stop(Info) ->
     case whereis(ct_util_server) of
-	undefined -> ok;
-	_ -> call({stop,Info})
+	undefined -> 
+	    ok;
+	CtUtilPid ->
+	    Ref = monitor(process, CtUtilPid),
+	    call({stop,Info}),
+	    receive
+		{'DOWN',Ref,_,_,_} -> ok
+	    end
     end.
 
 %%%-----------------------------------------------------------------
diff --git a/lib/common_test/src/cth_log_redirect.erl b/lib/common_test/src/cth_log_redirect.erl
index a030701f19..11af1aa346 100644
--- a/lib/common_test/src/cth_log_redirect.erl
+++ b/lib/common_test/src/cth_log_redirect.erl
@@ -36,13 +36,17 @@
 	 handle_event/2, handle_call/2, handle_info/2,
 	 terminate/1]).
 
+%% Other
+-export([handle_remote_events/1]).
+
 -include("ct.hrl").
 
 -record(eh_state, {log_func,
 		   curr_suite,
 		   curr_group,
 		   curr_func,
-		   parallel_tcs = false}).
+		   parallel_tcs = false,
+		   handle_remote_events = false}).
 
 id(_Opts) ->
     ?MODULE.
@@ -51,7 +55,6 @@ init(?MODULE, _Opts) ->
     error_logger:add_report_handler(?MODULE),
     tc_log_async.
 
-
 pre_init_per_suite(Suite, Config, State) ->
     set_curr_func({Suite,init_per_suite}, Config),
     {Config, State}.
@@ -104,7 +107,8 @@ post_end_per_group(_Group, Config, Return, State) ->
 init(_Type) ->
     {ok, #eh_state{log_func = tc_log_async}}.
 
-handle_event({_Type, GL, _Msg}, State) when node(GL) /= node() ->
+handle_event({_Type,GL,_Msg}, #eh_state{handle_remote_events = false} = State)
+  when node(GL) /= node() ->
     {ok, State};
 handle_event(Event, #eh_state{log_func = LogFunc} = State) ->
     case lists:keyfind(sasl, 1, application:which_applications()) of
@@ -160,9 +164,12 @@ handle_call({set_curr_func,undefined,_Config}, State) ->
 handle_call({set_curr_func,TC,_Config}, State) ->
     {ok, ok, State#eh_state{curr_func = TC}};
 
-handle_call({set_logfunc,NewLogFunc},State) ->
+handle_call({set_logfunc,NewLogFunc}, State) ->
     {ok, NewLogFunc, State#eh_state{log_func = NewLogFunc}};
 
+handle_call({handle_remote_events,Bool}, State) ->
+    {ok, ok, State#eh_state{handle_remote_events = Bool}};
+
 handle_call(_Query, _State) ->
     {error, bad_query}.
 
@@ -179,8 +186,16 @@ set_curr_func(CurrFunc, Config) ->
 set_log_func(Func) ->
     gen_event:call(error_logger, ?MODULE, {set_logfunc, Func}).
 
+handle_remote_events(Bool) ->
+    gen_event:call(error_logger, ?MODULE, {handle_remote_events, Bool}).
+
 %%%-----------------------------------------------------------------
 
+format_header(#eh_state{curr_suite = undefined,
+			curr_group = undefined,
+			curr_func = undefined}) ->
+    io_lib:format("System report", []);
+
 format_header(#eh_state{curr_suite = Suite,
 			curr_group = undefined,
 			curr_func = undefined}) ->