"How to Implement SNMPv3 GETNEXT with SNMP4J" Question

Hi,

I’ve taken the example from SNMPv3 GETNEXT Example and tried this w/SNMP4J v2.8.5. This seems to fundamentally work, however, for some reason, I am seeing duplicate requests/responses and this is resulting in an eventual exception. The log is below and I’ve confirmed with Wireshark that two get-next-requests/get-responses occur. I’m guessing that this why the notify() is throwing, but I’m not sure why the duplication is happening.

Any thoughts on this? I am a new user to SNMP4J so it’s likely that I’ve just overlooked something obvious here ;)…

Thanks!

Initialized Salt to e767a2fae215bbae. UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536 Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=initauth,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=initpriv,localizationEngineID=null] RFC3414 §3.1.4.b Outgoing message is not encrypted Adding cache entry: StateReference[msgID=1030587082,pduHandle=PduHandle[1853501735],securityEngineID=,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] Running pending async request with handle PduHandle[1853501735] and retry count left 1 Sending message to 205.159.216.220/161 with length 61: 30:3b:02:01:03:30:11:02:04:3d:6d:82:ca:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00:30:11:04:00:04:00:a1:0b:02:01:00:02:01:00:02:01:00:30:00 Received message from /205.159.216.220/161 with length 107: 30:69:02:01:03:30:11:02:04:3d:6d:82:ca:02:03:00:ff:e3:04:01:00:02:01:03:04:20:30:1e:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:05:3b:ff:04:00:04:00:04:00:30:2f:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a8:1c:02:01:00:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:01:17 SNMPv3 header decoded: msgId=1030587082, msgMaxSize=65507, msgFlags=00, secModel=3 Accepting zero length security name Removed cache entry: StateReference[msgID=1030587082,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] RFC3412 §7.2.10 - Received PDU (msgID=1030587082) is a response or an internal class message. PduHandle.transactionID = 1853501735 MPv3 finished CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1853501735], stateReference=null, pdu=REPORT[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.4.0 = 23]], messageProcessingModel=3, securityName=, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@16aed750, tmStateReference=null] Searching pending request with handlePduHandle[1853501735] Send new request after report. Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:1f:88:80:16:89:14:3c:65:66:51:5d getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) SHA-1First digest: d0:b5:b2:e7:31:aa:ae:e7:ee:86:75:29:0c:34:1e:78:51:68:99:4d SHA-1localized key: 21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f SHA-1First digest: 21:9f:31:da:0f:fd:c6:a8:ef:10:7c:95:cf:4e:90:6e:22:32:f6:76 SHA-1localized key: 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18:4d:24:39:7f Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18,localizationEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d] RFC3414 §3.1.4.a Outgoing message needs to be encrypted initVect is 00:00:01:18:00:05:3c:00:e7:67:a2:fa:e2:15:bb:ae getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) RFC3414 §3.1.4.a Outgoing message needs to be encrypted initVect is 00:00:01:18:00:05:3c:00:e7:67:a2:fa:e2:15:bb:af aes encrypt: Data to encrypt 30:2b:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a1:18:02:04:6e:7a:31:27:02:01:00:02:01:00:30:0a:30:08:06:04:29:03:06:01:05:00 aes encrypt: Data to encrypt 30:2b:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a1:18:02:04:6e:7a:31:27:02:01:00:02:01:00:30:0a:30:08:06:04:29:03:06:01:05:00 aes encrypt: used key 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18 aes encrypt: used key 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18 aes encrypt: created privacy_params e7:67:a2:fa:e2:15:bb:af aes encrypt: created privacy_params e7:67:a2:fa:e2:15:bb:ae aes encrypt: encrypted Data 8f:35:c3:62:de:b7:b6:be:df:b3:32:96:7b:86:08:c1:1b:3a:a8:5f:35:af:3d:be:27:63:e0:79:c5:8c:16:7e:88:d8:db:88:99:cd:34:9e:ea:8a:f5:2c:be aes encrypt: encrypted Data 6f:6a:88:77:db:19:e2:9c:b0:40:dd:77:af:77:9a:ae:8c:8d:ae:91:bf:79:43:8b:52:d7:8a:aa:1c:c5:28:c7:fb:46:db:bf:86:0f:c1:7f:d7:5d:9f:9b:66 Adding cache entry: StateReference[msgID=1030587083,pduHandle=PduHandle[1853501735],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Adding cache entry: StateReference[msgID=1030587084,pduHandle=PduHandle[1853501735],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Sending message to 205.159.216.220/161 with length 131: 30:81:80:02:01:03:30:11:02:04:3d:6d:82:cb:02:03:00:ff:ff:04:01:07:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:05:3c:00:04:05:61:64:6d:69:6e:04:0c:a5:ae:2d:25:62:a6:e8:bb:bd:61:a9:97:04:08:e7:67:a2:fa:e2:15:bb:ae:04:2d:6f:6a:88:77:db:19:e2:9c:b0:40:dd:77:af:77:9a:ae:8c:8d:ae:91:bf:79:43:8b:52:d7:8a:aa:1c:c5:28:c7:fb:46:db:bf:86:0f:c1:7f:d7:5d:9f:9b:66 Adding previous message IDs [1030587083] to new entry StateReference[msgID=1030587084,pduHandle=PduHandle[1853501735],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Running pending async request with handle PduHandle[1853501735] and retry count left 0 Sending message to 205.159.216.220/161 with length 131: 30:81:80:02:01:03:30:11:02:04:3d:6d:82:cc:02:03:00:ff:ff:04:01:07:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:05:3c:00:04:05:61:64:6d:69:6e:04:0c:56:0d:f9:ea:e9:5b:a7:a7:f9:ca:db:c6:04:08:e7:67:a2:fa:e2:15:bb:af:04:2d:8f:35:c3:62:de:b7:b6:be:df:b3:32:96:7b:86:08:c1:1b:3a:a8:5f:35:af:3d:be:27:63:e0:79:c5:8c:16:7e:88:d8:db:88:99:cd:34:9e:ea:8a:f5:2c:be Received message from /205.159.216.220/161 with length 178: 30:81:af:02:01:03:30:11:02:04:3d:6d:82:cb:02:03:00:ff:e3:04:01:03:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:05:3c:00:04:05:61:64:6d:69:6e:04:0c:9e:03:15:11:23:ee:3c:88:15:ad:75:f2:04:08:61:db:61:d8:11:89:26:f5:04:5c:32:01:7a:2c:61:6f:af:69:80:01:5f:d3:68:0f:ca:ac:9f:57:a2:8c:0b:00:b6:17:18:44:2e:a5:a6:39:ed:12:9b:54:2d:76:d4:d3:ca:d4:e1:fa:0d:3a:32:56:a9:d8:f0:78:77:f2:60:70:9a:62:09:cf:f1:a2:76:61:0b:38:27:74:8c:15:0d:21:0a:7f:dd:65:58:2b:6a:17:23:ed:4a:a4:82:57:2d:2a:cf:ed:6e:a0:79:de SNMPv3 header decoded: msgId=1030587083, msgMaxSize=65507, msgFlags=03, secModel=3 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) CheckTime: time ok (non authoritative) initVect is 00:00:01:18:00:05:3c:00:61:db:61:d8:11:89:26:f5 java.lang.IllegalMonitorStateException Removed cache entry: StateReference[msgID=1030587084,pduHandle=null,securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@ae45eb6,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=[1030587083]] java.lang.IllegalMonitorStateException RFC3412 §7.2.10 - Received PDU (msgID=1030587083) is a response or an internal class message. PduHandle.transactionID = 1853501735 MPv3 finished at java.lang.Object.notify(Native Method) CommandResponderEvent[securityModel=3, securityLevel=3, maxSizeResponsePDU=65325, pduHandle=PduHandle[1853501735], stateReference=null, pdu=RESPONSE[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=1853501735, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = <xxxxxxxx>]], messageProcessingModel=3, securityName=admin, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@16aed750, tmStateReference=null] Looking up pending request with handle PduHandle[1853501735] Cancelling pending request with handle PduHandle[1853501735] Received: RESPONSE[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=1853501735, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = <xxxxxxxx>]] Received message from /205.159.216.220/161 with length 178: 30:81:af:02:01:03:30:11:02:04:3d:6d:82:cc:02:03:00:ff:e3:04:01:03:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:05:3c:00:04:05:61:64:6d:69:6e:04:0c:74:84:e1:ea:e5:8c:00:0e:d2:22:cc:c7:04:08:61:db:61:d8:11:89:26:f6:04:5c:32:34:5e:61:78:e2:ac:70:8d:a7:f5:80:6c:b1:ef:ef:7a:d2:4d:5b:98:9a:d1:95:b9:02:e2:33:38:04:e0:8b:e7:b9:bc:cd:bf:f7:67:f5:78:18:6b:34:4c:aa:1d:45:63:c0:d4:22:b9:7d:79:dc:6f:51:9c:5d:1f:8f:47:cc:27:3c:0d:67:84:40:d7:d2:ac:0a:4c:c7:65:a9:a1:9c:88:87:06:13:e9:f0:bd:be:a2:73:69:6d SNMPv3 header decoded: msgId=1030587084, msgMaxSize=65507, msgFlags=03, secModel=3 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) CheckTime: time ok (non authoritative) initVect is 00:00:01:18:00:05:3c:00:61:db:61:d8:11:89:26:f6 RFC3412 §7.2.10 - Received PDU (msgID=1030587084) is a response or internal class message, but cached information for the msgID could not be found Message from 205.159.216.220/161 not dispatched, reason: statusInfo=noError, status=-1409 at wctest.SNMP4jTest$2.onResponse(SNMP4jTest.java:136) at org.snmp4j.Snmp.processPdu(Snmp.java:1300) at org.snmp4j.MessageDispatcherImpl.fireProcessPdu(MessageDispatcherImpl.java:694) at org.snmp4j.MessageDispatcherImpl.dispatchMessage(MessageDispatcherImpl.java:310) at org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl.java:390) at org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl.java:350) at org.snmp4j.transport.AbstractTransportMapping.fireProcessMessage(AbstractTransportMapping.java:76) at org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread.run(DefaultUdpTransportMapping.java:430) at java.lang.Thread.run(Thread.java:748)

Most likely your timeout value is too small.

The command responder is not able to respond within that timeframe and therefore the command sender sends a retry message.
Then the command responder simply queues the requests (instead of detecting like SNMP4J agent, that such a retry request is already being processed) and the reply on the second retry will not have a corresponding request left in the command sender when it arrives.

That is nothing to worry about. Having a too small retry timeout value is only inefficient - not an error.

Most likely your timeout value is too small.

The responder is replying nearly instantaneously (~1ms RTT). Not only is the debug output all getting dumped nearly instantaneously too, the Wireshark trace also indicates the very small RTT responsitivity. The userTarget.setTimeout(500) seems large enough by far.

Is there something else I can tweak to help isolate what might be going on? I can add a timestamp in the responseListener (maybe there’s a flag to inform the logger to prepend timestamps on log records as well?)…

Thanks.

You can set the max. of retries to 0. With that you can verify that it is indeed not a retry issue.

I later saw the IllegalMonitorStateExceptions which are suspicious. Could you paste your code or is it exactly the sample code?
I will check the sample with the version you used too, to see if there is a general problem or not.

Hi Frank,

More testing here, with some interesting results. Hopefully you can help shed some light on this. To answer your first question: yes, the code is almost exactly the sample code; the changes are only in relation to using my particular USM user’s security attributes (AuthSHA and PrivAES128) and then also hard-coding the application arguments in my main() method.

I started up trying the same code on a Linux box (Ubuntu 18.04) - my initial tests were all with Win10. Both installations run quite recent versions of Java 8 (OpenJDK 265 via NetBeans 11.3 on Linux and Oracle 251 via NetBeans 8.2 on Win10).

On Linux I do not see the duplicate get-next-request PDUs in the Wireshark, but I do see the IllegalMonitorStateException (like on Win10). This monitor state exception is consistent between both Win10 and Linux and seems to be independent of the duplicate requests/responses.

Going back to Win10 and setting retries to zero (userTarget.setRetries(0)) resulted in a new and different error with a timeout exception (almost like the request timeout fired immediately):

Initialized Salt to 23a3681548e21216. UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536 Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=initauth,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=initpriv,localizationEngineID=null] RFC3414 §3.1.4.b Outgoing message is not encrypted Adding cache entry: StateReference[msgID=102723113,pduHandle=PduHandle[1157439378],securityEngineID=,securityModel=org.snmp4j.security.USM@224edc67,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] Running pending async request with handle PduHandle[1157439378] and retry count left 0 Sending message to 205.159.216.220/161 with length 61: 30:3b:02:01:03:30:11:02:04:06:1f:6e:29:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00:30:11:04:00:04:00:a1:0b:02:01:00:02:01:00:02:01:00:30:00 Received message from /205.159.216.220/161 with length 107: 30:69:02:01:03:30:11:02:04:06:1f:6e:29:02:03:00:ff:e3:04:01:00:02:01:03:04:20:30:1e:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:3d:97:04:00:04:00:04:00:30:2f:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a8:1c:02:01:00:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:01:21 SNMPv3 header decoded: msgId=102723113, msgMaxSize=65507, msgFlags=00, secModel=3 Accepting zero length security name Removed cache entry: StateReference[msgID=102723113,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@224edc67,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] RFC3412 §7.2.10 - Received PDU (msgID=102723113) is a response or an internal class message. PduHandle.transactionID = 1157439378 MPv3 finished CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1157439378], stateReference=null, pdu=REPORT[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.4.0 = 33]], messageProcessingModel=3, securityName=, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@758a781e, tmStateReference=null] Searching pending request with handlePduHandle[1157439378] Send new request after report. Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:1f:88:80:16:89:14:3c:65:66:51:5d getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) SHA-1First digest: d0:b5:b2:e7:31:aa:ae:e7:ee:86:75:29:0c:34:1e:78:51:68:99:4d SHA-1localized key: 21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f SHA-1First digest: 21:9f:31:da:0f:fd:c6:a8:ef:10:7c:95:cf:4e:90:6e:22:32:f6:76 SHA-1localized key: 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18:4d:24:39:7f Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18,localizationEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d] RFC3414 §3.1.4.a Outgoing message needs to be encrypted initVect is 00:00:01:18:00:06:3d:97:23:a3:68:15:48:e2:12:16 Request timed out: 1157439378 Cancelling pending request with handle PduHandle[1157439378] Timed out. Failed to process pending request PduHandle[1157439378] because null Exception in thread "Timer-0" java.lang.IllegalMonitorStateException at java.lang.Object.notify(Native Method) at wctest.SNMP4jTest$2.onResponse(SNMP4jTest.java:133) at org.snmp4j.Snmp$PendingRequest.run(Snmp.java:1905) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) aes encrypt: Data to encrypt 30:2b:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a1:18:02:04:44:fd:1f:92:02:01:00:02:01:00:30:0a:30:08:06:04:29:03:06:01:05:00 aes encrypt: used key 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18 aes encrypt: created privacy_params 23:a3:68:15:48:e2:12:16 aes encrypt: encrypted Data 46:cc:c1:ca:c6:f2:f7:c0:70:a7:67:82:eb:01:83:eb:51:56:ed:91:ae:56:1d:06:ac:03:19:d4:54:13:01:90:a7:31:4b:ae:fd:8f:c3:eb:30:41:fc:39:e0 Adding cache entry: StateReference[msgID=102723114,pduHandle=PduHandle[1157439378],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@224edc67,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Sending message to 205.159.216.220/161 with length 131: 30:81:80:02:01:03:30:11:02:04:06:1f:6e:2a:02:03:00:ff:ff:04:01:07:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:3d:97:04:05:61:64:6d:69:6e:04:0c:69:46:7c:49:ba:cd:12:35:2c:39:ef:41:04:08:23:a3:68:15:48:e2:12:16:04:2d:46:cc:c1:ca:c6:f2:f7:c0:70:a7:67:82:eb:01:83:eb:51:56:ed:91:ae:56:1d:06:ac:03:19:d4:54:13:01:90:a7:31:4b:ae:fd:8f:c3:eb:30:41:fc:39:e0 Received message from /205.159.216.220/161 with length 178: 30:81:af:02:01:03:30:11:02:04:06:1f:6e:2a:02:03:00:ff:e3:04:01:03:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:3d:98:04:05:61:64:6d:69:6e:04:0c:76:e6:60:05:c2:63:c4:7d:88:ac:c3:08:04:08:61:db:61:d8:11:89:27:02:04:5c:b7:4f:90:4e:fb:ca:42:3d:af:a4:09:2e:fb:bb:ac:7e:e2:5c:20:3d:fe:9d:d9:97:0e:af:cb:26:44:72:76:88:50:bc:4e:5c:21:a3:5e:26:b5:01:2a:fe:16:d8:c1:08:ba:bd:2d:e2:ae:7b:e3:0d:d8:3d:2c:67:5f:37:73:be:3a:15:19:b0:1a:bc:1b:e6:22:3a:d9:ca:b5:10:dd:b3:7b:c5:75:26:3d:b4:19:70:9f:34:71:43 SNMPv3 header decoded: msgId=102723114, msgMaxSize=65507, msgFlags=03, secModel=3 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) CheckTime: time ok (non authoritative) initVect is 00:00:01:18:00:06:3d:98:61:db:61:d8:11:89:27:02 Removed cache entry: StateReference[msgID=102723114,pduHandle=null,securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@224edc67,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] RFC3412 §7.2.10 - Received PDU (msgID=102723114) is a response or an internal class message. PduHandle.transactionID = 1157439378 MPv3 finished CommandResponderEvent[securityModel=3, securityLevel=3, maxSizeResponsePDU=65325, pduHandle=PduHandle[1157439378], stateReference=null, pdu=RESPONSE[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=1157439378, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = <xxxxxxxx>]], messageProcessingModel=3, securityName=admin, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@758a781e, tmStateReference=null] Looking up pending request with handle PduHandle[1157439378] Received response that cannot be matched to any outstanding request, address=205.159.216.220/161, requestID=1157439378

Finally suspecting that SNMP4J is somehow improperly implementing the 500ms timeout I went ahead and changed this timeout value to 5000 (5s) (userTarget.setTimeout(5000)). The IllegalMonitorStateException is thrown as per usual, but this time I no longer see the double requests/responses and instead see the proper single request/response. This mimics the Linux result (albeit with a different timeout value).

So there appears to be a general issue around the response listener signalling and then also some odd behaviour on Win10 wrt the timeout. Here’s a snapshot of the Wireshark packets on Win10 that shows the duplicate get-next-request packets being sent within a millisecond of each other

Please let me know if there’s any other info or tests that I can provide to help with this. Also let me know if you’d like me to update the exact copy of my test class.

Thanks again!

From your stack trace, it seems that your implementation of the onResponse callback method is causing the exception and thus improper handling of the response. Please check that code, it seems that you missed a synchronized in the method definition.

Thanks.

Yes, adding a synchronized qualifier to the onResponse override does indeed fix the IllegalMonitorStateException. This is another example of the difference between the v3 API (the example is written against this version) and the v2 API (the v2 API has no reference to synchronized in the javadoc for this method). I mentioned this in my last response in an earlier thread: https://forum.snmp.app/t/snmp4j-v3-java-9-requirement/454/2?u=coldforest

The duplicate (Win10) request/response behaviour is unchanged however. Any thoughts on this aspect?

***start time: 2020-11-17T17:45:01.553Z Initialized Salt to 3aba92fafb55ebe6. UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536 Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=initauth,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=initpriv,localizationEngineID=null] RFC3414 §3.1.4.b Outgoing message is not encrypted Adding cache entry: StateReference[msgID=2145104629,pduHandle=PduHandle[1685989488],securityEngineID=,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] Running pending async request with handle PduHandle[1685989488] and retry count left 1 Sending message to 205.159.216.220/161 with length 61: 30:3b:02:01:03:30:11:02:04:7f:db:b2:f5:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00:30:11:04:00:04:00:a1:0b:02:01:00:02:01:00:02:01:00:30:00 Received message from /205.159.216.220/161 with length 107: 30:69:02:01:03:30:11:02:04:7f:db:b2:f5:02:03:00:ff:e3:04:01:00:02:01:03:04:20:30:1e:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:49:a6:04:00:04:00:04:00:30:2f:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a8:1c:02:01:00:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:01:28 SNMPv3 header decoded: msgId=2145104629, msgMaxSize=65507, msgFlags=00, secModel=3 Accepting zero length security name Removed cache entry: StateReference[msgID=2145104629,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null] RFC3412 §7.2.10 - Received PDU (msgID=2145104629) is a response or an internal class message. PduHandle.transactionID = 1685989488 MPv3 finished CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1685989488], stateReference=null, pdu=REPORT[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.4.0 = 40]], messageProcessingModel=3, securityName=, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@227425a9, tmStateReference=null] Searching pending request with handlePduHandle[1685989488] Send new request after report. Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:1f:88:80:16:89:14:3c:65:66:51:5d getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) SHA-1First digest: d0:b5:b2:e7:31:aa:ae:e7:ee:86:75:29:0c:34:1e:78:51:68:99:4d SHA-1localized key: 21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f SHA-1First digest: 21:9f:31:da:0f:fd:c6:a8:ef:10:7c:95:cf:4e:90:6e:22:32:f6:76 SHA-1localized key: 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18:4d:24:39:7f Adding user admin = UsmUser[secName=admin,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=21:f4:c1:5c:cd:02:d8:c6:ad:79:94:49:fc:c2:a1:ca:11:28:5e:6f,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18,localizationEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d] RFC3414 §3.1.4.a Outgoing message needs to be encrypted initVect is 00:00:01:18:00:06:49:a6:3a:ba:92:fa:fb:55:eb:e6 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) RFC3414 §3.1.4.a Outgoing message needs to be encrypted initVect is 00:00:01:18:00:06:49:a7:3a:ba:92:fa:fb:55:eb:e7 aes encrypt: Data to encrypt 30:2b:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a1:18:02:04:64:7e:28:70:02:01:00:02:01:00:30:0a:30:08:06:04:29:03:06:01:05:00 aes encrypt: Data to encrypt 30:2b:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:04:00:a1:18:02:04:64:7e:28:70:02:01:00:02:01:00:30:0a:30:08:06:04:29:03:06:01:05:00 aes encrypt: used key 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18 aes encrypt: used key 6e:6b:7e:c5:5a:d3:14:0a:42:3a:0c:16:6a:30:b6:18 aes encrypt: created privacy_params 3a:ba:92:fa:fb:55:eb:e7 aes encrypt: created privacy_params 3a:ba:92:fa:fb:55:eb:e6 aes encrypt: encrypted Data 62:50:d7:83:40:16:67:8c:c2:9c:f5:5b:dd:38:0e:bc:c8:1c:8b:6c:38:ba:3e:06:85:38:83:b4:3e:5c:a1:e6:d5:08:e4:5b:fc:7e:f7:86:5c:c5:3c:4b:48 aes encrypt: encrypted Data 32:83:3b:d9:63:57:8e:80:23:df:b2:f9:62:43:a2:07:da:12:44:a4:e5:c4:05:e8:93:bf:40:f0:ea:98:35:95:4c:f6:40:5e:d5:24:15:35:b0:1a:88:bb:25 Adding cache entry: StateReference[msgID=2145104631,pduHandle=PduHandle[1685989488],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Running pending async request with handle PduHandle[1685989488] and retry count left 0 Adding cache entry: StateReference[msgID=2145104630,pduHandle=PduHandle[1685989488],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Sending message to 205.159.216.220/161 with length 131: 30:81:80:02:01:03:30:11:02:04:7f:db:b2:f7:02:03:00:ff:ff:04:01:07:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:49:a7:04:05:61:64:6d:69:6e:04:0c:63:39:f6:86:e6:e5:6e:7d:42:45:c9:4b:04:08:3a:ba:92:fa:fb:55:eb:e7:04:2d:62:50:d7:83:40:16:67:8c:c2:9c:f5:5b:dd:38:0e:bc:c8:1c:8b:6c:38:ba:3e:06:85:38:83:b4:3e:5c:a1:e6:d5:08:e4:5b:fc:7e:f7:86:5c:c5:3c:4b:48 Adding previous message IDs [2145104631] to new entry StateReference[msgID=2145104630,pduHandle=PduHandle[1685989488],securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=null] Sending message to 205.159.216.220/161 with length 131: 30:81:80:02:01:03:30:11:02:04:7f:db:b2:f6:02:03:00:ff:ff:04:01:07:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:49:a6:04:05:61:64:6d:69:6e:04:0c:61:9b:bb:75:19:3f:f3:f8:a8:b2:b3:ef:04:08:3a:ba:92:fa:fb:55:eb:e6:04:2d:32:83:3b:d9:63:57:8e:80:23:df:b2:f9:62:43:a2:07:da:12:44:a4:e5:c4:05:e8:93:bf:40:f0:ea:98:35:95:4c:f6:40:5e:d5:24:15:35:b0:1a:88:bb:25 Received message from /205.159.216.220/161 with length 178: 30:81:af:02:01:03:30:11:02:04:7f:db:b2:f7:02:03:00:ff:e3:04:01:03:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:49:a7:04:05:61:64:6d:69:6e:04:0c:53:18:fd:2c:51:c2:f2:60:52:e2:c4:45:04:08:61:db:61:d8:11:89:27:0d:04:5c:89:1e:f0:51:e8:c3:67:73:b6:17:d6:33:fc:58:1c:5c:c6:94:6d:7a:62:0a:c8:66:5b:71:5b:12:78:4a:91:e0:75:80:8d:7d:de:57:52:cf:ee:62:b9:50:b3:51:84:34:d1:db:31:e0:ba:57:df:96:9a:d9:60:99:c9:46:a8:2b:e4:0a:44:d6:97:66:e4:e2:18:37:4c:b3:c5:e5:d6:6f:e6:9a:04:3f:8b:9b:c7:11:7c:36:21:2c SNMPv3 header decoded: msgId=2145104631, msgMaxSize=65507, msgFlags=03, secModel=3 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) CheckTime: time ok (non authoritative) initVect is 00:00:01:18:00:06:49:a7:61:db:61:d8:11:89:27:0d Removed cache entry: StateReference[msgID=2145104630,pduHandle=null,securityEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,securityModel=org.snmp4j.security.USM@396f6598,securityName=admin,securityLevel=3,contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d,contextName=,retryMsgIDs=[2145104631]] RFC3412 §7.2.10 - Received PDU (msgID=2145104631) is a response or an internal class message. PduHandle.transactionID = 1685989488 MPv3 finished CommandResponderEvent[securityModel=3, securityLevel=3, maxSizeResponsePDU=65325, pduHandle=PduHandle[1685989488], stateReference=null, pdu=RESPONSE[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=1685989488, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = <xxxxxxxx>]], messageProcessingModel=3, securityName=admin, processed=false, peerAddress=205.159.216.220/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@227425a9, tmStateReference=null] Looking up pending request with handle PduHandle[1685989488] Cancelling pending request with handle PduHandle[1685989488] 2020-11-17T17:45:02.699Z: Received: RESPONSE[{contextEngineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, contextName=}, requestID=1685989488, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = <xxxxxxxx>]] ***end time: 2020-11-17T17:45:02.699Z Received message from /205.159.216.220/161 with length 178: 30:81:af:02:01:03:30:11:02:04:7f:db:b2:f6:02:03:00:ff:e3:04:01:03:02:01:03:04:39:30:37:04:0d:80:00:1f:88:80:16:89:14:3c:65:66:51:5d:02:02:01:18:02:03:06:49:a7:04:05:61:64:6d:69:6e:04:0c:f4:dd:6c:4b:6c:f0:1c:65:ad:cc:58:58:04:08:61:db:61:d8:11:89:27:0e:04:5c:3a:ca:d8:2c:69:e0:fa:bc:5b:b8:2b:11:d8:ec:1d:87:58:6a:44:f9:02:74:7a:64:c4:92:a5:5d:2e:7b:10:d3:be:56:62:b9:cf:c1:e7:2c:3d:67:76:70:ca:37:a8:64:2d:97:63:58:78:1a:93:35:18:ee:f5:02:cd:da:5f:b0:b9:c1:64:72:ef:1b:c2:27:ba:34:4c:c2:2d:05:e9:8c:02:0c:8a:5c:50:fb:84:97:1e:00:2f:cb SNMPv3 header decoded: msgId=2145104630, msgMaxSize=65507, msgFlags=03, secModel=3 getUser(engineID=80:00:1f:88:80:16:89:14:3c:65:66:51:5d, securityName=admin) CheckTime: time ok (non authoritative) initVect is 00:00:01:18:00:06:49:a7:61:db:61:d8:11:89:27:0e RFC3412 §7.2.10 - Received PDU (msgID=2145104630) is a response or internal class message, but cached information for the msgID could not be found Message from 205.159.216.220/161 not dispatched, reason: statusInfo=noError, status=-1409

The synchronized is necessary with both APIs (regardless v2.x or v3.x), because of the notify() call in the sample code. That is not related to the API at all.

Regarding the timing issue on Win10, I cannot help unless I see the timestamps of the logging events. Windows has a different multi-threading strategy that UNIX systems and of course the UDP buffering is different. Many things can influence that.

The synchronized is necessary with both APIs (regardless v2.x or v3.x), because of the notify() call in the sample code. That is not related to the API at all

How about this: a suggestion to update the v2 Javadoc to include this explicitly (can’t hurt, right?)?

Regarding the timing issue on Win10, I cannot help unless I see the timestamps of the logging events. Windows has a different multi-threading strategy that UNIX systems and of course the UDP buffering is different. Many things can influence that.

Sure. I did include the Wireshark image, which provides [Wireshark centric] timestamps. These are admittedly not necessarily germane to SNMP4J’s timeout logic, but it’s at least curious. I asked this earlier: how does one enable timestamps on the log4j logging in SNMP4J log records?

OK, let us summarise:

  • Timeout is configured as 500ms
  • Maximum retry count is 1 (= one retry, means max. 2 request PDUs in total)
  • Wireshark log shows, that encrypting the first encrypted PDU takes about 600ms on your Win10.
  • Thus, when the first request is sent out, the retry is already overdue. That’s is why SNMP4J immediately sends the retry.

Those are the facts, so far.

So, the next question you may ask is:

  • Q: “Why is the encryption of the first PDU is taking so much time?”
  • A: On some operating systems, computing a secure random takes a lot of time. That time is only needed for the first hashing, or encryption/decryption operation.

How about this: a suggestion to update the v2 Javadoc to include this explicitly (can’t hurt, right?)?

Not a good idea im my opinion, because having a synchronized onResponse method in general is not always a good design. The onResponse method should run as fast as possible. So it is totally dependent on the users requirements, how you implement it.

In SNMP4J v3.x there is no Log4J anymore, by default. SNMP4J v3.x uses Java logging instead by default. You can use the ConsoleLogFactory to get a timestamped logging to stdout easily.

  • Wireshark log shows, that encrypting the first encrypted PDU takes about 600ms on your Win10.

Thank you! It certainly wasn’t clear to me that the timeout might be started long before the actual get-next-request was sent. But I can appreciate the trade-off here (starting the timer on the initial get-request vs. before the first get-next-request PDU). But this was a good clue that I should have detected (the corresponding Wireshark timestamps on the Linux run, not surprisingly, are much quicker).

  • A: On some operating systems, computing a secure random takes a lot of time. That time is only needed for the first hashing, or encryption/decryption operation.

Ya, interesting to see such a difference between Win10 and Linux (both are similarly classed systems with lots of memory, fast processors, and SSDs). It’s obvious I guess that this encryption also needs to be done prior to every PDU being sent, correct (i.e., there’s no way to optimize this on subsequent sends)?

Not a good idea im my opinion,

OK, fair enough.

I’ll look into setting up a formatter for the logger to review the underlying timestamps on the logging sequence…

Thanks for your help with this Frank, I really appreciate it. I’ve learned a lot already after my first day and half with SNMP4J ;).