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
