3 Replies Latest reply on May 23, 2016 4:25 AM by adinn

    Using Byteman to debug Connection refused.

    whitingjr

      Hi,

      I am using Byteman to debug the cause of "Connection refused" errors. Byteman is the tool to unobtrusively help diagnose such problems.

       

      I wrote a script to dump some useful information. Like the URL that fails. My rule is not being triggered.

       

      This is my rule

       

      ########################################################################

      #

      # Rule to trace connection refused

      #

       

      RULE Socket connect01

      CLASS java.net.AbstractPlainSocketImpl

      METHOD doConnect(InetAddress, int, int)

      AT SYNCHRONIZE ALL

      IF TRUE

      DO debug("About to establish connection using host["+$1.getHostName()+"] host address["+$1.getHostAddress()+"] and port ["+$2+"] port.")

      ENDRULE

       

      ########################################################################

       

      When I start my domain I see this in stdout

       

      [Server:G1A] TransformListener() : accepting requests on localhost:9091

      [Server:G1A] retransforming java.net.AbstractPlainSocketImpl

      [Server:G1A] org.jboss.byteman.agent.Transformer : possible trigger for rule Socket connect01 in class java.net.AbstractPlainSocketImpl

      [Server:G1A] RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into java.net.AbstractPlainSocketImpl.doConnect(java.net.InetAddress,int,int) void for rule Socket connect01

      [Server:G1A] org.jboss.byteman.agent.Transformer : inserted trigger for Socket connect01 in class java.net.AbstractPlainSocketImpl

       

      This shows the rule loaded properly and my settings to install the Byteman jar into the system classloader worked.

       

      When my application is running I don't see any debug messages starting with "About to establish connection". Either in the system out nor my server.log file.

      I do see plenty of Connection refused messages. With this stack trace

       

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956)) Caused by: java.net.ConnectException: Connection refused

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.PlainSocketImpl.socketConnect(Native Method)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at java.net.Socket.connect(Socket.java:589)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.NetworkClient.doConnect(NetworkClient.java:175)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.http.HttpClient.New(HttpClient.java:308)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.http.HttpClient.New(HttpClient.java:326)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1168)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1147)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:998)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:932)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1282)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1257)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.setupWrappedStream(URLConnectionHTTPConduit.java:236)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleHeadersTrustCaching(HTTPConduit.java:1319)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.onFirstWrite(HTTPConduit.java:1279)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.onFirstWrite(URLConnectionHTTPConduit.java:267)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:47)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at org.apache.cxf.io.AbstractThresholdOutputStream.write(AbstractThresholdOutputStream.java:69)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:100)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:241)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:253)

      2016-05-17 14:05:44,066 ERROR [stderr] (Thread-28 (ActiveMQ-client-global-threads-1533517956))  ... 79 more

       

      so the condition that should cause my rule to trigger is happening.

      I notice the method doConnect is synchronized. I'm not expecting that to be a problem for Byteman. Am I wrong ?

       

      Regards,

      Jeremy

        • 1. Re: Using Byteman to debug Connection refused.
          adinn

          Hi Jeremy,

           

          Firstly, I'll confirm that you are right that it makes no difference that method doConnect is synchronized.

           

          All looks fine with your rule and you appear to have verbose trace enabled (since the Transformer is printing info about injection). So I would expect the debug call to print output at least at at the first synchronized block whenever doConnect gets called.

           

          There may be a problem with injection in this case but the more likely possibility is that doConnect is not getting called. AbstractPlainSocketImpl is an abstract class so whatever implements it might actually be overriding doConnect and not calling the super method. That would account for your rule not getting triggered. So, let's see if we can test that possibility before looking at the injected bytecode.


          What I suggest you do to investigate this is add two extra rules:

           

          RULE check which doConnect
          
          CLASS ^java.net.AbstractPlainSocketImpl
          METHOD doConnect(InetAddress, int, int) 
          AT ENTRY
          
          IF TRUE
          DO traceln("*** Call to " + $0.getClass().getName() + ".doConnect")
          ENDRULE
          


          RULE dump call tree
          
          CLASS java.net.ConnectException
          METHOD <init>
          AT ENTRY
          
          IF TRUE
          DO traceStack("*** ConnectException created here ==> ")
          ENDRULE
          

           

          This will help clarify what code is actually getting executed. Let me know what output this generates we can take it from there.

           

          regards,

           

           

          Andrew Dinn

          • 2. Re: Using Byteman to debug Connection refused.
            whitingjr

            Hi Andrew,

            Thank you for the two additional rules. They were helpful to diagnose the Connection refused message.

             

            In the end the messages only appeared after I modified the root logging level from ERROR to INFO.

            Changing the level meant stdout messages logged with INFO level began to be written by the file handler.

             

            It was down to user error.

             

            Many thanks for you help,

            Jeremy

            • 3. Re: Using Byteman to debug Connection refused.
              adinn

              Hi Jeremy,

              Jeremy Whiting wrote:


              In the end the messages only appeared after I modified the root logging level from ERROR to INFO.

              Changing the level meant stdout messages logged with INFO level began to be written by the file handler.

               

              Aarrrgh, yes! I would never have thought of that until you mentioned it.

               

              I am glad all is working again.

               

              regards,

               

               

              Andrew Dinn