Hi Brice,
The current snapshots of SNMP4J 1.x and 2.x contain
a fix for that issue in the DefaultTcpTransportMapping.java
file.
Best regards,
Frank
Am 20.01.2012 21:33, schrieb Frank Fock:
> Hi Brice,
>
> The log output suggests that there is a race condition between the
> connection timeout and the sending of a new packet. I will
> have look if it can be fixed.
>
> A workaround would be to choose a longer timeout.
>
> Best regards,
> Frank
>
> Am 18.01.2012 14:21, schrieb Brice Fines:
>> Hi Frank,
>>
>> Our environment is the following one.
>> We are using SNMP4J 1.11.03 (we cannot migrate yet to 2.x but we are up to
>> date with 1.x) in web application (running in WAS 6.1 with IBM JVM 1.5).
>> We are managing around 800 devices with our application using SNMP4J.
>> We are sending commands over TCP to these devices (on average, we send 100
>> commands during one day).
>>
>> Not too often (it can be months or weeks before it happens again), we get
>> a ClosedChannelException (see included log trace, device IP is
>> 10.247.254.2).
>>
>> Since this occurs once in a while, this is not critical (next command to
>> same device works ok, and all other commands work ok too) (everything else
>> (commands, PDU,...) is running smoothly).
>> I think I reported this some time ago; I was waiting to check if it would
>> disappear with last update (with the TCP fixes), but it showed up again.
>> Do you think it could be a race condition bug in
>> DefaultTcpTransportMapping?
>> Thanks in advance.
>>
>> Regards
>> Brice
>>
>>
>> [1/18/12 8:11:39:175 CET] 0000003b SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread<sendMessage>
>> Looking up connection for destination '10.247.254.2/161' returned:
>> SocketEntry[peerAddress=10.247.254.2/161,socket=Socket[addr=/10.247.254.2,port=161,localport=65423],lastUse=Wed
>> Jan 18 08:01:16 CET 2012]
>> [1/18/12 8:11:39:177 CET] 0000003b SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread<sendMessage>
>> {10.247.254.11/161=SocketEntry[peerAddress=10.247.254.11/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 08:00:30 CET 2012],
>> 10.247.254.28/161=SocketEntry[peerAddress=10.247.254.28/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:21 CET 2012],
>> 10.249.17.9/161=SocketEntry[peerAddress=10.249.17.9/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:51 CET 2012],
>> 10.247.254.1/161=SocketEntry[peerAddress=10.247.254.1/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 08:00:20 CET 2012],
>> 10.247.254.27/161=SocketEntry[peerAddress=10.247.254.27/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 08:00:25 CET 2012],
>> 10.247.254.2/161=SocketEntry[peerAddress=10.247.254.2/161,socket=Socket[addr=/10.247.254.2,port=161,localport=65423],lastUse=Wed
>> Jan 18 08:01:16 CET 2012],
>> 10.247.254.20/161=SocketEntry[peerAddress=10.247.254.20/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:31 CET 2012],
>> 10.249.17.2/161=SocketEntry[peerAddress=10.249.17.2/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:46 CET 2012],
>> 10.247.254.22/161=SocketEntry[peerAddress=10.247.254.22/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:36 CET 2012],
>> 10.247.254.17/161=SocketEntry[peerAddress=10.247.254.17/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:15 CET 2012],
>> 10.247.254.18/161=SocketEntry[peerAddress=10.247.254.18/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 07:30:26 CET 2012],
>> 10.247.254.13/161=SocketEntry[peerAddress=10.247.254.13/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 08:00:00 CET 2012],
>> 10.247.254.15/161=SocketEntry[peerAddress=10.247.254.15/161,socket=Socket[addr=/10.247.254.15,port=161,localport=65440],lastUse=Wed
>> Jan 18 08:01:46 CET 2012]}
>> [1/18/12 8:11:39:177 CET] 0000003b SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread<sendMessage>
>> Waking up selector for new message
>> [1/18/12 8:11:39:178 CET] 00000031 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
>> <addRegistration> Adding operation 4 for:
>> SocketEntry[peerAddress=10.247.254.2/161,socket=Socket[addr=/10.247.254.2,port=161,localport=65423],lastUse=Wed
>> Jan 18 08:01:16 CET 2012]
>> [1/18/12 8:11:39:179 CET] 00000033 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> to 10.247.254.10/161 closed due to timeout
>> [1/18/12 8:11:39:179 CET] 00000033 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Removing wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@48a048a
>> [1/18/12 8:11:39:179 CET] 00000033 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Run wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@77527752
>> [1/18/12 8:11:39:180 CET] 00000033 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> has not been used for 622564 micro seconds, closing it
>> [1/18/12 8:11:39:180 CET] 00000033 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> to 10.247.254.2/161 closed due to timeout
>> [1/18/12 8:11:39:180 CET] 00000033 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Removing wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@77527752
>> [1/18/12 8:11:39:181 CET] 00000033 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Run wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@39103910
>> [1/18/12 8:11:39:181 CET] 00000033 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> has not been used for 592518 micro seconds, closing it
>> [1/18/12 8:11:39:181 CET] 00000033 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> to 10.247.254.15/161 closed due to timeout
>> [1/18/12 8:11:39:181 CET] 00000033 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Removing wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@39103910
>> [1/18/12 8:11:39:182 CET] 00000032 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout<run> Socket
>> to 10.247.254.9/161 closed due to timeout
>> [1/18/12 8:11:39:182 CET] 00000032 SystemOut O
>> org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
>> <timerExpired> Removing wrapped TimerTask:
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout@73087308
>> [1/18/12 8:11:39:182 CET] 00000031 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
>> <addRegistration> Adding operation 8 for:
>> SocketEntry[peerAddress=10.247.254.2/161,socket=Socket[unconnected],lastUse=Wed
>> Jan 18 08:01:16 CET 2012]
>> [1/18/12 8:11:39:183 CET] 00000031 SystemOut O
>> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
>> <processPending> java.nio.channels.ClosedChannelException
>> [1/18/12 8:11:39:183 CET] 00000031 SystemOut O
>> org.snmp4j.transport.TcpTransportMapping<fireConnectionStateChanged>
>> Firing transport state event:
>> org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping@58fa58fa,peerAddress=10.247.254.2/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
>> _______________________________________________
>> SNMP4J mailing list
>> SNMP4J@agentpp.org
>> http://lists.agentpp.org/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
http://lists.agentpp.org/mailman/listinfo/snmp4j
