[SNMP4J] Socket behaviour with SNMP commands over TCP
Brice Fines
bfines at sermepa.es
Wed Sep 22 10:16:19 CEST 2010
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
More information about the SNMP4J
mailing list