Hi Frank,
We are using SNMP4J 1.11 under Windows XP SP3 with websphere application
server (6.1.0.29 with IBM JDK).
(The behaviour I report also happens under AIX (5.3.0.0) with websphere
application server (6.1.0.25 with IBM JDK))
We are sending SNMP commands over TCP.
When SNMP4J is trying to close a socket because of the socket timeout, the
socket remains opened until next command is sent to that client (the
socket is then closed and a new one is opened).
That would correspond to the code in the "run" method in "
DefaultTcpTransportMapping$SocketTimeout":
long now = System.currentTimeMillis();
if ((socketCleaner == null) ||
(now - entry.getLastUse() >= connectionTimeout)) {
if (logger.isDebugEnabled()) {
logger.debug("Socket has not been used for "+
(now - entry.getLastUse())+
" micro seconds, closing it");
}
sockets.remove(entry.getPeerAddress());
try {
synchronized (entry) {
entry.getSocket().close();
}
logger.info("Socket to "+entry.getPeerAddress()+
" closed due to timeout");
}
catch (IOException ex) {
logger.error(ex);
}
}
The call to "entry.getSocket().close();" seems to be delayed till next
command.
Can you try to reproduce it? Is this the correct behaviour?
Thanks in advance.
Regards
Brice
I will mix SNMP4J traces and system traces to make it clear:
(commands are working ok)
>netstat -an | findstr /c:10.2.2.91
(no connection opened to destination 10.2.2.91 before sending command)
(sending one command to 10.2.2.91)
#################################################################################
[16/04/10 12:15:45:507 CEST] 0000002c SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[16/04/10 12:15:45:507 CEST] 0000002c SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=1361984573,pduHandle=PduHandle[856038686],securityEngineID=,securitymodel=org.snmp4j.security....@25e025
e,securityName=urwxxxxxxx,securityLevel=1,contextEngineID=,contextName=]
[16/04/10 12:15:45:507 CEST] 0000002c SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[856038686] and retry count left 0
[16/04/10 12:15:45:507 CEST] 0000002c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule>
CommonTimer schedule task: org.snmp4j.snmp$pendingrequ...@27322732 delay:
5000
[16/04/10 12:15:45:522 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.91/161'
returned: null
[16/04/10 12:15:45:522 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> {}
[16/04/10 12:15:45:522 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Socket for address '10.2.2.91/161' is closed, opening it...
[16/04/10 12:15:45:522 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Trying to connect to 10.2.2.91/161
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[unconnected],lastUse=Fri
Apr 16
12:15:45 CEST 2010]
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is connectable
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Connected to 10.2.2.91/161
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule>
CommonTimer schedule task:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@79ba79ba
delay: 60000
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=1373],lastUse=Fri
Apr 16 12:15:45 CEST
2010]
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Fire connected event for 10.2.2.91/161
[16/04/10 12:15:45:538 CEST] 0000002f SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.transportstateevent[source=org.snmp4j.transport.defaulttcptransportmapp...@3b683b68,peerAddress=10.2.2.9
1/161,newState=1,cancelled=false,causingException=null]
....
#################################################################################
netstat -an | findstr /c:10.2.2.91
TCP 10.2.2.144:1373 10.2.2.91:161 ESTABLISHED
The command was answered, the connection is established, the socket
timeout has not happened yet
#################################################################################
...
[16/04/10 12:15:50:538 CEST] 00000030 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[16/04/10 12:15:50:538 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.snmp$pendingrequ...@27322732
[16/04/10 12:16:45:553 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@79ba79ba
[16/04/10 12:16:45:553 CEST] 00000030 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Scheduling 751
[16/04/10 12:16:45:553 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule>
CommonTimer schedule task:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@792a792a
delay: 751
[16/04/10 12:16:45:553 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@79ba79ba
[16/04/10 12:16:46:319 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@792a792a
[16/04/10 12:16:46:319 CEST] 00000030 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Socket has not been used for 60015 micro seconds, closing it
[16/04/10 12:16:46:319 CEST] 00000030 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Socket to 10.2.2.91/161 closed due to timeout
[16/04/10 12:16:46:319 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@792a792a
#################################################################################
C:\Documents and Settings\S1665BF>netstat -an | findstr /c:10.2.2.91
TCP 10.2.2.144:1373 10.2.2.91:161 TIME_WAIT
The socket is not really closed yet, a bit later we send another command
#################################################################################
[16/04/10 12:18:09:584 CEST] 0000002c 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:07:6b:00:00:41:ce:39:4b
[16/04/10 12:18:09:584 CEST] 0000002c SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:07:6b:00:00:41:ce:39:4b,
securityName=urwxxxxxxx)
[16/04/10 12:18:09:584 CEST] 0000002c SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[16/04/10 12:18:09:584 CEST] 0000002c SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=1361984576,pduHandle=PduHandle[856038690],securityEngineID=80:00:1f:88:80:07:6b:00:00:41:ce:39:4b,securi
tymodel=org.snmp4j.security....@25e025e,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:07:6b:00:00:41
:ce:39:4b,contextName=]
[16/04/10 12:18:09:584 CEST] 0000002c SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[856038690] and retry count left 0
[16/04/10 12:18:09:600 CEST] 0000002c SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule>
CommonTimer schedule task: org.snmp4j.snmp$pendingrequ...@76e876e8 delay:
5000
[16/04/10 12:18:09:600 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.91/161'
returned: null
[16/04/10 12:18:09:600 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> {}
[16/04/10 12:18:09:600 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Socket for address '10.2.2.91/161' is closed, opening it...
[16/04/10 12:18:09:600 CEST] 0000002c SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Trying to connect to 10.2.2.91/161
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 8 for:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[unconnected],lastUse=Fri
Apr 16
12:18:09 CEST 2010]
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is connectable
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Connected to 10.2.2.91/161
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl <schedule>
CommonTimer schedule task:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@25822582
delay: 60000
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketEntry
<addRegistration> Adding operation 4 for:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=1387],lastUse=Fri
Apr 16 12:18:09 CEST
2010]
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Fire connected event for 10.2.2.91/161
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.transportstateevent[source=org.snmp4j.transport.defaulttcptransportmapp...@3b683b68,peerAddress=10.2.2.9
1/161,newState=1,cancelled=false,causingException=null]
[16/04/10 12:18:09:600 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is writable
....
[16/04/10 12:18:14:600 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.snmp$pendingrequ...@76e876e8
[16/04/10 12:18:14:600 CEST] 00000030 SystemOut O
org.snmp4j.Snmp$PendingRequest <run> PendingRequest canceled key=null,
pdu=null, target=null, transport=null, listener=null
[16/04/10 12:18:14:600 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.snmp$pendingrequ...@76e876e8
################################################################################
second command runs OK
>netstat -an | findstr /c:10.2.2.91
TCP 10.2.2.144:1373 10.2.2.91:161 TIME_WAIT
TCP 10.2.2.144:1387 10.2.2.91:161 ESTABLISHED
The current connection (1387) is established, the previous one (1373) is
still wainting for closing
#################################################################################
[16/04/10 12:19:09:615 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Run wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@25822582
[16/04/10 12:19:09:615 CEST] 00000030 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Socket has not been used for 60015 micro seconds, closing it
[16/04/10 12:19:09:615 CEST] 00000030 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Socket to 10.2.2.91/161 closed due to timeout
[16/04/10 12:19:09:615 CEST] 00000030 SystemOut O
org.snmp4j.util.commonj.TimerManagerCommonTimerImpl$CommonJTimerTaskWrapper
<timerExpired> Removing wrapped TimerTask:
org.snmp4j.transport.defaulttcptransportmapping$sockettime...@25822582
#################################################################################
>netstat -an | findstr /c:10.2.2.91
TCP 10.2.2.144:1387 10.2.2.91:161 TIME_WAIT
When the timeout of the connection for the second command (1387) happens,
the first connection (1373) finally closes and the second one is now
waiting for closing
_______________________________________________
SNMP4J mailing list
SNMP4J@agentpp.org
http://lists.agentpp.org/mailman/listinfo/snmp4j
