Tracing socket create and close operations

[rombert]

I'm trying to debug a situation where an application is running out of file descriptors. I've enabled the SocketMonitor rules in my application, and after receiving a 'Too many open files' IOException I was able to get the full trace.

Strangely enough, the number of 'create' traces is way out of sync with the number of 'close' traces, but close to the number of 'connect' traces.

[rm@sec5 ~]$ grep -e '\*\*\*.*create' socketOperations.log   | wc -l
1342
[rm@sec5 ~]$ grep -e '\*\*\*.*connect' socketOperations.log  | wc -l
32228
[rm@sec5 ~]$ grep -e '\*\*\*.*close' socketOperations.log   | wc -l
31540

Is there anything I'm missing?

Thanks,

Robert

[adinn]

Robert Munteanu wrote:

Is there anything I'm missing?

Well, I guess that could account for the 'Too many open files' IOException. Of course it might just be that your rule is  missing some of the close operations because it is attached to ServerSocket.close and a subclass of ServerSocket has redefined the close method but not called super.close(). You could try injecting your close rule down into subclasses of ServerSocket too (i.e. specify CLASS ^ServerSocket) and see if the count changes.

The other thing which might be useful would be to print the socket in the create, open and close rules i.e. use traceln("open " + $0) etc then sort the output and tick off each create socket against an opened socket and then against a closed socket. Note that you don't need to write ... + $0.toString() -- Byteman automatically promotes anything to a string where it is needed.

If you use traceln("open" +  $0.getClass().getName() + " " + $0) then upon sorting this will also group the sockets by classname which  might make it easier to spot what is happening.

regards,

Andrew Dinn

[rombert]

Andrew Dinn wrote:

Robert Munteanu wrote:

Is there anything I'm missing?

Well, I guess that could account for the 'Too many open files' IOException. Of course it might just be that your rule is  missing some of the close operations because it is attached to ServerSocket.close and a subclass of ServerSocket has redefined the close method but not called super.close(). You could try injecting your close rule down into subclasses of ServerSocket too (i.e. specify CLASS ^ServerSocket) and see if the count changes.

The close rule actually uses ^java.net.ServerSocket, so I'm off the hook here. By looking closer at the logs, I discovered that SSL socket connections were counted twice, i.e.

*** connect 604717a9[SSL_NULL_WITH_NULL_NULL: Socket[addr=xxx/yyy,port=443,localport=46787]]java.net.Socket.connect(Socket.java:540)
com.sun.net.ssl.internal.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:550)
com.sun.net.ssl.internal.ssl.BaseSSLSocketImpl.connect(BaseSSLSocketImpl.java:141)
sun.net.NetworkClient.doConnect(NetworkClient.java:163)
sun.net.www.http.HttpClient.openServer(HttpClient.java:394)
sun.net.www.http.HttpClient.openServer(HttpClient.java:529)
sun.net.www.protocol.https.HttpsClient.<init>(HttpsClient.java:272)
sun.net.www.protocol.https.HttpsClient.New(HttpsClient.java:329)
sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.getNewHttpClient(AbstractDelegateHttpsURLConnection.java:172)
sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:801)
sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:158)
sun.net.www.protocol.https.HttpsURLConnectionImpl.connect(HttpsURLConnectionImpl.java:133)
*** connect 604717a9[SSL_NULL_WITH_NULL_NULL: Socket[addr=xxx/yyy,port=443,localport=46787]]com.sun.net.ssl.internal.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:552)
com.sun.net.ssl.internal.ssl.BaseSSLSocketImpl.connect(BaseSSLSocketImpl.java:141)
sun.net.NetworkClient.doConnect(NetworkClient.java:163)
sun.net.www.http.HttpClient.openServer(HttpClient.java:394)
sun.net.www.http.HttpClient.openServer(HttpClient.java:529)
sun.net.www.protocol.https.HttpsClient.<init>(HttpsClient.java:272)
sun.net.www.protocol.https.HttpsClient.New(HttpsClient.java:329)
sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.getNewHttpClient(AbstractDelegateHttpsURLConnection.java:172)
sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:801)
sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:158)
sun.net.www.protocol.https.HttpsURLConnectionImpl.connect(HttpsURLConnectionImpl.java:133)

Also, I'm still looking for the missing 'create' socket calls. I use the single Socket create rule from the sample rule, which is

RULE Socket trace create
CLASS java.net.Socket   
METHOD <init>(SocketAddress, SocketAddress, boolean)
AT EXIT                                             
IF TRUE                                             
DO traceStack("*** create " + $0, "socketOperations", 15)               
ENDRULE    

but I noticed that this does not count the no-arg constructor and the java.net.Proxy constructor. I'm going to look into getting those counted as well, and see where that takes me.

Thanks.

[adinn]

Robert Munteanu wrote:

The close rule actually uses ^java.net.ServerSocket, so I'm off the hook here. By looking closer at the logs, I discovered that SSL socket connections were counted twice, . . .

Ah ok. I think there is a note about this in the programmer's guide but I'll mention it here annyway. If you use overriding injection into a subclass method which calls the super method your rule gets triggered in both the child and the parent. If you know that all children will call the super and you only want one firing then you can drop the ^ and just run the rule once in the super class. If some children don't call super then you will have to inject trigger code into super and suibclasses try to idenitfy a condition to inhibit firing in the super class method when called from a subclass. For example, you could try

  IF !callerEquals("connect")

which would only allow the ruel to fire when triggered on an outermost call to connect. If you wanted to be more precise so as to be sure that it is a connect call on a class whose name ends in "SSLSocket" you could use a regexp match e.g

  IF !callerMatches(".*SocketImpl\.connect", true)

Robert Munteanu wrote:

Also, I'm still looking for the missing 'create' socket calls. I use the single Socket create rule from the sample rule, which is

RULE Socket trace create
CLASS java.net.Socket   
METHOD <init>(SocketAddress, SocketAddress, boolean)
AT EXIT                                             
IF TRUE                                             
DO traceStack("*** create " + $0, "socketOperations", 15)               
ENDRULE    

but I noticed that this does not count the no-arg constructor and the java.net.Proxy constructor. I'm going to look into getting those counted as well, and see where that takes me.

Yes, but you may need to check the output once again in case the no arg constructor etc indirect through one of the other constructors causing your code to count twice. Once again you migth want to use a condition to avoid counting more than once.

A thing you might notice with constructors is that an AT ENTRY rule is only fired after executing super.<init> (or redirecting through some alternative <init>), The rule may say AT ENTRY but actually is not safe to run rule code before the object has been constructed so Byteman doesn't do it.

regards,

Andrew Dinn

[rombert]

Robert Munteanu wrote:

Also, I'm still looking for the missing 'create' socket calls. I use the single Socket create rule from the sample rule, which is

RULE Socket trace create
CLASS java.net.Socket   
METHOD <init>(SocketAddress, SocketAddress, boolean)
AT EXIT                                             
IF TRUE                                             
DO traceStack("*** create " + $0, "socketOperations", 15)               
ENDRULE    

but I noticed that this does not count the no-arg constructor and the java.net.Proxy constructor. I'm going to look into getting those counted as well, and see where that takes me.

Yes, but you may need to check the output once again in case the no arg constructor etc indirect through one of the other constructors causing your code to count twice. Once again you migth want to use a condition to avoid counting more than once.

A thing you might notice with constructors is that an AT ENTRY rule is only fired after executing super.<init> (or redirecting through some alternative <init>), The rule may say AT ENTRY but actually is not safe to run rule code before the object has been constructed so Byteman doesn't do it.

Thanks. I'm lazy enough to not care about duplicates and I'm filtering them in my parser.