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
