Merge remote branch 'origin/peppe/common_test/tc_print_deadlock'

* origin/peppe/common_test/tc_print_deadlock:
  Fix problems with verbosity test suite
  Solve problem with IO deadlock in ct_util_server
  Implement test case that triggers known deadlock bug

OTP-10826

7 files changed, 236 insertions, 15 deletions

diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl
index 5924930072..be52be6bf3 100644
--- a/lib/common_test/src/ct_logs.erl
+++ b/lib/common_test/src/ct_logs.erl
@@ -397,9 +397,9 @@ tc_print(Category,Format,Args) ->
 %%% <p>This function is called by <code>ct</code> when printing
 %%% stuff from a testcase on the user console.</p>
 tc_print(Category,Importance,Format,Args) ->
-    VLvl = case ct_util:get_testdata({verbosity,Category}) of
+    VLvl = case ct_util:get_verbosity(Category) of
 	       undefined -> 
-		   ct_util:get_testdata({verbosity,'$unspecified'});
+		   ct_util:get_verbosity('$unspecified');
 	       {error,bad_invocation} ->
 		   ?MAX_VERBOSITY;
 	       Val ->
diff --git a/lib/common_test/src/ct_run.erl b/lib/common_test/src/ct_run.erl
index c0bdbb2a09..2d47a92b3e 100644
--- a/lib/common_test/src/ct_run.erl
+++ b/lib/common_test/src/ct_run.erl
@@ -2921,11 +2921,11 @@ opts2args(EnvStartOpts) ->
 			  [{event_handler_init,[atom_to_list(EH),ArgStr]}];
 		     ({event_handler,{EHs,Arg}}) when is_list(EHs) ->
 			  ArgStr = lists:flatten(io_lib:format("~p", [Arg])),
-			  Strs = lists:map(fun(EH) ->
-						   [atom_to_list(EH),
-						    ArgStr,"and"]
-					   end, EHs),
-			  [_LastAnd|StrsR] = lists:reverse(lists:flatten(Strs)),
+			  Strs = lists:flatmap(fun(EH) ->
+						       [atom_to_list(EH),
+							ArgStr,"and"]
+					       end, EHs),
+			  [_LastAnd | StrsR] = lists:reverse(Strs),
 			  [{event_handler_init,lists:reverse(StrsR)}];
 		     ({logopts,LOs}) when is_list(LOs) ->
 			  [{logopts,[atom_to_list(LO) || LO <- LOs]}];
diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl
index 0f2b2081d9..2e7e731595 100644
--- a/lib/common_test/src/ct_util.erl
+++ b/lib/common_test/src/ct_util.erl
@@ -39,7 +39,8 @@
 	 delete_suite_data/0, delete_suite_data/1, match_delete_suite_data/1,
 	 delete_testdata/0, delete_testdata/1,
 	 set_testdata/1, get_testdata/1, get_testdata/2,
-	 set_testdata_async/1, update_testdata/2, update_testdata/3]).
+	 set_testdata_async/1, update_testdata/2, update_testdata/3,
+	 set_verbosity/1, get_verbosity/1]).
 
 -export([override_silence_all_connections/0, override_silence_connections/1, 
 	 get_overridden_silenced_connections/0, 
@@ -128,6 +129,10 @@ do_start(Parent, Mode, LogDir, Verbosity) ->
     create_table(?conn_table,#conn.handle),
     create_table(?board_table,2),
     create_table(?suite_table,#suite_data.key),
+
+    create_table(?verbosity_table,1),
+    [ets:insert(?verbosity_table,{Cat,Lvl}) || {Cat,Lvl} <- Verbosity],
+
     {ok,StartDir} = file:get_cwd(),
     case file:set_cwd(LogDir) of
 	ok -> ok;
@@ -202,7 +207,7 @@ do_start(Parent, Mode, LogDir, Verbosity) ->
 	    self() ! {{stop,{self(),{user_error,CTHReason}}},
 		      {Parent,make_ref()}}
     end,
-    loop(Mode, [{{verbosity,Cat},Lvl} || {Cat,Lvl} <- Verbosity], StartDir).
+    loop(Mode, [], StartDir).
 
 create_table(TableName,KeyPos) ->
     create_table(TableName,set,KeyPos).
@@ -278,6 +283,19 @@ reset_cwd() ->
 get_start_dir() ->
     call(get_start_dir).
 
+%% handle verbosity outside ct_util_server (let the client read
+%% the verbosity table) to avoid possible deadlock situations
+set_verbosity(Elem = {_Category,_Level}) ->
+    ets:insert(?verbosity_table, Elem),
+    ok.
+get_verbosity(Category) ->
+    case ets:lookup(?verbosity_table, Category) of
+	[{Category,Level}] -> 
+	    Level;
+	_ ->
+	    undefined
+    end.
+
 loop(Mode,TestData,StartDir) ->
     receive 
 	{update_last_run_index,From} ->
@@ -377,6 +395,7 @@ loop(Mode,TestData,StartDir) ->
 	    ets:delete(?conn_table),
 	    ets:delete(?board_table),
 	    ets:delete(?suite_table),
+	    ets:delete(?verbosity_table),
 	    ct_logs:close(Info, StartDir),
 	    ct_event:stop(),
 	    ct_config:stop(),
diff --git a/lib/common_test/src/ct_util.hrl b/lib/common_test/src/ct_util.hrl
index c9c6514fa4..7c2e31f40c 100644
--- a/lib/common_test/src/ct_util.hrl
+++ b/lib/common_test/src/ct_util.hrl
@@ -21,6 +21,7 @@
 -define(conn_table,ct_connections).
 -define(board_table,ct_boards).
 -define(suite_table,ct_suite_data).
+-define(verbosity_table,ct_verbosity_table).
 
 -record(conn, {handle,
 	       targetref,
diff --git a/lib/common_test/test/ct_test_support.erl b/lib/common_test/test/ct_test_support.erl
index 7c33fd404d..5e109e98e9 100644
--- a/lib/common_test/test/ct_test_support.erl
+++ b/lib/common_test/test/ct_test_support.erl
@@ -312,8 +312,10 @@ wait_for_ct_stop(Retries, CTNode) ->
 	undefined ->
 	    true;
 	Pid ->
+	    Info = (catch process_info(Pid)),
 	    test_server:format(0, "Waiting for CT (~p) to finish (~p)...", 
 			       [Pid,Retries]),
+	    test_server:format(0, "Process info for ~p:~n~p", [Info]), 
 	    timer:sleep(5000),
 	    wait_for_ct_stop(Retries-1, CTNode)
     end.
@@ -328,12 +330,17 @@ handle_event(EH, Event) ->
     
 start_event_receiver(Config) ->
     CTNode = proplists:get_value(ct_node, Config),
-    spawn_link(CTNode, fun() -> er() end).
+    Level = proplists:get_value(trace_level, Config),
+    ER = spawn_link(CTNode, fun() -> er() end),
+    test_server:format(Level, "~nEvent receiver ~w started!~n", [ER]),
+    ER.
 
 get_events(_, Config) ->
     CTNode = proplists:get_value(ct_node, Config),
+    Level = proplists:get_value(trace_level, Config),
     {event_receiver,CTNode} ! {self(),get_events},
     Events = receive {event_receiver,Evs} -> Evs end,
+    test_server:format(Level, "Stopping event receiver!~n", []),
     {event_receiver,CTNode} ! stop,
     Events.
 
diff --git a/lib/common_test/test/ct_verbosity_SUITE.erl b/lib/common_test/test/ct_verbosity_SUITE.erl
index 349319de94..198d4c44b5 100644
--- a/lib/common_test/test/ct_verbosity_SUITE.erl
+++ b/lib/common_test/test/ct_verbosity_SUITE.erl
@@ -44,8 +44,11 @@
 %% there will be clashes with logging processes etc).
 %%--------------------------------------------------------------------
 init_per_suite(Config) ->
-    Config1 = ct_test_support:init_per_suite(Config),
-    Config1.
+    DataDir = ?config(data_dir, Config),
+    EvH = filename:join(DataDir,"simple_evh.erl"),
+    ct:pal("Compiling ~s: ~p", [EvH,compile:file(EvH,[{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).
@@ -56,7 +59,8 @@ init_per_testcase(TestCase, Config) ->
 end_per_testcase(TestCase, Config) ->
     ct_test_support:end_per_testcase(TestCase, Config).
 
-suite() -> [{ct_hooks,[ts_install_cth]}].
+suite() -> [{timetrap,{seconds,30}},
+	    {ct_hooks,[ts_install_cth]}].
 
 all() -> 
     [
@@ -67,7 +71,8 @@ all() ->
      change_default,
      combine_categories,
      testspec_only,
-     merge_with_testspec
+     merge_with_testspec,
+     possible_deadlock
     ].
 
 %%--------------------------------------------------------------------
@@ -173,6 +178,17 @@ merge_with_testspec(Config) ->
     ok = execute(TC, Opts, ERPid, Config).
 
 %%%-----------------------------------------------------------------
+%%% 
+possible_deadlock(Config) ->
+    TC = possible_deadlock,
+    DataDir = ?config(data_dir, Config),
+    Suite = filename:join(DataDir, "io_test_SUITE"),
+    {Opts,ERPid} = setup([{suite,Suite},{label,TC},
+			  {event_handler,[simple_evh]}], Config),
+    ok = execute(TC, Opts, ERPid, Config).
+    
+
+%%%-----------------------------------------------------------------
 %%% HELP FUNCTIONS
 %%%-----------------------------------------------------------------
 
@@ -180,7 +196,14 @@ 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],
+    Opts =
+	case proplists:get_value(event_handler, Test) of
+	    undefined ->
+		Opts0 ++ [{event_handler,{?eh,EvHArgs}} | Test];
+	    EvHs ->
+		Opts0 ++ [{event_handler,{[?eh|EvHs],EvHArgs}} |
+			  proplists:delete(event_handler, Test)]
+	end,
     ERPid = ct_test_support:start_event_receiver(Config),
     {Opts,ERPid}.
 
diff --git a/lib/common_test/test/ct_verbosity_SUITE_data/simple_evh.erl b/lib/common_test/test/ct_verbosity_SUITE_data/simple_evh.erl
new file mode 100644
index 0000000000..b677e601fb
--- /dev/null
+++ b/lib/common_test/test/ct_verbosity_SUITE_data/simple_evh.erl
@@ -0,0 +1,171 @@
+%%
+%% %CopyrightBegin%
+%% 
+%% Copyright Ericsson AB 2006-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%
+%%
+
+%%% @doc Common Test Framework Event Handler
+%%%
+%%% <p>This module implements an event handler that CT uses to
+%%% handle status and progress notifications during test runs.
+%%% The notifications are handled locally (per node) and passed
+%%% on to ct_master when CT runs in distributed mode. This
+%%% module may be used as a template for other event handlers
+%%% that can be plugged in to handle local logging and reporting.</p>
+-module(simple_evh).
+
+-behaviour(gen_event).
+
+%% gen_event callbacks
+-export([init/1, handle_event/2, handle_call/2, 
+	 handle_info/2, terminate/2, code_change/3]).
+
+-include_lib("common_test/include/ct_event.hrl").
+-include_lib("common_test/src/ct_util.hrl").
+
+%%====================================================================
+%% gen_event callbacks
+%%====================================================================
+%%--------------------------------------------------------------------
+%% Function: init(Args) -> {ok, State}
+%% Description: Whenever a new event handler is added to an event manager,
+%% this function is called to initialize the event handler.
+%%--------------------------------------------------------------------
+init(_) ->
+    io:format("Event handler ~w started!~n", [?MODULE]),
+    {ok,[]}.
+
+%%--------------------------------------------------------------------
+%% Function:  
+%% handle_event(Event, State) -> {ok, State} |
+%%                               {swap_handler, Args1, State1, Mod2, Args2} |
+%%                               remove_handler
+%% Description:Whenever an event manager receives an event sent using
+%% gen_event:notify/2 or gen_event:sync_notify/2, this function is called for
+%% each installed event handler to handle the event. 
+%%--------------------------------------------------------------------
+handle_event(Event = #event{name = test_stats},State) ->
+    %% this could cause a deadlock
+    ct:pal("~p: ~p~n", [Event#event.name,Event#event.data]),
+    {ok,State};
+handle_event(_Event,State) ->
+    {ok,State}.
+
+%%============================== EVENTS ==============================
+%%
+%% Name = test_start
+%% Data = {StartTime,LogDir}
+%%
+%% Name = start_info
+%% Data = {Tests,Suites,Cases}
+%% Tests = Suites = Cases = integer()
+%%
+%% Name = test_done
+%% Data = EndTime
+%%
+%% Name = start_make
+%% Data = Dir
+%%
+%% Name = finished_make
+%% Data = Dir
+%%
+%% Name = tc_start
+%% Data = {Suite,CaseOrGroup}
+%% CaseOrGroup = atom() | {Conf,GroupName,GroupProperties}
+%% Conf = init_per_group | end_per_group
+%% GroupName = atom()
+%% GroupProperties = list()
+%%
+%% Name = tc_done
+%% Data = {Suite,CaseOrGroup,Result}
+%% CaseOrGroup = atom() | {Conf,GroupName,GroupProperties}
+%% Conf = init_per_group | end_per_group
+%% GroupName = atom()
+%% GroupProperties = list()
+%% Result = ok | {skipped,Reason} | {failed,Reason} 
+%%
+%% Name = tc_user_skip
+%% Data = {Suite,Case,Comment}
+%% Comment = string()
+%%
+%% Name = tc_auto_skip
+%% Data = {Suite,Case,Comment}
+%% Comment = string()
+%%
+%% Name = test_stats
+%% Data = {Ok,Failed,Skipped}
+%% Ok = Failed = integer()
+%% Skipped = {UserSkipped,AutoSkipped}
+%% UserSkipped = AutoSkipped = integer()
+%%
+%% Name = start_logging
+%% Data = CtRunDir
+%%
+%% Name = stop_logging
+%% Data = []
+%%
+%% Name = start_write_file
+%% Data = FullNameFile
+%%
+%% Name = finished_write_file
+%% Data = FullNameFile
+%%
+%% Name = 
+%% Data = 
+%%
+
+%%--------------------------------------------------------------------
+%% Function: 
+%% handle_call(Request, State) -> {ok, Reply, State} |
+%%                                {swap_handler, Reply, Args1, State1, 
+%%                                  Mod2, Args2} |
+%%                                {remove_handler, Reply}
+%% Description: Whenever an event manager receives a request sent using
+%% gen_event:call/3,4, this function is called for the specified event 
+%% handler to handle the request.
+%%--------------------------------------------------------------------
+handle_call(_Req, State) ->
+    Reply = ok,
+    {ok, Reply, State}.
+
+%%--------------------------------------------------------------------
+%% Function: 
+%% handle_info(Info, State) -> {ok, State} |
+%%                             {swap_handler, Args1, State1, Mod2, Args2} |
+%%                              remove_handler
+%% Description: This function is called for each installed event handler when
+%% an event manager receives any other message than an event or a synchronous
+%% request (or a system message).
+%%--------------------------------------------------------------------
+handle_info(_Info, State) ->
+    {ok, State}.
+
+%%--------------------------------------------------------------------
+%% Function: terminate(Reason, State) -> void()
+%% Description:Whenever an event handler is deleted from an event manager,
+%% this function is called. It should be the opposite of Module:init/1 and 
+%% do any necessary cleaning up. 
+%%--------------------------------------------------------------------
+terminate(_Reason, _State) ->
+    ok.
+
+%%--------------------------------------------------------------------
+%% Function: code_change(OldVsn, State, Extra) -> {ok, NewState} 
+%% Description: Convert process state when code is changed
+%%--------------------------------------------------------------------
+code_change(_OldVsn, State, _Extra) ->
+    {ok, State}.
+