[2025-04-30T11:25:48.209445174Z INFO quiche_server] listening on [::]:443 [2025-04-30T11:25:48.209466384Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T11:25:48.209472515Z TRACE quiche_server] GSO detected: false [2025-04-30T11:25:49.040622221Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:57371 to [::]:443 [2025-04-30T11:25:49.040657397Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T11:25:49.040668217Z WARN quiche_server] Doing version negotiation [2025-04-30T11:25:49.040766120Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:57371 to [::]:443 [2025-04-30T11:25:49.040775758Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T11:25:49.040782260Z WARN quiche_server] Doing version negotiation [2025-04-30T11:25:49.040817305Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:57371 to [::]:443 [2025-04-30T11:25:49.040826473Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T11:25:49.040833035Z WARN quiche_server] Doing version negotiation [2025-04-30T11:25:49.040858713Z TRACE quiche_server] recv() would block [2025-04-30T11:25:49.427028673Z TRACE quiche_server] got 1200 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:49.427052698Z TRACE quiche_server] got packet Initial version=1 dcid=a477904ea96a2c1b scid=38bcbee2d2805a0a token= [2025-04-30T11:25:49.427062196Z DEBUG quiche_server] New connection: dcid=a477904ea96a2c1b scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 [2025-04-30T11:25:49.427256098Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Initial version=1 dcid=a477904ea96a2c1b scid=38bcbee2d2805a0a token= len=504 pn=0 [2025-04-30T11:25:49.427269494Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm CRYPTO off=0 len=482 [2025-04-30T11:25:49.427297416Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("h3") [2025-04-30T11:25:49.427301964Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("hq-interop") [2025-04-30T11:25:49.427448969Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 write message lvl=Initial len=123 [2025-04-30T11:25:49.427482412Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 set write secret lvl=Handshake [2025-04-30T11:25:49.427572890Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 write message lvl=Handshake len=9960 [2025-04-30T11:25:49.427577219Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 set write secret lvl=OneRTT [2025-04-30T11:25:49.427585254Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 set read secret lvl=Handshake [2025-04-30T11:25:49.427614999Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 dropped invalid packet [2025-04-30T11:25:49.427618075Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 1200 bytes [2025-04-30T11:25:49.427635127Z TRACE quiche_server] recv() would block [2025-04-30T11:25:49.427645987Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Initial version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=132 pn=0 [2025-04-30T11:25:49.427649223Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm ACK delay=51 blocks=[0..0] ecn_counts=None [2025-04-30T11:25:49.427653912Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=0 len=123 [2025-04-30T11:25:49.427662658Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=998.974042ms 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: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, 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: 376, tv_nsec: 457226088 }, next_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:49.427689078Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=959 pn=1 [2025-04-30T11:25:49.427692033Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=0 len=955 [2025-04-30T11:25:49.427697884Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=998.939237ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1200 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, 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: 376, tv_nsec: 457226088 }, next_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:49.427741205Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 376, tv_nsec: 457226088 } }) [2025-04-30T11:25:49.427750422Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:49.427757085Z TRACE quiche_server] recv() would block [2025-04-30T11:25:49.427768917Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=2 [2025-04-30T11:25:49.427773656Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=955 len=1141 [2025-04-30T11:25:49.427781971Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=998.85511ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=2400 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 1, last_sent_packet: 2, 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: 376, tv_nsec: 457349328 }, next_time: Instant { tv_sec: 376, tv_nsec: 457349328 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:49.427816756Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 376, tv_nsec: 457349328 } }) [2025-04-30T11:25:49.427830392Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:49.427836543Z TRACE quiche_server] recv() would block [2025-04-30T11:25:49.427848465Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=3 [2025-04-30T11:25:49.427851401Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=2096 len=1141 [2025-04-30T11:25:49.427858364Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=998.778777ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=3600 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 2, last_sent_packet: 3, 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: 376, tv_nsec: 457428375 }, next_time: Instant { tv_sec: 376, tv_nsec: 457428375 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:49.427903148Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 376, tv_nsec: 457428375 } }) [2025-04-30T11:25:49.427910982Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:49.427916432Z TRACE quiche_server] recv() would block [2025-04-30T11:25:49.427921302Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:49.427924728Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:50.427973615Z TRACE quiche_server] timed out [2025-04-30T11:25:50.427991388Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 loss detection timeout expired [2025-04-30T11:25:50.427999033Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=997.637307ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=3600 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 2, last_sent_packet: 3, 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: 376, tv_nsec: 457428375 }, next_time: Instant { tv_sec: 376, tv_nsec: 457428375 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:50.428025242Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:50.428028778Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.427079702Z TRACE quiche_server] timed out [2025-04-30T11:25:51.427109878Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 loss detection timeout expired [2025-04-30T11:25:51.427116510Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=1.996519549s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=3600 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 2, last_sent_packet: 3, 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: 376, tv_nsec: 457428375 }, next_time: Instant { tv_sec: 376, tv_nsec: 457428375 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.427143982Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.427147729Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.524950216Z TRACE quiche_server] got 57 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.524968931Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.524993387Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=20 pn=8 [2025-04-30T11:25:51.525004357Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm PING mtu_probe=None [2025-04-30T11:25:51.525008515Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm PADDING len=1 [2025-04-30T11:25:51.525032600Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 dropped epoch 0 state [2025-04-30T11:25:51.525036577Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 57 bytes [2025-04-30T11:25:51.525043440Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525058568Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=4 [2025-04-30T11:25:51.525062726Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm ACK delay=8 blocks=[8..8] ecn_counts=None [2025-04-30T11:25:51.525067936Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=3237 len=1136 [2025-04-30T11:25:51.525080660Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.995965065s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=4613 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 3, last_sent_packet: 4, 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: 378, tv_nsec: 554635042 }, next_time: Instant { tv_sec: 378, tv_nsec: 554635042 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525147976Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 554635042 } }) [2025-04-30T11:25:51.525155770Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525160950Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525171990Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=5 [2025-04-30T11:25:51.525175788Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=4373 len=1141 [2025-04-30T11:25:51.525185135Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.995977969s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=5813 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 4, last_sent_packet: 5, 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: 378, tv_nsec: 554752281 }, next_time: Instant { tv_sec: 378, tv_nsec: 554752281 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525239396Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 554752281 } }) [2025-04-30T11:25:51.525250297Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525258161Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525274762Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=6 [2025-04-30T11:25:51.525280753Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=5514 len=1141 [2025-04-30T11:25:51.525295131Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.995966447s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=7013 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 5, last_sent_packet: 6, 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: 378, tv_nsec: 554851306 }, next_time: Instant { tv_sec: 378, tv_nsec: 554851306 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525343040Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 554851306 } }) [2025-04-30T11:25:51.525357547Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525366223Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525382203Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=7 [2025-04-30T11:25:51.525388355Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=6655 len=1141 [2025-04-30T11:25:51.525402541Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.995967029s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=8213 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 6, last_sent_packet: 7, 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: 378, tv_nsec: 554959338 }, next_time: Instant { tv_sec: 378, tv_nsec: 554959338 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525480306Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 554959338 } }) [2025-04-30T11:25:51.525485196Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525490345Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525503039Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1146 pn=8 [2025-04-30T11:25:51.525507828Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=7796 len=1141 [2025-04-30T11:25:51.525518969Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.995973931s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=9413 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 7, last_sent_packet: 8, 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: 378, tv_nsec: 555082458 }, next_time: Instant { tv_sec: 378, tv_nsec: 555082458 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525556679Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 555082458 } }) [2025-04-30T11:25:51.525561108Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525566347Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525578350Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Handshake version=1 dcid=38bcbee2d2805a0a scid=f0777940b56b3c7337d3e721e0d803a08e4482b0 len=1028 pn=9 [2025-04-30T11:25:51.525589040Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=8937 len=1023 [2025-04-30T11:25:51.525601142Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=3.99596791s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=10495 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, first_sent_time: Instant { tv_sec: 376, tv_nsec: 457226088 }, end_of_app_limited: 8, last_sent_packet: 9, 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: 378, tv_nsec: 555158550 }, next_time: Instant { tv_sec: 378, tv_nsec: 555158550 }, max_datagram_size: 1350, last_packet_size: None, iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.525636889Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 1082 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 555158550 } }) [2025-04-30T11:25:51.525641387Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.525646056Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.525651597Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.525655093Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.556963747Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.556979286Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.556988674Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=23 pn=9 [2025-04-30T11:25:51.556996809Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=39 blocks=[1..4] ecn_counts=None [2025-04-30T11:25:51.557002590Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 1 [2025-04-30T11:25:51.557006217Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 2 [2025-04-30T11:25:51.557009142Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 3 [2025-04-30T11:25:51.557011997Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 4 [2025-04-30T11:25:51.557031253Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.557037194Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.557043085Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.557046381Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.557732774Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.557739026Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.557743705Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=23 pn=10 [2025-04-30T11:25:51.557748263Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=9 blocks=[1..5] ecn_counts=None [2025-04-30T11:25:51.557757290Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 5 [2025-04-30T11:25:51.557766998Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.557770575Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.557773861Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.557776155Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.558572313Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.558578134Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.558582652Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=23 pn=11 [2025-04-30T11:25:51.558587191Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=7 blocks=[1..6] ecn_counts=None [2025-04-30T11:25:51.558590237Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 6 [2025-04-30T11:25:51.558598382Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.558601698Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.558604764Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.558606958Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.559556984Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.559562394Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.559566651Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=23 pn=12 [2025-04-30T11:25:51.559570980Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=7 blocks=[1..7] ecn_counts=None [2025-04-30T11:25:51.559573905Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 7 [2025-04-30T11:25:51.559581539Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.559584796Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.559587721Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.559589915Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.560535923Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.560541253Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.560545541Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=23 pn=13 [2025-04-30T11:25:51.560550140Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=7 blocks=[1..8] ecn_counts=None [2025-04-30T11:25:51.560553055Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 8 [2025-04-30T11:25:51.560581558Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.560585335Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.560588652Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.560590866Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.562792430Z TRACE quiche_server] got 352 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.562799473Z TRACE quiche_server] got packet Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a [2025-04-30T11:25:51.562809833Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Handshake version=1 dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 scid=38bcbee2d2805a0a len=80 pn=14 [2025-04-30T11:25:51.562815924Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=131 blocks=[1..9] ecn_counts=None [2025-04-30T11:25:51.562819741Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 9 [2025-04-30T11:25:51.562823819Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm CRYPTO off=0 len=52 [2025-04-30T11:25:51.562840260Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 set read secret lvl=OneRTT [2025-04-30T11:25:51.562898889Z TRACE quiche::tls] f0777940b56b3c7337d3e721e0d803a08e4482b0 write message lvl=OneRTT len=428 [2025-04-30T11:25:51.562910140Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 dropped epoch 1 state [2025-04-30T11:25:51.562916412Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 connection established: proto=Ok("hq-interop") cipher=Some(AES256_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: 65527, initial_max_data: 262144, initial_max_stream_data_bidi_local: 262144, initial_max_stream_data_bidi_remote: 262144, initial_max_stream_data_uni: 262144, initial_max_streams_bidi: 128, initial_max_streams_uni: 128, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: false, active_conn_id_limit: 8, initial_source_connection_id: Some(38bcbee2d2805a0a), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T11:25:51.562943613Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false len=214 pn=15 [2025-04-30T11:25:51.562951027Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[ac, ab, a2, 02, db, 61, bc, 5b] reset_token=[df, 4a, 19, 5c, 7d, e6, ae, c5, eb, 42, fb, a4, 47, ae, 51, 57] [2025-04-30T11:25:51.562959152Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[3c, 86, c8, 8a, 10, 46, 3a, 1b] reset_token=[5a, 95, d8, 6c, d8, 80, 94, d3, 7a, bb, 33, 33, 5b, 85, df, 63] [2025-04-30T11:25:51.562964913Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[5f, 51, 99, ae, 4f, 78, 86, 61] reset_token=[7e, c8, 88, 10, 2e, 86, 6b, fb, d0, f0, 3c, f0, 74, e5, c6, b0] [2025-04-30T11:25:51.562970613Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[9a, 68, 50, 28, 99, 82, f1, a6] reset_token=[60, 41, 3d, 75, 27, 34, 39, 27, 61, bd, 48, 8d, 82, 6f, fd, 0c] [2025-04-30T11:25:51.562976604Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[d3, d2, 2d, fe, 4b, 6a, 71, 47] reset_token=[6a, 51, 3a, 2b, 5f, 3b, 5b, b9, 4b, c7, e0, 32, f9, 87, 34, 7b] [2025-04-30T11:25:51.562982054Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[4f, 78, 48, 28, 89, 2d, 7c, dc] reset_token=[b0, c8, 38, 05, 36, 2f, e4, bc, 6b, 93, 7a, a6, ff, 24, 70, fb] [2025-04-30T11:25:51.562987475Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[bd, 88, 00, 31, df, fc, 5c, fa] reset_token=[9e, 12, 11, 6e, 13, f7, 90, a2, 64, 7e, a3, ff, 2f, 03, 10, fb] [2025-04-30T11:25:51.562998335Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 352 bytes [2025-04-30T11:25:51.563006911Z TRACE quiche_server] got 60 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.563010908Z TRACE quiche_server] got packet Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false [2025-04-30T11:25:51.563021559Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false len=39 pn=16 [2025-04-30T11:25:51.563026598Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T11:25:51.563034593Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 60 bytes [2025-04-30T11:25:51.563037969Z DEBUG quiche_apps::common] f0777940b56b3c7337d3e721e0d803a08e4482b0 response stream 0 is writable with capacity Ok(13500) [2025-04-30T11:25:51.563045343Z TRACE quiche_apps::common] f0777940b56b3c7337d3e721e0d803a08e4482b0 received 17 bytes [2025-04-30T11:25:51.563048469Z TRACE quiche_apps::common] f0777940b56b3c7337d3e721e0d803a08e4482b0 stream 0 has 17 bytes (fin? true) [2025-04-30T11:25:51.563053268Z INFO quiche_apps::common] f0777940b56b3c7337d3e721e0d803a08e4482b0 got GET request for "/www/qphpylotfr" on stream 0 [2025-04-30T11:25:51.563080709Z INFO quiche_apps::common] f0777940b56b3c7337d3e721e0d803a08e4482b0 sending response of size 5120 on stream 0 [2025-04-30T11:25:51.563088844Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.563096569Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T11:25:51.563105656Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Short dcid=38bcbee2d2805a0a key_phase=false len=1324 pn=10 [2025-04-30T11:25:51.563109343Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm ACK delay=9 blocks=[15..16] ecn_counts=None [2025-04-30T11:25:51.563113160Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[51, 62, 51, b2, 37, f4, a4, e8, 53, 15, 2a, 1b, 7f, ba, 27, 43, 0b, 37, 5e, 8a] reset_token=[39, e6, b1, c0, bb, 86, 00, 47, e7, b5, 1b, e0, 81, cc, 62, e3] [2025-04-30T11:25:51.563120143Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[17, 96, 30, e8, 84, 27, 90, 40, b4, b1, 1f, 60, 27, 5b, 0b, 13, fb, 7a, 1e, c6] reset_token=[48, 98, 50, af, 5f, 54, 3b, 64, 79, bc, 0e, b9, eb, c5, cb, 92] [2025-04-30T11:25:51.563126354Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[06, 3d, 7e, 10, 3e, db, 8f, 33, 2d, 5f, fe, d9, 57, 0c, 16, f7, d8, 4c, 74, 6b] reset_token=[be, f5, 45, 2a, 7e, 5b, 55, 30, 86, 16, 73, 3b, 57, ad, 70, 9f] [2025-04-30T11:25:51.563132456Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[cb, 5e, 7f, 4a, de, dd, ce, ff, bf, ea, b8, 5e, 07, f7, 3b, f5, 56, c6, fa, 2d] reset_token=[f4, 08, 75, 3e, 4f, 1a, c4, ec, 33, 9e, 15, ad, 1f, 4a, d4, 4d] [2025-04-30T11:25:51.563138787Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[63, 66, 08, b7, f3, 3d, 12, 3c, 93, f6, 0f, 42, 51, d5, 78, 9d, f4, 11, 0a, 62] reset_token=[d6, 87, 4c, 27, c3, 14, 51, 1f, e2, 16, d8, 59, f2, 66, 85, 6d] [2025-04-30T11:25:51.563144909Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[9f, 90, 61, 90, 0b, f0, b1, ab, 80, f8, 83, d6, 9d, 36, 51, 4b, 67, 88, bd, 75] reset_token=[96, f5, 42, 20, 7f, 6e, 1f, ab, ef, ea, 80, 8b, 3c, ba, 13, 99] [2025-04-30T11:25:51.563150930Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[69, 57, 29, 58, 0c, f2, 22, dd, 51, 4f, 07, db, b6, 6d, 9b, b9, 36, 78, 32, e6] reset_token=[97, 1d, ef, f2, 36, 54, 18, fb, c2, e6, 98, 7a, b8, 37, b5, 93] [2025-04-30T11:25:51.563156981Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm HANDSHAKE_DONE [2025-04-30T11:25:51.563159777Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm CRYPTO off=0 len=428 [2025-04-30T11:25:51.563162672Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm STREAM id=0 off=0 len=601 fin=false [2025-04-30T11:25:51.563181828Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=80.443796ms latest_rtt=37.239228ms srtt=33.168779ms min_rtt=31.940595ms rttvar=5.591424ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1350 app_limited=true congestion_recovery_start_time=None Rate { delivered: 10495, delivered_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, first_sent_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, end_of_app_limited: 9, last_sent_packet: 10, largest_acked: 9, rate_sample: RateSample { delivery_rate: 4928, is_app_limited: true, interval: 2.129349549s, delivered: 10495, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 376, tv_nsec: 457226088 }), send_elapsed: 0ns, ack_elapsed: 2.129349549s, rtt: 2.129349549s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508761, last_update: Instant { tv_sec: 378, tv_nsec: 592680336 }, next_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.563199952Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=12150 out_len=1350 left=1324 [2025-04-30T11:25:51.563204200Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Short dcid=38bcbee2d2805a0a key_phase=false len=1324 pn=11 [2025-04-30T11:25:51.563207235Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm STREAM id=0 off=601 len=1318 fin=false [2025-04-30T11:25:51.563213577Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=80.518435ms latest_rtt=37.239228ms srtt=33.168779ms min_rtt=31.940595ms rttvar=5.591424ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=2700 app_limited=true congestion_recovery_start_time=None Rate { delivered: 10495, delivered_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, first_sent_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, end_of_app_limited: 10, last_sent_packet: 11, largest_acked: 9, rate_sample: RateSample { delivery_rate: 4928, is_app_limited: true, interval: 2.129349549s, delivered: 10495, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 376, tv_nsec: 457226088 }), send_elapsed: 0ns, ack_elapsed: 2.129349549s, rtt: 2.129349549s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508761, last_update: Instant { tv_sec: 378, tv_nsec: 592680336 }, next_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.563226151Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=10800 out_len=1350 left=1324 [2025-04-30T11:25:51.563229938Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Short dcid=38bcbee2d2805a0a key_phase=false len=1324 pn=12 [2025-04-30T11:25:51.563232863Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm STREAM id=0 off=1919 len=1318 fin=false [2025-04-30T11:25:51.563238374Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=80.520699ms latest_rtt=37.239228ms srtt=33.168779ms min_rtt=31.940595ms rttvar=5.591424ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=4050 app_limited=true congestion_recovery_start_time=None Rate { delivered: 10495, delivered_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, first_sent_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, end_of_app_limited: 11, last_sent_packet: 12, largest_acked: 9, rate_sample: RateSample { delivery_rate: 4928, is_app_limited: true, interval: 2.129349549s, delivered: 10495, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 376, tv_nsec: 457226088 }), send_elapsed: 0ns, ack_elapsed: 2.129349549s, rtt: 2.129349549s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508761, last_update: Instant { tv_sec: 378, tv_nsec: 592680336 }, next_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.563253862Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=9450 out_len=1350 left=1324 [2025-04-30T11:25:51.563257560Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Short dcid=38bcbee2d2805a0a key_phase=false len=1324 pn=13 [2025-04-30T11:25:51.563260455Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm STREAM id=0 off=3237 len=1318 fin=false [2025-04-30T11:25:51.563265795Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=80.5211ms latest_rtt=37.239228ms srtt=33.168779ms min_rtt=31.940595ms rttvar=5.591424ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=5400 app_limited=true congestion_recovery_start_time=None Rate { delivered: 10495, delivered_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, first_sent_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, end_of_app_limited: 12, last_sent_packet: 13, largest_acked: 9, rate_sample: RateSample { delivery_rate: 4928, is_app_limited: true, interval: 2.129349549s, delivered: 10495, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 376, tv_nsec: 457226088 }), send_elapsed: 0ns, ack_elapsed: 2.129349549s, rtt: 2.129349549s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508761, last_update: Instant { tv_sec: 378, tv_nsec: 592680336 }, next_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.563277326Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=8100 out_len=1350 left=1324 [2025-04-30T11:25:51.563280833Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx pkt Short dcid=38bcbee2d2805a0a key_phase=false len=571 pn=14 [2025-04-30T11:25:51.563283778Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 tx frm STREAM id=0 off=4555 len=565 fin=true [2025-04-30T11:25:51.563289700Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 timer=80.52071ms latest_rtt=37.239228ms srtt=33.168779ms min_rtt=31.940595ms rttvar=5.591424ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=5997 app_limited=true congestion_recovery_start_time=None Rate { delivered: 10495, delivered_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, first_sent_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, end_of_app_limited: 13, last_sent_packet: 14, largest_acked: 9, rate_sample: RateSample { delivery_rate: 4928, is_app_limited: true, interval: 2.129349549s, delivered: 10495, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 376, tv_nsec: 457226088 }), send_elapsed: 0ns, ack_elapsed: 2.129349549s, rtt: 2.129349549s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508761, last_update: Instant { tv_sec: 378, tv_nsec: 592680336 }, next_time: Instant { tv_sec: 378, tv_nsec: 592680336 }, max_datagram_size: 1350, last_packet_size: Some(0), iv: 0ns, max_pacing_rate: None } hystart=window_end=Some(0) last_round_min_rtt=18446744073709551615.999999999s current_round_min_rtt=18446744073709551615.999999999s css_baseline_min_rtt=18446744073709551615.999999999s rtt_sample_count=0 css_start_time=None css_round_count=0 cubic={ k=0 w_max=0 } [2025-04-30T11:25:51.563454488Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 written 5997 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:52017, at: Instant { tv_sec: 378, tv_nsec: 592680336 } }) [2025-04-30T11:25:51.563470868Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.563479054Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.563485255Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.563489763Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.596061117Z TRACE quiche_server] got 44 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.596075705Z TRACE quiche_server] got packet Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false [2025-04-30T11:25:51.596084411Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false len=23 pn=17 [2025-04-30T11:25:51.596092316Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=8 blocks=[10..11] ecn_counts=None [2025-04-30T11:25:51.596097375Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 10 [2025-04-30T11:25:51.596101273Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 11 [2025-04-30T11:25:51.596118495Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 44 bytes [2025-04-30T11:25:51.596124546Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.596128664Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.596131770Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.598241864Z TRACE quiche_server] got 44 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.598249447Z TRACE quiche_server] got packet Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false [2025-04-30T11:25:51.598254537Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false len=23 pn=18 [2025-04-30T11:25:51.598259827Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm ACK delay=7 blocks=[10..13] ecn_counts=None [2025-04-30T11:25:51.598263674Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 12 [2025-04-30T11:25:51.598266559Z TRACE quiche::recovery::congestion::recovery] f0777940b56b3c7337d3e721e0d803a08e4482b0 packet newly acked 13 [2025-04-30T11:25:51.598292849Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 44 bytes [2025-04-30T11:25:51.598297407Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.598300693Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.598303388Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.599191708Z TRACE quiche_server] got 43 bytes from [::ffff:193.167.0.100]:52017 to [::]:443 [2025-04-30T11:25:51.599198621Z TRACE quiche_server] got packet Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false [2025-04-30T11:25:51.599203771Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx pkt Short dcid=f0777940b56b3c7337d3e721e0d803a08e4482b0 key_phase=false len=22 pn=19 [2025-04-30T11:25:51.599209261Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 rx frm APPLICATION_CLOSE err=100 reason=[] [2025-04-30T11:25:51.599216334Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 processed 43 bytes [2025-04-30T11:25:51.599220542Z TRACE quiche_server] recv() would block [2025-04-30T11:25:51.599227626Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.599230411Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.744423380Z TRACE quiche_server] timed out [2025-04-30T11:25:51.744437697Z TRACE quiche] f0777940b56b3c7337d3e721e0d803a08e4482b0 draining timeout expired [2025-04-30T11:25:51.744464587Z TRACE quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 done writing [2025-04-30T11:25:51.744468354Z TRACE quiche_server] Collecting garbage [2025-04-30T11:25:51.744471770Z INFO quiche_server] f0777940b56b3c7337d3e721e0d803a08e4482b0 connection collected recv=13 sent=15 lost=0 retrans=0 sent_bytes=16679 recv_bytes=1430 lost_bytes=0 [local_addr=[::]:443 peer_addr=[::ffff:193.167.0.100]:52017 validation_state=Validated active=true recv=13 sent=15 lost=0 retrans=0 rtt=33.384513ms min_rtt=Some(31.940595ms) rttvar=3.682473ms cwnd=13500 sent_bytes=16679 recv_bytes=1430 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=163681]