[SNMP4J] Socket behaviour with SNMP commands over TCP
bangarappa
bang.chill at gmail.com
Wed Sep 22 15:05:06 CEST 2010
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 <bfines at 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 <fock at agentpp.com>
> Enviado por: snmp4j-bounces at agentpp.org
> 21/09/2010 19:57
>
> Para
> snmp4j at 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<bfines at 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.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
> >>
> > _______________________________________________
> > 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
>
> _______________________________________________
> SNMP4J mailing list
> SNMP4J at agentpp.org
> http://lists.agentpp.org/mailman/listinfo/snmp4j
>
> _______________________________________________
> SNMP4J mailing list
> SNMP4J at agentpp.org
> http://lists.agentpp.org/mailman/listinfo/snmp4j
>
More information about the SNMP4J
mailing list