[SNMP4J] Behaviour of ResponseListener in SNMP V3
Frank Fock
fock at agentpp.com
Wed Oct 12 23:43:01 CEST 2016
Hi Peter,
I just seem to have found the cause: The class
"SecureSnmpFactory$WrappedReportHandler" is not part of SNMP4J
and so I assume that this implementation is causing the issue.
Best regards,
Frank
Am 12.10.2016 um 16:29 schrieb Peter Verthez:
> Hi Frank,
>
> I found it suspicious that there was no real explanation, so I went
> back to my test, and unfortunately that test had succeeded with SNMP4J
> 2.5.2 because the agent was genuinely not reachable... When I tested
> again with an agent that should be reachable, I found the same
> problem, also with SNMP4J 2.5.2.
>
> I debugged a little in the SNMP4J code. The cancel is really
> happening after the report message, with the following stack trace:
>
> Daemon Thread [DefaultUDPTransportMapping_172.31.109.98/0] (Suspended
> (breakpoint at line 1925 in Snmp$PendingRequest))
> owns: Snmp$AsyncPendingRequest (id=36087)
> Snmp$AsyncPendingRequest(Snmp$PendingRequest).cancel() line: 1925
> Snmp$ReportProcessor.processReport(PduHandle,
> CommandResponderEvent) line: 1409
> SecureSnmpFactory$WrappedReportHandler.processReport(PduHandle,
> CommandResponderEvent) line: 157
> Snmp.processPdu(CommandResponderEvent) line: 1248
> MessageDispatcherImpl.fireProcessPdu(CommandResponderEvent) line: 691
> MessageDispatcherImpl.dispatchMessage(TransportMapping,
> MessageProcessingModel, Address, BERInputStream,
> TransportStateReference) line: 310
> MessageDispatcherImpl.processMessage(TransportMapping, Address,
> BERInputStream, TransportStateReference) line: 387
> MessageDispatcherImpl.processMessage(TransportMapping, Address,
> ByteBuffer, TransportStateReference) line: 347
> DefaultUdpTransportMapping(AbstractTransportMapping<A>).fireProcessMessage(Address,
> ByteBuffer, TransportStateReference) line: 76
> DefaultUdpTransportMapping$ListenThread.run() line: 425
> Thread.run() line: 745
>
> Here is what I find (with SNMP4J 2.5.2):
> - the 'usmStatsUnknownUserNames' report that we get here is handled in
> ReportProcessor.processReport
> - the resend variable stays false, because it is not one of the 3
> special cases given there in lines 1364-1380
> - as a consequence, the else is entered in line 1402, which cancels
> the request
> - the cancel request returns false here (apparently state of the
> PendingRequest is VIRGIN at that time), so that 'intime' is false on
> Snmp.java line 1414, which causes the listener not to be called
>
> So the question is: why is the state of the PendingRequest equal to
> VIRGIN? Is this unexpected?
>
> Best regards,
> Peter.
>
> On 11/10/2016 0:14, Frank Fock wrote:
>> Hi Peter,
>>
>> Thank you for trying version 2.5.2, although it seems to be
>> inexplicable why the behavior changed.
>> There are no changes in 2.5.2 and 2.5.1 in the class Snmp.
>>
>> Best regards,
>> Frank
>>
>> Am 10.10.2016 um 13:27 schrieb Peter Verthez:
>>> Traces now, for info:
>>>
>>> 2016-10-10 13:25:54,180 DEBUG
>>> [JM-45-Ping-Ping-7]-[org.snmp4j.security.UsmUserTable] Adding user
>>> verthezp_wrong2 =
>>> UsmUser[secName=verthezp_wrong2,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=12345678,privProtocol=null,privPassphrase=null,localizationEngineID=null]
>>> 2016-10-10 13:25:54,182 DEBUG
>>> [JM-45-Ping-Ping-7]-[org.snmp4j.security.USM] RFC3414 §3.1.4.b
>>> Outgoing message is not encrypted
>>> 2016-10-10 13:25:54,182 DEBUG
>>> [JM-45-Ping-Ping-7]-[org.snmp4j.mp.MPv3] Adding cache entry:
>>> StateReference[msgID=16001,pduHandle=PduHandle[922855848],securityEngineID=,securityModel=org.snmp4j.security.USM at 137719b6,securityName=verthezp_wrong2,securityLevel=1,contextEngineID=,contextName=nt,retryMsgIDs=null]
>>> 2016-10-10 13:25:54,182 DEBUG [JM-45-Ping-Ping-7]-[org.snmp4j.Snmp]
>>> Running pending async request with handle PduHandle[922855848] and
>>> retry count left 1
>>> 2016-10-10 13:25:54,182 DEBUG
>>> [JM-45-Ping-Ping-7]-[org.snmp4j.transport.DefaultUdpTransportMapping] Sending
>>> message to 135.249.41.7/161 with length 61:
>>> 30:3b:02:01:03:30:0f:02:02:3e:81: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:13:04:00:04:02:6e:74:a0:0b:02:01:00:02:01:00:02:01:00:30:00
>>> 2016-10-10 13:25:58,187 DEBUG [SNMP4J
>>> Timer]-[org.snmp4j.security.USM] RFC3414 §3.1.4.b Outgoing message
>>> is not encrypted
>>> 2016-10-10 13:25:58,187 DEBUG [SNMP4J Timer]-[org.snmp4j.mp.MPv3]
>>> Adding cache entry:
>>> StateReference[msgID=16002,pduHandle=PduHandle[922855848],securityEngineID=,securityModel=org.snmp4j.security.USM at 137719b6,securityName=verthezp_wrong2,securityLevel=1,contextEngineID=,contextName=nt,retryMsgIDs=null]
>>> 2016-10-10 13:25:58,188 DEBUG [SNMP4J Timer]-[org.snmp4j.mp.MPv3]
>>> Adding previous message IDs [16001] to new entry
>>> StateReference[msgID=16002,pduHandle=PduHandle[922855848],securityEngineID=,securityModel=org.snmp4j.security.USM at 137719b6,securityName=verthezp_wrong2,securityLevel=1,contextEngineID=,contextName=nt,retryMsgIDs=null]
>>> 2016-10-10 13:25:58,188 DEBUG [SNMP4J Timer]-[org.snmp4j.Snmp]
>>> Running pending async request with handle PduHandle[922855848] and
>>> retry count left 0
>>> 2016-10-10 13:25:58,188 DEBUG [SNMP4J
>>> Timer]-[org.snmp4j.transport.DefaultUdpTransportMapping] Sending
>>> message to 135.249.41.7/161 with length 61:
>>> 30:3b:02:01:03:30:0f:02:02:3e:82: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:13:04:00:04:02:6e:74:a0:0b:02:01:00:02:01:00:02:01:00:30:00
>>> 2016-10-10 13:26:06,188 DEBUG [SNMP4J Timer]-[org.snmp4j.Snmp]
>>> Request timed out: 922855848
>>> 2016-10-10 13:26:06,188 INFO [SNMP4J
>>> Timer]-[com.alcatel.util.net.snmp.SnmpUserTarget] Received response
>>> org.snmp4j.event.ResponseEvent[source=org.snmp4j.Snmp at dbb54af]
>>> 2016-10-10 13:26:06,189 DEBUG [SNMP4J Timer]-[org.snmp4j.Snmp]
>>> Cancelling pending request with handle PduHandle[922855848]
>>>
>>>
>>> Best regards,
>>> Peter.
>>>
>>>
>>> On 10/10/2016 13:25, Peter Verthez wrote:
>>>> Hi Frank,
>>>>
>>>> I've tried now with SNMP4J 2.5.2 (downloaded by manually changing
>>>> the download URL), and with that version I also can't reproduce the
>>>> problem anymore: the ResponseListener is now called.
>>>>
>>>> So we'll upgrade to that version.
>>>>
>>>> Thanks,
>>>> Peter.
>>>>
>>>>
>>>>
>>>> On 10/10/2016 8:19, Peter Verthez wrote:
>>>>> Hi Frank,
>>>>>
>>>>> Apparently the download page is not updated yet for SNMP4J 2.5.2?
>>>>>
>>>>> http://www.snmp4j.org/html/download.html
>>>>>
>>>>> Best regards,
>>>>> Peter.
>>>>>
>>>>>
>>>>> On 10/10/2016 7:58, Peter Verthez wrote:
>>>>>> Hi Frank,
>>>>>>
>>>>>> Answers on your possibilities:
>>>>>>
>>>>>> 1. No, the code that I showed in a previous mail is verbatim
>>>>>> copy/pasted from our source code, the snmp.send method call comes
>>>>>> directly after the creation of the ResponseListener.
>>>>>>
>>>>>> 2. No, we don't have an explicit cancel anywhere in our code,
>>>>>> except inside the ResponseListener, as I showed in the code in
>>>>>> the previous mail (which isn't reached).
>>>>>>
>>>>>> 3. No, we are using the original SNMP4J source code.
>>>>>>
>>>>>> I'll try with SNMP4J 2.5.2 to see whether that makes a difference.
>>>>>>
>>>>>> Best regards,
>>>>>> Peter.
>>>>>>
>>>>>>
>>>>>> On 9/10/2016 16:36, Frank Fock wrote:
>>>>>>> Hi Peter,
>>>>>>>
>>>>>>> Sorry, my statement in my previous message was wrong. Please
>>>>>>> ignore it, because
>>>>>>> setting the request-id field to 0 in a REPORT PDU is OK: If the
>>>>>>> request was encrypted
>>>>>>> the command responder would have no chance to decode the
>>>>>>> request-id field.
>>>>>>> That's is why the command generator has to be able to match the
>>>>>>> request anyway
>>>>>>> by the message-id field. SNMP4J is capable of that, so far, no
>>>>>>> problem.
>>>>>>>
>>>>>>> With SNMP4J 2.5.2 (current release) I still could not reproduce
>>>>>>> the issue.
>>>>>>> My unit test works as expected and calls the ResponseListener.
>>>>>>>
>>>>>>> From the code analysis, I see only three possibilities how the
>>>>>>> behavior you observed
>>>>>>> could happen:
>>>>>>>
>>>>>>> 1. The ReponseListener parameter is null (please check for a
>>>>>>> typo in the parameter name
>>>>>>> or a null assignment before the send call)
>>>>>>> 2. The pending request was cancelled by closing the Snmp session
>>>>>>> or cancelling the request
>>>>>>> (Normally this would have been reported in the log, but...)
>>>>>>> 3. You did not use the original SNMP4J source code.
>>>>>>>
>>>>>>> Best regards,
>>>>>>> Frank
>>>>>>>
>>>>>>>
>>>>>>> Am 09.10.2016 um 10:33 schrieb Frank Fock:
>>>>>>>> Hi Peter,
>>>>>>>>
>>>>>>>> The command responder is not setting the request-id correctly
>>>>>>>> in the REPORT PDU.
>>>>>>>> This is causing the issue on the SNMP4J side. Nevertheless,
>>>>>>>> SNMP4J should behave more
>>>>>>>> robust and should call the response listener after the request
>>>>>>>> times out.
>>>>>>>> I will add a corresponding unit test for that and fix it.
>>>>>>>>
>>>>>>>> Best regards,
>>>>>>>> Frank
>>>>>>>>
>>>>>>>> Am 07.10.2016 um 12:55 schrieb Peter Verthez:
>>>>>>>>> OK, my apologies: I was copying the wrong traces. Here are the
>>>>>>>>> correct ones. I've also added a logging message "Received
>>>>>>>>> response " + event in the first line of the
>>>>>>>>> ResponseListener.onResponse(), and the traces below show that
>>>>>>>>> it is not coming.
>>>>>>>>>
>>>>>>>>> 2016-10-07 12:51:17,934 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.security.UsmUserTable] Adding
>>>>>>>>> user verthezp_wrong2 =
>>>>>>>>> UsmUser[secName=verthezp_wrong2,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=12345678,privProtocol=null,privPassphrase=null,localizationEngineID=null]
>>>>>>>>> 2016-10-07 12:51:17,950 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.mp.MPv3] Context engine ID of
>>>>>>>>> scoped PDU is empty! Setting it to authoritative engine ID:
>>>>>>>>> 80:00:02:7d:03:00:90:d0:6d:fa:bc
>>>>>>>>> 2016-10-07 12:51:17,956 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.security.USM]
>>>>>>>>> getUser(engineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,
>>>>>>>>> securityName=verthezp_wrong2)
>>>>>>>>> 2016-10-07 12:51:17,964 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.security.USM] RFC3414 §3.1.4.b
>>>>>>>>> Outgoing message is not encrypted
>>>>>>>>> 2016-10-07 12:51:17,965 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.mp.MPv3] Adding cache entry:
>>>>>>>>> StateReference[msgID=46925,pduHandle=PduHandle[1444975050],securityEngineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,securityModel=org.snmp4j.security.USM at 529c7488,securityName=verthezp_wrong2,securityLevel=2,contextEngineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,contextName=nt,retryMsgIDs=null]
>>>>>>>>>
>>>>>>>>> 2016-10-07 12:51:17,972 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.Snmp] Running pending async
>>>>>>>>> request with handle PduHandle[1444975050] and retry count left 1
>>>>>>>>> 2016-10-07 12:51:17,973 DEBUG
>>>>>>>>> [JM-4-Ping-Ping-7]-[org.snmp4j.transport.DefaultUdpTransportMapping]
>>>>>>>>> Sending message to 135.249.41.7/161 with length 357:
>>>>>>>>> 30:82:01:61:02:01:03:30:10:02:03:00:b7:4d:02:03:00:ff:ff:04:01:05:02:01:03:04:38:30:36:04:0b:80:00:02:7d:03:00:90:d0:6d:fa:bc:02:01:08:02:03:02:86:91:04:0f:76:65:72:74:68:65:7a:70:5f:77:72:6f:6e:67:32:04:0c:c2:71:d3:1c:34:43:4a:bb:b8:ba:b2:93:04:00:30:82:01:0e:04:0b:80:00:02:7d:03:00:90:d0:6d:fa:bc:04:02:6e:74:a0:81:fa:02:04:56:20:91:ca:02:01:00:02:01:00:30:81:eb:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:06:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:09:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:02:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:23:3c:03:02:00:05:00:30:0c:06:08:2b:06:01:02:01:01:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:07:00:05:00:30:0c:06:08:2b:06:01:02:01:01:02:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:03:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:0d:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:17:02:01:04:01:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:01:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:02:00:05:00
>>>>>>>>>
>>>>>>>>> 2016-10-07 12:51:18,125 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.transport.DefaultUdpTransportMapping]
>>>>>>>>> Received message from /135.249.41.7/161 with length 103:
>>>>>>>>> 30:65:02:01:03:30:10:02:03:00:b7:4d:02:03:00:ff:ff:04:01:00:02:01:03:04:1d:30:1b:04:0b:80:00:02:7d:03:00:90:d0:6d:fa:bc:02:01:08:02:03:02:86:92:04:00:04:00:04:00:30:2f:04:0b:80:00:02:7d:03:00:90:d0:6d:fa:bc:04:02:6e:74: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:03:00:41:01:44
>>>>>>>>>
>>>>>>>>> 2016-10-07 12:51:18,125 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.mp.MPv3]
>>>>>>>>> SNMPv3 header decoded: msgId=46925, msgMaxSize=65535,
>>>>>>>>> msgFlags=00, secModel=3
>>>>>>>>> 2016-10-07 12:51:18,126 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.security.USM]
>>>>>>>>> Accepting zero length security name
>>>>>>>>> 2016-10-07 12:51:18,126 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.mp.MPv3]
>>>>>>>>> Removed cache entry:
>>>>>>>>> StateReference[msgID=46925,pduHandle=PduHandle[1444975050],securityEngineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,securityModel=org.snmp4j.security.USM at 529c7488,securityName=verthezp_wrong2,securityLevel=2,contextEngineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,contextName=nt,retryMsgIDs=null]
>>>>>>>>> 2016-10-07 12:51:18,126 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.mp.MPv3]
>>>>>>>>> RFC3412 §7.2.10 - Received PDU (msgID=46925) is a response or
>>>>>>>>> an internal class message. PduHandle.transactionID = 1444975050
>>>>>>>>> 2016-10-07 12:51:18,126 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.mp.MPv3]
>>>>>>>>> MPv3 finished
>>>>>>>>> 2016-10-07 12:51:18,126 DEBUG
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.Snmp]
>>>>>>>>> Searching pending request with handlePduHandle[1444975050]
>>>>>>>>> 2016-10-07 12:51:18,128 INFO
>>>>>>>>> [DefaultUDPTransportMapping_172.31.109.98/0]-[org.snmp4j.Snmp]
>>>>>>>>> Received late report from 135.249.41.7/161 with request ID 0
>>>>>>>>> 2016-10-07 12:51:21,973 DEBUG [SNMP4J Timer]-[org.snmp4j.Snmp]
>>>>>>>>> PendingRequest canceled key=null, pdu=null, target=null,
>>>>>>>>> transport=null, listener=null
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Best regards,
>>>>>>>>> Peter.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 7/10/2016 8:18, Peter Verthez wrote:
>>>>>>>>>> Ah, maybe I copied the wrong traces then and that is the
>>>>>>>>>> source of the confusion (we have a mix of SNMPv2 and v3 agents).
>>>>>>>>>>
>>>>>>>>>> Let me check...
>>>>>>>>>>
>>>>>>>>>> Thanks,
>>>>>>>>>> Peter.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 6/10/2016 21:45, Frank Fock wrote:
>>>>>>>>>>> Hi Peter,
>>>>>>>>>>>
>>>>>>>>>>> The PDU that is send is a SNMPv2c GET request and not a v3
>>>>>>>>>>> request.
>>>>>>>>>>> So this cannot be an issue with the USM or other v3 processing.
>>>>>>>>>>>
>>>>>>>>>>> To be able to reproduce the issue I might need more details.
>>>>>>>>>>> If it is indeed
>>>>>>>>>>> a v3 request, I would like to have the log for it. In addition,
>>>>>>>>>>> is the "unknown user" locally unknown the the USM of the
>>>>>>>>>>> command
>>>>>>>>>>> sender or remotely unknown to the command responder.
>>>>>>>>>>>
>>>>>>>>>>> If locally unknown, a exception is thrown during the send call.
>>>>>>>>>>>
>>>>>>>>>>> Best regards,
>>>>>>>>>>> Frank
>>>>>>>>>>>
>>>>>>>>>>> Am 06.10.2016 um 09:45 schrieb Peter Verthez:
>>>>>>>>>>>> Hi Frank,
>>>>>>>>>>>>
>>>>>>>>>>>> The PDU instance is not used in another thread, only in
>>>>>>>>>>>> this one. All normal functionality works properly (we
>>>>>>>>>>>> started to use async requests 1.5 years ago), except for
>>>>>>>>>>>> this timeout due to a wrong security name being used. I'm
>>>>>>>>>>>> not sure whether that is a new regression or something that
>>>>>>>>>>>> wasn't tested before by our test team.
>>>>>>>>>>>>
>>>>>>>>>>>> I'm not sure which further information I have to give, I
>>>>>>>>>>>> can't provide the full source code as this is a proprietary
>>>>>>>>>>>> product. If you want me to debug something specific I can
>>>>>>>>>>>> do that.
>>>>>>>>>>>>
>>>>>>>>>>>> Best regards,
>>>>>>>>>>>> Peter.
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 5/10/2016 22:55, Frank Fock wrote:
>>>>>>>>>>>>> Hi Peter,
>>>>>>>>>>>>>
>>>>>>>>>>>>> From the provided send call alone, I cannot verify if the
>>>>>>>>>>>>> parameters are correctly
>>>>>>>>>>>>> setup. The SnmpUserTarget.this, for example, might not
>>>>>>>>>>>>> work if called in a constructor
>>>>>>>>>>>>> of that class.
>>>>>>>>>>>>>
>>>>>>>>>>>>> The pdu instance might be used concurrently by another
>>>>>>>>>>>>> thread (with same or different
>>>>>>>>>>>>> request ID), which would corrupt the pending request
>>>>>>>>>>>>> management.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>> Frank
>>>>>>>>>>>>>
>>>>>>>>>>>>> Am 05.10.2016 um 08:14 schrieb Peter Verthez:
>>>>>>>>>>>>>> Hi Frank,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> The call of the send method was in the last line of my
>>>>>>>>>>>>>> code snippet: session is an Snmp object.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>>> Peter.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On 4/10/2016 20:12, Frank Fock wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Hi Peter,
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> How do call the send method? Is the listener set there?
>>>>>>>>>>>>>>> All fields null should not happen normally....
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>>>> Frank
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Am 04.10.2016 um 11:18 schrieb Peter Verthez:
>>>>>>>>>>>>>>>> Hi Frank,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Our code is simply:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> ResponseListener respListener = new
>>>>>>>>>>>>>>>> ResponseListener() {
>>>>>>>>>>>>>>>> @Override
>>>>>>>>>>>>>>>> public void
>>>>>>>>>>>>>>>> onResponse(ResponseEvent event) {
>>>>>>>>>>>>>>>> // canceling is required as
>>>>>>>>>>>>>>>> per SNMP4J documentation
>>>>>>>>>>>>>>>> ((Snmp)event.getSource()).cancel(event.getRequest(),
>>>>>>>>>>>>>>>> this);
>>>>>>>>>>>>>>>> PDU response =
>>>>>>>>>>>>>>>> event.getResponse();
>>>>>>>>>>>>>>>> updateStats(session, agentId, startTime, response);
>>>>>>>>>>>>>>>> listener.onResponse(response, event.getUserObject());
>>>>>>>>>>>>>>>> }
>>>>>>>>>>>>>>>> };
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> session.send(pdu, SnmpUserTarget.this, userContext,
>>>>>>>>>>>>>>>> respListener);
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> It doesn't reach even the first line of the onResponse
>>>>>>>>>>>>>>>> method.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I've been debugging a little, and the
>>>>>>>>>>>>>>>> PendingRequest.run() method in the Snmp class is always
>>>>>>>>>>>>>>>> being exited because all fields are null, and so it
>>>>>>>>>>>>>>>> never calls the onResponse method on the listener. This
>>>>>>>>>>>>>>>> is also what the debug message says:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> 2016-09-28 16:43:36,861 DEBUG [SNMP4J
>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.Snmp] PendingRequest canceled
>>>>>>>>>>>>>>>> key=null, pdu=null, target=null, transport=null,
>>>>>>>>>>>>>>>> listener=null
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I've then put a breakpoint in the cancel() method, and
>>>>>>>>>>>>>>>> it gets run when the following report is coming in
>>>>>>>>>>>>>>>> (copied from the debugger):
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> REPORT[{contextEngineID=80:00:02:7d:03:00:90:d0:6d:fa:bc,
>>>>>>>>>>>>>>>> contextName=nt}, requestID=0, errorStatus=0,
>>>>>>>>>>>>>>>> errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.3.0 = 18]]
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>>>>> Peter.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On 3/10/2016 23:06, Frank Fock wrote:
>>>>>>>>>>>>>>>>> Hi Peter,
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Yes, the ResponseEvent should be returned after the
>>>>>>>>>>>>>>>>> timeout with a null response.
>>>>>>>>>>>>>>>>> From the log, it is unclear why you do not get the
>>>>>>>>>>>>>>>>> event. Is there an if-statement
>>>>>>>>>>>>>>>>> that ignores the ResponseEvent with null response in
>>>>>>>>>>>>>>>>> your code?
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>>>>>> Frank
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Am 30.09.2016 um 10:12 schrieb Peter Verthez:
>>>>>>>>>>>>>>>>>> Hi Frank,
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> If we are using asynchronous SNMP calls with SNMPv3,
>>>>>>>>>>>>>>>>>> what should be the behaviour in case of timeout, when
>>>>>>>>>>>>>>>>>> you used wrong credentials such as a wrong user name.
>>>>>>>>>>>>>>>>>> Should the ResponseListener always be triggered, with
>>>>>>>>>>>>>>>>>> event.getResponse() = null, after the timeout?
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> I would expect that, but it looks like this is not
>>>>>>>>>>>>>>>>>> what I'm seeing: the ResponseListener does not seem
>>>>>>>>>>>>>>>>>> to be triggered in that case. So this means that our
>>>>>>>>>>>>>>>>>> application never knows that a timeout occurred. We
>>>>>>>>>>>>>>>>>> are using currently SNMP4J 2.5.0. Debug logging from
>>>>>>>>>>>>>>>>>> SNMP4J:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:31,768 DEBUG
>>>>>>>>>>>>>>>>>> [JM-49-Ping-Ping-4]-[org.snmp4j.Snmp] Running pending
>>>>>>>>>>>>>>>>>> async request with handle PduHandle[1071987217] and
>>>>>>>>>>>>>>>>>> retry count left 1
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:31,768 DEBUG
>>>>>>>>>>>>>>>>>> [JM-49-Ping-Ping-4]-[org.snmp4j.transport.DefaultUdpTransportMapping]
>>>>>>>>>>>>>>>>>> Sending message to 135.249.41.44/161 with length 268:
>>>>>>>>>>>>>>>>>> 30:82:01:08:02:01:01:04:06:70:75:62:6c:69:63:a0:81:fa:02:04:3f:e5:3a:11:02:01:00:02:01:00:30:81:eb:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:06:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:09:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:02:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:23:3c:03:02:00:05:00:30:0c:06:08:2b:06:01:02:01:01:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:07:00:05:00:30:0c:06:08:2b:06:01:02:01:01:02:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:03:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:0d:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:17:02:01:04:01:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:01:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:02:00:05:00
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:35,771 DEBUG [SNMP4J
>>>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.Snmp] Running pending async
>>>>>>>>>>>>>>>>>> request with handle PduHandle[1071987217] and retry
>>>>>>>>>>>>>>>>>> count left 0
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:35,771 DEBUG [SNMP4J
>>>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.transport.DefaultUdpTransportMapping]
>>>>>>>>>>>>>>>>>> Sending message to 135.249.41.44/161 with length 268:
>>>>>>>>>>>>>>>>>> 30:82:01:08:02:01:01:04:06:70:75:62:6c:69:63:a0:81:fa:02:04:3f:e5:3a:11:02:01:00:02:01:00:30:81:eb:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:06:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:09:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:0b:02:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:23:3c:03:02:00:05:00:30:0c:06:08:2b:06:01:02:01:01:03:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:07:00:05:00:30:0c:06:08:2b:06:01:02:01:01:02:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:17:01:03:00:05:00:30:10:06:0c:2b:06:01:04:01:84:7d:3d:01:09:0d:00:05:00:30:12:06:0e:2b:06:01:04:01:84:7d:3d:01:17:02:01:04:01:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:01:00:05:00:30:11:06:0d:2b:06:01:04:01:84:7d:3d:01:09:1c:02:00:05:00
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:36,861 DEBUG [SNMP4J
>>>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.Snmp] PendingRequest canceled
>>>>>>>>>>>>>>>>>> key=null, pdu=null, target=null, transport=null,
>>>>>>>>>>>>>>>>>> listener=null
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:43,771 DEBUG [SNMP4J
>>>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.Snmp] Request timed out: 1071987217
>>>>>>>>>>>>>>>>>> 2016-09-28 16:43:43,772 DEBUG [SNMP4J
>>>>>>>>>>>>>>>>>> Timer]-[org.snmp4j.Snmp] Cancelling pending request
>>>>>>>>>>>>>>>>>> with handle PduHandle[1071987217]
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Best regards,
>>>>>>>>>>>>>>>>>> Peter.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>> _______________________________________________
>>>>>>> SNMP4J mailing list
>>>>>>> SNMP4J at agentpp.org
>>>>>>> https://oosnmp.net/mailman/listinfo/snmp4j
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>
>
--
---
AGENT++
Maximilian-Kolbe-Str. 10
73257 Koengen, Germany
https://agentpp.com
Phone: +49 7024 8688230
Fax: +49 7024 8688231
More information about the SNMP4J
mailing list