[2025-04-30T11:49:17.096679726Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T11:49:17.096961375Z INFO quiche_apps::client] connecting to 193.167.100.100:443 from 0.0.0.0:41550 with scid 073ce7a4ff33a76022912fd4fed5d640691f8cc1 [2025-04-30T11:49:17.097001810Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 write message lvl=Initial len=266 [2025-04-30T11:49:17.097017650Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Initial version=1 dcid=96b069ba0383559e4955d7320507d818 scid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 len=270 pn=0 [2025-04-30T11:49:17.097020866Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm CRYPTO off=0 len=266 [2025-04-30T11:49:17.097034462Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=998.933295ms 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: 216, tv_nsec: 865623111 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, 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: 216, tv_nsec: 865623111 }, next_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:17.097101908Z TRACE quiche_apps::client] written 1200 [2025-04-30T11:49:18.097130892Z TRACE quiche_apps::client] timed out [2025-04-30T11:49:18.097164014Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 loss detection timeout expired [2025-04-30T11:49:18.097171608Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=997.795647ms 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: 216, tv_nsec: 865623111 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, 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: 216, tv_nsec: 865623111 }, next_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:18.097193990Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:18.097232623Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Initial version=1 dcid=96b069ba0383559e4955d7320507d818 scid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 len=270 pn=1 [2025-04-30T11:49:18.097236780Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm CRYPTO off=0 len=266 [2025-04-30T11:49:18.097254564Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=1.997955456s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=666 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, end_of_app_limited: 1, last_sent_packet: 1, 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: 217, tv_nsec: 865865044 }, next_time: Instant { tv_sec: 217, tv_nsec: 865865044 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:18.097389747Z TRACE quiche_apps::client] written 1200 bytes from 0.0.0.0:41550 to 193.167.100.100:443 [2025-04-30T11:49:18.097399305Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:18.607441746Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:18.607479066Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Initial version=1 dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 scid=509606446e49dee6 token= len=117 pn=0 [2025-04-30T11:49:18.607495907Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm ACK delay=125 blocks=[0..0] ecn_counts=None [2025-04-30T11:49:18.607503431Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 packet newly acked 0 [2025-04-30T11:49:18.607510805Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm CRYPTO off=0 len=90 [2025-04-30T11:49:18.607636150Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 set write secret lvl=Handshake [2025-04-30T11:49:18.607650598Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 set read secret lvl=Handshake [2025-04-30T11:49:18.607691855Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Handshake version=1 dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 scid=509606446e49dee6 len=1008 pn=0 [2025-04-30T11:49:18.607698988Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm CRYPTO off=0 len=737 [2025-04-30T11:49:18.607933558Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 write message lvl=Handshake len=52 [2025-04-30T11:49:18.607937746Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 set write secret lvl=OneRTT [2025-04-30T11:49:18.607945330Z TRACE quiche::tls] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 set read secret lvl=OneRTT [2025-04-30T11:49:18.607963665Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 connection established: proto=Ok("hq-interop") cipher=Some(AES256_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(96b069ba0383559e4955d7320507d818), max_idle_timeout: 30000, stateless_reset_token: Some(10832233875200203865118351497192389712), max_udp_payload_size: 2048, initial_max_data: 1638000, initial_max_stream_data_bidi_local: 16380, initial_max_stream_data_bidi_remote: 1474200, initial_max_stream_data_uni: 16380, initial_max_streams_bidi: 100, initial_max_streams_uni: 3, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: true, active_conn_id_limit: 8, initial_source_connection_id: Some(509606446e49dee6), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T11:49:18.607975837Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm PADDING len=250 [2025-04-30T11:49:18.607989343Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 1200 bytes [2025-04-30T11:49:18.607993991Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:18.607996697Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:18.608005593Z DEBUG quiche_apps::common] sending HTTP request "GET /imjnkyptmp\r\n" [2025-04-30T11:49:18.608087657Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Initial version=1 dcid=509606446e49dee6 scid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 len=6 pn=2 [2025-04-30T11:49:18.608091574Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm ACK delay=76 blocks=[0..0] ecn_counts=None [2025-04-30T11:49:18.608100381Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=4.020622677s latest_rtt=1.510504386s srtt=1.510504386s min_rtt=1.510504386s rttvar=755.252193ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 218, tv_nsec: 376127497 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 220, is_app_limited: true, interval: 1.510504386s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 216, tv_nsec: 865623111 }), send_elapsed: 0ns, ack_elapsed: 1.510504386s, rtt: 1.510504386s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11171, last_update: Instant { tv_sec: 218, tv_nsec: 376615924 }, next_time: Instant { tv_sec: 218, tv_nsec: 376615964 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:18.608121030Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Handshake version=1 dcid=509606446e49dee6 scid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 len=61 pn=3 [2025-04-30T11:49:18.608123845Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm ACK delay=53 blocks=[0..0] ecn_counts=None [2025-04-30T11:49:18.608126480Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm CRYPTO off=0 len=52 [2025-04-30T11:49:18.608132481Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=4.020590867s latest_rtt=1.510504386s srtt=1.510504386s min_rtt=1.510504386s rttvar=755.252193ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=448 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 218, tv_nsec: 376127497 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 220, is_app_limited: true, interval: 1.510504386s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 216, tv_nsec: 865623111 }), send_elapsed: 0ns, ack_elapsed: 1.510504386s, rtt: 1.510504386s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11171, last_update: Instant { tv_sec: 218, tv_nsec: 376733224 }, next_time: Instant { tv_sec: 218, tv_nsec: 376615964 }, max_datagram_size: 1350, last_packet_size: None, iv: 10.294513ms, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:18.608143151Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 dropped epoch 0 state [2025-04-30T11:49:18.608147790Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13385 out_len=1174 left=1148 [2025-04-30T11:49:18.608159762Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Short dcid=509606446e49dee6 key_phase=false len=1148 pn=4 [2025-04-30T11:49:18.608162407Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[27, 6b, 08, 9f, 75, e9, da, 12, aa, 15, c5, 3c, 89, 19, c9, d0, 78, b1, 60, df] reset_token=[f6, c8, b6, 57, 9e, b3, e0, 43, 12, f4, e4, 90, db, 44, f3, 3f] [2025-04-30T11:49:18.608173228Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[d4, 60, 15, b9, c3, 12, f7, dd, b2, f8, 4d, e8, 3c, 8f, a8, ab, 73, 16, 3a, 74] reset_token=[d7, 2b, 60, 8f, 2c, b5, 2d, a7, e8, 11, 47, 6e, 1f, 3b, 17, 6a] [2025-04-30T11:49:18.608178468Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[a4, 05, 3d, 4b, 73, 1b, 34, 8e, 42, 12, 1a, 68, 7f, 33, 59, 1a, 49, e0, 11, 85] reset_token=[0a, 7f, 5a, 1b, 5d, 9f, d0, 17, d5, da, 35, 7d, 90, 5a, a6, 05] [2025-04-30T11:49:18.608183547Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[ec, d3, 94, 9e, 23, 69, 81, fd, c1, e3, 53, 6b, 11, 06, 60, 88, 7a, 56, 8a, 58] reset_token=[df, 5d, 85, e8, bd, 52, 23, 92, 12, 2f, a1, b1, 14, 88, b2, e0] [2025-04-30T11:49:18.608188516Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[e8, 42, c8, de, 84, e3, 54, 7f, 55, 00, bd, bf, aa, b8, da, d2, 69, 30, 47, 99] reset_token=[9b, 38, d0, 21, 85, dd, da, 3c, 9d, 6d, 7f, bb, 12, f7, 50, 94] [2025-04-30T11:49:18.608193295Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[bb, e7, 05, a8, 13, 58, 07, 58, 15, d4, 8a, 5e, ff, 03, 09, 53, 74, da, 1c, b8] reset_token=[7f, ab, 30, 57, 1d, c5, 89, 44, dd, ec, aa, 2f, 7a, 40, 79, b7] [2025-04-30T11:49:18.608198265Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[ae, b6, e2, 50, 99, c9, 40, 2c, 8b, c8, ae, eb, 31, 86, ed, 64, ce, c0, 27, 15] reset_token=[4e, e2, 90, 7d, 29, d2, 88, 43, 4e, 9a, 4a, 0d, 06, a0, d3, a5] [2025-04-30T11:49:18.608203074Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T11:49:18.608205689Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm PADDING len=846 [2025-04-30T11:49:18.608214525Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=4.531376993s latest_rtt=1.510504386s srtt=1.510504386s min_rtt=1.510504386s rttvar=755.252193ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1289 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 218, tv_nsec: 376127497 }, first_sent_time: Instant { tv_sec: 216, tv_nsec: 865623111 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 220, is_app_limited: true, interval: 1.510504386s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 216, tv_nsec: 865623111 }), send_elapsed: 0ns, ack_elapsed: 1.510504386s, rtt: 1.510504386s } } pacer=Pacer { enabled: true, capacity: 13500, used: 1174, rate: 11171, last_update: Instant { tv_sec: 218, tv_nsec: 376733224 }, next_time: Instant { tv_sec: 218, tv_nsec: 387027737 }, max_datagram_size: 1350, last_packet_size: Some(1174), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:18.608268346Z TRACE quiche_apps::client] written 1350 bytes from 0.0.0.0:41550 to 193.167.100.100:443 [2025-04-30T11:49:18.608273295Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:19.600731561Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:19.600769782Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 dropped invalid packet [2025-04-30T11:49:19.600775243Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 1200 bytes [2025-04-30T11:49:19.600795490Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:19.600798937Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:19.600808004Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:19.605507078Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:19.605519742Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 dropped invalid packet [2025-04-30T11:49:19.605523238Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 1200 bytes [2025-04-30T11:49:19.605526955Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:19.605529380Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:19.605534419Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:19.606507064Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:19.606521912Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 dropped invalid packet [2025-04-30T11:49:19.606526260Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 1200 bytes [2025-04-30T11:49:19.606530888Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:19.606533934Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:19.606539675Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:20.112775702Z TRACE quiche_apps::client] got 646 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:20.112814565Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Handshake version=1 dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 scid=509606446e49dee6 len=22 pn=4 [2025-04-30T11:49:20.112829413Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm ACK delay=0 blocks=[3..3] ecn_counts=None [2025-04-30T11:49:20.112836898Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 packet newly acked 3 [2025-04-30T11:49:20.112864900Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Short dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 key_phase=false len=567 pn=0 [2025-04-30T11:49:20.112872975Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm CRYPTO off=0 len=546 [2025-04-30T11:49:20.112914404Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 646 bytes [2025-04-30T11:49:20.112919844Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:20.112923180Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:20.112934993Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12326 out_len=1350 left=1319 [2025-04-30T11:49:20.112941204Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Short dcid=509606446e49dee6 key_phase=false len=5 pn=5 [2025-04-30T11:49:20.112944360Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm ACK delay=8 blocks=[0..0] ecn_counts=None [2025-04-30T11:49:20.112953808Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=2.30133531s latest_rtt=1.504847073s srtt=1.509797221s min_rtt=1.504847073s rttvar=567.853472ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1174 app_limited=true congestion_recovery_start_time=None Rate { delivered: 448, delivered_time: Instant { tv_sec: 219, tv_nsec: 881463037 }, first_sent_time: Instant { tv_sec: 218, tv_nsec: 376615964 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 3, rate_sample: RateSample { delivery_rate: 76, is_app_limited: true, interval: 1.510992853s, delivered: 115, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 218, tv_nsec: 376127497 }), send_elapsed: 1.510992853s, ack_elapsed: 1.50533554s, rtt: 1.504847073s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11176, last_update: Instant { tv_sec: 219, tv_nsec: 881583555 }, next_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:20.113036384Z TRACE quiche_apps::client] written 31 bytes from 0.0.0.0:41550 to 193.167.100.100:443 [2025-04-30T11:49:20.113042516Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:20.113832618Z TRACE quiche_apps::client] got 168 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:20.113842056Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Short dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 key_phase=false len=147 pn=1 [2025-04-30T11:49:20.113849299Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm ACK delay=250 blocks=[4..4] ecn_counts=None [2025-04-30T11:49:20.113853086Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 packet newly acked 4 [2025-04-30T11:49:20.113857615Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm HANDSHAKE_DONE [2025-04-30T11:49:20.113861953Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 dropped epoch 1 state [2025-04-30T11:49:20.113866802Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm NEW_TOKEN len=37 [2025-04-30T11:49:20.113870569Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[63, b9, ec, 3b, 61, 10, b4, c3] reset_token=[65, c1, db, c3, 0c, 11, ec, 1c, e0, f0, 43, cd, dd, 73, cb, d9] [2025-04-30T11:49:20.113877442Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[5b, 41, a3, fc, 6c, 6c, c5, e5] reset_token=[18, a6, e8, 0c, f6, ec, 50, bc, a8, 6a, ad, 3f, 8e, fe, 7c, f7] [2025-04-30T11:49:20.113882001Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[91, 6b, c7, fe, 55, 7c, 82, 54] reset_token=[77, 57, 21, 2a, 85, 0b, a3, 83, 3a, 60, 98, 19, a5, 5c, a1, 4b] [2025-04-30T11:49:20.113924812Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 168 bytes [2025-04-30T11:49:20.113929350Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:20.113931785Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:20.113938858Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:49:20.113942425Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Short dcid=509606446e49dee6 key_phase=false len=5 pn=6 [2025-04-30T11:49:20.113944960Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm ACK delay=12 blocks=[0..1] ecn_counts=None [2025-04-30T11:49:20.113951422Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=none latest_rtt=1.495467449s srtt=1.508005999s min_rtt=1.495467449s rttvar=429.472547ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1622, delivered_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, first_sent_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 4, rate_sample: RateSample { delivery_rate: 853, is_app_limited: true, interval: 1.510992853s, delivered: 1289, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 218, tv_nsec: 376127497 }), send_elapsed: 1.510992853s, ack_elapsed: 1.50533554s, rtt: 1.504847073s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11190, last_update: Instant { tv_sec: 219, tv_nsec: 881583555 }, next_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:20.113994704Z TRACE quiche_apps::client] written 31 bytes from 0.0.0.0:41550 to 193.167.100.100:443 [2025-04-30T11:49:20.113999914Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:20.115895994Z TRACE quiche_apps::client] got 1066 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:20.115910852Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx pkt Short dcid=073ce7a4ff33a76022912fd4fed5d640691f8cc1 key_phase=false len=1045 pn=2 [2025-04-30T11:49:20.115920020Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 rx frm STREAM id=0 off=0 len=1024 fin=true [2025-04-30T11:49:20.115930189Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 1066 bytes [2025-04-30T11:49:20.115934868Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:20.115937913Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:20.115945518Z TRACE quiche_apps::common] received 1024 bytes [2025-04-30T11:49:20.115948894Z TRACE quiche_apps::common] stream 0 has 1024 bytes (fin? true) [2025-04-30T11:49:20.115952461Z DEBUG quiche_apps::common] 1/1 responses received [2025-04-30T11:49:20.115955536Z INFO quiche_apps::common] 1/1 response(s) received in 3.018849681s, closing... [2025-04-30T11:49:20.115964032Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1324 [2025-04-30T11:49:20.115968491Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx pkt Short dcid=509606446e49dee6 key_phase=false len=10 pn=7 [2025-04-30T11:49:20.115971617Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T11:49:20.115980674Z TRACE quiche::recovery::congestion::recovery] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 timer=3.250875949s latest_rtt=1.495467449s srtt=1.508005999s min_rtt=1.495467449s rttvar=429.472547ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=36 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1622, delivered_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, first_sent_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, end_of_app_limited: 6, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { delivery_rate: 853, is_app_limited: true, interval: 1.510992853s, delivered: 1289, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 218, tv_nsec: 376127497 }), send_elapsed: 1.510992853s, ack_elapsed: 1.50533554s, rtt: 1.504847073s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11190, last_update: Instant { tv_sec: 219, tv_nsec: 884615500 }, next_time: Instant { tv_sec: 219, tv_nsec: 881583555 }, max_datagram_size: 1350, last_packet_size: None, iv: 3.217158ms, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:49:20.116027623Z TRACE quiche_apps::client] written 36 bytes from 0.0.0.0:41550 to 193.167.100.100:443 [2025-04-30T11:49:20.116032712Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:21.617059910Z TRACE quiche_apps::client] got 42 bytes from 193.167.100.100:443 to 0.0.0.0:41550 [2025-04-30T11:49:21.617099596Z TRACE quiche_apps::client] 0.0.0.0:41550: processed 42 bytes [2025-04-30T11:49:21.617107059Z TRACE quiche_apps::client] 0.0.0.0:41550: recv() would block [2025-04-30T11:49:21.617112009Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:21.617121277Z TRACE quiche_apps::client] 0.0.0.0:41550 -> 193.167.100.100:443: done writing [2025-04-30T11:49:29.798217136Z TRACE quiche_apps::client] timed out [2025-04-30T11:49:29.798270847Z TRACE quiche] 073ce7a4ff33a76022912fd4fed5d640691f8cc1 draining timeout expired [2025-04-30T11:49:29.798313938Z TRACE quiche_apps::client] done reading [2025-04-30T11:49:29.798318506Z INFO quiche_apps::client] connection closed, recv=6 sent=8 lost=0 retrans=1 sent_bytes=2114 recv_bytes=3080 lost_bytes=0 [local_addr=0.0.0.0:41550 peer_addr=193.167.100.100:443 validation_state=Validated active=true recv=6 sent=8 lost=0 retrans=1 rtt=1.508005999s min_rtt=Some(1.495467449s) rttvar=429.472547ms cwnd=13500 sent_bytes=2114 recv_bytes=3080 lost_bytes=0 stream_retrans_bytes=266 pmtu=1350 delivery_rate=853]