[SNMP4J] Possible concurrency bug in snmp4j ?

Tue Feb 13 10:51:23 CET 2018

The immediate reconnection issue (TCP) to the same address and port (SFJ-164) has been fixed in SNMP4J 2.6.0 which is available as SNAPSHOT. 

See also the mailing list archive around January 27th. 

The ticket system is available for users with support contract.

Best regards,
Frank 

> On 12. Feb 2018, at 19:53, Maayan, Elhanan <Elhanan.Maayan at sbdinc.com> wrote:
> 
> Thanks, I'll try that , I'm trying to access the bug system, but I can't find it....
> 
> The real issue I'm encountering which I don't know the cause is that the snmp4j tries to send messages, trying to connect , but simply doesn't, I did a thread dump and it seems to be stuck on the select method no matter what
> 
> "DefaultTCPTransportMapping_192.168.60.80/0" #75906 daemon prio=5 os_prio=0 tid=0x00007f4748e75000 nid=0x79e5 runnable [0x00007f4733768000]
>   java.lang.Thread.State: RUNNABLE
> 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
> 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
> 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
> 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
> 	- locked <0x00000007042019f8> (a sun.nio.ch.Util$3)
> 	- locked <0x00000007042019e8> (a java.util.Collections$UnmodifiableSet)
> 	- locked <0x0000000704201a08> (a sun.nio.ch.EPollSelectorImpl)
> 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
> 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
> 	at org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.run(DefaultTcpTransportMapping.java:786)
> 	at java.lang.Thread.run(Thread.java:745)
> 
> there's nothing on tcpdump, using a separate snmp4j on shell on the same machine is able to connect to the same remote machine, 
> 
> but still:
> 2018-02-12 20:46:48,982 DEBUG DefaultTcpTransportMapping - Looking up connection for destination '192.168.56.1/162' returned: SocketEntry[peerAddress=192.168.56.1/162,socket=Socket[unconnected],lastUse=Mon Mar 09 07:06:25 IST 1970,readBufferPosition=-1]
> 2018-02-12 20:46:48,982 DEBUG DefaultTcpTransportMapping - {192.168.56.1/162=SocketEntry[peerAddress=192.168.56.1/162,socket=Socket[unconnected],lastUse=Mon Mar 09 07:06:25 IST 1970,readBufferPosition=-1]}
> 2018-02-12 20:46:48,982 DEBUG DefaultTcpTransportMapping - Socket for address '192.168.56.1/162' is closed, opening it...
> 2018-02-12 20:46:48,982 DEBUG DefaultTcpTransportMapping - Trying to connect to 192.168.56.1/162
> 
> 
> I see that "trying to connect to" is invoked the wakeup, so that must means the .select is released, but returns no keys, can there be any reason for that? 
> 
> 
> 
> 
> -----Original Message-----
> From: Frank Fock [mailto:fock at agentpp.com] 
> Sent: Monday, February 12, 2018 8:45 PM
> To: Maayan, Elhanan <Elhanan.Maayan at sbdinc.com>
> Cc: snmp4j at agentpp.org
> Subject: Re: [SNMP4J] Possible concurrency bug in snmp4j ?
> 
> *External Message, please be cautious.*
> 
> Hi Elhanan,
> 
> Please upgrade to SNMP4J 2.5.11 to fix this issue.
> 
> Best regards 
> Frank
> 
>> Am 12.02.2018 um 18:05 schrieb Maayan, Elhanan <Elhanan.Maayan at sbdinc.com>:
>> 
>> Hi..i'm using snm4j 2.4.3.
>> 
>> Is it possible that just when snmp4j closes a connection (due to timeout, or remote closing) and it's trying to addRegistration causing to throw an exception, is it possible that snmp4j can no longer establish connection?
>> 
>> 
>> 
>> Below is a small log of a sample client I'm doing , which does interval every 5 seconds, furthermore it's target.setTimeout is also set to 5 seconds, to emulate the bug (which actually happens upon remote close)
>> 
>> You can see that subsequent attempts simply try to connect but don't' send anything..
>> 
>> 
>> 
>> Mon Feb 12 18:10:37 IST 2018 Sending message
>> 
>> Looking up connection for destination '192.168.97.21/162' returned: SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[addr=qa-mv-0640.corp.aeroscout.com/192.168.97.21,port=162,localport=51072],lastUse=Mon Mar 09 04:30:03 IST 1970,readBufferPosition=-1]
>> 
>> {192.168.97.21/162=SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[addr=qa-mv-0640.corp.aeroscout.com/192.168.97.21,port=162,localport=51072],lastUse=Mon Mar 09 04:30:03 IST 1970,readBufferPosition=-1]}
>> 
>> Waking up selector for new message
>> 
>> Socket has not been used for 10002 milliseconds, closing it
>> 
>> Socket to 192.168.97.21/162 closed due to timeout
>> 
>> Adding operation 8 for: SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[unconnected],lastUse=Mon Mar 09 04:30:13 IST 1970,readBufferPosition=-1]
>> 
>> java.nio.channels.ClosedChannelException
>> 
>> Firing transport state event: org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 1d6c6de8,peerAddress=192.168.97.21/162,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
>> 
>> State changed to Closed Peer address 192.168.97.21/162
>> 
>> Exception in thread "DefaultTCPTransportMapping_192.168.60.80/0" java.lang.RuntimeException: java.nio.channels.ClosedChannelException
>> 
>>       at org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.processPending(DefaultTcpTransportMapping.java:697)
>> 
>>       at org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.run(DefaultTcpTransportMapping.java:893)
>> 
>>       at java.lang.Thread.run(Thread.java:745)
>> 
>> Caused by: java.nio.channels.ClosedChannelException
>> 
>>       at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:197)
>> 
>>       at org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry.addRegistration(DefaultTcpTransportMapping.java:433)
>> 
>>       at org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.processPending(DefaultTcpTransportMapping.java:658)
>> 
>>       ... 2 more
>> 
>> Mon Feb 12 18:10:47 IST 2018 Sending message
>> 
>> Looking up connection for destination '192.168.97.21/162' returned: null
>> 
>> {}
>> 
>> Socket for address '192.168.97.21/162' is closed, opening it...
>> 
>> Trying to connect to 192.168.97.21/162
>> 
>> Mon Feb 12 18:10:57 IST 2018 Sending message
>> 
>> Looking up connection for destination '192.168.97.21/162' returned: SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[unconnected],lastUse=Mon Mar 09 04:30:23 IST 1970,readBufferPosition=-1]
>> 
>> {192.168.97.21/162=SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[unconnected],lastUse=Mon Mar 09 04:30:23 IST 1970,readBufferPosition=-1]}
>> 
>> Socket for address '192.168.97.21/162' is closed, opening it...
>> 
>> Trying to connect to 192.168.97.21/162
>> 
>> Mon Feb 12 18:11:07 IST 2018 Sending message
>> 
>> Looking up connection for destination '192.168.97.21/162' returned: SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[unconnected],lastUse=Mon Mar 09 04:30:33 IST 1970,readBufferPosition=-1]
>> 
>> {192.168.97.21/162=SocketEntry[peerAddress=192.168.97.21/162,socket=Socket[unconnected],lastUse=Mon Mar 09 04:30:33 IST 1970,readBufferPosition=-1]}
>> 
>> Socket for address '192.168.97.21/162' is closed, opening it...
>> _______________________________________________
>> SNMP4J mailing list
>> SNMP4J at agentpp.org
>> https://oosnmp.net/mailman/listinfo/snmp4j
> 