Problems getting browser and curl to connect to HTTP/3 server

[cowwoc]

Jetty Version
12.0.7-SNAPSHOT using this PR: #11368

Jetty Environment
core

Java Version
openjdk version "21.0.1" 2023-10-17 LTS
OpenJDK Runtime Environment Zulu21.30+15-CA (build 21.0.1+12-LTS)
OpenJDK 64-Bit Server VM Zulu21.30+15-CA (build 21.0.1+12-LTS, mixed mode, sharing)

Question
My server is accepting HTTP/1, HTTPS/1, HTTP/2, and HTTP/3 connections. I am able to connect Jetty's HttpClient to the server's HTTP/3 endpoint just fine, but Chrome and Curl don't work (for different reasons).

1. Chrome hits the HTTPS/2 endpoint, gets a response containing Alt-Svc: h3=":8443"; ma=60 but no matter what I do, it never tries hitting the HTTP/3 endpoint... even in subsequent page reloads. Wireshark confirms there is no activity on the UDP port.

If I configure Cloudflare to act as a HTTP/3 -> HTTP/2 tunnel then Chrome happily hits Cloudflare's HTTP/3 endpoint. I don't know what "trick" I'm missing to convince the browser to try hitting the HTTP/3 endpoint.

2. If I run curl --http3 --verbose https://licensed.app:8443/ I get:

* Host licensed.app:8443 was resolved.
* IPv6: 2607:f2c0:948a:ba00:29cb:e324:bf4d:ca98
* IPv4: 69.165.149.235
*   Trying 69.165.149.235:8443...
* QUIC cipher selection: TLS_AES_128_GCM_SHA256:TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_CCM_SHA256
*  CAfile: C:\util\curl\curl-ca-bundle.crt
*  CApath: none
*   Trying [2607:f2c0:948a:ba00:29cb:e324:bf4d:ca98]:8443...
* QUIC cipher selection: TLS_AES_128_GCM_SHA256:TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_CCM_SHA256
*   Trying 69.165.149.235:8443...
*  subjectAltName: host "licensed.app" matched cert's "licensed.app"
* Verified certificate just fine
* Connected to licensed.app (69.165.149.235) port 8443
* using HTTP/3
* [HTTP/3] [0] OPENED stream for https://licensed.app:8443/
* [HTTP/3] [0] [:method: GET]
* [HTTP/3] [0] [:scheme: https]
* [HTTP/3] [0] [:authority: licensed.app:8443]
* [HTTP/3] [0] [:path: /]
* [HTTP/3] [0] [user-agent: curl/8.6.0]
* [HTTP/3] [0] [accept: */*]
> GET / HTTP/3
> Host: licensed.app:8443
> User-Agent: curl/8.6.0
> Accept: */*
>
< HTTP/3 200
< server: Jetty(12.0.7-SNAPSHOT)
< date: Sat, 17 Feb 2024 20:56:59 GMT
< vary: Accept-Encoding
< alt-svc: h3=":8443"; ma=60
< vary: Accept
< cache-control: max-age=300
* HTTP/3 stream 0 reset by server
* Connection #0 to host licensed.app left intact
curl: (95) HTTP/3 stream 0 reset by server

From the server's perspective, I see my code running Sink.write(response, true, StandardCharsets.UTF_8.encode(body)); and when this method completes curl gets disconnected unexpectly. Here are the DEBUG logs from the server and the corresponding Wireshark capture:

server-logs-for-curl.txt
curl-wireshark.zip

So to recap, I've got two separate problems: one with Chrome and another with curl. Let me know if you have any ideas for what I can try next.

[sbordet]

Please try Firefox.

Chrome has always been extremely difficult to get going, and so far we have not yet understood why.

[cowwoc]

@sbordet Will do. Regarding curl, I think even the Jetty client's connection is getting terminated prematurely. It throws:

18:50:15.144 [Thread-1] DEBUG o.e.jetty.io.AbstractConnection.onFillInterestedFailed() - ClientQuicConnection@4c9cdfcd::DatagramChannelEndPoint@484976cb[{l=null,r=null,CLOSED,fill=-,flush=-,to=2/300000}{io=1/1,kio=-1,kro=-1}]->[ClientQuicConnection@4c9cdfcd] onFillInterestedFailed {}
java.nio.channels.ClosedChannelException: null
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.FillInterest.onClose(FillInterest.java:147)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:336)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.SelectableChannelEndPoint.onClose(SelectableChannelEndPoint.java:165)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:326)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:253)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:217)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:200)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.IO.close(IO.java:444)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.IO.close(IO.java:459)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.ManagedSelector$StopSelector.update(ManagedSelector.java:1056)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processUpdates(ManagedSelector.java:575)
	at org.eclipse.jetty.io@12.0.7-SNAPSHOT/org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:542)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:512)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:258)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:971)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1201)
	at org.eclipse.jetty.util@12.0.7-SNAPSHOT/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1156)
	at app.licensed.client/app.licensed.client.scope.AbstractClientScope.lambda$new$2(AbstractClientScope.java:87)
	at app.licensed.common/app.licensed.common.util.DelegatingThreadFactory.lambda$newThread$0(DelegatingThreadFactory.java:35)
	at java.base/java.lang.Thread.run(Thread.java:1583)

This is a DEBUG log, not a WARN, so it's possible no one else has noticed this before.

[cowwoc]

@sbordet I just tried Firefox. Same issue. It is hitting the server with HTTP/2 instead of HTTP/3. I must be doing something wrong

The server is up in case you want to take a look. Let me know if you spot any obvious problems.

[cowwoc]

I'm going to dig some more into this tomorrow, but I wanted to mention that if you haven't run across chrome://net-export/ (https://www.chromium.org/for-testers/providing-network-details/) I suggest you take a look. It provides a lot more information about why the browser is not trying to request HTTP/3. For example, they use exponential backoff to avoid hitting "broken" HTTP/3 endpoints too often: https://chromium.googlesource.com/chromium/src/+/HEAD/net/http/broken_alternative_services.h#60

I'm going to try flushing that cache somehow tomorrow and seeing what the new net-export says...

Also, I've temporarily moved my HTTP/3 endpoint from port 8443 to 443 (in case you're interested in hitting it)...

[cowwoc]

Okay... I figured out what was happening. There are four (!!) separate issues going on.

1. Chrome caches HTTP/3 failures and doesn't retry for a long time.
2. Chrome refuses port numbers greater than 1024.
3. Even if everything is successful, Chrome won't use an HTTP/3 connection until the third page load.
4. If the response contains a Referrer-Policy header then Chrome, Firefox and CURL all refuse to establish an HTTP/3 connection.

Background for issue 1

1. As previously mentioned, every time Chrome runs into a problem with an HTTP/3 endpoint, avoids hitting it for a period of time. This period of time gets exponentially longer, every time a failure occurs: https://chromium.googlesource.com/chromium/src/+/HEAD/net/http/broken_alternative_services.h#60

Background for issue 2

https://stackoverflow.com/a/72793129/14731

Background for issue 3

The only way I found to clear the ALT-SVC cache in Chrome was to use Incognito mode. So here is what I did:

1. Open a new Incognito tab.
2. Open chrome://net-export/ and start recording.
3. Open another tab in the same Incognito session and hit https://licensed.app/
4. The first time the page is loaded using HTTP/2 and notes the Alt-Svc header.
5. The second time the page is loaded using HTTP/2 but shortly after that request it also hits the page using HTTP/3. The network tab in Developer Console only reports the HTTP/2 request, but the net-export shows both requests.
6. All subsequent requests are sent to HTTP/3.

My interpretation is that the first request uses HTTP/2 because it doesn't know if the server uses HTTP/3. The second request doesn't necessarily trust the Alt-Svc header, so it requests the page in HTTP/2 but silently double-checks if HTTP/3 works under the hood. Once the browser establishes that HTTP/3 really is available, all subsequent calls use HTTP/3.

Firefox also required the use of Incognito mode to clear the Alt-Svc cache. Once I did that, I saw that the first request uses HTTP/2 and all subsequent requests use HTTP/3.

curl --http3 --verbose https://licensed.app/ works on the first attempt.

All of this is 100% reproducible, so long as the server does not return a Referrer-Policy header.

Background for issue 4

My website contains a "Sign in with Google" button. Reading their instructions at https://developers.google.com/identity/gsi/web/guides/get-google-api-clientid they write:

When testing using http and localhost set the Referrer-Policy header in your web app to Referrer-Policy: no-referrer-when-downgrade.

But it turns out that if I include this header (even if I set to the default value), it causes the following problem (per chrome://net-export/):

t=65893888 [st= 4]       +HTTP_TRANSACTION_READ_HEADERS  [dt=35]
t=65893923 [st=39]          HTTP_TRANSACTION_RESTART_AFTER_ERROR
                            --> net_error = -356 (ERR_QUIC_PROTOCOL_ERROR)
t=65893923 [st=39]       -HTTP_TRANSACTION_READ_HEADERS

See http3.log for the full log.

I can't figure out why this header would cause a problem but it seems to be reproducible on Chrome, Firefox and CURL... so something is going on. Any ideas?

[cowwoc]

I filed this bug report against Chrome: https://issues.chromium.org/issues/325808006

though I doubt I will get a response anytime soon. Hopefully someone else has an idea, especially since CURL also doesn't like this header for some reason.

[cowwoc]

I worked with the author of curl, and based on the logs I think it is highly probable that all of the above bugs are actually caused by Jetty. Remember that Chrome flagged the HTTP/3 connection as "broken" due to something being wrong with the response headers? This explains it.

I ran curl -s --http3 --trace-config "http/3" -vvv https://licensed.app/ in two cases. One with the Referrer-Policy header and one without it. When the header was present, Jetty was failing to send a Content-Length response header. That seems to be the thing that trips up CURL.

Going through the logs on both ends, it looks like Jetty is terminating the connection too soon. It writes a frame containing the response headers but the connection is reset (from curl's point of view) before it gets a chance to read the frame.

Here is a quick example.

This is Jetty's point of view of what's happening:

19:41:51.285 [main-3] DEBUG o.e.j.h.s.i.HttpStreamOverHTTP3.sendHeaders() - HTTP3 Response #0/38f7ed28:
HTTP/3.0 200
Server: Jetty(12.0.7-SNAPSHOT)
Date: Tue, 20 Feb 2024 00:41:51 GMT
Vary: Accept-Encoding
Alt-Svc: h3=":443"; ma=300
Vary: Accept
Cache-Control: max-age=300
Referrer-Policy: strict-origin-when-cross-origin
Content-Length: 1137
Last-Modified: 2024-02-19T20:42:32.325441Z
Content-Type: text/html;charset=utf-8


19:41:51.286 [main-3] DEBUG org.eclipse.jetty.http3.HTTP3Stream.write() - writing HeadersFrame@54237953[last=false,{HTTP/3.0{s=200,h=10,cl=1137}}] on HTTP3StreamServer@53b2cd4b#0[demand=false,stalled=false,last=true,idle=-29996,session=HTTP3SessionServer@38f7ed28[streams=1,NOT_CLOSED]]
19:41:51.286 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.process() - flushing HeadersFrame@54237953[last=false,{HTTP/3.0{s=200,h=10,cl=1137}}]#0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.286 [main-3] DEBUG o.e.jetty.http3.qpack.QpackEncoder.encode() - Encoding: streamId=0, metadata=HTTP/3.0{s=200,h=10,cl=1137}
19:41:51.286 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.process() - writing 1 buffers (183 bytes) for stream #0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.287 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.succeeded() - succeeded to write HeadersFrame@54237953[last=false,{HTTP/3.0{s=200,h=10,cl=1137}}]#0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.287 [main-3] DEBUG org.eclipse.jetty.http3.HTTP3Stream.write() - writing DataFrame@4050a56a[last=true,length=1137] on HTTP3StreamServer@53b2cd4b#0[demand=false,stalled=false,last=true,idle=-29998,session=HTTP3SessionServer@38f7ed28[streams=1,NOT_CLOSED]]
19:41:51.287 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.process() - flushing DataFrame@4050a56a[last=true,length=1137]#0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.287 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.process() - writing 2 buffers (1140 bytes) for stream #0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.288 [main-3] DEBUG o.eclipse.jetty.http3.MessageFlusher.succeeded() - succeeded to write DataFrame@4050a56a[last=true,length=1137]#0 on MessageFlusher@22323c26[PROCESSING]
19:41:51.289 [main-3] DEBUG o.eclipse.jetty.http3.HTTP3Session.removeStream() - destroyed HTTP3StreamServer@53b2cd4b#0[demand=false,stalled=false,last=true,idle=-29998,session=HTTP3SessionServer@38f7ed28[streams=1,NOT_CLOSED]]
19:41:51.373 [main-21] DEBUG o.e.j.h.s.i.ServerHTTP3Session.onClose() - session closed remotely 0x0/ ServerHTTP3Session@44a960f2[ServerQuicSession@73f193a6[id=7d8a30acebc277761b4c23d44fab0e440ae15d52]]
19:41:51.373 [main-21] DEBUG o.eclipse.jetty.http3.HTTP3Session.onClose() - session closed remotely 0x0/ HTTP3SessionServer@38f7ed28[streams=0,NOT_CLOSED]

and this is curl's point of view:

* [HTTP/3] data idle
* [HTTP/3] ingress, recvfrom -> EAGAIN
* [HTTP/3] recvd 5 packets with 239 bytes -> 0
* [HTTP/3] vquic_send_tail_split: [1444 gso=1444][44 gso=44]
* [HTTP/3] vquic_send(len=1444, gso=1444) -> 0, sent=1444
* [HTTP/3] vquic_send(len=44, gso=44) -> 0, sent=44
* [HTTP/3] [0] cf_recv(len=102400) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] [0] status: HTTP/3 200

* [HTTP/3] [0] header: server: Jetty(12.0.7-SNAPSHOT)
* [HTTP/3] [0] header: date: Tue, 20 Feb 2024 00:41:51 GMT
* [HTTP/3] [0] header: vary: Accept-Encoding
* [HTTP/3] [0] header: alt-svc: h3=":443"; ma=300
* [HTTP/3] [0] header: vary: Accept
* [HTTP/3] [0] header: cache-control: max-age=300
* [HTTP/3] [0] reset -> 0
* [HTTP/3] [0] read_stream(len=183) -> 183
* [HTTP/3] [0] RESET: error 270
* [HTTP/3] [0] quic close(err=270) -> 0
* [HTTP/3] ingress, recvfrom -> EAGAIN
* [HTTP/3] recvd 3 packets with 1454 bytes -> 0
* [HTTP/3] vquic_send(len=44, gso=44) -> 0, sent=44
* [HTTP/3] [0] cf_recv(len=102400) -> 175, 0
< HTTP/3 200
< server: Jetty(12.0.7-SNAPSHOT)
< date: Tue, 20 Feb 2024 00:41:51 GMT
< vary: Accept-Encoding
< alt-svc: h3=":443"; ma=300
< vary: Accept
< cache-control: max-age=300
* [HTTP/3] ingress, recvfrom -> EAGAIN
* HTTP/3 stream 0 reset by server
* [HTTP/3] [0] cf_recv(len=102400) -> -1, 95
* [HTTP/3] [0] easy handle is done
* Connection #0 to host licensed.app left intact

The interesting bit is that both sides see that 183 bytes are being sent but from curl's point of view, the connection is terminated before it finishes reading it fully. And you know what else is interesting? :) If you compare what was supposed to get sent vs what was received, you'll notice that the connection is terminated immediately before that magical header we talked about: Referrer-Policy: strict-origin-when-cross-origin.

Here are log files with full DEBUG logs on (the above snippet only shows HTTP/3 related events):

curl-full-debug.log
full-jetty-debug.log

So to recap: Jetty fails to flush messages fully before terminating the connection.

How do we debug this further?

[cowwoc]

I've spent a couple more hours today trying to debug this but I've hit a brick wall. It's extremely easy to reproduce the problem using curl -s --http3 --trace-config "http/3" -vvv https://licensed.app/. I just can't figure out which part of Jetty's code is killing the connection.