Add test debug information and fix timing issues

5 files changed, 65 insertions, 22 deletions

diff --git a/lib/mnesia/test/mnesia_atomicity_test.erl b/lib/mnesia/test/mnesia_atomicity_test.erl
index 612c4ad368..cc32ba3826 100644
--- a/lib/mnesia/test/mnesia_atomicity_test.erl
+++ b/lib/mnesia/test/mnesia_atomicity_test.erl
@@ -700,11 +700,19 @@ start_restart_check(RestartOp, ReplicaNeed, Config) ->
 
     %% mnesia shall be killed at that node, where A is reading
     %% the information from
-    kill_where_to_read(TabName, N1, [N2, N3]),
+    Read = kill_where_to_read(TabName, N1, [N2, N3]),
 
     %% wait some time to let mnesia go down and spread those news around
     %% fun A shall be able to finish its job before being restarted
-    wait(500),
+    Wait = fun(Loop) ->
+		   wait(300),
+		   sys:get_status(mnesia_monitor),
+		   case lists:member(Read, mnesia_lib:val({current, db_nodes})) of
+		       true -> Loop(Loop);
+		       false -> ok
+		   end
+	   end,
+    Wait(Wait),
     A ! go_ahead,
 
     %% the sticky write doesnt work on remote nodes !!!
@@ -772,10 +780,12 @@ kill_where_to_read(TabName, N1, Nodes) ->
     Read = rpc:call(N1,mnesia,table_info, [TabName, where_to_read]),
     case lists:member(Read, Nodes) of
 	true ->
-	    mnesia_test_lib:kill_mnesia([Read]);
+	    mnesia_test_lib:kill_mnesia([Read]),
+	    Read;
 	false ->
 	    ?error("Fault while killing Mnesia: ~p~n", [Read]),
-	    mnesia_test_lib:kill_mnesia(Nodes)
+	    mnesia_test_lib:kill_mnesia(Nodes),
+	    Read
     end.
 
 sync_tid_release() ->
diff --git a/lib/mnesia/test/mnesia_consistency_test.erl b/lib/mnesia/test/mnesia_consistency_test.erl
index 9cc84de87b..2fe1bd34e6 100644
--- a/lib/mnesia/test/mnesia_consistency_test.erl
+++ b/lib/mnesia/test/mnesia_consistency_test.erl
@@ -665,10 +665,10 @@ consistency_after_restore(ReplicaType, Op, Config) ->
     [lists:foreach(fun(E) -> ok = mnesia:dirty_write({Tab, E, 2}) end, NList) ||
 	Tab <- Tabs],
     
-    Pids1 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carA, Op]), ok} || _ <- lists:seq(1, 5)],
-    Pids2 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carB, Op]), ok} || _ <- lists:seq(1, 5)],
-    Pids3 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carC, Op]), ok} || _ <- lists:seq(1, 5)],
-    Pids4 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carD, Op]), ok} || _ <- lists:seq(1, 5)],
+    Pids1 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carA, Op]), carA} || _ <- lists:seq(1, 5)],
+    Pids2 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carB, Op]), carB} || _ <- lists:seq(1, 5)],
+    Pids3 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carC, Op]), carC} || _ <- lists:seq(1, 5)],
+    Pids4 = [{'EXIT', spawn_link(?MODULE, change_tab, [self(), carD, Op]), carD} || _ <- lists:seq(1, 5)],
     
     AllPids = Pids1 ++ Pids2 ++ Pids3 ++ Pids4,
     
@@ -678,19 +678,38 @@ consistency_after_restore(ReplicaType, Op, Config) ->
 			  Else -> Else
 		      end
 	      end,
-    
+
     timer:sleep(timer:seconds(Delay)),  %% Let changers grab locks
     ?verbose("Doing restore~n", []),
     ?match(Tabs, Restore(File, [{default_op, Op}])),
 
-    timer:sleep(timer:seconds(Delay)),  %% Let em die
+    Collect = fun(Msg, Acc) ->
+		      receive Msg -> Acc
+		      after 10000 -> [Msg|Acc]
+		      end
+	      end,
 
-    ?match_multi_receive(AllPids),
+    Failed1 = lists:foldl(Collect, [], AllPids),
+    Failed  = lists:foldl(Collect, [], Failed1),
+
+    case Failed of
+	[] -> ok;
+	_  ->
+	    ?match([], Failed),
+	    io:format("TIME: ~p sec~n", [erlang:system_time(seconds) band 16#FF]),
+	    Dbg = fun({_, Pid, Tab}) ->
+			  io:format("Tab ~p: ~p~n",[Tab, process_info(Pid, current_stacktrace)]),
+			  [io:format(" ~p~n", [Rec]) || Rec <- mnesia:dirty_match_object({Tab, '_', '_'})]
+		  end,
+	    [Dbg(Msg) || Msg <- Failed],
+	    io:format(" Held: ~p~n", [mnesia_locker:get_held_locks()]),
+	    io:format("Queue: ~p~n", [mnesia_locker:get_lock_queue()])
+    end,
 
-    case ?match(ok, restore_verify_tabs(Tabs)) of 
-	{success, ok} -> 
+    case ?match(ok, restore_verify_tabs(Tabs)) of
+	{success, ok} ->
 	    file:delete(File);
-	_ -> 
+	_ ->
 	    {T, M, S} = time(),
 	    File2 = ?flat_format("consistency_error~w~w~w.BUP", [T, M, S]),
 	    file:rename(File, File2)
@@ -700,17 +719,20 @@ consistency_after_restore(ReplicaType, Op, Config) ->
 change_tab(Father, Tab, Test) ->
     Key = rand:uniform(20),
     Update = fun() ->
+		     Time = erlang:system_time(seconds) band 16#FF,
+		     case put(time, Time) of
+			 Time -> ok;
+			 _ -> io:format("~p ~p ~p sec~n", [self(), Tab, Time])
+		     end,
 		     case mnesia:read({Tab, Key}) of
-			 [{Tab, Key, 1}] -> 
-			     quit;
-			 [{Tab, Key, _N}] ->				       
-			     mnesia:write({Tab, Key, 3})
+			 [{Tab, Key, 1}] ->  quit;
+			 [{Tab, Key, _N}] -> mnesia:write({Tab, Key, 3})
 		     end
 	     end,
     case mnesia:transaction(Update) of
 	{atomic, quit} ->
-	    exit(ok);
-	{aborted, {no_exists, Tab}} when Test == recreate_tables ->%% I'll allow this 
+	    exit(Tab);
+	{aborted, {no_exists, Tab}} when Test == recreate_tables -> %% I'll allow this
 	    change_tab(Father, Tab, Test);
 	{atomic, ok} ->
 	    change_tab(Father, Tab, Test)
diff --git a/lib/mnesia/test/mnesia_evil_backup.erl b/lib/mnesia/test/mnesia_evil_backup.erl
index b71348f144..e745ec9b04 100644
--- a/lib/mnesia/test/mnesia_evil_backup.erl
+++ b/lib/mnesia/test/mnesia_evil_backup.erl
@@ -325,7 +325,7 @@ restore(Config, Op)  ->
     end,
     ?match(ok, file:delete(File1)),
     ?match(ok, file:delete(File2)),
-    ?match([], Check() -- Before),
+    ?match([], Check() -- (Before ++ [{ok, latest_log}, {ok, previous_log}])),
 
     ?verify_mnesia(Nodes, []).
 
diff --git a/lib/mnesia/test/mnesia_recovery_test.erl b/lib/mnesia/test/mnesia_recovery_test.erl
index 2388b595d0..130b87346f 100644
--- a/lib/mnesia/test/mnesia_recovery_test.erl
+++ b/lib/mnesia/test/mnesia_recovery_test.erl
@@ -504,12 +504,21 @@ with_checkpoint(Config, Type) when is_list(Config) ->
     ?match(ok, mnesia:deactivate_checkpoint(sune)),
     ?match([], check_chkp(Nodes)),
 
+    Wait = fun(Loop) ->
+		   timer:sleep(300),
+		   sys:get_status(mnesia_monitor),
+		   case lists:member(Kill, mnesia_lib:val({current, db_nodes})) of
+		       true -> Loop(Loop);
+		       false -> ok
+		   end
+	   end,
+
     case Kill of
 	Node1 -> 
 	    ignore;
 	Node2 ->
 	    mnesia_test_lib:kill_mnesia([Kill]),
-	    timer:sleep(500),  %% Just to help debugging
+	    Wait(Wait),
 	    ?match({ok, sune, _}, mnesia:activate_checkpoint([{name, sune}, 
 		{max, mnesia:system_info(tables)}, 
 		{ram_overrides_dump, true}])),
diff --git a/lib/mnesia/test/mt.erl b/lib/mnesia/test/mt.erl
index 793fb125e6..5a981bf539 100644
--- a/lib/mnesia/test/mt.erl
+++ b/lib/mnesia/test/mt.erl
@@ -80,6 +80,8 @@ resolve(Suite0) when is_atom(Suite0) ->
 	{Suite, Case} ->
 	    {Suite, is_group(Suite,Case)}
     end;
+resolve({Suite0, {group, Case}}) ->
+    resolve({Suite0, Case});
 resolve({Suite0, Case}) when is_atom(Suite0), is_atom(Case) ->
     case alias(Suite0) of
 	Suite when is_atom(Suite) ->