[2025-09-12T05:42:16.629762456Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-09-12T05:42:16.630052686Z INFO quiche_apps::client] connecting to [fd00:cafe:cafe:100::100]:443 from [::]:41259 with scid 44202b09a7a2e98ece4aa8eebac792272d4d4e2e [2025-09-12T05:42:16.630105905Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e write message lvl=Initial len=266 [2025-09-12T05:42:16.630123557Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Initial version=1 dcid=9b30715da5af7cf29b92d33ba50dfec1 scid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e len=270 pn=0 [2025-09-12T05:42:16.630126843Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm CRYPTO off=0 len=266 [2025-09-12T05:42:16.630141360Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=998.921714ms 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: 730, tv_nsec: 880495556 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 880495556 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { bandwidth: 0.00 Kbps, 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: 730, tv_nsec: 880495556 }, next_time: Instant { tv_sec: 730, tv_nsec: 880495556 }, 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-09-12T05:42:16.630187606Z TRACE quiche_apps::client] written 1200 [2025-09-12T05:42:16.673840378Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.673866246Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Initial version=1 dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e scid=d1eeda39f5291b9c token= len=118 pn=0 [2025-09-12T05:42:16.673882105Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm ACK delay=445 blocks=[0..0] ecn_counts=None [2025-09-12T05:42:16.673889669Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 0 [2025-09-12T05:42:16.673896642Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm CRYPTO off=0 len=90 [2025-09-12T05:42:16.674010273Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e set write secret lvl=Handshake [2025-09-12T05:42:16.674024520Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e set read secret lvl=Handshake [2025-09-12T05:42:16.674062360Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Handshake version=1 dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e scid=d1eeda39f5291b9c len=754 pn=1 [2025-09-12T05:42:16.674069093Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm CRYPTO off=0 len=732 [2025-09-12T05:42:16.674307395Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e write message lvl=Handshake len=52 [2025-09-12T05:42:16.674312355Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e set write secret lvl=OneRTT [2025-09-12T05:42:16.674322163Z TRACE quiche::tls] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e set read secret lvl=OneRTT [2025-09-12T05:42:16.674344424Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e connection established: proto=Ok("h3") cipher=Some(AES256_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(9b30715da5af7cf29b92d33ba50dfec1), max_idle_timeout: 60000, stateless_reset_token: Some(140022261989468672436118740552248326373), max_udp_payload_size: 65527, initial_max_data: 1048576, initial_max_stream_data_bidi_local: 1048576, initial_max_stream_data_bidi_remote: 1048576, initial_max_stream_data_uni: 1048576, initial_max_streams_bidi: 128, initial_max_streams_uni: 128, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 8, initial_source_connection_id: Some(d1eeda39f5291b9c), retry_source_connection_id: None, max_datagram_frame_size: Some(65536), unknown_params: None } [2025-09-12T05:42:16.674378127Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=232 pn=2 [2025-09-12T05:42:16.674384699Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm CRYPTO off=0 len=89 [2025-09-12T05:42:16.674399447Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=3 off=0 len=19 fin=false [2025-09-12T05:42:16.674404877Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=7 off=0 len=1 fin=false [2025-09-12T05:42:16.674408534Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=11 off=0 len=1 fin=false [2025-09-12T05:42:16.674412932Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm PADDING len=88 [2025-09-12T05:42:16.674419775Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.674425165Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.674428140Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.674445091Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm SETTINGS stream=2 len=18 [2025-09-12T05:42:16.674460210Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e open GREASE stream 14 [2025-09-12T05:42:16.674470779Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm GREASE stream=0 len=0 [2025-09-12T05:42:16.674477652Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm GREASE stream=0 len=18 [2025-09-12T05:42:16.674486098Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm HEADERS stream=0 len=30 fin=true [2025-09-12T05:42:16.674493091Z DEBUG quiche_apps::common] Sent HTTP request [":method: GET", ":scheme: https", ":authority: server6", ":path: /paluifldbj", "user-agent: quiche"] [2025-09-12T05:42:16.674560536Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm HEADERS stream=4 len=30 fin=true [2025-09-12T05:42:16.674567369Z DEBUG quiche_apps::common] Sent HTTP request [":method: GET", ":scheme: https", ":authority: server6", ":path: /jjcldaqoxi", "user-agent: quiche"] [2025-09-12T05:42:16.674628532Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 3 is readable [2025-09-12T05:42:16.674635225Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 3 [2025-09-12T05:42:16.674640204Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e open peer's control stream 3 [2025-09-12T05:42:16.674644192Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 3 [2025-09-12T05:42:16.674647908Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 3 [2025-09-12T05:42:16.674652036Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 16 bytes on stream 3 [2025-09-12T05:42:16.674656134Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm SETTINGS max_field_section=None, qpack_max_table=Some(4096), qpack_blocked=Some(16) raw=Some([(1, 4096), (7, 16), (8, 1), (33, 1), (51, 1), (727725890, 1)]), additional_settings=Some([(33, 1), (727725890, 1)]) stream=3 payload_len=16 [2025-09-12T05:42:16.674685769Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 7 is readable [2025-09-12T05:42:16.674691299Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 7 [2025-09-12T05:42:16.674695687Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 11 is readable [2025-09-12T05:42:16.674699815Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 11 [2025-09-12T05:42:16.674731975Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Initial version=1 dcid=d1eeda39f5291b9c scid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e len=6 pn=1 [2025-09-12T05:42:16.674735752Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=108 blocks=[0..0] ecn_counts=None [2025-09-12T05:42:16.674747544Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=130.500913ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 924774401 }, next_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, 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-09-12T05:42:16.674772260Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Handshake version=1 dcid=d1eeda39f5291b9c scid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e len=62 pn=2 [2025-09-12T05:42:16.674775776Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=88 blocks=[1..1] ecn_counts=None [2025-09-12T05:42:16.674779092Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm CRYPTO off=0 len=52 [2025-09-12T05:42:16.674786516Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.325045ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=116 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925154738 }, next_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, max_datagram_size: 1350, last_packet_size: None, iv: 301.059µ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-09-12T05:42:16.674799741Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e dropped epoch 0 state [2025-09-12T05:42:16.674815470Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=1147 pn=3 [2025-09-12T05:42:16.674818866Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=53 blocks=[2..2] ecn_counts=None [2025-09-12T05:42:16.674822082Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[7c, 80, 4f, 52, 5a, 04, 55, 05, f4, 43, 65, 66, 4c, bc, 90, 9a, 28, dd, 77, 0f] reset_token=[38, d1, 68, 29, 45, 3a, 1b, 07, 55, e3, e1, 07, 9b, 24, 3e, a9] [2025-09-12T05:42:16.674834345Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[07, 2b, 6d, 1f, 02, 8d, be, a2, 00, f8, f0, 8d, c4, 86, 1f, 81, db, 0b, 35, a6] reset_token=[bc, 4f, 50, fe, 05, 15, f3, 1f, 5b, 82, f2, 27, e2, 94, ad, 3f] [2025-09-12T05:42:16.674841629Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[d9, 72, a5, ab, 83, 71, 63, d9, 22, 30, 29, 11, 96, 33, 3c, fb, 25, 34, 33, 13] reset_token=[f9, 58, 3b, e6, 4a, 32, 68, 02, 24, b6, 0b, be, 9b, 47, d4, c0] [2025-09-12T05:42:16.674847910Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[92, 2c, 58, bf, f9, 1f, 2f, 1f, f7, eb, 6e, 7a, c3, cc, 6e, f4, 5d, de, fe, 4b] reset_token=[f0, a1, a5, c6, 32, 98, 69, 10, d7, e9, fa, 48, 52, 0a, 74, 1f] [2025-09-12T05:42:16.674853992Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[14, f2, 9a, 15, f5, 85, ad, 20, 88, ee, 54, d7, 2c, b2, 69, 76, 09, 1c, 84, c0] reset_token=[7c, 94, a1, 5b, 18, d8, 74, ff, df, 84, c0, 98, 5a, e4, 2c, c3] [2025-09-12T05:42:16.674859973Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[ec, e9, a4, 33, 74, ed, 1d, 00, 5b, 77, f8, 6b, 7f, 8b, 5a, a2, 33, 92, a6, 53] reset_token=[92, a6, 67, 6b, cc, 40, b6, b6, 44, 6a, 9d, 2f, 2b, 1a, 30, 99] [2025-09-12T05:42:16.674865914Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[5b, 05, 18, 6e, 67, d9, d9, db, 54, 5c, f7, 5b, 97, 3f, 70, 71, 05, 90, 1e, 0c] reset_token=[67, 6f, f2, 84, da, 3e, d0, 9e, f0, 05, 01, a2, 30, 7e, ed, 13] [2025-09-12T05:42:16.674872165Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=2 off=0 len=19 fin=false [2025-09-12T05:42:16.674875431Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm PADDING len=838 [2025-09-12T05:42:16.674886973Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.224618ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1289 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1173, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925154738 }, next_time: Instant { tv_sec: 730, tv_nsec: 925455797 }, max_datagram_size: 1350, last_packet_size: Some(1173), 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-09-12T05:42:16.674924843Z TRACE quiche_apps::client] written 1350 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.674934080Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=6 pn=4 [2025-09-12T05:42:16.674937286Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=6 off=0 len=1 fin=false [2025-09-12T05:42:16.674943608Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.167963ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1321 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925361783 }, next_time: Instant { tv_sec: 730, tv_nsec: 925455797 }, max_datagram_size: 1350, last_packet_size: None, iv: 3.127384ms, 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-09-12T05:42:16.674974766Z TRACE quiche_apps::client] written 32 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.674982270Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=6 pn=5 [2025-09-12T05:42:16.674985366Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=10 off=0 len=1 fin=false [2025-09-12T05:42:16.674991227Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.120374ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1353 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 32, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925361783 }, next_time: Instant { tv_sec: 730, tv_nsec: 928583181 }, max_datagram_size: 1350, last_packet_size: Some(32), 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-09-12T05:42:16.675016163Z TRACE quiche_apps::client] written 32 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.675021593Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=73 pn=6 [2025-09-12T05:42:16.675024058Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=0 off=0 len=68 fin=true [2025-09-12T05:42:16.675028787Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.082895ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1452 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925450989 }, next_time: Instant { tv_sec: 730, tv_nsec: 928583181 }, max_datagram_size: 1350, last_packet_size: None, iv: 339.99µ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-09-12T05:42:16.675052440Z TRACE quiche_apps::client] written 99 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.675057881Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=37 pn=7 [2025-09-12T05:42:16.675060335Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=4 off=0 len=32 fin=true [2025-09-12T05:42:16.675065715Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.045956ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1515 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 6, last_sent_packet: 7, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 63, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925450989 }, next_time: Instant { tv_sec: 730, tv_nsec: 928923171 }, max_datagram_size: 1350, last_packet_size: Some(63), 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-09-12T05:42:16.675085412Z TRACE quiche_apps::client] written 63 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.675090301Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=31 pn=8 [2025-09-12T05:42:16.675092705Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm STREAM id=14 off=0 len=26 fin=true [2025-09-12T05:42:16.675097274Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=131.014447ms latest_rtt=43.796358ms srtt=43.796358ms min_rtt=43.796358ms rttvar=21.898179ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1572 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 924774431 }, end_of_app_limited: 7, last_sent_packet: 8, largest_acked: 0, rate_sample: RateSample { bandwidth: 60.82 Kbps, is_app_limited: true, interval: 43.796358ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 880495556 }), send_elapsed: 0ns, ack_elapsed: 43.796358ms, rtt: 43.796358ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 385306, last_update: Instant { tv_sec: 730, tv_nsec: 925520087 }, next_time: Instant { tv_sec: 730, tv_nsec: 928923171 }, max_datagram_size: 1350, last_packet_size: None, iv: 311.441µ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-09-12T05:42:16.675113404Z TRACE quiche_apps::client] written 57 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.675120357Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.707900841Z TRACE quiche_apps::client] got 242 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.707919605Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=221 pn=3 [2025-09-12T05:42:16.707930646Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm ACK delay=134 blocks=[3..3] ecn_counts=None [2025-09-12T05:42:16.707935535Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 3 [2025-09-12T05:42:16.707941687Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm HANDSHAKE_DONE [2025-09-12T05:42:16.707946215Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e dropped epoch 1 state [2025-09-12T05:42:16.707951455Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[0a, 59, 37, fd, 98, c1, f1, b7] reset_token=[a0, 21, 9c, 99, 96, 4d, e0, ab, 2b, 78, 67, 5e, ce, 37, bc, a6] [2025-09-12T05:42:16.707958077Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[07, 73, b3, 15, 64, a3, 1f, 53] reset_token=[05, 4d, 6a, 28, 11, 0f, 4a, ca, fc, 7d, 02, 15, 0c, af, e8, 83] [2025-09-12T05:42:16.707963497Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[61, c0, 3e, 1c, de, 59, 2d, 2f] reset_token=[99, 80, bd, 06, 31, 55, 84, 81, 7e, fd, 05, b1, 00, 8b, 93, 16] [2025-09-12T05:42:16.707967926Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[ea, 5f, 98, 9f, c5, c2, 32, 9e] reset_token=[1d, d7, af, 97, 44, 6b, b0, 53, 76, 1e, b2, 22, a1, fb, b8, a3] [2025-09-12T05:42:16.707972464Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[eb, 65, e6, 74, 51, d3, 75, 24] reset_token=[b8, 2f, 99, 5c, a3, 31, d8, 85, 92, 3b, b1, 23, b4, bd, d7, 65] [2025-09-12T05:42:16.707976672Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[82, 3e, af, eb, f9, fa, d9, 31] reset_token=[22, d1, cc, 51, 9f, d0, 5a, c5, 54, 7f, eb, b4, 35, f9, e5, d2] [2025-09-12T05:42:16.707981320Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[aa, 8e, 12, 0f, bf, d6, 0d, 5d] reset_token=[94, d4, a5, 90, c2, 2d, 78, fc, 4f, d4, 13, 37, 13, bf, d7, ba] [2025-09-12T05:42:16.708000326Z TRACE quiche_apps::client] [::]:41259: processed 242 bytes [2025-09-12T05:42:16.708004393Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.708006798Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.708018489Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=9 [2025-09-12T05:42:16.708021525Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=12 blocks=[3..3] ecn_counts=None [2025-09-12T05:42:16.708028588Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=111.091145ms latest_rtt=32.892353ms srtt=42.433357ms min_rtt=32.892353ms rttvar=19.149635ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=283 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1506, delivered_time: Instant { tv_sec: 730, tv_nsec: 958348150 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 925455797 }, end_of_app_limited: 8, last_sent_packet: 9, largest_acked: 3, rate_sample: RateSample { bandwidth: 279.50 Kbps, is_app_limited: true, interval: 33.573719ms, delivered: 1173, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 681.366µs, ack_elapsed: 33.573719ms, rtt: 32.892353ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 397682, last_update: Instant { tv_sec: 730, tv_nsec: 925520087 }, next_time: Instant { tv_sec: 730, tv_nsec: 958755920 }, 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-09-12T05:42:16.708073251Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.708078351Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.709061879Z TRACE quiche_apps::client] got 44 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.709069673Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=23 pn=4 [2025-09-12T05:42:16.709075494Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm ACK delay=14 blocks=[3..5] ecn_counts=None [2025-09-12T05:42:16.709078960Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 4 [2025-09-12T05:42:16.709081405Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 5 [2025-09-12T05:42:16.709091554Z TRACE quiche_apps::client] [::]:41259: processed 44 bytes [2025-09-12T05:42:16.709095070Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.709097305Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.709101733Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.713068055Z TRACE quiche_apps::client] got 44 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.713080609Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=23 pn=5 [2025-09-12T05:42:16.713091709Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm ACK delay=33 blocks=[3..7] ecn_counts=None [2025-09-12T05:42:16.713096078Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 6 [2025-09-12T05:42:16.713099053Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 7 [2025-09-12T05:42:16.713128698Z TRACE quiche_apps::client] [::]:41259: processed 44 bytes [2025-09-12T05:42:16.713133537Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.713136332Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.713142393Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.714413987Z TRACE quiche_apps::client] got 45 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.714420369Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=24 pn=6 [2025-09-12T05:42:16.714424968Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm ACK delay=134 blocks=[3..8] ecn_counts=None [2025-09-12T05:42:16.714428003Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e packet newly acked 8 [2025-09-12T05:42:16.714437090Z TRACE quiche_apps::client] [::]:41259: processed 45 bytes [2025-09-12T05:42:16.714440366Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.714442530Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.714446388Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.716441376Z TRACE quiche_apps::client] got 162 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.716450493Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=141 pn=7 [2025-09-12T05:42:16.716462365Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=0 len=119 fin=false [2025-09-12T05:42:16.716470800Z TRACE quiche_apps::client] [::]:41259: processed 162 bytes [2025-09-12T05:42:16.716474988Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.716477713Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.716481009Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.716486720Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.716491208Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.716494945Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.716500355Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 116 bytes on stream 0 [2025-09-12T05:42:16.716503832Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm HEADERS stream=0 payload_len=116 [2025-09-12T05:42:16.716507729Z TRACE quiche::h3::qpack::decoder] Header count=0 base=0 [2025-09-12T05:42:16.716510915Z TRACE quiche::h3::qpack::decoder] Indexed index=25 static=true [2025-09-12T05:42:16.716515924Z TRACE quiche::h3::qpack::decoder] Literal name_idx=92 static=true value=[97, 105, 111, 113, 117, 105, 99, 47, 49, 46, 50, 46, 48] [2025-09-12T05:42:16.716523077Z TRACE quiche::h3::qpack::decoder] Literal name_idx=6 static=true value=[70, 114, 105, 44, 32, 49, 50, 32, 83, 101, 112, 32, 50, 48, 50, 53, 32, 48, 53, 58, 52, 50, 58, 49, 54, 32, 71, 77, 84] [2025-09-12T05:42:16.716529840Z TRACE quiche::h3::qpack::decoder] Literal name_idx=44 static=true value=[116, 101, 120, 116, 47, 112, 108, 97, 105, 110, 59, 32, 99, 104, 97, 114, 115, 101, 116, 61, 117, 116, 102, 45, 56] [2025-09-12T05:42:16.716534228Z TRACE quiche::h3::qpack::decoder] Literal name_idx=4 static=true value=[53, 49, 50, 48] [2025-09-12T05:42:16.716538015Z TRACE quiche::h3::qpack::decoder] Literal name_idx=10 static=true value=[70, 114, 105, 44, 32, 49, 50, 32, 83, 101, 112, 32, 50, 48, 50, 53, 32, 48, 53, 58, 52, 50, 58, 49, 53, 32, 71, 77, 84] [2025-09-12T05:42:16.716544247Z TRACE quiche::h3::qpack::decoder] Literal name_idx=7 static=true value=[34, 48, 101, 99, 53, 97, 52, 55, 99, 99, 51, 54, 54, 52, 102, 102, 57, 98, 57, 100, 101, 97, 102, 57, 48, 102, 49, 52, 100, 52, 50, 100, 50, 34] [2025-09-12T05:42:16.716556750Z DEBUG quiche_apps::common] got response headers [(":status", "200"), ("server", "aioquic/1.2.0"), ("date", "Fri, 12 Sep 2025 05:42:16 GMT"), ("content-type", "text/plain; charset=utf-8"), ("content-length", "5120"), ("last-modified", "Fri, 12 Sep 2025 05:42:15 GMT"), ("etag", "\"0ec5a47cc3664ff9b9deaf90f14d42d2\"")] on stream id 0 [2025-09-12T05:42:16.716591314Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=10 [2025-09-12T05:42:16.716595282Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=17 blocks=[3..7] ecn_counts=None [2025-09-12T05:42:16.716604058Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 10, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.716646136Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.716651967Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.717145124Z TRACE quiche_apps::client] got 163 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.717149752Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=142 pn=8 [2025-09-12T05:42:16.717155183Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=0 len=120 fin=false [2025-09-12T05:42:16.717161704Z TRACE quiche_apps::client] [::]:41259: processed 163 bytes [2025-09-12T05:42:16.717164961Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.717167145Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.717170340Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.717175851Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.717179247Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.717182153Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.717185819Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 117 bytes on stream 4 [2025-09-12T05:42:16.717188304Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm HEADERS stream=4 payload_len=117 [2025-09-12T05:42:16.717190959Z TRACE quiche::h3::qpack::decoder] Header count=0 base=0 [2025-09-12T05:42:16.717193143Z TRACE quiche::h3::qpack::decoder] Indexed index=25 static=true [2025-09-12T05:42:16.717196068Z TRACE quiche::h3::qpack::decoder] Literal name_idx=92 static=true value=[97, 105, 111, 113, 117, 105, 99, 47, 49, 46, 50, 46, 48] [2025-09-12T05:42:16.717200326Z TRACE quiche::h3::qpack::decoder] Literal name_idx=6 static=true value=[70, 114, 105, 44, 32, 49, 50, 32, 83, 101, 112, 32, 50, 48, 50, 53, 32, 48, 53, 58, 52, 50, 58, 49, 54, 32, 71, 77, 84] [2025-09-12T05:42:16.717204234Z TRACE quiche::h3::qpack::decoder] Literal name_idx=44 static=true value=[116, 101, 120, 116, 47, 112, 108, 97, 105, 110, 59, 32, 99, 104, 97, 114, 115, 101, 116, 61, 117, 116, 102, 45, 56] [2025-09-12T05:42:16.717207690Z TRACE quiche::h3::qpack::decoder] Literal name_idx=4 static=true value=[49, 48, 50, 52, 48] [2025-09-12T05:42:16.717210545Z TRACE quiche::h3::qpack::decoder] Literal name_idx=10 static=true value=[70, 114, 105, 44, 32, 49, 50, 32, 83, 101, 112, 32, 50, 48, 50, 53, 32, 48, 53, 58, 52, 50, 58, 49, 53, 32, 71, 77, 84] [2025-09-12T05:42:16.717214954Z TRACE quiche::h3::qpack::decoder] Literal name_idx=7 static=true value=[34, 51, 97, 53, 56, 100, 56, 101, 51, 100, 55, 101, 52, 50, 97, 98, 50, 99, 53, 52, 48, 53, 97, 55, 49, 49, 51, 49, 50, 50, 50, 102, 102, 34] [2025-09-12T05:42:16.717223129Z DEBUG quiche_apps::common] got response headers [(":status", "200"), ("server", "aioquic/1.2.0"), ("date", "Fri, 12 Sep 2025 05:42:16 GMT"), ("content-type", "text/plain; charset=utf-8"), ("content-length", "10240"), ("last-modified", "Fri, 12 Sep 2025 05:42:15 GMT"), ("etag", "\"3a58d8e3d7e42ab2c5405a71131222ff\"")] on stream id 4 [2025-09-12T05:42:16.717232416Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=11 [2025-09-12T05:42:16.717234921Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=10 blocks=[3..8] ecn_counts=None [2025-09-12T05:42:16.717245721Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 11, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.717274164Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.717278341Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.718552860Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.718560424Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=9 [2025-09-12T05:42:16.718568018Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=119 len=1155 fin=false [2025-09-12T05:42:16.718589248Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.718593035Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.718595299Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.718597814Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.718601731Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.718605027Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.718607953Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 0 [2025-09-12T05:42:16.718610317Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm DATA stream=0 wire_payload_len=5120 [2025-09-12T05:42:16.718615617Z DEBUG quiche_apps::common] got 1152 bytes of response data on stream 0 [2025-09-12T05:42:16.718623061Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=12 [2025-09-12T05:42:16.718625766Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=7 blocks=[3..9] ecn_counts=None [2025-09-12T05:42:16.718632068Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 12, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.718662885Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.718667173Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.719584218Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.719592012Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=10 [2025-09-12T05:42:16.719598264Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=120 len=1155 fin=false [2025-09-12T05:42:16.719605427Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.719609324Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.719612811Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.719616868Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.719622879Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.719627828Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.719632597Z TRACE quiche::h3::stream] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e read 1 bytes on stream 4 [2025-09-12T05:42:16.719636655Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm DATA stream=4 wire_payload_len=10240 [2025-09-12T05:42:16.719644640Z DEBUG quiche_apps::common] got 1152 bytes of response data on stream 4 [2025-09-12T05:42:16.719655750Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=13 [2025-09-12T05:42:16.719658485Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=7 blocks=[3..10] ecn_counts=None [2025-09-12T05:42:16.719665118Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 13, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.719692729Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.719696727Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.722608910Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.722617536Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=11 [2025-09-12T05:42:16.722624629Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=1274 len=1155 fin=false [2025-09-12T05:42:16.722632584Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.722636672Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.722639366Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.722642522Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.722647862Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 0 [2025-09-12T05:42:16.722655807Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=14 [2025-09-12T05:42:16.722658873Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..11] ecn_counts=None [2025-09-12T05:42:16.722665876Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 14, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.722696152Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.722700700Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.723615821Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.723624898Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=12 [2025-09-12T05:42:16.723631120Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=1275 len=1155 fin=false [2025-09-12T05:42:16.723638534Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.723641810Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.723644014Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.723646538Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.723650927Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 4 [2025-09-12T05:42:16.723658020Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=15 [2025-09-12T05:42:16.723660484Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..12] ecn_counts=None [2025-09-12T05:42:16.723666576Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 15, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.723698355Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.723702553Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.725869110Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.725877155Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=13 [2025-09-12T05:42:16.725884218Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=2429 len=1155 fin=false [2025-09-12T05:42:16.725891712Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.725895709Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.725898484Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.725901610Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.725906700Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 0 [2025-09-12T05:42:16.725914604Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=16 [2025-09-12T05:42:16.725917620Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..13] ecn_counts=None [2025-09-12T05:42:16.725938689Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 16, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.725969466Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.725978263Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.726865552Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.726873416Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=14 [2025-09-12T05:42:16.726880400Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=2430 len=1155 fin=false [2025-09-12T05:42:16.726888114Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.726892091Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.726894856Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.726897902Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.726903092Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 4 [2025-09-12T05:42:16.726911257Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=17 [2025-09-12T05:42:16.726914323Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..14] ecn_counts=None [2025-09-12T05:42:16.726922217Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 17, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.726952103Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.726956611Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.729143045Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.729152453Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=15 [2025-09-12T05:42:16.729159666Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=3584 len=1155 fin=false [2025-09-12T05:42:16.729167541Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.729171688Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.729174384Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.729177479Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.729182699Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 0 [2025-09-12T05:42:16.729190834Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=18 [2025-09-12T05:42:16.729193970Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..15] ecn_counts=None [2025-09-12T05:42:16.729207315Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 18, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.729239294Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.729244103Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.730142904Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.730149456Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=16 [2025-09-12T05:42:16.730155147Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=3585 len=1155 fin=false [2025-09-12T05:42:16.730161158Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.730164334Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.730166518Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.730168942Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.730173080Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 4 [2025-09-12T05:42:16.730179572Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=19 [2025-09-12T05:42:16.730182006Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=3 blocks=[3..16] ecn_counts=None [2025-09-12T05:42:16.730187707Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 19, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.730217122Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.730221119Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.732487111Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.732497000Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=17 [2025-09-12T05:42:16.732504043Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=0 off=4739 len=503 fin=true [2025-09-12T05:42:16.732508301Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=4740 len=646 fin=false [2025-09-12T05:42:16.732516576Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.732520654Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.732523399Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.732526455Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 0 is readable [2025-09-12T05:42:16.732533598Z DEBUG quiche_apps::common] got 503 bytes of response data on stream 0 [2025-09-12T05:42:16.732537014Z DEBUG quiche_apps::common] 1/2 responses received [2025-09-12T05:42:16.732540090Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.732544358Z DEBUG quiche_apps::common] got 646 bytes of response data on stream 4 [2025-09-12T05:42:16.732552643Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=20 [2025-09-12T05:42:16.732555779Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=6 blocks=[3..17] ecn_counts=None [2025-09-12T05:42:16.732563393Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 20, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.732618666Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.732623896Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.733451417Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.733461866Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=18 [2025-09-12T05:42:16.733470382Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=5386 len=1155 fin=false [2025-09-12T05:42:16.733478848Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.733482405Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.733491041Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.733493906Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.733499246Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 4 [2025-09-12T05:42:16.733508433Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=21 [2025-09-12T05:42:16.733511218Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=5 blocks=[3..18] ecn_counts=None [2025-09-12T05:42:16.733518281Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 21, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.733554088Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.733562093Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.735243305Z TRACE quiche_apps::client] got 633 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.735256038Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=612 pn=19 [2025-09-12T05:42:16.735263472Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=6541 len=588 fin=false [2025-09-12T05:42:16.735271797Z TRACE quiche_apps::client] [::]:41259: processed 633 bytes [2025-09-12T05:42:16.735275324Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.735277598Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.735280283Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.735284942Z DEBUG quiche_apps::common] got 588 bytes of response data on stream 4 [2025-09-12T05:42:16.735293217Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=22 [2025-09-12T05:42:16.735295892Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..19] ecn_counts=None [2025-09-12T05:42:16.735302495Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 22, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.735344663Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.735349302Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.739117586Z TRACE quiche_apps::client] got 484 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.739131201Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=463 pn=20 [2025-09-12T05:42:16.739139236Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=7129 len=439 fin=false [2025-09-12T05:42:16.739149435Z TRACE quiche_apps::client] [::]:41259: processed 484 bytes [2025-09-12T05:42:16.739153883Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.739156659Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.739159304Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.739163892Z DEBUG quiche_apps::common] got 439 bytes of response data on stream 4 [2025-09-12T05:42:16.739171747Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=23 [2025-09-12T05:42:16.739174321Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=5 blocks=[3..20] ecn_counts=None [2025-09-12T05:42:16.739180994Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 23, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.739210929Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.739215067Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.747500538Z TRACE quiche_apps::client] got 324 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.747515436Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=303 pn=21 [2025-09-12T05:42:16.747523721Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=7568 len=279 fin=false [2025-09-12T05:42:16.747533439Z TRACE quiche_apps::client] [::]:41259: processed 324 bytes [2025-09-12T05:42:16.747545251Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.747548226Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.747551623Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.747557594Z DEBUG quiche_apps::common] got 279 bytes of response data on stream 4 [2025-09-12T05:42:16.747568164Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=24 [2025-09-12T05:42:16.747592158Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=6 blocks=[3..21] ecn_counts=None [2025-09-12T05:42:16.747600754Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, end_of_app_limited: 9, last_sent_packet: 24, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 966997417 }, next_time: Instant { tv_sec: 730, tv_nsec: 966997417 }, 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-09-12T05:42:16.747636190Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.747641239Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.748252005Z TRACE quiche_apps::client] got 326 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.748259729Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=305 pn=22 [2025-09-12T05:42:16.748266211Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=7847 len=281 fin=false [2025-09-12T05:42:16.748273986Z TRACE quiche_apps::client] [::]:41259: processed 326 bytes [2025-09-12T05:42:16.748277432Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.748279696Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.748282271Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.748287020Z DEBUG quiche_apps::common] got 281 bytes of response data on stream 4 [2025-09-12T05:42:16.748294744Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=25 [2025-09-12T05:42:16.748297359Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=4 blocks=[3..22] ecn_counts=None [2025-09-12T05:42:16.748304763Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, end_of_app_limited: 9, last_sent_packet: 25, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 998722737 }, next_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, 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-09-12T05:42:16.748339528Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.748344086Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.750242084Z TRACE quiche_apps::client] got 1200 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.750252213Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1179 pn=23 [2025-09-12T05:42:16.750258885Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=8128 len=1155 fin=false [2025-09-12T05:42:16.750266489Z TRACE quiche_apps::client] [::]:41259: processed 1200 bytes [2025-09-12T05:42:16.750269906Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.750272160Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.750274725Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.750279263Z DEBUG quiche_apps::common] got 1155 bytes of response data on stream 4 [2025-09-12T05:42:16.750306975Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=5 pn=26 [2025-09-12T05:42:16.750309860Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm ACK delay=6 blocks=[3..23] ecn_counts=None [2025-09-12T05:42:16.750316492Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=none latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, end_of_app_limited: 9, last_sent_packet: 26, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 730, tv_nsec: 998722737 }, next_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, 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-09-12T05:42:16.750345486Z TRACE quiche_apps::client] written 31 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.750349584Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:16.751180468Z TRACE quiche_apps::client] got 1125 bytes from [fd00:cafe:cafe:100::100]:443 to [::]:41259 [2025-09-12T05:42:16.751188393Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx pkt Short dcid=44202b09a7a2e98ece4aa8eebac792272d4d4e2e key_phase=false len=1104 pn=24 [2025-09-12T05:42:16.751195406Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e rx frm STREAM id=4 off=9283 len=1080 fin=true [2025-09-12T05:42:16.751208340Z TRACE quiche_apps::client] [::]:41259: processed 1125 bytes [2025-09-12T05:42:16.751211847Z TRACE quiche_apps::client] [::]:41259: recv() would block [2025-09-12T05:42:16.751214081Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:16.751216645Z TRACE quiche::h3] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e stream id 4 is readable [2025-09-12T05:42:16.751222216Z DEBUG quiche_apps::common] got 1080 bytes of response data on stream 4 [2025-09-12T05:42:16.751224951Z DEBUG quiche_apps::common] 2/2 responses received [2025-09-12T05:42:16.751227566Z INFO quiche_apps::common] 2/2 response(s) received in 121.036754ms, closing... [2025-09-12T05:42:16.751235260Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx pkt Short dcid=d1eeda39f5291b9c key_phase=false len=11 pn=27 [2025-09-12T05:42:16.751237925Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e tx frm APPLICATION_CLOSE err=100 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-09-12T05:42:16.751245800Z TRACE quiche::recovery::congestion::recovery] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e timer=113.581784ms latest_rtt=35.928257ms srtt=39.497147ms min_rtt=30.917341ms rttvar=12.274741ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=37 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1789, delivered_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, first_sent_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, end_of_app_limited: 26, last_sent_packet: 27, largest_acked: 8, rate_sample: RateSample { bandwidth: 290.64 Kbps, is_app_limited: true, interval: 40.076997ms, delivered: 1456, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 730, tv_nsec: 924774431 }), send_elapsed: 4.14874ms, ack_elapsed: 40.076997ms, rtt: 35.928257ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 427246, last_update: Instant { tv_sec: 731, tv_nsec: 1663714 }, next_time: Instant { tv_sec: 730, tv_nsec: 998722737 }, max_datagram_size: 1350, last_packet_size: None, iv: 86.601µ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-09-12T05:42:16.751275826Z TRACE quiche_apps::client] written 37 bytes from [::]:41259 to [fd00:cafe:cafe:100::100]:443 [2025-09-12T05:42:16.751279482Z TRACE quiche_apps::client] [::]:41259 -> [fd00:cafe:cafe:100::100]:443: done writing [2025-09-12T05:42:17.017592057Z TRACE quiche_apps::client] timed out [2025-09-12T05:42:17.017611784Z TRACE quiche] 44202b09a7a2e98ece4aa8eebac792272d4d4e2e draining timeout expired [2025-09-12T05:42:17.017651067Z TRACE quiche_apps::client] done reading [2025-09-12T05:42:17.017657489Z INFO quiche_apps::client] connection closed, recv=25 sent=28 lost=0 retrans=0 sent_bytes=2561 recv_bytes=17992 lost_bytes=0 [local_addr=[::]:41259 peer_addr=[fd00:cafe:cafe:100::100]:443 validation_state=Validated active=true recv=25 sent=28 lost=0 retrans=0 rtt=39.497147ms min_rtt=Some(30.917341ms) rttvar=12.274741ms cwnd=13500 sent_bytes=2561 recv_bytes=17992 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=36330]