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

Using Byteman to debug Connection refused.

whitingjr May 17, 2016 3:05 PM

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.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 May 18, 2016 4:02 AM (in response to whitingjr)
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
Actions
2. Re: Using Byteman to debug Connection refused.

whitingjr May 19, 2016 8:32 PM (in response to adinn)

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
Actions
3. Re: Using Byteman to debug Connection refused.

adinn May 23, 2016 4:25 AM (in response to whitingjr)

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
Actions

Go to original post