[2025-04-30T11:57:20.919552726Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T11:57:20.919836428Z INFO quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:41311 with scid 61b4b53db4d208c48a2713107902fb5ff0fb307f [2025-04-30T11:57:20.919875992Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f write message lvl=Initial len=266 [2025-04-30T11:57:20.919895799Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Initial version=1 dcid=890c051be69fda667fbe5f616c3f4bf0 scid=61b4b53db4d208c48a2713107902fb5ff0fb307f len=270 pn=0 [2025-04-30T11:57:20.919898925Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm CRYPTO off=0 len=266 [2025-04-30T11:57:20.919913362Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=998.929578ms 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: 700, tv_nsec: 688498275 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 688498275 }, 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: 700, tv_nsec: 688498275 }, next_time: Instant { tv_sec: 700, tv_nsec: 688498275 }, 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-30T11:57:20.919960701Z TRACE quiche_apps::client] written 1200 [2025-04-30T11:57:20.961847971Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:20.961866545Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Initial version=1 dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f scid=bac549c6608e702e token= len=117 pn=0 [2025-04-30T11:57:20.961879420Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm ACK delay=125 blocks=[0..0] ecn_counts=None [2025-04-30T11:57:20.961885701Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f packet newly acked 0 [2025-04-30T11:57:20.961891953Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm CRYPTO off=0 len=90 [2025-04-30T11:57:20.962000447Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f set write secret lvl=Handshake [2025-04-30T11:57:20.962013491Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f set read secret lvl=Handshake [2025-04-30T11:57:20.962046202Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Handshake version=1 dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f scid=bac549c6608e702e len=1008 pn=0 [2025-04-30T11:57:20.962052905Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm CRYPTO off=0 len=738 [2025-04-30T11:57:20.962277195Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f write message lvl=Handshake len=52 [2025-04-30T11:57:20.962281884Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f set write secret lvl=OneRTT [2025-04-30T11:57:20.962291201Z TRACE quiche::tls] 61b4b53db4d208c48a2713107902fb5ff0fb307f set read secret lvl=OneRTT [2025-04-30T11:57:20.962308103Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f connection established: proto=Ok("hq-interop") cipher=Some(AES256_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(890c051be69fda667fbe5f616c3f4bf0), max_idle_timeout: 30000, stateless_reset_token: Some(43971439071868161377516059129461395020), max_udp_payload_size: 2048, initial_max_data: 1638000, initial_max_stream_data_bidi_local: 16380, initial_max_stream_data_bidi_remote: 1474200, initial_max_stream_data_uni: 16380, initial_max_streams_bidi: 100, initial_max_streams_uni: 3, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: true, active_conn_id_limit: 8, initial_source_connection_id: Some(bac549c6608e702e), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T11:57:20.962326037Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm PADDING len=249 [2025-04-30T11:57:20.962339502Z TRACE quiche_apps::client] [::]:41311: processed 1200 bytes [2025-04-30T11:57:20.962344071Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:20.962369448Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:20.962379898Z DEBUG quiche_apps::common] sending HTTP request "GET /dmgykplhom\r\n" [2025-04-30T11:57:20.962422017Z DEBUG quiche_apps::common] sending HTTP request "GET /hhkixjmeay\r\n" [2025-04-30T11:57:20.962468765Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Initial version=1 dcid=bac549c6608e702e scid=61b4b53db4d208c48a2713107902fb5ff0fb307f len=6 pn=1 [2025-04-30T11:57:20.962472622Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=75 blocks=[0..0] ecn_counts=None [2025-04-30T11:57:20.962481068Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=125.438849ms latest_rtt=42.019177ms srtt=42.019177ms min_rtt=42.019177ms rttvar=21.009588ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7924, is_app_limited: true, interval: 42.019177ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 688498275 }), send_elapsed: 0ns, ack_elapsed: 42.019177ms, rtt: 42.019177ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 401602, last_update: Instant { tv_sec: 700, tv_nsec: 730960773 }, next_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, 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-30T11:57:20.962500594Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Handshake version=1 dcid=bac549c6608e702e scid=61b4b53db4d208c48a2713107902fb5ff0fb307f len=61 pn=2 [2025-04-30T11:57:20.962503450Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=56 blocks=[0..0] ecn_counts=None [2025-04-30T11:57:20.962505994Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm CRYPTO off=0 len=52 [2025-04-30T11:57:20.962511946Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=126.006473ms latest_rtt=42.019177ms srtt=42.019177ms min_rtt=42.019177ms rttvar=21.009588ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=115 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7924, is_app_limited: true, interval: 42.019177ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 688498275 }), send_elapsed: 0ns, ack_elapsed: 42.019177ms, rtt: 42.019177ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 401602, last_update: Instant { tv_sec: 700, tv_nsec: 731115803 }, next_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, max_datagram_size: 1350, last_packet_size: None, iv: 286.353µ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-30T11:57:20.962527334Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f dropped epoch 0 state [2025-04-30T11:57:20.962531632Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13385 out_len=1174 left=1148 [2025-04-30T11:57:20.962543014Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=1148 pn=3 [2025-04-30T11:57:20.962545528Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[93, d1, 0e, 6b, bd, 29, 59, 02, ba, c4, 17, f8, 4e, 4a, da, 87, 7c, 94, 28, 05] reset_token=[84, d1, c7, 10, bb, 72, 09, d4, 70, b6, 82, fa, 36, 82, 44, 2d] [2025-04-30T11:57:20.962552732Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[99, c5, 17, 77, fe, 42, 4b, 1e, 03, 5f, f0, 33, de, 56, 8f, e4, 54, 32, eb, a3] reset_token=[71, 94, f8, ca, 36, 7e, b9, 65, 2d, a2, d5, 21, a5, cb, fe, ee] [2025-04-30T11:57:20.962557892Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[ba, 24, 47, 91, 8e, eb, 03, 76, 67, ea, 18, ab, bf, cd, e2, 3b, ef, 95, ed, a8] reset_token=[09, aa, 69, ce, f8, 63, a6, 21, cd, ae, 8d, 7a, 43, 49, b4, c9] [2025-04-30T11:57:20.962562771Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[a1, 58, d7, af, 82, 6a, 38, 81, 47, 80, 2c, cf, b1, e9, e6, a3, e0, e9, e4, 05] reset_token=[ff, 38, 7d, a4, c5, a5, 15, a3, 7f, a2, 9d, 0f, 3b, 61, 1d, 31] [2025-04-30T11:57:20.962567499Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[20, 34, 27, 38, 5f, 61, d9, 04, f0, 49, db, a7, 7b, 88, 83, a3, 3b, bd, 0a, cd] reset_token=[67, fd, 22, e9, 0d, 20, ec, b5, b8, cf, d2, 07, f8, 30, 3a, 6d] [2025-04-30T11:57:20.962572429Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[a8, 61, e0, c4, 40, 47, 13, 67, ae, 06, 9a, be, 1a, 0d, 66, ed, 10, 9b, 20, a9] reset_token=[d9, 2a, 83, 9a, 1b, ff, ab, 71, 86, 7c, a5, 32, 83, 76, b1, 20] [2025-04-30T11:57:20.962577208Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[f8, bc, 30, 94, dd, 4d, 85, 7a, bb, 5c, ae, 13, d4, 5a, 1b, 9b, 48, bc, 9b, 7f] reset_token=[99, 03, 62, 4f, a2, 49, d3, f1, 80, 4d, 31, 7c, 89, 54, a8, 1b] [2025-04-30T11:57:20.962581917Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T11:57:20.962584502Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm PADDING len=846 [2025-04-30T11:57:20.962593438Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=125.92503ms latest_rtt=42.019177ms srtt=42.019177ms min_rtt=42.019177ms rttvar=21.009588ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1289 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7924, is_app_limited: true, interval: 42.019177ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 688498275 }), send_elapsed: 0ns, ack_elapsed: 42.019177ms, rtt: 42.019177ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1174, rate: 401602, last_update: Instant { tv_sec: 700, tv_nsec: 731115803 }, next_time: Instant { tv_sec: 700, tv_nsec: 731402156 }, 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-30T11:57:20.962628183Z TRACE quiche_apps::client] written 1350 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:20.962634676Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12211 out_len=1350 left=1324 [2025-04-30T11:57:20.962639745Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=22 pn=4 [2025-04-30T11:57:20.962644153Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm STREAM id=4 off=0 len=17 fin=true [2025-04-30T11:57:20.962652839Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=125.865128ms latest_rtt=42.019177ms srtt=42.019177ms min_rtt=42.019177ms rttvar=21.009588ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1337 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 7924, is_app_limited: true, interval: 42.019177ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 688498275 }), send_elapsed: 0ns, ack_elapsed: 42.019177ms, rtt: 42.019177ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 401602, last_update: Instant { tv_sec: 700, tv_nsec: 731287145 }, next_time: Instant { tv_sec: 700, tv_nsec: 731402156 }, max_datagram_size: 1350, last_packet_size: None, iv: 3.042814ms, 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-30T11:57:20.962693205Z TRACE quiche_apps::client] written 48 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:20.962701020Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:20.996449102Z TRACE quiche_apps::client] got 646 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:20.996464791Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Handshake version=1 dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f scid=bac549c6608e702e len=22 pn=1 [2025-04-30T11:57:20.996474179Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm ACK delay=0 blocks=[2..2] ecn_counts=None [2025-04-30T11:57:20.996478857Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f packet newly acked 2 [2025-04-30T11:57:20.996498274Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=567 pn=0 [2025-04-30T11:57:20.996504686Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm CRYPTO off=0 len=546 [2025-04-30T11:57:20.996535263Z TRACE quiche_apps::client] [::]:41311: processed 646 bytes [2025-04-30T11:57:20.996539702Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:20.996542336Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:20.996550231Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12278 out_len=1350 left=1319 [2025-04-30T11:57:20.996553978Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=5 [2025-04-30T11:57:20.996556483Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=6 blocks=[0..0] ecn_counts=None [2025-04-30T11:57:20.996570209Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=102.990373ms latest_rtt=34.155686ms srtt=41.036239ms min_rtt=34.155686ms rttvar=17.723063ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1222 app_limited=true congestion_recovery_start_time=None Rate { delivered: 448, delivered_time: Instant { tv_sec: 700, tv_nsec: 765116489 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 730960803 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 2, rate_sample: RateSample { delivery_rate: 3366, is_app_limited: true, interval: 34.155686ms, delivered: 115, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 411221, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:20.996606166Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:20.996610925Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:20.997754910Z TRACE quiche_apps::client] got 168 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:20.997765680Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=147 pn=1 [2025-04-30T11:57:20.997772142Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm ACK delay=250 blocks=[3..4] ecn_counts=None [2025-04-30T11:57:20.997775629Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f packet newly acked 3 [2025-04-30T11:57:20.997778734Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f packet newly acked 4 [2025-04-30T11:57:20.997782432Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm HANDSHAKE_DONE [2025-04-30T11:57:20.997785938Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f dropped epoch 1 state [2025-04-30T11:57:20.997791118Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm NEW_TOKEN len=37 [2025-04-30T11:57:20.997797109Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[16, f2, 5e, 40, f6, 79, 37, 66] reset_token=[a5, 06, 52, 02, a7, f3, 40, e3, ea, 52, 62, 1f, ba, c7, e6, 95] [2025-04-30T11:57:20.997807218Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[8b, b7, de, a3, 4d, b1, 3f, 68] reset_token=[d9, ff, 04, 5c, 2b, 61, b9, 35, 52, 0e, ed, e2, a4, 01, a8, e3] [2025-04-30T11:57:20.997815143Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[09, e6, f6, b3, 38, a2, 65, cb] reset_token=[32, 33, 5f, 72, b0, 9c, 84, 69, 8c, fb, 02, f3, 79, f2, 3e, c7] [2025-04-30T11:57:20.997853405Z TRACE quiche_apps::client] [::]:41311: processed 168 bytes [2025-04-30T11:57:20.997857953Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:20.997860267Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:20.997867521Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:20.997871158Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=6 [2025-04-30T11:57:20.997873683Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=12 blocks=[0..1] ecn_counts=None [2025-04-30T11:57:20.997885134Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:20.997925930Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:20.997930980Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.000170739Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.000181950Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=2 [2025-04-30T11:57:21.000189084Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=0 off=0 len=1190 fin=false [2025-04-30T11:57:21.000196848Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.000200375Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.000202679Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.000207388Z TRACE quiche_apps::common] received 1190 bytes [2025-04-30T11:57:21.000210003Z TRACE quiche_apps::common] stream 0 has 1190 bytes (fin? false) [2025-04-30T11:57:21.000216695Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.000219951Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=7 [2025-04-30T11:57:21.000222346Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..2] ecn_counts=None [2025-04-30T11:57:21.000228838Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.000263062Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.000267611Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.001160855Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.001173209Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=3 [2025-04-30T11:57:21.001181264Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=0 off=1190 len=1188 fin=false [2025-04-30T11:57:21.001190471Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.001194849Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.001197735Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.001202814Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.001205739Z TRACE quiche_apps::common] stream 0 has 1188 bytes (fin? false) [2025-04-30T11:57:21.001213734Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.001217802Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=8 [2025-04-30T11:57:21.001220848Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..3] ecn_counts=None [2025-04-30T11:57:21.001228502Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 8, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.001262366Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.001267445Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.002172262Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.002182180Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=4 [2025-04-30T11:57:21.002188762Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=0 off=2378 len=1188 fin=false [2025-04-30T11:57:21.002196136Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.002199603Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.002201917Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.002206165Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.002219109Z TRACE quiche_apps::common] stream 0 has 1188 bytes (fin? false) [2025-04-30T11:57:21.002225822Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.002229028Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=9 [2025-04-30T11:57:21.002231402Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..4] ecn_counts=None [2025-04-30T11:57:21.002238135Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 9, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.002266388Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.002270436Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.006222527Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.006236553Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=5 [2025-04-30T11:57:21.006244749Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=0 off=3566 len=1188 fin=false [2025-04-30T11:57:21.006254186Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.006258485Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.006261310Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.006266540Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.006269315Z TRACE quiche_apps::common] stream 0 has 1188 bytes (fin? false) [2025-04-30T11:57:21.006277420Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.006281368Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=10 [2025-04-30T11:57:21.006284433Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..5] ecn_counts=None [2025-04-30T11:57:21.006292228Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 10, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.006333896Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.006339477Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.006537328Z TRACE quiche_apps::client] got 410 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.006547527Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=389 pn=6 [2025-04-30T11:57:21.006553588Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=0 off=4754 len=366 fin=true [2025-04-30T11:57:21.006561052Z TRACE quiche_apps::client] [::]:41311: processed 410 bytes [2025-04-30T11:57:21.006564448Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.006566763Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.006572423Z TRACE quiche_apps::common] received 366 bytes [2025-04-30T11:57:21.006574718Z TRACE quiche_apps::common] stream 0 has 366 bytes (fin? true) [2025-04-30T11:57:21.006577052Z DEBUG quiche_apps::common] 1/2 responses received [2025-04-30T11:57:21.006583474Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.006586610Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=11 [2025-04-30T11:57:21.006589014Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..6] ecn_counts=None [2025-04-30T11:57:21.006595186Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 11, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.006622938Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.006626965Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.007598006Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.007608275Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=7 [2025-04-30T11:57:21.007619847Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=0 len=1190 fin=false [2025-04-30T11:57:21.007627311Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.007630818Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.007633092Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.007637330Z TRACE quiche_apps::common] received 1190 bytes [2025-04-30T11:57:21.007639574Z TRACE quiche_apps::common] stream 4 has 1190 bytes (fin? false) [2025-04-30T11:57:21.007646006Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.007649152Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=12 [2025-04-30T11:57:21.007651597Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..7] ecn_counts=None [2025-04-30T11:57:21.007657678Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 12, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.007685811Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.007689878Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.011507025Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.011519137Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=8 [2025-04-30T11:57:21.011527183Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=1190 len=1188 fin=false [2025-04-30T11:57:21.011536029Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.011540217Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.011543093Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.011548252Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.011551017Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.011558822Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.011562839Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=13 [2025-04-30T11:57:21.011565895Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..8] ecn_counts=None [2025-04-30T11:57:21.011573850Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 13, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.011613695Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.011618644Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.012518691Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.012529411Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=9 [2025-04-30T11:57:21.012537877Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=2378 len=1188 fin=false [2025-04-30T11:57:21.012547626Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.012552956Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.012557224Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.012563225Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.012567032Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.012574747Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.012577973Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=14 [2025-04-30T11:57:21.012580397Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..9] ecn_counts=None [2025-04-30T11:57:21.012586909Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 14, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.012616425Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.012620342Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.016160690Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.016173494Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=10 [2025-04-30T11:57:21.016181609Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=3566 len=1188 fin=false [2025-04-30T11:57:21.016190696Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.016194944Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.016197769Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.016202989Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.016205754Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.016213529Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.016217376Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=15 [2025-04-30T11:57:21.016220362Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=5 blocks=[0..10] ecn_counts=None [2025-04-30T11:57:21.016228136Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 15, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.016275505Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.016283670Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.017171655Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.017179460Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=11 [2025-04-30T11:57:21.017185451Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=4754 len=1188 fin=false [2025-04-30T11:57:21.017192364Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.017195660Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.017197904Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.017201751Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.017203955Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.017215147Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.017218433Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=16 [2025-04-30T11:57:21.017220807Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..11] ecn_counts=None [2025-04-30T11:57:21.017226738Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 16, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.017255552Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.017262545Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.021751020Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.021760048Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=12 [2025-04-30T11:57:21.021767351Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=5942 len=1188 fin=false [2025-04-30T11:57:21.021775136Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.021779293Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.021782069Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.021786898Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.021789673Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.021796616Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.021800393Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=17 [2025-04-30T11:57:21.021803329Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..12] ecn_counts=None [2025-04-30T11:57:21.021810332Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 17, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.021850237Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.021859083Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.028664813Z TRACE quiche_apps::client] got 1210 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.028672627Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1189 pn=13 [2025-04-30T11:57:21.028678478Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=7130 len=1166 fin=false [2025-04-30T11:57:21.028685201Z TRACE quiche_apps::client] [::]:41311: processed 1210 bytes [2025-04-30T11:57:21.028688467Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.028690751Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.028706821Z TRACE quiche_apps::common] received 1166 bytes [2025-04-30T11:57:21.028709106Z TRACE quiche_apps::common] stream 4 has 1166 bytes (fin? false) [2025-04-30T11:57:21.028728853Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.028732229Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=18 [2025-04-30T11:57:21.028734624Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=7 blocks=[0..13] ecn_counts=None [2025-04-30T11:57:21.028740935Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, end_of_app_limited: 5, last_sent_packet: 18, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 765201138 }, next_time: Instant { tv_sec: 700, tv_nsec: 768243952 }, 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-30T11:57:21.028769930Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.028776723Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.029252464Z TRACE quiche_apps::client] got 336 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.029257714Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=315 pn=14 [2025-04-30T11:57:21.029263155Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=8296 len=292 fin=false [2025-04-30T11:57:21.029274556Z TRACE quiche_apps::client] [::]:41311: processed 336 bytes [2025-04-30T11:57:21.029278112Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.029280377Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.029284364Z TRACE quiche_apps::common] received 292 bytes [2025-04-30T11:57:21.029286679Z TRACE quiche_apps::common] stream 4 has 292 bytes (fin? false) [2025-04-30T11:57:21.029292459Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.029295575Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=19 [2025-04-30T11:57:21.029297930Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..14] ecn_counts=None [2025-04-30T11:57:21.029303801Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, end_of_app_limited: 5, last_sent_packet: 19, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 797944688 }, next_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, 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-30T11:57:21.029331463Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.029338145Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.032411878Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.032422187Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=1211 pn=15 [2025-04-30T11:57:21.032429801Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=8588 len=1188 fin=false [2025-04-30T11:57:21.032438257Z TRACE quiche_apps::client] [::]:41311: processed 1232 bytes [2025-04-30T11:57:21.032442335Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.032445170Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.032450099Z TRACE quiche_apps::common] received 1188 bytes [2025-04-30T11:57:21.032452875Z TRACE quiche_apps::common] stream 4 has 1188 bytes (fin? false) [2025-04-30T11:57:21.032460349Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:57:21.032464156Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=5 pn=20 [2025-04-30T11:57:21.032467091Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm ACK delay=4 blocks=[0..15] ecn_counts=None [2025-04-30T11:57:21.032474425Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=none latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, end_of_app_limited: 5, last_sent_packet: 20, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 797944688 }, next_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, 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-30T11:57:21.032514901Z TRACE quiche_apps::client] written 31 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.032522896Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.032838768Z TRACE quiche_apps::client] got 508 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.032844649Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx pkt Short dcid=61b4b53db4d208c48a2713107902fb5ff0fb307f key_phase=false len=487 pn=16 [2025-04-30T11:57:21.032851302Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f rx frm STREAM id=4 off=9776 len=464 fin=true [2025-04-30T11:57:21.032859527Z TRACE quiche_apps::client] [::]:41311: processed 508 bytes [2025-04-30T11:57:21.032863615Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.032866400Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.032871910Z TRACE quiche_apps::common] received 464 bytes [2025-04-30T11:57:21.032874645Z TRACE quiche_apps::common] stream 4 has 464 bytes (fin? true) [2025-04-30T11:57:21.032877581Z DEBUG quiche_apps::common] 2/2 responses received [2025-04-30T11:57:21.032880446Z INFO quiche_apps::common] 2/2 response(s) received in 112.914766ms, closing... [2025-04-30T11:57:21.032887559Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1324 [2025-04-30T11:57:21.032891537Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx pkt Short dcid=bac549c6608e702e key_phase=false len=10 pn=21 [2025-04-30T11:57:21.032894503Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T11:57:21.032904191Z TRACE quiche::recovery::congestion::recovery] 61b4b53db4d208c48a2713107902fb5ff0fb307f timer=124.453254ms latest_rtt=35.016715ms srtt=40.283798ms min_rtt=34.155686ms rttvar=14.797178ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=36 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1670, delivered_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, first_sent_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, end_of_app_limited: 20, last_sent_packet: 21, largest_acked: 4, rate_sample: RateSample { delivery_rate: 39144, is_app_limited: true, interval: 34.155686ms, delivered: 1337, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 700, tv_nsec: 730960803 }), send_elapsed: 0ns, ack_elapsed: 34.155686ms, rtt: 34.155686ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 418902, last_update: Instant { tv_sec: 700, tv_nsec: 801539979 }, next_time: Instant { tv_sec: 700, tv_nsec: 797944688 }, max_datagram_size: 1350, last_packet_size: None, iv: 85.939µ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-30T11:57:21.032945528Z TRACE quiche_apps::client] written 36 bytes from [::]:41311 to [fd00:cafe:cafe:100::100]:443 [2025-04-30T11:57:21.032953042Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.063852944Z TRACE quiche_apps::client] got 42 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41311 [2025-04-30T11:57:21.063871799Z TRACE quiche_apps::client] [::]:41311: processed 42 bytes [2025-04-30T11:57:21.063877280Z TRACE quiche_apps::client] [::]:41311: recv() would block [2025-04-30T11:57:21.063881708Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.063887328Z TRACE quiche_apps::client] [::]:41311 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-04-30T11:57:21.332215647Z TRACE quiche_apps::client] timed out [2025-04-30T11:57:21.332242959Z TRACE quiche] 61b4b53db4d208c48a2713107902fb5ff0fb307f draining timeout expired [2025-04-30T11:57:21.332284526Z TRACE quiche_apps::client] done reading [2025-04-30T11:57:21.332289255Z INFO quiche_apps::client] connection closed, recv=20 sent=22 lost=0 retrans=0 sent_bytes=2263 recv_bytes=18030 lost_bytes=0 [local_addr=[::]:41311 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=20 sent=22 lost=0 retrans=0 rtt=40.283798ms min_rtt=Some(34.155686ms) rttvar=14.797178ms cwnd=13500 sent_bytes=2263 recv_bytes=18030 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=39144]