Hi Brice,
Did you find any workaround for this behavior? For me its going to next
level and subsequent send call is throwing IO exception due socket exhaust.
Thanks,
Bangar
On Fri, Apr 16, 2010 at 4:55 PM, Brice Fines <bfi...@sermepa.es> 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
>
_______________________________________________
SNMP4J mailing list
SNMP4J@agentpp.org
http://lists.agentpp.org/mailman/listinfo/snmp4j
