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, 223 insertions, 118 deletions

diff --git a/lib/snmp/test/snmp_agent_test.erl b/lib/snmp/test/snmp_agent_test.erl
index 468280db02..426524be4d 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]]).
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).