Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
Hi Frank,
OK, I found the issue. We are providing our own TimerFactory, because
we found that in certain cases the timer of SNMP4J could leak
exceptions, which was causing problems in our application (a timer is
not run anymore when one of its tasks is throwing an exception, see e.g.
http://bryanpendleton.blogspot.fr/2009/05/timertask-exception-handling.html
for details).
So basically we have a TimerTask that encapsulates the TimerTask from
SNMP4J and which does:
@Override
public void run() {
try {
m_inner.run();
}
catch (Exception t) {
m_log.error("Exception leaked out of TimerTask", t);
}
}
But that means that the state set by schedule is not propagated to the
m_inner, which is the AsyncPendingRequest. That is causing the problem
here. Strange that we did not see this before, because we have this
TimerFactory already since 2009, but in any case that is the cause of
the issue.
I'll fix that at our end. But should this vulnerability in
PendingRequest.run() be examined at your end, so that we don't need to
do this workaround?
In any case, thanks for all your help!
Best regards,
Peter.
On 13/10/2016 8:56, Peter Verthez wrote:
Hi Frank,
That WrappedReportHandler is the following (because we otherwise don't
have visibility about reports in our logs):
private static class WrappedReportHandler implements ReportHandler {
private final ReportHandler m_inner;
private final SnmpTracer m_snmpTracer = new Log4jSnmpTracer();
public WrappedReportHandler(ReportHandler inner) {
m_inner = inner;
}
@Override
public void processReport(PduHandle pduHandle,
CommandResponderEvent event) {
m_snmpTracer.logReport(event);
m_inner.processReport(pduHandle, event);
}
}
I don't see how this can affect the processing (event is not modified
in the logReport method).
We are using the MessageDispatcherImpl from SNMP4J.
I'll debug further later today to verify the expectations that you have.
Thanks,
Peter.
On 12/10/2016 23:43, Frank Fock wrote:
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).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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
Hi Frank,
That WrappedReportHandler is the following (because we otherwise don't
have visibility about reports in our logs):
private static class WrappedReportHandler implements ReportHandler {
private final ReportHandler m_inner;
private final SnmpTracer m_snmpTracer = new Log4jSnmpTracer();
public WrappedReportHandler(ReportHandler inner) {
m_inner = inner;
}
@Override
public void processReport(PduHandle pduHandle,
CommandResponderEvent event) {
m_snmpTracer.logReport(event);
m_inner.processReport(pduHandle, event);
}
}
I don't see how this can affect the processing (event is not modified in
the logReport method).
We are using the MessageDispatcherImpl from SNMP4J.
I'll debug further later today to verify the expectations that you have.
Thanks,
Peter.
On 12/10/2016 23:43, Frank Fock wrote:
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).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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
Hi Peter, You analysis matches mine. The problem is, that the cancel returns true on my system and with my unit test in that case. From reading the code, the cancel must return true in this case, because the pending request is already scheduled at that time which is ensured by the pduHandleAssigned callback from the MessageDispatcherImpl.sendPdu. Are you using your own MessageDispatcher that does not call the callback. (Sorry, I have no plausible other idea...) 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).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@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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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@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@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@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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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@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@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@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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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@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@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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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:
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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
Re: [SNMP4J] Behaviour of ResponseListener in SNMP V3
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. -- --- AGENT++ Maximilian-Kolbe-Str. 10 73257 Koengen, Germany https://agentpp.com Phone: +49 7024 8688230 Fax: +49 7024 8688231 ___ SNMP4J mailing list SNMP4J@agentpp.org https://oosnmp.net/mailman/listinfo/snmp4j
