[SNMP4J] Behaviour of ResponseListener in SNMP V3
Frank Fock
fock at agentpp.com
Sun Oct 9 16:36:49 CEST 2016
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.
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>>
>>
>>
>
More information about the SNMP4J
mailing list