[2025-04-30T18:37:54.650439067Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE
[2025-04-30T18:37:54.650760849Z INFO  quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:39479 with scid c46397f0e8d6c008ab0055e495dd7b91f09599e5
[2025-04-30T18:37:54.650803489Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 write message lvl=Initial len=266
[2025-04-30T18:37:54.650820481Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Initial version=1 dcid=478bc40fd23342d955b8ec2959f5e145 scid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 len=270 pn=0 
[2025-04-30T18:37:54.650823697Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm CRYPTO off=0 len=266
[2025-04-30T18:37:54.650838585Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=998.931091ms 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: 536, tv_nsec: 120203178 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 120203178 }, 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: 536, tv_nsec: 120203178 }, next_time: Instant { tv_sec: 536, tv_nsec: 120203178 }, 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-30T18:37:54.650888418Z TRACE quiche_apps::client] written 1200
[2025-04-30T18:37:54.691368383Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.691391486Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Initial version=1 dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 scid=136a301e63ac064d5f token= len=119 pn=0 
[2025-04-30T18:37:54.691404140Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=3 blocks=[0..0] ecn_counts=None
[2025-04-30T18:37:54.691410412Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 0
[2025-04-30T18:37:54.691416272Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm CRYPTO off=0 len=90
[2025-04-30T18:37:54.691527260Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 set write secret lvl=Handshake
[2025-04-30T18:37:54.691539864Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 set read secret lvl=Handshake
[2025-04-30T18:37:54.691598293Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Handshake version=1 dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 scid=136a301e63ac064d5f len=1004 pn=1 
[2025-04-30T18:37:54.691607190Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm CRYPTO off=0 len=741
[2025-04-30T18:37:54.691838583Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 write message lvl=Handshake len=52
[2025-04-30T18:37:54.691843242Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 set write secret lvl=OneRTT
[2025-04-30T18:37:54.691853150Z TRACE quiche::tls] c46397f0e8d6c008ab0055e495dd7b91f09599e5 set read secret lvl=OneRTT
[2025-04-30T18:37:54.691874681Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 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(478bc40fd23342d955b8ec2959f5e145), max_idle_timeout: 30000, stateless_reset_token: Some(297984894626812016526455227026028822541), max_udp_payload_size: 1472, initial_max_data: 16777216, initial_max_stream_data_bidi_local: 65536, initial_max_stream_data_bidi_remote: 65536, initial_max_stream_data_uni: 65536, initial_max_streams_bidi: 100, initial_max_streams_uni: 100, ack_delay_exponent: 8, max_ack_delay: 26, disable_active_migration: false, active_conn_id_limit: 4, initial_source_connection_id: Some(136a301e63ac064d5f), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None }
[2025-04-30T18:37:54.691895950Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm PADDING len=239
[2025-04-30T18:37:54.691913513Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.691919254Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.691922350Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.691931597Z DEBUG quiche_apps::common] sending HTTP request "GET /tfumhwelmx\r\n"
[2025-04-30T18:37:54.691982673Z DEBUG quiche_apps::common] sending HTTP request "GET /alekksomal\r\n"
[2025-04-30T18:37:54.692027096Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Initial version=1 dcid=136a301e63ac064d5f scid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 len=6 pn=1 
[2025-04-30T18:37:54.692031494Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=79 blocks=[0..0] ecn_counts=None
[2025-04-30T18:37:54.692041313Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=121.197651ms latest_rtt=40.617292ms srtt=40.617292ms min_rtt=40.617292ms rttvar=20.308646ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8198, is_app_limited: true, interval: 40.617292ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 120203178 }), send_elapsed: 0ns, ack_elapsed: 40.617292ms, rtt: 40.617292ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 415463, last_update: Instant { tv_sec: 536, tv_nsec: 161305068 }, next_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, 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-30T18:37:54.692062903Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Handshake version=1 dcid=136a301e63ac064d5f scid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 len=61 pn=2 
[2025-04-30T18:37:54.692066420Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=58 blocks=[1..1] ecn_counts=None
[2025-04-30T18:37:54.692069706Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm CRYPTO off=0 len=52
[2025-04-30T18:37:54.692076859Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=121.792695ms latest_rtt=40.617292ms srtt=40.617292ms min_rtt=40.617292ms rttvar=20.308646ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=116 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8198, is_app_limited: true, interval: 40.617292ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 120203178 }), send_elapsed: 0ns, ack_elapsed: 40.617292ms, rtt: 40.617292ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 415463, last_update: Instant { tv_sec: 536, tv_nsec: 161450890 }, next_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, max_datagram_size: 1350, last_packet_size: None, iv: 279.207µ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-30T18:37:54.692095564Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 dropped epoch 0 state
[2025-04-30T18:37:54.692101125Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13384 out_len=1172 left=1145
[2025-04-30T18:37:54.692114499Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=1145 pn=3 
[2025-04-30T18:37:54.692117866Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[fe, ec, d5, 30, ad, ce, 8e, ad, e1, 34, b8, e3, 19, bf, 3b, e3, 2c, d9, 98, 8b] reset_token=[cf, 8e, e5, 27, a3, 1b, a4, 2b, 83, c7, 75, f3, f4, 1e, 5f, 77]
[2025-04-30T18:37:54.692125991Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[b2, 20, 90, b3, 58, 2f, 21, c8, 3b, 6d, c4, 84, 05, 25, ca, c4, c3, e0, 5f, 8e] reset_token=[6d, f0, 9f, 33, 59, 14, 4f, f4, 7c, 91, 34, d3, 67, 16, 34, 5d]
[2025-04-30T18:37:54.692133145Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[ef, 93, 69, e9, 3f, 2f, 48, af, 0e, 06, 17, 8c, c8, 6b, 5b, c3, 7c, 73, 5d, d4] reset_token=[a3, a9, 97, 03, 82, 34, a4, 0e, d5, d8, b3, 52, ea, c2, 72, 99]
[2025-04-30T18:37:54.692140228Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm STREAM id=0 off=0 len=17 fin=true
[2025-04-30T18:37:54.692143454Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm PADDING len=1003
[2025-04-30T18:37:54.692152711Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=121.716923ms latest_rtt=40.617292ms srtt=40.617292ms min_rtt=40.617292ms rttvar=20.308646ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1288 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8198, is_app_limited: true, interval: 40.617292ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 120203178 }), send_elapsed: 0ns, ack_elapsed: 40.617292ms, rtt: 40.617292ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1172, rate: 415463, last_update: Instant { tv_sec: 536, tv_nsec: 161450890 }, next_time: Instant { tv_sec: 536, tv_nsec: 161730097 }, max_datagram_size: 1350, last_packet_size: Some(1172), 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-30T18:37:54.692190151Z TRACE quiche_apps::client] written 1350 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.692196483Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12212 out_len=1350 left=1323
[2025-04-30T18:37:54.692199859Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=22 pn=4 
[2025-04-30T18:37:54.692202314Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm STREAM id=4 off=0 len=17 fin=true
[2025-04-30T18:37:54.692207684Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=121.66204ms latest_rtt=40.617292ms srtt=40.617292ms min_rtt=40.617292ms rttvar=20.308646ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1337 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 161305108 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8198, is_app_limited: true, interval: 40.617292ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 120203178 }), send_elapsed: 0ns, ack_elapsed: 40.617292ms, rtt: 40.617292ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 415463, last_update: Instant { tv_sec: 536, tv_nsec: 161627050 }, next_time: Instant { tv_sec: 536, tv_nsec: 161730097 }, max_datagram_size: 1350, last_packet_size: None, iv: 2.93889ms, 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-30T18:37:54.692235075Z TRACE quiche_apps::client] written 49 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.692239263Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.724690752Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.724709497Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=2 
[2025-04-30T18:37:54.724719035Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=0 blocks=[3..4] ecn_counts=None
[2025-04-30T18:37:54.724723604Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 3
[2025-04-30T18:37:54.724726920Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 4
[2025-04-30T18:37:54.724731569Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm HANDSHAKE_DONE
[2025-04-30T18:37:54.724736648Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 dropped epoch 1 state
[2025-04-30T18:37:54.724741838Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[13, 6a, ad, d5, b0, 51, 25, 03, 4e] reset_token=[8c, f8, 84, 8e, d9, 6e, a5, 40, fe, 6b, ad, c2, eb, 23, cc, 5b]
[2025-04-30T18:37:54.724748911Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[13, 6a, 7c, 6c, e6, dc, 34, fd, 01] reset_token=[71, 0e, e4, f5, 2c, c9, 1a, ce, 64, 78, 0a, f6, b1, 3c, 24, b5]
[2025-04-30T18:37:54.724754432Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[13, 6a, 9f, 8d, db, 16, bf, 11, ee] reset_token=[3b, 93, 72, da, 8e, cd, 24, 16, 1f, 81, 1f, 11, 46, f0, 24, 83]
[2025-04-30T18:37:54.724761926Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm PADDING len=1066
[2025-04-30T18:37:54.724778056Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.724782344Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.724784748Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.724792623Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.724796841Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=5 
[2025-04-30T18:37:54.724799516Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=10 blocks=[2..2] ecn_counts=None
[2025-04-30T18:37:54.724806309Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.724851563Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.724856533Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.725662572Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.725670146Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=3 
[2025-04-30T18:37:54.725675616Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm PING mtu_probe=None
[2025-04-30T18:37:54.725682268Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm PADDING len=1158
[2025-04-30T18:37:54.725688280Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.725691606Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.725693860Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.725699751Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.725702907Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=6 
[2025-04-30T18:37:54.725705392Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..3] ecn_counts=None
[2025-04-30T18:37:54.725711453Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 6, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.725737802Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.725746318Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.725986959Z TRACE quiche_apps::client] got 366 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.725991738Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=345 pn=4 
[2025-04-30T18:37:54.725997138Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm CRYPTO off=0 len=321
[2025-04-30T18:37:54.726021564Z TRACE quiche_apps::client] [::]:39479: processed 366 bytes
[2025-04-30T18:37:54.726025231Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.726027515Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.726033706Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.726036782Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=7 
[2025-04-30T18:37:54.726039166Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=5 blocks=[2..4] ecn_counts=None
[2025-04-30T18:37:54.726045278Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.726073891Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.726077909Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.726983204Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.726990478Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=5 
[2025-04-30T18:37:54.726996258Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=0 off=0 len=1155 fin=false
[2025-04-30T18:37:54.727027507Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.727031284Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.727033568Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.727038287Z TRACE quiche_apps::common] received 1155 bytes
[2025-04-30T18:37:54.727041042Z TRACE quiche_apps::common] stream 0 has 1155 bytes (fin? false)
[2025-04-30T18:37:54.727047714Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.727050750Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=8 
[2025-04-30T18:37:54.727053085Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=7 blocks=[2..5] ecn_counts=None
[2025-04-30T18:37:54.727062072Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 8, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.727089012Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.727092909Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.727983817Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.727990940Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=6 
[2025-04-30T18:37:54.727996701Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=0 off=1155 len=1153 fin=false
[2025-04-30T18:37:54.728003273Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.728006680Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.728008904Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.728012921Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.728015576Z TRACE quiche_apps::common] stream 0 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.728021537Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.728024493Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=9 
[2025-04-30T18:37:54.728026827Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..6] ecn_counts=None
[2025-04-30T18:37:54.728032678Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 9, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.728063015Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.728066953Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.728982216Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.728989149Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=7 
[2025-04-30T18:37:54.728994859Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=0 off=2308 len=1153 fin=false
[2025-04-30T18:37:54.729000941Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.729004297Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.729006531Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.729010619Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.729012843Z TRACE quiche_apps::common] stream 0 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.729018684Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.729021609Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=10 
[2025-04-30T18:37:54.729024014Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..7] ecn_counts=None
[2025-04-30T18:37:54.729029635Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 10, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.729054862Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.729058609Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.729981667Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.729988390Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=8 
[2025-04-30T18:37:54.729994010Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=0 off=3461 len=1153 fin=false
[2025-04-30T18:37:54.730000041Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.730003327Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.730005551Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.730009209Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.730016101Z TRACE quiche_apps::common] stream 0 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.730022122Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.730025108Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=11 
[2025-04-30T18:37:54.730027463Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=4 blocks=[2..8] ecn_counts=None
[2025-04-30T18:37:54.730033063Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 11, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.730058561Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.730062508Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.730982871Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.730989664Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=9 
[2025-04-30T18:37:54.730994914Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=0 off=4614 len=506 fin=true
[2025-04-30T18:37:54.730998270Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=0 len=643 fin=false
[2025-04-30T18:37:54.731004612Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.731007888Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.731010102Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.731015602Z TRACE quiche_apps::common] received 506 bytes
[2025-04-30T18:37:54.731017907Z TRACE quiche_apps::common] stream 0 has 506 bytes (fin? true)
[2025-04-30T18:37:54.731020211Z DEBUG quiche_apps::common] 1/2 responses received
[2025-04-30T18:37:54.731023477Z TRACE quiche_apps::common] received 643 bytes
[2025-04-30T18:37:54.731025651Z TRACE quiche_apps::common] stream 4 has 643 bytes (fin? false)
[2025-04-30T18:37:54.731031412Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.731034317Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=12 
[2025-04-30T18:37:54.731036622Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=5 blocks=[2..9] ecn_counts=None
[2025-04-30T18:37:54.731042062Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 12, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.731072128Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.731075985Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.731982092Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.731988924Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=10 
[2025-04-30T18:37:54.731994766Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=643 len=1153 fin=false
[2025-04-30T18:37:54.732000917Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.732004193Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.732006487Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.732010425Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.732012659Z TRACE quiche_apps::common] stream 4 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.732018630Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.732021596Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=13 
[2025-04-30T18:37:54.732023960Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..10] ecn_counts=None
[2025-04-30T18:37:54.732029961Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 13, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.732054978Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.732063243Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.732982515Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.732988987Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=11 
[2025-04-30T18:37:54.732994597Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=1796 len=1153 fin=false
[2025-04-30T18:37:54.733000749Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.733004015Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.733006229Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.733010216Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.733012440Z TRACE quiche_apps::common] stream 4 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.733018402Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.733021287Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=14 
[2025-04-30T18:37:54.733023652Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..11] ecn_counts=None
[2025-04-30T18:37:54.733029212Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 14, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.733055942Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.733059679Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.733982567Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.733989079Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=12 
[2025-04-30T18:37:54.733994629Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=2949 len=1153 fin=false
[2025-04-30T18:37:54.734000721Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.734004017Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.734006271Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.734009908Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.734012082Z TRACE quiche_apps::common] stream 4 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.734017863Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.734025417Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=15 
[2025-04-30T18:37:54.734027851Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..12] ecn_counts=None
[2025-04-30T18:37:54.734033342Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 15, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.734058609Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.734062266Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.734983751Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.734990654Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=13 
[2025-04-30T18:37:54.734996134Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=4102 len=1153 fin=false
[2025-04-30T18:37:54.735002025Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.735005361Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.735007605Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.735011442Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.735013657Z TRACE quiche_apps::common] stream 4 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.735019638Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.735022553Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=16 
[2025-04-30T18:37:54.735024888Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[2..13] ecn_counts=None
[2025-04-30T18:37:54.735030438Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 4, last_sent_packet: 16, largest_acked: 4, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 32.834055ms, delivered: 1221, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 161305108 }), send_elapsed: 424.989µs, ack_elapsed: 32.834055ms, rtt: 32.409066ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.735061306Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.735065253Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.756255481Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.756276470Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=14 
[2025-04-30T18:37:54.756287791Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=0 blocks=[5..5] ecn_counts=None
[2025-04-30T18:37:54.756293212Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 5
[2025-04-30T18:37:54.756299604Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=5255 len=1148 fin=false
[2025-04-30T18:37:54.756313911Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.756318629Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.756321454Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.756327666Z TRACE quiche_apps::common] received 1148 bytes
[2025-04-30T18:37:54.756330902Z TRACE quiche_apps::common] stream 4 has 1148 bytes (fin? false)
[2025-04-30T18:37:54.756340791Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.756345900Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=136a301e63ac064d5f key_phase=false len=5 pn=17 
[2025-04-30T18:37:54.756348996Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=8 blocks=[3..14] ecn_counts=None
[2025-04-30T18:37:54.756356931Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=none latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, end_of_app_limited: 16, last_sent_packet: 17, largest_acked: 5, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 194221467 }, next_time: Instant { tv_sec: 536, tv_nsec: 197160357 }, 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-30T18:37:54.756399901Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.756408788Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.756422233Z TRACE quiche_apps::client] got 162 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.756429296Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=141 pn=15 
[2025-04-30T18:37:54.756450877Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=0 blocks=[5..6] ecn_counts=None
[2025-04-30T18:37:54.756456037Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 6
[2025-04-30T18:37:54.756462338Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=1 conn_id=[22, dd, 2a, d3, 42, 6d, 54, 0f, ab] reset_token=[bb, 23, 35, 7d, d7, 0f, 2b, 9c, ca, 47, 6d, 7d, 63, 8f, e4, 67]
[2025-04-30T18:37:54.756470814Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 path ID 0 changed DCID: old seq num 0 new seq num 1
[2025-04-30T18:37:54.756475503Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=2 conn_id=[22, dd, a1, 4b, a4, 67, f4, 10, 7c] reset_token=[73, 68, 34, ea, 1c, 09, 2d, 13, c0, 7e, 5b, 59, 00, 47, 21, 57]
[2025-04-30T18:37:54.756480603Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 path ID 0 changed DCID: old seq num 1 new seq num 2
[2025-04-30T18:37:54.756485161Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=3 conn_id=[22, dd, 78, 0f, ac, cc, 5c, 92, 27] reset_token=[3d, d3, e8, 17, 1e, 58, 98, 9d, 7e, 7d, 0f, d0, 1a, 11, 08, 51]
[2025-04-30T18:37:54.756489830Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 path ID 0 changed DCID: old seq num 2 new seq num 3
[2025-04-30T18:37:54.756494208Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=4 conn_id=[22, dd, e3, 32, 2b, 25, 19, f8, f8] reset_token=[46, 49, d0, 12, 97, 5d, db, e2, 54, e3, 37, 5d, be, 87, 21, f3]
[2025-04-30T18:37:54.756499177Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 path ID 0 changed DCID: old seq num 3 new seq num 4
[2025-04-30T18:37:54.756509096Z TRACE quiche_apps::client] [::]:39479: processed 162 bytes
[2025-04-30T18:37:54.756513554Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.756516370Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.756523683Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1318
[2025-04-30T18:37:54.756529464Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=22dd2ad3426d540fab key_phase=false len=13 pn=18 
[2025-04-30T18:37:54.756532720Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=11 blocks=[4..15] ecn_counts=None
[2025-04-30T18:37:54.756536136Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm RETIRE_CONNECTION_ID seq_num=3
[2025-04-30T18:37:54.756538982Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm RETIRE_CONNECTION_ID seq_num=1
[2025-04-30T18:37:54.756541777Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm RETIRE_CONNECTION_ID seq_num=0
[2025-04-30T18:37:54.756544512Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm RETIRE_CONNECTION_ID seq_num=2
[2025-04-30T18:37:54.756552397Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=134.693343ms latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=40 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, end_of_app_limited: 17, last_sent_packet: 18, largest_acked: 6, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 40, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 225953489 }, next_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, max_datagram_size: 1350, last_packet_size: Some(40), 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-30T18:37:54.756620374Z TRACE quiche_apps::client] written 40 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.756629802Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.757429930Z TRACE quiche_apps::client] got 1232 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.757435159Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1211 pn=16 
[2025-04-30T18:37:54.757440970Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm PING mtu_probe=None
[2025-04-30T18:37:54.757444377Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=6403 len=1184 fin=false
[2025-04-30T18:37:54.757465496Z TRACE quiche_apps::client] [::]:39479: processed 1232 bytes
[2025-04-30T18:37:54.757469013Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.757471277Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.757475545Z TRACE quiche_apps::common] received 1184 bytes
[2025-04-30T18:37:54.757477809Z TRACE quiche_apps::common] stream 4 has 1184 bytes (fin? false)
[2025-04-30T18:37:54.757484362Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13460 out_len=1350 left=1318
[2025-04-30T18:37:54.757487568Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=22dd2ad3426d540fab key_phase=false len=5 pn=19 
[2025-04-30T18:37:54.757489982Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=6 blocks=[4..16] ecn_counts=None
[2025-04-30T18:37:54.757496194Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=133.749626ms latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=40 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, end_of_app_limited: 17, last_sent_packet: 19, largest_acked: 6, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 226914147 }, next_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, max_datagram_size: 1350, last_packet_size: None, iv: 93.846µ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-30T18:37:54.757525419Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.757531991Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.759370873Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.759380261Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=17 
[2025-04-30T18:37:54.759386112Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=3 blocks=[5..8] ecn_counts=None
[2025-04-30T18:37:54.759389548Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 7
[2025-04-30T18:37:54.759396732Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 8
[2025-04-30T18:37:54.759400739Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=7587 len=1148 fin=false
[2025-04-30T18:37:54.759408644Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.759412191Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.759414455Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.759418583Z TRACE quiche_apps::common] received 1148 bytes
[2025-04-30T18:37:54.759420817Z TRACE quiche_apps::common] stream 4 has 1148 bytes (fin? false)
[2025-04-30T18:37:54.759445273Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13460 out_len=1350 left=1318
[2025-04-30T18:37:54.759448669Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=22dd2ad3426d540fab key_phase=false len=5 pn=20 
[2025-04-30T18:37:54.759451043Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=8 blocks=[6..17] ecn_counts=None
[2025-04-30T18:37:54.759456654Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=131.789226ms latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=40 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 228811800 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, end_of_app_limited: 19, last_sent_packet: 20, largest_acked: 8, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 226914147 }, next_time: Instant { tv_sec: 536, tv_nsec: 228968714 }, 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-30T18:37:54.759486670Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.759493473Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.760368511Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.760376746Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=1179 pn=18 
[2025-04-30T18:37:54.760382798Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=8735 len=1153 fin=false
[2025-04-30T18:37:54.760389340Z TRACE quiche_apps::client] [::]:39479: processed 1200 bytes
[2025-04-30T18:37:54.760392676Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.760394931Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.760398918Z TRACE quiche_apps::common] received 1153 bytes
[2025-04-30T18:37:54.760401152Z TRACE quiche_apps::common] stream 4 has 1153 bytes (fin? false)
[2025-04-30T18:37:54.760407384Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13460 out_len=1350 left=1318
[2025-04-30T18:37:54.760410349Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=22dd2ad3426d540fab key_phase=false len=5 pn=21 
[2025-04-30T18:37:54.760412724Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm ACK delay=3 blocks=[6..18] ecn_counts=None
[2025-04-30T18:37:54.760423244Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=130.822527ms latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=40 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 228811800 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, end_of_app_limited: 19, last_sent_packet: 21, largest_acked: 8, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 226914147 }, next_time: Instant { tv_sec: 536, tv_nsec: 228968714 }, 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-30T18:37:54.760452628Z TRACE quiche_apps::client] written 32 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.760459361Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.760728445Z TRACE quiche_apps::client] got 404 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.760736820Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx pkt Short dcid=c46397f0e8d6c008ab0055e495dd7b91f09599e5 key_phase=false len=383 pn=19 
[2025-04-30T18:37:54.760742661Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm ACK delay=3 blocks=[5..10] ecn_counts=None
[2025-04-30T18:37:54.760746078Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 9
[2025-04-30T18:37:54.760748522Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 packet newly acked 10
[2025-04-30T18:37:54.760751949Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 rx frm STREAM id=4 off=9888 len=352 fin=true
[2025-04-30T18:37:54.760759433Z TRACE quiche_apps::client] [::]:39479: processed 404 bytes
[2025-04-30T18:37:54.760762909Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.760765184Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.760770824Z TRACE quiche_apps::common] received 352 bytes
[2025-04-30T18:37:54.760773148Z TRACE quiche_apps::common] stream 4 has 352 bytes (fin? true)
[2025-04-30T18:37:54.760775433Z DEBUG quiche_apps::common] 2/2 responses received
[2025-04-30T18:37:54.760777697Z INFO  quiche_apps::common] 2/2 response(s) received in 109.883719ms, closing...
[2025-04-30T18:37:54.760784049Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13460 out_len=1350 left=1323
[2025-04-30T18:37:54.760787375Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx pkt Short dcid=22dd2ad3426d540fab key_phase=false len=10 pn=22 
[2025-04-30T18:37:54.760789790Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65]
[2025-04-30T18:37:54.760796262Z TRACE quiche::recovery::congestion::recovery] c46397f0e8d6c008ab0055e495dd7b91f09599e5 timer=134.710635ms latest_rtt=32.409066ms srtt=39.591263ms min_rtt=32.409066ms rttvar=17.28354ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=77 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1554, delivered_time: Instant { tv_sec: 536, tv_nsec: 230168420 }, first_sent_time: Instant { tv_sec: 536, tv_nsec: 225953489 }, end_of_app_limited: 21, last_sent_packet: 22, largest_acked: 10, rate_sample: RateSample { delivery_rate: 37186, is_app_limited: true, interval: 0ns, delivered: 0, prior_delivered: 1554, prior_time: Some(Instant { tv_sec: 536, tv_nsec: 197160357 }), send_elapsed: 0ns, ack_elapsed: 28.546119ms, rtt: 28.546119ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 426230, last_update: Instant { tv_sec: 536, tv_nsec: 230214566 }, next_time: Instant { tv_sec: 536, tv_nsec: 228968714 }, max_datagram_size: 1350, last_packet_size: None, iv: 86.808µ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-30T18:37:54.760831518Z TRACE quiche_apps::client] written 37 bytes from [::]:39479 to [fd00:cafe:cafe:100::100]:443
[2025-04-30T18:37:54.760838301Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.761468080Z TRACE quiche_apps::client] got 49 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.761472478Z TRACE quiche_apps::client] [::]:39479: processed 49 bytes
[2025-04-30T18:37:54.761475614Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.761477888Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.761481404Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.787050981Z TRACE quiche_apps::client] got 48 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.787066470Z TRACE quiche_apps::client] [::]:39479: processed 48 bytes
[2025-04-30T18:37:54.787070678Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.787073574Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.787078904Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.788919880Z TRACE quiche_apps::client] got 1312 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.788925050Z TRACE quiche_apps::client] [::]:39479: processed 1312 bytes
[2025-04-30T18:37:54.788928045Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.788930239Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.788933395Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:54.791236056Z TRACE quiche_apps::client] got 57 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:39479
[2025-04-30T18:37:54.791244331Z TRACE quiche_apps::client] [::]:39479: processed 57 bytes
[2025-04-30T18:37:54.791247567Z TRACE quiche_apps::client] [::]:39479: recv() would block
[2025-04-30T18:37:54.791249962Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:54.791253799Z TRACE quiche_apps::client] [::]:39479 -> [fd00:cafe:cafe:100::100]:443: done writing
[2025-04-30T18:37:55.087586272Z TRACE quiche_apps::client] timed out
[2025-04-30T18:37:55.087606840Z TRACE quiche] c46397f0e8d6c008ab0055e495dd7b91f09599e5 draining timeout expired
[2025-04-30T18:37:55.087640173Z TRACE quiche_apps::client] done reading
[2025-04-30T18:37:55.087644450Z INFO  quiche_apps::client] connection closed, recv=20 sent=23 lost=0 retrans=0 sent_bytes=2321 recv_bytes=20164 lost_bytes=0 [local_addr=[::]:39479 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=20 sent=23 lost=0 retrans=0 rtt=39.591263ms min_rtt=Some(32.409066ms) rttvar=17.28354ms cwnd=13500 sent_bytes=2321 recv_bytes=20164 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=37186]