Re: [SNMP4J] Timeouts in version 2.5.7+
Hi Steffen,
I understood the problem very well, but I am trying to find a possible cause.
In past, users have chosen a very low timeout because it worked - the system(s)
answered very fast and SNMP4J timeout mechanism was not fast enough to timeout
the request although the timeout value was lower than the effective response
time.
This behaviour then changed by some other timing side effect and all answers
were timed out then.
I just wanted to sort this out, but you did not provide your timeout value
though.
As supporter it is very difficult to operate with too few facts.
As you can see from the following code of the DefaultUdpTransportMapping class,
the “Received…” log message must be printed out if something was received from
the UDP port:
public void run() {
DatagramSocket socketCopy = socket;
if (socketCopy != null) {
try {
socketCopy.setSoTimeout(getSocketTimeout());
if (receiveBufferSize > 0) {
socketCopy.setReceiveBufferSize(Math.max(receiveBufferSize,
maxInboundMessageSize));
}
if (logger.isDebugEnabled()) {
logger.debug("UDP receive buffer size for socket " +
getAddress() + " is set to: " +
socketCopy.getReceiveBufferSize());
}
} catch (SocketException ex) {
logger.error(ex);
setSocketTimeout(0);
}
}
while (!stop) {
DatagramPacket packet = new DatagramPacket(buf, buf.length,
udpAddress.getInetAddress(),
udpAddress.getPort());
try {
socketCopy = socket;
ByteBuffer bis;
TransportStateReference stateReference =
new TransportStateReference(DefaultUdpTransportMapping.this,
udpAddress, null,
SecurityLevel.undefined, SecurityLevel.undefined,
false, socketCopy);
try {
if (socketCopy == null) {
stop = true;
continue;
}
try {
socketCopy.receive(packet);
}
catch (SocketTimeoutException ste) {
continue;
}
bis = prepareInPacket(packet, buf, stateReference);
}
catch (InterruptedIOException iiox) {
if (iiox.bytesTransferred <= 0) {
continue;
}
bis = prepareInPacket(packet, buf, stateReference);
}
if (logger.isDebugEnabled()) {
logger.debug("Received message from "+packet.getAddress()+"/"+
packet.getPort()+
" with length "+packet.getLength()+": "+
new OctetString(packet.getData(), 0,
packet.getLength()).toHexString());
}
if (bis != null) {
fireProcessMessage(new UdpAddress(packet.getAddress(),
packet.getPort()), bis, stateReference);
}
}
catch (SocketTimeoutException stex) {
// ignore
}
catch (PortUnreachableException purex) {
synchronized (DefaultUdpTransportMapping.this) {
listener = null;
}
logger.error(purex);
if (logger.isDebugEnabled()) {
purex.printStackTrace();
}
if (SNMP4JSettings.isForwardRuntimeExceptions()) {
throw new RuntimeException(purex);
}
break;
}
catch (SocketException soex) {
if (!stop) {
logger.warn("Socket for transport mapping " + toString() + " error: " +
soex.getMessage());
}
if (SNMP4JSettings.isForwardRuntimeExceptions()) {
stop = true;
throw new RuntimeException(soex);
}
else if (!stop) {
try {
DatagramSocket newSocket = renewSocketAfterException(soex,
socketCopy);
if (newSocket == null) {
throw soex;
}
socket = newSocket;
} catch (SocketException e) {
stop = true;
socket = null;
logger.error("Socket renewal for transport mapping " + toString() +
" failed with: " + e.getMessage(), e);
}
}
}
catch (IOException iox) {
logger.warn(iox);
if (logger.isDebugEnabled()) {
iox.printStackTrace();
}
if (SNMP4JSettings.isForwardRuntimeExceptions()) {
throw new RuntimeException(iox);
}
}
}
If that is not the case,
(a) either Java is not able to receive UDP packets from that socket anymore
(then none of the possible reasons is caused by the SNMP4J stack or a specific
version of it)
(b) The while loop is exited.
Possible reasons for (b) could be an API call or an uncaught exception within
the while loop.
Can you reproduce the issue with a simple MIB walk or an application where you
ca share the log - at least the snippet between last successful answer
processing and the first failure?
Best regards,
Frank
> On 9. Apr 2018, at 15:19, Steffen Brüntjen
> wrote:
>
> Hi!
>
>> Is your timeout value big enough?
>
> It seem
Re: [SNMP4J] Timeouts in version 2.5.7+
Hi! > Is your timeout value big enough? It seems I couldn't make the problem clear, so once again from the beginning. I've been sending millions of millions SNMP queries over a long time, like months, with no problems. Then I replaced SNMP4J version 2.5.6 with version 2.5.7 (it can be any other newer release) and restarted the program. The program starts running fine again, but only for some comparatively short amount of time (sometimes 10 minutes, sometimes 2 days). From the moment on, when the problem arises, NO more SNMP packets are received at all. There's not a single SNMP request that results in something else but a timeout. I made no configuration changes like timeouts/retries, no changes in the network, none of the 200 devices change and no one has access to the machine. Consequently, when I restart the program, it runs fine again. So I bet a too low timeout can't be the problem. As an example here's my last test. I extracted all data from SNMP4J log messages: 2018-04-05 10:43 Program starts 2018-04-05 10:43 First outgoing SNMP request 2018-04-05 22:23 Last incoming message 2018-04-09 . Program is still running (until today) 4,994,621 sent messages from 2018-04-05 10:43 to 22:23 4,992,120 received msgs from 2018-04-05 10:43 to 22:23 53,323 sent messages from 2018-04-05 22:23 to now 0 received msgs from 2018-04-05 22:23 to now (The different number of outgoing requests per amount of time comes from the fact I wrote in my first mail: The program queries the sysObjectId and then - if successful - more OIDs. If the sysObjectId can't be queried, the rest of communication doesn't take place.) > I do not see any differences in the stacktraces, do I miss something? In your last mail you wrote, that "From the stack trace it seems that there is no idle TaskManager in your ThreadPool for the MultiThreadMessageDispatcher left.". So with the two identical stack traces I was trying to point out that there's no indication of a missing TaskManager thread. Best regards and thanks, Steffen Brüntjen -Original Message- From: Frank Fock [mailto:f...@agentpp.com] Sent: Freitag, 6. April 2018 15:40 To: Steffen Brüntjen Cc: snmp4j@agentpp.org Subject: Re: [SNMP4J] Timeouts in version 2.5.7+ Is your timeout value big enough? I do not see any differences in the stacktraces, do I miss something? > Am 06.04.2018 um 14:15 schrieb Steffen Brüntjen : > > Hi Frank > > Mmh, I don't think it's because of uncaught exceptions (at least not outside > of SNMP4J). SNMP packets are continued to be sent out normally, the responses > are received by kernel but not "recognized" by SNMP4J (see tcpdump output). I > get normal timeouts as if the devices wouldn't respond any more (but they > do). I reproduced the problem once again with TRACE logging enabled. The > SNMP4J logs appear to be very normal, except that there are no more "Received > message from ... with length ...: ..." messages any more > (DefaultUdpTransportMapping.java:409). Here are the different types of log > messages after problem occurs (in random order): > > Sending message to .../161 with length 43: ... | > (DefaultUdpTransportMapping.java:112) > Removed pending request with handle: PduHandle[...] | (Snmp.java:995) > Request timed out: ... | (Snmp.java:1900) > Running pending sync request with handle PduHandle[...] and retry count left > 1 | (Snmp.java:1808) > > > The stacktraces look the same when everything is running fine: > > "snmp.3" #39 prio=5 os_prio=0 tid=0x7f682a81a000 nid=0x2a71 in > Object.wait() [0x7f67932f9000] > java.lang.Thread.State: WAITING (on object monitor) >at java.lang.Object.wait(Native Method) >at java.lang.Object.wait(Object.java:502) >at org.snmp4j.util.ThreadPool$TaskManager.run(ThreadPool.java:275) >- locked <0x88861810> (a org.snmp4j.util.ThreadPool$TaskManager) > > "snmp.2" #38 prio=5 os_prio=0 tid=0x7f682a818000 nid=0x2a70 in > Object.wait() [0x7f67933fa000] > java.lang.Thread.State: WAITING (on object monitor) >at java.lang.Object.wait(Native Method) >at java.lang.Object.wait(Object.java:502) >at org.snmp4j.util.ThreadPool$TaskManager.run(ThreadPool.java:275) >- locked <0x88861a20> (a org.snmp4j.util.ThreadPool$TaskManager) > > "snmp.1" #37 prio=5 os_prio=0 tid=0x7f6829986800 nid=0x2a6f in > Object.wait() [0x7f67934fb000] > java.lang.Thread.State: WAITING (on object monitor) >at java.lang.Object.wait(Native Method) >at java.lang.Object.wait(Object.java:502) >at org.snmp4j.util.ThreadPool$TaskManager.run(ThreadPool.java:275) >- locked <0x88861c30> (a org.snmp4j.util.ThreadPool$TaskManager) > > "snmp.0" #36 prio=5 os_prio=0 tid=0x7f6829988800 nid=0x2a6e in > Object.wait() [0x7f67935fc000] > java.lang.Thread.State: WAITING (on object monitor) >at java.lang.Object.wait(Native Method) >at java.lang.Object.wait(Object.java:502) >at org.snmp4j.u
