[2025-04-30T13:25:10.613306662Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE
[2025-04-30T13:25:10.613607866Z INFO  quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:35449 with scid 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7
[2025-04-30T13:25:10.613648382Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 write message lvl=Initial len=266
[2025-04-30T13:25:10.613665193Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Initial version=1 dcid=832d7793368fd14c8a85d802e169e817 scid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 len=270 pn=0 
[2025-04-30T13:25:10.613668309Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm CRYPTO off=0 len=266
[2025-04-30T13:25:10.613682005Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=998.932734ms 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: 540, tv_nsec: 981655990 }, first_sent_time: Instant { tv_sec: 540, tv_nsec: 981655990 }, 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: 540, tv_nsec: 981655990 }, next_time: Instant { tv_sec: 540, tv_nsec: 981655990 }, 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-30T13:25:10.613726858Z TRACE quiche_apps::client] written 1200
[2025-04-30T13:25:10.653920202Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.653933537Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Initial version=1 dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 scid=0f75107b15857f29 token= len=116 pn=0 
[2025-04-30T13:25:10.653943075Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm ACK delay=0 blocks=[0..0] ecn_counts=None
[2025-04-30T13:25:10.653948044Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 packet newly acked 0
[2025-04-30T13:25:10.653952593Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm CRYPTO off=0 len=90
[2025-04-30T13:25:10.654054263Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 set write secret lvl=Handshake
[2025-04-30T13:25:10.654064312Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 set read secret lvl=Handshake
[2025-04-30T13:25:10.654087024Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Handshake version=1 dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 scid=0f75107b15857f29 len=694 pn=0 
[2025-04-30T13:25:10.654092565Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm CRYPTO off=0 len=673
[2025-04-30T13:25:10.654272321Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 write message lvl=Handshake len=36
[2025-04-30T13:25:10.654276118Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 set write secret lvl=OneRTT
[2025-04-30T13:25:10.654282601Z TRACE quiche::tls] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 set read secret lvl=OneRTT
[2025-04-30T13:25:10.654296517Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 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(832d7793368fd14c8a85d802e169e817), max_idle_timeout: 0, stateless_reset_token: None, max_udp_payload_size: 1472, initial_max_data: 65536, initial_max_stream_data_bidi_local: 65536, initial_max_stream_data_bidi_remote: 65536, initial_max_stream_data_uni: 65536, initial_max_streams_bidi: 100, initial_max_streams_uni: 0, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: true, active_conn_id_limit: 2, initial_source_connection_id: Some(0f75107b15857f29), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None }
[2025-04-30T13:25:10.654321844Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=294 pn=0 
[2025-04-30T13:25:10.654328837Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[ec, 30, eb, 30, 09, ac, a4, 94] reset_token=[6d, 02, ad, 7b, 87, b2, 9a, 51, 35, e4, 51, 2a, 04, 7a, 43, 25]
[2025-04-30T13:25:10.654335750Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[44, e3, c0, 03, 11, 2f, d7, 63] reset_token=[ed, 11, 34, db, 15, a6, 81, 47, 48, e3, 26, f4, 2f, 85, cc, 4a]
[2025-04-30T13:25:10.654340830Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[cd, 53, 06, df, f4, 84, 05, d0] reset_token=[40, b1, d0, 53, 5e, 01, 78, 19, 93, 86, 04, 10, cf, 96, 23, b9]
[2025-04-30T13:25:10.654345619Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm PADDING len=193
[2025-04-30T13:25:10.654351730Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.654356199Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.654358613Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.654366177Z DEBUG quiche_apps::common] sending HTTP request "GET /hhiozybfca\r\n"
[2025-04-30T13:25:10.654404419Z DEBUG quiche_apps::common] sending HTTP request "GET /uospxhpuln\r\n"
[2025-04-30T13:25:10.654436899Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Initial version=1 dcid=0f75107b15857f29 scid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 len=5 pn=1 
[2025-04-30T13:25:10.654440266Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=63 blocks=[0..0] ecn_counts=None
[2025-04-30T13:25:10.654447950Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=120.429729ms latest_rtt=40.315653ms srtt=40.315653ms min_rtt=40.315653ms rttvar=20.157826ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8259, is_app_limited: true, interval: 40.315653ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 540, tv_nsec: 981655990 }), send_elapsed: 0ns, ack_elapsed: 40.315653ms, rtt: 40.315653ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418571, last_update: Instant { tv_sec: 541, tv_nsec: 22335464 }, next_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, 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-30T13:25:10.654465724Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Handshake version=1 dcid=0f75107b15857f29 scid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 len=45 pn=2 
[2025-04-30T13:25:10.654468549Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=47 blocks=[0..0] ecn_counts=None
[2025-04-30T13:25:10.654471194Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm CRYPTO off=0 len=36
[2025-04-30T13:25:10.654476945Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=120.899619ms latest_rtt=40.315653ms srtt=40.315653ms min_rtt=40.315653ms rttvar=20.157826ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=99 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8259, is_app_limited: true, interval: 40.315653ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 540, tv_nsec: 981655990 }), send_elapsed: 0ns, ack_elapsed: 40.315653ms, rtt: 40.315653ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418571, last_update: Instant { tv_sec: 541, tv_nsec: 22470387 }, next_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, max_datagram_size: 1350, last_packet_size: None, iv: 236.519µ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-30T13:25:10.654493125Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 dropped epoch 0 state
[2025-04-30T13:25:10.654497443Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13401 out_len=1191 left=1160
[2025-04-30T13:25:10.654508674Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=1165 pn=3 
[2025-04-30T13:25:10.654511149Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=21 blocks=[0..0] ecn_counts=None
[2025-04-30T13:25:10.654513693Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[e2, f5, 07, 60, 2c, 73, d3, cb, 0d, 2a, 54, 62, e0, f6, 28, c7, 69, 6a, 64, af] reset_token=[97, 59, 0c, 22, 09, 94, 1a, 21, 26, 1d, 24, c5, 9c, 54, fe, 9d]
[2025-04-30T13:25:10.654520015Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm STREAM id=0 off=0 len=17 fin=true
[2025-04-30T13:25:10.654522680Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm PADDING len=1098
[2025-04-30T13:25:10.654528942Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=120.847631ms latest_rtt=40.315653ms srtt=40.315653ms min_rtt=40.315653ms rttvar=20.157826ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1290 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8259, is_app_limited: true, interval: 40.315653ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 540, tv_nsec: 981655990 }), send_elapsed: 0ns, ack_elapsed: 40.315653ms, rtt: 40.315653ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1191, rate: 418571, last_update: Instant { tv_sec: 541, tv_nsec: 22470387 }, next_time: Instant { tv_sec: 541, tv_nsec: 22706906 }, max_datagram_size: 1350, last_packet_size: Some(1191), 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-30T13:25:10.654561643Z TRACE quiche_apps::client] written 1350 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.654568095Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12210 out_len=1350 left=1324
[2025-04-30T13:25:10.654572964Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=22 pn=4 
[2025-04-30T13:25:10.654583745Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm STREAM id=4 off=0 len=17 fin=true
[2025-04-30T13:25:10.654593302Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=120.78289ms latest_rtt=40.315653ms srtt=40.315653ms min_rtt=40.315653ms rttvar=20.157826ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1338 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 22335504 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8259, is_app_limited: true, interval: 40.315653ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 540, tv_nsec: 981655990 }), send_elapsed: 0ns, ack_elapsed: 40.315653ms, rtt: 40.315653ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418571, last_update: Instant { tv_sec: 541, tv_nsec: 22606211 }, next_time: Instant { tv_sec: 541, tv_nsec: 22706906 }, max_datagram_size: 1350, last_packet_size: None, iv: 2.960071ms, 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-30T13:25:10.654635341Z TRACE quiche_apps::client] written 48 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.654643707Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.686450280Z TRACE quiche_apps::client] got 44 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.686467613Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=23 pn=1 
[2025-04-30T13:25:10.686476609Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm ACK delay=0 blocks=[3..3] ecn_counts=None
[2025-04-30T13:25:10.686481579Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 packet newly acked 3
[2025-04-30T13:25:10.686486598Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm HANDSHAKE_DONE
[2025-04-30T13:25:10.686491468Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 dropped epoch 1 state
[2025-04-30T13:25:10.686505724Z TRACE quiche_apps::client] [::]:35449: processed 44 bytes
[2025-04-30T13:25:10.686510854Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.686514050Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.686523517Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13452 out_len=1350 left=1319
[2025-04-30T13:25:10.686528236Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=5 
[2025-04-30T13:25:10.686531592Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=7 blocks=[1..1] ecn_counts=None
[2025-04-30T13:25:10.686539738Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=101.266409ms latest_rtt=31.799183ms srtt=39.251093ms min_rtt=31.799183ms rttvar=17.247486ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=48 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1524, delivered_time: Instant { tv_sec: 541, tv_nsec: 54506089 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 22706906 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 3, rate_sample: RateSample { delivery_rate: 37021, is_app_limited: true, interval: 32.170585ms, delivered: 1191, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 429924, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.686590743Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.686596865Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.687523580Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.687537516Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=2 
[2025-04-30T13:25:10.687546272Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm ACK delay=12 blocks=[3..4] ecn_counts=None
[2025-04-30T13:25:10.687550941Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 packet newly acked 4
[2025-04-30T13:25:10.687556752Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=0 off=0 len=1153 fin=false
[2025-04-30T13:25:10.687570818Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.687575807Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.687578923Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.687584724Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T13:25:10.687587820Z TRACE quiche_apps::common] stream 0 has 1153 bytes (fin? false)
[2025-04-30T13:25:10.687596747Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.687601245Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=6 
[2025-04-30T13:25:10.687604612Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=7 blocks=[1..2] ecn_counts=None
[2025-04-30T13:25:10.687612035Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.687651018Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.687656478Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.688501190Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.688511329Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=3 
[2025-04-30T13:25:10.688522971Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=0 len=1158 fin=false
[2025-04-30T13:25:10.688530465Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.688534041Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.688536416Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.688540584Z TRACE quiche_apps::common] received 1158 bytes
[2025-04-30T13:25:10.688542848Z TRACE quiche_apps::common] stream 4 has 1158 bytes (fin? false)
[2025-04-30T13:25:10.688549530Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.688552837Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=7 
[2025-04-30T13:25:10.688555241Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..3] ecn_counts=None
[2025-04-30T13:25:10.688576601Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.688606026Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.688610194Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.689500231Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.689510149Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=4 
[2025-04-30T13:25:10.689516802Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=0 off=1153 len=1156 fin=false
[2025-04-30T13:25:10.689524276Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.689527782Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.689530117Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.689534425Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.689536649Z TRACE quiche_apps::common] stream 0 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.689543051Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.689546347Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=8 
[2025-04-30T13:25:10.689548781Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..4] ecn_counts=None
[2025-04-30T13:25:10.689554903Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 8, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.689588606Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.689592644Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.690499902Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.690509831Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=5 
[2025-04-30T13:25:10.690516564Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=1158 len=1156 fin=false
[2025-04-30T13:25:10.690523917Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.690527444Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.690529748Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.690533916Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.690536170Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.690542602Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.690545728Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=9 
[2025-04-30T13:25:10.690548163Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..5] ecn_counts=None
[2025-04-30T13:25:10.690554655Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 9, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.690587837Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.690591965Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.691499464Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.691509382Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=6 
[2025-04-30T13:25:10.691515704Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=0 off=2309 len=1156 fin=false
[2025-04-30T13:25:10.691522968Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.691526444Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.691528769Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.691533027Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.691535241Z TRACE quiche_apps::common] stream 0 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.691541663Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.691544869Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=10 
[2025-04-30T13:25:10.691547313Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..6] ecn_counts=None
[2025-04-30T13:25:10.691553425Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 10, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.691581237Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.691585124Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.692498935Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.692508774Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=7 
[2025-04-30T13:25:10.692515316Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=2314 len=1156 fin=false
[2025-04-30T13:25:10.692522469Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.692525956Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.692528270Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.692532418Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.692534622Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.692541014Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.692548849Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=11 
[2025-04-30T13:25:10.692551393Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..7] ecn_counts=None
[2025-04-30T13:25:10.692557565Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 11, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.692586669Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.692590667Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.693500059Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.693510028Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=8 
[2025-04-30T13:25:10.693516610Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=0 off=3465 len=1156 fin=false
[2025-04-30T13:25:10.693523864Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.693527301Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.693529625Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.693533803Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.693536067Z TRACE quiche_apps::common] stream 0 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.693542519Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.693545645Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=12 
[2025-04-30T13:25:10.693548049Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..8] ecn_counts=None
[2025-04-30T13:25:10.693554071Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 12, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.693587493Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.693591671Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.694499070Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.694508818Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=9 
[2025-04-30T13:25:10.694515391Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=3470 len=1156 fin=false
[2025-04-30T13:25:10.694522825Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.694526311Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.694528615Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.694532763Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.694534987Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.694541279Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.694544405Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=13 
[2025-04-30T13:25:10.694546850Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..9] ecn_counts=None
[2025-04-30T13:25:10.694553242Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 13, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.694581675Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.694585682Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.695506596Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.695514391Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=10 
[2025-04-30T13:25:10.695520562Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=0 off=4621 len=499 fin=true
[2025-04-30T13:25:10.695529589Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=4626 len=651 fin=false
[2025-04-30T13:25:10.695549096Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.695555648Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.695559395Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.695567260Z TRACE quiche_apps::common] received 499 bytes
[2025-04-30T13:25:10.695570326Z TRACE quiche_apps::common] stream 0 has 499 bytes (fin? true)
[2025-04-30T13:25:10.695572670Z DEBUG quiche_apps::common] 1/2 responses received
[2025-04-30T13:25:10.695575996Z TRACE quiche_apps::common] received 651 bytes
[2025-04-30T13:25:10.695578180Z TRACE quiche_apps::common] stream 4 has 651 bytes (fin? false)
[2025-04-30T13:25:10.695585223Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.695588440Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=14 
[2025-04-30T13:25:10.695590874Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=8 blocks=[1..10] ecn_counts=None
[2025-04-30T13:25:10.695597266Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, end_of_app_limited: 5, last_sent_packet: 14, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 54559529 }, next_time: Instant { tv_sec: 541, tv_nsec: 57519600 }, 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-30T13:25:10.695626140Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.695632342Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.718115086Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.718126848Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=11 
[2025-04-30T13:25:10.718134012Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=5277 len=1156 fin=false
[2025-04-30T13:25:10.718141887Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.718145644Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.718148048Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.718152567Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.718154911Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.718161914Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.718165331Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=15 
[2025-04-30T13:25:10.718173165Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..11] ecn_counts=None
[2025-04-30T13:25:10.718179878Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, end_of_app_limited: 5, last_sent_packet: 15, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 86199229 }, next_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, 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-30T13:25:10.718210235Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.718214372Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.720019612Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.720029741Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=12 
[2025-04-30T13:25:10.720036163Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=6433 len=1156 fin=false
[2025-04-30T13:25:10.720043477Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.720046953Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.720049248Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.720053546Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.720055800Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.720062302Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.720065498Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=16 
[2025-04-30T13:25:10.720067973Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=4 blocks=[1..12] ecn_counts=None
[2025-04-30T13:25:10.720074104Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, end_of_app_limited: 5, last_sent_packet: 16, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 86199229 }, next_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, 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-30T13:25:10.720108178Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.720112446Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.723982893Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.724000105Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=13 
[2025-04-30T13:25:10.724010685Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=7589 len=1156 fin=false
[2025-04-30T13:25:10.724020734Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.724025583Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.724028739Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.724034389Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.724037405Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.724065257Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.724070046Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=17 
[2025-04-30T13:25:10.724073362Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=8 blocks=[1..13] ecn_counts=None
[2025-04-30T13:25:10.724081858Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, end_of_app_limited: 5, last_sent_packet: 17, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 86199229 }, next_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, 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-30T13:25:10.724119509Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.724124959Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.730162513Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.730175798Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=1179 pn=14 
[2025-04-30T13:25:10.730184454Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=8745 len=1156 fin=false
[2025-04-30T13:25:10.730194232Z TRACE quiche_apps::client] [::]:35449: processed 1200 bytes
[2025-04-30T13:25:10.730198941Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.730202127Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.730220170Z TRACE quiche_apps::common] received 1156 bytes
[2025-04-30T13:25:10.730223396Z TRACE quiche_apps::common] stream 4 has 1156 bytes (fin? false)
[2025-04-30T13:25:10.730232233Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319
[2025-04-30T13:25:10.730236511Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=5 pn=18 
[2025-04-30T13:25:10.730239757Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm ACK delay=7 blocks=[1..14] ecn_counts=None
[2025-04-30T13:25:10.730247902Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=none latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, end_of_app_limited: 5, last_sent_packet: 18, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 86199229 }, next_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, 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-30T13:25:10.730285853Z TRACE quiche_apps::client] written 31 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.730291153Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:10.730488022Z TRACE quiche_apps::client] got 383 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:35449
[2025-04-30T13:25:10.730497870Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx pkt Short dcid=5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 key_phase=false len=362 pn=15 
[2025-04-30T13:25:10.730505815Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 rx frm STREAM id=4 off=9901 len=339 fin=true
[2025-04-30T13:25:10.730515563Z TRACE quiche_apps::client] [::]:35449: processed 383 bytes
[2025-04-30T13:25:10.730520232Z TRACE quiche_apps::client] [::]:35449: recv() would block
[2025-04-30T13:25:10.730523348Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:10.730529660Z TRACE quiche_apps::common] received 339 bytes
[2025-04-30T13:25:10.730532716Z TRACE quiche_apps::common] stream 4 has 339 bytes (fin? true)
[2025-04-30T13:25:10.730535912Z DEBUG quiche_apps::common] 2/2 responses received
[2025-04-30T13:25:10.730539148Z INFO  quiche_apps::common] 2/2 response(s) received in 116.808874ms, closing...
[2025-04-30T13:25:10.730547473Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1324
[2025-04-30T13:25:10.730551741Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx pkt Short dcid=0f75107b15857f29 key_phase=false len=10 pn=19 
[2025-04-30T13:25:10.730554977Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65]
[2025-04-30T13:25:10.730563864Z TRACE quiche::recovery::congestion::recovery] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 timer=121.641665ms latest_rtt=32.869397ms srtt=38.44138ms min_rtt=31.799183ms rttvar=14.555038ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=36 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1572, delivered_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, first_sent_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, end_of_app_limited: 18, last_sent_packet: 19, largest_acked: 4, rate_sample: RateSample { delivery_rate: 38513, is_app_limited: true, interval: 32.170585ms, delivered: 1239, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 541, tv_nsec: 22335504 }), send_elapsed: 371.402µs, ack_elapsed: 32.170585ms, rtt: 31.799183ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 438980, last_update: Instant { tv_sec: 541, tv_nsec: 98584998 }, next_time: Instant { tv_sec: 541, tv_nsec: 86199229 }, max_datagram_size: 1350, last_packet_size: None, iv: 82.008µ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-30T13:25:10.730609009Z TRACE quiche_apps::client] written 36 bytes from [::]:35449 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T13:25:10.730614148Z TRACE quiche_apps::client] [::]:35449 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T13:25:11.020955098Z TRACE quiche_apps::client] timed out
[2025-04-30T13:25:11.020986858Z TRACE quiche] 5e83982c73df6c0ecfd5d77caf59ba64f3e872a7 draining timeout expired
[2025-04-30T13:25:11.021019309Z TRACE quiche_apps::client] done reading
[2025-04-30T13:25:11.021023647Z INFO  quiche_apps::client] connection closed, recv=18 sent=20 lost=0 retrans=0 sent_bytes=2201 recv_bytes=17227 lost_bytes=0 [local_addr=[::]:35449 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=18 sent=20 lost=0 retrans=0 rtt=38.44138ms min_rtt=Some(31.799183ms) rttvar=14.555038ms cwnd=13500 sent_bytes=2201 recv_bytes=17227 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=38513]