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 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 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
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@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
_______________________________________________
SNMP4J mailing list
SNMP4J@agentpp.org
https://oosnmp.net/mailman/listinfo/snmp4j