[2025-04-30T20:08:29.102482017Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE
[2025-04-30T20:08:29.102789432Z INFO  quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:36395 with scid 0c219abf9a8488479a9768cf80a1f6bed7b45cba
[2025-04-30T20:08:29.102829777Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba write message lvl=Initial len=266
[2025-04-30T20:08:29.102845707Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Initial version=1 dcid=f233c3f6dd08c87bf5866d7d54a3b5ac scid=0c219abf9a8488479a9768cf80a1f6bed7b45cba len=270 pn=0 
[2025-04-30T20:08:29.102848793Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm CRYPTO off=0 len=266
[2025-04-30T20:08:29.102862979Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=998.933395ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 438631968 }, next_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.102923452Z TRACE quiche_apps::client] written 1200
[2025-04-30T20:08:29.143827035Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.143867090Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Initial version=1 dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba scid=ab42bb50e72a1c6326561b37 token= len=1158 pn=0 
[2025-04-30T20:08:29.143882209Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=0 len=90
[2025-04-30T20:08:29.143987335Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba set write secret lvl=Handshake
[2025-04-30T20:08:29.143998847Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba set read secret lvl=Handshake
[2025-04-30T20:08:29.144011480Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm PADDING len=1044
[2025-04-30T20:08:29.144037028Z TRACE quiche_apps::client] [::]:36395: processed 1200 bytes
[2025-04-30T20:08:29.144043039Z TRACE quiche_apps::client] got 211 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.144047027Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Handshake version=1 dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba scid=ab42bb50e72a1c6326561b37 len=170 pn=0 
[2025-04-30T20:08:29.144051726Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=0 len=146
[2025-04-30T20:08:29.144068377Z TRACE quiche_apps::client] [::]:36395: processed 211 bytes
[2025-04-30T20:08:29.144072264Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.144074889Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.144099335Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Initial version=1 dcid=ab42bb50e72a1c6326561b37 scid=0c219abf9a8488479a9768cf80a1f6bed7b45cba len=5 pn=1 
[2025-04-30T20:08:29.144102681Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=29 blocks=[0..0] ecn_counts=None
[2025-04-30T20:08:29.144113170Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=957.683194ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 479925841 }, next_time: Instant { tv_sec: 906, tv_nsec: 479925841 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.144140001Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Handshake version=1 dcid=ab42bb50e72a1c6326561b37 scid=0c219abf9a8488479a9768cf80a1f6bed7b45cba len=5 pn=2 
[2025-04-30T20:08:29.144142796Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=11 blocks=[0..0] ecn_counts=None
[2025-04-30T20:08:29.144147926Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=957.6488ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 438631968 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 479925841 }, next_time: Instant { tv_sec: 906, tv_nsec: 479925841 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.144158656Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba dropped epoch 0 state
[2025-04-30T20:08:29.144227224Z TRACE quiche_apps::client] written 1200 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.144239407Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.144449182Z TRACE quiche_apps::client] got 535 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.144478437Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Handshake version=1 dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba scid=ab42bb50e72a1c6326561b37 len=494 pn=1 
[2025-04-30T20:08:29.144493796Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=146 len=469
[2025-04-30T20:08:29.144580127Z TRACE quiche_apps::client] [::]:36395: processed 535 bytes
[2025-04-30T20:08:29.144587010Z TRACE quiche_apps::client] got 145 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.144590967Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Handshake version=1 dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba scid=ab42bb50e72a1c6326561b37 len=104 pn=2 
[2025-04-30T20:08:29.144595876Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=615 len=79
[2025-04-30T20:08:29.144745276Z TRACE quiche_apps::client] [::]:36395: processed 145 bytes
[2025-04-30T20:08:29.144752089Z TRACE quiche_apps::client] got 101 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.144766706Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Handshake version=1 dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba scid=ab42bb50e72a1c6326561b37 len=60 pn=3 
[2025-04-30T20:08:29.144771535Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=694 len=36
[2025-04-30T20:08:29.144807923Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba write message lvl=Handshake len=36
[2025-04-30T20:08:29.144811880Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba set write secret lvl=OneRTT
[2025-04-30T20:08:29.144821398Z TRACE quiche::tls] 0c219abf9a8488479a9768cf80a1f6bed7b45cba set read secret lvl=OneRTT
[2025-04-30T20:08:29.144835074Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba connection established: proto=Ok("hq-interop") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(f233c3f6dd08c87bf5866d7d54a3b5ac), max_idle_timeout: 120000, stateless_reset_token: Some(210583923196737783681531193876121058643), max_udp_payload_size: 1500, initial_max_data: 1048576, initial_max_stream_data_bidi_local: 16777216, initial_max_stream_data_bidi_remote: 16777216, initial_max_stream_data_uni: 16777216, initial_max_streams_bidi: 128, initial_max_streams_uni: 128, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 8, initial_source_connection_id: Some(ab42bb50e72a1c6326561b37), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None }
[2025-04-30T20:08:29.144869128Z TRACE quiche_apps::client] [::]:36395: processed 101 bytes
[2025-04-30T20:08:29.144881420Z TRACE quiche_apps::client] got 68 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.144886620Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba dropped invalid packet
[2025-04-30T20:08:29.144889716Z TRACE quiche_apps::client] [::]:36395: processed 68 bytes
[2025-04-30T20:08:29.144893483Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.144896148Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.144905456Z DEBUG quiche_apps::common] sending HTTP request "GET /zjitdnbher\r\n"
[2025-04-30T20:08:29.145214944Z DEBUG quiche_apps::common] sending HTTP request "GET /fwbvrbgrtn\r\n"
[2025-04-30T20:08:29.145302789Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Handshake version=1 dcid=ab42bb50e72a1c6326561b37 scid=0c219abf9a8488479a9768cf80a1f6bed7b45cba len=45 pn=3 
[2025-04-30T20:08:29.145309181Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=61 blocks=[0..3] ecn_counts=None
[2025-04-30T20:08:29.145314421Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm CRYPTO off=0 len=36
[2025-04-30T20:08:29.145325551Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=998.924178ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=103 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 481085463 }, next_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.145350709Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13397 out_len=1247 left=1217
[2025-04-30T20:08:29.145359345Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=302 pn=4 
[2025-04-30T20:08:29.145362020Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[14, a3, 2b, 72, 4b, 4a, 51, 0a, 2c, a3, 9e, 8a, 1e, 16, c8, 9a, f0, c2, 0c, 84] reset_token=[88, 66, 68, 23, 7d, 8a, 47, 36, b2, 29, d6, db, f9, 4b, 2c, d5]
[2025-04-30T20:08:29.145369213Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[5a, 2e, 21, c0, 83, a7, 85, a1, da, dd, dc, 3a, 4d, 2b, d3, 06, 11, ff, d4, 09] reset_token=[f8, bc, 16, 10, 64, 46, 7d, b2, 54, 1d, 21, a0, d8, df, d5, 39]
[2025-04-30T20:08:29.145374683Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[4f, 75, 10, fe, ae, b3, 84, a2, c1, de, 34, a6, 6c, 9e, 58, d2, 44, e0, 8a, 56] reset_token=[6e, c1, 46, 76, 88, 03, d7, d6, b0, 87, f0, 80, 20, e5, 99, 82]
[2025-04-30T20:08:29.145379863Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[3b, 1f, 9d, 40, 54, d1, 4b, ee, 80, 33, 84, 22, e2, 0d, 9c, 0c, 76, 12, 86, 46] reset_token=[b5, 08, 55, 63, 4b, b1, f1, 83, 61, 31, bc, c2, 9f, 09, a4, 2c]
[2025-04-30T20:08:29.145385083Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[6d, de, 2b, b9, a6, 0b, 49, 8c, 24, e8, 78, d6, 3c, 42, 70, cf, 81, 7d, 30, f5] reset_token=[4f, 09, 28, 16, d5, 42, 42, 63, 3c, 71, b1, da, 2a, 19, 08, d2]
[2025-04-30T20:08:29.145390894Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[a9, c9, 87, bb, 20, 7a, 10, 8b, d0, 4e, 1a, c3, 8b, 76, 5a, bd, af, 3c, 36, 2e] reset_token=[2c, c1, 7a, 89, 0c, d6, 00, 3c, 03, ba, 5a, d6, f6, 8b, 00, 75]
[2025-04-30T20:08:29.145395993Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[00, 79, 21, e1, aa, 9e, 39, 03, eb, 2e, 0d, 6d, f5, 47, 63, c0, 3b, a8, 21, 76] reset_token=[ee, 7d, b1, 53, 9d, 0b, 79, 25, 88, 80, 99, 77, bc, 56, 7d, 88]
[2025-04-30T20:08:29.145401193Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm STREAM id=0 off=0 len=17 fin=true
[2025-04-30T20:08:29.145410590Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=998.83961ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=435 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 481085463 }, next_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.145623238Z TRACE quiche_apps::client] written 435 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.145638377Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13065 out_len=1350 left=1320
[2025-04-30T20:08:29.145652433Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=22 pn=5 
[2025-04-30T20:08:29.145657212Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm STREAM id=4 off=0 len=17 fin=true
[2025-04-30T20:08:29.145668303Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=998.581427ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=487 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 481468029 }, next_time: Instant { tv_sec: 906, tv_nsec: 481468029 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.145704871Z TRACE quiche_apps::client] written 52 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.145712716Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.177962847Z TRACE quiche_apps::client] got 42 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.178003703Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=21 pn=0 
[2025-04-30T20:08:29.178016868Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm HANDSHAKE_DONE
[2025-04-30T20:08:29.178024652Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba dropped epoch 1 state
[2025-04-30T20:08:29.178040381Z TRACE quiche_apps::client] [::]:36395: processed 42 bytes
[2025-04-30T20:08:29.178045892Z TRACE quiche_apps::client] got 64 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.178049128Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=43 pn=1 
[2025-04-30T20:08:29.178056151Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm NEW_TOKEN len=21
[2025-04-30T20:08:29.178062663Z TRACE quiche_apps::client] [::]:36395: processed 64 bytes
[2025-04-30T20:08:29.178066430Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.178069075Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.178079605Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1315
[2025-04-30T20:08:29.178085115Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=5 pn=6 
[2025-04-30T20:08:29.178087770Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=3 blocks=[0..1] ecn_counts=None
[2025-04-30T20:08:29.178131021Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=991.501124ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 6, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 513909077 }, next_time: Instant { tv_sec: 906, tv_nsec: 513909077 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.178213345Z TRACE quiche_apps::client] written 35 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.178224486Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.178310467Z TRACE quiche_apps::client] got 302 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.178319614Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=281 pn=6 
[2025-04-30T20:08:29.178326757Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=0 len=257
[2025-04-30T20:08:29.178357505Z TRACE quiche_apps::client] [::]:36395: processed 302 bytes
[2025-04-30T20:08:29.178361582Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.178364007Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.178371291Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.178374727Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=7 
[2025-04-30T20:08:29.178377172Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=6 blocks=[0..1, 6..6] ecn_counts=None
[2025-04-30T20:08:29.178384616Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=991.24779ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 7, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 514202727 }, next_time: Instant { tv_sec: 906, tv_nsec: 514202727 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.178421895Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.178428899Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.178520330Z TRACE quiche_apps::client] got 303 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.178526902Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=282 pn=7 
[2025-04-30T20:08:29.178533083Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm CRYPTO off=257 len=257
[2025-04-30T20:08:29.178551678Z TRACE quiche_apps::client] [::]:36395: processed 303 bytes
[2025-04-30T20:08:29.178555475Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.178563941Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.178571024Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.178574251Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=8 
[2025-04-30T20:08:29.178576665Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=5 blocks=[0..1, 6..7] ecn_counts=None
[2025-04-30T20:08:29.178583758Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=991.048928ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 8, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 514402821 }, next_time: Instant { tv_sec: 906, tv_nsec: 514402821 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.178615658Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.178622381Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.181025512Z TRACE quiche_apps::client] got 67 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181051881Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba dropped invalid packet
[2025-04-30T20:08:29.181056540Z TRACE quiche_apps::client] [::]:36395: processed 67 bytes
[2025-04-30T20:08:29.181062721Z TRACE quiche_apps::client] got 73 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181068482Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=52 pn=8 
[2025-04-30T20:08:29.181084422Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[86, 3e, 07, 1c, fb, 34, 45, 29, bb, 9b, a1, 44] reset_token=[41, 7c, 85, 47, 2b, 4b, b5, b5, 1a, de, 04, 51, 0a, d8, 55, 8b]
[2025-04-30T20:08:29.181104760Z TRACE quiche_apps::client] [::]:36395: processed 73 bytes
[2025-04-30T20:08:29.181109729Z TRACE quiche_apps::client] got 73 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181112685Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=52 pn=9 
[2025-04-30T20:08:29.181118215Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[17, 42, 00, 00, 34, 8b, aa, a5, 4c, cc, 0a, ff] reset_token=[00, 92, 7a, fa, c2, e0, 63, ea, a0, 20, 5e, 22, 9d, e8, 58, 62]
[2025-04-30T20:08:29.181124577Z TRACE quiche_apps::client] [::]:36395: processed 73 bytes
[2025-04-30T20:08:29.181129496Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181132381Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=10 
[2025-04-30T20:08:29.181137862Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=0 off=0 len=1171 fin=false
[2025-04-30T20:08:29.181151507Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.181156356Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181159232Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=11 
[2025-04-30T20:08:29.181163399Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=0 off=1171 len=1169 fin=false
[2025-04-30T20:08:29.181195189Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.181199838Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.181202483Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.181209937Z TRACE quiche_apps::common] received 2340 bytes
[2025-04-30T20:08:29.181212822Z TRACE quiche_apps::common] stream 0 has 2340 bytes (fin? false)
[2025-04-30T20:08:29.181223702Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.181229122Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=9 
[2025-04-30T20:08:29.181232168Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=7 blocks=[0..1, 6..11] ecn_counts=None
[2025-04-30T20:08:29.181242387Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=988.389948ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 9, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 517052944 }, next_time: Instant { tv_sec: 906, tv_nsec: 517052944 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.181302820Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.181310414Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.181884829Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.181891081Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=12 
[2025-04-30T20:08:29.181897804Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=0 off=2340 len=1169 fin=false
[2025-04-30T20:08:29.181904546Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.181907983Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.181910257Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.181914274Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.181916539Z TRACE quiche_apps::common] stream 0 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.181922810Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.181926026Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=10 
[2025-04-30T20:08:29.181933550Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..12] ecn_counts=None
[2025-04-30T20:08:29.181939752Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=987.692954ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 10, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 517754887 }, next_time: Instant { tv_sec: 906, tv_nsec: 517754887 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.181970870Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.181977362Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.182893506Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.182901731Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=13 
[2025-04-30T20:08:29.182908083Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=0 off=3509 len=1169 fin=false
[2025-04-30T20:08:29.182914506Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.182917912Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.182920206Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.182924124Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.182926358Z TRACE quiche_apps::common] stream 0 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.182932529Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.182935745Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=11 
[2025-04-30T20:08:29.182938079Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=3 blocks=[0..1, 6..13] ecn_counts=None
[2025-04-30T20:08:29.182944091Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=986.688715ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 11, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 518764686 }, next_time: Instant { tv_sec: 906, tv_nsec: 518764686 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.182978174Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.182985168Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.183324793Z TRACE quiche_apps::client] got 489 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.183332558Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=468 pn=14 
[2025-04-30T20:08:29.183338629Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=0 off=4678 len=442 fin=true
[2025-04-30T20:08:29.183345251Z TRACE quiche_apps::client] [::]:36395: processed 489 bytes
[2025-04-30T20:08:29.183348678Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.183350902Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.183354779Z TRACE quiche_apps::common] received 442 bytes
[2025-04-30T20:08:29.183357023Z TRACE quiche_apps::common] stream 0 has 442 bytes (fin? true)
[2025-04-30T20:08:29.183359328Z DEBUG quiche_apps::common] 1/2 responses received
[2025-04-30T20:08:29.183365309Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13116 out_len=1350 left=1313
[2025-04-30T20:08:29.183368304Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=12 
[2025-04-30T20:08:29.183370649Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..14] ecn_counts=None
[2025-04-30T20:08:29.183377121Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=986.255625ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=384 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 481085463 }, end_of_app_limited: 4, last_sent_packet: 12, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.183405765Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.183412638Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.184406312Z TRACE quiche_apps::client] got 1221 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.184447268Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1200 pn=15 
[2025-04-30T20:08:29.184466233Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=0 len=1171 fin=false
[2025-04-30T20:08:29.184475671Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm ACK delay=35 blocks=[4..5] ecn_counts=None
[2025-04-30T20:08:29.184483716Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba packet newly acked 4
[2025-04-30T20:08:29.184488034Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba packet newly acked 5
[2025-04-30T20:08:29.184540002Z TRACE quiche_apps::client] [::]:36395: processed 1221 bytes
[2025-04-30T20:08:29.184546363Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.184549930Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.184557264Z TRACE quiche_apps::common] received 1171 bytes
[2025-04-30T20:08:29.184561121Z TRACE quiche_apps::common] stream 4 has 1171 bytes (fin? false)
[2025-04-30T20:08:29.184575157Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.184581900Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=13 
[2025-04-30T20:08:29.184585226Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=16 blocks=[0..1, 6..15] ecn_counts=None
[2025-04-30T20:08:29.184595486Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 13, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.184681817Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.184691986Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.185425674Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.185461410Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=16 
[2025-04-30T20:08:29.185478983Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=1171 len=1169 fin=false
[2025-04-30T20:08:29.185497458Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.185501966Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.185504601Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.185511544Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.185514500Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.185525661Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.185531622Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=14 
[2025-04-30T20:08:29.185534217Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=8 blocks=[0..1, 6..16] ecn_counts=None
[2025-04-30T20:08:29.185544927Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 14, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.185612183Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.185620107Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.186406038Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.186420355Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=17 
[2025-04-30T20:08:29.186428179Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=2340 len=1169 fin=false
[2025-04-30T20:08:29.186437587Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.186441214Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.186443598Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.186448096Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.186450641Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.186458646Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.186462233Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=15 
[2025-04-30T20:08:29.186464758Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..17] ecn_counts=None
[2025-04-30T20:08:29.186472292Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 15, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.186510894Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.186517847Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.187417851Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.187432088Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=18 
[2025-04-30T20:08:29.187439852Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=3509 len=1169 fin=false
[2025-04-30T20:08:29.187448488Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.187452165Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.187454559Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.187458888Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.187461272Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.187469387Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.187472974Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=16 
[2025-04-30T20:08:29.187475429Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..18] ecn_counts=None
[2025-04-30T20:08:29.187486299Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 16, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.187522086Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.187529019Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.188434463Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.188447748Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=19 
[2025-04-30T20:08:29.188455672Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=4678 len=1169 fin=false
[2025-04-30T20:08:29.188464729Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.188468246Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.188470540Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.188474808Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.188477924Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.188485789Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.188489185Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=17 
[2025-04-30T20:08:29.188499324Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..19] ecn_counts=None
[2025-04-30T20:08:29.188519001Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 17, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.188554597Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.188561590Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.189436728Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.189448530Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=20 
[2025-04-30T20:08:29.189455814Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=5847 len=1169 fin=false
[2025-04-30T20:08:29.189464229Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.189467756Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.189470080Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.189474458Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.189476883Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.189483936Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.189487202Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=18 
[2025-04-30T20:08:29.189489607Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..20] ecn_counts=None
[2025-04-30T20:08:29.189496740Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 18, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.189536705Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.189544159Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.190457718Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.190470412Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=21 
[2025-04-30T20:08:29.190477575Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=7016 len=1169 fin=false
[2025-04-30T20:08:29.190485871Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.190489317Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.190491792Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.190496150Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.190498444Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.190505778Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.190509114Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=19 
[2025-04-30T20:08:29.190511519Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=4 blocks=[0..1, 6..21] ecn_counts=None
[2025-04-30T20:08:29.190518161Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 19, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.190551764Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.190558757Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.191467798Z TRACE quiche_apps::client] got 1216 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.191482335Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=1195 pn=22 
[2025-04-30T20:08:29.191489799Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=8185 len=1169 fin=false
[2025-04-30T20:08:29.191497974Z TRACE quiche_apps::client] [::]:36395: processed 1216 bytes
[2025-04-30T20:08:29.191501531Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.191509797Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.191514385Z TRACE quiche_apps::common] received 1169 bytes
[2025-04-30T20:08:29.191516689Z TRACE quiche_apps::common] stream 4 has 1169 bytes (fin? false)
[2025-04-30T20:08:29.191542838Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1313
[2025-04-30T20:08:29.191546595Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=7 pn=20 
[2025-04-30T20:08:29.191549030Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm ACK delay=7 blocks=[0..1, 6..22] ecn_counts=None
[2025-04-30T20:08:29.191556674Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=none latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 12, last_sent_packet: 20, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 519197666 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.191591319Z TRACE quiche_apps::client] written 37 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.191598272Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.192250452Z TRACE quiche_apps::client] got 933 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.192263126Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx pkt Short dcid=0c219abf9a8488479a9768cf80a1f6bed7b45cba key_phase=false len=912 pn=23 
[2025-04-30T20:08:29.192269738Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba rx frm STREAM id=4 off=9354 len=886 fin=true
[2025-04-30T20:08:29.192278034Z TRACE quiche_apps::client] [::]:36395: processed 933 bytes
[2025-04-30T20:08:29.192281560Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.192283845Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.192289826Z TRACE quiche_apps::common] received 886 bytes
[2025-04-30T20:08:29.192292120Z TRACE quiche_apps::common] stream 4 has 886 bytes (fin? true)
[2025-04-30T20:08:29.192294565Z DEBUG quiche_apps::common] 2/2 responses received
[2025-04-30T20:08:29.192297069Z INFO  quiche_apps::common] 2/2 response(s) received in 89.368377ms, closing...
[2025-04-30T20:08:29.192303792Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1320
[2025-04-30T20:08:29.192307489Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx pkt Short dcid=ab42bb50e72a1c6326561b37 key_phase=false len=10 pn=21 
[2025-04-30T20:08:29.192309963Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65]
[2025-04-30T20:08:29.192318690Z TRACE quiche::recovery::congestion::recovery] 0c219abf9a8488479a9768cf80a1f6bed7b45cba timer=141.404991ms latest_rtt=38.807609ms srtt=38.807609ms min_rtt=38.807609ms rttvar=19.403804ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=40 app_limited=true congestion_recovery_start_time=None Rate { delivered: 384, delivered_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, first_sent_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, end_of_app_limited: 20, last_sent_packet: 21, largest_acked: 5, rate_sample: RateSample { delivery_rate: 9798, is_app_limited: true, interval: 39.190175ms, delivered: 384, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 906, tv_nsec: 481085463 }), send_elapsed: 0ns, ack_elapsed: 39.190175ms, rtt: 39.190175ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434837, last_update: Instant { tv_sec: 906, tv_nsec: 528136169 }, next_time: Instant { tv_sec: 906, tv_nsec: 519197666 }, max_datagram_size: 1350, last_packet_size: None, iv: 91.988µs, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } 
[2025-04-30T20:08:29.192360257Z TRACE quiche_apps::client] written 40 bytes from [::]:36395 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T20:08:29.192366539Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.223806316Z TRACE quiche_apps::client] got 45 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:36395
[2025-04-30T20:08:29.223839719Z TRACE quiche_apps::client] [::]:36395: processed 45 bytes
[2025-04-30T20:08:29.223844578Z TRACE quiche_apps::client] [::]:36395: recv() would block
[2025-04-30T20:08:29.223847213Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.223854015Z TRACE quiche_apps::client] [::]:36395 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T20:08:29.542241254Z TRACE quiche_apps::client] timed out
[2025-04-30T20:08:29.542275057Z TRACE quiche] 0c219abf9a8488479a9768cf80a1f6bed7b45cba draining timeout expired
[2025-04-30T20:08:29.542321775Z TRACE quiche_apps::client] done reading
[2025-04-30T20:08:29.542326313Z INFO  quiche_apps::client] connection closed, recv=25 sent=22 lost=0 retrans=0 sent_bytes=1540 recv_bytes=19068 lost_bytes=0 [local_addr=[::]:36395 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=25 sent=22 lost=0 retrans=0 rtt=38.807609ms min_rtt=Some(38.807609ms) rttvar=19.403804ms cwnd=13500 sent_bytes=1540 recv_bytes=19068 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=9798]