[2025-04-30T17:13:40.039559131Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T17:13:40.039828566Z INFO quiche_apps::client] connecting to 193.167.100.100:443 from 0.0.0.0:38937 with scid e5616b97a38c3c42790f3e0954021948a08bb4ef [2025-04-30T17:13:40.039871026Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef write message lvl=Initial len=266 [2025-04-30T17:13:40.039889711Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Initial version=1 dcid=aa2f51301587a53e887a66a237ffd885 scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=270 pn=0 [2025-04-30T17:13:40.039892787Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm CRYPTO off=0 len=266 [2025-04-30T17:13:40.039905811Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=998.929227ms 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: 482, tv_nsec: 568322775 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 568322775 }, 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: 482, tv_nsec: 568322775 }, next_time: Instant { tv_sec: 482, tv_nsec: 568322775 }, 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-30T17:13:40.039963740Z TRACE quiche_apps::client] written 1200 [2025-04-30T17:13:40.078633326Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.078650077Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Initial version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd token= len=1194 pn=4330537 [2025-04-30T17:13:40.078661479Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=0 len=90 [2025-04-30T17:13:40.078769491Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef set write secret lvl=Handshake [2025-04-30T17:13:40.078779851Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef set read secret lvl=Handshake [2025-04-30T17:13:40.078790621Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm ACK delay=154 blocks=[0..0] ecn_counts=None [2025-04-30T17:13:40.078796402Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 0 [2025-04-30T17:13:40.078806541Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm PADDING len=1075 [2025-04-30T17:13:40.078828793Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.078834884Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.078838220Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.078855262Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Initial version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=1 [2025-04-30T17:13:40.078859119Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=25 blocks=[4330537..4330537] ecn_counts=None [2025-04-30T17:13:40.078867896Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.214123ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 607334252 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 607334252 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 607334252 }, next_time: Instant { tv_sec: 482, tv_nsec: 607334252 }, 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-30T17:13:40.078931285Z TRACE quiche_apps::client] written 1200 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.078940482Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.079607473Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.079618002Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330537 [2025-04-30T17:13:40.079624966Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=0 len=1172 [2025-04-30T17:13:40.079644843Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.079648840Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.079651285Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.079660041Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=2 [2025-04-30T17:13:40.079662756Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=5 blocks=[4330537..4330537] ecn_counts=None [2025-04-30T17:13:40.079669830Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=115.412349ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.079682623Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef dropped epoch 0 state [2025-04-30T17:13:40.079709504Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.079713982Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.080614702Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.080624780Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330538 [2025-04-30T17:13:40.080636733Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=1172 len=1171 [2025-04-30T17:13:40.080649246Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.080652973Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.080655368Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.080663663Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=3 [2025-04-30T17:13:40.080666238Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330538] ecn_counts=None [2025-04-30T17:13:40.080672880Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=115.416486ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.080706924Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.080711203Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.081622531Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.081632560Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330539 [2025-04-30T17:13:40.081639363Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=2343 len=1171 [2025-04-30T17:13:40.081650955Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.081654581Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.081656936Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.081665081Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=4 [2025-04-30T17:13:40.081667716Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330539] ecn_counts=None [2025-04-30T17:13:40.081674198Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=114.415209ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.081712801Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.081717489Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.082631273Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.082641432Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330540 [2025-04-30T17:13:40.082648285Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=3514 len=1171 [2025-04-30T17:13:40.082660157Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.082663744Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.082666138Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.082674304Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=5 [2025-04-30T17:13:40.082676849Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330540] ecn_counts=None [2025-04-30T17:13:40.082683241Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=113.406167ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.082716483Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.082720781Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.083641167Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.083651286Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330541 [2025-04-30T17:13:40.083657988Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=4685 len=1171 [2025-04-30T17:13:40.083669049Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.083672616Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.083674970Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.083688435Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=6 [2025-04-30T17:13:40.083691140Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330541] ecn_counts=None [2025-04-30T17:13:40.083698234Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=112.391204ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 6, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.083732217Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.083736796Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.084651321Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.084661199Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330542 [2025-04-30T17:13:40.084667822Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=5856 len=1171 [2025-04-30T17:13:40.084679404Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.084683060Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.084685445Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.084693290Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=7 [2025-04-30T17:13:40.084695884Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330542] ecn_counts=None [2025-04-30T17:13:40.084702256Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=111.387151ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 7, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.084740017Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.084744676Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.085660173Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.085670211Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330543 [2025-04-30T17:13:40.085676774Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=7027 len=1171 [2025-04-30T17:13:40.085687584Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.085691101Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.085693465Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.085701230Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=8 [2025-04-30T17:13:40.085703774Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=3 blocks=[4330537..4330543] ecn_counts=None [2025-04-30T17:13:40.085710137Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=110.379281ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 8, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.085742617Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.085746915Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.086669476Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.086679404Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=1195 pn=4330544 [2025-04-30T17:13:40.086686147Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=8198 len=1171 [2025-04-30T17:13:40.086698270Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.086701886Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.086704241Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.086711905Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=9 [2025-04-30T17:13:40.086714440Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330537..4330544] ecn_counts=None [2025-04-30T17:13:40.086737082Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=109.352195ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 1, last_sent_packet: 9, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 608124494 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, 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-30T17:13:40.086774302Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.086778971Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.087214507Z TRACE quiche_apps::client] got 653 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.087221861Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=616 pn=4330545 [2025-04-30T17:13:40.087228263Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=9369 len=592 [2025-04-30T17:13:40.087743169Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef write message lvl=Handshake len=36 [2025-04-30T17:13:40.087749140Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef set write secret lvl=OneRTT [2025-04-30T17:13:40.087756363Z TRACE quiche::tls] e5616b97a38c3c42790f3e0954021948a08bb4ef set read secret lvl=OneRTT [2025-04-30T17:13:40.087768576Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef connection established: proto=Ok("h3") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(aa2f51301587a53e887a66a237ffd885), max_idle_timeout: 60000, stateless_reset_token: Some(219368954860019029688713937340502990081), max_udp_payload_size: 1500, initial_max_data: 2621440, initial_max_stream_data_bidi_local: 262144, initial_max_stream_data_bidi_remote: 262144, initial_max_stream_data_uni: 262144, initial_max_streams_bidi: 100, initial_max_streams_uni: 100, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 2, initial_source_connection_id: Some(400000c5a5e5c3dd), retry_source_connection_id: None, max_datagram_frame_size: Some(65535), unknown_params: None } [2025-04-30T17:13:40.087789486Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 653 bytes [2025-04-30T17:13:40.087795717Z TRACE quiche_apps::client] got 112 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.087799755Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=91 pn=4330537 [2025-04-30T17:13:40.087805345Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=3 off=0 len=41 fin=false [2025-04-30T17:13:40.087810134Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=7 off=0 len=1 fin=false [2025-04-30T17:13:40.087813170Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=11 off=0 len=1 fin=false [2025-04-30T17:13:40.087816256Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm PADDING len=20 [2025-04-30T17:13:40.087826465Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 112 bytes [2025-04-30T17:13:40.087830102Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.087832456Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.087844900Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm SETTINGS stream=2 len=18 [2025-04-30T17:13:40.087856732Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef open GREASE stream 14 [2025-04-30T17:13:40.087865238Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm GREASE stream=0 len=0 [2025-04-30T17:13:40.087870788Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm GREASE stream=0 len=18 [2025-04-30T17:13:40.087877100Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm HEADERS stream=0 len=29 fin=true [2025-04-30T17:13:40.087882831Z DEBUG quiche_apps::common] Sent HTTP request [":method: GET", ":scheme: https", ":authority: server4", ":path: /ctczndirna", "user-agent: quiche"] [2025-04-30T17:13:40.087922134Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 3 is readable [2025-04-30T17:13:40.087927925Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 3 [2025-04-30T17:13:40.087931872Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef open peer's control stream 3 [2025-04-30T17:13:40.087935079Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 3 [2025-04-30T17:13:40.087938084Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 3 [2025-04-30T17:13:40.087941601Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 38 bytes on stream 3 [2025-04-30T17:13:40.087945228Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm SETTINGS max_field_section=Some(131072), qpack_max_table=Some(4096), qpack_blocked=Some(100) raw=Some([(1, 4096), (6, 131072), (7, 100), (8, 1), (16765559, 1), (630, 1), (51, 1), (727725890, 1), (374, 4207849484)]), additional_settings=Some([(16765559, 1), (727725890, 1), (374, 4207849484)]) stream=3 payload_len=38 [2025-04-30T17:13:40.087954485Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 7 is readable [2025-04-30T17:13:40.087957901Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 7 [2025-04-30T17:13:40.087961258Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 11 is readable [2025-04-30T17:13:40.087964694Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 11 [2025-04-30T17:13:40.087976536Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=49 pn=10 [2025-04-30T17:13:40.087979442Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=94 blocks=[4330537..4330545] ecn_counts=None [2025-04-30T17:13:40.087982578Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm CRYPTO off=0 len=36 [2025-04-30T17:13:40.087990422Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.414248ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=103 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 9, last_sent_packet: 10, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616456909 }, next_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, max_datagram_size: 1350, last_packet_size: None, iv: 236.895µ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-30T17:13:40.088008306Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13397 out_len=1247 left=1213 [2025-04-30T17:13:40.088014447Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=72 pn=11 [2025-04-30T17:13:40.088017052Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=26 blocks=[4330537..4330537] ecn_counts=None [2025-04-30T17:13:40.088019627Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[4a, f9, ea, d5, eb, 99, e5, ad, d7, e3, 16, e2, e9, 24, 36, 26, b4, 6f, 14, 15] reset_token=[ae, 59, 5e, 11, a5, 6e, bd, f4, e1, b3, 6e, 9f, fe, 95, 19, 0b] [2025-04-30T17:13:40.088025859Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm STREAM id=2 off=0 len=19 fin=false [2025-04-30T17:13:40.088032031Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.3727ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=201 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 10, last_sent_packet: 11, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 98, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616456909 }, next_time: Instant { tv_sec: 482, tv_nsec: 616693804 }, max_datagram_size: 1350, last_packet_size: Some(98), 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-30T17:13:40.088068909Z TRACE quiche_apps::client] written 201 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.088076554Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13299 out_len=1350 left=1324 [2025-04-30T17:13:40.088082375Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=6 pn=12 [2025-04-30T17:13:40.088086422Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm STREAM id=6 off=0 len=1 fin=false [2025-04-30T17:13:40.088094768Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.309441ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=233 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 11, last_sent_packet: 12, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616559632 }, next_time: Instant { tv_sec: 482, tv_nsec: 616693804 }, max_datagram_size: 1350, last_packet_size: None, iv: 298.994µ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-30T17:13:40.088146415Z TRACE quiche_apps::client] written 32 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.088155783Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13267 out_len=1350 left=1324 [2025-04-30T17:13:40.088162104Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=6 pn=13 [2025-04-30T17:13:40.088166012Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm STREAM id=10 off=0 len=1 fin=false [2025-04-30T17:13:40.088174979Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.229361ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=265 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 12, last_sent_packet: 13, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 32, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616559632 }, next_time: Instant { tv_sec: 482, tv_nsec: 616992798 }, 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-04-30T17:13:40.088215885Z TRACE quiche_apps::client] written 32 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.088223620Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13235 out_len=1350 left=1324 [2025-04-30T17:13:40.088229971Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=72 pn=14 [2025-04-30T17:13:40.088233789Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm STREAM id=0 off=0 len=67 fin=true [2025-04-30T17:13:40.088260880Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.142949ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=363 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 13, last_sent_packet: 14, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616706818 }, next_time: Instant { tv_sec: 482, tv_nsec: 616992798 }, max_datagram_size: 1350, last_packet_size: None, iv: 298.994µ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-30T17:13:40.088301616Z TRACE quiche_apps::client] written 98 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.088309190Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13137 out_len=1350 left=1324 [2025-04-30T17:13:40.088315763Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=31 pn=15 [2025-04-30T17:13:40.088319770Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm STREAM id=14 off=0 len=26 fin=true [2025-04-30T17:13:40.088330219Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=116.07402ms latest_rtt=38.811703ms srtt=38.811703ms min_rtt=38.811703ms rttvar=19.405851ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=420 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 14, last_sent_packet: 15, largest_acked: 0, rate_sample: RateSample { delivery_rate: 8579, is_app_limited: true, interval: 38.811703ms, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 568322775 }), send_elapsed: 0ns, ack_elapsed: 38.811703ms, rtt: 38.811703ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 57, rate: 434791, last_update: Instant { tv_sec: 482, tv_nsec: 616706818 }, next_time: Instant { tv_sec: 482, tv_nsec: 617291792 }, max_datagram_size: 1350, last_packet_size: Some(57), 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-30T17:13:40.088376747Z TRACE quiche_apps::client] written 57 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.088384031Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.118762898Z TRACE quiche_apps::client] got 58 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.118780571Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Handshake version=1 dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef scid=400000c5a5e5c3dd len=22 pn=4330546 [2025-04-30T17:13:40.118789347Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm ACK delay=20 blocks=[7..10] ecn_counts=None [2025-04-30T17:13:40.118794537Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 7 [2025-04-30T17:13:40.118797733Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 8 [2025-04-30T17:13:40.118800548Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 9 [2025-04-30T17:13:40.118803213Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 10 [2025-04-30T17:13:40.118822109Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 58 bytes [2025-04-30T17:13:40.118827038Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.118830084Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.118842396Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Handshake version=1 dcid=400000c5a5e5c3dd scid=e5616b97a38c3c42790f3e0954021948a08bb4ef len=8 pn=16 [2025-04-30T17:13:40.118845913Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=7 blocks=[4330546..4330546] ecn_counts=None [2025-04-30T17:13:40.118854329Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=91.668946ms latest_rtt=39.140076ms srtt=38.832749ms min_rtt=38.811703ms rttvar=14.596481ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=317 app_limited=true congestion_recovery_start_time=None Rate { delivered: 436, delivered_time: Instant { tv_sec: 482, tv_nsec: 647264600 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 15, last_sent_packet: 16, largest_acked: 10, rate_sample: RateSample { delivery_rate: 2631, is_app_limited: true, interval: 39.140076ms, delivered: 103, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 434555, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 617291792 }, max_datagram_size: 1350, last_packet_size: None, iv: 131.169µ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-30T17:13:40.118909833Z TRACE quiche_apps::client] written 62 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.118915243Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.119110559Z TRACE quiche_apps::client] got 432 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.119117552Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=411 pn=4330538 [2025-04-30T17:13:40.119123814Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm CRYPTO off=0 len=242 [2025-04-30T17:13:40.119143651Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm ACK delay=28 blocks=[11..11] ecn_counts=None [2025-04-30T17:13:40.119147408Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 11 [2025-04-30T17:13:40.119151045Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm HANDSHAKE_DONE [2025-04-30T17:13:40.119154642Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef dropped epoch 1 state [2025-04-30T17:13:40.119158910Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[40, 00, 00, cf, 87, 36, b1, 41] reset_token=[ce, 59, ad, da, c0, a2, 79, e0, f1, 66, f8, 6e, f0, 78, 4c, c5] [2025-04-30T17:13:40.119165412Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[40, 00, 00, d0, c1, e2, e9, df] reset_token=[30, 5d, 44, 3a, 6a, ec, 70, 6c, 03, 33, b9, f3, 7f, 00, dc, 47] [2025-04-30T17:13:40.119170472Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[40, 00, 00, d7, 95, ce, 45, 86] reset_token=[fb, 1b, 8d, 03, 5f, 4e, 5b, d1, 6c, 17, 69, 24, c3, 4b, 05, fc] [2025-04-30T17:13:40.119175401Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[40, 00, 00, dd, 89, ab, e9, bf] reset_token=[74, 4b, d9, 19, 2c, 2e, 16, b4, 6d, 5b, bd, 57, 58, c4, f0, 1f] [2025-04-30T17:13:40.119179549Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm PADDING len=30 [2025-04-30T17:13:40.119192162Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 432 bytes [2025-04-30T17:13:40.119195849Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.119199857Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.119210386Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13281 out_len=1350 left=1316 [2025-04-30T17:13:40.119216147Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=17 [2025-04-30T17:13:40.119220185Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=11 blocks=[4330538..4330538] ecn_counts=None [2025-04-30T17:13:40.119236756Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=83.622374ms latest_rtt=30.909511ms srtt=37.842343ms min_rtt=30.909511ms rttvar=12.928169ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=219 app_limited=true congestion_recovery_start_time=None Rate { delivered: 534, delivered_time: Instant { tv_sec: 482, tv_nsec: 647603315 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 16, last_sent_packet: 17, largest_acked: 11, rate_sample: RateSample { delivery_rate: 5135, is_app_limited: true, interval: 39.140076ms, delivered: 201, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 445929, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.119281270Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.119286209Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.119296488Z TRACE quiche_apps::client] got 112 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.119302559Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=91 pn=4330539 [2025-04-30T17:13:40.119310665Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm ACK delay=55 blocks=[11..14] ecn_counts=None [2025-04-30T17:13:40.119316035Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 12 [2025-04-30T17:13:40.119320383Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 13 [2025-04-30T17:13:40.119324250Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 14 [2025-04-30T17:13:40.119329620Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=0 len=62 fin=false [2025-04-30T17:13:40.119334720Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm PADDING len=4 [2025-04-30T17:13:40.119349397Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 112 bytes [2025-04-30T17:13:40.119353555Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.119355970Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.119358715Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.119363013Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.119366369Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.119369435Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.119372160Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm UNKNOWN raw_type=436 stream=0 payload_len=0 [2025-04-30T17:13:40.119377871Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.119380826Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.119384403Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 57 bytes on stream 0 [2025-04-30T17:13:40.119386928Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm HEADERS stream=0 payload_len=57 [2025-04-30T17:13:40.119397007Z TRACE quiche::h3::qpack::decoder] Header count=0 base=0 [2025-04-30T17:13:40.119401204Z TRACE quiche::h3::qpack::decoder] Indexed index=25 static=true [2025-04-30T17:13:40.119407767Z TRACE quiche::h3::qpack::decoder] Literal name_idx=83 static=true value=[104, 51, 61, 34, 58, 52, 52, 51, 34, 59, 32, 109, 97, 61, 51, 54, 48, 48] [2025-04-30T17:13:40.119414820Z TRACE quiche::h3::qpack::decoder] Literal Without Name Reference name=[112, 114, 105, 111, 114, 105, 116, 121] value=[117, 61, 51, 44, 105] [2025-04-30T17:13:40.119421602Z TRACE quiche::h3::qpack::decoder] Literal name_idx=6 static=true value=[87, 101, 100, 44, 32, 51, 48, 32, 65, 112, 114, 32, 50, 48, 50, 53, 32, 49, 55, 58, 49, 51, 58, 52, 48, 32, 71, 77, 84] [2025-04-30T17:13:40.119430459Z DEBUG quiche_apps::common] got response headers [(":status", "200"), ("alt-svc", "h3=\":443\"; ma=3600"), ("priority", "u=3,i"), ("date", "Wed, 30 Apr 2025 17:13:40 GMT")] on stream id 0 [2025-04-30T17:13:40.119440789Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13443 out_len=1350 left=1316 [2025-04-30T17:13:40.119444205Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=18 [2025-04-30T17:13:40.119446740Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=17 blocks=[4330538..4330539] ecn_counts=None [2025-04-30T17:13:40.119453152Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=76.644353ms latest_rtt=30.795454ms srtt=36.961481ms min_rtt=30.795454ms rttvar=11.457848ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=57 app_limited=true congestion_recovery_start_time=None Rate { delivered: 696, delivered_time: Instant { tv_sec: 482, tv_nsec: 647788252 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 608124524 }, end_of_app_limited: 17, last_sent_packet: 18, largest_acked: 14, rate_sample: RateSample { delivery_rate: 9274, is_app_limited: true, interval: 39.140076ms, delivered: 363, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 456556, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.119488939Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.119493177Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.120267178Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.120277588Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=1211 pn=4330540 [2025-04-30T17:13:40.120283839Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm ACK delay=66 blocks=[11..15] ecn_counts=None [2025-04-30T17:13:40.120287276Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef packet newly acked 15 [2025-04-30T17:13:40.120291945Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=62 len=1185 fin=false [2025-04-30T17:13:40.120303376Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.120306953Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.120309377Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.120312002Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.120320628Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.120323995Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.120326980Z TRACE quiche::h3::stream] e5616b97a38c3c42790f3e0954021948a08bb4ef read 1 bytes on stream 0 [2025-04-30T17:13:40.120329385Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm DATA stream=0 wire_payload_len=5120 [2025-04-30T17:13:40.120334554Z DEBUG quiche_apps::common] got 1182 bytes of response data on stream 0 [2025-04-30T17:13:40.120341748Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1316 [2025-04-30T17:13:40.120345004Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=19 [2025-04-30T17:13:40.120347409Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=8 blocks=[4330538..4330540] ecn_counts=None [2025-04-30T17:13:40.120353019Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=none latest_rtt=31.471408ms srtt=36.209221ms min_rtt=30.795454ms rttvar=10.097904ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 753, delivered_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, end_of_app_limited: 18, last_sent_packet: 19, largest_acked: 15, rate_sample: RateSample { delivery_rate: 10730, is_app_limited: true, interval: 39.140076ms, delivered: 420, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 466041, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.120387594Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.120391641Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.121275329Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.121285377Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=1211 pn=4330541 [2025-04-30T17:13:40.121292260Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=1247 len=1190 fin=false [2025-04-30T17:13:40.121299744Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.121303251Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.121305625Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.121308220Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.121312769Z DEBUG quiche_apps::common] got 1190 bytes of response data on stream 0 [2025-04-30T17:13:40.121319652Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1316 [2025-04-30T17:13:40.121322988Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=20 [2025-04-30T17:13:40.121325493Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330538..4330541] ecn_counts=None [2025-04-30T17:13:40.121336934Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=none latest_rtt=31.471408ms srtt=36.209221ms min_rtt=30.795454ms rttvar=10.097904ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 753, delivered_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, end_of_app_limited: 18, last_sent_packet: 20, largest_acked: 15, rate_sample: RateSample { delivery_rate: 10730, is_app_limited: true, interval: 39.140076ms, delivered: 420, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 466041, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.121369846Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.121373663Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.122284281Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.122294099Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=1211 pn=4330542 [2025-04-30T17:13:40.122300691Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=2437 len=1190 fin=false [2025-04-30T17:13:40.122319677Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.122323424Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.122325768Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.122328393Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.122332982Z DEBUG quiche_apps::common] got 1190 bytes of response data on stream 0 [2025-04-30T17:13:40.122339945Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1316 [2025-04-30T17:13:40.122343311Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=21 [2025-04-30T17:13:40.122345806Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=5 blocks=[4330538..4330542] ecn_counts=None [2025-04-30T17:13:40.122352338Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=none latest_rtt=31.471408ms srtt=36.209221ms min_rtt=30.795454ms rttvar=10.097904ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 753, delivered_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, end_of_app_limited: 18, last_sent_packet: 21, largest_acked: 15, rate_sample: RateSample { delivery_rate: 10730, is_app_limited: true, interval: 39.140076ms, delivered: 420, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 466041, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.122388586Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.122392754Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.123292852Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.123302560Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=1211 pn=4330543 [2025-04-30T17:13:40.123309172Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=3627 len=1190 fin=false [2025-04-30T17:13:40.123316827Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 1232 bytes [2025-04-30T17:13:40.123320293Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.123322668Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.123325253Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.123329711Z DEBUG quiche_apps::common] got 1190 bytes of response data on stream 0 [2025-04-30T17:13:40.123336403Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1316 [2025-04-30T17:13:40.123339599Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=8 pn=22 [2025-04-30T17:13:40.123341994Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm ACK delay=4 blocks=[4330538..4330543] ecn_counts=None [2025-04-30T17:13:40.123347985Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=none latest_rtt=31.471408ms srtt=36.209221ms min_rtt=30.795454ms rttvar=10.097904ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 753, delivered_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, end_of_app_limited: 18, last_sent_packet: 22, largest_acked: 15, rate_sample: RateSample { delivery_rate: 10730, is_app_limited: true, interval: 39.140076ms, delivered: 420, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 466041, last_update: Instant { tv_sec: 482, tv_nsec: 647322419 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, 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-30T17:13:40.123381678Z TRACE quiche_apps::client] written 34 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.123385575Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.123659128Z TRACE quiche_apps::client] got 432 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.123666392Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx pkt Short dcid=e5616b97a38c3c42790f3e0954021948a08bb4ef key_phase=false len=411 pn=4330544 [2025-04-30T17:13:40.123672093Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm STREAM id=0 off=4817 len=368 fin=true [2025-04-30T17:13:40.123675710Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef rx frm PADDING len=20 [2025-04-30T17:13:40.123682462Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 432 bytes [2025-04-30T17:13:40.123685889Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.123688263Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.123696078Z TRACE quiche::h3] e5616b97a38c3c42790f3e0954021948a08bb4ef stream id 0 is readable [2025-04-30T17:13:40.123701628Z DEBUG quiche_apps::common] got 368 bytes of response data on stream 0 [2025-04-30T17:13:40.123704363Z DEBUG quiche_apps::common] 1/1 responses received [2025-04-30T17:13:40.123706868Z INFO quiche_apps::common] 1/1 response(s) received in 83.739512ms, closing... [2025-04-30T17:13:40.123712969Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1324 [2025-04-30T17:13:40.123716236Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx pkt Short dcid=400000c5a5e5c3dd key_phase=false len=11 pn=23 [2025-04-30T17:13:40.123718670Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef tx frm APPLICATION_CLOSE err=100 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T17:13:40.123725493Z TRACE quiche::recovery::congestion::recovery] e5616b97a38c3c42790f3e0954021948a08bb4ef timer=101.585859ms latest_rtt=31.471408ms srtt=36.209221ms min_rtt=30.795454ms rttvar=10.097904ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=37 app_limited=true congestion_recovery_start_time=None Rate { delivered: 753, delivered_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, first_sent_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, end_of_app_limited: 22, last_sent_packet: 23, largest_acked: 15, rate_sample: RateSample { delivery_rate: 10730, is_app_limited: true, interval: 39.140076ms, delivered: 420, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 482, tv_nsec: 608124524 }), send_elapsed: 0ns, ack_elapsed: 39.140076ms, rtt: 39.140076ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 466041, last_update: Instant { tv_sec: 482, tv_nsec: 652197841 }, next_time: Instant { tv_sec: 482, tv_nsec: 647824303 }, max_datagram_size: 1350, last_packet_size: None, iv: 79.392µ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-30T17:13:40.123759076Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:38937 to 193.167.100.100:443 [2025-04-30T17:13:40.123762562Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.154194730Z TRACE quiche_apps::client] got 53 bytes from 193.167.100.100:443 to 0.0.0.0:38937 [2025-04-30T17:13:40.154208095Z TRACE quiche_apps::client] 0.0.0.0:38937: processed 53 bytes [2025-04-30T17:13:40.154212834Z TRACE quiche_apps::client] 0.0.0.0:38937: recv() would block [2025-04-30T17:13:40.154215599Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.154219596Z TRACE quiche_apps::client] 0.0.0.0:38937 -> 193.167.100.100:443: done writing [2025-04-30T17:13:40.354472038Z TRACE quiche_apps::client] timed out [2025-04-30T17:13:40.354486065Z TRACE quiche] e5616b97a38c3c42790f3e0954021948a08bb4ef draining timeout expired [2025-04-30T17:13:40.354539915Z TRACE quiche_apps::client] done reading [2025-04-30T17:13:40.354545165Z INFO quiche_apps::client] connection closed, recv=19 sent=24 lost=5 retrans=0 sent_bytes=1615 recv_bytes=17815 lost_bytes=0 [local_addr=0.0.0.0:38937 peer_addr=193.167.100.100:443 validation_state=Validated active=true recv=19 sent=24 lost=5 retrans=0 rtt=36.209221ms min_rtt=Some(30.795454ms) rttvar=10.097904ms cwnd=13500 sent_bytes=1615 recv_bytes=17815 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=10730]