[SNMP4J] Unusual Delay in sr.nextBytes()
Jim.Zenor at gdc4s.com
Jim.Zenor at gdc4s.com
Thu May 30 16:13:16 CEST 2013
Hi,
I've been using SNMP4J 2.1.0 (with JDK 1.7.0_05 on a VM with RHEL 2.6.32-279.2.1.el6.x86_64) for a month or so now and have noticed an unusual performance variation when running my trap-sender test program. One time it will run in less than a second, the next time 10-30 seconds.
I reproduced the delay with org.snmp4j.tools.console.SnmpRequest using the following command-line:
java -classpath \
$COMMON/lib/log4j.jar:\
$SNMP4J/snmp4j-2.1.0/dist/lib/SNMP4J.jar:\
org.snmp4j.tools.console.SnmpRequest \
-p TRAP \
-a MD5 \
-A myotherpassword \
-u myuser \
-v 3 \
-x DES \
-X mypassword \
localhost/162 \
"1.3.6.1.2.1.1.3.0={t}0" \
"1.3.6.1.6.3.1.1.4.1.0={o}1.3.6.1.6.3.1.1.5.1" \
"1.3.6.1.2.1.1.1.0={s}System XYZ, Version N.M"
I loaded the SNMP4J 2.1.0 source into Eclipse and started adding debug trace statements. The delay, when it happens, was occurring in the Salt constructor within the method call to sr.nextBytes(rnd).
protected Salt() {
byte[] rnd = new byte[8];
try {
SecureRandom sr = SecureRandom.getInstance("SHA1PRNG");
sr.nextBytes(rnd);
}...
I'm hacking here... but after reading the JDK Javadocs for SecureRandom, I added the method call "sr.setSeed(rnd);" before the call to sr.nextBytes(rnd). It seems to have fixed the delay; however, I don't know why and I'm not sure if it causes other problems.
Is this a known problem? Is there a workaround or something I'm doing wrong?
Thanks
P.S. Here's the stdout. It shows a 14.5 second delay which happened before the first line of debug trace:
0 [main] DEBUG org.snmp4j.security.Salt - Entering Salt()
9 [main] DEBUG org.snmp4j.security.Salt - calling sr.nextBytes(rnd)
14544 [main] DEBUG org.snmp4j.security.Salt - Initialized Salt to 3aba6a14e42fcf0f.
14551 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user myuser = UsmUser[secName=myuser,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=myotherpassword,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=mypassword,localizationEngineID=null]
14554 [DefaultUDPTransportMapping_10.248.169.158/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 10.248.169.158/0 is set to: 131072
14557 [main] DEBUG org.snmp4j.mp.MPv3 - Context engine ID of unconfirmed scoped PDU is empty! Setting it to local engine ID
14559 [main] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:0a:f8:a9:9e, securityName=myuser)
14634 [main] DEBUG org.snmp4j.security.AuthGeneric - MD5First digest: c4:8f:bc:c9:59:c4:73:23:9a:03:81:00:19:5d:c2:ad
14634 [main] DEBUG org.snmp4j.security.AuthGeneric - MD5localized key: fe:5e:bc:fe:09:13:ba:f4:02:ac:52:2d:3c:f8:bf:37
14687 [main] DEBUG org.snmp4j.security.AuthGeneric - MD5First digest: eb:3a:d6:ba:92:94:41:a0:ff:64:08:3d:02:1c:07:f1
14688 [main] DEBUG org.snmp4j.security.AuthGeneric - MD5localized key: 8c:94:41:7b:6d:40:cb:d5:97:07:1a:31:76:eb:7d:96
14689 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user myuser = UsmUser[secName=myuser,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=fe:5e:bc:fe:09:13:ba:f4:02:ac:52:2d:3c:f8:bf:37,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=8c:94:41:7b:6d:40:cb:d5:97:07:1a:31:76:eb:7d:96,localizationEngineID=80:00:13:70:01:0a:f8:a9:9e]
14690 [main] DEBUG org.snmp4j.security.USM - RFC3414 ยง3.1.4.a Outgoing message needs to be encrypted
14690 [main] DEBUG org.snmp4j.security.PrivDES - Preparing decrypt_params.
14690 [main] DEBUG org.snmp4j.security.PrivDES - Preparing iv for encryption.
14871 [main] DEBUG org.snmp4j.security.PrivDES - Using padding.
14871 [main] DEBUG org.snmp4j.security.PrivDES - Encryption finished.
14872 [main] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=803982166,pduHandle=PduHandle[2091434141],securityEngineID=80:00:13:70:01:0a:f8:a9:9e,securityModel=org.snmp4j.security.USM at 1b54a291,securityName=myuser,securityLevel=3,contextEngineID=80:00:13:70:01:0a:f8:a9:9e,contextName=,retryMsgIDs=null]
14873 [main] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/162 with length 192: 30:81:bd:02:01:03:30:11:02:04:2f:eb:cb:56:02:03:00:ff:ff:04:01:03:02:01:03:04:33:30:31:04:09:80:00:13:70:01:0a:f8:a9:9e:02:01:00:02:01:00:04:06:6d:79:75:73:65:72:04:0c:05:50:9b:45:30:e5:99:85:fd:e8:91:24:04:08:00:00:00:00:e4:2f:cf:0f:04:70:6f:9e:d5:92:ae:bc:38:4f:d9:be:7e:7b:0e:0e:12:29:c6:44:8b:ed:90:cf:ec:82:8b:08:49:d5:9f:22:dc:eb:e7:31:17:86:5e:e8:16:d9:ff:ba:9d:48:1d:28:58:e7:eb:65:72:6f:a7:3e:13:a4:54:db:a4:30:6b:9b:46:8e:25:b6:3d:f4:6e:9f:95:a7:ac:31:62:6b:14:c4:ed:1c:42:e6:a2:43:70:12:87:88:7b:20:02:1a:af:ab:8e:2e:a5:7c:e7:5f:8d:3a:73:c7:30:71:40:f3:ce:35:8a:23
14873 [main] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
14873 [main] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
14873 [DefaultUDPTransportMapping_10.248.169.158/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Worker task stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
TRAP sent successfully
More information about the SNMP4J
mailing list