[SNMP4J] Socket behaviour with SNMP commands over TCP
Brice Fines
bfines at sermepa.es
Fri Apr 16 13:25:52 CEST 2010
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.USM at 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$PendingRequest at 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$SocketTimeout at 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.DefaultTcpTransportMapping at 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$PendingRequest at 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$SocketTimeout at 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$SocketTimeout at 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$SocketTimeout at 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$SocketTimeout at 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$SocketTimeout at 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.USM at 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$PendingRequest at 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$SocketTimeout at 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.DefaultTcpTransportMapping at 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$PendingRequest at 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$PendingRequest at 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$SocketTimeout at 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$SocketTimeout at 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
More information about the SNMP4J
mailing list