[SNMP4J] ClosedChannelException caused by socket timeout?
Brice Fines
bfines at sermepa.es
Wed Jan 12 15:55:19 CET 2011
Hi Frank,
(happy new year everybody)
Once in a while, I get a java.nio.channels.ClosedChannelException when
trying to send SNMP SET commands over TCP with SNMP4J.
We are using SNMP4J version 1.11.1.
WebSphere Platform 6.1 [EJB3 6.1.0.27 cf270934.03] [ND 6.1.0.27
cf270937.16]
Host Operating System is AIX, version 5.3
Java version = 1.5.0, Java Compiler = j9jit23, Java VM name = IBM J9 VM
We have an automatic process that send SET command to some devices every
15 minutes.
The program use a TransporStateListener with the following:
public void connectionStateChanged(TransportStateEvent
transportStateEvent) {
if (transportStateEvent.getNewState() ==
TransportStateEvent.STATE_CLOSED) {
...send alert by mail...
if (transportStateEvent.getCausingException() !=
null) {
transportStateEvent.getCausingException().printStackTrace();
}
}
}
We use default timeout (1 minute) for DefaultTcpTransportMapping.
We use 5 seconds timeout for Targets.
I think that the sequence is something like the following one:
_we send a command 1 to a client by TCP
_TCP socket is opened for command 1
_command 1 finished ok (client was unreachable, response in responseEvent
was null)
_later, we send a command 2 to the same client by TCP
_TCP socket from command 1 is selected and used for command 2
_TCP socket timeout happens and socket is closed
_using TCP socket for command 2 results in exception
I enclose the matching logs at the end of this message.
Should not socket timeout be prevented in that case?
The previous sequence in the log (client is 10.249.66.42):
_later, we send a command 2 to the same client by TCP
[1/12/11 7:30:05:533 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.66.42/161' returned:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:05:536 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:05:538 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 150 to 10.249.66.42/161: 30:...
_TCP socket timeout happens and socket is closed
[1/12/11 7:30:05:539 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.66.42/161 closed due to timeout
_using TCP socket for command 2 results in exception
[1/12/11 7:30:10:598 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:10:602 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> java.nio.channels.ClosedChannelException
[1/12/11 7:30:10:604 CET] 00000031 SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 3d203d2,peerAddress=10.249.66.42/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
Thanks in advance.
Regards
Brice
System.Err
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R
java.nio.channels.ClosedChannelException
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R at
java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:193)
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R at
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry.addRegistration(DefaultTcpTransportMapping.java:418)
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R at
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.processPending(DefaultTcpTransportMapping.java:611)
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R at
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread.run(DefaultTcpTransportMapping.java:818)
[1/12/11 7:30:10:625 CET] 00000031 SystemErr R at
org.snmp4j.util.spring.TaskExecutorWorkerTaskImpl$WorkerTaskWrapper.run(TaskExecutorWorkerTaskImpl.java:129)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
org.springframework.scheduling.commonj.DelegatingWork.run(DelegatingWork.java:61)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.ws.asynchbeans.J2EEContext$RunProxy.run(J2EEContext.java:264)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
java.security.AccessController.doPrivileged(AccessController.java:219)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
javax.security.auth.Subject.doAs(Subject.java:495)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:118)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.ws.asynchbeans.J2EEContext$DoAsProxy.run(J2EEContext.java:335)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
java.security.AccessController.doPrivileged(AccessController.java:246)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.ws.asynchbeans.J2EEContext.run(J2EEContext.java:1146)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.ws.asynchbeans.WorkWithExecutionContextImpl.go(WorkWithExecutionContextImpl.java:195)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
com.ibm.ws.asynchbeans.CJWorkItemImpl.run(CJWorkItemImpl.java:187)
[1/12/11 7:30:10:626 CET] 00000031 SystemErr R at
java.lang.Thread.run(Thread.java:811)
System.Out
[1/12/11 7:30:00:090 CET] 0000003b SystemOut O starting automatic
process to send SET command
[1/12/11 7:30:00:265 CET] 0000003b SystemOut O number of clients for
automatic process 14
[1/12/11 7:30:00:302 CET] 0000003b SystemOut O org.snmp4j.security.USM
<generateResponseMessage> RFC3414 §3.1.4.b Outgoing message is not
encrypted
[1/12/11 7:30:00:303 CET] 0000003b SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=716078228,pduHandle=PduHandle[1366685023],securityEngineID=,securityModel=org.snmp4j.security.USM at e600e60,securityName=urwabcdefg,securityLevel=1,contextEngineID=,contextName=]
[1/12/11 7:30:00:304 CET] 0000003b SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1366685023] and retry count left 0
[1/12/11 7:30:00:304 CET] 0000003b SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule> CommonTimer
schedule task: org.snmp4j.Snmp$PendingRequest at 66b266b2 delay: 5000
[1/12/11 7:30:00:305 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.254.4.170/161' returned:
SocketEntry[peerAddress=10.254.4.170/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:15:00 CET 2011]
[1/12/11 7:30:00:307 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.247.252.85/161=SocketEntry[peerAddress=10.247.252.85/161,socket=Socket[addr=/10.247.252.85,port=161,localport=40091],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.31/161=SocketEntry[peerAddress=10.249.11.31/161,socket=Socket[addr=/10.249.11.31,port=161,localport=40114],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.46/161=SocketEntry[peerAddress=10.249.11.46/161,socket=Socket[addr=/10.249.11.46,port=161,localport=40123],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.66.42/161=SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.75/161=SocketEntry[peerAddress=10.249.11.75/161,socket=Socket[addr=/10.249.11.75,port=161,localport=40140],lastUse=Wed
Jan 12 07:16:21 CET 2011],
10.247.252.236/161=SocketEntry[peerAddress=10.247.252.236/161,socket=Socket[addr=/10.247.252.236,port=161,localport=40107],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.60/161=SocketEntry[peerAddress=10.249.11.60/161,socket=Socket[addr=/10.249.11.60,port=161,localport=40128],lastUse=Wed
Jan 12 07:16:16 CET 2011],
10.247.252.45/161=SocketEntry[peerAddress=10.247.252.45/161,socket=Socket[addr=/10.247.252.45,port=161,localport=40075],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.247.253.37/161=SocketEntry[peerAddress=10.247.253.37/161,socket=Socket[addr=/10.247.253.37,port=161,localport=40067],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.66.118/161=SocketEntry[peerAddress=10.249.66.118/161,socket=Socket[addr=/10.249.66.118,port=161,localport=40046],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.254.4.170/161=SocketEntry[peerAddress=10.254.4.170/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:15:00 CET 2011],
10.247.253.59/161=SocketEntry[peerAddress=10.247.253.59/161,socket=Socket[addr=/10.247.253.59,port=161,localport=40086],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.66.194/161=SocketEntry[peerAddress=10.249.66.194/161,socket=Socket[addr=/10.249.66.194,port=161,localport=40052],lastUse=Wed
Jan 12 07:16:15 CET 2011]}
[1/12/11 7:30:00:307 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Socket for address '10.254.4.170/161' is closed, opening it...
[1/12/11 7:30:00:308 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Trying to connect to 10.254.4.170/161
[1/12/11 7:30:00:309 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.253.31/161 closed due to timeout
[1/12/11 7:30:00:309 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.254.4.170/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:30:00 CET 2011]
[1/12/11 7:30:00:309 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 51ba51ba
[1/12/11 7:30:00:310 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.11/161 closed due to timeout
[1/12/11 7:30:00:311 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 3a2c3a2c
[1/12/11 7:30:00:310 CET] 0000003c ThreadMonitor W WSVR0606W: Thread
"aaaaaTimeManager.Alarm Pool : 1" (0000003c) was previously reported to be
hung but has completed. It was active for approximately 764698
milliseconds. There is/are 1 thread(s) in total in the server that still
may be hung.
[1/12/11 7:30:00:311 CET] 00000032 ThreadMonitor W WSVR0606W: Thread
"aaaaaTimeManager.Alarm Pool : 0" (00000032) was previously reported to be
hung but has completed. It was active for approximately 764713
milliseconds. There is/are 0 thread(s) in total in the server that still
may be hung.
[1/12/11 7:30:00:332 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 14581458
[1/12/11 7:30:00:332 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 824688 micro seconds, closing it
[1/12/11 7:30:00:345 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 6d206d20
[1/12/11 7:30:00:345 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 824695 micro seconds, closing it
[1/12/11 7:30:05:310 CET] 0000003b SystemOut O org.snmp4j.Snmp <send>
Removed pending request with handle: PduHandle[1366685023]
[1/12/11 7:30:05:325 CET] 0000003b SystemOut O sent SET command to ip
10.254.4.170 ERROR Response inside ResponseEvent is null
[1/12/11 7:30:05:463 CET] 0000003b SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped PDU is empty! Setting
it to authoritative engine ID: 80:00:1f:88:80:2a:70:00:00:a6:3b:4b:4a
[1/12/11 7:30:05:464 CET] 0000003b SystemOut O org.snmp4j.security.USM
<getUser> getUser(engineID=80:00:1f:88:80:2a:70:00:00:a6:3b:4b:4a,
securityName=urwabcdefg)
[1/12/11 7:30:05:528 CET] 0000003b SystemOut O
org.snmp4j.security.AuthGeneric <passwordToKey> MD5First digest:
b4:f1:54:db:6f:3f:08:b8:1a:93:2a:f0:a3:aa:ae:e4
[1/12/11 7:30:05:528 CET] 0000003b SystemOut O
org.snmp4j.security.AuthGeneric <passwordToKey> MD5localized key:
ed:df:ee:8b:0e:37:68:d5:64:1f:5b:e7:64:16:e8:ba
[1/12/11 7:30:05:529 CET] 0000003b SystemOut O
org.snmp4j.security.UsmUserTable <addUser> Adding user urwabcdefg =
UsmUser[secName=urwabcdefg,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=11:11:11:11:11:11:11:11:11:11:11:11:11:11:11:11,privProtocol=null,privPassphrase=null,localizationEngineID=80:00:1f:88:80:2a:70:00:00:a6:3b:4b:4a]
[1/12/11 7:30:05:530 CET] 0000003b SystemOut O org.snmp4j.security.USM
<generateResponseMessage> RFC3414 §3.1.4.b Outgoing message is not
encrypted
[1/12/11 7:30:05:531 CET] 0000003b SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=716078229,pduHandle=PduHandle[1366685024],securityEngineID=80:00:1f:88:80:2a:70:00:00:a6:3b:4b:4a,securityModel=org.snmp4j.security.USM at e600e60,securityName=urwabcdefg,securityLevel=2,contextEngineID=80:00:1f:88:80:2a:70:00:00:a6:3b:4b:4a,contextName=]
[1/12/11 7:30:05:532 CET] 0000003b SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1366685024] and retry count left 0
[1/12/11 7:30:05:532 CET] 0000003b SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule> CommonTimer
schedule task: org.snmp4j.Snmp$PendingRequest at 4c024c02 delay: 5000
[1/12/11 7:30:05:533 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.66.42/161' returned:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:05:534 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.247.252.85/161=SocketEntry[peerAddress=10.247.252.85/161,socket=Socket[addr=/10.247.252.85,port=161,localport=40091],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.31/161=SocketEntry[peerAddress=10.249.11.31/161,socket=Socket[addr=/10.249.11.31,port=161,localport=40114],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.46/161=SocketEntry[peerAddress=10.249.11.46/161,socket=Socket[addr=/10.249.11.46,port=161,localport=40123],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.66.42/161=SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.75/161=SocketEntry[peerAddress=10.249.11.75/161,socket=Socket[addr=/10.249.11.75,port=161,localport=40140],lastUse=Wed
Jan 12 07:16:21 CET 2011],
10.247.252.236/161=SocketEntry[peerAddress=10.247.252.236/161,socket=Socket[addr=/10.247.252.236,port=161,localport=40107],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.60/161=SocketEntry[peerAddress=10.249.11.60/161,socket=Socket[addr=/10.249.11.60,port=161,localport=40128],lastUse=Wed
Jan 12 07:16:16 CET 2011],
10.247.253.37/161=SocketEntry[peerAddress=10.247.253.37/161,socket=Socket[addr=/10.247.253.37,port=161,localport=40067],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.66.118/161=SocketEntry[peerAddress=10.249.66.118/161,socket=Socket[addr=/10.249.66.118,port=161,localport=40046],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.254.4.170/161=SocketEntry[peerAddress=10.254.4.170/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:30:00 CET 2011],
10.249.66.194/161=SocketEntry[peerAddress=10.249.66.194/161,socket=Socket[addr=/10.249.66.194,port=161,localport=40052],lastUse=Wed
Jan 12 07:16:15 CET 2011]}
[1/12/11 7:30:05:535 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Waking up selector for new message
[1/12/11 7:30:05:535 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.45/161 closed due to timeout
[1/12/11 7:30:05:536 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 14581458
[1/12/11 7:30:05:536 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.253.59/161 closed due to timeout
[1/12/11 7:30:05:536 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[addr=/10.249.66.42,port=161,localport=40034],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:05:537 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 6d206d20
[1/12/11 7:30:05:537 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 71847184
[1/12/11 7:30:05:537 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
writable
[1/12/11 7:30:05:537 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 28a628a6
[1/12/11 7:30:05:538 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 829883 micro seconds, closing it
[1/12/11 7:30:05:538 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 829909 micro seconds, closing it
[1/12/11 7:30:05:538 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.85/161 closed due to timeout
[1/12/11 7:30:05:538 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 150 to 10.249.66.42/161: 30:...
[1/12/11 7:30:05:539 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 71847184
[1/12/11 7:30:05:539 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.66.42/161 closed due to timeout
[1/12/11 7:30:05:539 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 37043704
[1/12/11 7:30:05:540 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 28a628a6
[1/12/11 7:30:05:540 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 829905 micro seconds, closing it
[1/12/11 7:30:05:541 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 2a8c2a8c
[1/12/11 7:30:05:541 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 829902 micro seconds, closing it
[1/12/11 7:30:10:540 CET] 0000003b SystemOut O org.snmp4j.Snmp <send>
Removed pending request with handle: PduHandle[1366685024]
[1/12/11 7:30:10:550 CET] 0000003b SystemOut O sent SET command to ip
10.249.66.42 ERROR Response inside ResponseEvent is null
[1/12/11 7:30:10:590 CET] 0000003b SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped PDU is empty! Setting
it to authoritative engine ID: 80:00:1f:88:80:6d:24:00:00:9c:48:4b:4a
[1/12/11 7:30:10:591 CET] 0000003b SystemOut O org.snmp4j.security.USM
<getUser> getUser(engineID=80:00:1f:88:80:6d:24:00:00:9c:48:4b:4a,
securityName=urwabcdefg)
[1/12/11 7:30:10:592 CET] 0000003b SystemOut O org.snmp4j.security.USM
<generateResponseMessage> RFC3414 §3.1.4.b Outgoing message is not
encrypted
[1/12/11 7:30:10:593 CET] 0000003b SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=716078230,pduHandle=PduHandle[1366685025],securityEngineID=80:00:1f:88:80:6d:24:00:00:9c:48:4b:4a,securityModel=org.snmp4j.security.USM at e600e60,securityName=urwabcdefg,securityLevel=2,contextEngineID=80:00:1f:88:80:6d:24:00:00:9c:48:4b:4a,contextName=]
[1/12/11 7:30:10:593 CET] 0000003b SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1366685025] and retry count left 0
[1/12/11 7:30:10:594 CET] 0000003b SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule> CommonTimer
schedule task: org.snmp4j.Snmp$PendingRequest at 21582158 delay: 5000
[1/12/11 7:30:10:594 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Looking up connection for destination '10.249.66.150/161' returned: null
[1/12/11 7:30:10:596 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
{10.249.11.31/161=SocketEntry[peerAddress=10.249.11.31/161,socket=Socket[addr=/10.249.11.31,port=161,localport=40114],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.46/161=SocketEntry[peerAddress=10.249.11.46/161,socket=Socket[addr=/10.249.11.46,port=161,localport=40123],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.75/161=SocketEntry[peerAddress=10.249.11.75/161,socket=Socket[addr=/10.249.11.75,port=161,localport=40140],lastUse=Wed
Jan 12 07:16:21 CET 2011],
10.247.252.236/161=SocketEntry[peerAddress=10.247.252.236/161,socket=Socket[addr=/10.247.252.236,port=161,localport=40107],lastUse=Wed
Jan 12 07:16:15 CET 2011],
10.249.11.60/161=SocketEntry[peerAddress=10.249.11.60/161,socket=Socket[addr=/10.249.11.60,port=161,localport=40128],lastUse=Wed
Jan 12 07:16:16 CET 2011],
10.254.4.170/161=SocketEntry[peerAddress=10.254.4.170/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:30:00 CET 2011],
10.249.66.194/161=SocketEntry[peerAddress=10.249.66.194/161,socket=Socket[addr=/10.249.66.194,port=161,localport=40052],lastUse=Wed
Jan 12 07:16:15 CET 2011]}
[1/12/11 7:30:10:596 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Socket for address '10.249.66.150/161' is closed, opening it...
[1/12/11 7:30:10:597 CET] 0000003b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
Trying to connect to 10.249.66.150/161
[1/12/11 7:30:10:597 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.66.118/161 closed due to timeout
[1/12/11 7:30:10:598 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.249.66.42/161,socket=Socket[unconnected],lastUse=Wed
Jan 12 07:16:15 CET 2011]
[1/12/11 7:30:10:598 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 37043704
[1/12/11 7:30:10:599 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.253.37/161 closed due to timeout
[1/12/11 7:30:10:599 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 76fc76fc
[1/12/11 7:30:10:599 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 834893 micro seconds, closing it
[1/12/11 7:30:10:599 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 2a8c2a8c
[1/12/11 7:30:10:600 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.247.252.236/161 closed due to timeout
[1/12/11 7:30:10:600 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 76fc76fc
[1/12/11 7:30:10:600 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 26362636
[1/12/11 7:30:10:601 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 77cc77cc
[1/12/11 7:30:10:601 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 834938 micro seconds, closing it
[1/12/11 7:30:10:601 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 834869 micro seconds, closing it
[1/12/11 7:30:10:602 CET] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> java.nio.channels.ClosedChannelException
[1/12/11 7:30:10:602 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.11.31/161 closed due to timeout
[1/12/11 7:30:10:602 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.66.194/161 closed due to timeout
[1/12/11 7:30:10:602 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 77cc77cc
[1/12/11 7:30:10:603 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 26362636
[1/12/11 7:30:10:603 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 67d867d8
[1/12/11 7:30:10:603 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 834830 micro seconds, closing it
[1/12/11 7:30:10:603 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 4dfe4dfe
[1/12/11 7:30:10:604 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.11.46/161 closed due to timeout
[1/12/11 7:30:10:604 CET] 00000031 SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 3d203d2,peerAddress=10.249.66.42/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
[1/12/11 7:30:10:604 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 67d867d8
[1/12/11 7:30:10:605 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 57b857b8
[1/12/11 7:30:10:605 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 828913 micro seconds, closing it
[1/12/11 7:30:10:606 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
has not been used for 834586 micro seconds, closing it
[1/12/11 7:30:10:606 CET] 0000003c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.11.75/161 closed due to timeout
[1/12/11 7:30:10:606 CET] 00000032 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run> Socket
to 10.249.11.60/161 closed due to timeout
[1/12/11 7:30:10:606 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 57b857b8
[1/12/11 7:30:10:607 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout at 4dfe4dfe
[1/12/11 7:30:10:607 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 66b266b2
[1/12/11 7:30:10:607 CET] 0000003c SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[1/12/11 7:30:10:608 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 4c024c02
[1/12/11 7:30:10:608 CET] 0000003c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 66b266b2
[1/12/11 7:30:10:608 CET] 00000032 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[1/12/11 7:30:10:608 CET] 00000032 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.Snmp$PendingRequest at 4c024c02
[1/12/11 7:30:15:600 CET] 0000003b SystemOut O org.snmp4j.Snmp <send>
Removed pending request with handle: PduHandle[1366685025]
More information about the SNMP4J
mailing list