[SNMP4J] trap error

[dajiang]

Hi,

I am using snmp4j to receive v3 traps from some devices. I've got a 
strange problem: the trap receiving shows different results in two 
different computers; in one computer, snmp4j is able to decode v3 
security info and show valid trap info; in another, it shows decoding error.

The two computers run same OS: Windows Server 2008; and I installed same 
JDK (1.6). The snmp4j version is 2.0.2. I use 
org.snmp4j.tools.console.SnmpRequest to do the test; and the command 
line is :

java -cp ..\lib\log4j-1.2.14.jar;. org.snmp4j.tools.console.SnmpRequest 
-u snmpadmin -a MD5 -A snmpadmin -x AES -X snmpadmin -Ol 0.0.0.0/162

I run it in folder: snmp4j-2.0.2\classes.

The output for the good result is:

4758 [DefaultUDPTransportMapping_0.0.0.0/162] DEBUG 
org.snmp4j.transport.Default
UdpTransportMapping  - Received message from /10.1.18.1/12151 with 
length 316: 3
0:82:01:38:02:01:03:30:11:02:04:25:37:29:68:02:03:00:ff:e3:04:01:03:02:01:03:04:
32:30:30:04:05:01:02:03:04:05:02:01:00:02:01:00:04:09:73:6e:6d:70:61:64:6d:69:6e
:04:0c:d4:a7:41:86:53:8c:d3:e9:f7:87:6d:bd:04:08:73:bc:d0:8e:65:fd:15:dd:04:81:e
b:d2:42:62:e6:7c:85:f5:53:4f:9c:8d:98:d6:bb:d5:11:0d:a6:5a:64:6d:4d:94:93:a5:fd:
1d:7c:7e:c4:7c:b5:0a:12:15:14:0e:49:93:2f:58:5b:00:28:61:7a:23:50:ac:6c:81:ce:b8
:e4:f5:4b:4c:ea:99:72:44:98:09:ea:0f:86:c0:58:e2:64:c7:7f:36:b6:a6:62:4a:a7:a7:c
c:26:dd:05:ab:c5:c9:9a:87:a6:0b:51:bf:54:d0:50:fb:87:a6:a7:91:67:57:7a:e6:55:ca:
7b:31:2c:0c:33:a1:19:35:bc:a7:c3:f3:dc:88:2b:70:85:e6:96:72:ac:50:ad:e1:35:25:04
:7c:39:91:d9:dd:53:eb:67:19:34:4c:fe:79:36:de:bb:7e:7a:be:c3:86:9b:21:23:ee:07:5
2:a1:87:d1:a5:e4:7e:a5:87:b8:30:20:0b:2c:66:24:0c:fa:55:52:83:d3:ea:da:a9:0f:7e:
2a:1b:0d:b2:03:c9:6b:3d:64:3e:91:56:48:cf:43:8c:ea:56:84:63:18:d0:a4:f4:ed:a5:33
:96:fa:78:c1:b9:aa:e1:1c:d0:ce:9b:ff:6e:45:25:6d:da:cc:e3:0a:77:1a
4758 [DispatcherPool.1] DEBUG org.snmp4j.mp.MPv3  - SNMPv3 header 
decoded: msgId
=624372071, msgMaxSize=65507, msgFlags=03, secModel=3
5070 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: used k
ey fa:10:64:e8:83:e7:01:b0:86:bb:cd:d4:8f:ea:23:c5
5522 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: used p
rivacy_params 73:bc:d0:8e:65:fd:15:db
5460 [DispatcherPool.1] DEBUG org.snmp4j.security.USM  - 
getUser(engineID=01:02:
03:04:05, securityName=snmpadmin)
5585 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: decryp
ted Data 
30:81:e8:04:05:01:02:03:04:05:04:00:a7:81:dc:02:04:7f:10:a2:aa:02:01:0
0:02:01:00:30:81:cd:30:10:06:08:2b:06:01:02:01:01:03:00:43:04:01:28:f6:5b:30:18:
06:0a:2b:06:01:06:03:01:01:04:01:00:06:0a:2b:06:01:04:01:d7:78:01:06:01:30:23:06
:0c:2b:06:01:04:01:d7:78:01:05:01:01:01:04:13:32:30:31:32:2d:30:37:2d:30:37:20:3
1:39:3a:34:34:3a:34:34:30:15:06:0c:2b:06:01:04:01:d7:78:01:05:01:01:02:04:05:70:
6f:72:74:34:30:1a:06:0c:2b:06:01:04:01:d7:78:01:05:01:01:04:04:0a:31:30:2e:31:2e
:31:38:2e:31:34:30:1b:06:0c:2b:06:01:04:01:d7:78:01:05:01:01:05:04:0b:31:30:2e:3
2:36:2e:38:2e:31:39:33:30:2a:06:0c:2b:06:01:04:01:d7:78:01:05:01:01:0a:04:1a:49:
43:4d:50:20:45:43:48:4f:20:70:61:79:6c:6f:61:64:20:6d:6f:64:69:66:69:65:64
5647 [DispatcherPool.1] DEBUG org.snmp4j.security.UsmTimeTable  - 
CheckTime: tim
e ok (non authoritative)
5928 [DispatcherPool.0] DEBUG org.snmp4j.mp.MPv3  - RFC3412 º7.2.10 - 
Received P
DU is NOT a response or internal class message -> unchanged PduHandle = 
PduHandl
e[2131796650]
5990 [DispatcherPool.1] DEBUG org.snmp4j.security.PrivAES  - initVect is 
00:00:0
0:00:00:00:00:00:73:bc:d0:8e:65:fd:15:dc
6068 [DispatcherPool.0] DEBUG org.snmp4j.Snmp  - Fire process PDU event: 
Command
ResponderEvent[securityModel=3, securityLevel=3, 
maxSizeResponsePDU=65370, pduHa
ndle=PduHandle[2131796650], stateReference=null, 
pdu=TRAP[reqestID=2131796650, e
rrorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = 2 days, 6:03:37.23; 
1.3.6.1.
6.3.1.1.4.1.0 = 1.3.6.1.4.1.11256.1.6.1; 1.3.6.1.4.1.11256.1.5.1.1.1 = 
2012-07-0
7 19:44:44; 1.3.6.1.4.1.11256.1.5.1.1.2 = port4; 
1.3.6.1.4.1.11256.1.5.1.1.4 = 1
0.1.18.14; 1.3.6.1.4.1.11256.1.5.1.1.5 = 10.26.8.193; 
1.3.6.1.4.1.11256.1.5.1.1.
10 = ICMP ECHO payload modified]], messageProcessingModel=3, 
securityName=snmpad
min, processed=false, peerAddress=10.1.18.1/12151, 
transportMapping=org.snmp4j.t
ransport.DefaultUdpTransportMapping at 276af2, tmStateReference=null]

And output for the bad one:

4352 [DefaultUDPTransportMapping_0.0.0.0/162] DEBUG 
org.snmp4j.transport.Default
UdpTransportMapping  - Received message from /10.1.18.1/18322 with 
length 322: 3
0:82:01:3e:02:01:03:30:11:02:04:25:37:24:cf:02:03:00:ff:e3:04:01:03:02:01:03:04:
33:30:31:04:06:01:02:03:04:05:06:02:01:00:02:01:00:04:09:73:6e:6d:70:61:64:6d:69
:6e:04:0c:c8:d4:7d:8c:8b:14:c9:d5:32:9e:ce:ac:04:08:00:00:00:01:35:fa:06:cd:04:8
1:f0:55:5d:20:6f:e9:67:b3:d8:50:50:44:d7:78:8d:e5:35:e4:a5:f0:1d:71:bf:38:57:89:
fc:18:81:2a:0b:fe:ff:c7:b4:19:0f:86:89:fc:31:2f:9e:1d:1f:45:86:24:f9:e3:2b:f9:fb
:ad:16:68:b8:08:12:10:c5:fe:2b:23:41:45:1d:1b:ee:1f:a0:c8:e6:b1:13:f6:7c:55:e2:c
e:9f:63:f1:88:92:8c:c7:e0:5e:d1:8e:cc:8e:b8:d7:fb:48:17:9c:c1:e7:86:36:37:de:56:
f7:a2:e7:5f:3e:d0:b2:5c:ea:82:75:d7:08:11:8d:df:aa:fc:f9:77:9a:5d:5b:5b:98:86:8d
:ac:db:fa:36:63:44:1a:82:87:a8:57:02:c8:9d:d1:41:20:57:11:95:72:1f:f4:de:20:bd:5
8:62:f6:a1:3b:e6:dd:9b:25:a8:e1:6e:be:1a:6e:7f:ee:3d:a5:0b:a6:e2:2c:04:cc:e5:e0:
ba:ca:1a:3b:d5:03:1d:a1:d5:97:d6:ef:fd:10:4c:c6:f4:b7:bc:d6:01:58:88:a1:33:cc:a4
:09:de:24:7f:7f:59:17:5e:1e:3f:3d:e7:98:29:14:47:91:37:6f:46:d8:db:47:19:9d:60:1
4:59
4539 [DispatcherPool.0] DEBUG org.snmp4j.mp.MPv3  - SNMPv3 header 
decoded: msgId
=624370895, msgMaxSize=65507, msgFlags=03, secModel=3
4539 [DefaultUDPTransportMapping_0.0.0.0/162] DEBUG 
org.snmp4j.transport.Default
UdpTransportMapping  - Received message from /10.1.18.1/18322 with 
length 322: 3
0:82:01:3e:02:01:03:30:11:02:04:25:37:24:d0:02:03:00:ff:e3:04:01:03:02:01:03:04:
33:30:31:04:06:01:02:03:04:05:06:02:01:00:02:01:00:04:09:73:6e:6d:70:61:64:6d:69
:6e:04:0c:72:41:05:92:7f:15:49:a1:80:4c:d5:0e:04:08:00:00:00:01:35:fa:06:ce:04:8
1:f0:5e:b2:cb:86:48:af:84:13:47:e6:e8:11:c1:37:fb:3e:eb:dc:70:d5:1f:56:93:73:49:
4e:71:1a:8e:17:a6:06:3b:4f:61:9d:a9:90:b5:4e:4c:85:9b:0e:12:c1:4f:02:4a:2e:cb:51
:5a:9a:f7:62:f0:00:c9:50:f5:7e:35:43:64:81:6d:78:7e:32:7e:c6:99:ac:90:9e:0e:8f:2
e:7d:2d:5f:4d:6b:8d:00:58:5d:4d:e5:e2:04:38:37:49:16:3b:6a:37:c0:75:c2:74:6b:95:
83:83:4a:7c:77:83:ec:a7:87:0f:64:b7:37:d1:fd:d3:f4:e9:00:e3:ea:8a:14:a5:c6:86:9d
:96:7d:99:9d:37:c2:00:d6:62:08:d2:58:41:6c:32:6b:ca:da:7f:2b:08:c3:31:ac:43:1d:d
f:bc:96:2a:a2:a1:ab:f7:24:36:64:93:48:a7:0f:e3:b4:63:b2:81:b2:d9:f6:61:33:f1:0e:
96:b9:44:08:bc:8d:5c:94:18:72:b1:e8:b8:f1:b7:ea:ee:3d:40:ba:ea:9f:a2:c4:98:41:03
:de:c8:63:f6:a8:31:65:e2:8d:1d:2b:d6:31:18:ec:ad:61:66:f5:78:2d:7e:28:59:b3:1a:0
5:db
4570 [DispatcherPool.0] DEBUG org.snmp4j.security.USM  - 
getUser(engineID=01:02:
03:04:05:06, securityName=snmpadmin)
4804 [DispatcherPool.1] DEBUG org.snmp4j.mp.MPv3  - SNMPv3 header 
decoded: msgId
=624370896, msgMaxSize=65507, msgFlags=03, secModel=3
4836 [DispatcherPool.0] DEBUG org.snmp4j.security.UsmTimeTable  - 
CheckTime: tim
e ok (non authoritative)
4898 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - initVect is 
00:00:0
0:00:00:00:00:00:00:00:00:01:35:fa:06:cd
4898 [DispatcherPool.1] DEBUG org.snmp4j.security.USM  - 
getUser(engineID=01:02:
03:04:05:06, securityName=snmpadmin)
4914 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: Data t
o decrypt 
30:82:01:3e:02:01:03:30:11:02:04:25:37:24:cf:02:03:00:ff:e3:04:01:03:0
2:01:03:04:33:30:31:04:06:01:02:03:04:05:06:02:01:00:02:01:00:04:09:73:6e:6d:70:
61:64:6d:69:6e:04:0c:c8:d4:7d:8c:8b:14:c9:d5:32:9e:ce:ac:04:08:00:00:00:01:35:fa
:06:cd:04:81:f0:55:5d:20:6f:e9:67:b3:d8:50:50:44:d7:78:8d:e5:35:e4:a5:f0:1d:71:b
f:38:57:89:fc:18:81:2a:0b:fe:ff:c7:b4:19:0f:86:89:fc:31:2f:9e:1d:1f:45:86:24:f9:
e3:2b:f9:fb:ad:16:68:b8:08:12:10:c5:fe:2b:23:41:45:1d:1b:ee:1f:a0:c8:e6:b1:13:f6
:7c:55:e2:ce:9f:63:f1:88:92:8c:c7:e0:5e:d1:8e:cc:8e:b8:d7:fb:48:17:9c:c1:e7:86:3
6:37:de:56:f7:a2:e7:5f:3e:d0:b2:5c:ea:82:75:d7:08:11:8d:df:aa:fc:f9:77:9a:5d:5b:
5b:98:86:8d:ac:db:fa:36:63:44:1a:82:87:a8:57:02:c8:9d:d1:41:20:57:11:95:72:1f:f4
:de:20:bd:58:62:f6:a1:3b:e6:dd:9b:25:a8:e1:6e:be:1a:6e:7f:ee:3d:a5:0b:a6:e2:2c:0
4:cc:e5:e0:ba:ca:1a:3b:d5:03:1d:a1:d5:97:d6:ef:fd:10:4c:c6:f4:b7:bc:d6:01:58:88:
a1:33:cc:a4:09:de:24:7f:7f:59:17:5e:1e:3f:3d:e7:98:29:14:47:91:37:6f:46:d8:db:47
:19:9d:60:14:59
4945 [DispatcherPool.1] DEBUG org.snmp4j.security.UsmTimeTable  - 
CheckTime: tim
e ok (non authoritative)
5116 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: used k
ey 6d:d9:9c:2a:c3:2f:1b:c8:e1:60:59:cb:37:ec:41:c6
5163 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: used p
rivacy_params 00:00:00:01:35:fa:06:cd
5148 [DispatcherPool.1] DEBUG org.snmp4j.security.PrivAES  - initVect is 
00:00:0
0:00:00:00:00:00:00:00:00:01:35:fa:06:ce
5194 [DispatcherPool.0] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: decryp
ted Data 
4a:b6:cb:97:ee:03:c8:14:51:d2:68:7c:25:cc:a1:77:5a:fd:a6:f1:ed:89:c5:3
4:51:ec:3d:b9:67:89:d3:58:cc:59:6b:93:e3:bf:11:8f:c2:3b:74:0f:ea:5e:54:d3:b2:a9:
4f:da:d3:51:d1:62:4a:a7:d5:dc:76:d1:40:92:78:40:49:0f:72:41:cf:b5:39:91:58:c1:97
:9a:c2:13:0f:01:71:40:80:38:41:47:c4:8f:2c:e4:44:82:d0:cb:ed:50:9b:4f:74:c0:eb:1
b:03:55:b5:88:96:ff:19:4c:6d:c9:48:87:b0:95:6f:67:c7:22:ed:af:d8:a8:cc:ed:92:c9:
08:b5:b0:ad:ac:6a:30:0e:61:df:9d:78:50:f5:89:0f:e3:e8:c2:dc:a0:54:39:0d:b9:72:1f
:fc:66:1b:a0:67:fb:bc:e3:5e:f3:53:8d:e9:89:5c:37:9d:fa:44:bb:2e:72:e9:00:e8:95:e
4:60:d6:90:fb:5a:37:8b:20:2e:26:5a:b1:47:84:78:79:a0:6b:92:d6:57:a5:40:0a:4f:6b:
fd:c0:51:46:cf:27:d8:81:17:15:1a:17:a4:c8:0b:c9:7e:63:50:5c:74:e0:87:97:96:2d:b4
:0c:37:f7
5210 [DispatcherPool.1] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: Data t
o decrypt 
30:82:01:3e:02:01:03:30:11:02:04:25:37:24:d0:02:03:00:ff:e3:04:01:03:0
2:01:03:04:33:30:31:04:06:01:02:03:04:05:06:02:01:00:02:01:00:04:09:73:6e:6d:70:
61:64:6d:69:6e:04:0c:72:41:05:92:7f:15:49:a1:80:4c:d5:0e:04:08:00:00:00:01:35:fa
:06:ce:04:81:f0:5e:b2:cb:86:48:af:84:13:47:e6:e8:11:c1:37:fb:3e:eb:dc:70:d5:1f:5
6:93:73:49:4e:71:1a:8e:17:a6:06:3b:4f:61:9d:a9:90:b5:4e:4c:85:9b:0e:12:c1:4f:02:
4a:2e:cb:51:5a:9a:f7:62:f0:00:c9:50:f5:7e:35:43:64:81:6d:78:7e:32:7e:c6:99:ac:90
:9e:0e:8f:2e:7d:2d:5f:4d:6b:8d:00:58:5d:4d:e5:e2:04:38:37:49:16:3b:6a:37:c0:75:c
2:74:6b:95:83:83:4a:7c:77:83:ec:a7:87:0f:64:b7:37:d1:fd:d3:f4:e9:00:e3:ea:8a:14:
a5:c6:86:9d:96:7d:99:9d:37:c2:00:d6:62:08:d2:58:41:6c:32:6b:ca:da:7f:2b:08:c3:31
:ac:43:1d:df:bc:96:2a:a2:a1:ab:f7:24:36:64:93:48:a7:0f:e3:b4:63:b2:81:b2:d9:f6:6
1:33:f1:0e:96:b9:44:08:bc:8d:5c:94:18:72:b1:e8:b8:f1:b7:ea:ee:3d:40:ba:ea:9f:a2:
c4:98:41:03:de:c8:63:f6:a8:31:65:e2:8d:1d:2b:d6:31:18:ec:ad:61:66:f5:78:2d:7e:28
:59:b3:1a:05:db
5350 [DispatcherPool.0] WARN org.snmp4j.mp.MPv3  - ASN.1 parse error: 
Data lengt
h > 4 bytes are not supported!
java.io.IOException: Data length > 4 bytes are not supported!5522 
[DispatcherPoo
l.1] DEBUG org.snmp4j.security.PrivAES  - aes decrypt: used key 
6d:d9:9c:2a:c3:2
f:1b:c8:e1:60:59:cb:37:ec:41:c6

5584 [DispatcherPool.1] DEBUG org.snmp4j.security.PrivAES  - aes 
decrypt: used p
rivacy_params 00:00:00:01:35:fa:06:ce
         at org.snmp4j.asn1.BER.decodeLength(BER.java:528)5616 
[DispatcherPool.1]
  DEBUG org.snmp4j.security.PrivAES  - aes decrypt: decrypted Data 
84:d8:d7:02:5
d:12:42:2a:99:5b:72:eb:83:ac:b7:2d:a7:2a:34:e7:8f:3e:d2:e2:10:10:97:b8:5c:0a:6e:
c8:40:da:3e:16:11:69:ee:85:ad:f6:23:11:1f:76:58:c7:ad:38:d3:2e:df:d3:39:3e:a1:18
:5e:5c:ab:8e:cf:1c:39:33:1b:e6:ac:6b:b3:9f:af:e4:05:16:a3:50:3e:3e:1b:e0:e6:5a:7
c:4e:e8:9d:2c:57:ea:5f:a3:15:bb:96:61:d7:8a:19:a0:b3:0d:a5:67:ed:a1:80:f4:7b:46:
ad:65:a4:77:49:84:39:90:bb:de:0d:c0:c9:57:5d:dc:50:31:94:60:20:23:df:55:92:f4:56
:61:a0:af:3d:56:35:b2:b0:cf:5f:45:ac:b0:65:91:1f:04:f8:2f:f6:75:ad:41:e4:a0:66:7
f:43:39:f9:01:b6:8c:d3:b3:f4:11:70:40:c5:90:d1:70:1f:5c:1a:78:06:bb:9a:36:70:cd:
87:f0:98:28:45:eb:05:0e:f5:72:a8:85:9a:42:87:21:84:2e:cb:a5:9c:91:14:32:8a:f8:a0
:d3:92:de:11:64:92:bf:21:a6:4b:fa:66:f9:5f:5c:ad:ee:3d:a6:12:b9:72

5756 [DispatcherPool.1] WARN org.snmp4j.mp.MPv3  - ASN.1 parse error: 
Data lengt
h > 4 bytes are not supported!
         at org.snmp4j.asn1.BER.decodeHeader(BER.java:583)
         at org.snmp4j.asn1.BER.decodeHeader(BER.java:608)
         at org.snmp4j.ScopedPDU.decodeBER(ScopedPDU.java:141)
         at org.snmp4j.mp.MPv3.prepareDataElements(MPv3.java:1091)
         at 
org.snmp4j.MessageDispatcherImpl.dispatchMessage(MessageDispatcherImp
l.java:272)
         at 
org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl
.java:361)
         at 
org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl
.java:321)
         at 
org.snmp4j.util.MultiThreadedMessageDispatcher$MessageTask.run(MultiT
hreadedMessageDispatcher.java:182)
         at org.snmp4j.util.ThreadPool$TaskManager.run(ThreadPool.java:238)
java.io.IOException: Data length > 4 bytes are not supported!5959 
[DispatcherPoo
l.0] WARN org.snmp4j.MessageDispatcherImpl  - statusInfo=noError, 
status=-1408

         at org.snmp4j.asn1.BER.decodeLength(BER.java:528)
         at org.snmp4j.asn1.BER.decodeHeader(BER.java:583)
         at org.snmp4j.asn1.BER.decodeHeader(BER.java:608)
         at org.snmp4j.ScopedPDU.decodeBER(ScopedPDU.java:141)
         at org.snmp4j.mp.MPv3.prepareDataElements(MPv3.java:1091)
         at 
org.snmp4j.MessageDispatcherImpl.dispatchMessage(MessageDispatcherImp
l.java:272)
         at 
org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl
.java:361)
         at 
org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl
.java:321)
         at 
org.snmp4j.util.MultiThreadedMessageDispatcher$MessageTask.run(MultiT
hreadedMessageDispatcher.java:182)
         at org.snmp4j.util.ThreadPool$TaskManager.run(ThreadPool.java:238)
6162 [DispatcherPool.1] WARN org.snmp4j.MessageDispatcherImpl  - 
statusInfo=noEr
ror, status=-1408

I have no idea what could be the cause for this: OS problem, JDK spoiled?
Any comments, ideas, suggestion is greatly appreciated.