[2025-04-30T21:50:17.165419571Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T21:50:17.165700523Z INFO quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:55982 with scid c21caf6c5ecf4bcde3c44187a0106749df7257a3 [2025-04-30T21:50:17.165741339Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 write message lvl=Initial len=266 [2025-04-30T21:50:17.165760264Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Initial version=1 dcid=28fcc4e2255e12846d52504cf086a49d scid=c21caf6c5ecf4bcde3c44187a0106749df7257a3 len=270 pn=0 [2025-04-30T21:50:17.165763530Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm CRYPTO off=0 len=266 [2025-04-30T21:50:17.165776935Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=998.930932ms 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: 748, tv_nsec: 205391276 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 205391276 }, 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: 748, tv_nsec: 205391276 }, next_time: Instant { tv_sec: 748, tv_nsec: 205391276 }, 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-30T21:50:17.165821668Z TRACE quiche_apps::client] written 1200 [2025-04-30T21:50:17.207524990Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.207542232Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Initial version=1 dcid=c21caf6c5ecf4bcde3c44187a0106749df7257a3 scid=f5cb10b5cbf9f13ff0449c6ef5ca288f token= len=117 pn=0 [2025-04-30T21:50:17.207554925Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm ACK delay=1455 blocks=[0..0] ecn_counts=None [2025-04-30T21:50:17.207560686Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 0 [2025-04-30T21:50:17.207569823Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm CRYPTO off=0 len=90 [2025-04-30T21:50:17.207669999Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 set write secret lvl=Handshake [2025-04-30T21:50:17.207680358Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 set read secret lvl=Handshake [2025-04-30T21:50:17.207709262Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Handshake version=1 dcid=c21caf6c5ecf4bcde3c44187a0106749df7257a3 scid=f5cb10b5cbf9f13ff0449c6ef5ca288f len=1024 pn=0 [2025-04-30T21:50:17.207716375Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm CRYPTO off=0 len=692 [2025-04-30T21:50:17.207931725Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 write message lvl=Handshake len=36 [2025-04-30T21:50:17.207936304Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 set write secret lvl=OneRTT [2025-04-30T21:50:17.207944589Z TRACE quiche::tls] c21caf6c5ecf4bcde3c44187a0106749df7257a3 set read secret lvl=OneRTT [2025-04-30T21:50:17.207962332Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 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(28fcc4e2255e12846d52504cf086a49d), max_idle_timeout: 300000, stateless_reset_token: None, max_udp_payload_size: 65527, initial_max_data: 3750000, initial_max_stream_data_bidi_local: 3750000, initial_max_stream_data_bidi_remote: 3750000, initial_max_stream_data_uni: 3750000, initial_max_streams_bidi: 100, initial_max_streams_uni: 100, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 3, initial_source_connection_id: Some(f5cb10b5cbf9f13ff0449c6ef5ca288f), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T21:50:17.207983060Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm PADDING len=311 [2025-04-30T21:50:17.207998700Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.208004360Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.208007386Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.208016302Z DEBUG quiche_apps::common] sending HTTP request "GET /zuzkbbwufl\r\n" [2025-04-30T21:50:17.208065203Z DEBUG quiche_apps::common] sending HTTP request "GET /zwbxlfiejt\r\n" [2025-04-30T21:50:17.208112320Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Initial version=1 dcid=f5cb10b5cbf9f13ff0449c6ef5ca288f scid=c21caf6c5ecf4bcde3c44187a0106749df7257a3 len=6 pn=1 [2025-04-30T21:50:17.208116619Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=71 blocks=[0..0] ecn_counts=None [2025-04-30T21:50:17.208126417Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=124.904244ms latest_rtt=41.830659ms srtt=41.830659ms min_rtt=41.830659ms rttvar=20.915329ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7960, is_app_limited: true, interval: 41.830659ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 205391276 }), send_elapsed: 0ns, ack_elapsed: 41.830659ms, rtt: 41.830659ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 403412, last_update: Instant { tv_sec: 748, tv_nsec: 247643127 }, next_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, 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-30T21:50:17.208147676Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Handshake version=1 dcid=f5cb10b5cbf9f13ff0449c6ef5ca288f scid=c21caf6c5ecf4bcde3c44187a0106749df7257a3 len=45 pn=2 [2025-04-30T21:50:17.208151123Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=54 blocks=[0..0] ecn_counts=None [2025-04-30T21:50:17.208154369Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm CRYPTO off=0 len=36 [2025-04-30T21:50:17.208161302Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=125.433436ms latest_rtt=41.830659ms srtt=41.830659ms min_rtt=41.830659ms rttvar=20.915329ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=107 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7960, is_app_limited: true, interval: 41.830659ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 205391276 }), send_elapsed: 0ns, ack_elapsed: 41.830659ms, rtt: 41.830659ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 403412, last_update: Instant { tv_sec: 748, tv_nsec: 247785812 }, next_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, max_datagram_size: 1350, last_packet_size: None, iv: 265.238µ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-30T21:50:17.208179896Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 dropped epoch 0 state [2025-04-30T21:50:17.208185146Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13393 out_len=1174 left=1140 [2025-04-30T21:50:17.208198471Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=f5cb10b5cbf9f13ff0449c6ef5ca288f key_phase=false len=1140 pn=3 [2025-04-30T21:50:17.208201666Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[bf, 5b, 7c, 41, 2a, e9, ba, b5, 9b, 37, 65, 5c, 21, 4a, 91, 9b, 9e, 4f, 3a, 07] reset_token=[6c, 9f, 88, c7, 7d, 58, cd, 72, ca, df, 1b, 60, b7, 19, 96, fd] [2025-04-30T21:50:17.208209641Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[cf, 37, 51, ac, fe, 2c, 19, 2e, 79, 70, ca, 0c, 18, 63, 31, 14, ab, e8, eb, f7] reset_token=[68, 99, 50, 88, 4f, 76, a8, a5, 77, 6f, 5f, 7f, c8, d2, 13, 4d] [2025-04-30T21:50:17.208216083Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T21:50:17.208219219Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm PADDING len=1038 [2025-04-30T21:50:17.208227494Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=125.367224ms latest_rtt=41.830659ms srtt=41.830659ms min_rtt=41.830659ms rttvar=20.915329ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1281 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7960, is_app_limited: true, interval: 41.830659ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 205391276 }), send_elapsed: 0ns, ack_elapsed: 41.830659ms, rtt: 41.830659ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1174, rate: 403412, last_update: Instant { tv_sec: 748, tv_nsec: 247785812 }, next_time: Instant { tv_sec: 748, tv_nsec: 248051050 }, max_datagram_size: 1350, last_packet_size: Some(1174), 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-30T21:50:17.208267048Z TRACE quiche_apps::client] written 1350 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.208274361Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12219 out_len=1350 left=1316 [2025-04-30T21:50:17.208281204Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=f5cb10b5cbf9f13ff0449c6ef5ca288f key_phase=false len=22 pn=4 [2025-04-30T21:50:17.208286544Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm STREAM id=4 off=0 len=17 fin=true [2025-04-30T21:50:17.208297104Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=125.297294ms latest_rtt=41.830659ms srtt=41.830659ms min_rtt=41.830659ms rttvar=20.915329ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1337 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7960, is_app_limited: true, interval: 41.830659ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 205391276 }), send_elapsed: 0ns, ack_elapsed: 41.830659ms, rtt: 41.830659ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 403412, last_update: Instant { tv_sec: 748, tv_nsec: 247954665 }, next_time: Instant { tv_sec: 748, tv_nsec: 248051050 }, max_datagram_size: 1350, last_packet_size: None, iv: 3.048992ms, 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-30T21:50:17.208374928Z TRACE quiche_apps::client] written 56 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.208390818Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.243084923Z TRACE quiche_apps::client] got 1452 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.243105802Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1431 pn=0 [2025-04-30T21:50:17.243114869Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 path ID 0 now see SCID with seq num 1 [2025-04-30T21:50:17.243119808Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm PING mtu_probe=None [2025-04-30T21:50:17.243129937Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm PADDING len=1413 [2025-04-30T21:50:17.243140376Z TRACE quiche_apps::client] [::]:55982: processed 1452 bytes [2025-04-30T21:50:17.243145335Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.243148581Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.243160604Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12163 out_len=1350 left=1311 [2025-04-30T21:50:17.243169189Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=f5cb10b5cbf9f13ff0449c6ef5ca288f key_phase=false len=5 pn=5 [2025-04-30T21:50:17.243175201Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=6 blocks=[0..0] ecn_counts=None [2025-04-30T21:50:17.243193725Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=90.397276ms latest_rtt=41.830659ms srtt=41.830659ms min_rtt=41.830659ms rttvar=20.915329ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1337 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 247643167 }, end_of_app_limited: 3, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7960, is_app_limited: true, interval: 41.830659ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 205391276 }), send_elapsed: 0ns, ack_elapsed: 41.830659ms, rtt: 41.830659ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 403412, last_update: Instant { tv_sec: 748, tv_nsec: 282836139 }, next_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, 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-30T21:50:17.243253566Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.243261341Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.243282690Z TRACE quiche_apps::client] got 155 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.243290895Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=134 pn=1 [2025-04-30T21:50:17.243302657Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm ACK delay=194 blocks=[3..4] ecn_counts=None [2025-04-30T21:50:17.243309540Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 3 [2025-04-30T21:50:17.243314760Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 4 [2025-04-30T21:50:17.243349474Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.243363020Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 dropped epoch 1 state [2025-04-30T21:50:17.243372347Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=1 conn_id=[ed, 01, d0, 18, f0, 9c, 48, d9, 9c, 2e, 0b, 62, f2, 57, a6, b8] reset_token=[6a, cb, d5, 79, 5f, 08, fa, 00, a8, ac, f3, f5, 20, 01, 34, cf] [2025-04-30T21:50:17.243384509Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 path ID 0 changed DCID: old seq num 0 new seq num 1 [2025-04-30T21:50:17.243389719Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=1 conn_id=[ec, 17, 34, 96, 15, 78, 6d, e2, d4, d3, 94, 2c, d6, 73, b4, 6e] reset_token=[0e, 63, 15, 23, b9, 91, 46, c5, 19, 88, 4d, 81, 06, af, d4, e9] [2025-04-30T21:50:17.243397423Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=1 conn_id=[43, e6, 19, 75, 6a, 35, 7b, 41, 70, 04, 07, 3d, 6a, 52, 97, 78] reset_token=[b7, cb, a3, c6, 20, 56, 66, 11, fb, 4f, e2, 1a, 74, 98, ee, 4a] [2025-04-30T21:50:17.243402573Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm RETIRE_CONNECTION_ID seq_num=0 [2025-04-30T21:50:17.243420196Z TRACE quiche_apps::client] [::]:55982: processed 155 bytes [2025-04-30T21:50:17.243425936Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.243429032Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.243432368Z INFO quiche_apps::client] Retiring source CID c21caf6c5ecf4bcde3c44187a0106749df7257a3 [2025-04-30T21:50:17.243445663Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1311 [2025-04-30T21:50:17.243451865Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=47 pn=6 [2025-04-30T21:50:17.243455291Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=19 blocks=[0..1] ecn_counts=None [2025-04-30T21:50:17.243459359Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=1 conn_id=[8e, b7, 26, e2, bc, 68, 4d, 18, e6, 37, 6d, a4, 4a, 45, fb, fe, ab, cb, 42, 82] reset_token=[3e, 57, 43, 7c, ae, 58, 9d, fd, 9b, 71, f6, 52, 97, b8, e7, 43] [2025-04-30T21:50:17.243466111Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm RETIRE_CONNECTION_ID seq_num=0 [2025-04-30T21:50:17.243475358Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=135.588162ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, max_datagram_size: 1350, last_packet_size: None, iv: 196.642µ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-30T21:50:17.243523367Z TRACE quiche_apps::client] written 81 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.243529248Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.244375510Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.244386049Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=2 [2025-04-30T21:50:17.244392241Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.244395888Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=0 len=1191 fin=false [2025-04-30T21:50:17.244404103Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.244407600Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.244409894Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.244431604Z TRACE quiche_apps::common] received 1191 bytes [2025-04-30T21:50:17.244434159Z TRACE quiche_apps::common] stream 4 has 1191 bytes (fin? false) [2025-04-30T21:50:17.244441683Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.244444999Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=7 [2025-04-30T21:50:17.244447374Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=7 blocks=[0..2] ecn_counts=None [2025-04-30T21:50:17.244454276Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=134.609354ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.244483450Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.244487328Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.245399021Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.245409410Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=3 [2025-04-30T21:50:17.245420641Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.245424168Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=1191 len=1189 fin=false [2025-04-30T21:50:17.245431942Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.245435529Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.245437813Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.245441971Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.245444195Z TRACE quiche_apps::common] stream 4 has 1189 bytes (fin? false) [2025-04-30T21:50:17.245451058Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.245454304Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=8 [2025-04-30T21:50:17.245456688Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=5 blocks=[0..3] ecn_counts=None [2025-04-30T21:50:17.245462880Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=133.600821ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 8, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.245491222Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.245495079Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.246424425Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.246434714Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=4 [2025-04-30T21:50:17.246440705Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.246444112Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=2380 len=1189 fin=false [2025-04-30T21:50:17.246451476Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.246454972Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.246457236Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.246461464Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.246463678Z TRACE quiche_apps::common] stream 4 has 1189 bytes (fin? false) [2025-04-30T21:50:17.246470311Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.246473366Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=9 [2025-04-30T21:50:17.246480890Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[0..4] ecn_counts=None [2025-04-30T21:50:17.246487973Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=132.575687ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 9, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.246516396Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.246520193Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.246923352Z TRACE quiche_apps::client] got 572 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.246930976Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=551 pn=5 [2025-04-30T21:50:17.246936557Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.246939512Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=3569 len=527 fin=false [2025-04-30T21:50:17.246946966Z TRACE quiche_apps::client] [::]:55982: processed 572 bytes [2025-04-30T21:50:17.246950352Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.246952606Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.246956634Z TRACE quiche_apps::common] received 527 bytes [2025-04-30T21:50:17.246958838Z TRACE quiche_apps::common] stream 4 has 527 bytes (fin? false) [2025-04-30T21:50:17.246965700Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.246968897Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=10 [2025-04-30T21:50:17.246971281Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[0..5] ecn_counts=None [2025-04-30T21:50:17.246977202Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=132.086508ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 10, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.247010023Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.247013950Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.247948957Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.247959236Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=6 [2025-04-30T21:50:17.247965097Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.247968473Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=4096 len=1189 fin=false [2025-04-30T21:50:17.247975997Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.247979463Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.247981798Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.247985845Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.247988049Z TRACE quiche_apps::common] stream 4 has 1189 bytes (fin? false) [2025-04-30T21:50:17.247994892Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.247998008Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=11 [2025-04-30T21:50:17.248000372Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[0..6] ecn_counts=None [2025-04-30T21:50:17.248006504Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=131.057217ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 11, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.248034145Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.248037842Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.248974041Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.248984129Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=7 [2025-04-30T21:50:17.248989950Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.248998315Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=5285 len=1189 fin=false [2025-04-30T21:50:17.249005910Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.249009366Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.249011660Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.249015718Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.249017912Z TRACE quiche_apps::common] stream 4 has 1189 bytes (fin? false) [2025-04-30T21:50:17.249024715Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.249027830Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=12 [2025-04-30T21:50:17.249030205Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=5 blocks=[0..7] ecn_counts=None [2025-04-30T21:50:17.249036296Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=130.027434ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 12, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.249064198Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.249067875Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.249999345Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.250009965Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=8 [2025-04-30T21:50:17.250015905Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.250019282Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=6474 len=1189 fin=false [2025-04-30T21:50:17.250026746Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.250030192Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.250032486Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.250036574Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.250038778Z TRACE quiche_apps::common] stream 4 has 1189 bytes (fin? false) [2025-04-30T21:50:17.250055379Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.250058605Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=13 [2025-04-30T21:50:17.250060979Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=5 blocks=[0..8] ecn_counts=None [2025-04-30T21:50:17.250072721Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=128.990969ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 13, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.250101194Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.250105101Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.250498762Z TRACE quiche_apps::client] got 574 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.250508911Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=553 pn=9 [2025-04-30T21:50:17.250514942Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.250517858Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=7663 len=529 fin=false [2025-04-30T21:50:17.250525121Z TRACE quiche_apps::client] [::]:55982: processed 574 bytes [2025-04-30T21:50:17.250528568Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.250530832Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.250534689Z TRACE quiche_apps::common] received 529 bytes [2025-04-30T21:50:17.250536883Z TRACE quiche_apps::common] stream 4 has 529 bytes (fin? false) [2025-04-30T21:50:17.250543826Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.250546982Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=14 [2025-04-30T21:50:17.250549326Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[0..9] ecn_counts=None [2025-04-30T21:50:17.250555317Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=128.508413ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 14, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.250587908Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.250592627Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.251524297Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.251534736Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=10 [2025-04-30T21:50:17.251540677Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.251543974Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=0 off=0 len=1191 fin=false [2025-04-30T21:50:17.251551437Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.251554834Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.251557128Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.251561226Z TRACE quiche_apps::common] received 1191 bytes [2025-04-30T21:50:17.251563460Z TRACE quiche_apps::common] stream 0 has 1191 bytes (fin? false) [2025-04-30T21:50:17.251570042Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.251573228Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=15 [2025-04-30T21:50:17.251575612Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[0..10] ecn_counts=None [2025-04-30T21:50:17.251581713Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=127.481997ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 15, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.251609435Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.251613172Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.252550723Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.252561063Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1211 pn=11 [2025-04-30T21:50:17.252567084Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm HANDSHAKE_DONE [2025-04-30T21:50:17.252570450Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=0 off=1191 len=1189 fin=false [2025-04-30T21:50:17.252583394Z TRACE quiche_apps::client] [::]:55982: processed 1232 bytes [2025-04-30T21:50:17.252587081Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.252589405Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.252593443Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:50:17.252595697Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:50:17.252602810Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:50:17.252606036Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=5 pn=16 [2025-04-30T21:50:17.252608460Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=5 blocks=[0..11] ecn_counts=None [2025-04-30T21:50:17.252614692Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=126.448938ms latest_rtt=34.92071ms srtt=40.966914ms min_rtt=34.92071ms rttvar=17.413983ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1563, delivered_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 285885131 }, end_of_app_limited: 5, last_sent_packet: 16, largest_acked: 4, rate_sample: RateSample { delivery_rate: 34815, is_app_limited: true, interval: 35.328593ms, delivered: 1230, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 247643167 }), send_elapsed: 407.883µs, ack_elapsed: 35.328593ms, rtt: 34.92071ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411917, last_update: Instant { tv_sec: 748, tv_nsec: 283123913 }, next_time: Instant { tv_sec: 748, tv_nsec: 286081773 }, 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-30T21:50:17.252643175Z TRACE quiche_apps::client] written 39 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.252646772Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.276888722Z TRACE quiche_apps::client] got 1452 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.276904061Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1431 pn=13 [2025-04-30T21:50:17.276912296Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm ACK delay=28 blocks=[5..7] ecn_counts=None [2025-04-30T21:50:17.276916865Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 5 [2025-04-30T21:50:17.276920091Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 6 [2025-04-30T21:50:17.276923026Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 7 [2025-04-30T21:50:17.276928216Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=8192 len=1405 fin=false [2025-04-30T21:50:17.276940168Z TRACE quiche_apps::client] [::]:55982: processed 1452 bytes [2025-04-30T21:50:17.276944586Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.276947482Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.276952581Z TRACE quiche_apps::common] received 1405 bytes [2025-04-30T21:50:17.276955396Z TRACE quiche_apps::common] stream 4 has 1405 bytes (fin? false) [2025-04-30T21:50:17.276983509Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1309 [2025-04-30T21:50:17.276991313Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=7 pn=17 [2025-04-30T21:50:17.276994489Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=9 blocks=[3..11, 13..13] ecn_counts=None [2025-04-30T21:50:17.277002283Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=none latest_rtt=30.503293ms srtt=39.65896ms min_rtt=30.503293ms rttvar=15.676392ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1644, delivered_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, end_of_app_limited: 16, last_sent_packet: 17, largest_acked: 7, rate_sample: RateSample { delivery_rate: 2638, is_app_limited: true, interval: 30.699935ms, delivered: 81, prior_delivered: 1563, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 285885131 }), send_elapsed: 0ns, ack_elapsed: 30.699935ms, rtt: 30.699935ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 425502, last_update: Instant { tv_sec: 748, tv_nsec: 316661628 }, next_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, 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-30T21:50:17.277039903Z TRACE quiche_apps::client] written 41 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.277044672Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.278067923Z TRACE quiche_apps::client] got 1452 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.278078302Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1431 pn=14 [2025-04-30T21:50:17.278085215Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=0 off=2380 len=1410 fin=false [2025-04-30T21:50:17.278092598Z TRACE quiche_apps::client] [::]:55982: processed 1452 bytes [2025-04-30T21:50:17.278096105Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.278098379Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.278102617Z TRACE quiche_apps::common] received 1410 bytes [2025-04-30T21:50:17.278104851Z TRACE quiche_apps::common] stream 0 has 1410 bytes (fin? false) [2025-04-30T21:50:17.278111634Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1309 [2025-04-30T21:50:17.278114779Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=7 pn=18 [2025-04-30T21:50:17.278117174Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=4 blocks=[3..11, 13..14] ecn_counts=None [2025-04-30T21:50:17.278123456Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=none latest_rtt=30.503293ms srtt=39.65896ms min_rtt=30.503293ms rttvar=15.676392ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1644, delivered_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, end_of_app_limited: 16, last_sent_packet: 18, largest_acked: 7, rate_sample: RateSample { delivery_rate: 2638, is_app_limited: true, interval: 30.699935ms, delivered: 81, prior_delivered: 1563, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 285885131 }), send_elapsed: 0ns, ack_elapsed: 30.699935ms, rtt: 30.699935ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 425502, last_update: Instant { tv_sec: 748, tv_nsec: 316661628 }, next_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, 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-30T21:50:17.278156557Z TRACE quiche_apps::client] written 41 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.278160324Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.279267991Z TRACE quiche_apps::client] got 1452 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.279278360Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=1431 pn=15 [2025-04-30T21:50:17.279284692Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm ACK delay=28 blocks=[5..8] ecn_counts=None [2025-04-30T21:50:17.279288149Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 8 [2025-04-30T21:50:17.279291665Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=4 off=9597 len=643 fin=true [2025-04-30T21:50:17.279295282Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=0 off=3790 len=756 fin=false [2025-04-30T21:50:17.279303137Z TRACE quiche_apps::client] [::]:55982: processed 1452 bytes [2025-04-30T21:50:17.279306673Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.279308988Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.279346217Z TRACE quiche_apps::common] received 643 bytes [2025-04-30T21:50:17.279349212Z TRACE quiche_apps::common] stream 4 has 643 bytes (fin? true) [2025-04-30T21:50:17.279351687Z DEBUG quiche_apps::common] 1/2 responses received [2025-04-30T21:50:17.279355514Z TRACE quiche_apps::common] received 756 bytes [2025-04-30T21:50:17.279357698Z TRACE quiche_apps::common] stream 0 has 756 bytes (fin? false) [2025-04-30T21:50:17.279365252Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1309 [2025-04-30T21:50:17.279368478Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=7 pn=19 [2025-04-30T21:50:17.279370852Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm ACK delay=10 blocks=[4..11, 13..15] ecn_counts=None [2025-04-30T21:50:17.279377304Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=none latest_rtt=30.503293ms srtt=39.65896ms min_rtt=30.503293ms rttvar=15.676392ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1644, delivered_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, end_of_app_limited: 18, last_sent_packet: 19, largest_acked: 8, rate_sample: RateSample { delivery_rate: 2638, is_app_limited: true, interval: 30.699935ms, delivered: 81, prior_delivered: 1563, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 285885131 }), send_elapsed: 0ns, ack_elapsed: 30.699935ms, rtt: 30.699935ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 425502, last_update: Instant { tv_sec: 748, tv_nsec: 316661628 }, next_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, 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-30T21:50:17.279405577Z TRACE quiche_apps::client] written 41 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.279413401Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.279805159Z TRACE quiche_apps::client] got 623 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.279815669Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx pkt Short dcid=bf5b7c412ae9bab59b37655c214a919b9e4f3a07 key_phase=false len=602 pn=16 [2025-04-30T21:50:17.279829344Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm ACK delay=41 blocks=[5..10] ecn_counts=None [2025-04-30T21:50:17.279832770Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 9 [2025-04-30T21:50:17.279835195Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 packet newly acked 10 [2025-04-30T21:50:17.279838792Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 rx frm STREAM id=0 off=4546 len=574 fin=true [2025-04-30T21:50:17.279846836Z TRACE quiche_apps::client] [::]:55982: processed 623 bytes [2025-04-30T21:50:17.279850343Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.279852597Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.279857115Z TRACE quiche_apps::common] received 574 bytes [2025-04-30T21:50:17.279859350Z TRACE quiche_apps::common] stream 0 has 574 bytes (fin? true) [2025-04-30T21:50:17.279861634Z DEBUG quiche_apps::common] 2/2 responses received [2025-04-30T21:50:17.279863928Z INFO quiche_apps::common] 2/2 response(s) received in 114.038864ms, closing... [2025-04-30T21:50:17.279870530Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1316 [2025-04-30T21:50:17.279873716Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx pkt Short dcid=ed01d018f09c48d99c2e0b62f257a6b8 key_phase=false len=10 pn=20 [2025-04-30T21:50:17.279876111Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T21:50:17.279882833Z TRACE quiche::recovery::congestion::recovery] c21caf6c5ecf4bcde3c44187a0106749df7257a3 timer=127.34937ms latest_rtt=30.503293ms srtt=39.65896ms min_rtt=30.503293ms rttvar=15.676392ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=44 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1644, delivered_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, first_sent_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, end_of_app_limited: 19, last_sent_packet: 20, largest_acked: 10, rate_sample: RateSample { delivery_rate: 2638, is_app_limited: true, interval: 30.699935ms, delivered: 81, prior_delivered: 1563, prior_time: Some(Instant { tv_sec: 748, tv_nsec: 285885131 }), send_elapsed: 0ns, ack_elapsed: 30.699935ms, rtt: 30.699935ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 425502, last_update: Instant { tv_sec: 748, tv_nsec: 319550704 }, next_time: Instant { tv_sec: 748, tv_nsec: 316661628 }, max_datagram_size: 1350, last_packet_size: None, iv: 103.407µ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-30T21:50:17.279911316Z TRACE quiche_apps::client] written 44 bytes from [::]:55982 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T21:50:17.279914813Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.310589493Z TRACE quiche_apps::client] got 57 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:55982 [2025-04-30T21:50:17.310609941Z TRACE quiche_apps::client] [::]:55982: processed 57 bytes [2025-04-30T21:50:17.310613608Z TRACE quiche_apps::client] [::]:55982: recv() would block [2025-04-30T21:50:17.310616012Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.310626552Z TRACE quiche_apps::client] [::]:55982 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T21:50:17.587961938Z TRACE quiche_apps::client] timed out [2025-04-30T21:50:17.587987385Z TRACE quiche] c21caf6c5ecf4bcde3c44187a0106749df7257a3 draining timeout expired [2025-04-30T21:50:17.588027099Z TRACE quiche_apps::client] done reading [2025-04-30T21:50:17.588031988Z INFO quiche_apps::client] connection closed, recv=18 sent=21 lost=0 retrans=0 sent_bytes=2416 recv_bytes=18820 lost_bytes=0 [local_addr=[::]:55982 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=18 sent=21 lost=0 retrans=0 rtt=39.65896ms min_rtt=Some(30.503293ms) rttvar=15.676392ms cwnd=13500 sent_bytes=2416 recv_bytes=18820 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=2638]