URLDecoder timeout for very large POST requests

[martin]

Hi,

I am experiencing a problem with inbound emails from Mandrill that contain
large attachments.

Mandrill is posting a large URLEncoded JSON string - the last one that
failed was around 15MB.

The error that I receive (see stack trace below) seems to suggest that
Lucee is timing out after 10 seconds during the decoding of this string -
before it even gets to run any of our code where we have set a request
timeout of two minutes.

I am guessing that this is where Lucee is parsing the ‘form’ struct?

Can anybody think of a way around this problem or how to improve
performance here??

Your hopefully,

Martin

request ((fail to retrieve
path:java.lang.NullPointerException:null):49) has run into a timeout (10
seconds) and has been stopped.
StackTrace
string
request ((fail to retrieve path:java.lang.NullPointerException:null):49) has
run into a timeout (10 seconds) and has been stopped.
at
lucee.commons.net.URLDecoder.decode(URLDecoder.java:65):65
at
lucee.runtime.type.scope.ScopeSupport.fillDecoded(ScopeSupport.java:179):179
at
lucee.runtime.type.scope.FormImpl.initializeUrlEncodedOrTextPlain(FormImpl.java:261):261
at
lucee.runtime.type.scope.FormImpl.initialize(FormImpl.java:134):134
at
lucee.runtime.PageContextImpl.formScope(PageContextImpl.java:1172):1172
at
lucee.runtime.type.scope.UndefinedImpl.reinitialize(UndefinedImpl.java:595):595
at
lucee.runtime.type.scope.UndefinedImpl.initialize(UndefinedImpl.java:574):574
at
lucee.runtime.PageContextImpl.initialize(PageContextImpl.java:546):546
at
lucee.runtime.CFMLFactoryImpl.getPageContextImpl(CFMLFactoryImpl.java:161):161
at
lucee.runtime.CFMLFactoryImpl.getLuceePageContext(CFMLFactoryImpl.java:140):140
at
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:435):435
at
lucee.loader.servlet.CFMLServlet.service(Unknown Source):-1
at
javax.servlet.http.HttpServlet.service(HttpServlet.java:727):727
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303):303
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52):52
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
com.seefusion.Filter.doFilter(Filter.java:49):49
at
com.seefusion.SeeFusion.doFilter(SeeFusion.java:1500):1500
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220):220
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122):122
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504):504
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170):170
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103):103
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116):116
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421):421
at
org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190):190
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611):611
at
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314):314
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145):1145
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615):615
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61):61
at
java.lang.Thread.run(Thread.java:745):745

    TagContext Array

[Michael_van_Leest]

Isn’t there also a setting in tomcat and in the lucee config for max
upload/form size? Not sure if that is related to your issue, but might be
worth looking at.

Mike2015-11-11 15:30 GMT+01:00 <@martin>:

Hi,

I am experiencing a problem with inbound emails from Mandrill that contain
large attachments.

Mandrill is posting a large URLEncoded JSON string - the last one that
failed was around 15MB.

The error that I receive (see stack trace below) seems to suggest that
Lucee is timing out after 10 seconds during the decoding of this string -
before it even gets to run any of our code where we have set a request
timeout of two minutes.

I am guessing that this is where Lucee is parsing the ‘form’ struct?

Can anybody think of a way around this problem or how to improve
performance here??

Your hopefully,

Martin

request ((fail to retrieve
path:java.lang.NullPointerException:null):49) has run into a timeout (10
seconds) and has been stopped.
StackTrace
string
request ((fail to retrieve path:java.lang.NullPointerException:null):49)
has
run into a timeout (10 seconds) and has been stopped.
at
lucee.commons.net.URLDecoder.decode(URLDecoder.java:65):65
at

lucee.runtime.type.scope.ScopeSupport.fillDecoded(ScopeSupport.java:179):179
at

lucee.runtime.type.scope.FormImpl.initializeUrlEncodedOrTextPlain(FormImpl.java:261):261
at
lucee.runtime.type.scope.FormImpl.initialize(FormImpl.java:134):134
at
lucee.runtime.PageContextImpl.formScope(PageContextImpl.java:1172):1172
at

lucee.runtime.type.scope.UndefinedImpl.reinitialize(UndefinedImpl.java:595):595
at

lucee.runtime.type.scope.UndefinedImpl.initialize(UndefinedImpl.java:574):574
at
lucee.runtime.PageContextImpl.initialize(PageContextImpl.java:546):546
at

lucee.runtime.CFMLFactoryImpl.getPageContextImpl(CFMLFactoryImpl.java:161):161
at

lucee.runtime.CFMLFactoryImpl.getLuceePageContext(CFMLFactoryImpl.java:140):140
at

lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:435):435
at
lucee.loader.servlet.CFMLServlet.service(Unknown Source):-1
at
javax.servlet.http.HttpServlet.service(HttpServlet.java:727):727
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303):303
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52):52
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
com.seefusion.Filter.doFilter(Filter.java:49):49
at
com.seefusion.SeeFusion.doFilter(SeeFusion.java:1500):1500
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at

org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220):220
at

org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122):122
at

org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504):504
at

org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170):170
at

org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103):103
at

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116):116
at

org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421):421
at
org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190):190
at

org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611):611
at

org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314):314
at

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145):1145
at

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615):615
at

org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61):61
at
java.lang.Thread.run(Thread.java:745):745

    TagContext Array

–
Love Lucee? Become a supporter and be part of the Lucee project today! -
http://lucee.org/supporters/become-a-supporter.html

You received this message because you are subscribed to the Google Groups
“Lucee” group.
To unsubscribe from this group and stop receiving emails from it, send an
email to lucee+unsubscribe@googlegroups.com.
To post to this group, send email to lucee@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/lucee/a09ac603-c09d-4b41-aa9e-1f1f2fac5a26%40googlegroups.com
https://groups.google.com/d/msgid/lucee/a09ac603-c09d-4b41-aa9e-1f1f2fac5a26%40googlegroups.com?utm_medium=email&utm_source=footer
.
For more options, visit https://groups.google.com/d/optout.

–
Michael van Leest

[martin]

Hi Mike,

Thanks for the suggestion, however, I do not think that it is related to
this. We are running in Windows using IIS8 so I think that IIS takes care
of the file size restrictions?? I may be wrong there, but we have already
setup the server to accept file uploads of up to 50MB.

It looks like this is simply Lucee timing out when trying to decode the
large JSON string, but the timeout occurs at a point before we can control
the request in our code - although I am guessing that the 10 seconds is
taken from the default request timeout set in the Lucee admin.

I have done a quick test in Lucee to read the string in question, decode it
and write it back to disk, that shows each of these tasks takes around a
second for a 15MB file leaving me a bit confused by the timeout. Could it
be that it is taking more than 10 seconds to actually download/upload the
data from Mandrill to our server once the Lucee request has been started?

I am guessing that the only solution may be to increase the default request
timeout, but I really wanted to avoid that if possible. I will try it at 20
seconds.

I have just noticed that you can turn on the RequestTimout URL parameter…
I could maybe add that to the webhook URL, but I guess there is then a risk
of something abusing that somehow?

MartinOn Wednesday, November 11, 2015 at 3:51:25 PM UTC, Michael van Leest wrote:

Isn’t there also a setting in tomcat and in the lucee config for max
upload/form size? Not sure if that is related to your issue, but might be
worth looking at.

Mike

2015-11-11 15:30 GMT+01:00 <mar...@cubicstate.com <javascript:>>:

Hi,

I am experiencing a problem with inbound emails from Mandrill that
contain large attachments.

Mandrill is posting a large URLEncoded JSON string - the last one that
failed was around 15MB.

The error that I receive (see stack trace below) seems to suggest that
Lucee is timing out after 10 seconds during the decoding of this string -
before it even gets to run any of our code where we have set a request
timeout of two minutes.

I am guessing that this is where Lucee is parsing the ‘form’ struct?

Can anybody think of a way around this problem or how to improve
performance here??

Your hopefully,

Martin

request ((fail to retrieve
path:java.lang.NullPointerException:null):49) has run into a timeout (10
seconds) and has been stopped.
StackTrace
string
request ((fail to retrieve path:java.lang.NullPointerException:null):49)
has
run into a timeout (10 seconds) and has been stopped.
at
lucee.commons.net.URLDecoder.decode(URLDecoder.java:65):65
at

lucee.runtime.type.scope.ScopeSupport.fillDecoded(ScopeSupport.java:179):179
at

lucee.runtime.type.scope.FormImpl.initializeUrlEncodedOrTextPlain(FormImpl.java:261):261
at
lucee.runtime.type.scope.FormImpl.initialize(FormImpl.java:134):134
at
lucee.runtime.PageContextImpl.formScope(PageContextImpl.java:1172):1172
at

lucee.runtime.type.scope.UndefinedImpl.reinitialize(UndefinedImpl.java:595):595
at

lucee.runtime.type.scope.UndefinedImpl.initialize(UndefinedImpl.java:574):574
at
lucee.runtime.PageContextImpl.initialize(PageContextImpl.java:546):546
at

lucee.runtime.CFMLFactoryImpl.getPageContextImpl(CFMLFactoryImpl.java:161):161
at

lucee.runtime.CFMLFactoryImpl.getLuceePageContext(CFMLFactoryImpl.java:140):140
at

lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:435):435
at
lucee.loader.servlet.CFMLServlet.service(Unknown Source):-1
at
javax.servlet.http.HttpServlet.service(HttpServlet.java:727):727
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303):303
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52):52
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at
com.seefusion.Filter.doFilter(Filter.java:49):49
at
com.seefusion.SeeFusion.doFilter(SeeFusion.java:1500):1500
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241):241
at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208):208
at

org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220):220
at

org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122):122
at

org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504):504
at

org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170):170
at

org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103):103
at

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116):116
at

org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421):421
at
org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190):190
at

org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611):611
at

org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314):314
at

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145):1145
at

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615):615
at

org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61):61
at
java.lang.Thread.run(Thread.java:745):745

    TagContext Array

–
Love Lucee? Become a supporter and be part of the Lucee project today! -
http://lucee.org/supporters/become-a-supporter.html

You received this message because you are subscribed to the Google Groups
“Lucee” group.
To unsubscribe from this group and stop receiving emails from it, send an
email to lucee+un...@googlegroups.com <javascript:>.
To post to this group, send email to lu...@googlegroups.com <javascript:>
.
To view this discussion on the web visit
https://groups.google.com/d/msgid/lucee/a09ac603-c09d-4b41-aa9e-1f1f2fac5a26%40googlegroups.com
https://groups.google.com/d/msgid/lucee/a09ac603-c09d-4b41-aa9e-1f1f2fac5a26%40googlegroups.com?utm_medium=email&utm_source=footer
.
For more options, visit https://groups.google.com/d/optout.

–
Michael van Leest

[bennadel]

Did you ever get to the bottom of this? I am currently seeing requests in my application getting terminated at over 900 seconds, all at the same exact stack-trace that you are seeing:

lucee.commons.net.URLDecoder.decode(URLDecoder.java:65)
lucee.runtime.type.scope.ScopeSupport.fillDecoded(ScopeSupport.java:192)
lucee.runtime.type.scope.FormImpl.initializeUrlEncodedOrTextPlain(FormImpl.java:253)
lucee.runtime.type.scope.FormImpl.initialize(FormImpl.java:136)
lucee.runtime.PageContextImpl.formScope(PageContextImpl.java:1212)
lucee.runtime.type.scope.UndefinedImpl.reinitialize(UndefinedImpl.java:644)
lucee.runtime.type.scope.UndefinedImpl.initialize(UndefinedImpl.java:621)
lucee.runtime.PageContextImpl.initialize(PageContextImpl.java:498)
lucee.runtime.CFMLFactoryImpl.getPageContextImpl(CFMLFactoryImpl.java:171)
lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1060)
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1038)
lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:102)
lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
.....

I’m currently using Fusion Reactor to try and debug this, and unfortunately, its not even reporting a Content-Length.

[bdw429s]

@bennadel This is a topic that we imported from our Google Group so I’m not sure if it actually will notify any of the original people from the thread as I think it auto-created their accounts here.

Regarding the error, do you have any idea what’s in the form scope, what content type it is, or have a standalone page that can be submitted to reproduce the issue? I’m assuming there’s some massive amount of form data that’s taking a very long time to URL decode. Does the FusionReactor profiler show any other parts of Lucee that are spending a lot of time running?

[bennadel]

So, the Content Length of the Fusion Reactor profiler says NaN – I’m not sure if that means the header is corrupted – or, if it just hasn’t gotten processed yet. It’s crazy. We just installed FR today, so I am still getting situated.

I have to run – will report more tomorrow.

[bdw429s]

It’s possible that the content length isn’t available until it’s processed, but that said-- I was pretty sure most clients sent the content length in the incoming HTTP headers. You may be able to capture more from your browser debugging tools (assuming you can reproduce this on demand) or with a packet sniffer.

[martin]

@bennadel I have just looked back at some email conversations from 5 years ago. It does not look like this was ever resolved, but in our case the number of users sending large attachments was very low and failures of this nature were handled manually.

The app in question changed to use Mailgun in 2016 which has a different setup around these inbound email webhooks. As such, we have never seen this error again.

Not much help I am afraid!!

[bennadel]

It looks like this client is not sending the Content-Length header. We’re going to try and add that today (we own the Client software as well). Hopefully that will shed some light.

[bennadel]

I’m seeing something very curious in the Fusion Reactor stack-trace / Profiler. When spawning a new Thread (cfthread), it looks as if Lucee is duplicating the Form scope for the thread (see screenshot)

Am I crazy to think that it’s actually performing the URL decoding again for the sake of the spawned thread? If so, we’d be incurring the cost of a large HTTP post twice.

[Zackster]

hmmm, could be related to this bug which @bdw429s found with arrayEach [LDEV-2559] - Lucee

[bennadel]

Oh, very interesting, re: Brad’s ticket.

This morning, I did some experimentation, and I can demonstrate – I think – that as the size of the FORM post increases, the cost / time / overhead of spawning a CFThread increases dramatically. Even in a local CommandBox instance, posting a 1.5MB payload causes CFThread to take 30-seconds to spawn:

Lucee Appears To Incur Request-Cloning Overhead When Spawning CFThread

I am wondering if there is a way that I can clear the request param map prior to spawning the thread? I didn’t see anything like that in getPageContext() output.

[Zackster]

Great investigative work @bennadel, that 30s is a bit crazy, I’m sure @micstriit will be keen to investigate

I had noticed that threads seemed to have so much overhead they were barely useful when I was working on speeding up the Lucee docs processing…

[bennadel]

I’m digging through the Lucee source code to see if there is a way I can clear / reset the Form data before spawning the thread (in hopes that the clone operation doesn’t have to re-parse it). But, so far, no such luck. I do see that I can access the underlying servlet request; but, nothing in the way for .getFormScope().clear() seems to make a difference.

[bennadel]

It looks like cloning the page-contex ultimately calls this: Lucee/HTTPServletRequestWrap.java at dbb220d72027fea68f927654388456515289867a · lucee/Lucee · GitHub

return ScopeUtil.getParameterMap(new URLItem[][] { form.getRaw(), url.getRaw() }, new String[] { form.getEncoding(), url.getEncoding() });

… and I don’t see any way to reset the underlying .raw data in the FormImpl.

[joe.gooch]

You could probably cheat your way around it…

Dump the input out to a file, urldecoded or otherwise
Save the temp file’s path in a string
cfhttp call localhost/yourtemplatelocation and pass the temp file’s path

Let that template process the content in a cfthread, and use the filesystem to pull the payload… Then the clone is only cloning the form scope which only contains the filename, not the content.

Not ideal, but if it’s more efficient, so be it. You could maybe even solve it at the J2EE level with a servletfilter or jsp that does that work and manipulates the HTTPServletRequest before it is passed to Lucee.

[bennadel]

Oh, that’s a super interesting idea! In my case, its just a giant JSON payload. I wonder if I could get the client to attach it as a File instead of just a form field.

[bennadel]

OH CHICKENS! Sir, you may just be the best thing that happened to me this week

I just did a quick test locally where I posted the JSON payload as File rather than a Form Field, then I just do a fileRead( form.textFile ) and do my Thread spawning.

It runs instantly! Threads spawn instantly! This could really be a viable step!

[joe.gooch]

Neat, I helped Ben Nadel. Now I just need to get a pic with you sometime so I can make it into your slideshow

[bennadel]

Heck yeah! That would be great

Talking to my other devs to see how feasible it is to start experimenting with this file-based approach. I’m so excited, I feel nauseous