Merge branch 'bmk/snmp/snmp4213_integration' into maint-r14

* bmk/snmp/snmp4213_integration:
  Added make targets for building an snmp dialyzer plt.
  [compiler] Fix the --warnings/--W option parsing in the snmpc wrapper script. The short warning option was incorrectly '--w', instead of as documented '--W'. This has now been corrected. Tuncer Ayaz OTP-9718
  [compiler] Improved version info printout from the MIB compiler frontend escript. OTP-9618
  [agent] When sending an error message (reply) regarding snmpUnknownPDUHandlers, the agent used the wrong OID. OTP-9747
  Updated appup file and release notes. OTP-9745
  [agent] Version 4.20 introduced a change that broke trap sending from subagents. Due to a bug in the test code, this was not discovered, until that bug was fixed. OTP-9745
  Upped the version in prep of patch. OTP-9748
  Fixed expect function, which basically ignored detected errors. Also added more printouts to make it easier to follow the flow of the test. In the same spirit, changed the tags in some of the test cases so that it would be possible to distinguish one expect call form another (not always possible since some functions are used by several test cases). OTP-9748

2 files changed, 242 insertions, 137 deletions

diff --git a/lib/snmp/test/snmp_agent_test.erl b/lib/snmp/test/snmp_agent_test.erl
index 468280db02..c95346b5a6 100644
--- a/lib/snmp/test/snmp_agent_test.erl
+++ b/lib/snmp/test/snmp_agent_test.erl
@@ -92,7 +92,8 @@ all() ->
     Conf1 ++ Conf2.
 
 groups() -> 
-    [{all_tcs, [], cases()},
+    [
+     {all_tcs, [], cases()},
      {mib_storage, [],
       [
        {group, mib_storage_ets}, 
@@ -1321,7 +1322,7 @@ finish_v3(Config) when is_list(Config) ->
 
 
 mt_cases() -> 
-[multi_threaded, mt_trap].
+    [multi_threaded, mt_trap].
 
 init_mt(Config) when is_list(Config) ->
     SaNode = ?config(snmp_sa, Config),
@@ -1498,7 +1499,8 @@ mt_trap(Config) when is_list(Config) ->
     ?line load_master("TestTrapv2"),
     try_test(mt_trap_test, [MA]),
     ?line unload_master("TestTrapv2"),
-    ?line unload_master("Test1").
+    ?line unload_master("Test1"),
+    ok.
 
 v2_types(suite) -> [];
 v2_types(Config) when is_list(Config) ->
@@ -3134,8 +3136,9 @@ mt_trap_test(MA) ->
     ?DBG("mt_trap_test(01) -> issue testTrapv22 (standard trap)", []),
     snmpa:send_trap(MA, testTrapv22, "standard trap"),
     ?DBG("mt_trap_test(02) -> await v2trap", []),
-    ?line expect(1, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?system ++ [0,1]}]),
+    ?line expect(mt_trap_test_1, v2trap, 
+		 [{[sysUpTime, 0],   any},
+		  {[snmpTrapOID, 0], ?system ++ [0,1]}]),
 
     ?DBG("mt_trap_test(03) -> issue mtTrap (standard trap)", []),
     snmpa:send_trap(MA, mtTrap, "standard trap"),
@@ -3143,28 +3146,22 @@ mt_trap_test(MA) ->
     ?DBG("mt_trap_test(04) -> multi pid: ~p. Now request sysUpTime...", [Pid]),
     g([[sysUpTime,0]]),
 
-    %% Previously (before OTP-6784) this was done at 09 below 
-    %% when the test1:multiStr was actually executed by the 
-    %% worker-process, but as of 4.9.4, this is now executed
-    %% my the master_agent-process...
-    ?DBG("mt_trap_test(05) -> send continue to multi-pid", []),
-    Pid ! continue,
-
     ?DBG("mt_trap_test(06) -> await sysUpTime", []),
-    ?line expect(2, [{[sysUpTime,0], any}]),
+    ?line expect(mt_trap_test_2, [{[sysUpTime,0], any}]),
     ?DBG("mt_trap_test(07) -> issue testTrapv22 (standard trap)", []),
     snmpa:send_trap(MA, testTrapv22, "standard trap"),
     ?DBG("mt_trap_test(08) -> await v2trap", []),
-    ?line expect(3, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?system ++ [0,1]}]),
+    ?line expect(mt_trap_test_3, v2trap, 
+		 [{[sysUpTime, 0],   any}, 
+		  {[snmpTrapOID, 0], ?system ++ [0,1]}]),
 
-    %% ?DBG("mt_trap_test(09) -> send continue to multi-pid", []),
-    %% Pid ! continue,
+    ?DBG("mt_trap_test(09) -> send continue to multi-pid", []),
+    Pid ! continue,
 
     ?DBG("mt_trap_test(10) -> await v2trap", []),
-    ?line expect(4, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?testTrap ++ [2]},
-			     {[multiStr,0], "ok"}]),
+    ?line expect(mt_trap_test_4, v2trap, [{[sysUpTime, 0], any},
+					  {[snmpTrapOID, 0], ?testTrap ++ [2]},
+					  {[multiStr,0], "ok"}]),
     ?DBG("mt_trap_test(11) -> done", []),
     ok.
 
@@ -3563,53 +3560,82 @@ do_mul_set_err() ->
 %% Req. SA-MIB
 sa_mib() ->
     g([[sa, [2,0]]]),
-    ?line expect(1, [{[sa, [2,0]], 3}]),
+    ?line expect(sa_mib_1, [{[sa, [2,0]], 3}]),
     s([{[sa, [1,0]], s, "sa_test"}]),
-    ?line expect(2, [{[sa, [1,0]], "sa_test"}]).
+    ?line expect(sa_mib_2, [{[sa, [1,0]], "sa_test"}]),
+    ok.
 
 ma_trap1(MA) ->
     ok = snmpa:send_trap(MA, testTrap2, "standard trap"), 
-    ?line expect(1, trap, [system], 6, 1, [{[system, [4,0]],
-				    "{mbj,eklas}@erlang.ericsson.se"}]),
+    ?line expect(ma_trap1_1, 
+		 trap, [system], 6, 1, [{[system, [4,0]],
+					 "{mbj,eklas}@erlang.ericsson.se"}]),
     ok = snmpa:send_trap(MA, testTrap1, "standard trap"),
-    ?line expect(2, trap, [1,2,3] , 1, 0, [{[system, [4,0]],
-				      "{mbj,eklas}@erlang.ericsson.se"}]).
+    ?line expect(ma_trap1_2, 
+		 trap, [1,2,3] , 1, 0, [{[system, [4,0]],
+					 "{mbj,eklas}@erlang.ericsson.se"}]),
+    ok.
 
 ma_trap2(MA) ->
     snmpa:send_trap(MA,testTrap2,"standard trap",[{sysContact,"pelle"}]),
-    ?line expect(3, trap, [system], 6, 1, [{[system, [4,0]], "pelle"}]).
+    ?line expect(ma_trap2_3, 
+		 trap, [system], 6, 1, [{[system, [4,0]], "pelle"}]),
+    ok.
 
 ma_v2_2_v1_trap(MA) ->
     snmpa:send_trap(MA,testTrapv22,"standard trap",[{sysContact,"pelle"}]),
-    ?line expect(3, trap, [system], 6, 1, [{[system, [4,0]], "pelle"}]).    
+    ?line expect(ma_v2_2_v1_trap_3, 
+		 trap, [system], 6, 1, [{[system, [4,0]], "pelle"}]),
+    ok.    
 
 ma_v2_2_v1_trap2(MA) ->
     snmpa:send_trap(MA,linkUp,"standard trap",[{ifIndex, [1], 1},
 					      {ifAdminStatus, [1], 1},
 					      {ifOperStatus, [1], 2}]),
-    ?line expect(3, trap, [1,2,3], 3, 0, [{[ifIndex, 1], 1},
-					 {[ifAdminStatus, 1], 1},
-					 {[ifOperStatus, 1], 2}]).    
+    ?line expect(ma_v2_2_v1_trap2_3, 
+		 trap, [1,2,3], 3, 0, [{[ifIndex, 1], 1},
+				       {[ifAdminStatus, 1], 1},
+				       {[ifOperStatus, 1], 2}]),
+    ok.
 
 sa_trap1(SA) ->
-    snmpa:send_trap(SA, saTrap, "standard trap"),
-    ?line expect(4, trap, [ericsson], 6, 1, [{[system, [4,0]],
-				      "{mbj,eklas}@erlang.ericsson.se"},
-				     {[sa, [1,0]], "sa_test"}]).
+    %% io:format("sa_trap1 -> entry with"
+    %% 	      "~n   SA:       ~p"
+    %% 	      "~n   node(SA): ~p"
+    %% 	      "~n   self():   ~p"
+    %% 	      "~n   node():   ~p"
+    %% 	      "~n", [SA, node(SA), self(), node()]),
+    _VRes  = (catch snmpa:verbosity(SA, {subagents, trace})),
+    %% io:format("sa_trap1 -> SA verbosity set: "
+    %% 	      "~n   VRes: ~p"
+    %% 	      "~n", [VRes]),
+    _TSRes = (catch snmpa:send_trap(SA, saTrap, "standard trap")),
+    %% io:format("sa_trap1 -> SA trap send: "
+    %% 	      "~n   TSRes: ~p"
+    %% 	      "~n", [TSRes]),
+    ?line expect(sa_trap1_4, 
+		 trap, [ericsson], 6, 1, [{[system, [4,0]],
+					   "{mbj,eklas}@erlang.ericsson.se"},
+					  {[sa, [1,0]], "sa_test"}]),
+    snmpa:verbosity(SA, {subagents, silence}),
+    ok.
 
 sa_trap2(SA) ->
     snmpa:send_trap(SA, saTrap, "standard trap",[{sysContact,"pelle"}]),
-    ?line expect(5, trap, [ericsson], 6, 1, [{[system, [4,0]],
-				      "pelle"},
-				     {[sa, [1,0]], "sa_test"}]).
+    ?line expect(sa_trap2_5, 
+		 trap, [ericsson], 6, 1, [{[system, [4,0]], "pelle"},
+					  {[sa, [1,0]], "sa_test"}]),
+    ok.
 
 sa_trap3(SA) ->
     snmpa:send_trap(SA, saTrap2, "standard trap",
 			 [{intViewSubtree, [4], [1,2,3,4]}]),
-    ?line expect(6, trap, [ericsson], 6, 2, [{[system, [4,0]],
-				      "{mbj,eklas}@erlang.ericsson.se"},
-				     {[sa, [1,0]], "sa_test"},
-				     {[intViewSubtree,4],[1,2,3,4]}]).
+    ?line expect(sa_trap3_6, 
+		 trap, [ericsson], 6, 2, [{[system, [4,0]],
+					   "{mbj,eklas}@erlang.ericsson.se"},
+					  {[sa, [1,0]], "sa_test"},
+					  {[intViewSubtree,4],[1,2,3,4]}]),
+    ok.
 
 ma_v2_trap1(MA) ->
     ?DBG("ma_v2_traps -> entry with MA = ~p => "
@@ -4029,33 +4055,42 @@ ma_v1_2_v2_trap2(MA) ->
     
 
 sa_v1_2_v2_trap1(SA) ->
+    snmpa:verbosity(SA, {subagents, trace}),
     snmpa:send_trap(SA, saTrap, "standard trap"),
-    ?line expect(4, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?ericsson ++ [0, 1]},
-			     {[system, [4,0]],
-			      "{mbj,eklas}@erlang.ericsson.se"},
-			     {[sa, [1,0]], "sa_test"},
-			     {[snmpTrapEnterprise, 0], ?ericsson}]).
+    ?line expect(trap1_4, v2trap, [{[sysUpTime, 0], any},
+				   {[snmpTrapOID, 0], ?ericsson ++ [0, 1]},
+				   {[system, [4,0]],
+				    "{mbj,eklas}@erlang.ericsson.se"},
+				   {[sa, [1,0]], "sa_test"},
+				   {[snmpTrapEnterprise, 0], ?ericsson}]),
+    snmpa:verbosity(SA, {subagents, silence}),
+    ok.
 
 sa_v1_2_v2_trap2(SA) ->
+    snmpa:verbosity(SA, {subagents, trace}),
     snmpa:send_trap(SA, saTrap, "standard trap",[{sysContact,"pelle"}]),
-    ?line expect(4, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?ericsson ++ [0, 1]},
-			     {[system, [4,0]], "pelle"},
-			     {[sa, [1,0]], "sa_test"},
-			     {[snmpTrapEnterprise, 0], ?ericsson}]).
-			     
+    ?line expect(trap2_4, v2trap, [{[sysUpTime, 0], any},
+				   {[snmpTrapOID, 0], ?ericsson ++ [0, 1]},
+				   {[system, [4,0]], "pelle"},
+				   {[sa, [1,0]], "sa_test"},
+				   {[snmpTrapEnterprise, 0], ?ericsson}]),
+    snmpa:verbosity(SA, {subagents, silence}),
+    ok.
+
 
 sa_v1_2_v2_trap3(SA) ->
+    snmpa:verbosity(SA, {subagents, trace}),
     snmpa:send_trap(SA, saTrap2, "standard trap",
 			 [{intViewSubtree, [4], [1,2,3,4]}]),
-    ?line expect(4, v2trap, [{[sysUpTime, 0], any},
-			     {[snmpTrapOID, 0], ?ericsson ++ [0, 2]},
-			     {[system, [4,0]],
-			      "{mbj,eklas}@erlang.ericsson.se"},
-			     {[sa, [1,0]], "sa_test"},
-			     {[intViewSubtree,4],[1,2,3,4]},
-			     {[snmpTrapEnterprise, 0], ?ericsson}]).
+    ?line expect(trap3_4, v2trap, [{[sysUpTime, 0], any},
+				   {[snmpTrapOID, 0], ?ericsson ++ [0, 2]},
+				   {[system, [4,0]],
+				    "{mbj,eklas}@erlang.ericsson.se"},
+				   {[sa, [1,0]], "sa_test"},
+				   {[intViewSubtree,4],[1,2,3,4]},
+				   {[snmpTrapEnterprise, 0], ?ericsson}]),
+    snmpa:verbosity(SA, {subagents, silence}),
+    ok.
 			     
 
 %% Req. SA-MIB, OLD-SNMPEA-MIB
@@ -4195,9 +4230,9 @@ snmp_standard_mib(Config) when is_list(Config) ->
 
 %% Req. SNMP-STANDARD-MIB
 standard_mib_a() ->
-    ?line [OutPkts] = get_req(2, [[snmpOutPkts,0]]),
+    ?line [OutPkts]  = get_req(2, [[snmpOutPkts,0]]),
     ?line [OutPkts2] = get_req(3, [[snmpOutPkts,0]]),
-    ?line OutPkts2 = OutPkts + 1,
+    ?line OutPkts2   = OutPkts + 1,
     %% There are some more counters we could test here, but it's not that
     %% important, since they are removed from SNMPv2-MIB.
     ok.
@@ -4207,27 +4242,27 @@ std_mib_init() ->
     %% disable authentication failure traps.  (otherwise w'd get many of
     %% them - this is also a test to see that it works).
     s([{[snmpEnableAuthenTraps,0], 2}]),
-    ?line expect(1, [{[snmpEnableAuthenTraps, 0], 2}]).
+    ?line expect(std_mib_init_1, [{[snmpEnableAuthenTraps, 0], 2}]).
 
 %% Req. SNMP-STANDARD-MIB | SNMPv2-MIB
 std_mib_finish() ->
     %% enable again
     s([{[snmpEnableAuthenTraps,0], 1}]),
-    ?line expect(1, [{[snmpEnableAuthenTraps, 0], 1}]).
+    ?line expect(std_mib_finish_1, [{[snmpEnableAuthenTraps, 0], 1}]).
 
 %% Req. SNMP-STANDARD-MIB
 standard_mib_test_finish() ->
-    %% force a authenticationFailure
+    %% force a authenticationFailure (should result in a trap)
     std_mib_write(),
     %% check that we got a trap
-    ?line expect(2, trap, [1,2,3], 4, 0, []).
+    ?line expect(standard_mib_test_finish_2, trap, [1,2,3], 4, 0, []).
 
 %% Req. SNMP-STANDARD-MIB | SNMPv2-MIB
 std_mib_read() ->
     ?DBG("std_mib_read -> entry", []),
     g([[sysUpTime,0]]), % try a bad <something>; msg dropped, no reply
     ?DBG("std_mib_read -> await timeout (i.e. no reply)", []),
-    ?line expect(1, timeout). % make sure we don't get a trap!
+    ?line expect(std_mib_read_1, timeout). % make sure we don't get a trap!
 
 
 %% Req. SNMP-STANDARD-MIB | SNMPv2-MIB
@@ -4362,10 +4397,10 @@ std_mib_c({InBadCommunityNames, InBadCommunityUses, InASNErrs}) ->
 snmpv2_mib_a() ->
     ?line [SetSerial] = get_req(2, [[snmpSetSerialNo,0]]),
     s([{[snmpSetSerialNo,0], SetSerial}, {[sysLocation, 0], "val2"}]),
-    ?line expect(3, [{[snmpSetSerialNo,0], SetSerial},
-		     {[sysLocation, 0], "val2"}]),
+    ?line expect(snmpv2_mib_a_3, [{[snmpSetSerialNo,0], SetSerial},
+				  {[sysLocation, 0], "val2"}]),
     s([{[sysLocation, 0], "val3"}, {[snmpSetSerialNo,0], SetSerial}]),
-    ?line expect(4, inconsistentValue, 2,
+    ?line expect(snmpv2_mib_a_4, inconsistentValue, 2,
 		 [{[sysLocation, 0], "val3"},
 		  {[snmpSetSerialNo,0], SetSerial}]),
     ?line ["val2"] = get_req(5, [[sysLocation,0]]).
@@ -4688,46 +4723,46 @@ snmp_view_based_acm_mib() ->
 
 do_set(Row) ->
     s(Row),
-    expect(1, Row).
+    expect(do_set_1, Row).
     
 add_row(RowStatus) ->
     s([{RowStatus, ?createAndGo}]),
-    expect(1, [{RowStatus, ?createAndGo}]).
+    expect(add_row_1, [{RowStatus, ?createAndGo}]).
 
 del_row(RowStatus) ->
     s([{RowStatus, ?destroy}]),
-    expect(1, [{RowStatus, ?destroy}]).
+    expect(del_row_1, [{RowStatus, ?destroy}]).
     
     
 
 use_no_rights() ->
     g([[xDescr,0]]),
-    ?v1_2_3(expect(11, noSuchName, 1, any),
-	    expect(12, [{[xDescr,0], noSuchObject}]),
-	    expect(13, authorizationError, 1, any)),
+    ?v1_2_3(expect(use_no_rights_11, noSuchName, 1, any),
+	    expect(use_no_rights_12, [{[xDescr,0], noSuchObject}]),
+	    expect(use_no_rights_13, authorizationError, 1, any)),
     g([[xDescr2,0]]),
-    ?v1_2_3(expect(21, noSuchName, 1, any),
-	    expect(22, [{[xDescr2,0], noSuchObject}]),
-	    expect(23, authorizationError, 1, any)),
+    ?v1_2_3(expect(use_no_rights_21, noSuchName, 1, any),
+	    expect(use_no_rights_22, [{[xDescr2,0], noSuchObject}]),
+	    expect(use_no_rights_23, authorizationError, 1, any)),
     gn([[xDescr]]),
-    ?v1_2_3(expect(31, noSuchName, 1, any),
-	    expect(32, [{[xDescr], endOfMibView}]),
-	    expect(33, authorizationError, 1, any)),
+    ?v1_2_3(expect(use_no_rights_31, noSuchName, 1, any),
+	    expect(use_no_rights_32, [{[xDescr], endOfMibView}]),
+	    expect(use_no_rights_33, authorizationError, 1, any)),
     s([{[xDescr,0], "tryit"}]),
-    ?v1_2_3(expect(41, noSuchName, 1, any),
-	    expect(42, noAccess, 1, any),
-	    expect(43, authorizationError, 1, any)).
+    ?v1_2_3(expect(use_no_rights_41, noSuchName, 1, any),
+	    expect(use_no_rights_42, noAccess, 1, any),
+	    expect(use_no_rights_43, authorizationError, 1, any)).
 
 
 use_rights() ->
     g([[xDescr,0]]),
-    expect(1, [{[xDescr,0], any}]),
+    expect(use_rights_1, [{[xDescr,0], any}]),
     g([[xDescr2,0]]),
-    expect(2, [{[xDescr2,0], any}]),
+    expect(use_rights_2, [{[xDescr2,0], any}]),
     s([{[xDescr,0], "tryit"}]),
-    expect(3, noError, 0, any),
+    expect(use_rights_3, noError, 0, any),
     g([[xDescr,0]]),
-    expect(4, [{[xDescr,0], "tryit"}]).
+    expect(use_rights_4, [{[xDescr,0], "tryit"}]).
 
 mk_ln(X) ->
     [length(X) | X].
diff --git a/lib/snmp/test/snmp_agent_test_lib.erl b/lib/snmp/test/snmp_agent_test_lib.erl
index a18d9f3201..084b3ee8da 100644
--- a/lib/snmp/test/snmp_agent_test_lib.erl
+++ b/lib/snmp/test/snmp_agent_test_lib.erl
@@ -296,7 +296,12 @@ call(N,M,F,A) ->
 	    ?DBG("call -> done:"
 		 "~n   Ret: ~p"
 		 "~n   Zed: ~p", [Ret, Zed]),
-	    Ret
+	    case Ret of
+		{error, Reason} ->
+		    exit(Reason);
+		OK ->
+		    OK
+	    end
     end.
 
 wait(From, Env, M, F, A) ->
@@ -724,17 +729,13 @@ expect(Id, A, B, C, D, E) ->
     expect2(Id, Fun).
 
 expect2(Id, F) ->
-    io:format("~w:expect2 -> entry with"
-	      "~n   Id:   ~w"
-	      "~n", [?MODULE, Id]),
+    io:format("EXPECT for ~w~n", [Id]),
     case F() of
 	{error, Reason} ->
-	    {error, Id, Reason};
+	    io:format("EXPECT failed for ~w: ~n~p~n", [Id, Reason]),
+	    throw({error, {expect, Id, Reason}});
 	Else ->
-	    io:format("~w:expect2 -> "
-		      "~n   Id:   ~w"
-		      "~n   Else: ~p"
-		      "~n", [?MODULE, Id, Else]),
+	    io:format("EXPECT result for ~w: ~n~p~n", [Id, Else]),
 	    Else
     end.
 
@@ -769,21 +770,15 @@ do_expect(Expect) when is_atom(Expect) ->
 
 do_expect({any_pdu, To}) 
   when is_integer(To) orelse (To =:= infinity) ->
-    io:format("~w:do_expect(any_pdu) -> entry with"
-	      "~n   To:   ~w"
-	      "~n", [?MODULE, To]),
+    io:format("EXPECT any PDU~n", []),
     receive_pdu(To);
 
 do_expect({any_trap, To}) ->
-    io:format("~w:do_expect(any_trap) -> entry with"
-	      "~n   To:   ~w"
-	      "~n", [?MODULE, To]),
+    io:format("EXPECT any TRAP within ~w~n", [To]),
     receive_trap(To);
 
 do_expect({timeout, To}) ->
-    io:format("~w:do_expect(timeout) -> entry with"
-	      "~n   To:   ~w"
-	      "~n", [?MODULE, To]),
+    io:format("EXPECT nothing within ~w~n", [To]),
     receive
 	X ->
 	    {error, {unexpected, X}}
@@ -794,13 +789,16 @@ do_expect({timeout, To}) ->
 
 do_expect({Err, To}) 
   when is_atom(Err) andalso (is_integer(To) orelse (To =:= infinity)) ->
+    io:format("EXPECT error ~w within ~w~n", [Err, To]),
     do_expect({{error, Err}, To});
 
 do_expect({error, Err}) when is_atom(Err) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT error ~w~n", [Err]),
     do_expect2(Check, any, Err, any, any, get_timeout());
 do_expect({{error, Err}, To}) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT error ~w within ~w~n", [Err, To]),
     do_expect2(Check, any, Err, any, any, To);
 
 %% exp_varbinds() -> [exp_varbind()]
@@ -810,16 +808,25 @@ do_expect({{error, Err}, To}) ->
 %% ExpVBs         -> exp_varbinds() | {VbsCondition, exp_varbinds()}
 do_expect(ExpVBs) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT 'get-response'"
+	      "~n   with"
+	      "~n      Varbinds: ~p~n", [ExpVBs]),
     do_expect2(Check, 'get-response', noError, 0, ExpVBs, get_timeout()).
 
 
 do_expect(v2trap, ExpVBs) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT 'snmpv2-trap'"
+	      "~n   with"
+	      "~n      Varbinds: ~p~n", [ExpVBs]),
     do_expect2(Check, 'snmpv2-trap', noError, 0, ExpVBs, get_timeout());
 
 
 do_expect(report, ExpVBs) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT 'report'"
+	      "~n   with"
+	      "~n      Varbinds: ~p~n", [ExpVBs]),
     do_expect2(Check, 'report', noError, 0, ExpVBs, get_timeout());
 
 
@@ -827,16 +834,13 @@ do_expect(inform, ExpVBs) ->
     do_expect({inform, true}, ExpVBs);
 
 do_expect({inform, false}, ExpVBs) ->
-    io:format("~w:do_expect(inform, false) -> entry with"
-	      "~n   ExpVBs: ~p"
-	      "~n", [?MODULE, ExpVBs]),
     Check = fun(_, R) -> R end,
+    io:format("EXPECT 'inform-request' (false)"
+	      "~n   with"
+	      "~n      Varbinds: ~p~n", [ExpVBs]),
     do_expect2(Check, 'inform-request', noError, 0, ExpVBs, get_timeout());
 
 do_expect({inform, true}, ExpVBs) ->
-    io:format("~w:do_expect(inform, true) -> entry with"
-	      "~n   ExpVBs: ~p"
-	      "~n", [?MODULE, ExpVBs]),
     Check = 
 	fun(PDU, ok) ->
 		RespPDU = PDU#pdu{type         = 'get-response',
@@ -847,6 +851,9 @@ do_expect({inform, true}, ExpVBs) ->
 	   (_, Err) ->
 		Err
 	end,
+    io:format("EXPECT 'inform-request' (true)"
+	      "~n   with"
+	      "~n      Varbinds: ~p~n", [ExpVBs]),
     do_expect2(Check, 'inform-request', noError, 0, ExpVBs, get_timeout());
 
 do_expect({inform, {error, EStat, EIdx}}, ExpVBs) 
@@ -861,6 +868,11 @@ do_expect({inform, {error, EStat, EIdx}}, ExpVBs)
 	   (_, Err) ->
 		Err
 	end,
+    io:format("EXPECT 'inform-request' (error)"
+	      "~n   with"
+	      "~n      Error Status: ~p"
+	      "~n      Error Index:  ~p"
+	      "~n      Varbinds:     ~p~n", [EStat, EIdx, ExpVBs]),
     do_expect2(Check, 'inform-request', noError, 0, ExpVBs, get_timeout()).
 
 
@@ -871,6 +883,12 @@ do_expect(Err, Idx, ExpVBs, To)
   when is_atom(Err) andalso 
        (is_integer(Idx) orelse is_list(Idx) orelse (Idx == any)) ->
     Check = fun(_, R) -> R end,
+    io:format("EXPECT 'get-response'"
+	      "~n   with"
+	      "~n      Error:    ~p"
+	      "~n      Index:    ~p"
+	      "~n      Varbinds: ~p"
+	      "~n   within ~w~n", [Err, Idx, ExpVBs, To]),
     do_expect2(Check, 'get-response', Err, Idx, ExpVBs, To).
 
 
@@ -878,15 +896,13 @@ do_expect(Type, Enterp, Generic, Specific, ExpVBs) ->
     do_expect(Type, Enterp, Generic, Specific, ExpVBs, 3500).
 
 do_expect(trap, Enterp, Generic, Specific, ExpVBs, To) ->
-    io:format("~w:do_expect(trap) -> entry with"
-	      "~n   Enterp:   ~w"
-	      "~n   Generic:  ~w"
-	      "~n   Specific: ~w"
-	      "~n   ExpVBs:   ~w"
-	      "~n   To:       ~w"
-	      "~nwhen"
-	      "~n   Time:   ~w"
-	      "~n", [?MODULE, Enterp, Generic, Specific, ExpVBs, To, t()]),
+    io:format("EXPECT trap"
+	      "~n   with"
+	      "~n      Enterp:   ~w"
+	      "~n      Generic:  ~w"
+	      "~n      Specific: ~w"
+	      "~n      Varbinds: ~w"
+	      "~n   within ~w~n", [Enterp, Generic, Specific, ExpVBs, To]),
     PureE = purify_oid(Enterp),
     case receive_trap(To) of
 	#trappdu{enterprise    = PureE, 
@@ -916,49 +932,51 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
        (is_list(ExpVBs) orelse (ExpVBs =:= any)) andalso
        (is_integer(To) orelse (To =:= infinity)) ->
 
-    io:format("~w:do_expect2 -> entry with"
-	      "~n   Type:   ~w"
-	      "~n   Err:    ~w"
-	      "~n   Idx:    ~w"
-	      "~n   ExpVBs: ~w"
-	      "~n   To:     ~w"
-	      "~nwhen"
-	      "~n   Time:   ~w"
-	      "~n", [?MODULE, Type, Err, Idx, ExpVBs, To, t()]),
-
     case receive_pdu(To) of
 
 	#pdu{type         = Type, 
 	     error_status = Err,
 	     error_index  = Idx} when ExpVBs =:= any -> 
+	    io:format("EXPECT received expected pdu (1)~n", []),
 	    ok;
 
 	#pdu{type         = Type, 
 	     request_id   = ReqId, 
 	     error_status = Err2,
 	     error_index  = Idx} when ExpVBs =:= any -> 
+	    io:format("EXPECT received expected pdu with "
+		      "unexpected error status (2): "
+		      "~n   Error Status: ~p~n", [Err2]),
 	    {error, {unexpected_error_status, Err, Err2, ReqId}};
 
 	#pdu{error_status = Err} when (Type   =:= any) andalso 
 				      (Idx    =:= any) andalso 
 				      (ExpVBs =:= any) -> 
+	    io:format("EXPECT received expected pdu (3)~n", []),
 	    ok;
 
 	#pdu{request_id   = ReqId, 
 	     error_status = Err2} when (Type   =:= any) andalso 
 				       (Idx    =:= any) andalso 
 				       (ExpVBs =:= any) -> 
+	    io:format("EXPECT received expected pdu with "
+		      "unexpected error status (4): "
+		      "~n   Error Status: ~p~n", [Err2]),
 	    {error, {unexpected_error_status, Err, Err2, ReqId}};
 
 	#pdu{type         = Type, 
 	     error_status = Err} when (Idx =:= any) andalso 
 				      (ExpVBs =:= any) -> 
+	    io:format("EXPECT received expected pdu (5)~n", []),
 	    ok;
 
 	#pdu{type         = Type, 
 	     request_id   = ReqId, 
 	     error_status = Err2} when (Idx =:= any) andalso 
 				       (ExpVBs =:= any) -> 
+	    io:format("EXPECT received expected pdu with "
+		      "unexpected error status (6): "
+		      "~n   Error Status: ~p~n", [Err2]),
 	    {error, {unexpected_error_status, Err, Err2, ReqId}};
 
 	#pdu{type         = Type, 
@@ -967,8 +985,13 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     error_index  = EI} when is_list(Idx) andalso (ExpVBs =:= any) -> 
 	    case lists:member(EI, Idx) of
 		true ->
+		    io:format("EXPECT received expected pdu with "
+			      "expected error index (7)~n", []),
 		    ok;
 		false ->
+		    io:format("EXPECT received expected pdu with "
+			      "unexpected error index (8): "
+			      "~n   Error Index: ~p~n", [EI]),
 		    {error, {unexpected_error_index, EI, Idx, ReqId}}
 	    end;
 
@@ -978,8 +1001,15 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     error_index  = EI} when is_list(Idx) andalso (ExpVBs =:= any) -> 
 	    case lists:member(EI, Idx) of
 		true ->
+		    io:format("EXPECT received expected pdu with "
+			      "unexpected error status (9): "
+			      "~n   Error Status: ~p~n", [Err2]),
 		    {error, {unexpected_error_status, Err, Err2, ReqId}};
 		false ->
+		    io:format("EXPECT received expected pdu with "
+			      "unexpected error (10): "
+			      "~n   Error Status: ~p"
+			      "~n   Error index:  ~p~n", [Err2, EI]),
 		    {error, {unexpected_error, {Err, Idx}, {Err2, EI}, ReqId}}
 	    end;
 
@@ -987,6 +1017,12 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     request_id   = ReqId, 
 	     error_status = Err2, 
 	     error_index  = Idx2} when ExpVBs =:= any ->
+	    io:format("EXPECT received unexpected pdu with (11) "
+		      "~n   Type:         ~p"
+		      "~n   ReqId:        ~p"
+		      "~n   Errot status: ~p"
+		      "~n   Error index:  ~p"
+		      "~n", [Type2, ReqId, Err2, Idx2]),
 	    {error, 
 	     {unexpected_pdu, 
 	      {Type, Err, Idx}, {Type2, Err2, Idx2}, ReqId}};
@@ -995,11 +1031,26 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     error_status = Err, 
 	     error_index  = Idx,
 	     varbinds     = VBs} = PDU ->
+	    io:format("EXPECT received pdu (12): "
+		      "~n   [exp] Type:         ~p"
+		      "~n   [exp] Error Status: ~p"
+		      "~n   [exp] Error Index:  ~p"
+		      "~n   VBs:                ~p"
+		      "~nwhen"
+		      "~n   ExpVBs:             ~p"
+		      "~n", [Type, Err, Idx, VBs, ExpVBs]),
 	    Check(PDU, check_vbs(purify_oids(ExpVBs), VBs));
 
 	#pdu{type         = Type, 
 	     error_status = Err, 
 	     varbinds     = VBs} = PDU when Idx =:= any ->
+	    io:format("EXPECT received pdu (13): "
+		      "~n   [exp] Type:         ~p"
+		      "~n   [exp] Error Status: ~p"
+		      "~n   VBs:                ~p"
+		      "~nwhen"
+		      "~n   ExpVBs:             ~p"
+		      "~n", [Type, Err, VBs, ExpVBs]),
 	    Check(PDU, check_vbs(purify_oids(ExpVBs), VBs));
 
 	#pdu{type         = Type, 
@@ -1007,6 +1058,15 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     error_status = Err, 
 	     error_index  = EI,
 	     varbinds     = VBs} = PDU when is_list(Idx) ->
+	    io:format("EXPECT received pdu (14): "
+		      "~n   [exp] Type:         ~p"
+		      "~n   ReqId:              ~p"
+		      "~n   [exp] Error Status: ~p"
+		      "~n   [exp] Error Index:  ~p"
+		      "~n   VBs:                ~p"
+		      "~nwhen"
+		      "~n   ExpVBs:             ~p"
+		      "~n", [Type, ReqId, Err, EI, VBs, ExpVBs]),
 	    PureVBs = purify_oids(ExpVBs), 
 	    case lists:member(EI, Idx) of
 		true ->
@@ -1020,6 +1080,13 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	     error_status = Err2, 
 	     error_index  = Idx2,
 	     varbinds     = VBs2} ->
+	    io:format("EXPECT received unexpected pdu with (15) "
+		      "~n   Type:         ~p"
+		      "~n   ReqId:        ~p"
+		      "~n   Errot status: ~p"
+		      "~n   Error index:  ~p"
+		      "~n   Varbinds:     ~p"
+		      "~n", [Type2, ReqId, Err2, Idx2, VBs2]),
 	    {error, 
 	     {unexpected_pdu, 
 	      {Type,  Err,  Idx, purify_oids(ExpVBs)}, 
@@ -1027,6 +1094,9 @@ do_expect2(Check, Type, Err, Idx, ExpVBs, To)
 	      ReqId}};
 	
 	Error ->
+	    io:format("EXPECT received error (16):  "
+		      "~n   Error: ~p"
+		      "~n", [Error]),
 	    Error
     end.
 
@@ -1466,7 +1536,7 @@ rpc(Node, F, A) ->
 %% 
 %% 
 %% t() ->
-%%     {A,B,C} = erlang:now(),
+%%     {A,B,C} = os:timestamp(),
 %%     A*1000000000+B*1000+(C div 1000).
 %% 
 %% 
@@ -1478,6 +1548,6 @@ rpc(Node, F, A) ->
     
 
 %% Time in milli seconds
-t() ->
-    {A,B,C} = erlang:now(),
-    A*1000000000+B*1000+(C div 1000).
+%% t() ->
+%%     {A,B,C} = os:timestamp(),
+%%     A*1000000000+B*1000+(C div 1000).