4 Replies Latest reply on Jul 1, 2010 8:22 AM by Robert Munteanu

    Tracing socket create and close operations

    Robert Munteanu Newbie

      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

        • 1. Re: Tracing socket create and close operations
          Andrew Dinn Master

          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

          1 of 1 people found this helpful
          • 2. Re: Tracing socket create and close operations
            Robert Munteanu Newbie

            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.

            • 3. Re: Tracing socket create and close operations
              Andrew Dinn Master

              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

              1 of 1 people found this helpful
              • 4. Re: Tracing socket create and close operations
                Robert Munteanu Newbie

                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.