[2025-04-30T17:17:26.235945581Z INFO quiche_server] listening on [::]:443 [2025-04-30T17:17:26.235972521Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T17:17:26.235979935Z TRACE quiche_server] GSO detected: false [2025-04-30T17:17:27.082211629Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:47941 to [::]:443 [2025-04-30T17:17:27.082247446Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T17:17:27.082255421Z WARN quiche_server] Doing version negotiation [2025-04-30T17:17:27.082349757Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:47941 to [::]:443 [2025-04-30T17:17:27.082356058Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T17:17:27.082359836Z WARN quiche_server] Doing version negotiation [2025-04-30T17:17:27.082389961Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:47941 to [::]:443 [2025-04-30T17:17:27.082396975Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T17:17:27.082402785Z WARN quiche_server] Doing version negotiation [2025-04-30T17:17:27.082433322Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.143149864Z TRACE quiche_server] got 1200 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.143184328Z TRACE quiche_server] got packet Initial version=1 dcid=7f5f8659d3681c92 scid=9fbeb3e10cb21a75 token= [2025-04-30T17:17:28.143194977Z DEBUG quiche_server] New connection: dcid=7f5f8659d3681c92 scid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 [2025-04-30T17:17:28.143450704Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Initial version=1 dcid=7f5f8659d3681c92 scid=9fbeb3e10cb21a75 token= len=1174 pn=0 [2025-04-30T17:17:28.143466523Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm CRYPTO off=0 len=257 [2025-04-30T17:17:28.143497120Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("h3") [2025-04-30T17:17:28.143503151Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("hq-interop") [2025-04-30T17:17:28.143633304Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 write message lvl=Initial len=123 [2025-04-30T17:17:28.143674681Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 set write secret lvl=Handshake [2025-04-30T17:17:28.143755201Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 write message lvl=Handshake len=696 [2025-04-30T17:17:28.143759659Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 set write secret lvl=OneRTT [2025-04-30T17:17:28.143769528Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 set read secret lvl=Handshake [2025-04-30T17:17:28.143794224Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm PADDING len=896 [2025-04-30T17:17:28.143819461Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 1200 bytes [2025-04-30T17:17:28.143831683Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.143848004Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Initial version=1 dcid=9fbeb3e10cb21a75 scid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 len=132 pn=0 [2025-04-30T17:17:28.143852532Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm ACK delay=52 blocks=[0..0] ecn_counts=None [2025-04-30T17:17:28.143858634Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm CRYPTO off=0 len=123 [2025-04-30T17:17:28.143871307Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=998.962971ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=187 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, 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: false, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 842, tv_nsec: 254814978 }, next_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, 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:17:28.143911232Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Handshake version=1 dcid=9fbeb3e10cb21a75 scid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 len=700 pn=1 [2025-04-30T17:17:28.143915620Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm CRYPTO off=0 len=696 [2025-04-30T17:17:28.143924797Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=998.909943ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=941 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, 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: false, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 842, tv_nsec: 254814978 }, next_time: Instant { tv_sec: 842, tv_nsec: 254814978 }, 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:17:28.143983246Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 254814978 } }) [2025-04-30T17:17:28.143993315Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.143999516Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.144004596Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.144007942Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.234313086Z TRACE quiche_server] got 1201 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.234345666Z TRACE quiche_server] got packet Initial version=1 dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 scid=9fbeb3e10cb21a75 token= [2025-04-30T17:17:28.234362618Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Initial version=1 dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 scid=9fbeb3e10cb21a75 token= len=1163 pn=1 [2025-04-30T17:17:28.234379740Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=0 blocks=[0..0] ecn_counts=None [2025-04-30T17:17:28.234389759Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 0 [2025-04-30T17:17:28.234403204Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm PADDING len=1141 [2025-04-30T17:17:28.234432688Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 1201 bytes [2025-04-30T17:17:28.234440633Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.234452726Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.234457555Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.259696681Z TRACE quiche_server] got 92 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.259728801Z TRACE quiche_server] got packet Handshake version=1 dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 scid=9fbeb3e10cb21a75 [2025-04-30T17:17:28.259759138Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Handshake version=1 dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 scid=9fbeb3e10cb21a75 len=56 pn=0 [2025-04-30T17:17:28.259774556Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm CRYPTO off=0 len=36 [2025-04-30T17:17:28.259800194Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 set read secret lvl=OneRTT [2025-04-30T17:17:28.259852461Z TRACE quiche::tls] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 write message lvl=OneRTT len=396 [2025-04-30T17:17:28.259868381Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 dropped epoch 1 state [2025-04-30T17:17:28.259874963Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 connection established: proto=Ok("hq-interop") cipher=Some(AES128_GCM) curve=Some("P-256") sigalg=None resumed=false TransportParams { original_destination_connection_id: None, max_idle_timeout: 60000, stateless_reset_token: None, max_udp_payload_size: 1500, initial_max_data: 2500000, initial_max_stream_data_bidi_local: 250000, initial_max_stream_data_bidi_remote: 250000, initial_max_stream_data_uni: 250000, initial_max_streams_bidi: 3, initial_max_streams_uni: 3, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 2, initial_source_connection_id: Some(9fbeb3e10cb21a75), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T17:17:28.259916791Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 dropped epoch 0 state [2025-04-30T17:17:28.259922923Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 92 bytes [2025-04-30T17:17:28.259939022Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.259950203Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1324 [2025-04-30T17:17:28.259963117Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=441 pn=2 [2025-04-30T17:17:28.259967446Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[16, 8a, 1f, 09, 0d, 62, 17, 31, 21, d7, 7b, 77, 67, 8a, 6b, 36, ec, 4f, f0, 1c] reset_token=[45, 5e, cd, 0a, 29, 83, b0, c0, c4, 10, 33, 81, 4c, 35, 6c, 28] [2025-04-30T17:17:28.259978997Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm HANDSHAKE_DONE [2025-04-30T17:17:28.259983305Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm CRYPTO off=0 len=396 [2025-04-30T17:17:28.260000637Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.512972ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=467 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.260620158Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 467 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 370922918 } }) [2025-04-30T17:17:28.260640345Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.260647589Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.260652478Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.260655553Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.266100835Z TRACE quiche_server] got 58 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.266114661Z TRACE quiche_server] got packet Handshake version=1 dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 scid=9fbeb3e10cb21a75 [2025-04-30T17:17:28.266123878Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 dropped invalid packet [2025-04-30T17:17:28.266127625Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 58 bytes [2025-04-30T17:17:28.266133286Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.266137463Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.266140860Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.295228836Z TRACE quiche_server] got 80 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.295256978Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.295269943Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=59 pn=0 [2025-04-30T17:17:28.295283678Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T17:17:28.295291232Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm STREAM id=4 off=0 len=17 fin=true [2025-04-30T17:17:28.295308304Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 80 bytes [2025-04-30T17:17:28.295312813Z DEBUG quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 response stream 0 is writable with capacity Ok(13033) [2025-04-30T17:17:28.295317090Z DEBUG quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 response stream 4 is writable with capacity Ok(13033) [2025-04-30T17:17:28.295324404Z TRACE quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 received 17 bytes [2025-04-30T17:17:28.295328121Z TRACE quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 stream 0 has 17 bytes (fin? true) [2025-04-30T17:17:28.295333421Z INFO quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 got GET request for "/www/tnbpbvkdao" on stream 0 [2025-04-30T17:17:28.295362766Z INFO quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 sending response of size 5120 on stream 0 [2025-04-30T17:17:28.295371542Z TRACE quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 received 17 bytes [2025-04-30T17:17:28.295374467Z TRACE quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 stream 4 has 17 bytes (fin? true) [2025-04-30T17:17:28.295378044Z INFO quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 got GET request for "/www/rmbvsenznt" on stream 4 [2025-04-30T17:17:28.295393383Z INFO quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 sending response of size 10240 on stream 4 [2025-04-30T17:17:28.295402950Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.295413180Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=13033 out_len=1350 left=1319 [2025-04-30T17:17:28.295421475Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=3 [2025-04-30T17:17:28.295425422Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm ACK delay=18 blocks=[0..0] ecn_counts=None [2025-04-30T17:17:28.295431013Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=0 off=0 len=1314 fin=false [2025-04-30T17:17:28.295453394Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.523292ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1817 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295476618Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=11683 out_len=1350 left=1324 [2025-04-30T17:17:28.295480866Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=4 [2025-04-30T17:17:28.295483981Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=0 len=1319 fin=false [2025-04-30T17:17:28.295490504Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.555111ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=3167 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295503187Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=10333 out_len=1350 left=1324 [2025-04-30T17:17:28.295507095Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=5 [2025-04-30T17:17:28.295510030Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=0 off=1314 len=1318 fin=false [2025-04-30T17:17:28.295515390Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.557635ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=4517 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295531850Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=8983 out_len=1350 left=1324 [2025-04-30T17:17:28.295535608Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=6 [2025-04-30T17:17:28.295538503Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=1319 len=1318 fin=false [2025-04-30T17:17:28.295544654Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.556814ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=5867 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 6, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295556356Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=7633 out_len=1350 left=1324 [2025-04-30T17:17:28.295560233Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=7 [2025-04-30T17:17:28.295563149Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=0 off=2632 len=1318 fin=false [2025-04-30T17:17:28.295568419Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.557835ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=7217 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 7, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295583276Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=6283 out_len=1350 left=1324 [2025-04-30T17:17:28.295587003Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=8 [2025-04-30T17:17:28.295589899Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=2637 len=1318 fin=false [2025-04-30T17:17:28.295595239Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.557986ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=8567 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 8, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295606620Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=4933 out_len=1350 left=1324 [2025-04-30T17:17:28.295610256Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1176 pn=9 [2025-04-30T17:17:28.295613262Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=0 off=3950 len=1170 fin=true [2025-04-30T17:17:28.295618682Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.557936ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=9769 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 9, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295747623Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 9302 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 370922918 } }) [2025-04-30T17:17:28.295766447Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.295775164Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.295784862Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=3731 out_len=1350 left=1324 [2025-04-30T17:17:28.295792676Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=10 [2025-04-30T17:17:28.295797596Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=3955 len=1318 fin=false [2025-04-30T17:17:28.295812253Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.538309ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=11119 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 10, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295838372Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=2381 out_len=1350 left=1324 [2025-04-30T17:17:28.295845084Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=11 [2025-04-30T17:17:28.295849993Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=5273 len=1318 fin=false [2025-04-30T17:17:28.295886020Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.519574ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=12469 app_limited=true congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 11, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295900878Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=1031 out_len=1350 left=1005 [2025-04-30T17:17:28.295904845Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1005 pn=12 [2025-04-30T17:17:28.295911297Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=6591 len=999 fin=false [2025-04-30T17:17:28.295917749Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=296.552355ms latest_rtt=90.523841ms srtt=90.523841ms min_rtt=90.523841ms rttvar=45.26192ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=13500 app_limited=false congestion_recovery_start_time=None Rate { delivered: 187, delivered_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 1, last_sent_packet: 12, largest_acked: 0, rate_sample: RateSample { delivery_rate: 2065, is_app_limited: true, interval: 90.523841ms, delivered: 187, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 254814978 }), send_elapsed: 0ns, ack_elapsed: 90.523841ms, rtt: 90.523841ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 186414, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, 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:17:28.295975828Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 3731 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 370922918 } }) [2025-04-30T17:17:28.295985656Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.295993480Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.296001956Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=0 out_len=1350 left=0 [2025-04-30T17:17:28.296008869Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.296013728Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.316103419Z TRACE quiche_server] got 44 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.316120521Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.316131131Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=23 pn=1 [2025-04-30T17:17:28.316142211Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=2375 blocks=[2..2] ecn_counts=None [2025-04-30T17:17:28.316149024Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 2 [2025-04-30T17:17:28.316166877Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 44 bytes [2025-04-30T17:17:28.316171917Z DEBUG quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 response stream 4 is writable with capacity Ok(467) [2025-04-30T17:17:28.316182767Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.316191563Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=467 out_len=1350 left=441 [2025-04-30T17:17:28.316199057Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=441 pn=13 [2025-04-30T17:17:28.316202754Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=7590 len=435 fin=false [2025-04-30T17:17:28.316213774Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=281.32651ms latest_rtt=56.186317ms srtt=86.231649ms min_rtt=56.186317ms rttvar=42.530821ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=13500 app_limited=false congestion_recovery_start_time=None Rate { delivered: 654, delivered_time: Instant { tv_sec: 842, tv_nsec: 427109235 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 0, last_sent_packet: 13, largest_acked: 2, rate_sample: RateSample { delivery_rate: 8311, is_app_limited: true, interval: 56.186317ms, delivered: 467, prior_delivered: 187, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 370922918 }), send_elapsed: 0ns, ack_elapsed: 56.186317ms, rtt: 56.186317ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 195693, last_update: Instant { tv_sec: 842, tv_nsec: 370922918 }, next_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(13) last_round_min_rtt=56.186317ms 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:17:28.316270560Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 467 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 370922918 } }) [2025-04-30T17:17:28.316279026Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.316284937Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.316290989Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=0 out_len=1350 left=0 [2025-04-30T17:17:28.316295657Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.316298873Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.330089084Z TRACE quiche_server] got 43 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.330106967Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.330116835Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=22 pn=2 [2025-04-30T17:17:28.330126704Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=0 blocks=[2..4] ecn_counts=None [2025-04-30T17:17:28.330132394Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 3 [2025-04-30T17:17:28.330135901Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 4 [2025-04-30T17:17:28.330153594Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 43 bytes [2025-04-30T17:17:28.330157401Z DEBUG quiche_apps::common] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 response stream 4 is writable with capacity Ok(5400) [2025-04-30T17:17:28.330168111Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.330175384Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=5400 out_len=1350 left=1324 [2025-04-30T17:17:28.330181826Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=1324 pn=14 [2025-04-30T17:17:28.330184982Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=8025 len=1318 fin=false [2025-04-30T17:17:28.330194360Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=252.852772ms latest_rtt=70.171431ms srtt=84.22412ms min_rtt=56.186317ms rttvar=35.913169ms cwnd=16200 ssthresh=18446744073709551615 bytes_in_flight=12150 app_limited=true congestion_recovery_start_time=None Rate { delivered: 3354, delivered_time: Instant { tv_sec: 842, tv_nsec: 441094349 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 0, last_sent_packet: 14, largest_acked: 4, rate_sample: RateSample { delivery_rate: 56366, is_app_limited: true, interval: 56.186317ms, delivered: 3167, prior_delivered: 187, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 370922918 }), send_elapsed: 0ns, ack_elapsed: 56.186317ms, rtt: 56.186317ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 240429, last_update: Instant { tv_sec: 842, tv_nsec: 441150614 }, next_time: Instant { tv_sec: 842, tv_nsec: 441150614 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(13) last_round_min_rtt=56.186317ms current_round_min_rtt=70.171431ms css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=2 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T17:17:28.330220869Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=4050 out_len=1350 left=1324 [2025-04-30T17:17:28.330225418Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx pkt Short dcid=9fbeb3e10cb21a75 key_phase=false len=903 pn=15 [2025-04-30T17:17:28.330228604Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 tx frm STREAM id=4 off=9343 len=897 fin=true [2025-04-30T17:17:28.330234715Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 timer=252.860716ms latest_rtt=70.171431ms srtt=84.22412ms min_rtt=56.186317ms rttvar=35.913169ms cwnd=16200 ssthresh=18446744073709551615 bytes_in_flight=13079 app_limited=true congestion_recovery_start_time=None Rate { delivered: 3354, delivered_time: Instant { tv_sec: 842, tv_nsec: 441094349 }, first_sent_time: Instant { tv_sec: 842, tv_nsec: 370922918 }, end_of_app_limited: 0, last_sent_packet: 15, largest_acked: 4, rate_sample: RateSample { delivery_rate: 56366, is_app_limited: true, interval: 56.186317ms, delivered: 3167, prior_delivered: 187, prior_time: Some(Instant { tv_sec: 842, tv_nsec: 370922918 }), send_elapsed: 0ns, ack_elapsed: 56.186317ms, rtt: 56.186317ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 240429, last_update: Instant { tv_sec: 842, tv_nsec: 441150614 }, next_time: Instant { tv_sec: 842, tv_nsec: 441150614 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(13) last_round_min_rtt=56.186317ms current_round_min_rtt=70.171431ms css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=2 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T17:17:28.330287052Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 written 2279 bytes with Some(SendInfo { from: [::]:443, to: [fd00:cafe:cafe::100]:34346, at: Instant { tv_sec: 842, tv_nsec: 441150614 } }) [2025-04-30T17:17:28.330293474Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.330298895Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.330302080Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.330304866Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.331519438Z TRACE quiche_server] got 43 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.331526611Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.331531881Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=22 pn=3 [2025-04-30T17:17:28.331537051Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=0 blocks=[2..6] ecn_counts=None [2025-04-30T17:17:28.331540347Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 5 [2025-04-30T17:17:28.331542761Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 6 [2025-04-30T17:17:28.331552149Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 43 bytes [2025-04-30T17:17:28.331556006Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.331558470Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.331560594Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.333471614Z TRACE quiche_server] got 44 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.333498153Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.333506599Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=23 pn=4 [2025-04-30T17:17:28.333515055Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=125 blocks=[2..8] ecn_counts=None [2025-04-30T17:17:28.333519984Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 7 [2025-04-30T17:17:28.333523370Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 8 [2025-04-30T17:17:28.333537877Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 44 bytes [2025-04-30T17:17:28.333543648Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.333547976Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.333551332Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.335489983Z TRACE quiche_server] got 44 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.335502556Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.335510461Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=23 pn=5 [2025-04-30T17:17:28.335518145Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=125 blocks=[2..10] ecn_counts=None [2025-04-30T17:17:28.335522884Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 9 [2025-04-30T17:17:28.335526240Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 10 [2025-04-30T17:17:28.335543553Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 44 bytes [2025-04-30T17:17:28.335548893Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.335552840Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.335556016Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.337535553Z TRACE quiche_server] got 43 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.337545792Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.337551813Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=22 pn=6 [2025-04-30T17:17:28.337557283Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=0 blocks=[2..12] ecn_counts=None [2025-04-30T17:17:28.337560990Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 11 [2025-04-30T17:17:28.337563495Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 12 [2025-04-30T17:17:28.337574275Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 43 bytes [2025-04-30T17:17:28.337578493Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.337581448Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.337583692Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.362612044Z TRACE quiche_server] got 44 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.362637731Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.362652028Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=23 pn=7 [2025-04-30T17:17:28.362666876Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=1750 blocks=[2..14] ecn_counts=None [2025-04-30T17:17:28.362674049Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 13 [2025-04-30T17:17:28.362686562Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 14 [2025-04-30T17:17:28.362714575Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 44 bytes [2025-04-30T17:17:28.362724954Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.362730564Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.362734612Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.377917500Z TRACE quiche_server] got 48 bytes from [fd00:cafe:cafe::100]:34346 to [::]:443 [2025-04-30T17:17:28.377933580Z TRACE quiche_server] got packet Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false [2025-04-30T17:17:28.377942086Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx pkt Short dcid=644aa263dbb21daf0b3d8efcd9631c50a4a0e744 key_phase=false len=27 pn=8 [2025-04-30T17:17:28.377951033Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm CONNECTION_CLOSE err=0 frame=0 reason=[] [2025-04-30T17:17:28.377956613Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 rx frm ACK delay=1750 blocks=[2..15] ecn_counts=None [2025-04-30T17:17:28.377961562Z TRACE quiche::recovery::congestion::recovery] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 packet newly acked 15 [2025-04-30T17:17:28.377980478Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 processed 48 bytes [2025-04-30T17:17:28.377986108Z TRACE quiche_server] recv() would block [2025-04-30T17:17:28.377989034Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.377992109Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.889530820Z TRACE quiche_server] timed out [2025-04-30T17:17:28.889558672Z TRACE quiche] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 draining timeout expired [2025-04-30T17:17:28.889603545Z TRACE quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 done writing [2025-04-30T17:17:28.889609236Z TRACE quiche_server] Collecting garbage [2025-04-30T17:17:28.889614696Z INFO quiche_server] 644aa263dbb21daf0b3d8efcd9631c50a4a0e744 connection collected recv=12 sent=16 lost=0 retrans=0 sent_bytes=17187 recv_bytes=2926 lost_bytes=0 [local_addr=[::]:443 peer_addr=[fd00:cafe:cafe::100]:34346 validation_state=Validated active=true recv=12 sent=16 lost=0 retrans=0 rtt=69.150944ms min_rtt=Some(32.478286ms) rttvar=28.119825ms cwnd=16200 sent_bytes=17187 recv_bytes=2926 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=186237]