http://coldfusion.com logo
Join Slack
Powered by
Our application makes 10k+ multi-part cfhttp POST ...
# lucee
c
Our application makes 10k+ multi-part cfhttp POST requests per day (via a scheduled job) to various client Dynamics REST APIs for the purpose of syncing data to our system. ā€¢ Starting in June, we've been having intermittent issues with one of those requests hanging/blocking on 
<http://java.net|java.net>.SocketInputStream.socketRead0(Native Method)
. This SO article discusses the issue in more detail: https://stackoverflow.com/questions/28785085/how-to-prevent-hangs-on-socketinputstream-socketread0-in-java/28950809#28950809 ā€¢ Once this happens, the originating request/thread is stuck and the only solution is to restart Lucee. ā€¢ The blocking happens several times a week, but it's out of tens of thousands of requests. ā€¢ It wasn't a problem until June of this year. Our environment: Windows Server 2016 Lucee 5.3.10.97 Java 11.0.13 (Eclipse Adoptium) 64bit It's a bit of a needle in a haystack, but does anyone have suggestions on how to troubleshoot/resolve this? We are considering using a different library for making these requests, but that seems heavy-handed.
Here's (most of) the stack trace:
Copy code
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(Unknown Source)
java.net.SocketInputStream.read(Unknown Source)
java.net.SocketInputStream.read(Unknown Source)
sun.security.ssl.SSLSocketInputRecord.read(Unknown Source)
sun.security.ssl.SSLSocketInputRecord.readFully(Unknown Source)
sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(Unknown Source)
sun.security.ssl.SSLSocketInputRecord.decode(Unknown Source)
sun.security.ssl.SSLTransport.decode(Unknown Source)
sun.security.ssl.SSLSocketImpl.decode(Unknown Source)
sun.security.ssl.SSLSocketImpl.readApplicationRecord(Unknown Source)
sun.security.ssl.SSLSocketImpl$AppInputStream.read(Unknown Source)
org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:205)
org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:176)
org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135)
java.util.zip.InflaterInputStream.fill(Unknown Source)
java.util.zip.InflaterInputStream.read(Unknown Source)
java.util.zip.GZIPInputStream.read(Unknown Source)
java.io.FilterInputStream.read(Unknown Source)
org.apache.http.client.entity.LazyDecompressingInputStream.read(LazyDecompressingInputStream.java:64)
lucee.commons.io.IOUtil.copy(IOUtil.java:308)
lucee.commons.io.IOUtil.copy(IOUtil.java:75)
lucee.commons.io.IOUtil.toBytes(IOUtil.java:1107)
lucee.commons.io.IOUtil.toBytes(IOUtil.java:1102)
lucee.commons.net.http.httpclient.HTTPResponse4Impl.getContentAsByteArray(HTTPResponse4Impl.java:84)
lucee.runtime.tag.Http.contentAsBinary(Http.java:1373)
lucee.runtime.tag.Http._doEndTag(Http.java:1297)
lucee.runtime.tag.Http.doEndTag(Http.java:696)
dynamics.dynamics_webapi_request_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi_Request.cfc:120)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
lucee.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:786)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
dynamics.dynamics_webapi_request_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi_Request.cfc:48)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:696)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1931)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
dynamics.dynamics_webapi_cfc$cf.udfCall2(/cfc/dynamics/dynamics_WebApi.cfc:201)
dynamics.dynamics_webapi_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi.cfc)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl._callCachedWithin(UDFImpl.java:282)
lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
dynamics.dynamics_webapi_cfc$cf.udfCall1(/cfc/dynamics/dynamics_WebApi.cfc:169)
dynamics.dynamics_webapi_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi.cfc)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
dynamics.dynamics_webapi_cfc$cf.udfCall7(/cfc/dynamics/dynamics_WebApi.cfc:1166)
dynamics.dynamics_webapi_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi.cfc)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
dynamics.dynamics_webapi_cfc$cf.udfCall4(/cfc/dynamics/dynamics_WebApi.cfc:546)
dynamics.dynamics_webapi_cfc$cf.udfCall(/cfc/dynamics/dynamics_WebApi.cfc)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:697)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1950)
lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
dynamics.environment_cfc$cf.udfCall5(/cfc/dynamics/environment.cfc:446)
dynamics.environment_cfc$cf.udfCall(/cfc/dynamics/environment.cfc)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:696)
lucee.runtime.ComponentImpl.onMissingMethod(ComponentImpl.java:623)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1950)
lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
i
Suggestions off the top of my head...The Stack Overflow article suggests using a nonblocking HTTP client like Grizzly, which is maybe what you're already considering given your post, but might be worth a try if nothing else works. Another thought, If you run the http requests in a thread, you could probably add some logic to determine if the http request is going to hang (doesn't respond in x seconds/minutes and just terminate the thread it's in. Its pure speculation. And stupid question, but does setting a timeout on cfhttp fix the problem?
a
@zackster i vaguely remember something about this being an issue thats fixed in 6 ?
hunting lucee jira
c
@ian.hickey thanks for the input. we are looking at Grizzly as one option. we do have a timeout set on 
cfhttp
. we do have some requests that timeout without doing this hanging/blocking thing
a
@czeller i believe 6 introduced new http connection pooling
i vaguelly remember a ticket about http being blocked and not recovering until a lucee restart
i can't find the ticket now
c
@alexpixl8 thanks. all my searching takes me to discussions several years old about Java (and maybe Java+Windows)
a
i think it was specifically about a connection becoming blocked or stale and there only being a certain number of connections and them not being released in some scenarios
lucee 6 i think they changed how http is done with some connection pooling
6 is obvs in RC atm but might be worth testing up your app on it
šŸ‘ 1
see if it solves your sissue
issue
j
@czeller there might be a solution nestled in this doc that I wrote for my project: https://gist.github.com/jamiejackson/0e7f4eb399b161e610c1392c5d657d0e
the 
<http://sun.net|sun.net>.client.*
timeouts may be relevant and you may want to set some appropriate ones explicitly.
just an idea.
c
@jamiejackson that's definitely worth trying. thanks!
šŸ‘ 1
z
Yep good suggestion
c
Just to follow up - I tried adding the following to the Java options for the Tomcat Service Control panel, but sadly, this did not solve the issue šŸ˜ž
Copy code
-Dsun.net.client.defaultConnectTimeout=30000
-Dsun.net.client.defaultReadTimeout=600000
My guess is these timeouts only apply if you don't explicitly define a timeout on cfhttp, which we are already doing.
j
i don't know how the cfhttp timeout interplays with the java properties but maybe cfhttp dumbs down the timeouts in some way. is it feasible to try things with the cfhttp timeouts removed, but with the java properties in place? also, i think your connect timeout is probably way overestimated. iirc, connection timeouts will either be quick or they will be broken. with regard to the read timeout, do your cfhttp processes legitimately take up to 10 minutes?
c
@jamiejackson I set the timeouts really high with the intent of not breaking any existing functionality (on a busy system that does a lot of things) and at the same time (if they worked), stopping the hung requests after a few minutes
z
Lucee uses Apache http client, plus U should be setting that on the actual http calls
Open in Slack
PreviousNext
Powered by