Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Requests aborted over HTTP/3 #6678

Open
inetol opened this issue Nov 5, 2024 · 28 comments
Open

Requests aborted over HTTP/3 #6678

inetol opened this issue Nov 5, 2024 · 28 comments

Comments

@inetol
Copy link

inetol commented Nov 5, 2024 •
edited
Loading

See #6678 (comment)
@francislavoie
Copy link
Member

Thanks for opening an issue! We'll look into this.

It's not immediately clear to us what is going on, so we'll need your help to understand it better.

Ideally, we need to be able to reproduce the bug in the most minimal way possible. This allows us to write regression tests to verify the fix is working. If we can't reproduce it, then you'll have to test our changes for us until it's fixed -- and then we can't add test cases, either.

I've attached a template below that will help make this easier and faster! It will ask for some information you've already provided; that's OK, just fill it out the best you can. 👍

I've also included some helpful tips below the template. Feel free to let me know if you have any questions!

Thank you again for your report, we look forward to resolving it!

Template

## 1. Environment

### 1a. Operating system and version

```
paste here
```


### 1b. Caddy version (run `caddy version` or paste commit SHA)

```
paste here
```


### 1c. Go version (if building Caddy from source; run `go version`)

```
paste here
```


## 2. Description

### 2a. What happens (briefly explain what is wrong)




### 2b. Why it's a bug (if it's not obvious)




### 2c. Log output

```
paste terminal output or logs here
```



### 2d. Workaround(s)




### 2e. Relevant links




## 3. Tutorial (minimal steps to reproduce the bug)

Helpful tips

  1. Environment: Please fill out your OS and Caddy versions, even if you don't think they are relevant. (They are always relevant.) If you built Caddy from source, provide the commit SHA and specify your exact Go version.

  2. Description: Describe at a high level what the bug is. What happens? Why is it a bug? Not all bugs are obvious, so convince readers that it's actually a bug.

    • 2c) Log output: Paste terminal output and/or complete logs in a code block. DO NOT REDACT INFORMATION except for credentials.
    • 2d) Workaround: What are you doing to work around the problem in the meantime? This can help others who encounter the same problem, until we implement a fix.
    • 2e) Relevant links: Please link to any related issues, pull requests, docs, and/or discussion. This can add crucial context to your report.

  3. Tutorial: What are the minimum required specific steps someone needs to take in order to experience the same bug? Your goal here is to make sure that anyone else can have the same experience with the bug as you do. You are writing a tutorial, so make sure to carry it out yourself before posting it. Please:

    • Start with an empty config. Add only the lines/parameters that are absolutely required to reproduce the bug.
    • Do not run Caddy inside containers.
    • Run Caddy manually in your terminal; do not use systemd or other init systems.
    • If making HTTP requests, avoid web browsers. Use a simpler HTTP client instead, like curl.
    • Do not redact any information from your config (except credentials). Domain names are public knowledge and often necessary for quick resolution of an issue!
    • Note that ignoring this advice may result in delays, or even in your issue being closed. 😞 Only actionable issues are kept open, and if there is not enough information or clarity to reproduce the bug, then the report is not actionable.

Example of a tutorial:

Create a config file: 
{ ... }

Open terminal and run Caddy:

$ caddy ...

Make an HTTP request:

$ curl ...

Notice that the result is ___ but it should be ___.

@inetol
Copy link
Author

inetol commented Nov 6, 2024 •
edited
Loading

1. Environment

1a. Operating system and version

Linux 5.14.0-503.11.1.el9_5.x86_64

1b. Caddy version (run caddy version or paste commit SHA)

238f1108e6600049d9041abc88db24526ee4f882

1c. Go version (if building Caddy from source; run go version)

go1.23.3 linux/amd64

2. Description

2a. What happens (briefly explain what is wrong)

Since commit 5b44d6c (more specifically quic-go/quic-go@7c3544c); In a reverse proxy configuration, if the client accesses via HTTP/3 the connection may abort abruptly, causing the backend to never receive that request.

2b. Why it's a bug (if it's not obvious)

HTTP implementations (HTTP/1.1 and HTTP/2.0) of the Go stdlib do not have this issue.

2c. Log output

In most cases, this msg will be what is returned to the logger when this issue is reproduced:

WARN    http.handlers.reverse_proxy     aborting with incomplete response       {"upstream": "paste.inetol.net:443", "duration": 0.044265522, "request": {"remote_ip": "127.0.0.1", "remote_port": "41100", "client_ip": "127.0.0.1", "proto": "HTTP/3.0", "method": "GET", "host": "paste.inetol.net:443", "uri": "/assets/chunks/chunk-BXqmZvty.js", "headers": {"Sec-Fetch-Mode": ["cors"], "Pragma": ["no-cache"], "Cache-Control": ["no-cache"], "Accept-Language": ["en-US,en;q=0.5"], "Sec-Fetch-Site": ["same-origin"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Accept": ["*/*"], "Priority": ["u=1"], "X-Forwarded-Host": ["remotepaste.localhost"], "Referer": ["https://remotepaste.localhost/"], "X-Forwarded-For": ["127.0.0.1"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0"], "Alt-Used": ["remotepaste.localhost"], "Sec-Fetch-Dest": ["script"], "X-Forwarded-Proto": ["https"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h3", "server_name": "remotepaste.localhost"}}, "error": "reading: context canceled"}

In worst case scenario, Caddy will not retry the connection with the backend by returning a 502 error to the client and one of the following msgs will be recorded to the logger:

ERROR    http.log.error  EOF     {"request": {"remote_ip": "127.0.0.1", "remote_port": "32875", "client_ip": "127.0.0.1", "proto": "HTTP/3.0", "method": "GET", "host": "ran.localhost", "uri": "/static/model7.svg", "headers": {"Accept": ["image/avif,image/webp,image/png,image/svg+xml,image/*;q=0.8,*/*;q=0.5"], "Sec-Fetch-Site": ["same-origin"], "Sec-Fetch-Dest": ["image"], "Sec-Fetch-Mode": ["no-cors"], "Pragma": ["no-cache"], "Accept-Language": ["en-US,en;q=0.5"], "Alt-Used": ["ran.localhost"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0"], "Cache-Control": ["no-cache"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Priority": ["u=6"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h3", "server_name": "ran.localhost"}}, "duration": 0.000125333, "status": 502, "err_id": "5r96gsdr1", "err_trace": "reverseproxy.statusError (reverseproxy.go:1353)"}
ERROR    http.log.error  http: server closed idle connection     {"request": {"remote_ip": "127.0.0.1", "remote_port": "45723", "client_ip": "127.0.0.1", "proto": "HTTP/3.0", "method": "GET", "host": "ran.localhost", "uri": "/static/u/2/main-V8RD-zA2.js", "headers": {"Sec-Fetch-Site": ["same-origin"], "Pragma": ["no-cache"], "Sec-Fetch-Dest": ["script"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Cache-Control": ["no-cache"], "Priority": ["u=2"], "Accept-Language": ["en-US,en;q=0.5"], "Alt-Used": ["ran.localhost"], "Accept": ["*/*"], "Sec-Fetch-Mode": ["no-cors"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h3", "server_name": "ran.localhost"}}, "duration": 0.000206845, "status": 502, "err_id": "49j8kuvb4", "err_trace": "reverseproxy.statusError (reverseproxy.go:1353)"}

2d. Workaround(s)

Disabling "h3" using protocols global directive.

3. Tutorial (minimal steps to reproduce the bug)

You can easily reproduce this issue by creating a reverse proxy of a specific site under my domain where this error is replicable..:

  1. Use Caddy v2.9.0-beta.3.

  2. Create the Caddyfile and start the server:

# Caddyfile

{
	local_certs
	skip_install_trust
}

remote.localhost

reverse_proxy https://paste.inetol.net {
	header_up Host {upstream_hostport}
}

  1. Open Firefox now so that it tries to establish the connection with HTTP/3 (each restart of Caddy may require as well a restart of Firefox, as it will then prefer to use HTTP/2 (?))

  2. With the DevTools Network Inspector open (F12 > Network) and the "Disable Cache" checkbox selected; Access https://remote.localhost and refresh between full page loads until you see WARN or ERROR logs being thrown out from Caddy.

The same applies for Chromium-based browsers if you get it to connect via HTTP/3.

@inetol

This comment has been minimized.

Sign in to view
@francislavoie
Copy link
Member

FYI @marten-seemann

@marten-seemann
Copy link
Contributor

@inetol Could you record a qlog of the transfer and post it here? As of #6581, this is possible to setting the QLOGDIR env.

@inetol
Copy link
Author

inetol commented Nov 7, 2024

Freshly started Caddy and Firefox, the log has been captured by accessing the site for the first time showing the issue.

Log: 
�{"qlog_format":"JSON-SEQ","qlog_version":"0.3","title":"quic-go qlog","configuration":{"code_version":"v0.48.1"},"trace":{"vantage_point":{"type":"server"},"common_fields":{"ODCID":"018a44fc2526d77aba042d46e2ff56","group_id":"018a44fc2526d77aba042d46e2ff56","reference_time":1730979028594.441,"time_format":"relative"}}}
�{"time":0.052898,"name":"recovery:congestion_state_updated","data":{"new":"slow_start"}}
�{"time":0.059069,"name":"transport:parameters_set","data":{"owner":"local","original_destination_connection_id":"018a44fc2526d77aba042d46e2ff56","stateless_reset_token":"4a25ee4d6ff2b45dfcd78532d26179e2","initial_source_connection_id":"f7f3f43a","disable_active_migration":true,"max_idle_timeout":30000,"max_udp_payload_size":1452,"ack_delay_exponent":3,"max_ack_delay":26,"active_connection_id_limit":4,"initial_max_data":786432,"initial_max_stream_data_bidi_local":524288,"initial_max_stream_data_bidi_remote":524288,"initial_max_stream_data_uni":524288,"initial_max_streams_bidi":100,"initial_max_streams_uni":100}}
�{"time":0.080719,"name":"security:key_updated","data":{"trigger":"tls","key_type":"client_initial_secret"}}
�{"time":0.08143,"name":"security:key_updated","data":{"trigger":"tls","key_type":"server_initial_secret"}}
�{"time":0.172408,"name":"transport:version_information","data":{"server_versions":["1","6b3343cf"],"chosen_version":"1"}}
�{"time":0.17335,"name":"transport:connection_started","data":{"ip_version":"ipv4","src_ip":"127.0.0.1","src_port":443,"dst_ip":"127.0.0.1","dst_port":36648,"src_cid":"583711","dst_cid":"018a44fc2526d77aba042d46e2ff56"}}
�{"time":0.583236,"name":"security:key_updated","data":{"trigger":"tls","key_type":"server_handshake_secret"}}
�{"time":0.586642,"name":"security:key_updated","data":{"trigger":"tls","key_type":"client_handshake_secret"}}
�{"time":0.650149,"name":"security:key_updated","data":{"trigger":"tls","key_type":"server_1rtt_secret","key_phase":0}}
�{"time":0.65076,"name":"transport:parameters_set","data":{"owner":"remote","initial_source_connection_id":"583711","disable_active_migration":false,"max_idle_timeout":30000,"max_udp_payload_size":4611686018427387903,"ack_delay_exponent":3,"max_ack_delay":20,"active_connection_id_limit":8,"initial_max_data":25165824,"initial_max_stream_data_bidi_local":12582912,"initial_max_stream_data_bidi_remote":1048576,"initial_max_stream_data_uni":1048576,"initial_max_streams_bidi":16,"initial_max_streams_uni":16,"max_datagram_frame_size":1200}}
�{"time":0.660729,"name":"transport:packet_received","data":{"header":{"packet_type":"initial","packet_number":0,"version":"1","scil":3,"scid":"583711","dcil":15,"dcid":"018a44fc2526d77aba042d46e2ff56"},"raw":{"length":671,"payload_length":643},"frames":[{"frame_type":"crypto","offset":0,"length":622}],"ecn":"Not-ECT"}}
�{"time":0.662011,"name":"transport:packet_dropped","data":{"header":{"packet_type":""},"raw":{"length":581},"trigger":"unknown_connection_id"}}
�{"time":0.671388,"name":"transport:packet_sent","data":{"header":{"packet_type":"initial","packet_number":0,"version":"1","scil":4,"scid":"f7f3f43a","dcil":3,"dcid":"583711"},"raw":{"length":134,"payload_length":117},"frames":[{"frame_type":"ack","acked_ranges":[[0]]},{"frame_type":"crypto","offset":0,"length":90}],"ecn":"Not-ECT"}}
�{"time":0.671839,"name":"transport:packet_sent","data":{"header":{"packet_type":"handshake","packet_number":0,"version":"1","scil":4,"scid":"f7f3f43a","dcil":3,"dcid":"583711"},"raw":{"length":1146,"payload_length":1130},"frames":[{"frame_type":"crypto","offset":0,"length":1108}],"ecn":"Not-ECT"}}
�{"time":0.673222,"name":"recovery:metrics_updated","data":{"min_rtt":0,"smoothed_rtt":0,"latest_rtt":0,"rtt_variance":0,"congestion_window":40960,"bytes_in_flight":134,"packets_in_flight":1}}
�{"time":0.673883,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"initial","delta":199.988629}}
�{"time":0.674274,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1280,"packets_in_flight":2}}
�{"time":0.681968,"name":"transport:packet_sent","data":{"header":{"packet_type":"handshake","packet_number":1,"version":"1","scil":4,"scid":"f7f3f43a","dcil":3,"dcid":"583711"},"raw":{"length":55,"payload_length":39},"frames":[{"frame_type":"crypto","offset":1108,"length":17}],"ecn":"Not-ECT"}}
�{"time":0.682589,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"583711","packet_number":0,"key_phase_bit":"0"},"raw":{"length":142},"frames":[{"frame_type":"new_connection_id","sequence_number":1,"retire_prior_to":0,"length":4,"connection_id":"14ff1e25","stateless_reset_token":"8252b5c3b0a4d1c99fb4f34f06b11ff9"},{"frame_type":"new_connection_id","sequence_number":4,"retire_prior_to":0,"length":4,"connection_id":"781848ad","stateless_reset_token":"2a5e8fac2e537734b97a1d4935f57d93"},{"frame_type":"new_connection_id","sequence_number":3,"retire_prior_to":0,"length":4,"connection_id":"75057bff","stateless_reset_token":"6047606f776c8de37af6c9dfb3eb1f7a"},{"frame_type":"new_connection_id","sequence_number":2,"retire_prior_to":0,"length":4,"connection_id":"3c615ab9","stateless_reset_token":"0155b93c636c3e966f554d7d1625d041"},{"frame_type":"new_connection_id","sequence_number":5,"retire_prior_to":0,"length":4,"connection_id":"776efd64","stateless_reset_token":"7b6ff2687da7880d042285733e09d442"}],"ecn":"Not-ECT"}}
�{"time":0.68294,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1335,"packets_in_flight":3}}
�{"time":0.683351,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1477,"packets_in_flight":4}}
�{"time":0.770822,"name":"recovery:ecn_state_updated","data":{"new":"testing"}}
�{"time":0.772275,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"583711","packet_number":1,"key_phase_bit":"0"},"raw":{"length":29},"frames":[{"frame_type":"stream","stream_id":3,"offset":0,"length":5}],"ecn":"ECT(0)"}}
�{"time":0.773677,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1506,"packets_in_flight":5}}
�{"time":1.304607,"name":"security:key_discarded","data":{"trigger":"tls","key_type":"server_initial_secret"}}
�{"time":1.304607,"name":"security:key_discarded","data":{"trigger":"tls","key_type":"client_initial_secret"}}
�{"time":1.305438,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"handshake","delta":199.370659}}
�{"time":1.308704,"name":"recovery:congestion_state_updated","data":{"new":"application_limited"}}
�{"time":1.309075,"name":"recovery:metrics_updated","data":{"min_rtt":0.622038,"smoothed_rtt":0.622038,"latest_rtt":0.622038,"rtt_variance":0.311019,"bytes_in_flight":171,"packets_in_flight":2}}
�{"time":1.309305,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":1.309686,"name":"transport:packet_received","data":{"header":{"packet_type":"handshake","packet_number":0,"version":"1","scil":3,"scid":"583711","dcil":4,"dcid":"f7f3f43a"},"raw":{"length":38,"payload_length":22},"frames":[{"frame_type":"ack","ack_delay":0.024,"acked_ranges":[[0,1]]}],"ecn":"Not-ECT"}}
�{"time":3.907838,"name":"security:key_updated","data":{"trigger":"tls","key_type":"client_1rtt_secret","key_phase":0}}
�{"time":3.910473,"name":"transport:packet_received","data":{"header":{"packet_type":"handshake","packet_number":1,"version":"1","scil":3,"scid":"583711","dcil":4,"dcid":"f7f3f43a"},"raw":{"length":78,"payload_length":62},"frames":[{"frame_type":"ack","ack_delay":2.504,"acked_ranges":[[0,1]]},{"frame_type":"crypto","offset":0,"length":36}],"ecn":"Not-ECT"}}
�{"time":3.913539,"name":"transport:alpn_information","data":{"chosen_alpn":"h3"}}
�{"time":3.913709,"name":"security:key_discarded","data":{"trigger":"tls","key_type":"server_handshake_secret"}}
�{"time":3.913709,"name":"security:key_discarded","data":{"trigger":"tls","key_type":"client_handshake_secret"}}
�{"time":3.915312,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":18.711816}}
�{"time":3.953112,"name":"recovery:ecn_state_updated","data":{"new":"failed","trigger":"ACK doesn't contain ECN marks"}}
�{"time":3.954114,"name":"recovery:metrics_updated","data":{"smoothed_rtt":0.931,"latest_rtt":3.101882,"rtt_variance":0.853,"bytes_in_flight":0}}
�{"time":3.954334,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":3.956588,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":0,"key_phase_bit":"0"},"raw":{"length":97,"payload_length":91},"frames":[{"frame_type":"ack","ack_delay":2.496,"acked_ranges":[[0,1]]},{"frame_type":"new_connection_id","sequence_number":1,"retire_prior_to":0,"length":3,"connection_id":"666a37","stateless_reset_token":"c027409c6d26b229c2c29216aa085119"},{"frame_type":"new_connection_id","sequence_number":2,"retire_prior_to":0,"length":3,"connection_id":"fa8ac8","stateless_reset_token":"43feb61f2eb90118a52108c01a08cab6"},{"frame_type":"new_connection_id","sequence_number":3,"retire_prior_to":0,"length":3,"connection_id":"c236b4","stateless_reset_token":"325d1ffb4749e564ee556664ab48ed38"}],"ecn":"Not-ECT"}}
�{"time":3.967098,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":1,"key_phase_bit":"0"},"raw":{"length":60,"payload_length":54},"frames":[{"frame_type":"stream","stream_id":2,"offset":0,"length":27},{"frame_type":"stream","stream_id":6,"offset":0,"length":1},{"frame_type":"stream","stream_id":10,"offset":0,"length":1}],"ecn":"Not-ECT"}}
�{"time":3.979671,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":2,"key_phase_bit":"0"},"raw":{"length":306},"frames":[{"frame_type":"ack","ack_delay":0.104944,"acked_ranges":[[0,1]]},{"frame_type":"crypto","offset":0,"length":183},{"frame_type":"retire_connection_id","sequence_number":0},{"frame_type":"handshake_done"},{"frame_type":"new_token","token":{"data":"355d109ba6d19f08036de3572471d2a7663b32dc396bacd2a37e596e7f9122ada2ec912d78180165dcc358130f723a256b0553825d8e4ec0117382c15564ef8f41215f03ca7099f312d918258f4d85a2a18e480f0ec1"}}],"ecn":"Not-ECT"}}
�{"time":3.980553,"name":"recovery:metrics_updated","data":{"bytes_in_flight":306,"packets_in_flight":1}}
�{"time":3.980683,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":24.330096}}
�{"time":4.314959,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":2,"key_phase_bit":"0"},"raw":{"length":45,"payload_length":39},"frames":[{"frame_type":"new_connection_id","sequence_number":4,"retire_prior_to":0,"length":3,"connection_id":"4b5da9","stateless_reset_token":"15957fb1d0297f2b0538af01e35c7cb8"}],"ecn":"Not-ECT"}}
�{"time":23.618126,"name":"recovery:metrics_updated","data":{"smoothed_rtt":3.262,"latest_rtt":19.580047,"rtt_variance":5.302,"bytes_in_flight":0}}
�{"time":23.622574,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":23.624558,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":3,"key_phase_bit":"0"},"raw":{"length":28,"payload_length":22},"frames":[{"frame_type":"ack","ack_delay":19.248,"acked_ranges":[[0,2]]}],"ecn":"Not-ECT"}}
�{"time":23.654223,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":3,"key_phase_bit":"0"},"raw":{"length":1366},"frames":[{"frame_type":"ping"}],"ecn":"Not-ECT"}}
�{"time":23.656777,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1366,"packets_in_flight":1}}
�{"time":23.812915,"name":"recovery:mtu_updated","data":{"mtu":1366,"done":false}}
�{"time":23.814699,"name":"recovery:metrics_updated","data":{"min_rtt":0.170425,"smoothed_rtt":2.875,"latest_rtt":0.170425,"rtt_variance":4.749,"bytes_in_flight":0}}
�{"time":23.81543,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":4,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.016,"acked_ranges":[[0,3]]}],"ecn":"Not-ECT"}}
�{"time":30.067372,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":4,"key_phase_bit":"0"},"raw":{"length":28},"frames":[{"frame_type":"ack","ack_delay":6.235051,"acked_ranges":[[2,4]]}],"ecn":"Not-ECT"}}
�{"time":98.712025,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":5,"key_phase_bit":"0"},"raw":{"length":314,"payload_length":308},"frames":[{"frame_type":"stream","stream_id":0,"offset":0,"length":288,"fin":true}],"ecn":"Not-ECT"}}
�{"time":98.727123,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":5,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"ping"}],"ecn":"Not-ECT"}}
�{"time":98.728886,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1409,"packets_in_flight":1}}
�{"time":98.870878,"name":"recovery:mtu_updated","data":{"mtu":1409,"done":false}}
�{"time":98.877119,"name":"recovery:metrics_updated","data":{"min_rtt":0.142262,"smoothed_rtt":2.533,"latest_rtt":0.142262,"rtt_variance":4.244,"bytes_in_flight":0}}
�{"time":98.878342,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":6,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.016,"acked_ranges":[[0,5]]}],"ecn":"Not-ECT"}}
�{"time":98.971373,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":7,"key_phase_bit":"0"},"raw":{"length":300,"payload_length":294},"frames":[{"frame_type":"stream","stream_id":4,"offset":0,"length":274,"fin":true}],"ecn":"Not-ECT"}}
�{"time":98.98062,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":6,"key_phase_bit":"0"},"raw":{"length":27},"frames":[{"frame_type":"ack","ack_delay":0.029264,"acked_ranges":[[2,7]]}],"ecn":"Not-ECT"}}
�{"time":99.405895,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":8,"key_phase_bit":"0"},"raw":{"length":286,"payload_length":280},"frames":[{"frame_type":"stream","stream_id":8,"offset":0,"length":260,"fin":true}],"ecn":"Not-ECT"}}
�{"time":99.673018,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":7,"key_phase_bit":"0"},"raw":{"length":308},"frames":[{"frame_type":"ack","ack_delay":0.297288,"acked_ranges":[[2,8]]},{"frame_type":"stream","stream_id":4,"offset":0,"length":279,"fin":true}],"ecn":"Not-ECT"}}
�{"time":99.67436,"name":"recovery:metrics_updated","data":{"bytes_in_flight":308,"packets_in_flight":1}}
�{"time":99.675382,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":39.497268}}
�{"time":99.929,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":8,"key_phase_bit":"0"},"raw":{"length":65},"frames":[{"frame_type":"stream","stream_id":8,"offset":0,"length":41,"fin":true}],"ecn":"Not-ECT"}}
�{"time":100.0973,"name":"recovery:metrics_updated","data":{"bytes_in_flight":373,"packets_in_flight":2}}
�{"time":100.097921,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":39.330621}}
�{"time":100.20574,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":9,"key_phase_bit":"0"},"raw":{"length":96},"frames":[{"frame_type":"stream","stream_id":0,"offset":0,"length":72}],"ecn":"Not-ECT"}}
�{"time":100.207333,"name":"recovery:metrics_updated","data":{"bytes_in_flight":469,"packets_in_flight":3}}
�{"time":100.207784,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":39.409046}}
�{"time":100.21127,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":10,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":72,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.212022,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1878,"packets_in_flight":4}}
�{"time":100.213845,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":11,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":1455,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.214807,"name":"recovery:metrics_updated","data":{"bytes_in_flight":3287,"packets_in_flight":5}}
�{"time":100.216741,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":12,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":2838,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.217352,"name":"recovery:metrics_updated","data":{"bytes_in_flight":4696,"packets_in_flight":6}}
�{"time":100.219135,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":13,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":4221,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.219606,"name":"recovery:metrics_updated","data":{"bytes_in_flight":6105,"packets_in_flight":7}}
�{"time":100.222291,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":14,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":5604,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.222782,"name":"recovery:metrics_updated","data":{"bytes_in_flight":7514,"packets_in_flight":8}}
�{"time":100.224745,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":15,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":6987,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.228412,"name":"recovery:metrics_updated","data":{"bytes_in_flight":8923,"packets_in_flight":9}}
�{"time":100.230406,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":16,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":8370,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.231107,"name":"recovery:metrics_updated","data":{"bytes_in_flight":10332,"packets_in_flight":10}}
�{"time":100.233081,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":17,"key_phase_bit":"0"},"raw":{"length":1409},"frames":[{"frame_type":"stream","stream_id":0,"offset":9753,"length":1383}],"ecn":"Not-ECT"}}
�{"time":100.233562,"name":"recovery:metrics_updated","data":{"bytes_in_flight":11741,"packets_in_flight":11}}
�{"time":100.235355,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":18,"key_phase_bit":"0"},"raw":{"length":782},"frames":[{"frame_type":"stream","stream_id":0,"offset":11136,"length":756}],"ecn":"Not-ECT"}}
�{"time":100.235866,"name":"recovery:metrics_updated","data":{"bytes_in_flight":12523,"packets_in_flight":12}}
�{"time":100.253548,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":19,"key_phase_bit":"0"},"raw":{"length":26},"frames":[{"frame_type":"stream","stream_id":0,"offset":11892,"length":0,"fin":true}],"ecn":"Not-ECT"}}
�{"time":100.254831,"name":"recovery:metrics_updated","data":{"bytes_in_flight":12549,"packets_in_flight":13}}
�{"time":100.255101,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":39.501336}}
�{"time":100.264018,"name":"recovery:metrics_updated","data":{"smoothed_rtt":2.251,"latest_rtt":0.283958,"rtt_variance":3.745,"bytes_in_flight":12176,"packets_in_flight":11}}
�{"time":100.264278,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":37.214159}}
�{"time":100.264739,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":9,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.04,"acked_ranges":[[0,8]]}],"ecn":"Not-ECT"}}
�{"time":100.268236,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":20,"key_phase_bit":"0"},"raw":{"length":28},"frames":[{"frame_type":"max_streams","stream_type":"bidirectional","maximum":102},{"frame_type":"max_streams","stream_type":"bidirectional","maximum":101}],"ecn":"Not-ECT"}}
�{"time":100.268656,"name":"recovery:metrics_updated","data":{"bytes_in_flight":12204,"packets_in_flight":12}}
�{"time":100.268897,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":37.227493}}
�{"time":100.443709,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.99,"latest_rtt":0.165105,"rtt_variance":3.33,"bytes_in_flight":0}}
�{"time":100.44947,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":100.449971,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":10,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.032,"acked_ranges":[[0,20]]}],"ecn":"Not-ECT"}}
�{"time":100.453337,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":21,"key_phase_bit":"0"},"raw":{"length":25},"frames":[{"frame_type":"max_streams","stream_type":"bidirectional","maximum":103}],"ecn":"Not-ECT"}}
�{"time":100.534176,"name":"recovery:metrics_updated","data":{"bytes_in_flight":25,"packets_in_flight":1}}
�{"time":100.534617,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":35.226125}}
�{"time":110.60314,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.767,"latest_rtt":0.212266,"rtt_variance":2.941,"bytes_in_flight":0}}
�{"time":110.605534,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":110.640759,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":11,"key_phase_bit":"0"},"raw":{"length":292,"payload_length":286},"frames":[{"frame_type":"ack","ack_delay":9.896,"acked_ranges":[[0,21]]},{"frame_type":"stream","stream_id":12,"offset":0,"length":260,"fin":true}],"ecn":"Not-ECT"}}
�{"time":110.659794,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":22,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"ping"}],"ecn":"Not-ECT"}}
�{"time":110.661778,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1430,"packets_in_flight":1}}
�{"time":110.780156,"name":"recovery:mtu_updated","data":{"mtu":1430,"done":false}}
�{"time":110.784785,"name":"recovery:metrics_updated","data":{"min_rtt":0.119039,"smoothed_rtt":1.561,"latest_rtt":0.119039,"rtt_variance":2.617,"bytes_in_flight":0}}
�{"time":110.786418,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":12,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.008,"acked_ranges":[[0,22]]}],"ecn":"Not-ECT"}}
�{"time":111.506356,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":23,"key_phase_bit":"0"},"raw":{"length":114},"frames":[{"frame_type":"ack","ack_delay":0.730037,"acked_ranges":[[9,12]]},{"frame_type":"stream","stream_id":12,"offset":0,"length":84}],"ecn":"Not-ECT"}}
�{"time":111.508169,"name":"recovery:metrics_updated","data":{"bytes_in_flight":114,"packets_in_flight":1}}
�{"time":111.509111,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":32.009143}}
�{"time":111.51402,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":24,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"stream","stream_id":12,"offset":84,"length":1404}],"ecn":"Not-ECT"}}
�{"time":111.514591,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1544,"packets_in_flight":2}}
�{"time":111.517366,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":25,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"stream","stream_id":12,"offset":1488,"length":1404}],"ecn":"Not-ECT"}}
�{"time":111.517777,"name":"recovery:metrics_updated","data":{"bytes_in_flight":2974,"packets_in_flight":3}}
�{"time":111.51981,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":26,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"stream","stream_id":12,"offset":2892,"length":1404}],"ecn":"Not-ECT"}}
�{"time":111.520261,"name":"recovery:metrics_updated","data":{"bytes_in_flight":4404,"packets_in_flight":4}}
�{"time":111.522155,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":27,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"stream","stream_id":12,"offset":4296,"length":1404}],"ecn":"Not-ECT"}}
�{"time":111.522546,"name":"recovery:metrics_updated","data":{"bytes_in_flight":5834,"packets_in_flight":5}}
�{"time":111.524679,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":28,"key_phase_bit":"0"},"raw":{"length":1430},"frames":[{"frame_type":"stream","stream_id":12,"offset":5700,"length":1404}],"ecn":"Not-ECT"}}
�{"time":111.52506,"name":"recovery:metrics_updated","data":{"bytes_in_flight":7264,"packets_in_flight":6}}
�{"time":111.527845,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":29,"key_phase_bit":"0"},"raw":{"length":496},"frames":[{"frame_type":"stream","stream_id":12,"offset":7104,"length":470}],"ecn":"Not-ECT"}}
�{"time":111.528577,"name":"recovery:metrics_updated","data":{"bytes_in_flight":7760,"packets_in_flight":7}}
�{"time":111.596552,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":30,"key_phase_bit":"0"},"raw":{"length":26},"frames":[{"frame_type":"stream","stream_id":12,"offset":7574,"length":0,"fin":true}],"ecn":"Not-ECT"}}
�{"time":111.598856,"name":"recovery:metrics_updated","data":{"bytes_in_flight":7786,"packets_in_flight":8}}
�{"time":111.599477,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":32.014754}}
�{"time":111.767658,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.386,"latest_rtt":0.162951,"rtt_variance":2.312,"bytes_in_flight":0}}
�{"time":111.769631,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":111.770272,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":13,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.056,"acked_ranges":[[0,30]]}],"ecn":"Not-ECT"}}
�{"time":111.775452,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":31,"key_phase_bit":"0"},"raw":{"length":25},"frames":[{"frame_type":"max_streams","stream_type":"bidirectional","maximum":104}],"ecn":"Not-ECT"}}
�{"time":111.776023,"name":"recovery:metrics_updated","data":{"bytes_in_flight":25,"packets_in_flight":1}}
�{"time":111.776284,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":30.629231}}
�{"time":121.254517,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.239,"latest_rtt":0.215984,"rtt_variance":2.026,"bytes_in_flight":0}}
�{"time":121.260649,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":121.29414,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":14,"key_phase_bit":"0"},"raw":{"length":406,"payload_length":400},"frames":[{"frame_type":"ack","ack_delay":9.176,"acked_ranges":[[0,31]]},{"frame_type":"stream","stream_id":16,"offset":0,"length":374,"fin":true}],"ecn":"Not-ECT"}}
�{"time":121.323675,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":32,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"ping"}],"ecn":"Not-ECT"}}
�{"time":121.325839,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1441,"packets_in_flight":1}}
�{"time":121.485343,"name":"recovery:mtu_updated","data":{"mtu":1441,"done":true}}
�{"time":121.488339,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.103,"latest_rtt":0.156934,"rtt_variance":1.79,"bytes_in_flight":0}}
�{"time":121.488789,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":15,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.024,"acked_ranges":[[0,32]]}],"ecn":"Not-ECT"}}
�{"time":122.075101,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":33,"key_phase_bit":"0"},"raw":{"length":100},"frames":[{"frame_type":"ack","ack_delay":0.589928,"acked_ranges":[[13,15]]},{"frame_type":"stream","stream_id":16,"offset":0,"length":70}],"ecn":"Not-ECT"}}
�{"time":122.076864,"name":"recovery:metrics_updated","data":{"bytes_in_flight":100,"packets_in_flight":1}}
�{"time":122.077586,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":28.253101}}
�{"time":122.081723,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":34,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":70,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.083557,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1541,"packets_in_flight":2}}
�{"time":122.086362,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":35,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":1485,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.086813,"name":"recovery:metrics_updated","data":{"bytes_in_flight":2982,"packets_in_flight":3}}
�{"time":122.088706,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":36,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":2900,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.089207,"name":"recovery:metrics_updated","data":{"bytes_in_flight":4423,"packets_in_flight":4}}
�{"time":122.09101,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":37,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":4315,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.091672,"name":"recovery:metrics_updated","data":{"bytes_in_flight":5864,"packets_in_flight":5}}
�{"time":122.093224,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":38,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":5730,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.093826,"name":"recovery:metrics_updated","data":{"bytes_in_flight":7305,"packets_in_flight":6}}
�{"time":122.095519,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":39,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":16,"offset":7145,"length":1415}],"ecn":"Not-ECT"}}
�{"time":122.095829,"name":"recovery:metrics_updated","data":{"bytes_in_flight":8746,"packets_in_flight":7}}
�{"time":122.097031,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":40,"key_phase_bit":"0"},"raw":{"length":228},"frames":[{"frame_type":"stream","stream_id":16,"offset":8560,"length":202}],"ecn":"Not-ECT"}}
�{"time":122.097352,"name":"recovery:metrics_updated","data":{"bytes_in_flight":8974,"packets_in_flight":8}}
�{"time":122.116788,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":41,"key_phase_bit":"0"},"raw":{"length":26},"frames":[{"frame_type":"stream","stream_id":16,"offset":8762,"length":0,"fin":true}],"ecn":"Not-ECT"}}
�{"time":122.11797,"name":"recovery:metrics_updated","data":{"bytes_in_flight":9000,"packets_in_flight":9}}
�{"time":122.118401,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":28.254214}}
�{"time":122.246277,"name":"recovery:metrics_updated","data":{"smoothed_rtt":0.98,"latest_rtt":0.125191,"rtt_variance":1.586,"bytes_in_flight":0}}
�{"time":122.247649,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":122.24802,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":16,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.032,"acked_ranges":[[0,41]]}],"ecn":"Not-ECT"}}
�{"time":122.250795,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":42,"key_phase_bit":"0"},"raw":{"length":25},"frames":[{"frame_type":"max_streams","stream_type":"bidirectional","maximum":105}],"ecn":"Not-ECT"}}
�{"time":122.251036,"name":"recovery:metrics_updated","data":{"bytes_in_flight":25,"packets_in_flight":1}}
�{"time":122.251236,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":27.321505}}
�{"time":131.911134,"name":"recovery:metrics_updated","data":{"smoothed_rtt":2.061,"latest_rtt":9.630725,"rtt_variance":3.352,"bytes_in_flight":0}}
�{"time":131.91443,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":131.933556,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":17,"key_phase_bit":"0"},"raw":{"length":356,"payload_length":350},"frames":[{"frame_type":"ack","ack_delay":9.512,"acked_ranges":[[0,42]]},{"frame_type":"stream","stream_id":20,"offset":0,"length":324,"fin":true}],"ecn":"Not-ECT"}}
�{"time":132.09334,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":18,"key_phase_bit":"0"},"raw":{"length":350,"payload_length":344},"frames":[{"frame_type":"stream","stream_id":24,"offset":0,"length":324,"fin":true}],"ecn":"Not-ECT"}}
�{"time":132.102317,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":43,"key_phase_bit":"0"},"raw":{"length":27},"frames":[{"frame_type":"ack","ack_delay":0.025337,"acked_ranges":[[16,18]]}],"ecn":"Not-ECT"}}
�{"time":132.733141,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":44,"key_phase_bit":"0"},"raw":{"length":94},"frames":[{"frame_type":"stream","stream_id":20,"offset":0,"length":70}],"ecn":"Not-ECT"}}
�{"time":132.735735,"name":"recovery:metrics_updated","data":{"bytes_in_flight":94,"packets_in_flight":1}}
�{"time":132.736948,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":35.453411}}
�{"time":132.740504,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":45,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":20,"offset":70,"length":1415}],"ecn":"Not-ECT"}}
�{"time":132.740955,"name":"recovery:metrics_updated","data":{"bytes_in_flight":1535,"packets_in_flight":2}}
�{"time":132.742368,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":46,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":20,"offset":1485,"length":1415}],"ecn":"Not-ECT"}}
�{"time":132.742889,"name":"recovery:metrics_updated","data":{"bytes_in_flight":2976,"packets_in_flight":3}}
�{"time":132.744021,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":47,"key_phase_bit":"0"},"raw":{"length":1441},"frames":[{"frame_type":"stream","stream_id":20,"offset":2900,"length":1415}],"ecn":"Not-ECT"}}
�{"time":132.744642,"name":"recovery:metrics_updated","data":{"bytes_in_flight":4417,"packets_in_flight":4}}
�{"time":132.745964,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":48,"key_phase_bit":"0"},"raw":{"length":817},"frames":[{"frame_type":"stream","stream_id":20,"offset":4315,"length":791}],"ecn":"Not-ECT"}}
�{"time":132.746275,"name":"recovery:metrics_updated","data":{"bytes_in_flight":5234,"packets_in_flight":5}}
�{"time":132.791258,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":49,"key_phase_bit":"0"},"raw":{"length":26},"frames":[{"frame_type":"stream","stream_id":20,"offset":5106,"length":0,"fin":true}],"ecn":"Not-ECT"}}
�{"time":132.792831,"name":"recovery:metrics_updated","data":{"bytes_in_flight":5260,"packets_in_flight":6}}
�{"time":132.793251,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":35.460084}}
�{"time":132.796718,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":50,"key_phase_bit":"0"},"raw":{"length":419},"frames":[{"frame_type":"stream","stream_id":24,"offset":0,"length":395,"fin":true}],"ecn":"Not-ECT"}}
�{"time":132.798681,"name":"recovery:metrics_updated","data":{"bytes_in_flight":5679,"packets_in_flight":7}}
�{"time":133.057409,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.819,"latest_rtt":0.131945,"rtt_variance":2.996,"bytes_in_flight":0}}
�{"time":133.059753,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":133.061196,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":19,"key_phase_bit":"0"},"raw":{"length":27,"payload_length":21},"frames":[{"frame_type":"ack","ack_delay":0.12,"acked_ranges":[[0,50]]}],"ecn":"Not-ECT"}}
�{"time":133.069641,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"666a37","packet_number":51,"key_phase_bit":"0"},"raw":{"length":28},"frames":[{"frame_type":"max_streams","stream_type":"bidirectional","maximum":106},{"frame_type":"max_streams","stream_type":"bidirectional","maximum":107}],"ecn":"Not-ECT"}}
�{"time":133.070242,"name":"recovery:metrics_updated","data":{"bytes_in_flight":28,"packets_in_flight":1}}
�{"time":133.070563,"name":"recovery:loss_timer_updated","data":{"event_type":"set","timer_type":"pto","packet_number_space":"application_data","delta":33.795817}}
�{"time":152.361457,"name":"recovery:metrics_updated","data":{"smoothed_rtt":1.611,"latest_rtt":0.155136,"rtt_variance":2.662,"bytes_in_flight":0}}
�{"time":152.365946,"name":"recovery:loss_timer_updated","data":{"event_type":"cancelled"}}
�{"time":152.3738,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"f7f3f43a","packet_number":20,"key_phase_bit":"0"},"raw":{"length":28,"payload_length":22},"frames":[{"frame_type":"ack","ack_delay":19.104,"acked_ranges":[[0,51]]}],"ecn":"Not-ECT"}}
�{"time":30160.046995,"name":"transport:connection_closed","data":{"owner":"local","trigger":"idle_timeout"}}

File: sqlog.zip

@marten-seemann
Copy link
Contributor

The qlog looks fine, the client doesn't even send an error.

I'm not sure what NS_ERROR_CORRUPTED_CONTENT means in the first place, so it's hard to speculate what could cause this. v0.47.0 was not a particularly big release, but we added Trailer support and fixed a Content-Length issue, which might influence things.

Could you bisect which commit in quic-go (between v0.46.0 and v0.47.0) caused this behavior?

@otbutz
Copy link

otbutz commented Nov 7, 2024

I'm not sure what NS_ERROR_CORRUPTED_CONTENT means in the first place

Quickly skimmed the Firefox bugtracker and this might indicate that HTTP header(s) are invalid. e.g multiple Content-Length headers for the same response.

@inetol
Copy link
Author

inetol commented Nov 7, 2024

Could you bisect which commit in quic-go (between v0.46.0 and v0.47.0) caused this behavior?

@marten-seemann From commit quic-go/quic-go@7c3544c onwards the issue manifests.

@marten-seemann
Copy link
Contributor

Thank you for bisecting @inetol! So it looks like this is actually a Content-Length issue.

Would you mind re-running your test on this branch? https://github.com/quic-go/quic-go/compare/print-http3-headers

All I did was add a bit of logging right before the header fields are QPACK encoded. This should tell us what the invalid value is. I suspect it's either an invalid value being sent (maybe a -1 that's being copied from an http.Response?), or if we're sending a duplicate value.

@inetol
Copy link
Author

inetol commented Nov 8, 2024

Um, looks like that section of code is not being executed because no log msg with the headers appears in the console and I have run the same tests as before.

@otbutz
Copy link

otbutz commented Nov 8, 2024 •
edited
Loading

@inetol you could try to gather the logs via Firefox. Visit about:logging, select the HTTP/3 preset, choose a logfile as the destination and start the capture process.

Image

@inetol
Copy link
Author

inetol commented Nov 8, 2024

Visit about:logging, select the HTTP/3 preset, choose a logfile as the destination and start the capture process.

There are no relevant logs, at least on the client side.

@marten-seemann I have not been able to get any new logs on console by building Caddy with quic-go/quic-go#print-http3-headers branch.

@marten-seemann
Copy link
Contributor

No idea what’s going on then. If we’re not sending any headers, how can they cause any problems?

@inetol
Copy link
Author

inetol commented Nov 9, 2024

@marten-seemann I noticed that since commit quic-go/quic-go@7c3544c, the request body is no longer nil on reverseproxy package.

I've created a quick patch that "fixes" this specific issue in my case..:

--- a/modules/caddyhttp/reverseproxy/reverseproxy.go
+++ b/modules/caddyhttp/reverseproxy/reverseproxy.go
@@ -842,6 +842,12 @@
 		req = req.WithContext(context.WithoutCancel(req.Context()))
 	}
 
+	// FIXME: Debug
+	if req.Body != nil {
+		req.Body = nil
+		req.ContentLength = 0
+	}
+
 	// do the round-trip
 	start := time.Now()
 	res, err := h.Transport.RoundTrip(req)

I hope I have at least identified the issue better because I am a bit lost now.

@francislavoie
Copy link
Member

Huh? Doesn't that just break all non-GET requests with a body?

@inetol
Copy link
Author

inetol commented Nov 9, 2024

Yes, it's a small test to identify which part of the request was the problematic one; as previously if the client did not send a body via HTTP/3, it went through the entire reverseproxy as nil, but this behavior had changed with the above-mentioned commit.

@marten-seemann
Copy link
Contributor

@inetol Where did the request body change in quic-go/quic-go@7c3544c? I just tested quic-go v0.47.0 with a HEAD request, and it has a Body set on both the http.Request (on the server side) and on the http.Response on the client side. This body returns 0, io.EOF on the Read call, as you would expect.

I'm wondering, is quic-go/quic-go#4648 causing any problems?

@inetol
Copy link
Author

inetol commented Nov 11, 2024

@marten-seemann Sorry, I forgot mentioning that the body checks were performed only and just before the request goes into the Caddy reverseproxy round-trip, I do not know if this is the expected behavior now since my problem seems to originate from the existence of the body?

caddy/modules/caddyhttp/reverseproxy/reverseproxy.go

Line 847 in 825fe48

res, err := h.Transport.RoundTrip(req)

...I mean, by looking at the commit quic-go/quic-go@7c3544c I can already see that at most that infers to the body could be the Content-Length which leads me to believe that it is some misinterpretation by Caddy due to that header, hence the previous question.

I'm wondering, is quic-go/quic-go#4648 causing any problems?

Nope

@marten-seemann
Copy link
Contributor

Is there any discrepancy between HTTP/3 and the standard library HTTP versions with regards to the Content-Length field, that leads to this error surfacing on HTTP/3, but not on older HTTP versions? Are there any cases where quic-go should set a different value?

@inetol
Copy link
Author

inetol commented Nov 12, 2024

Is there any discrepancy between HTTP/3 and the standard library HTTP versions with regards to the Content-Length field, that leads to this error surfacing on HTTP/3, but not on older HTTP versions? Are there any cases where quic-go should set a different value?

AFAIK, the net stdlib returns a Content-Length value of 0 IF the client sends an empty body, I don't know if RoundTrip can consume a Content-Length header value of -1 though...

On the other hand, I noticed some warns being returned to the console in another project where I was doing similar testing, and it seems that they are related to this issue because they also occur under the same conditions..:

WARN http.handlers.reverse_proxy aborting with incomplete response {"upstream": "paste.inetol.net:443", "duration": 0.045993958, "request": {"remote_ip": "127.0.0.1", "remote_port": "46755", "client_ip": "127.0.0.1", "proto": "HTTP/3.0", "method": "GET", "host": "paste.inetol.net:443", "uri": "/assets/chunks/chunk-CRk4iC61.js", "headers": {"X-Forwarded-For": ["127.0.0.1"], "Priority": ["u=1"], "Accept": ["*/*"], "Alt-Used": ["remotepaste.localhost"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Cache-Control": ["no-cache"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0"], "Sec-Fetch-Mode": ["cors"], "X-Forwarded-Host": ["remotepaste.localhost"], "Sec-Fetch-Dest": ["script"], "Referer": ["https://remotepaste.localhost/"], "Pragma": ["no-cache"], "Sec-Fetch-Site": ["same-origin"], "X-Forwarded-Proto": ["https"], "Accept-Language": ["en-US,en;q=0.5"]}, "tls": {"resumed": true, "version": 772, "cipher_suite": 4865, "proto": "h3", "server_name": "remotepaste.localhost"}}, "error": "reading: context canceled"}

This behavior can be replicated if you configure a reverse proxy to the remote server or by running the same project locally:

# Caddyfile

{
	#debug
	local_certs
	skip_install_trust
}

remotepaste.localhost {
	reverse_proxy https://paste.inetol.net {
		header_up Host {upstream_hostport}
	}
}

I will update the above instructions later today.

@inetol inetol changed the title (2.9.0-beta.3) Corrupted content over HTTP/3 Requests aborted over HTTP/3 Nov 12, 2024
@WeidiDeng
Copy link
Member

WeidiDeng commented Nov 13, 2024 •
edited
Loading

I did some digging, the problem the requests won't be tried is because caddy's reverse proxy is based on stdlib reverse proxy. And there are two places that will make sure these types of requests are retriable. One is the content-length sanitization if rewrite is enabled,

caddy/modules/caddyhttp/reverseproxy/reverseproxy.go

Lines 601 to 610 in 238f110

// if enabled, perform rewrites on the cloned request; if
// the method is GET or HEAD, prevent the request body
// from being copied to the upstream
if h.Rewrite != nil {
changed := h.Rewrite.Rewrite(req, repl)
if changed && (h.Rewrite.Method == "GET" || h.Rewrite.Method == "HEAD") {
req.ContentLength = 0
req.Body = nil
}
}

But in this case, it doesn't apply as there is no rewrite involved.

The problem is with the second place,

caddy/modules/caddyhttp/reverseproxy/reverseproxy.go

Lines 629 to 631 in 238f110

if req.ContentLength == 0 {
req.Body = nil // Issue golang/go#16036: nil Body for http.Transport retries
}

Now that http3 sets content length to -1, this won't apply anymore. Even though everything else is completely the same.

I checked stdlib implementations for Content-Length parsing when there is none declared, for http1 this is -1 if chunked encoding is used, 0 otherwise

https://github.com/golang/go/blob/239dbd7dbac883d6f9b6522774a0dfd519f77fa8/src/net/http/transfer.go#L730-L739

The comment here is confusing, in reality it applies to requests with methods other than GET. I found out when I tried to implement a forward proxy without using hijack for http1 requests, as the body is http.NoBody set based on this value.

For http2, if the headers frame has the flag end stream set, content length is 0, Content-Length is not checked in this case. Otherwise, if Content-Length is absent, it's -1, if present but invalid, 0, else parse it as the value.

https://github.com/golang/go/blob/239dbd7dbac883d6f9b6522774a0dfd519f77fa8/src/net/http/h2_bundle.go#L6058-L6072

I think we could do the same as stdlib http2. But I need to check if the header frame has the flag with similar meanings first. What do you think @marten-seemann ?

Update: there is no such indication in http3 header frame. Should we just set content length to 0 if the request is GET or HEAD?

@WeidiDeng
Copy link
Member

@inetol Can you try with xcaddy build --with github.com/quic-go/quic-go=github.com/WeidiDeng/quic-go@get-content-length?

@marten-seemann
Copy link
Contributor

@WeidiDeng Great debugging work, thank you!!!

I think we could do the same as stdlib http2. But I need to check if the header frame has the flag with similar meanings first. What do you think @marten-seemann ?

Update: there is no such indication in http3 header frame. Should we just set content length to 0 if the request is GET or HEAD?

We could, but is this the correct thing to do? On the one hand, GET and HEAD requests are defined (I assume, are they really?) to have a 0-length body. On the other hand, a client could be misbehaving, and we would never notice.

@marten-seemann marten-seemann mentioned this issue Nov 13, 2024
Closed
@inetol
Copy link
Author

inetol commented Nov 13, 2024

Can you try with xcaddy build --with github.com/quic-go/quic-go=github.com/WeidiDeng/quic-go@get-content-length?

That patch seems to fix it!

@marten-seemann
Copy link
Contributor

Can you try with xcaddy build --with github.com/quic-go/quic-go=github.com/WeidiDeng/quic-go@get-content-length?

That patch seems to fix it!

Unfortunately, this fix is not spec-compliant though. See quic-go/quic-go#4722 (comment) for more details.

I believe this needs to be handled in Caddy itself, taking care of the fact that both HEAD and GET requests indeed can have a request body.

@mholt
Copy link
Member

mholt commented Nov 15, 2024

That agrees with what @mohammed90 discussed with us in Slack.

To be fair, the spec does allow intermediaries to reject request bodies for HEAD and GET requests, and advises servers to not have "private agreements" with clients due to unspecified behaviors (I imagine that consists of reasoning such as, "we know our clients behave this way, therefore we can do this"):

Although request message framing is independent of the method used, content received in a GET request has no generally defined semantics, cannot alter the meaning or target of the request, and might lead some implementations to reject the request and close the connection because of its potential as a request smuggling attack (Section 11.2 of [HTTP/1.1]). A client SHOULD NOT generate content in a GET request unless it is made directly to an origin server that has previously indicated, in or out of band, that such a request has a purpose and will be adequately supported. An origin server SHOULD NOT rely on private agreements to receive content, since participants in HTTP communication are often unaware of intermediaries along the request chain.

I'm open to changing how we handle things, but I'm worried that a change here will break other use cases. 🤷‍♂

@WeidiDeng
Copy link
Member

Unfortunately, this fix is not spec-compliant though. See quic-go/quic-go#4722 (comment) for more details.

@marten-seemann That's exactly what I thought when I came up with that patch. It just restored some older behaviours without considering if that's actually correct. Meant for debug only.

@mholt Should we set a new parameter for reverse proxy that keeps bodies for theses requests, and by default that's false. I think very few would make use of it hence no related bug reports before. But it's there for someone who needs it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@mholt @marten-seemann @francislavoie @otbutz @WeidiDeng @inetol