org.apache.axis2.AxisFault: Transport error: 502 Error: Bad Gateway

[bdw429s]

This is a bit of an odd issue and it involves several layers so I can't be sure that Boncode is at fault but I'm at a loss to troubleshoot it any further. I have a client site running IIS with a per-site Boncode installation that has each IIS site pointing to matching CommandBox servers running ColdFusion 2016 with AJP enabled in the Undertow server. All of the pages in these sites are served via virtual directories BTW. All of this work absolutely beautifully except.... after several days of flawless testing, the client found a cfinvoke call in their code that calls an internal webservice on the same server via SOAP that was throwing this error:

org.apache.axis2.AxisFault: Transport error: 502 Error: Bad Gateway
    at org.apache.axis2.transport.http.HTTPSender.handleResponse(HTTPSender.java:310)
    at org.apache.axis2.transport.http.HTTPSender.sendViaPost(HTTPSender.java:194)
    at org.apache.axis2.transport.http.HTTPSender.send(HTTPSender.java:75)
    at org.apache.axis2.transport.http.CommonsHTTPTransportSender.writeMessageWithCommons(CommonsHTTPTransportSender.java:402)
    at org.apache.axis2.transport.http.CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:231)
    at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:443)
    at org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:406)
    at org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:229)
    at org.apache.axis2.client.OperationClient.execute(OperationClient.java:165)
    at webservices.WebservicesUtilityCfcStub.initialize_object(WebservicesUtilityCfcStub.java:550)
    at sun.reflect.GeneratedMethodAccessor116.invoke... ''

The code is very simple and looks about like this (a couple params removed for readability):

<cfinvoke webservice="http://dev003c/webservices/utility.cfc?wsdl"
                method="initialize_object"
                returnvariable="w_result_struct">

I've traced the request through and the initial request that hits the test .cfm page that runs the cfinvoke call is fine, but the internal request that is made by the underlying Axis libraries in ColdFusion is hitting IIS and IIS sure enough comes back with a 502 status. I enabled failed request tracing in ISS and found the actual response of the SOAP call was:

Generic Connector Communication Error: 
<hr>
Please check and adjust your setup:
<br>Ensure that Tomcat is running on given host and port.<br>
If this is a timeout error consider adjusting IIS timeout by changing executionTimeout attribute in web.config (see manual).
<br>
<pre>
Connection between Tomcat and IIS experienced error. If you restarted Tomcat this is expected.     
at BonCodeAJP13.BonCodeAJP13ServerConnection.ConnectionError()    
at BonCodeAJP13.BonCodeAJP13ServerConnection.p_CreateConnection(BonCodeAJP13PacketCollection packetsToSend)    
at BonCodeIIS.BonCodeCallHandler.ProcessRequest(HttpContext context)
</pre>

This is odd since the SOAP call is simply a POST to a web-accessible CFC. The issue appears to be related to SOAP calls only since I can hit the same CFC and run the same code, but bypass the SOAP stuff with this URL and it works great (a couple params removed for readability):

http://dev003c/webservices/utility.cfc?method=initialize_object

I also tried to re-create the exact same SOAP body and POST from the Postman app and it also worked correct (through Boncode) so I think there's something a little different happening when the SOAP POST comes specifically from the Axis libraries inside of ColdFusion.
I enabled the highest level of log levels inside of BonCode and can see that this error simply happens over and over-- 500 times until BonCode gives up:

Unable to read data from the transport connection: An established connection was aborted by the software in your host machine.
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at BonCodeAJP13.BonCodeAJP13ServerConnection.ComunicateWithTomcat()
2018-05-04 11:36:21 warning Stream reading problem (1). Null packet received in stream.
2018-05-04 11:36:21 1.0.36 ERROR 

I don't know what that could possibly be. The AJP port is up and working fantastically for everything else we've tested with the exception of this SOAP POST to the CFC. Here is the FULL log output. Note there are two separate requests that this log captures. The initial hit of my browser to a test file called bradTest.cfc which runs the cfinvoke code, and then the second request which is the actual SOAP request that is failing.

BonCodeAJP13Connection_4_DEV003_20180504.log

I am also including the full IIS trace of the bad request that shows the SOAP request. Unzip this file and open the IIS bad request trace.xml file. Note the xsl file needs to be in the same directory for it to render in your browser.

IIS bad request trace.zip

I would love any additional information you can give me.

[bdw429s]

An additional note here, if I point the webservice call directly at the HTTP listener in CommandBox, it works great, so it's only an issue going through IIS/Boncode.

[Bilal-S]

Brad, from logs there seems to be a missing byte: </soapenv:Envelope should be </soapenv:Envelope> . Why that is would need to sniffed out. I know a few years back that when we used Axis 2, we had to change a few items to make it work with IIS some call patterns are not supported by IIS. However, this seems to be plain HTTP Post so it should not apply. Is there a min test case on CF 2016 that you have handy? E.g. utility.cfc? Or does this happen with any CFC exposed as web-service?

[bdw429s]

Thanks for the reply @Bilal-S . Good catch on the missing character, but why would that show up as a Null packet received in stream. error. I would expect the HTTP body to be sent with the post and then Axis to blow up when trying to deserialize the XML. Or perhaps that is what happened and Axis is not configured to log anything??

I'm home now from the client where I was seeing this and will try and recreated it on my own machine. If I can, I will certainly provide those instructions here.

[Bilal-S]

Brad, were you able to recreate?

[bdw429s]

Thanks for the reminder @Bilal-S . I tried it today locally and I am able to reproduce this, but ONLY if I am hitting my CFC from a virtual directory. Here is my local setup.

I started up a CommandBox server running Adobe 2016:

> touch Application.cfm
> touch index.cfm --open
> server set web.ajp.enable=true
> server set web.alias./brad=C:/some/path
> server set app.cfengine=adobe@2016
> server start

Then I pointed an IIS site with BonCode to my default AJP port of 8009 which is being listened to on my CommandBox server. I also created a matching Virtual Directory in IIS called /brad that points to C:/some/path.

I created the following file in C:/some/path/service.cfc:

component {

    remote struct function foo() {
        return { foo : 'test' };
    }
}

I then put this test code in the index.cfm file created and opened above:

<cfinvoke webservice="http://127.0.0.1/brad/service.cfc?wsdl"
  method="foo">

I can hit this URL in my browser and it works great: http://127.0.0.1/brad/service.cfc?wsdl

I can also hit this URL in my browser and it works great: http://127.0.0.1:81/brad/service.cfc?method=foo

But when I run the index.cfm which makes the SOAP call, I get this error:

org.apache.axis2.AxisFault: Transport error: 502 Error: Bad Gateway

Which is due to that missing byte in BonCode.

If I bypass IIS and Boncode and change the webservice invoke to hit the HTTP port on CommandBox directly like so:

<cfinvoke webservice="http://127.0.0.1:53316/brad/service.cfc?wsdl"
                method="foo">

Then it works fine.

So to recap, SOAP calls through IIS when hitting a CFC in a virtual directory seem to specifically be the cause of this issue. Let me know if you need more information to recreate this on your end.

[bdw429s]

Hi @Bilal-S , did you get a chance to review my steps to reproduce the error above?

[Bilal-S]

Brad, I saw the steps and I think it is clear enough to follow. I am currently on a multi-week business trip in Europe and won't have access to my test-rig at home. I will run this through its paces once I return.

Thanks again for the info, Bilal

[bdw429s]

Thanks for the info @Bilal-S and enjoy your trip!

[funketyme]

Just an FYI. We have recently upgraded from Tomcat 8 / Lucee 4.5 to Tomcat 9 / Lucee 5.x. In the past week we have seen a similar "502 Bad Gateway" error occassionally. I'm still in the process of debugging and don't have any sample code to post at this time, but wanted to leave a note here in case it helps.

[bdw429s]

@funketyme That's a very generic message, but if you open up the logging levels in Boncode, you should get a lot more information from the Boncode side of things that causes the generic IIS error. Here's the docs: http://www.boncode.net/connector/webdocs/Tomcat_Connector.htm#_Toc483166268 Read the "Log Level" section.

[bdw429s]

@Bilal-S I hope your trip was well. Have you had a chance to try the full reproduction steps I posted back on May 16th?

[funketyme]

Thanks for the quick response. We are still running 1.00 from a few years ago and have also noticed some of the IIS worker process issues fixed by a newer version. We are going to upgrade to 1.036B, up our logging, and do some tests in our QA environment before upgrading production.

[Bilal-S]

Yes I am back but still doing 14 hour days. I am looking into a few issues.

[Bilal-S]

Brad, I no longer get the 502 errors but I am also not sure I setup things correctly to mimic your test. Can you try this package with new build and let me know what you see? https://drive.google.com/file/d/1FCW8aK6S20oQH5kgO8WN91Y3ziagFzCA/view?usp=sharing

This is not a full install package, you will have to replace the library files inside the standard package.

Best, Bilal

[bdw429s]

Hi @Bilal-S the version of the connector now shows as 1.0.37 but the error persists. Are you available for a screen share call so I can help you reproduce this? Also...

I no longer get the 502 errors

Does that mean that you were able to reproduce the error and you made changes that caused the error to go away? Or does it mean that you were never able to reproduce the error at all?

[bdw429s]

Here's a snippet of the Boncode logs, which again show a missing character at the end of the XML packet:

 begin of packet ====> 
Type:18
User Data High:52
User Data Low:0
� �<?xml version='1.0' encoding='UTF-8'?><soapenv:Envelope xmlns:soapenv="http://www.w3.org/2003/05/soap-envelope"><soapenv:Body><ns3:foo xmlns:ns3="http://ws.apache.org/axis2" /></soapenv:Body></soapenv:Envelope
 <==== end of packet

2018-07-10 14:22:07 warning Stream reading problem (1). Null packet received in stream.
2018-07-10 14:22:07 1.0.37 ERROR 

Unable to read data from the transport connection: An established connection was aborted by the software in your host machine.
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at BonCodeAJP13.BonCodeAJP13ServerConnection.ComunicateWithTomcat()
2018-07-10 14:22:07 warning Stream reading problem (1). Null packet received in stream.
2018-07-10 14:22:07 1.0.37 ERROR 

I'm also curious what the extra characters are before the start of the XML.

[Bilal-S]

Thanks for letting me know. I found the issue for the 502 problems. There were a few things related to timing of network packets and ordering of them.
I could net get a good debug environment to work for Axis issue. I will have to setup a whole new rig and that does take a little time since Visual Studio is a pain to install.

[bdw429s]

I'm not sure what all you need setup to be able to develop, but as far as setting up a test environment, are you using CommandBox like I showed above? It requires zero installation, doesn't conflict with any other servers you may have running, and will spin up in seconds. You don't even need an Adobe CF license. It will spin up a developer edition by default. You should be able to spin up my example pretty much anywhere.

[Bilal-S]

I am using CF2018 and the setup with a SOAP service in virtual and local directory. I am using a node client to make the calls and not getting any errors with the 1.0.37 beta build. Both services in local and dir return results without any bytes chopped off.

I will install a second CF server and make the calls between them.

[Bilal-S]

We may have to connect to see whether I am getting this wrong? I am assuming you have <EnableAdobeMode>True</EnableAdobeMode> In your BonCode settings file when using Adobe 2016?

[bdw429s]

No, I am not using Adobe mode because I am not using Adobe's hacked-up version of Tomcat with their customized AJP connectors. I am running ACF on CommandBox which deploys programmatically on JBoss Undertow and Boncode is connecting directly to Undertow's AJP listener which I wouldn't expect to require any of the Adobe workarounds for the AJP settings and such.

I would be happy to do a quick Zoom call with you to show you. When would be a good time that works for you? If you would join the CFML Slack team I've linked to we can DM and arrange to get together much easier.
https://cfml-slack.herokuapp.com/

[Bilal-S]

This would explain some of it. Adobe uses a quirky way of auto-mapping virtual directories from IIS to servlet container. I will see whether I can signup to the slack channel in a bit so we can coordinate a screen sharing meeting.

B.

[bdw429s]

Ok, thanks and let me know when you're available. I'm still confused on a few issues though.

• Are you saying I should be using Adobe mode even though I'm not using a J2E install?
• Have you tested Boncode on a J2E install of Adobe CF (not their hacked up Tomcat version)
• Have you tested Boncode with CommandBox? I provided step by step instructions above and it only takes a couple minutes to have it all spun up and running with nothing installed.

There is also a screencast here that shows running Boncode with CommandBox: https://www.youtube.com/watch?v=8q7sSZ7gK3E

[Bilal-S]

Should be fixed with 1.0.37 https://github.com/Bilal-S/iis2tomcat/releases/tag/1.0.37

[bdw429s]

@Bilal-S Excellent work! Were you able to get to the bottom of it, or did you just have to put in a work around for zero content length?