[SNMP4J] Timeouts in version 2.5.7+

Tue Apr 3 13:26:21 CEST 2018

Hi Frank

Thanks for your reply. I don't reuse PDUs. In case of SNMPv2c, the effective statements would be:

  PDU pdu = new PDU();
  pdu.setType(PDU.GET);
  pdu.add(new VariableBinding(...));
  ResponseEvent responseEvent = snmp.send(pdu, target); // timeout

I believe the PDU request IDs will be coming from this code in MessageDispatcherImpl:

  protected PduHandle createPduHandle() {
    return new PduHandle(getNextRequestID());
  }

There's only one static snmp instance for all targets, I read somewhere that this is the preferred implementation.

I'am also able to remote debug the program, but I wouldn't know where to look at. Also, it's a bit of extra work and it will take a while, but it's possible.

Best regards,
Steffen

-----Original Message-----
From: Frank Fock [mailto:fock at agentpp.com] 
Sent: Sonntag, 1. April 2018 08:23
To: Steffen Brüntjen <Steffen.Bruentjen at macmon.eu>
Cc: snmp4j at agentpp.org
Subject: Re: [SNMP4J] Timeouts in version 2.5.7+

Hi Steffen,

There was no change on the DefaultUdpTransportMapping between 2.5.6 and 2.5.7, thus I assume that behaviour change is a side effect of some other changes. SNMP4J is no a bit faster.
Have you checked your code for race conditions?
When you use Snmp.send, how do you create the request IDs of the PDUs? 

Also reusing the PDU objects before the request is finished might cause this issue. 

Best regards,
Frank  

> On 16. Mar 2018, at 12:14, Steffen Brüntjen <Steffen.Bruentjen at macmon.eu> wrote:
> 
> Hi!
> 
> I'm using SNMP4J for monitoring around 200 devices. It has been running stably for months. Now I found a problem in the latest releases: When my process runs for a couple of hours (sometimes days), after some time SNMP4J returns nothing but timeouts. My program initially uses Snmp.send() and TableUtils (I think, this doesn't matter). After the problem shows up once, all my program effectively does is querying the SysObjectIds (because this already results in timeouts):
> 
>    org.snmp4j.Snmp.send(get(SnmpV2Mib.sysObjectID), target)
> 
> 
> Some of the targets are community targets, some are user targets, but I get timeouts for all devices. I repeated testing with only community targets resulting in the same behavior. I tracked down the problem to release 2.5.7. The previous version 2.5.6 works without problems, all releases starting with 2.5.7 show the problem. I also analyzed the SNMP packages using tcpdump. The devices send their answers quickly, the packets don't look any special. It seems that SNMP4J doesn't receive, recognize or process the UDP packets.
> 
> Can you reproduce the problem? Does anyone see problems in source code changes from 2.5.6 to 2.5.7?
> 
> Best regards
> Steffen Brüntjen
> 
> 
> 
> Here are some stacktraces at the time the problem exists:
> 
> "DefaultUDPTransportMapping_0.0.0.0/162" #72 daemon prio=5 os_prio=0 tid=0x00007fa0ac00a000 nid=0x4433 runnable [0x00007fa08b4f3000]
>   java.lang.Thread.State: RUNNABLE
> 	at java.net.PlainDatagramSocketImpl.receive0(Native Method)
> 	- locked <0x0000000089977c28> (a java.net.PlainDatagramSocketImpl)
> 	at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
> 	- locked <0x0000000089977c28> (a java.net.PlainDatagramSocketImpl)
> 	at java.net.DatagramSocket.receive(DatagramSocket.java:812)
> 	- locked <0x0000000089b2b3a8> (a java.net.DatagramPacket)
> 	- locked <0x0000000089977c78> (a java.net.DatagramSocket)
> 	at org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread.run(DefaultUdpTransportMapping.java:397)
> 	at java.lang.Thread.run(Thread.java:745)
> 
> "DefaultUDPTransportMapping_0.0.0.0/0" #33 daemon prio=5 os_prio=0 tid=0x00007fa126c9d800 nid=0x440c in Object.wait() [0x00007fa0b60f1000]
>   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.execute(ThreadPool.java:103)
> 	- locked <0x00000000883cde50> (a org.snmp4j.util.ThreadPool)
> 	at org.snmp4j.util.MultiThreadedMessageDispatcher.processMessage(MultiThreadedMessageDispatcher.java:162)
> 	at org.snmp4j.transport.AbstractTransportMapping.fireProcessMessage(AbstractTransportMapping.java:76)
> 	at org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread.run(DefaultUdpTransportMapping.java:430)
> 	at java.lang.Thread.run(Thread.java:745)
> 
> "snmp.3" #37 prio=5 os_prio=0 tid=0x00007fa125a38000 nid=0x4410 in Object.wait() [0x00007fa0b5ced000]
>   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 <0x00000000883ddeb8> (a org.snmp4j.util.ThreadPool$TaskManager)
> 
> "snmp.2" #36 prio=5 os_prio=0 tid=0x00007fa126ca1800 nid=0x440f in Object.wait() [0x00007fa0b5dee000]
>   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 <0x00000000883de0c8> (a org.snmp4j.util.ThreadPool$TaskManager)
> 
> "snmp.1" #35 prio=5 os_prio=0 tid=0x00007fa126ca0800 nid=0x440e in Object.wait() [0x00007fa0b5eef000]
>   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 <0x00000000883de2d8> (a org.snmp4j.util.ThreadPool$TaskManager)
> 
> "snmp.0" #34 prio=5 os_prio=0 tid=0x00007fa126ca0000 nid=0x440d in Object.wait() [0x00007fa0b5ff0000]
>   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 <0x00000000883de4e8> (a org.snmp4j.util.ThreadPool$TaskManager)
> 
> "trap.0" #71 prio=5 os_prio=0 tid=0x00007fa0ac004000 nid=0x4432 in Object.wait() [0x00007fa08b5f4000]
>   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 <0x0000000089979080> (a org.snmp4j.util.ThreadPool$TaskManager)
> 
> 
> And then there are some monitoring threads that send SNMP queries:
> 
> "mon-001" #43 prio=5 os_prio=0 tid=0x00007fa0c000c000 nid=0x4416 in Object.wait() [0x00007fa0b52e7000]
>   java.lang.Thread.State: TIMED_WAITING (on object monitor)
> 	at java.lang.Object.wait(Native Method)
> 	at org.snmp4j.Snmp.send(Snmp.java:991)
> 	- locked <0x00000000fdc0c6e0> (a org.snmp4j.Snmp$SyncResponseListener)
> 	at org.snmp4j.Snmp.send(Snmp.java:963)
> 	at org.snmp4j.Snmp.send(Snmp.java:928)
>     at [...]
> 
> 
> 
> And here's some non-binary tcpdump output:
> 
> 12:05:49.820810 IP 192.168.101.211.57522 > 10.100.7.204.snmp:  GetRequest(28)  system.sysObjectID.0
> E..G.. at .@. at ...e.
> d.......38.0).....public..../.........0.0...+.........
> 12:05:49.821321 IP 10.100.7.204.snmp > 192.168.101.211.57522:  GetResponse(37)  system.sysObjectID.0=E:cisco.1.614
> E..P.. at .@.SW
> d....e......<..02.....public.%../.........0.0...+........       +....   ..f
> ^C
> _______________________________________________
> SNMP4J mailing list
> SNMP4J at agentpp.org
> https://oosnmp.net/mailman/listinfo/snmp4j