File upload puzzle

[a1730]

Jetty Version INFO :oejs.Server:main: jetty-12.0.10; built: 2024-05-30T04:40:36.563Z; git: https://github.com/jetty/jetty.project/commit/26106dfc84a03ddb6216062fe33b047fc332d0ce; jvm 22.0.1+8

Jetty Environment core,ee8

Java Version openjdk 22.0.1 2024-04-16 OpenJDK Runtime Environment Temurin-22.0.1+8 (build 22.0.1+8) OpenJDK 64-Bit Server VM Temurin-22.0.1+8 (build 22.0.1+8, mixed mode)

Question We have a very simple file upload service that worked very well with Jetty-10 but gets stuck with files larger than 12KB on Jetty-12 throwing a timeout exception.

Type: IOException
Message: java.util.concurrent.TimeoutException: Idle timeout 30000 ms elapsed

What could be blocking file upload? The attached servlet blocks on file upload when the file size is more than 12KB i.e. XLSX_150 works but XLSX_200 hangs. I must be missing a tunable knob.
Please help, I am at a loss where to look.

Thank you. The servlet: JettyHangingServlet.zip Jetty Configuration: jetty configuration Sample files: file_example_XLSX_150.xlsx file_example_XLSX_200.xlsx](https://github.com/user-attachments/files/15856079/file_example_XLSX_200.xlsx)

[sbordet]

I just tried your example, and everything works fine:

client-side:

simon@boron:/tmp/jetty-base$ curl -v -F "file=@/tmp/200.xlsx" http://localhost:8080/upload/aristax
* Host localhost:8080 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> POST /upload/aristax HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.5.0
> Accept: */*
> Content-Length: 14152
> Content-Type: multipart/form-data; boundary=------------------------TlcDU0O9TyZj5ggLOANmwr
> 
* We are completely uploaded and fine
< HTTP/1.1 302 Found
< Server: Jetty(12.0.11-SNAPSHOT)
< Location: http://localhost:8080/eb2b/upload/Edi894ToARISTAX.do
< Content-Length: 0
< 
* Connection #0 to host localhost left intact

server-side:

2024-06-16 18:40:44.702:INFO :ca.JettyHangingServlet:qtp1489069835-49: ContentType multipart/form-data; boundary=------------------------TlcDU0O9TyZj5ggLOANmwr
2024-06-16 18:40:44.702:INFO :ca.JettyHangingServlet:qtp1489069835-49: ContentLength 14152
2024-06-16 18:40:44.702:INFO :ca.JettyHangingServlet:qtp1489069835-49: Content-Transfer-Encoding null
2024-06-16 18:40:44.702:INFO :ca.JettyHangingServlet:qtp1489069835-49: Request: /upload/aristax /upload/aristax 7 aristax
2024-06-16 18:40:44.702:WARN :ca.JettyHangingServlet:qtp1489069835-49: ============================ partner is aristax
2024-06-16 18:40:44.703:WARN :ca.JettyHangingServlet:qtp1489069835-49: --------------------------- working on partner is aristax 1
2024-06-16 18:40:44.703:INFO :ca.JettyHangingServlet:qtp1489069835-49: Parts part is org.eclipse.jetty.ee8.nested.MultiPartFormInputStream$MultiPart :application/octet-stream
2024-06-16 18:40:44.703:INFO :ca.JettyHangingServlet:qtp1489069835-49: Submitted file is 200.xlsx
2024-06-16 18:40:44.703:INFO :ca.JettyHangingServlet:qtp1489069835-49: Part: aristax file 13940
2024-06-16 18:40:44.703:INFO :ca.JettyHangingServlet:qtp1489069835-49: I just need to see this.
2024-06-16 18:40:44.703:INFO :ca.JettyHangingServlet:qtp1489069835-49: Partner aristax EDI file upload [200.xlsx 13Kb], status: Ok.  

[sbordet]

WIth a larger file:

client-side:

simon@boron:/tmp/jetty-base$ curl -v -F "file=@/tmp/doc.pdf" http://localhost:8080/upload/aristax
* Host localhost:8080 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> POST /upload/aristax HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.5.0
> Accept: */*
> Content-Length: 647039
> Content-Type: multipart/form-data; boundary=------------------------pTsUBmC27EgytYosTk9mrd
> 
* We are completely uploaded and fine
< HTTP/1.1 302 Found
< Server: Jetty(12.0.11-SNAPSHOT)
< Location: http://localhost:8080/eb2b/upload/Edi894ToARISTAX.do
< Content-Length: 0
< 
* Connection #0 to host localhost left intact

server-side:

2024-06-16 18:41:47.891:INFO :ca.JettyHangingServlet:qtp1489069835-49: ContentType multipart/form-data; boundary=------------------------pTsUBmC27EgytYosTk9mrd
2024-06-16 18:41:47.891:INFO :ca.JettyHangingServlet:qtp1489069835-49: ContentLength 647039
2024-06-16 18:41:47.891:INFO :ca.JettyHangingServlet:qtp1489069835-49: Content-Transfer-Encoding null
2024-06-16 18:41:47.891:INFO :ca.JettyHangingServlet:qtp1489069835-49: Request: /upload/aristax /upload/aristax 7 aristax
2024-06-16 18:41:47.891:WARN :ca.JettyHangingServlet:qtp1489069835-49: ============================ partner is aristax
2024-06-16 18:41:47.901:WARN :ca.JettyHangingServlet:qtp1489069835-49: --------------------------- working on partner is aristax 1
2024-06-16 18:41:47.901:INFO :ca.JettyHangingServlet:qtp1489069835-49: Parts part is org.eclipse.jetty.ee8.nested.MultiPartFormInputStream$MultiPart :application/pdf
2024-06-16 18:41:47.901:INFO :ca.JettyHangingServlet:qtp1489069835-49: Submitted file is doc.pdf
2024-06-16 18:41:47.901:INFO :ca.JettyHangingServlet:qtp1489069835-49: Part: aristax file 646837
2024-06-16 18:41:47.901:INFO :ca.JettyHangingServlet:qtp1489069835-49: I just need to see this.
2024-06-16 18:41:47.901:INFO :ca.JettyHangingServlet:qtp1489069835-49: Partner aristax EDI file upload [doc.pdf 631Kb], status: Ok.  

[a1730]

Thank you for looking at this issue @sbordet . I was going to add that we are probably doing something wrong hence the ask for a tunable ... However, we have been using the servlet for years successfully on Jetty-10. We only experience the issue with our Jetty-12 (ee8) install.

How do you recommend we start tracing this beast? Any pointers will be appreciated. Thanks again.

FWIW, Jetty is behind HAProxy in our deployments.

[sbordet]

Enable org.eclipse.jetty.LEVEL=DEBUG in JETTY_HOME/resources/jetty-logging.properties, then make a request with curl like I did above, and post here the logs.

[a1730]

Thanks @sbordet . I used curl and it worked (this was on the jetty server) - Linux, it hangs when I went through the browser ( m$windows.) So I decided to send the log file for that session. My apologies if you were looking for something specific. Deleted big dump. Thank you so much.

[a1730]

Hi @sbordet, I took some time to go through the log files and the only difference that I can see between the failed upload and a successful one is AsyncContentProducer@2e02eaba not ready. This is not the case with a successful upload. line 687 ... 751

oejen.BlockingContentProducer:qtp1630678941-31: nextContent async producer is not ready, waiting on semaphore LockedSemaphore permits=0
...
oejen.BlockingContentProducer:qtp1630678941-54: onContentProducible releasing semaphore LockedSemaphore permits=0 unready=true

line 1907

oejen.BlockingContentProducer:qtp1630678941-24: onContentProducible releasing semaphore LockedSemaphore permits=0 unready=false

Do you have any recommendations where to look or what to look for comparing line 687 of the attached file to line 1907?

loglog.zip Thank you very much.

[a1730]

This may help someone someday.

We found out after lots of digging that it was not a Jetty issue naturally 😉

This issue is probably due to different interpretation of HTTP spec. by different proxies. Please see HAProxy doesn't emit :authority when converting h1 --> h2. The comment from Willey was most illuminating to us that this is an HTTP WG issue to clarify. Looking for workaround, there is no way to tell HAProxy to be rfc7540 compliant, and Jetty server does not seem to have a compliance flag for rfc9113.

The workaround referenced by @capflam or anything on Google search that recommends forcing the http-request uri will eventually lead to issues. i.e.

   http-request set-uri https://%[req.hdr(host)]%[pathq]
   http-request set-uri http://%[baseq]

Trust us; we tested a whole bunch of them with different forwarded/forward-for headers... Just don't go there.

Following the wisdom of the NGINX crew on HTTP/2 to backend, we disabled HTTP/2 from HAProxy to the backend on the final hop and Life is good again. Thank you for your time.

@sbordet, Thank you! Thank you all for your support.