[SNMP4J] elusive ClosedChannelException in DefaultTcpTransportMapping

[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 at 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 at 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 at 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 at 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 at 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 at 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 at 58fa58fa,peerAddress=10.247.254.2/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]