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....@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 -- AGENT++ http://www.agentpp.com http://www.snmp4j.com http://www.mibexplorer.com http://www.mibdesigner.com _______________________________________________ SNMP4J mailing list SNMP4J@agentpp.org http://lists.agentpp.org/mailman/listinfo/snmp4j