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
