Hi Brice, As you said, yes i am bind to use TCP along with UDP. Things are fine with UDP, but the moment i switch to TCP after some time my server is getting exhausted with socket exception.
Sorry, may be i am getting into some basics here. Can someone tell me, the reason behind TCPMapping creating multiple new socket connections? I see this behavior even when set timeout value to 0 or -1. Regards, Bangar On Wed, Sep 22, 2010 at 1:46 PM, Brice Fines <bfi...@sermepa.es> wrote: > Hi, > > @Bangar > So far, we did not run into socket port problems (maybe later with a > higher number of SNMP over TCP clients). As Frank stated, this seems to be > the default (and correct) behaviour of the underlying OS with sockets. > Inside the JVM, the socket.close() method get called, but the JVM cannot > force the OS to really close the socket. Maybe you can check this by > writing a short program that uses TCP sockets, and you could monitor what > happens during execution to check if/when sockets are closed. > As I stated before, I noticed this behaviour under Windows XP and AIX > (both using IBM JVM). > Maybe you can check if SUN JVM does the same with sockets. > Anyway, I think sockets behaviour is related to JVM and/or OS, it is not a > SNMP4J problem. > So, as Frank suggested, if you can use SNMP over UDP, you should give it a > try. > > @Frank > I suppose your question was for Bangar, but, for our app, we are compelled > to use TCP instead of UDP to send command (to receive TRAP, we use UDP) > because our security system does not allow direct incoming traffic against > server from outside (e.g. internet). By using TCP, the incoming traffic > use the same socket connection used to open communication and send command > from server (i.e. the incoming traffic use outgoing traffic socket). With > UDP, command answer would come in a brand new connection that would be > denied by firewalls security. Security cannot be modified in that case > (too many SNMP clients out there to put some rules for everyone + servers > NEVER can be connected directly from outside). So we use TCP (maybe > another option would be to build a bridge (hardware/software) to send > command over UDP to clients, but TCP was easier to implement). > Maybe Bangar is forced to use TCP due to security constraints too. > By the way, I updated our app to SNMP4J 1.11.1 (the release including the > fix for thread CPU usage), and checked it works OK under Windows XP and > AIX (both with IBM JVM). Thanks for including the fix in official release. > > Regards > > > > > Frank Fock <f...@agentpp.com> > Enviado por: snmp4j-boun...@agentpp.org > 21/09/2010 19:57 > > Para > snmp4j@agentpp.org > cc > > Asunto > Re: [SNMP4J] Socket behaviour with SNMP commands over TCP > > > > > > > Hi, > > The behavior listed below is simply normal TCP operation. > Nothing special and nothing one should provide any workarounds > for. If you close and open TCP regularly why not using > UDP instead? > > Best regards, > Frank > > On 21.09.2010 15:35, bangarappa wrote: > > 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 > > -- > 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 > > _______________________________________________ > 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