[2025-04-30T21:42:38.793142051Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T21:42:38.793446006Z INFO quiche_apps::client] connecting to 193.167.100.100:443 from 0.0.0.0:44506 with scid 717438ef72656e572123b353f0ff3645e294c7b2 [2025-04-30T21:42:38.793495037Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 write message lvl=Initial len=451 [2025-04-30T21:42:38.793514322Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Initial version=1 dcid=a3ca1d1d6c7033b1731a2c01629610aa scid=717438ef72656e572123b353f0ff3645e294c7b2 len=455 pn=0 [2025-04-30T21:42:38.793517508Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm CRYPTO off=0 len=451 [2025-04-30T21:42:38.793530863Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=998.923108ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=518 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 289, tv_nsec: 833137330 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 833137330 }, 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: 289, tv_nsec: 833137330 }, next_time: Instant { tv_sec: 289, tv_nsec: 833137330 }, 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-30T21:42:38.793610301Z TRACE quiche_apps::client] written 1200 [2025-04-30T21:42:38.827873926Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.827892571Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Initial version=1 dcid=717438ef72656e572123b353f0ff3645e294c7b2 scid=a3378437620b5db6965c2a7b499d7681 token= len=123 pn=0 [2025-04-30T21:42:38.827904573Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm ACK delay=1200 blocks=[0..0] ecn_counts=None [2025-04-30T21:42:38.827910143Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 packet newly acked 0 [2025-04-30T21:42:38.827915724Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm CRYPTO off=0 len=96 [2025-04-30T21:42:38.827995272Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 set write secret lvl=Handshake [2025-04-30T21:42:38.828003968Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 set read secret lvl=Handshake [2025-04-30T21:42:38.828024165Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Handshake version=1 dcid=717438ef72656e572123b353f0ff3645e294c7b2 scid=a3378437620b5db6965c2a7b499d7681 len=1018 pn=0 [2025-04-30T21:42:38.828029485Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm CRYPTO off=0 len=140 [2025-04-30T21:42:38.828054923Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 write message lvl=Handshake len=36 [2025-04-30T21:42:38.828057798Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 set write secret lvl=OneRTT [2025-04-30T21:42:38.828063849Z TRACE quiche::tls] 717438ef72656e572123b353f0ff3645e294c7b2 set read secret lvl=OneRTT [2025-04-30T21:42:38.828076923Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 connection established: proto=Ok("hq-interop") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=true TransportParams { original_destination_connection_id: Some(a3ca1d1d6c7033b1731a2c01629610aa), max_idle_timeout: 300000, stateless_reset_token: None, max_udp_payload_size: 65527, initial_max_data: 3750000, initial_max_stream_data_bidi_local: 3750000, initial_max_stream_data_bidi_remote: 3750000, initial_max_stream_data_uni: 3750000, 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: 3, initial_source_connection_id: Some(a3378437620b5db6965c2a7b499d7681), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T21:42:38.828097051Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm PADDING len=857 [2025-04-30T21:42:38.828108372Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.828112830Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.828115395Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.828123079Z DEBUG quiche_apps::common] sending HTTP request "GET /cefpyuiume\r\n" [2025-04-30T21:42:38.828181547Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Initial version=1 dcid=a3378437620b5db6965c2a7b499d7681 scid=717438ef72656e572123b353f0ff3645e294c7b2 len=5 pn=1 [2025-04-30T21:42:38.828185345Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=36 blocks=[0..0] ecn_counts=None [2025-04-30T21:42:38.828193299Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=102.99642ms latest_rtt=34.433892ms srtt=34.433892ms min_rtt=34.433892ms rttvar=17.216946ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 518, delivered_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { delivery_rate: 15043, is_app_limited: true, interval: 34.433892ms, delivered: 518, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 833137330 }), send_elapsed: 0ns, ack_elapsed: 34.433892ms, rtt: 34.433892ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 490069, last_update: Instant { tv_sec: 289, tv_nsec: 867757568 }, next_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, 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-30T21:42:38.828212175Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Handshake version=1 dcid=a3378437620b5db6965c2a7b499d7681 scid=717438ef72656e572123b353f0ff3645e294c7b2 len=45 pn=2 [2025-04-30T21:42:38.828214970Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=23 blocks=[0..0] ecn_counts=None [2025-04-30T21:42:38.828217534Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm CRYPTO off=0 len=36 [2025-04-30T21:42:38.828223185Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=103.251733ms latest_rtt=34.433892ms srtt=34.433892ms min_rtt=34.433892ms rttvar=17.216946ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=107 app_limited=true congestion_recovery_start_time=None Rate { delivered: 518, delivered_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 15043, is_app_limited: true, interval: 34.433892ms, delivered: 518, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 833137330 }), send_elapsed: 0ns, ack_elapsed: 34.433892ms, rtt: 34.433892ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 490069, last_update: Instant { tv_sec: 289, tv_nsec: 867856261 }, next_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, max_datagram_size: 1350, last_packet_size: None, iv: 218.337µ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-30T21:42:38.828238313Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 dropped epoch 0 state [2025-04-30T21:42:38.828242912Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13393 out_len=1175 left=1141 [2025-04-30T21:42:38.828254072Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=a3378437620b5db6965c2a7b499d7681 key_phase=false len=1141 pn=3 [2025-04-30T21:42:38.828256567Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[45, 85, 31, a3, db, 6a, c1, ef, 93, 6b, 98, 7b, e7, ed, 1e, 75, e9, 4f, 68, fc] reset_token=[74, a8, 50, e0, 66, 50, 2c, 35, e9, a0, ac, a6, 4e, 8e, 81, 0a] [2025-04-30T21:42:38.828263279Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[15, d5, 8a, 88, 33, 5e, fd, 10, b1, 39, 05, fd, 22, 39, 07, 69, 46, 99, be, 95] reset_token=[18, 88, 05, f3, ef, 63, 87, 76, 27, 51, da, 5b, 1e, 8f, d4, e0] [2025-04-30T21:42:38.828268609Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T21:42:38.828271164Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm PADDING len=1039 [2025-04-30T21:42:38.828277666Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=103.197322ms latest_rtt=34.433892ms srtt=34.433892ms min_rtt=34.433892ms rttvar=17.216946ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1282 app_limited=true congestion_recovery_start_time=None Rate { delivered: 518, delivered_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 15043, is_app_limited: true, interval: 34.433892ms, delivered: 518, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 833137330 }), send_elapsed: 0ns, ack_elapsed: 34.433892ms, rtt: 34.433892ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 1175, rate: 490069, last_update: Instant { tv_sec: 289, tv_nsec: 867856261 }, next_time: Instant { tv_sec: 289, tv_nsec: 868074598 }, max_datagram_size: 1350, last_packet_size: Some(1175), 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-30T21:42:38.828339291Z TRACE quiche_apps::client] written 1350 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.828347546Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.863081082Z TRACE quiche_apps::client] got 1452 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.863104877Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1431 pn=0 [2025-04-30T21:42:38.863116508Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 path ID 0 now see SCID with seq num 1 [2025-04-30T21:42:38.863124072Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm PING mtu_probe=None [2025-04-30T21:42:38.863140913Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm PADDING len=1413 [2025-04-30T21:42:38.863159077Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1452 bytes [2025-04-30T21:42:38.863167833Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.863172502Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.863199512Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=12218 out_len=1350 left=1311 [2025-04-30T21:42:38.863207407Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=a3378437620b5db6965c2a7b499d7681 key_phase=false len=5 pn=4 [2025-04-30T21:42:38.863210673Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=12 blocks=[0..0] ecn_counts=None [2025-04-30T21:42:38.863223186Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=68.251191ms latest_rtt=34.433892ms srtt=34.433892ms min_rtt=34.433892ms rttvar=17.216946ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1282 app_limited=true congestion_recovery_start_time=None Rate { delivered: 518, delivered_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 867757598 }, end_of_app_limited: 2, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 15043, is_app_limited: true, interval: 34.433892ms, delivered: 518, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 833137330 }), send_elapsed: 0ns, ack_elapsed: 34.433892ms, rtt: 34.433892ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 490069, last_update: Instant { tv_sec: 289, tv_nsec: 902872543 }, next_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, 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-30T21:42:38.863278348Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.863283999Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.863294829Z TRACE quiche_apps::client] got 155 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.863299378Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=134 pn=1 [2025-04-30T21:42:38.863306180Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm ACK delay=164 blocks=[3..3] ecn_counts=None [2025-04-30T21:42:38.863310628Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 packet newly acked 3 [2025-04-30T21:42:38.863342478Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.863356514Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 dropped epoch 1 state [2025-04-30T21:42:38.863365941Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=1 conn_id=[92, 90, b7, 3f, 12, ae, a2, 6e, 84, f2, b2, ea, b9, ee, 23, f9] reset_token=[24, f3, bd, 05, ae, 5a, 2b, 09, 51, 4d, ac, b6, e6, 8b, 85, bc] [2025-04-30T21:42:38.863378405Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 path ID 0 changed DCID: old seq num 0 new seq num 1 [2025-04-30T21:42:38.863386039Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=1 conn_id=[6a, 2b, 62, b9, 47, 84, ac, d3, 65, af, e6, 46, fc, dc, 14, f5] reset_token=[d2, a3, f8, 3e, c7, 3b, 87, be, ab, 65, 94, 00, 52, 6d, af, 3b] [2025-04-30T21:42:38.863394685Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=1 conn_id=[03, 89, 6d, 31, e1, a4, fb, 6d, a8, 64, 38, 94, 0e, 18, fe, 51] reset_token=[15, 1e, de, 51, 5b, 03, 30, ae, 6a, 67, 01, 48, 8b, 64, b7, 06] [2025-04-30T21:42:38.863399794Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm RETIRE_CONNECTION_ID seq_num=0 [2025-04-30T21:42:38.863416676Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 155 bytes [2025-04-30T21:42:38.863421735Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.863430722Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.863434028Z INFO quiche_apps::client] Retiring source CID 717438ef72656e572123b353f0ff3645e294c7b2 [2025-04-30T21:42:38.863446761Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1311 [2025-04-30T21:42:38.863452652Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=47 pn=5 [2025-04-30T21:42:38.863455938Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=18 blocks=[0..1] ecn_counts=None [2025-04-30T21:42:38.863459986Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=1 conn_id=[b6, 49, 4f, 3d, 2f, ad, b4, 05, 1e, 8f, 03, fb, 38, 2d, 89, 19, 21, e8, 08, 2f] reset_token=[87, 80, 24, 23, 99, 8f, 3f, cc, 2a, b3, ef, 08, d7, 94, 0c, 94] [2025-04-30T21:42:38.863467089Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm RETIRE_CONNECTION_ID seq_num=0 [2025-04-30T21:42:38.863475825Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=111.582985ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 5, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, max_datagram_size: 1350, last_packet_size: None, iv: 165.566µ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-30T21:42:38.863521069Z TRACE quiche_apps::client] written 81 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.863526459Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.864191034Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.864198407Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=2 [2025-04-30T21:42:38.864204378Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.864207975Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=0 len=1191 fin=false [2025-04-30T21:42:38.864216080Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.864219657Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.864221981Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.864227321Z TRACE quiche_apps::common] received 1191 bytes [2025-04-30T21:42:38.864230156Z TRACE quiche_apps::common] stream 0 has 1191 bytes (fin? false) [2025-04-30T21:42:38.864236889Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.864240065Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=6 [2025-04-30T21:42:38.864242519Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=4 blocks=[0..2] ecn_counts=None [2025-04-30T21:42:38.864254331Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=110.804649ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 6, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.864288535Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.864292472Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.865200588Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.865210747Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=3 [2025-04-30T21:42:38.865216688Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.865219874Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=1191 len=1189 fin=false [2025-04-30T21:42:38.865227468Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.865231025Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.865233379Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.865264076Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.865266741Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.865273985Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.865277281Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=7 [2025-04-30T21:42:38.865279725Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=7 blocks=[0..3] ecn_counts=None [2025-04-30T21:42:38.865286708Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=109.772262ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 7, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.865337793Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.865348793Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.866207148Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.866214311Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=4 [2025-04-30T21:42:38.866220232Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.866223498Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=2380 len=1189 fin=false [2025-04-30T21:42:38.866230982Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.866234558Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.866236983Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.866241151Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.866243345Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.866249767Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.866253113Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=8 [2025-04-30T21:42:38.866255517Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=4 blocks=[0..4] ecn_counts=None [2025-04-30T21:42:38.866262481Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=108.79647ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 8, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.866295081Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.866299028Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.866688481Z TRACE quiche_apps::client] got 572 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.866698500Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=551 pn=5 [2025-04-30T21:42:38.866704201Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.866707176Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=3569 len=527 fin=false [2025-04-30T21:42:38.866719830Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 572 bytes [2025-04-30T21:42:38.866723497Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.866725831Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.866729788Z TRACE quiche_apps::common] received 527 bytes [2025-04-30T21:42:38.866732013Z TRACE quiche_apps::common] stream 0 has 527 bytes (fin? false) [2025-04-30T21:42:38.866738534Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.866741650Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=9 [2025-04-30T21:42:38.866744055Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=5 blocks=[0..5] ecn_counts=None [2025-04-30T21:42:38.866750286Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=108.308694ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 9, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.866783358Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.866787365Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.867698327Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.867708095Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=6 [2025-04-30T21:42:38.867713806Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.867717212Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=4096 len=1189 fin=false [2025-04-30T21:42:38.867724456Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.867728002Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.867730327Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.867734454Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.867736708Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.867743391Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.867746517Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=10 [2025-04-30T21:42:38.867748961Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=4 blocks=[0..6] ecn_counts=None [2025-04-30T21:42:38.867754912Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=107.304128ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 10, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.867793734Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.867797912Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.868707912Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.868717380Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=7 [2025-04-30T21:42:38.868723110Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.868726196Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=5285 len=1189 fin=false [2025-04-30T21:42:38.868733470Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.868737046Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.868739441Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.868743598Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.868745813Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.868752184Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.868755290Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=11 [2025-04-30T21:42:38.868757684Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=4 blocks=[0..7] ecn_counts=None [2025-04-30T21:42:38.868763926Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=106.295094ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 11, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.868802257Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.868806475Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.869716184Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.869726314Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=8 [2025-04-30T21:42:38.869732004Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.869735100Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=6474 len=1189 fin=false [2025-04-30T21:42:38.869742493Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.869746040Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.869748424Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.869752452Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.869754676Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.869761098Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.869764184Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=12 [2025-04-30T21:42:38.869766538Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=4 blocks=[0..8] ecn_counts=None [2025-04-30T21:42:38.869773100Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=105.2859ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 12, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.869805180Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.869809077Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.870198470Z TRACE quiche_apps::client] got 574 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.870205393Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=553 pn=9 [2025-04-30T21:42:38.870210863Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.870213729Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=7663 len=529 fin=false [2025-04-30T21:42:38.870220962Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 574 bytes [2025-04-30T21:42:38.870224459Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.870226783Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.870236030Z TRACE quiche_apps::common] received 529 bytes [2025-04-30T21:42:38.870238354Z TRACE quiche_apps::common] stream 0 has 529 bytes (fin? false) [2025-04-30T21:42:38.870245197Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.870248273Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=13 [2025-04-30T21:42:38.870250657Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=5 blocks=[0..9] ecn_counts=None [2025-04-30T21:42:38.870256809Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=104.802212ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 13, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.870289048Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.870292956Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.871216090Z TRACE quiche_apps::client] got 1232 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.871229214Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=1211 pn=10 [2025-04-30T21:42:38.871235927Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.871239373Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=8192 len=1189 fin=false [2025-04-30T21:42:38.871248520Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 1232 bytes [2025-04-30T21:42:38.871252918Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.871255403Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.871260372Z TRACE quiche_apps::common] received 1189 bytes [2025-04-30T21:42:38.871262607Z TRACE quiche_apps::common] stream 0 has 1189 bytes (fin? false) [2025-04-30T21:42:38.871289316Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1311 [2025-04-30T21:42:38.871293955Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=5 pn=14 [2025-04-30T21:42:38.871296419Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm ACK delay=7 blocks=[0..10] ecn_counts=None [2025-04-30T21:42:38.871304695Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=103.754205ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=81 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 4, last_sent_packet: 14, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 903125813 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, 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-30T21:42:38.871373583Z TRACE quiche_apps::client] written 39 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.871383070Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:38.871959471Z TRACE quiche_apps::client] got 904 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.871968317Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=883 pn=11 [2025-04-30T21:42:38.871976743Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.871981802Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=9381 len=859 fin=false [2025-04-30T21:42:38.871990639Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 904 bytes [2025-04-30T21:42:38.871995488Z TRACE quiche_apps::client] got 57 bytes from 193.167.100.100:443 to 0.0.0.0:44506 [2025-04-30T21:42:38.871998503Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx pkt Short dcid=458531a3db6ac1ef936b987be7ed1e75e94f68fc key_phase=false len=36 pn=12 [2025-04-30T21:42:38.872002240Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm HANDSHAKE_DONE [2025-04-30T21:42:38.872004745Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm STREAM id=0 off=10240 len=0 fin=true [2025-04-30T21:42:38.872008061Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 rx frm PADDING len=13 [2025-04-30T21:42:38.872012620Z TRACE quiche_apps::client] 0.0.0.0:44506: processed 57 bytes [2025-04-30T21:42:38.872015956Z TRACE quiche_apps::client] 0.0.0.0:44506: recv() would block [2025-04-30T21:42:38.872018320Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:38.872024061Z TRACE quiche_apps::common] received 859 bytes [2025-04-30T21:42:38.872026305Z TRACE quiche_apps::common] stream 0 has 859 bytes (fin? true) [2025-04-30T21:42:38.872028719Z DEBUG quiche_apps::common] 1/1 responses received [2025-04-30T21:42:38.872031104Z INFO quiche_apps::common] 1/1 response(s) received in 78.417026ms, closing... [2025-04-30T21:42:38.872037716Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13419 out_len=1350 left=1316 [2025-04-30T21:42:38.872040942Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx pkt Short dcid=9290b73f12aea26e84f2b2eab9ee23f9 key_phase=false len=10 pn=15 [2025-04-30T21:42:38.872043346Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T21:42:38.872050059Z TRACE quiche::recovery::congestion::recovery] 717438ef72656e572123b353f0ff3645e294c7b2 timer=111.601208ms latest_rtt=34.906346ms srtt=34.492948ms min_rtt=34.433892ms rttvar=13.030822ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=125 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1693, delivered_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, first_sent_time: Instant { tv_sec: 289, tv_nsec: 902872543 }, end_of_app_limited: 14, last_sent_packet: 15, largest_acked: 3, rate_sample: RateSample { delivery_rate: 33358, is_app_limited: true, interval: 35.223346ms, delivered: 1175, prior_delivered: 518, prior_time: Some(Instant { tv_sec: 289, tv_nsec: 867757598 }), send_elapsed: 317µs, ack_elapsed: 35.223346ms, rtt: 34.906346ms } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 489230, last_update: Instant { tv_sec: 289, tv_nsec: 911718060 }, next_time: Instant { tv_sec: 289, tv_nsec: 904082087 }, max_datagram_size: 1350, last_packet_size: None, iv: 89.937µ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-30T21:42:38.872088751Z TRACE quiche_apps::client] written 44 bytes from 0.0.0.0:44506 to 193.167.100.100:443 [2025-04-30T21:42:38.872092668Z TRACE quiche_apps::client] 0.0.0.0:44506 -> 193.167.100.100:443: done writing [2025-04-30T21:42:39.132426662Z TRACE quiche_apps::client] timed out [2025-04-30T21:42:39.132459093Z TRACE quiche] 717438ef72656e572123b353f0ff3645e294c7b2 draining timeout expired [2025-04-30T21:42:39.132507202Z TRACE quiche_apps::client] done reading [2025-04-30T21:42:39.132511821Z INFO quiche_apps::client] connection closed, recv=15 sent=16 lost=0 retrans=0 sent_bytes=2383 recv_bytes=13570 lost_bytes=0 [local_addr=0.0.0.0:44506 peer_addr=193.167.100.100:443 validation_state=Validated active=true recv=15 sent=16 lost=0 retrans=0 rtt=34.492948ms min_rtt=Some(34.433892ms) rttvar=13.030822ms cwnd=13500 sent_bytes=2383 recv_bytes=13570 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=33358]