Unconsumed content for http/3

[sunng87]

Jetty version(s) 10.0.8 and current HEAD version on default branch

curl version

curl 7.81.0 (x86_64-pc-linux-gnu) libcurl/7.81.0 BoringSSL zlib/1.2.11 brotli/1.0.9 zstd/1.5.2 libidn2/2.3.2 libpsl/0.21.1 (+libidn2/2.3.0) nghttp2/1.46.0 quiche/0.11.0
Release-Date: 2022-01-05
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL UnixSockets zstd

Java version/vendor (use: java -version) 11

OS type/version Linux

Description Not sure if this is an issue with jetty or curl. Using curl --http3 always end up with body unread from jetty http3 server.

The curl output for requesting a demo server, written with jetty-http3 and should prints It works as body:

curl3 --http3 -vv -k https://localhost:5443/
*   Trying 127.0.0.1:5443...
* Connect socket 5 over QUIC to 127.0.0.1:5443
* Sent QUIC client Initial, ALPN: h3,h3-29,h3-28,h3-27
*   Trying ::1:5443...
* Connect socket 6 over QUIC to ::1:5443
* Sent QUIC client Initial, ALPN: h3,h3-29,h3-28,h3-27
* Connected to localhost () port 5443 (#0)
* h3 [:method: GET]
* h3 [:path: /]
* h3 [:scheme: https]
* h3 [:authority: localhost:5443]
* h3 [user-agent: curl/7.81.0]
* h3 [accept: */*]
* Using HTTP/3 Stream ID: 0 (easy handle 0x55fbaf5fed20)
> GET / HTTP/3
> Host: localhost:5443
> user-agent: curl/7.81.0
> accept: */*
>
< HTTP/3 200
< server: Jetty(10.0.9-SNAPSHOT)
< content-length: 8
* transfer closed with 8 bytes remaining to read
* Connection #0 to host localhost left intact
curl: (18) transfer closed with 8 bytes remaining to read

Jetty also reports unconsumed content on server side

[qtp671536858-36] DEBUG org.eclipse.jetty.server.AsyncContentProducer - consumeAll AsyncContentProducer@be36e43[r=null,t=null,i=null,error=false,c=HttpChannelOverHTTP3@5db6d495{s=HttpChannelState@441cba59{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=https://localhost:5443/,age=112}]
java.io.IOException: Unconsumed content
        at org.eclipse.jetty.server.AsyncContentProducer.consumeAll(AsyncContentProducer.java:193)
        at org.eclipse.jetty.server.BlockingContentProducer.consumeAll(BlockingContentProducer.java:93)
        at org.eclipse.jetty.server.HttpInput.consumeAll(HttpInput.java:159)
        at org.eclipse.jetty.http3.server.internal.HttpChannelOverHTTP3.consumeInput(HttpChannelOverHTTP3.java:75)
        at org.eclipse.jetty.http3.server.internal.HttpTransportOverHTTP3.onCompleted(HttpTransportOverHTTP3.java:276)
        at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:968)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:485)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:457)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:894)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1038)
        at java.base/java.lang.Thread.run(Thread.java:829)

I also tested with the client shipped from quiche code base, using: cargo run --bin quiche-client -- --no-verify https://127.0.0.1:5443/ It prints the response body with no error or warning. However, there is still unconsumed content exception on server log.

I'm not quite familiar with the http/3 or quic protocol but will try to figure out more information from the debug. Just report the status here to see if it's a known issue.

How to reproduce?

curl3 --http3 -vv -k https://localhost:5443/

[gregw]

The basic issue here is that jetty will does not like servlets/applications that do not read the whole content of a request. Jetty will make an attempt to read any unconsumed content, but if that reading stalls, then we reset the connection. So firstly, perhaps this behaviour is not necessary in h3, where the content is easier to ignore without blocking.

However, the strange thing is, that from the info you have given, I can't see a request that has content? The content-length of 8 is on the response?

Something strange is going on??? @lorban ideas?

[lorban]

The IOException: Unconsumed content is a red herring: this exception is only printed at DEBUG log level and only to indicate the original cause of the consumeAll call; it's not indicating an error of any kind.

The real problems seems to be that for whatever reason, curl could not or did not read the 8 bytes of the response as I understand from that line:

curl: (18) transfer closed with 8 bytes remaining to read

Since the quiche client seems to be working fine for you, my first guess would be some sort of incompatibility between curl's and Jetty's HTTP3 (or maybe QUIC?) implementations.

If this is easily reproducible, I would advise you to collect Jetty's debug logs while serving a request from curl. Hopefully this will help us figure out why curl can't print the response.

[sunng87]

Gzipped log when requested from curl http3.log.gz

Gzipped log when requested from quiche client http3-quiche.log.gz

[lorban]

Do you know which implementation of HTTP3 and QUIC your build of curl is using? According to this doc curl seems to support ngtcp2 and quiche, and it would be useful to know which one you're using.

[sunng87]

@lorban according to the curl --version output, it should be based on quiche 0.11.0, the same backend for jetty.

curl 7.81.0 (x86_64-pc-linux-gnu) libcurl/7.81.0 BoringSSL zlib/1.2.11 brotli/1.0.9 zstd/1.5.2 libidn2/2.3.2 libpsl/0.21.1 (+libidn2/2.3.0) nghttp2/1.46.0 quiche/0.11.0
Release-Date: 2022-01-05

[lorban]

This seems to be caused by a bug in curl. AFAICT curl seems to get confused by the fact that Jetty writes the HTTP response in two QUIC packets.

After I hacked the QuicStreamEndPoint.flush() method to copy all the buffers into a single one (see this) such as to call session.flush() only once then curl is happy with Jetty's response.

I would advise you to take this problem to the curl devs.

[github-actions[bot]]

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

[sunng87]

I think this issue can be closed from jetty side.