[snmp|agent|test] Test case info and cleanup

1) A test case failed due to the times retreived by
   get(snmpEngineTime) reported to large time diffs
   (this is basically a sanity check).
   Added some more info about time(s) to see if there
   are some "gaps" somewhere.
   The problem occurred on a slow Virtial Machine.

2) A previous (failing) test case failed to cleanup after
   itself (see above), which caused later test cases to fail.
   Specifically, the app top supervisor was not terminated,
   which caused the start agent function to fail (basically
   already_started).

2 files changed, 76 insertions, 40 deletions

diff --git a/lib/snmp/test/snmp_agent_test.erl b/lib/snmp/test/snmp_agent_test.erl
index c4365e6a96..71e3fa3b9a 100644
--- a/lib/snmp/test/snmp_agent_test.erl
+++ b/lib/snmp/test/snmp_agent_test.erl
@@ -5146,12 +5146,21 @@ snmp_framework_mib_3(Config) when is_list(Config) ->
 %% Req. SNMP-FRAMEWORK-MIB
 snmp_framework_mib_test() ->
     ?line ["agentEngine"] = get_req(1, [[snmpEngineID,0]]),
+    T1 = snmp_misc:now(ms),
     ?line [EngineTime] = get_req(2, [[snmpEngineTime,0]]),
+    T2 = snmp_misc:now(ms),
     ?SLEEP(5000),
+    T3 = snmp_misc:now(ms),
     ?line [EngineTime2] = get_req(3, [[snmpEngineTime,0]]),
-    ?DBG("snmp_framework_mib -> time(s): "
-	 "~n   EngineTime 1 = ~p"
-	 "~n   EngineTime 2 = ~p", [EngineTime, EngineTime2]),
+    T4 = snmp_misc:now(ms),
+    ?PRINT2("snmp_framework_mib -> time(s): "
+            "~n   EngineTime 1: ~p"
+            "~n      Time to acquire: ~w ms"
+            "~n   EngineTime 2: ~p"
+            "~n      Time to acquire: ~w ms"
+            "~n   => (5 sec sleep between get(snmpEngineTime))"
+            "~n      Total time to acquire: ~w ms",
+            [EngineTime, T2-T1, EngineTime2, T4-T3, T4-T1]),
     if 
 	(EngineTime+7) < EngineTime2 ->
 	    ?line ?FAIL({too_large_diff, EngineTime, EngineTime2});
@@ -5160,11 +5169,18 @@ snmp_framework_mib_test() ->
 	true -> 
 	    ok
     end,
+    T5 = snmp_misc:now(ms),
     ?line case get_req(4, [[snmpEngineBoots,0]]) of
 	      [Boots] when is_integer(Boots) -> 
+                  T6 = snmp_misc:now(ms),
+                  ?PRINT2("snmp_framework_mib -> "
+                          "~n   boots: ~p"
+                          "~n      Time to acquire: ~w ms", [Boots, T6-T5]),
 		  ok;
 	      Else -> 
-		  ?FAIL(Else)
+                  ?PRINT2("snmp_framework_mib -> failed get proper boots:"
+                          "~n   ~p", [Else]),
+		  ?FAIL({invalid_boots, Else})
 	  end,
     ok.
 
diff --git a/lib/snmp/test/snmp_agent_test_lib.erl b/lib/snmp/test/snmp_agent_test_lib.erl
index 70e2e5f235..6defdadb5a 100644
--- a/lib/snmp/test/snmp_agent_test_lib.erl
+++ b/lib/snmp/test/snmp_agent_test_lib.erl
@@ -472,20 +472,24 @@ start_agent(Config, Vsns, Opts) ->
 
     process_flag(trap_exit,true),
 
+    ?PRINT2("start_agent -> try start snmp app supervisor", []),
     {ok, AppSup} = snmp_app_sup:start_link(),
     unlink(AppSup),
     ?DBG("start_agent -> snmp app supervisor: ~p", [AppSup]),
 
-    ?DBG("start_agent -> start master agent",[]),
+    ?PRINT2("start_agent -> try start master agent",[]),
     ?line Sup = start_sup(Env), 
-
-    ?DBG("start_agent -> unlink from supervisor", []),
     ?line unlink(Sup),
+    ?DBG("start_agent -> snmp supervisor: ~p", [Sup]),
+
+    ?PRINT2("start_agent -> try (rpc) start sub agent on ~p", [SaNode]),
     ?line SaDir = ?config(sa_dir, Config),
-    ?DBG("start_agent -> (rpc) start sub on ~p", [SaNode]),
     ?line {ok, Sub} = start_sub_sup(SaNode, SaDir),
-    ?DBG("start_agent -> done",[]),
-    ?line [{snmp_sup, {Sup, self()}}, {snmp_sub, Sub} | Config].
+    ?DBG("start_agent -> done", []),
+
+    ?line [{snmp_app_sup, AppSup}, 
+           {snmp_sup,     {Sup, self()}}, 
+           {snmp_sub,     Sub} | Config].
 
 
 app_agent_env_init(Env0, Opts) ->
@@ -678,35 +682,52 @@ merge_agent_options([{Key, _Value} = Opt|Opts], Options) ->
 
 
 stop_agent(Config) when is_list(Config) ->
-    ?LOG("stop_agent -> entry with"
-	 "~n   Config: ~p",[Config]),
-
-    {Sup, Par} = ?config(snmp_sup, Config),
-    ?DBG("stop_agent -> attempt to stop (sup) ~p"
-	"~n   Sup: ~p"
-	"~n   Par: ~p",
-	[Sup, 
-	(catch process_info(Sup)),
-	(catch process_info(Par))]),
-    
-    _Info = agent_info(Sup),
-    ?DBG("stop_agent -> Agent info: "
-	 "~n   ~p", [_Info]),
-    
-    stop_sup(Sup, Par),
-
-    {Sup2, Par2} = ?config(snmp_sub, Config),
-    ?DBG("stop_agent -> attempt to stop (sub) ~p"
-	"~n   Sup2: ~p"
-	"~n   Par2: ~p",
-	[Sup2,
-	(catch process_info(Sup2)),
-	(catch process_info(Par2))]),
-    stop_sup(Sup2, Par2),
-
-    ?DBG("stop_agent -> done - now cleanup config", []),
-    C1 = lists:keydelete(snmp_sup, 1, Config),
-    lists:keydelete(snmp_sub, 1, C1).
+    ?PRINT2("stop_agent -> entry with"
+            "~n   Config: ~p",[Config]),
+
+
+    %% Stop the sub-agent (the agent supervisor)
+    {SubSup, SubPar} = ?config(snmp_sub, Config),
+    ?PRINT2("stop_agent -> attempt to stop sub agent (~p)"
+            "~n   Sub Sup info: "
+            "~n      ~p"
+            "~n   Sub Par info: "
+            "~n      ~p",
+            [SubSup,
+             (catch process_info(SubSup)),
+             (catch process_info(SubPar))]),
+    stop_sup(SubSup, SubPar),
+    Config2 = lists:keydelete(snmp_sub, 1, Config),
+
+
+    %% Stop the master-agent (the top agent supervisor)
+    {MasterSup, MasterPar} = ?config(snmp_sup, Config),
+    ?PRINT2("stop_agent -> attempt to stop master agent (~p)"
+            "~n   Master Sup: "
+            "~n      ~p"
+            "~n   Master Par: "
+            "~n      ~p"
+            "~n   Agent Info: "
+            "~n      ~p",
+            [MasterSup, 
+             (catch process_info(MasterSup)),
+             (catch process_info(MasterPar)),
+             agent_info(MasterSup)]),
+    stop_sup(MasterSup, MasterPar),
+    Config3 = lists:keydelete(snmp_sup, 1, Config2),
+
+
+    %% Stop the top supervisor (of the snmp app)
+    AppSup = ?config(snmp_app_sup, Config),
+    ?PRINT2("stop_agent -> attempt to app sup ~p"
+            "~n   App Sup: ~p",
+            [AppSup, 
+             (catch process_info(AppSup))]),
+    Config4 = lists:keydelete(snmp_app_sup, 1, Config3),
+
+
+    ?PRINT2("stop_agent -> done", []),
+    Config4.
 
 
 start_sup(Env) ->
@@ -736,7 +757,6 @@ stop_sup(Pid, _) ->
     ?LOG("stop_sup -> attempt to stop ~p", [Pid]),
     Ref = erlang:monitor(process, Pid),
     ?LOG("stop_sup -> Ref: ~p", [Ref]),
-    %% Pid ! {'EXIT', Parent, shutdown}, % usch
     exit(Pid, kill), 
     await_stopped(Pid, Ref).