From 614ba49d9ff9c75466bc3bba5b25a2e583e09217 Mon Sep 17 00:00:00 2001
From: Peter Andersson <peppe@erlang.org>
Date: Wed, 14 Aug 2013 23:38:12 +0200
Subject: Introduce pre- and post-test i/o log

---
 lib/common_test/src/ct_logs.erl          |  72 +++++++++---
 lib/common_test/src/ct_util.erl          |  14 +++
 lib/test_server/src/test_server_ctrl.erl |  33 ++++--
 lib/test_server/src/test_server_io.erl   | 183 ++++++++++++++++++++++++-------
 4 files changed, 238 insertions(+), 64 deletions(-)

diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index bd37b690b6..08a7fcb831 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").
@@ -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><br><h2>Post-test Log</h2>\n<pre>\n",
+	      "</pre>\n<br /><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..e039f68121 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,
@@ -392,6 +393,14 @@ 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(),
@@ -405,6 +414,11 @@ loop(Mode,TestData,StartDir) ->
 	    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(),
diff --git a/lib/test_server/src/test_server_ctrl.erl b/lib/test_server/src/test_server_ctrl.erl
index 4a10684ea5..d0f31af198 100644
--- a/lib/test_server/src/test_server_ctrl.erl
+++ b/lib/test_server/src/test_server_ctrl.erl
@@ -1171,7 +1171,13 @@ init_tester(Mod, Func, Args, Dir, Name, {_,_,MinLev}=Levels,
 	  "<td>~.3fs</td><td><b>~ts</b></td><td>~w Ok, ~w Failed~ts of ~w</td></tr>\n"
 	  "</tfoot>\n",
 	  [Time,SuccessStr,OkN,FailedN,SkipStr,OkN+FailedN+SkippedN]),
-    test_server_io:stop([major,html,unexpected_io]).
+
+    test_server_io:stop([major,html,unexpected_io]),
+    {UnexpectedIoName,UnexpectedIoFooter} = get(test_server_unexpected_footer),
+    {ok,UnexpectedIoFd} = open_html_file(UnexpectedIoName, [append]),
+    io:put_chars(UnexpectedIoFd, "\n</pre>\n"++UnexpectedIoFooter),
+    file:close(UnexpectedIoFd),
+    ok.
 
 report_severe_error(Reason) ->
     test_server_sup:framework_call(report, [severe_error,Reason]).
@@ -1630,15 +1636,13 @@ start_log_file() ->
 		    FilenameMode),
     ok = write_file(?last_file, TestDir1 ++ "\n", FilenameMode),
     put(test_server_log_dir_base,TestDir1),
+
     MajorName = filename:join(TestDir1, ?suitelog_name),
     HtmlName = MajorName ++ ?html_ext,
     UnexpectedName = filename:join(TestDir1, ?unexpected_io_log),
+
     {ok,Major} = open_utf8_file(MajorName),
     {ok,Html}  = open_html_file(HtmlName),
-    {ok,Unexpected}  = open_html_file(UnexpectedName),
-    test_server_io:set_fd(major, Major),
-    test_server_io:set_fd(html, Html),
-    test_server_io:set_fd(unexpected_io, Unexpected),
 
     {UnexpHeader,UnexpFooter} =
 	case test_server_sup:framework_call(get_html_wrapper,
@@ -1651,8 +1655,17 @@ start_log_file() ->
 	    {xhtml,UH,UF} ->
 		{UH,UF}
 	end,
-    io:put_chars(Unexpected, UnexpHeader++"\n<pre>\n"),
-    put(test_server_unexpected_footer,UnexpFooter),
+
+    {ok,Unexpected} = open_html_file(UnexpectedName),
+    io:put_chars(Unexpected, [UnexpHeader,			      
+			      xhtml("<br>\n<h2>Unexpected I/O</h2>",
+				    "<br />\n<h3>Unexpected I/O</h3>"),
+			      "\n<pre>\n"]),
+    put(test_server_unexpected_footer,{UnexpectedName,UnexpFooter}),
+
+    test_server_io:set_fd(major, Major),
+    test_server_io:set_fd(html, Html),
+    test_server_io:set_fd(unexpected_io, Unexpected),
 
     make_html_link(filename:absname(?last_test ++ ?html_ext),
 		   HtmlName, filename:basename(Dir)),
@@ -5287,6 +5300,9 @@ html_header(Title) ->
 open_html_file(File) ->
     open_utf8_file(File).
 
+open_html_file(File,Opts) ->
+    open_utf8_file(File,Opts).
+
 write_html_file(File,Content) ->
     write_file(File,Content,utf8).
 
@@ -5295,6 +5311,9 @@ write_html_file(File,Content) ->
 open_utf8_file(File) ->
     file:open(File,[write,{encoding,utf8}]).
 
+open_utf8_file(File,Opts) ->
+    file:open(File,[{encoding,utf8}|Opts]).
+
 %% Write a file with specified encoding
 write_file(File,Content,latin1) ->
     file:write_file(File,Content);
diff --git a/lib/test_server/src/test_server_io.erl b/lib/test_server/src/test_server_io.erl
index 73d4468bda..a92dbf5887 100644
--- a/lib/test_server/src/test_server_io.erl
+++ b/lib/test_server/src/test_server_io.erl
@@ -32,27 +32,39 @@
 -export([start_link/0,stop/1,get_gl/1,set_fd/2,
 	 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]).
+	 set_footer/1,set_job_name/1,set_gl_props/1,
+	 reset_state/0,finish/0]).
 
 -export([init/1,handle_call/3,handle_info/2,terminate/2]).
 
--record(st, {fds,				%Singleton fds (gb_tree)
-	     shared_gl :: pid(),		%Shared group leader
-	     gls,				%Group leaders (gb_set)
-	     io_buffering=false,		%I/O buffering
-	     buffered,				%Buffered I/O requests
-	     html_footer,			%HTML footer
-	     job_name,				%Name of current job.
-	     gl_props,				%Properties for GL.
-	     stopping
+-record(st, {fds,			    % Singleton fds (gb_tree)
+	     tags=[],                       % Known tag types   
+	     shared_gl :: pid(),	    % Shared group leader
+	     gls,			    % Group leaders (gb_set)
+	     io_buffering=false,	    % I/O buffering
+	     buffered,			    % Buffered I/O requests
+	     html_footer,		    % HTML footer
+	     job_name,			    % Name of current job.
+	     gl_props,			    % Properties for GL
+	     phase,                         % Indicates current mode
+	     offline_buffer,                % Buffer I/O during startup
+	     stopping,                      % Reply to when process stopped
+	     pending_ops                    % Perform when process idle 
 	    }).
 
 start_link() ->
-    case gen_server:start_link({local,?MODULE}, ?MODULE, [], []) of
-	{ok,Pid} ->
-	    {ok,Pid};
-	Other ->
-	    Other
+    case whereis(?MODULE) of
+	undefined ->
+	    case gen_server:start_link({local,?MODULE}, ?MODULE, [], []) of
+		{ok,Pid} ->
+		    {ok,Pid};
+		Other ->
+		    Other
+	    end;
+	Pid ->
+	    %% already running, reset the state
+	    reset_state(),
+	    {ok,Pid}
     end.
 
 stop(FilesToClose) ->
@@ -62,6 +74,9 @@ stop(FilesToClose) ->
     group_leader(OldGL, self()),
     ok.
 
+finish() ->
+    req(finish).
+
 %% get_gl(Shared) -> Pid
 %%  Shared = boolean()
 %%  Pid = pid()
@@ -142,19 +157,27 @@ set_footer(Footer) ->
     req({set_footer,Footer}).
 
 %% set_job_name(Name)
+%%
 %%  Set a name for the currently running job. The name will be used
 %%  when printing to 'stdout'.
 %%
+
 set_job_name(Name) ->
     req({set_job_name,Name}).
 
 %% set_gl_props(PropList)
+%%
 %%  Set properties for group leader processes. When a group_leader process
 %%  is created, test_server_gl:set_props(PropList) will be called.
 
 set_gl_props(PropList) ->
     req({set_gl_props,PropList}).
 
+%% reset_state
+%%
+%% Reset the initial state
+reset_state() ->
+    req(reset_state).
 
 %%% Internal functions.
 
@@ -167,7 +190,10 @@ init([]) ->
 	    buffered=Empty,
 	    html_footer="</body>\n</html>\n",
 	    job_name="<name not set>",
-	    gl_props=[]}}.
+	    gl_props=[],
+	    phase=starting,
+	    offline_buffer=[],
+	    pending_ops=[]}}.
 
 req(Req) ->
     gen_server:call(?MODULE, Req, infinity).
@@ -178,9 +204,24 @@ handle_call({get_gl,false}, _From, #st{gls=Gls,gl_props=Props}=St) ->
     {reply,Pid,St#st{gls=gb_sets:insert(Pid, Gls)}};
 handle_call({get_gl,true}, _From, #st{shared_gl=Shared}=St) ->
     {reply,Shared,St};
-handle_call({set_fd,Tag,Fd}, _From, #st{fds=Fds0}=St) ->
+handle_call({set_fd,Tag,Fd}, _From, #st{fds=Fds0,tags=Tags0,
+					offline_buffer=OfflineBuff}=St) ->
     Fds = gb_trees:enter(Tag, Fd, Fds0),
-    {reply,ok,St#st{fds=Fds}};
+    St1 = St#st{fds=Fds,tags=[Tag|lists:delete(Tag, Tags0)]},
+    OfflineBuff1 =
+	if OfflineBuff == [] ->
+		[];
+	   true ->
+		%% Fd ready, print anything buffered for associated Tag
+		lists:filtermap(fun({T,From,Str}) when T == Tag ->
+					output(From, Tag, Str, St1),
+					false;
+				   (_) ->
+					true
+				end, lists:reverse(OfflineBuff))
+	end,
+    {reply,ok,St1#st{phase=started,
+		     offline_buffer=lists:reverse(OfflineBuff1)}};
 handle_call({start_transaction,Pid}, _From, #st{io_buffering=Buffer0,
 						buffered=Buf0}=St) ->
     Buf = case gb_trees:is_defined(Pid, Buf0) of
@@ -213,12 +254,15 @@ handle_call({set_job_name,Name}, _From, St) ->
 handle_call({set_gl_props,Props}, _From, #st{shared_gl=Shared}=St) ->
     test_server_gl:set_props(Shared, Props),
     {reply,ok,St#st{gl_props=Props}};
-handle_call({stop,FdTags}, From, #st{fds=Fds,shared_gl=SGL,gls=Gls0}=St0) ->
-    St = St0#st{gls=gb_sets:insert(SGL, Gls0),stopping=From},
-    gc(St),
-    %% Give the users of the surviving group leaders some
-    %% time to finish.
-    erlang:send_after(2000, self(), stop_group_leaders),
+handle_call(reset_state, From, #st{phase=stopping,pending_ops=Ops}=St) ->
+    %% can't reset during stopping phase, save op for later
+    Op = fun(NewSt) -> 
+		 {_,Result,NewSt1} = handle_call(reset_state, From, NewSt),
+		 {Result,NewSt1}
+	 end,
+    {noreply,St#st{pending_ops=[{From,Op}|Ops]}};
+handle_call(reset_state, _From, #st{fds=Fds,tags=Tags,gls=Gls,
+				    offline_buffer=OfflineBuff}) ->
     %% close open log files
     lists:foreach(fun(Tag) ->
 			  case gb_trees:lookup(Tag, Fds) of
@@ -227,8 +271,44 @@ handle_call({stop,FdTags}, From, #st{fds=Fds,shared_gl=SGL,gls=Gls0}=St0) ->
 			      {value,Fd} ->
 				  file:close(Fd)
 			  end
-		  end, FdTags),
-    {noreply,St}.
+		  end, Tags),
+    GlList = gb_sets:to_list(Gls),
+    [test_server_gl:stop(GL) || GL <- GlList],
+    timer:sleep(2000),
+    [exit(GL, kill) || GL <- GlList],
+    Empty = gb_trees:empty(),
+    {ok,Shared} = test_server_gl:start_link(),
+    {reply,ok,#st{fds=Empty,shared_gl=Shared,gls=gb_sets:empty(),
+		  io_buffering=gb_sets:empty(),
+		  buffered=Empty,
+		  html_footer="</body>\n</html>\n",
+		  job_name="<name not set>",
+		  gl_props=[],
+		  phase=starting,
+		  offline_buffer=OfflineBuff,
+		  pending_ops=[]}};
+handle_call({stop,FdTags}, From, #st{fds=Fds0,tags=Tags0,
+				     shared_gl=SGL,gls=Gls0}=St0) ->
+    St = St0#st{gls=gb_sets:insert(SGL, Gls0),phase=stopping,stopping=From},
+    gc(St),
+    %% close open log files
+    {Fds1,Tags1} = lists:foldl(fun(Tag, {Fds,Tags}) ->
+			       case gb_trees:lookup(Tag, Fds) of
+				   none ->
+				       {Fds,Tags};
+				   {value,Fd} ->
+				       file:close(Fd),
+				       {gb_trees:delete(Tag, Fds),
+					lists:delete(Tag, Tags)}
+			       end
+		       end, {Fds0,Tags0}, FdTags),
+    %% Give the users of the surviving group leaders some
+    %% time to finish.
+    erlang:send_after(2000, self(), stop_group_leaders),    
+    {noreply,St#st{fds=Fds1,tags=Tags1}};
+handle_call(finish, From, St) ->
+    gen_server:reply(From, ok),
+    {stop,normal,St}.
 
 handle_info({'EXIT',Pid,normal}, #st{gls=Gls0,stopping=From}=St) ->
     Gls = gb_sets:delete_any(Pid, Gls0),
@@ -236,10 +316,10 @@ handle_info({'EXIT',Pid,normal}, #st{gls=Gls0,stopping=From}=St) ->
 	true ->
 	    %% No more group leaders left.
 	    gen_server:reply(From, ok),
-	    {stop,normal,St#st{gls=Gls,stopping=undefined}};
+	    {noreply,St#st{gls=Gls,phase=stopping,stopping=undefined}};
 	false ->
 	    %% Wait for more group leaders to finish.
-	    {noreply,St#st{gls=Gls}}
+	    {noreply,St#st{gls=Gls,phase=stopping}}
     end;
 handle_info({'EXIT',_Pid,Reason}, _St) ->
     exit(Reason);
@@ -248,10 +328,21 @@ handle_info(stop_group_leaders, #st{gls=Gls}=St) ->
     [test_server_gl:stop(GL) || GL <- gb_sets:to_list(Gls)],
     erlang:send_after(2000, self(), kill_group_leaders),
     {noreply,St};
-handle_info(kill_group_leaders, #st{gls=Gls,stopping=From}=St) ->
+handle_info(kill_group_leaders, #st{gls=Gls,stopping=From,
+				    pending_ops=Ops}=St) ->
     [exit(GL, kill) || GL <- gb_sets:to_list(Gls)],
-    gen_server:reply(From, ok),
-    {stop,normal,St};
+    if From /= undefined ->
+	    gen_server:reply(From, ok);
+       true ->					% reply has been sent already
+	    ok
+    end,
+    %% we're idle, check if any ops are pending
+    St1 = lists:foldr(fun({ReplyTo,Op},NewSt) ->
+			      {Result,NewSt1} = Op(NewSt),
+			      gen_server:reply(ReplyTo, Result),
+			      NewSt1
+		      end, St#st{phase=idle,pending_ops=[]}, Ops),
+    {noreply,St1};
 handle_info(Other, St) ->
     io:format("Ignoring: ~p\n", [Other]),
     {noreply,St}.
@@ -259,11 +350,19 @@ handle_info(Other, St) ->
 terminate(_, _) ->
     ok.
 
-output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0}=St) ->
+output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0,
+			   phase=Phase,offline_buffer=OfflineBuff}=St) ->
     case gb_sets:is_member(From, Buffered) of
 	false ->
-	    do_output(Tag, Str, St),
-	    St;
+	    case do_output(Tag, Str, Phase, St) of
+		buffer when length(OfflineBuff)>500 ->
+		    %% something's wrong, clear buffer
+		    St#st{offline_buffer=[]};
+		buffer ->
+		    St#st{offline_buffer=[{Tag,From,Str}|OfflineBuff]};
+		_ ->
+		    St
+	    end;
 	true ->
 	    Q0 = gb_trees:get(From, Buf0),
 	    Q = queue:in({Tag,Str}, Q0),
@@ -271,17 +370,19 @@ output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0}=St) ->
 	    St#st{buffered=Buf}
     end.
 
-do_output(stdout, Str, #st{job_name=undefined}) ->
+do_output(stdout, Str, _, #st{job_name=undefined}) ->
     io:put_chars(Str);
-do_output(stdout, Str0, #st{job_name=Name}) ->
+do_output(stdout, Str0, _, #st{job_name=Name}) ->
     Str = io_lib:format("Testing ~ts: ~ts\n", [Name,Str0]),
     io:put_chars(Str);
-do_output(Tag, Str, #st{fds=Fds}=St) ->
+do_output(Tag, Str, Phase, #st{fds=Fds}=St) ->
     case gb_trees:lookup(Tag, Fds) of
+	none when Phase /= started ->
+	    buffer;
 	none ->
 	    S = io_lib:format("\n*** ERROR: ~w, line ~w: No known '~p' log file\n",
 			      [?MODULE,?LINE,Tag]),
-	    do_output(stdout, [S,Str], St);
+	    do_output(stdout, [S,Str], Phase, St);
 	{value,Fd} ->
 	    try
 		io:put_chars(Fd, Str),
@@ -293,14 +394,14 @@ do_output(Tag, Str, #st{fds=Fds}=St) ->
 		    S = io_lib:format("\n*** ERROR: ~w, line ~w: Error writing to "
 				      "log file '~p': ~p\n",
 				      [?MODULE,?LINE,Tag,Error]),
-		    do_output(stdout, [S,Str], St)
+		    do_output(stdout, [S,Str], Phase, St)
 	    end
     end.
 
 finalise_table(Fd, #st{html_footer=Footer}) ->
     case file:position(Fd, {cur,0}) of
 	{ok,Pos} ->
-	    %% We are writing to a seekable file.  Finalise so
+	    %% We are writing to a seekable file. Finalise so
 	    %% we get complete valid (and viewable) HTML code.
 	    %% Then rewind to overwrite the finalising code.
 	    io:put_chars(Fd, ["\n</table>\n",Footer]),
@@ -319,7 +420,7 @@ do_print_buffered(Q0, St) ->
 	eot ->
 	    Q;
 	{Tag,Str} ->
-	    do_output(Tag, Str, St),
+	    do_output(Tag, Str, undefined, St),
 	    do_print_buffered(Q, St)
     end.
 
-- 
cgit v1.2.3


From a5c108b7eed9badc3b0ea0b4bad3af4bf36bc55b Mon Sep 17 00:00:00 2001
From: Peter Andersson <peppe@erlang.org>
Date: Fri, 23 Aug 2013 15:18:22 +0200
Subject: Fix problem with start order of hooks and stopping of ct_util_server

---
 lib/common_test/src/ct_hooks.erl |  2 +-
 lib/common_test/src/ct_logs.erl  |  4 ++--
 lib/common_test/src/ct_util.erl  | 10 ++++++++--
 3 files changed, 11 insertions(+), 5 deletions(-)

diff --git a/lib/common_test/src/ct_hooks.erl b/lib/common_test/src/ct_hooks.erl
index 3d87a82e24..b492663c57 100644
--- a/lib/common_test/src/ct_hooks.erl
+++ b/lib/common_test/src/ct_hooks.erl
@@ -50,7 +50,7 @@
 -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, []).
 		      
 
diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index 08a7fcb831..4cc1564570 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -641,8 +641,8 @@ logger(Parent, Mode, Verbosity) ->
 		  "\n<pre>\n"]),
     MiscIoDivider =
 	"\n<a name=\"posttest\"></a>\n"++
-	xhtml("</pre>\n<br><br><h2>Post-test Log</h2>\n<pre>\n",
-	      "</pre>\n<br /><br />\n<h3>POST-TEST LOG</h3>\n<pre>\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}}),
 
diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl
index e039f68121..cbdf999cf8 100644
--- a/lib/common_test/src/ct_util.erl
+++ b/lib/common_test/src/ct_util.erl
@@ -693,8 +693,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.
 
 %%%-----------------------------------------------------------------
-- 
cgit v1.2.3


From 32fae66768d11bc62ff75705e1d5a6ebe2978432 Mon Sep 17 00:00:00 2001
From: Peter Andersson <peppe@erlang.org>
Date: Fri, 23 Aug 2013 15:58:56 +0200
Subject: Fix timing related problem

---
 lib/test_server/src/test_server_io.erl | 23 ++++++++++++++++++-----
 1 file changed, 18 insertions(+), 5 deletions(-)

diff --git a/lib/test_server/src/test_server_io.erl b/lib/test_server/src/test_server_io.erl
index a92dbf5887..62af3d5b28 100644
--- a/lib/test_server/src/test_server_io.erl
+++ b/lib/test_server/src/test_server_io.erl
@@ -274,8 +274,14 @@ handle_call(reset_state, _From, #st{fds=Fds,tags=Tags,gls=Gls,
 		  end, Tags),
     GlList = gb_sets:to_list(Gls),
     [test_server_gl:stop(GL) || GL <- GlList],
-    timer:sleep(2000),
-    [exit(GL, kill) || GL <- GlList],
+    timer:sleep(100),
+    case lists:filter(fun(GlPid) -> is_process_alive(GlPid) end, GlList) of
+	[] ->
+	    ok;
+	_ ->
+	    timer:sleep(2000),
+	    [exit(GL, kill) || GL <- GlList]
+    end,
     Empty = gb_trees:empty(),
     {ok,Shared} = test_server_gl:start_link(),
     {reply,ok,#st{fds=Empty,shared_gl=Shared,gls=gb_sets:empty(),
@@ -304,7 +310,7 @@ handle_call({stop,FdTags}, From, #st{fds=Fds0,tags=Tags0,
 		       end, {Fds0,Tags0}, FdTags),
     %% Give the users of the surviving group leaders some
     %% time to finish.
-    erlang:send_after(2000, self(), stop_group_leaders),    
+    erlang:send_after(1000, self(), stop_group_leaders),    
     {noreply,St#st{fds=Fds1,tags=Tags1}};
 handle_call(finish, From, St) ->
     gen_server:reply(From, ok),
@@ -325,8 +331,15 @@ handle_info({'EXIT',_Pid,Reason}, _St) ->
     exit(Reason);
 handle_info(stop_group_leaders, #st{gls=Gls}=St) ->
     %% Stop the remaining group leaders.
-    [test_server_gl:stop(GL) || GL <- gb_sets:to_list(Gls)],
-    erlang:send_after(2000, self(), kill_group_leaders),
+    GlPids = gb_sets:to_list(Gls),
+    [test_server_gl:stop(GL) || GL <- GlPids],
+    timer:sleep(100),
+    Wait = 
+	case lists:filter(fun(GlPid) -> is_process_alive(GlPid) end, GlPids) of
+	    [] -> 0;
+	    _  -> 2000
+	end,
+    erlang:send_after(Wait, self(), kill_group_leaders),
     {noreply,St};
 handle_info(kill_group_leaders, #st{gls=Gls,stopping=From,
 				    pending_ops=Ops}=St) ->
-- 
cgit v1.2.3


From 112b1f795ccd573a612208269e9b4937865445b5 Mon Sep 17 00:00:00 2001
From: Peter Andersson <peppe@erlang.org>
Date: Fri, 30 Aug 2013 14:52:08 +0200
Subject: Add test suite

---
 lib/common_test/test/Makefile                      |   1 +
 lib/common_test/test/ct_pre_post_test_io_SUITE.erl | 114 ++++++++++++++++++
 .../ct_pre_post_test_io_SUITE_data/cth_ctrl.erl    |  97 +++++++++++++++
 .../ct_pre_post_test_io_SUITE_data/dummy_SUITE.erl | 132 +++++++++++++++++++++
 lib/common_test/test/ct_test_support.erl           |  12 +-
 5 files changed, 355 insertions(+), 1 deletion(-)
 create mode 100644 lib/common_test/test/ct_pre_post_test_io_SUITE.erl
 create mode 100644 lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
 create mode 100644 lib/common_test/test/ct_pre_post_test_io_SUITE_data/dummy_SUITE.erl

diff --git a/lib/common_test/test/Makefile b/lib/common_test/test/Makefile
index 9d2edcd653..085f19d023 100644
--- a/lib/common_test/test/Makefile
+++ b/lib/common_test/test/Makefile
@@ -51,6 +51,7 @@ MODULES= \
 	ct_master_SUITE \
 	ct_misc_1_SUITE \
 	ct_hooks_SUITE \
+	ct_pre_post_test_io_SUITE \
 	ct_netconfc_SUITE \
 	ct_basic_html_SUITE \
 	ct_auto_compile_SUITE \
diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
new file mode 100644
index 0000000000..8d94a60244
--- /dev/null
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
@@ -0,0 +1,114 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 2012. 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
+%% compliance with the License. You should have received a copy of the
+%% Erlang Public License along with this software. If not, it can be
+%% retrieved online at http://www.erlang.org/.
+%%
+%% Software distributed under the License is distributed on an "AS IS"
+%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
+%% the License for the specific language governing rights and limitations
+%% under the License.
+%%
+%% %CopyrightEnd%
+%%
+
+%%%-------------------------------------------------------------------
+%%% File: ct_pre_post_test_io_SUITE
+%%%
+%%% Description:
+%%%
+%%% Test that ct:log/2 printouts and error/progress reports that happen
+%%% before or after the test run are saved in the pre/post test IO log.
+%%%-------------------------------------------------------------------
+-module(ct_pre_post_test_io_SUITE).
+
+-compile(export_all).
+
+-include_lib("common_test/include/ct.hrl").
+-include_lib("common_test/include/ct_event.hrl").
+
+-define(eh, ct_test_support_eh).
+
+%%--------------------------------------------------------------------
+%% TEST SERVER CALLBACK FUNCTIONS
+%%--------------------------------------------------------------------
+
+%%--------------------------------------------------------------------
+%% Description: Since Common Test starts another Test Server
+%% instance, the tests need to be performed on a separate node (or
+%% there will be clashes with logging processes etc).
+%%--------------------------------------------------------------------
+init_per_suite(Config) ->
+    DataDir = ?config(data_dir, Config),
+    CTH = filename:join(DataDir, "cth_ctrl.erl"),
+    ct:pal("Compiling ~p: ~p",
+	   [CTH,compile:file(CTH,[{outdir,DataDir},debug_info])]),
+    ct_test_support:init_per_suite([{path_dirs,[DataDir]} | Config]).
+
+end_per_suite(Config) ->
+    ct_test_support:end_per_suite(Config).
+
+init_per_testcase(TestCase, Config) ->
+    ct_test_support:init_per_testcase(TestCase, Config).
+
+end_per_testcase(TestCase, Config) ->
+    ct_test_support:end_per_testcase(TestCase, Config).
+
+suite() -> [{ct_hooks,[ts_install_cth]}].
+
+all() ->
+    [
+     pre_post_io
+    ].
+
+%%--------------------------------------------------------------------
+%% TEST CASES
+%%--------------------------------------------------------------------
+
+%%%-----------------------------------------------------------------
+%%%
+pre_post_io(Config) ->
+    TC = pre_post_io,
+    DataDir = ?config(data_dir, Config),
+    Suite = filename:join(DataDir, "dummy_SUITE"),
+    {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,cth_ctrl}], Config),
+    ct_test_support:run(Opts, Config),
+    ct:sleep(2000),
+    ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
+    ct:sleep(4000),
+    ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
+    ct:sleep(2000),
+    Events = ct_test_support:get_events(ERPid, Config),
+    ct_test_support:log_events(TC,
+			       reformat(Events, ?eh),
+			       ?config(priv_dir, Config),
+			       Opts),
+    TestEvents = events_to_check(TC),
+    ok = ct_test_support:verify_events(TestEvents, Events, Config).
+
+%%%-----------------------------------------------------------------
+%%% HELP FUNCTIONS
+%%%-----------------------------------------------------------------
+
+setup(Test, Config) ->
+    Opts0 = ct_test_support:get_opts(Config),
+    Level = ?config(trace_level, Config),
+    EvHArgs = [{cbm,ct_test_support},{trace_level,Level}],
+    Opts = Opts0 ++ [{event_handler,{?eh,EvHArgs}}|Test],
+    ERPid = ct_test_support:start_event_receiver(Config),
+    {Opts,ERPid}.
+
+reformat(Events, EH) ->
+    ct_test_support:reformat(Events, EH).
+
+%%%-----------------------------------------------------------------
+%%% TEST EVENTS
+%%%-----------------------------------------------------------------
+
+events_to_check(_Test) ->
+    [].
diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
new file mode 100644
index 0000000000..89f1734491
--- /dev/null
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
@@ -0,0 +1,97 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 2012. 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
+%% compliance with the License. You should have received a copy of the
+%% Erlang Public License along with this software. If not, it can be
+%% retrieved online at http://www.erlang.org/.
+%%
+%% Software distributed under the License is distributed on an "AS IS"
+%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
+%% the License for the specific language governing rights and limitations
+%% under the License.
+%%
+%% %CopyrightEnd%
+%%
+-module(cth_ctrl).
+
+-export([proceed/0,
+	 init/2, terminate/1]).
+
+%%%===================================================================
+%%% API
+%%%===================================================================
+
+proceed() ->
+    ?MODULE ! proceed.
+
+%%--------------------------------------------------------------------
+%% Hook functions
+%%--------------------------------------------------------------------
+init(_Id, _Opts) ->
+    WhoAmI = self(),
+    DispPid = spawn_link(fun() -> dispatcher(WhoAmI) end),
+    register(?MODULE, DispPid),
+    io:format(user,
+	      "~n~n+++ Startup finished, call ~w:proceed() to run tests!~n~n",
+	      [?MODULE]),
+    start_external_logger(cth_logger),
+    receive
+	{?MODULE,proceed} -> ok
+    after
+	10000 ->
+	    ok
+    end,
+    {ok,[],ct_last}.
+
+terminate(_State) ->
+    io:format(user,
+	      "~n~n+++ Tests finished, call ~w:proceed() to shut down!~n~n",
+	      [?MODULE]),
+    receive
+	{?MODULE,proceed} -> ok
+    after
+       10000 ->
+	    ok
+    end,
+    stop_external_logger(cth_logger),
+    stop_dispatcher(),
+    ok.
+
+%%%===================================================================
+%%% Internal functions
+%%%===================================================================
+
+start_external_logger(Name) ->
+    case whereis(Name) of
+	undefined -> ok;
+	Pid -> exit(Pid, kill)
+    end,
+    spawn(fun() -> init_logger(Name) end).
+
+stop_external_logger(Name) ->
+    catch exit(whereis(Name), kill).
+
+init_logger(Name) ->
+    register(Name, self()),
+    logger_loop(1).
+
+logger_loop(N) ->
+    ct:log("Logger iteration: ~p", [N]),
+    error_logger:error_report(N),
+    timer:sleep(250),
+    logger_loop(N+1).
+
+%%%-----------------------------------------------------------------
+
+dispatcher(SendTo) ->
+    receive Msg -> SendTo ! {?MODULE,Msg} end,
+    dispatcher(SendTo).
+
+stop_dispatcher() ->
+    catch exit(whereis(?MODULE), kill).
+	    
+
diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/dummy_SUITE.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/dummy_SUITE.erl
new file mode 100644
index 0000000000..ac9c4efd31
--- /dev/null
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/dummy_SUITE.erl
@@ -0,0 +1,132 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 2012. 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
+%% compliance with the License. You should have received a copy of the
+%% Erlang Public License along with this software. If not, it can be
+%% retrieved online at http://www.erlang.org/.
+%%
+%% Software distributed under the License is distributed on an "AS IS"
+%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
+%% the License for the specific language governing rights and limitations
+%% under the License.
+%%
+%% %CopyrightEnd%
+%%
+-module(dummy_SUITE).
+
+-compile(export_all).
+
+-include_lib("common_test/include/ct.hrl").
+
+%%--------------------------------------------------------------------
+%% @spec suite() -> Info
+%% Info = [tuple()]
+%% @end
+%%--------------------------------------------------------------------
+suite() ->
+    [{timetrap,{seconds,30}}].
+
+%%--------------------------------------------------------------------
+%% @spec init_per_suite(Config0) ->
+%%     Config1 | {skip,Reason} | {skip_and_save,Reason,Config1}
+%% Config0 = Config1 = [tuple()]
+%% Reason = term()
+%% @end
+%%--------------------------------------------------------------------
+init_per_suite(Config) ->
+    Config.
+
+%%--------------------------------------------------------------------
+%% @spec end_per_suite(Config0) -> void() | {save_config,Config1}
+%% Config0 = Config1 = [tuple()]
+%% @end
+%%--------------------------------------------------------------------
+end_per_suite(_Config) ->
+    ok.
+
+%%--------------------------------------------------------------------
+%% @spec init_per_group(GroupName, Config0) ->
+%%               Config1 | {skip,Reason} | {skip_and_save,Reason,Config1}
+%% GroupName = atom()
+%% Config0 = Config1 = [tuple()]
+%% Reason = term()
+%% @end
+%%--------------------------------------------------------------------
+init_per_group(_GroupName, Config) ->
+    Config.
+    
+%%--------------------------------------------------------------------
+%% @spec end_per_group(GroupName, Config0) ->
+%%               void() | {save_config,Config1}
+%% GroupName = atom()
+%% Config0 = Config1 = [tuple()]
+%% @end
+%%--------------------------------------------------------------------
+end_per_group(_GroupName, _Config) ->
+    ok.
+
+%%--------------------------------------------------------------------
+%% @spec init_per_testcase(TestCase, Config0) ->
+%%               Config1 | {skip,Reason} | {skip_and_save,Reason,Config1}
+%% TestCase = atom()
+%% Config0 = Config1 = [tuple()]
+%% Reason = term()
+%% @end
+%%--------------------------------------------------------------------
+init_per_testcase(_TestCase, Config) ->
+    ct:sleep(500),
+    Config.
+
+%%--------------------------------------------------------------------
+%% @spec end_per_testcase(TestCase, Config0) ->
+%%               void() | {save_config,Config1} | {fail,Reason}
+%% TestCase = atom()
+%% Config0 = Config1 = [tuple()]
+%% Reason = term()
+%% @end
+%%--------------------------------------------------------------------
+end_per_testcase(_TestCase, _Config) ->
+    ok.
+
+%%--------------------------------------------------------------------
+%% @spec groups() -> [Group]
+%% Group = {GroupName,Properties,GroupsAndTestCases}
+%% GroupName = atom()
+%% Properties = [parallel | sequence | Shuffle | {RepeatType,N}]
+%% GroupsAndTestCases = [Group | {group,GroupName} | TestCase]
+%% TestCase = atom()
+%% Shuffle = shuffle | {shuffle,{integer(),integer(),integer()}}
+%% RepeatType = repeat | repeat_until_all_ok | repeat_until_all_fail |
+%%              repeat_until_any_ok | repeat_until_any_fail
+%% N = integer() | forever
+%% @end
+%%--------------------------------------------------------------------
+groups() ->
+    [{g1,[parallel],[tc1,tc2,tc3]},
+     {g2,[],[tc4,tc5]}].
+
+%%--------------------------------------------------------------------
+%% @spec all() -> GroupsAndTestCases | {skip,Reason}
+%% GroupsAndTestCases = [{group,GroupName} | TestCase]
+%% GroupName = atom()
+%% TestCase = atom()
+%% Reason = term()
+%% @end
+%%--------------------------------------------------------------------
+all() -> 
+    [{group,g1},tc1,tc2,{group,g2}].
+
+tc1(_C) ->
+    ok.
+tc2(_C) ->
+    ok.
+tc3(_C) ->
+    ok.
+tc4(_C) ->
+    ok.
+tc5(_C) ->
+    ok.
diff --git a/lib/common_test/test/ct_test_support.erl b/lib/common_test/test/ct_test_support.erl
index 4132995bf6..5512b9c242 100644
--- a/lib/common_test/test/ct_test_support.erl
+++ b/lib/common_test/test/ct_test_support.erl
@@ -38,7 +38,7 @@
 
 -export([start_slave/3, slave_stop/1]).
 
--export([ct_test_halt/1]).
+-export([ct_test_halt/1, ct_rpc/2]).
 
 -include_lib("kernel/include/file.hrl").
 
@@ -377,6 +377,16 @@ wait_for_ct_stop(Retries, CTNode) ->
 	    wait_for_ct_stop(Retries-1, CTNode)
     end.
 
+%%%-----------------------------------------------------------------
+%%% ct_rpc/1
+ct_rpc({M,F,A}, Config) ->
+    CTNode = proplists:get_value(ct_node, Config),
+    Level = proplists:get_value(trace_level, Config),
+    test_server:format(Level, "~nCalling ~w:~w(~p) on ~p...",
+		       [M,F,A, CTNode]),
+    rpc:call(CTNode, M, F, A).
+
+
 %%%-----------------------------------------------------------------
 %%% EVENT HANDLING
 
-- 
cgit v1.2.3


From 376da624578485aae6160d8ee327330d58613fae Mon Sep 17 00:00:00 2001
From: Peter Andersson <peppe@erlang.org>
Date: Sun, 1 Sep 2013 23:36:24 +0200
Subject: Find and fix minor bugs

---
 lib/common_test/src/ct_hooks.erl                   |   5 +-
 lib/common_test/src/ct_logs.erl                    |   2 +-
 lib/common_test/src/ct_util.erl                    |  30 +++-
 lib/common_test/src/cth_log_redirect.erl           |  23 ++-
 lib/common_test/test/ct_pre_post_test_io_SUITE.erl | 158 +++++++++++++++++++--
 .../ct_pre_post_test_io_SUITE_data/cth_ctrl.erl    |  13 +-
 lib/common_test/test/ct_test_support.erl           |   9 +-
 7 files changed, 214 insertions(+), 26 deletions(-)

diff --git a/lib/common_test/src/ct_hooks.erl b/lib/common_test/src/ct_hooks.erl
index b492663c57..e845e9e908 100644
--- a/lib/common_test/src/ct_hooks.erl
+++ b/lib/common_test/src/ct_hooks.erl
@@ -52,7 +52,6 @@
 init(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 4cc1564570..1a6e4d31a8 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -524,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>".
diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl
index cbdf999cf8..bcc4caa62e 100644
--- a/lib/common_test/src/ct_util.erl
+++ b/lib/common_test/src/ct_util.erl
@@ -199,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,
@@ -405,9 +419,15 @@ loop(Mode,TestData,StartDir) ->
 	    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),
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}) ->
diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
index 8d94a60244..84341a0b99 100644
--- a/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
@@ -48,7 +48,8 @@ init_per_suite(Config) ->
     CTH = filename:join(DataDir, "cth_ctrl.erl"),
     ct:pal("Compiling ~p: ~p",
 	   [CTH,compile:file(CTH,[{outdir,DataDir},debug_info])]),
-    ct_test_support:init_per_suite([{path_dirs,[DataDir]} | Config]).
+    ct_test_support:init_per_suite([{path_dirs,[DataDir]},
+				    {start_sasl,true} | Config]).
 
 end_per_suite(Config) ->
     ct_test_support:end_per_suite(Config).
@@ -76,20 +77,117 @@ pre_post_io(Config) ->
     TC = pre_post_io,
     DataDir = ?config(data_dir, Config),
     Suite = filename:join(DataDir, "dummy_SUITE"),
-    {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,cth_ctrl}], Config),
+    {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,[cth_ctrl]}],
+			 Config),
+    
+    %%!--------------------------------------------------------------------
+    %%! Note that error reports will not start showing up in the pre-test
+    %%! io log until handle_remote_events has been set to true (see below).
+    %%! The reason is that the error logger has its group leader on the
+    %%! test_server node (not the ct node) and cth_log_redirect ignores
+    %%! events with remote destination until told otherwise.
+    %%!--------------------------------------------------------------------
+
+    spawn(fun() ->
+		  %% --- test run 1 ---
+		  ct:sleep(3000),
+		  ct_test_support:ct_rpc({cth_log_redirect,
+					  handle_remote_events,
+					  [true]}, Config),
+		  ct:sleep(2000),
+		  io:format(user, "Starting test run!~n", []),
+		  ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
+		  ct:sleep(6000),
+		  io:format(user, "Finishing off!~n", []),
+		  ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
+		  %% --- test run 2 ---
+		  ct:sleep(3000),
+		  ct_test_support:ct_rpc({cth_log_redirect,
+					  handle_remote_events,
+					  [true]}, Config),
+		  ct:sleep(2000),
+		  io:format(user, "Starting test run!~n", []),
+		  ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
+		  ct:sleep(6000),
+		  io:format(user, "Finishing off!~n", []),
+		  ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config)
+	  end),
     ct_test_support:run(Opts, Config),
-    ct:sleep(2000),
-    ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
-    ct:sleep(4000),
-    ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
-    ct:sleep(2000),
     Events = ct_test_support:get_events(ERPid, Config),
     ct_test_support:log_events(TC,
 			       reformat(Events, ?eh),
 			       ?config(priv_dir, Config),
 			       Opts),
     TestEvents = events_to_check(TC),
-    ok = ct_test_support:verify_events(TestEvents, Events, Config).
+    ok = ct_test_support:verify_events(TestEvents, Events, Config),
+    
+    LogDirs = lists:flatmap(fun({_EH,#event{name=start_logging,data=Dir}}) ->
+				    [Dir];
+			       (_) ->
+				    []
+			    end, Events),
+    PrePostIoFiles =
+	[filename:join(LogDir, "misc_io.log.html") || LogDir <- LogDirs],
+    lists:foreach(
+      fun(PrePostIoFile) ->
+	      ct:log("Reading Pre/Post Test IO Log file: ~ts", [PrePostIoFile]),
+	      {ok,Bin} = file:read_file(PrePostIoFile),
+	      Ts = string:tokens(binary_to_list(Bin),[$\n]),
+	      PrePostIOEntries =
+		  lists:foldl(fun([$L,$o,$g,$g,$e,$r|_],
+				  {pre,PreLogN,PreErrN,0,0}) ->
+				      {pre,PreLogN+1,PreErrN,0,0};
+				 ([$=,$E,$R,$R,$O,$R|_],
+				  {pre,PreLogN,PreErrN,0,0}) ->
+				      {pre,PreLogN,PreErrN+1,0,0};
+				 ([_,_,_,_,$P,$O,$S,$T,$-,$T,$E,$S,$T|_],
+				  {pre,PreLogN,PreErrN,0,0}) ->
+				      {post,PreLogN,PreErrN,0,0};
+				 ([$L,$o,$g,$g,$e,$r|_],
+				  {post,PreLogN,PreErrN,PostLogN,PostErrN}) ->
+				      {post,PreLogN,PreErrN,PostLogN+1,PostErrN};
+				 ([$=,$E,$R,$R,$O,$R|_],
+				  {post,PreLogN,PreErrN,PostLogN,PostErrN}) ->
+				      {post,PreLogN,PreErrN,PostLogN,PostErrN+1};
+				 (_, Counters) ->
+				      Counters
+			      end, {pre,0,0,0,0}, Ts),
+	      [_|Counters] = tuple_to_list(PrePostIOEntries),
+	      ct:log("Entries in the Pre/Post Test IO Log: ~p", [Counters]),
+	      case [C || C <- Counters, C < 2] of
+		  [] ->
+		      ok;
+		  _ ->
+		      exit("Not enough entries in the Pre/Post Test IO Log!")
+	      end
+      end, PrePostIoFiles), 
+
+    UnexpIoFiles =
+	[filelib:wildcard(
+	   filename:join(LogDir,
+			 "*dummy_SUITE.logs/run.*/"
+			 "unexpected_io.log.html")) || LogDir <- LogDirs],
+    lists:foreach(
+      fun(UnexpIoFile) ->
+	      ct:log("Reading Unexpected IO Log file: ~ts", [UnexpIoFile]),
+	      {ok,Bin} = file:read_file(UnexpIoFile),
+	      Ts = string:tokens(binary_to_list(Bin),[$\n]),
+	      UnexpIOEntries =
+		  lists:foldl(fun([$L,$o,$g,$g,$e,$r|_], [LogN,ErrN]) ->
+				      [LogN+1,ErrN];
+				 ([$=,$E,$R,$R,$O,$R|_], [LogN,ErrN]) ->
+				      [LogN,ErrN+1];
+				 (_, Counters) -> Counters
+			      end, [0,0], Ts),
+	      ct:log("Entries in the Unexpected IO Log: ~p", [UnexpIOEntries]),
+	      case [N || N <- UnexpIOEntries, N < 2] of
+		  [] ->
+		      ok;
+		  _ ->
+		      exit("Not enough entries in the Unexpected IO Log!")
+	      end
+      end, UnexpIoFiles),
+    ok.
 
 %%%-----------------------------------------------------------------
 %%% HELP FUNCTIONS
@@ -110,5 +208,45 @@ reformat(Events, EH) ->
 %%% TEST EVENTS
 %%%-----------------------------------------------------------------
 
-events_to_check(_Test) ->
-    [].
+events_to_check(pre_post_io) ->
+    [
+     {?eh,start_logging,{'DEF','RUNDIR'}},
+     {?eh,test_start,{'DEF',{'START_TIME','LOGDIR'}}},
+     {?eh,start_info,{1,1,7}},
+     {?eh,tc_start,{dummy_SUITE,init_per_suite}},
+     {?eh,tc_done,{dummy_SUITE,init_per_suite,ok}},
+     {parallel,
+      [{?eh,tc_start,{dummy_SUITE,{init_per_group,g1,[parallel]}}},
+       {?eh,tc_done,
+	{dummy_SUITE,{init_per_group,g1,[parallel]},ok}},
+       {?eh,tc_start,{dummy_SUITE,tc1}},
+       {?eh,tc_start,{dummy_SUITE,tc2}},
+       {?eh,tc_start,{dummy_SUITE,tc3}},
+       {?eh,tc_done,{dummy_SUITE,tc2,ok}},
+       {?eh,tc_done,{dummy_SUITE,tc1,ok}},
+       {?eh,tc_done,{dummy_SUITE,tc3,ok}},
+       {?eh,test_stats,{1,0,{0,0}}},
+       {?eh,test_stats,{2,0,{0,0}}},
+       {?eh,test_stats,{3,0,{0,0}}},
+       {?eh,tc_start,{dummy_SUITE,{end_per_group,g1,[parallel]}}},
+       {?eh,tc_done,{dummy_SUITE,{end_per_group,g1,[parallel]},ok}}]},
+     {?eh,tc_start,{dummy_SUITE,tc1}},
+     {?eh,tc_done,{dummy_SUITE,tc1,ok}},
+     {?eh,test_stats,{4,0,{0,0}}},
+     {?eh,tc_start,{dummy_SUITE,tc2}},
+     {?eh,tc_done,{dummy_SUITE,tc2,ok}},
+     {?eh,test_stats,{5,0,{0,0}}},
+     [{?eh,tc_start,{dummy_SUITE,{init_per_group,g2,[]}}},
+      {?eh,tc_done,{dummy_SUITE,{init_per_group,g2,[]},ok}},
+      {?eh,tc_start,{dummy_SUITE,tc4}},
+      {?eh,tc_done,{dummy_SUITE,tc4,ok}},
+      {?eh,test_stats,{6,0,{0,0}}},
+      {?eh,tc_start,{dummy_SUITE,tc5}},
+      {?eh,tc_done,{dummy_SUITE,tc5,ok}},
+      {?eh,test_stats,{7,0,{0,0}}},
+      {?eh,tc_start,{dummy_SUITE,{end_per_group,g2,[]}}},
+      {?eh,tc_done,{dummy_SUITE,{end_per_group,g2,[]},ok}}],
+     {?eh,tc_start,{dummy_SUITE,end_per_suite}},
+     {?eh,tc_done,{dummy_SUITE,end_per_suite,ok}},
+     {?eh,test_done,{'DEF','STOP_TIME'}},
+     {?eh,stop_logging,[]}].
diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
index 89f1734491..a9ea7b14dd 100644
--- a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
@@ -32,12 +32,19 @@ proceed() ->
 %% Hook functions
 %%--------------------------------------------------------------------
 init(_Id, _Opts) ->
+    case lists:keyfind(sasl, 1, application:which_applications()) of
+	false ->
+	    exit(sasl_not_started);
+	_Else ->
+	    ok
+    end,
     WhoAmI = self(),
     DispPid = spawn_link(fun() -> dispatcher(WhoAmI) end),
     register(?MODULE, DispPid),
     io:format(user,
-	      "~n~n+++ Startup finished, call ~w:proceed() to run tests!~n~n",
-	      [?MODULE]),
+	      "~n~n+++ Startup of ~w on ~p finished, "
+	      "call ~w:proceed() to run tests...~n",
+	      [?MODULE,node(),?MODULE]),
     start_external_logger(cth_logger),
     receive
 	{?MODULE,proceed} -> ok
@@ -49,7 +56,7 @@ init(_Id, _Opts) ->
 
 terminate(_State) ->
     io:format(user,
-	      "~n~n+++ Tests finished, call ~w:proceed() to shut down!~n~n",
+	      "~n~n+++ Tests finished, call ~w:proceed() to shut down...~n",
 	      [?MODULE]),
     receive
 	{?MODULE,proceed} -> ok
diff --git a/lib/common_test/test/ct_test_support.erl b/lib/common_test/test/ct_test_support.erl
index 5512b9c242..67e430f821 100644
--- a/lib/common_test/test/ct_test_support.erl
+++ b/lib/common_test/test/ct_test_support.erl
@@ -65,7 +65,6 @@ init_per_suite(Config, Level) ->
 	_ ->
 	    ok
     end,
-    
     start_slave(Config, Level).
 
 start_slave(Config, Level) ->
@@ -103,6 +102,14 @@ start_slave(NodeName, Config, Level) ->
 	    test_server:format(Level, "Dirs added to code path (on ~w):~n",
 			       [CTNode]),
 	    [io:format("~s~n", [D]) || D <- PathDirs],
+	    
+	    case proplists:get_value(start_sasl, Config) of
+		true ->
+		    rpc:call(CTNode, application, start, [sasl]),
+		    test_server:format(Level, "SASL started on ~w~n", [CTNode]);
+		_ ->
+		    ok
+	    end,
 
 	    TraceFile = filename:join(DataDir, "ct.trace"),
 	    case file:read_file_info(TraceFile) of
-- 
cgit v1.2.3