[snmp|agent|test] Timestamps and test manager

Added common (formated) timestamp function(s). Made use of
these in the verbosity module (for debug printouts) and in
the test suite(s).

I also *think* I found the cause for some if the test case
failures (timeouts).
For v3 (agent) test cases the test manager makes use of parts
of the agent code: snmp_framework_mib and snmp_user_based_sm_mib.
And since they store their data in snmpa_local_db, that also
needs to be running.
And this was the problem (I think). On some (slow) machines,
the snmpa_local_db process from the *previous* test case
might still be running when the we tried to start it. That meant
that no new snmpa_local_db was started. Instead the old one,
still running but terminating, was retain. For a while. Until
it actually finally stopped. So the next operation towards
snmpa_local_db, insert, simply hanged until the process
terminated.
This in combination with the fact that the packet server process,
which was started using proc_lib, previously called init_ack
before this init was actually done, could actually start and then
at a much later time hang because some operation timed out
(the packet server was hanging).

Yuckety yuck-yuck.

2 files changed, 71 insertions, 15 deletions

diff --git a/lib/snmp/test/snmp_test_lib.erl b/lib/snmp/test/snmp_test_lib.erl
index 4973630ea2..33f7b89974 100644
--- a/lib/snmp/test/snmp_test_lib.erl
+++ b/lib/snmp/test/snmp_test_lib.erl
@@ -607,7 +607,8 @@ p(F, A) when is_list(F) andalso is_list(A) ->
 
 %% This is just a bog standard printout, with a (formatted) timestamp
 %% prefix and a newline after.
-%% print1 prints to both standard_�o and to user. print2 just to standard_�o.
+%% print1 - prints to both standard_io and user.
+%% print2 - prints to just standard_io.
 
 print_format(F, A) ->
     FTS = snmp_test_lib:formated_timestamp(),
@@ -629,13 +630,5 @@ print(Prefix, Module, Line, Format, Args) ->
 	       Prefix, node(), self(), Module, Line|Args]).
 
 formated_timestamp() ->
-    format_timestamp(os:timestamp()).
-
-format_timestamp({_N1, _N2, N3} = Now) ->
-    {Date, Time}   = calendar:now_to_datetime(Now),
-    {YYYY,MM,DD}   = Date,
-    {Hour,Min,Sec} = Time,
-    FormatDate =
-        io_lib:format("~.4w:~.2.0w:~.2.0w-~.2.0w:~.2.0w:~.2.0w.~w",
-                      [YYYY, MM, DD, Hour, Min, Sec, round(N3/1000)]),
-    lists:flatten(FormatDate).
+    snmp_misc:formated_timestamp().
+
diff --git a/lib/snmp/test/snmp_test_mgr_misc.erl b/lib/snmp/test/snmp_test_mgr_misc.erl
index badbbad894..315e3ebd9e 100644
--- a/lib/snmp/test/snmp_test_mgr_misc.erl
+++ b/lib/snmp/test/snmp_test_mgr_misc.erl
@@ -604,6 +604,13 @@ init_usm('version-3', Dir) ->
     ?vlog("init_usm -> create (and init) fake \"agent\" table", []),
     ets:new(snmp_agent_table, [set, public, named_table]),
     ets:insert(snmp_agent_table, {agent_mib_storage, persistent}),
+    %% The local-db process may *still* be running (from a previous
+    %% test case), on the way down, but not yet dead.
+    %% Either way, before we start it, make sure its dead and *gone*!
+    %% How do we do that without getting hung up? Calling the stop
+    %% function, will not do since it uses Timeout=infinity.
+    ?vlog("init_usm -> ensure (old) fake local-db is dead", []),
+    ensure_local_db_dead(),
     ?vlog("init_usm -> try start fake local-db", []),
     case snmpa_local_db:start_link(normal, Dir,
                                    [{sname,     "MGR-LOCAL-DB"},
@@ -612,8 +619,12 @@ init_usm('version-3', Dir) ->
             ?vlog("started: ~p"
                   "~n      ~p", [Pid, process_info(Pid)]);
         {error, {already_started, Pid}} ->
+            LDBInfo = process_info(Pid),
             ?vlog("already started: ~p"
-                  "~n      ~p", [Pid, process_info(Pid)])
+                  "~n      ~p", [Pid, LDBInfo]),
+            ?FAIL({still_running, snmpa_local_db, LDBInfo});
+        {error, Reason} ->
+            ?FAIL({failed_starting, snmpa_local_db, Reason})
     end,
     NameDb = snmpa_agent:db(snmpEngineID),
     ?vlog("init_usm -> try set manager engine-id", []),
@@ -630,6 +641,60 @@ init_usm('version-3', Dir) ->
 init_usm(_Vsn, _Dir) ->
     ok.
 
+ensure_local_db_dead() ->
+    ensure_dead(whereis(snmpa_local_db), 2000).
+
+ensure_dead(Pid, Timeout) when is_pid(Pid) ->
+    MRef = erlang:monitor(process, Pid),
+    try
+        begin
+            ensure_dead_wait(Pid, MRef, Timeout),
+            ensure_dead_stop(Pid, MRef, Timeout),
+            ensure_dead_kill(Pid, MRef, Timeout),
+            exit(failed_stop_local_db)
+        end
+    catch
+        throw:ok ->
+            ok
+    end;
+ensure_dead(_, _) ->
+    ?vlog("ensure_dead -> already dead", []),
+    ok.
+
+ensure_dead_wait(Pid, MRef, Timeout) ->
+    receive
+        {'DOWN', MRef, process, Pid, _Info} ->
+            ?vlog("ensure_dead_wait -> died peacefully", []),
+            throw(ok)
+    after Timeout ->
+            ?vlog("ensure_dead_wait -> giving up", []),
+            ok
+    end.
+
+ensure_dead_stop(Pid, MRef, Timeout) ->
+    StopPid = spawn(fun() -> snmpa_local_db:stop() end),
+    receive
+        {'DOWN', MRef, process, Pid, _Info} ->
+            ?vlog("ensure_dead -> dead (stopped)", []),
+            throw(ok)
+    after Timeout ->
+            ?vlog("ensure_dead_stop -> giving up", []),
+            exit(StopPid, kill),
+            ok
+    end.
+
+ensure_dead_kill(Pid, MRef, Timeout) ->
+    exit(Pid, kill),
+    receive
+        {'DOWN', MRef, process, Pid, _Info} ->
+            ?vlog("ensure_dead -> dead (killed)", []),
+            throw(ok)
+    after Timeout ->
+            ?vlog("ensure_dead_kill -> giving up", []),
+            ok
+    end.
+
+
 
 display_incomming_message(M) ->
     display_message("Incomming",M).
@@ -831,6 +896,4 @@ d(_,_F,_A) ->
 
 print(F, A) ->
     ?PRINT2("MGR_PS " ++ F, A).
-    
-formated_timestamp() ->
-    snmp_test_lib:formated_timestamp().
+