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

5 files changed, 508 insertions, 2 deletions

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..84341a0b99
--- /dev/null
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl
@@ -0,0 +1,252 @@
+%%
+%% %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]},
+				    {start_sasl,true} | 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),
+    
+    %%!--------------------------------------------------------------------
+    %%! 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),
+    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),
+    
+    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
+%%%-----------------------------------------------------------------
+
+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(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
new file mode 100644
index 0000000000..a9ea7b14dd
--- /dev/null
+++ b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl
@@ -0,0 +1,104 @@
+%%
+%% %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) ->
+    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 of ~w on ~p finished, "
+	      "call ~w:proceed() to run tests...~n",
+	      [?MODULE,node(),?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",
+	      [?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..67e430f821 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").
 
@@ -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
@@ -378,6 +385,16 @@ wait_for_ct_stop(Retries, 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
 
 handle_event(EH, Event) ->