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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@7a407a4 _______________________________________________ SNMP4J mailing list [email protected] http://lists.agentpp.org/mailman/listinfo/snmp4j
