[SNMP4J] elusive ClosedChannelException in DefaultTcpTransportMapping strikes back?
Brice Fines
bfines at redsys.es
Fri Sep 21 10:07:30 CEST 2012
Hi Frank,
Back in April we updated snmp4j to version 1.11.0.4 to solve a race
condition in DefaultTcpTransportMapping ( [SFJ-57] ).
See previous threads:
http://lists.agentpp.org/pipermail/snmp4j/2012-January/004768.html
http://lists.agentpp.org/pipermail/snmp4j/2012-April/004815.html
Our app has been running during the last months, and, once in a while
(let's say twice a month), a ClosedChannelException pops out.
I checked with our production environment administrators that version
1.11.0.4 was in use.
I join the log trace of the last exception of this month at the end of the
mesage. Device IP is 10.249.30.39.
There is a first fireConnectionStateChanged at 10:15:26:557, and next
another one at 10:30:10:311.
Please can you check if it is a different problem?
Thanks for your support.
Regards
Brice
[9/18/12 10:15:26:515 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.30.39/161' returned: null
[9/18/12 10:15:26:516 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.247.252.80/161=SocketEntry[peerAddress=10.247.252.80/161,socket=Socket[addr=/10.247.252.80,port=161,localport=62682],lastUse=Tue
Sep 18 10:15:10 CEST 2012],
10.247.252.4/161=SocketEntry[peerAddress=10.247.252.4/161,socket=Socket[addr=/10.247.252.4,port=161,localport=62675],lastUse=Tue
Sep 18 10:15:00 CEST 2012],
10.247.252.228/161=SocketEntry[peerAddress=10.247.252.228/161,socket=Socket[addr=/10.247.252.228,port=161,localport=62692],lastUse=Tue
Sep 18 10:15:21 CEST 2012],
10.247.253.43/161=SocketEntry[peerAddress=10.247.253.43/161,socket=Socket[addr=/10.247.253.43,port=161,localport=62679],lastUse=Tue
Sep 18 10:15:05 CEST 2012],
10.247.252.109/161=SocketEntry[peerAddress=10.247.252.109/161,socket=Socket[addr=/10.247.252.109,port=161,localport=62690],lastUse=Tue
Sep 18 10:15:16 CEST 2012]}
[9/18/12 10:15:26:516 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Socket for address '10.249.30.39/161' is closed, opening it...
[9/18/12 10:15:26:517 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Trying to connect to 10.249.30.39/161
[9/18/12 10:15:26:518 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[unconnected],lastUse=Tue
Sep 18 10:15:26 CEST 2012]
[9/18/12 10:15:26:556 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
connectable
[9/18/12 10:15:26:556 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Connected to 10.249.30.39/161
[9/18/12 10:15:26:556 CEST] 0000002d SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule> CommonTimer
schedule task:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 671e671e
delay: 60000
[9/18/12 10:15:26:557 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[addr=/10.249.30.39,port=161,localport=62694],lastUse=Tue
Sep 18 10:15:26 CEST 2012]
[9/18/12 10:15:26:557 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Fire connected event for 10.249.30.39/161
[9/18/12 10:15:26:557 CEST] 0000002d SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 301c301c,peerAddress=10.249.30.39/161,newState=1,cancelled=false,causingException=null]
[9/18/12 10:15:26:558 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
writable
[9/18/12 10:15:26:558 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 151 to 10.249.30.39/161: 30:...
[9/18/12 10:15:26:559 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 1 for:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[addr=/10.249.30.39,port=161,localport=62694],lastUse=Tue
Sep 18 10:15:26 CEST 2012]
[9/18/12 10:15:26:559 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
writable
[9/18/12 10:15:26:592 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
readable
[9/18/12 10:15:26:592 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
reading
[9/18/12 10:15:26:592 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <readMessage>
Reading header 6 bytes from 10.249.30.39/161
[9/18/12 10:15:26:592 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <readMessage>
Message length is
org.snmp4j.transport.MessageLength[headerLength=2,payloadLength=119]
[9/18/12 10:15:26:593 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.249.30.39/161 with length 121:
30:...
[9/18/12 10:15:26:593 CEST] 0000002d SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=766741367, msgMaxSize=2147483647, msgFlags=00, secModel=3
[9/18/12 10:15:26:594 CEST] 0000002d SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:9d:73:00:00:85:06:ab:4c,
securityName=urwazerty)
[9/18/12 10:15:26:594 CEST] 0000002d SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=766741367,pduHandle=PduHandle[1572814595],securityEngineID=80:00:1f:88:80:9d:73:00:00:85:06:ab:4c,securityModel=org.snmp4j.security.USM at 6f286f28,securityName=urwazerty,securityLevel=2,contextEngineID=80:00:1f:88:80:9d:73:00:00:85:06:ab:4c,contextName=]
[9/18/12 10:15:26:594 CEST] 0000002d SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 §7.2.10 - Received PDU (msgID=766741367) is
a response or an internal class message. PduHandle.transactionID =
1572814595
[9/18/12 10:15:26:595 CEST] 0000002d SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[9/18/12 10:15:26:595 CEST] 0000002d SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Searching pending request
with handlePduHandle[1572814595]
[9/18/12 10:15:26:595 CEST] 0000002d SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Received late report from
10.249.30.39/161 with request ID 1572814595
[9/18/12 10:15:31:519 CEST] 0000002f SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle: PduHandle[1572814595]
[9/18/12 10:15:31:527 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 733a733a
[9/18/12 10:15:31:527 CEST] 00000032 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[9/18/12 10:15:31:528 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 733a733a
[9/18/12 10:16:00:238 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 71727172
[9/18/12 10:16:00:238 CEST] 0000002e SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 1347954812282129591 milliseconds, closing it
[9/18/12 10:16:05:507 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 40e840e8
[9/18/12 10:16:05:508 CEST] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 1347954817551816416 milliseconds, closing it
[9/18/12 10:30:05:249 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.30.39/161' returned:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[addr=/10.249.30.39,port=161,localport=62694],lastUse=Tue
Sep 18 10:15:26 CEST 2012]
[9/18/12 10:30:05:249 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.249.30.39/161=SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[addr=/10.249.30.39,port=161,localport=62694],lastUse=Tue
Sep 18 10:15:26 CEST 2012],
10.247.252.228/161=SocketEntry[peerAddress=10.247.252.228/161,socket=Socket[addr=/10.247.252.228,port=161,localport=62692],lastUse=Tue
Sep 18 10:15:21 CEST 2012],
10.247.253.43/161=SocketEntry[peerAddress=10.247.253.43/161,socket=Socket[addr=/10.247.253.43,port=161,localport=62941],lastUse=Tue
Sep 18 10:30:00 CEST 2012]}
[9/18/12 10:30:05:250 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Waking up selector for new message
[9/18/12 10:30:05:250 CEST] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.80/161 closed due to timeout
[9/18/12 10:30:05:251 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[addr=/10.249.30.39,port=161,localport=62694],lastUse=Tue
Sep 18 10:30:05 CEST 2012]
[9/18/12 10:30:05:251 CEST] 0000002e SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.109/161 closed due to timeout
[9/18/12 10:30:05:251 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at b620b62
[9/18/12 10:30:05:251 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 3aee3aee
[9/18/12 10:30:05:252 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
writable
[9/18/12 10:30:05:252 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at b0c0b0c
[9/18/12 10:30:05:252 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 671e671e
[9/18/12 10:30:05:252 CEST] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 1347955657296244541 milliseconds, closing it
[9/18/12 10:30:05:252 CEST] 0000002e SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 1347955657295572751 milliseconds, closing it
[9/18/12 10:30:05:253 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 151 to 10.249.30.39/161: 30:...
[9/18/12 10:30:05:253 CEST] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.228/161 closed due to timeout
[9/18/12 10:30:05:253 CEST] 0000002e SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.30.39/161 closed due to timeout
[9/18/12 10:30:05:253 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at b0c0b0c
[9/18/12 10:30:05:254 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 671e671e
[9/18/12 10:30:05:254 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 438c438c
[9/18/12 10:30:05:254 CEST] 00000032 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[9/18/12 10:30:05:254 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 438c438c
[9/18/12 10:30:10:251 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle: PduHandle[1572814599]
[9/18/12 10:30:10:259 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 72d072d0
[9/18/12 10:30:10:259 CEST] 0000002e SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[9/18/12 10:30:10:259 CEST] 0000002e SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 72d072d0
[9/18/12 10:30:10:305 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[9/18/12 10:30:10:306 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=766741370,pduHandle=PduHandle[1572814600],securityEngineID=,securityModel=org.snmp4j.security.USM at 6f286f28,securityName=urwazerty,securityLevel=1,contextEngineID=,contextName=]
[9/18/12 10:30:10:306 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1572814600] and retry count left 0
[9/18/12 10:30:10:307 CEST] 00000035 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule> CommonTimer
schedule task: org.snmp4j.Snmp$PendingRequest at 7a407a4 delay: 5000
[9/18/12 10:30:10:307 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.30.53/161' returned: null
[9/18/12 10:30:10:308 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.247.253.43/161=SocketEntry[peerAddress=10.247.253.43/161,socket=Socket[addr=/10.247.253.43,port=161,localport=62941],lastUse=Tue
Sep 18 10:30:00 CEST 2012]}
[9/18/12 10:30:10:308 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Socket for address '10.249.30.53/161' is closed, opening it...
[9/18/12 10:30:10:309 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Trying to connect to 10.249.30.53/161
[9/18/12 10:30:10:310 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.249.30.39/161,socket=Socket[unconnected],lastUse=Tue
Sep 18 10:30:05 CEST 2012]
[9/18/12 10:30:10:310 CEST] 0000002d SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> java.nio.channels.ClosedChannelException
[9/18/12 10:30:10:311 CEST] 0000002d SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 301c301c,peerAddress=10.249.30.39/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
[9/18/12 10:30:15:319 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 7a407a4
[9/18/12 10:30:15:320 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle: PduHandle[1572814600]
[9/18/12 10:30:15:320 CEST] 00000032 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> Request timed out: 1572814600
[9/18/12 10:30:15:321 CEST] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 7a407a4
More information about the SNMP4J
mailing list