[SNMP4J] Socket behaviour with SNMP commands over TCP
Frank Fock
fock at agentpp.com
Mon Apr 19 01:39:30 CEST 2010
Hi Brice,
I will investigate this in conjunction with the fix of
Jim Snyder for the Java 1.5 CPU usage bug.
Best regards,
Frank
On 16.04.2010 13:25, Brice Fines wrote:
> 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
>
>
>
> _______________________________________________
> SNMP4J mailing list
> SNMP4J at agentpp.org
> http://lists.agentpp.org/mailman/listinfo/snmp4j
--
AGENT++
http://www.agentpp.com
http://www.snmp4j.com
http://www.mibexplorer.com
http://www.mibdesigner.com
More information about the SNMP4J
mailing list