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] 003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThreadsendMessage
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] 003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThreadsendMessage
{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] 003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThreadsendMessage
Waking up selector for new message
[1/18/12 8:11:39:178 CET] 0031 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] 0033 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeoutrun Socket
to 10.247.254.10/161 closed due to timeout
[1/18/12 8:11:39:179 CET] 0033 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] 0033 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] 0033 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeoutrun Socket
has not been used for 622564 micro seconds, closing it
[1/18/12 8:11:39:180 CET] 0033 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeoutrun Socket
to 10.247.254.2/161 closed due to timeout
[1/18/12 8:11:39:180 CET] 0033 SystemOut O
