Open cowwoc opened 8 months ago
Please try Firefox.
Chrome has always been extremely difficult to get going, and so far we have not yet understood why.
@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.
@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.
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)...
Okay... I figured out what was happening. There are four (!!) separate issues going on.
Referrer-Policy
header then Chrome, Firefox and CURL all refuse to establish an HTTP/3 connection.https://stackoverflow.com/a/72793129/14731
The only way I found to clear the ALT-SVC cache in Chrome was to use Incognito mode. So here is what I did:
Alt-Svc
header.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.
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?
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.
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?
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.
Jetty Version 12.0.7-SNAPSHOT using this PR: https://github.com/jetty/jetty.project/pull/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).
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.
curl --http3 --verbose https://licensed.app:8443/
I get: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.