Hi Frank,
I have an snmpManager application running (IP 192.168.240.30/24) that is
polling my snmp4j agent (snmp4j agent v2.5.0/snmp4j 2.5.0 - IP
192.168.240.20/24).
In my manager I am using snmp4j 2.5.0 for my snmp requests.
I see, somewhat frequently, timeouts occurring on my manager even though I am
getting responses.
The responses are actually returned from my agent to my manager. I verified it
in wireshark and I see the response received in my log but for some reason the
packet is getting dropped I think by snmp4j before it reaches my application.
Then 10 seconds later (my timeout value) I see the request timeout in my log
due to the response being dropped.
I have looked into it but getting nowhere so not sure if its a timing thing or
something related to my manager application.
I have attached the snmp4j log (snmp4j-timeout_2.log) and the wireshark capture
(nullpreset12-snmp4j-timeout.pcapng) of a request and the response returned
from the agent but getting dropped by my manager.
the snmp message ID is 62420 and the PDU request ID is 2117843898.
I only have 1 thread running that is polling the agent.
The timestamp in the log for the request being sent is
2016-07-06 13:34:43,673
The response is received at
2016-07-06 13:34:43,683
I see the request handle lookup for the response at
13:34:43,685
I see a subsequent request handle cancel at
2016-07-06 13:34:43,688 but its for a different PDU request ID (129664087).
I do see a
ConcurrentModificationException at
2016-07-06 13:34:43,698
The timeout for the request is at timestamp:
2016-07-06 13:34:53,889
the wireshark pcap has the request and the response that is dropped by the
snmp4j in my manager application.
I am not sure if the exception is causing my issue or not since I am not sure
if that is related to the PDU in question.
thanks
Rushik
2016-07-06 13:34:43,670 [Thread-3] DEBUG org.snmp4j.mp.MPv3 - Context engine ID
of scoped PDU is empty! Setting it to authoritative engine ID:
80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee
2016-07-06 13:34:43,670 [Thread-3] DEBUG org.snmp4j.security.USM -
getUser(engineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee, securityName=MAagent)
2016-07-06 13:34:43,671 [Thread-3] DEBUG org.snmp4j.security.USM - RFC3414
§3.1.4.a Outgoing message needs to be encrypted
2016-07-06 13:34:43,671 [Thread-3] DEBUG org.snmp4j.security.PrivDES -
Preparing decrypt_params.
2016-07-06 13:34:43,671 [Thread-3] DEBUG org.snmp4j.security.PrivDES -
Preparing iv for encryption.
2016-07-06 13:34:43,671 [Thread-3] DEBUG org.snmp4j.security.PrivacyGeneric -
Using padding.
2016-07-06 13:34:43,671 [Thread-3] DEBUG org.snmp4j.security.PrivDES -
Encryption finished.
2016-07-06 13:34:43,672 [Thread-3] DEBUG org.snmp4j.mp.MPv3 - Adding cache
entry:
StateReference[msgID=62420,pduHandle=PduHandle[2117843898],securityEngineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee,securityModel=org.snmp4j.security.USM@f2106d8,securityName=MAagent,securityLevel=3,contextEngineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee,contextName=,retryMsgIDs=null]
2016-07-06 13:34:43,672 [Thread-3] DEBUG org.snmp4j.Snmp - Running pending sync
request with handle PduHandle[2117843898] and retry count left 1
2016-07-06 13:34:43,673 [Thread-3] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to
192.168.240.20/161 with length 215:
30:81:d4:02:01:03:30:10:02:03:00:f3:d4:02:03:00:ff:ff:04:01:07:02:01:03:04:3a:30:38:04:0d:80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee:02:01:61:02:03:01:4f:19:04:07:4d:41:61:67:65:6e:74:04:0c:99:fd:89:87:d9:31:a4:9a:21:20:d3:d6:04:08:00:00:00:61:c9:c4:7e:5f:04:81:80:d1:22:6d:3c:a7:0e:ab:88:d1:50:c8:04:eb:c7:e3:35:a3:e3:ce:7d:42:2c:81:01:c3:82:04:4c:6c:79:08:fe:04:df:59:45:31:54:b0:8d:4c:36:d5:41:1d:63:4e:4d:ca:6c:5d:09:d5:2c:5d:21:d6:59:ab:1f:c0:c0:53:fc:ae:c1:10:74:fe:28:8e:19:fa:df:c6:d9:f2:2c:db:d8:6d:e6:1f:33:9c:99:63:4a:dd:13:b1:d8:fe:6a:1b:61:e3:e3:fd:ee:22:7b:d7:68:37:91:42:9f:5b:0e:ad:41:b4:a9:89:be:28:35:ff:46:cf:d5:6e:54:4f:b4:53:99
2016-07-06 13:34:43,676 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Received message from
/192.168.240.50/161 with length 146:
30:81:8f:02:01:03:30:10:02:03:00:f5:4d:02:03:00:ff:e3:04:01:03:02:01:03:04:36:30:34:04:0d:80:00:1f:88:80:fb:33:a1:77:31:00:00:00:02:01:21:02:03:0b:ff:4a:04:03:6e:76:74:04:0c:6d:22:c8:b2:c3:20:9f:95:ee:12:49:4a:04:08:00:00:00:21:42:b9:0b:8f:04:40:0a:dc:3d:ba:15:5c:05:d5:05:d6:ee:dc:81:8e:89:d4:4d:61:4b:f8:b0:56:c9:0e:3d:15:d4:af:07:a0:8c:b2:6f:79:1b:1b:92:54:cd:53:1b:36:fb:af:72:b0:ff:91:04:ff:67:ea:4d:b5:93:b1:6a:24:c8:d5:83:e6:67:90
2016-07-06 13:34:43,677 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=62797, msgMaxSize=65507,
msgFlags=03, secModel=3
2016-07-06 13:34:43,677 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.security.USM -
getUser(engineID=80:00:1f:88:80:fb:33:a1:77:31:00:00:00, securityName=nvt)
2016-07-06 13:34:43,678 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.security.UsmTimeTable - CheckTime: time ok (non authoritative)
2016-07-06 13:34:43,679 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - Removed cache entry:
StateReference[msgID=62797,pduHandle=PduHandle[1292664087],securityEngineID=80:00:1f:88:80:fb:33:a1:77:31:00:00:00,securityModel=org.snmp4j.security.USM@2e10ecf6,securityName=nvt,securityLevel=3,contextEngineID=80:00:1f:88:80:fb:33:a1:77:31:00:00:00,contextName=,retryMsgIDs=null]
2016-07-06 13:34:43,679 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU (msgID=62797) is a
response or an internal class message. PduHandle.transactionID = 1292664087
2016-07-06 13:34:43,679 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - MPv3 finished
2016-07-06 13:34:43,679 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.Snmp - Looking up pending request with handle PduHandle[1292664087]
2016-07-06 13:34:43,683 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Received message from
/192.168.240.20/161 with length 239:
30:81:ec:02:01:03:30:10:02:03:00:f3:d4:02:03:00:ff:ff:04:01:03:02:01:03:04:3a:30:38:04:0d:80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee:02:01:61:02:03:01:4f:18:04:07:4d:41:61:67:65:6e:74:04:0c:1c:bd:fc:7d:6e:4d:2b:5a:6e:65:e6:b5:04:08:00:00:00:61:03:60:b6:e0:04:81:98:ae:be:1c:a2:36:22:26:59:36:2a:47:ff:ab:f3:d3:ea:f5:6b:33:dd:9f:22:60:7b:73:ab:9a:95:eb:7c:1c:34:46:13:fc:94:1c:59:47:ca:e7:eb:5f:1c:e3:6b:f9:26:43:0a:95:5a:92:e4:dd:33:5e:b7:63:b9:89:38:bb:9e:54:e7:55:fc:6f:3c:e8:a4:a1:ff:5d:0c:9f:7c:8a:51:19:33:86:e2:ec:22:e0:30:b4:4e:56:56:21:6c:4d:97:54:f2:a3:cb:39:96:ee:d2:c7:b4:1e:fd:82:c2:cc:81:48:80:59:a8:94:96:90:59:29:fd:4e:1c:c8:23:d6:90:13:bf:9b:3d:b5:ff:21:67:6c:2c:12:b7:e1:bf:66:f3:89:00:f7:e0:5f:4c:69:f0
2016-07-06 13:34:43,683 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=62420, msgMaxSize=65535,
msgFlags=03, secModel=3
2016-07-06 13:34:43,684 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.security.USM -
getUser(engineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee, securityName=MAagent)
2016-07-06 13:34:43,684 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.security.UsmTimeTable - CheckTime: time ok (non authoritative)
2016-07-06 13:34:43,685 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - Removed cache entry:
StateReference[msgID=62420,pduHandle=PduHandle[2117843898],securityEngineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee,securityModel=org.snmp4j.security.USM@f2106d8,securityName=MAagent,securityLevel=3,contextEngineID=80:00:13:70:01:2c:2c:2c:2c:78:bf:84:ee,contextName=,retryMsgIDs=null]
2016-07-06 13:34:43,685 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU (msgID=62420) is a
response or an internal class message. PduHandle.transactionID = 2117843898
2016-07-06 13:34:43,685 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.mp.MPv3 - MPv3 finished
2016-07-06 13:34:43,685 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.Snmp - Looking up pending request with handle PduHandle[2117843898]
2016-07-06 13:34:43,688 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.Snmp - Cancelling pending request with handle PduHandle[1292664087]
2016-07-06 13:34:43,689 [Thread-13] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Terminated worker task:
org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2016-07-06 13:34:43,689 [Thread-13] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Interrupting worker task:
org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2016-07-06 13:34:43,689 [Thread-13] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Joining worker task:
org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2016-07-06 13:34:43,689 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - Worker task
stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2016-07-06 13:34:43,694 [Thread-13] DEBUG org.snmp4j.mp.MPv3 - Local host
cannot be determined for creation of local engine ID
2016-07-06 13:34:43,698 [DefaultUDPTransportMapping_0.0.0.0/0] ERROR
org.snmp4j.MessageDispatcherImpl - java.util.ConcurrentModificationException
2016-07-06 13:34:43,703 [Thread-13] DEBUG org.snmp4j.mp.MPv3 - Local host
cannot be determined for creation of local engine ID
2016-07-06 13:34:43,704 [Thread-13] DEBUG org.snmp4j.security.UsmUserTable -
Adding user nvt =
UsmUser[secName=nvt,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=sixnet123,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=sixnet123,localizationEngineID=null]
2016-07-06 13:34:43,706 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for
socket 0.0.0.0/0 is set to: 62464
2016-07-06 13:34:43,706 [Thread-13] DEBUG org.snmp4j.security.USM - RFC3414
§3.1.4.b Outgoing message is not encrypted
2016-07-06 13:34:43,707 [Thread-13] DEBUG org.snmp4j.mp.MPv3 - Adding cache
entry:
StateReference[msgID=4945,pduHandle=PduHandle[1565824822],securityEngineID=,securityModel=org.snmp4j.security.USM@28d81627,securityName=nvt,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
2016-07-06 13:34:43,707 [Thread-13] DEBUG org.snmp4j.Snmp - Running pending
async request with handle PduHandle[1565824822] and retry count left 1
2016-07-06 13:34:53,889 [Timer-0] DEBUG org.snmp4j.Snmp - Request timed out:
2117843898
2016-07-06 13:34:53,890 [Thread-3] DEBUG org.snmp4j.Snmp - Removed pending
request with handle: PduHandle[2117843898]
2016-07-06 13:34:53,890 [Thread-3] DEBUG LTI -
LtiVictoryDataRadioThread::snmpRequestForPresetPropTable() event response is
null on preset: 12
_______________________________________________
SNMP4J mailing list
[email protected]
https://oosnmp.net/mailman/listinfo/snmp4j
