[2025-04-30T09:09:00.170395155Z INFO quiche_server] listening on [::]:443 [2025-04-30T09:09:00.170418388Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T09:09:00.170424870Z TRACE quiche_server] GSO detected: false [2025-04-30T09:09:00.949781431Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:58750 to [::]:443 [2025-04-30T09:09:00.949821515Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T09:09:00.949834720Z WARN quiche_server] Doing version negotiation [2025-04-30T09:09:00.949919767Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:58750 to [::]:443 [2025-04-30T09:09:00.949926300Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T09:09:00.949930287Z WARN quiche_server] Doing version negotiation [2025-04-30T09:09:00.949950745Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:58750 to [::]:443 [2025-04-30T09:09:00.949955043Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T09:09:00.949958479Z WARN quiche_server] Doing version negotiation [2025-04-30T09:09:00.949975581Z TRACE quiche_server] recv() would block [2025-04-30T09:09:01.937781935Z TRACE quiche_server] got 1220 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:01.937810208Z TRACE quiche_server] got packet Initial version=1 dcid=b12deb3b9e3cb974 scid= token= [2025-04-30T09:09:01.937818032Z DEBUG quiche_server] New connection: dcid=b12deb3b9e3cb974 scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 [2025-04-30T09:09:01.938062636Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Initial version=1 dcid=b12deb3b9e3cb974 scid= token= len=1202 pn=0 [2025-04-30T09:09:01.938076652Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm CRYPTO off=0 len=297 [2025-04-30T09:09:01.938106127Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("h3") [2025-04-30T09:09:01.938110875Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("hq-interop") [2025-04-30T09:09:01.938217914Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 write message lvl=Initial len=90 [2025-04-30T09:09:01.938252287Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 set write secret lvl=Handshake [2025-04-30T09:09:01.938332667Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 write message lvl=Handshake len=714 [2025-04-30T09:09:01.938336314Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 set write secret lvl=OneRTT [2025-04-30T09:09:01.938345731Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 set read secret lvl=Handshake [2025-04-30T09:09:01.938369235Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=881 [2025-04-30T09:09:01.938387338Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1220 bytes [2025-04-30T09:09:01.938400603Z TRACE quiche_server] recv() would block [2025-04-30T09:09:01.938413356Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Initial version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=99 pn=0 [2025-04-30T09:09:01.938417754Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=46 blocks=[0..0] ecn_counts=None [2025-04-30T09:09:01.938422874Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm CRYPTO off=0 len=90 [2025-04-30T09:09:01.938433834Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=998.968632ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=146 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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: 248, tv_nsec: 193828475 }, next_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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-30T09:09:01.938467907Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Handshake version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=718 pn=1 [2025-04-30T09:09:01.938471544Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm CRYPTO off=0 len=714 [2025-04-30T09:09:01.938478607Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=998.924299ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=910 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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: 248, tv_nsec: 193828475 }, next_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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-30T09:09:01.938541855Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 248, tv_nsec: 193828475 } }) [2025-04-30T09:09:01.938549619Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:01.938555049Z TRACE quiche_server] recv() would block [2025-04-30T09:09:01.938559127Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:01.938562032Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.082963721Z TRACE quiche_server] got 1220 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:02.082979250Z TRACE quiche_server] got packet Initial version=1 dcid=b12deb3b9e3cb974 scid= token= [2025-04-30T09:09:02.082987956Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Initial version=1 dcid=b12deb3b9e3cb974 scid= token= len=1202 pn=1 [2025-04-30T09:09:02.082995410Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm CRYPTO off=0 len=297 [2025-04-30T09:09:02.083001151Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PING mtu_probe=None [2025-04-30T09:09:02.083006831Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=880 [2025-04-30T09:09:02.083018903Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1220 bytes [2025-04-30T09:09:02.083023312Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.083032479Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Initial version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=5 pn=2 [2025-04-30T09:09:02.083035825Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=5 blocks=[0..1] ecn_counts=None [2025-04-30T09:09:02.083044301Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=854.358386ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=910 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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: 248, tv_nsec: 338450673 }, next_time: Instant { tv_sec: 248, tv_nsec: 338450673 }, 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-30T09:09:02.083105514Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 248, tv_nsec: 338450673 } }) [2025-04-30T09:09:02.083111826Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.083117056Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.083122155Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:02.083125852Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.383498191Z TRACE quiche_server] got 1220 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:02.383518829Z TRACE quiche_server] got packet Initial version=1 dcid=b12deb3b9e3cb974 scid= token= [2025-04-30T09:09:02.383529279Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Initial version=1 dcid=b12deb3b9e3cb974 scid= token= len=1202 pn=2 [2025-04-30T09:09:02.383537905Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm CRYPTO off=0 len=297 [2025-04-30T09:09:02.383545579Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PING mtu_probe=None [2025-04-30T09:09:02.383551530Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=880 [2025-04-30T09:09:02.383564614Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1220 bytes [2025-04-30T09:09:02.383569142Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.383603045Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Initial version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=5 pn=3 [2025-04-30T09:09:02.383609568Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=9 blocks=[0..2] ecn_counts=None [2025-04-30T09:09:02.383619215Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=553.783421ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=910 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, end_of_app_limited: 1, 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: 248, tv_nsec: 638996524 }, next_time: Instant { tv_sec: 248, tv_nsec: 638996524 }, 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-30T09:09:02.383684086Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 248, tv_nsec: 638996524 } }) [2025-04-30T09:09:02.383697681Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.383702089Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.383705596Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:02.383707890Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.938300973Z TRACE quiche_server] timed out [2025-04-30T09:09:02.938318916Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 loss detection timeout expired [2025-04-30T09:09:02.938325258Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=998.077218ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=910 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, end_of_app_limited: 1, 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: 248, tv_nsec: 638996524 }, next_time: Instant { tv_sec: 248, tv_nsec: 638996524 }, 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-30T09:09:02.938360684Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Initial version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=102 pn=4 [2025-04-30T09:09:02.938364281Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=69353 blocks=[0..2] ecn_counts=None [2025-04-30T09:09:02.938369040Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm CRYPTO off=0 len=90 [2025-04-30T09:09:02.938383106Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=998.019971ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1059 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, 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: 249, tv_nsec: 193767878 }, next_time: Instant { tv_sec: 249, tv_nsec: 193767878 }, 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-30T09:09:02.938433068Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 249, tv_nsec: 193767878 } }) [2025-04-30T09:09:02.938439871Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.938444770Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.938448086Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:02.938450340Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.984317130Z TRACE quiche_server] got 1220 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:02.984340073Z TRACE quiche_server] got packet Initial version=1 dcid=b12deb3b9e3cb974 scid= token= [2025-04-30T09:09:02.984353918Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Initial version=1 dcid=b12deb3b9e3cb974 scid= token= len=1202 pn=3 [2025-04-30T09:09:02.984368485Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm CRYPTO off=0 len=297 [2025-04-30T09:09:02.984380087Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PING mtu_probe=None [2025-04-30T09:09:02.984387721Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=880 [2025-04-30T09:09:02.984404181Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1220 bytes [2025-04-30T09:09:02.984410403Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.984424820Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Initial version=1 dcid= scid=e7baa4e53691b4fa765fc6c81836d3d861924b24 len=5 pn=5 [2025-04-30T09:09:02.984429338Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=9 blocks=[0..3] ecn_counts=None [2025-04-30T09:09:02.984456599Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=951.945757ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1059 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 193828475 }, end_of_app_limited: 3, 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: 249, tv_nsec: 239839007 }, next_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, 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-30T09:09:02.984522731Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 249, tv_nsec: 239839007 } }) [2025-04-30T09:09:02.984531307Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:02.984536978Z TRACE quiche_server] recv() would block [2025-04-30T09:09:02.984541787Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:02.984545333Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:03.440980612Z TRACE quiche_server] got 109 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:03.441015868Z TRACE quiche_server] got packet Handshake version=1 dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 scid= [2025-04-30T09:09:03.441031957Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Handshake version=1 dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 scid= len=80 pn=4 [2025-04-30T09:09:03.441051774Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm ACK delay=1 blocks=[1..1] ecn_counts=None [2025-04-30T09:09:03.441064438Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 packet newly acked 1 [2025-04-30T09:09:03.441071721Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm CRYPTO off=0 len=52 [2025-04-30T09:09:03.441096096Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 set read secret lvl=OneRTT [2025-04-30T09:09:03.441145558Z TRACE quiche::tls] e7baa4e53691b4fa765fc6c81836d3d861924b24 write message lvl=OneRTT len=428 [2025-04-30T09:09:03.441156869Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 dropped epoch 1 state [2025-04-30T09:09:03.441178529Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 connection established: proto=Ok("hq-interop") cipher=Some(AES256_GCM) curve=Some("X25519") sigalg=None resumed=false TransportParams { original_destination_connection_id: None, max_idle_timeout: 10000, stateless_reset_token: None, max_udp_payload_size: 1472, initial_max_data: 16777216, initial_max_stream_data_bidi_local: 65536, initial_max_stream_data_bidi_remote: 65536, initial_max_stream_data_uni: 65536, initial_max_streams_bidi: 0, initial_max_streams_uni: 3, ack_delay_exponent: 8, max_ack_delay: 26, disable_active_migration: false, active_conn_id_limit: 4, initial_source_connection_id: Some(), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T09:09:03.441215568Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 dropped epoch 0 state [2025-04-30T09:09:03.441219545Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 109 bytes [2025-04-30T09:09:03.441227560Z TRACE quiche_server] recv() would block [2025-04-30T09:09:03.441235074Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1332 [2025-04-30T09:09:03.441245283Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Short dcid= key_phase=false len=553 pn=6 [2025-04-30T09:09:03.441249170Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[f6, ee, fc, a7, c9, ea, b8, bf, 2a, f4, 79, b4, a0, 98, 8b, 25, ad, 7b, f9, 74] reset_token=[0d, 31, a8, 39, 82, 90, 0b, 3e, 5d, 02, eb, ac, 11, b3, 80, 6c] [2025-04-30T09:09:03.441259930Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[2c, 98, 5b, 2b, 4f, 66, 4e, c3, 06, 9e, 9d, 7f, d5, 49, bc, f6, be, 81, 71, 16] reset_token=[e6, e9, 7c, 72, 57, 60, 86, b4, d5, df, e9, 3e, d5, 23, f3, b1] [2025-04-30T09:09:03.441268877Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[b0, 6c, 7e, 38, 6e, 8c, 9d, a9, 2f, 58, e2, f0, de, c1, 1e, 30, d3, b5, 12, 68] reset_token=[3c, 01, fe, 78, f2, 0a, ef, c3, 66, d6, a4, 67, 80, 10, ef, bd] [2025-04-30T09:09:03.441277413Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm HANDSHAKE_DONE [2025-04-30T09:09:03.441280548Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm CRYPTO off=0 len=428 [2025-04-30T09:09:03.441294144Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=4.533808497s latest_rtt=1.502624272s srtt=1.502624272s min_rtt=1.502624272s rttvar=751.312136ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=571 app_limited=true congestion_recovery_start_time=None Rate { delivered: 764, delivered_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, first_sent_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, end_of_app_limited: 5, last_sent_packet: 6, largest_acked: 1, rate_sample: RateSample { delivery_rate: 508, is_app_limited: true, interval: 1.502624272s, delivered: 764, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 248, tv_nsec: 193828475 }), send_elapsed: 0ns, ack_elapsed: 1.502624272s, rtt: 1.502624272s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 11230, last_update: Instant { tv_sec: 249, tv_nsec: 239839007 }, next_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, 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-30T09:09:03.441372850Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 571 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 249, tv_nsec: 239839007 } }) [2025-04-30T09:09:03.441386405Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:03.441392516Z TRACE quiche_server] recv() would block [2025-04-30T09:09:03.441396303Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:03.441399339Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:03.441897372Z TRACE quiche_server] got 1252 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:03.441909204Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:03.441915907Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=1231 pn=5 [2025-04-30T09:09:03.441922309Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PING mtu_probe=None [2025-04-30T09:09:03.441929171Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=1210 [2025-04-30T09:09:03.441936355Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1252 bytes [2025-04-30T09:09:03.441941935Z TRACE quiche_server] got 45 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:03.441945041Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:03.441948978Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=24 pn=6 [2025-04-30T09:09:03.441953476Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm STREAM id=0 off=0 len=0 fin=false [2025-04-30T09:09:03.441959568Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 45 bytes [2025-04-30T09:09:03.441962383Z DEBUG quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 response stream 0 is writable with capacity Ok(12929) [2025-04-30T09:09:03.441969446Z TRACE quiche_server] got 62 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:03.441972732Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:03.441977010Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=41 pn=7 [2025-04-30T09:09:03.441981548Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T09:09:03.441986217Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 62 bytes [2025-04-30T09:09:03.441988662Z DEBUG quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 response stream 0 is writable with capacity Ok(12929) [2025-04-30T09:09:03.441993911Z TRACE quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 received 17 bytes [2025-04-30T09:09:03.441996356Z TRACE quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 stream 0 has 17 bytes (fin? true) [2025-04-30T09:09:03.442000995Z INFO quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 got GET request for "/www/xmfdlkxanc" on stream 0 [2025-04-30T09:09:03.442036029Z INFO quiche_apps::common] e7baa4e53691b4fa765fc6c81836d3d861924b24 sending response of size 1024 on stream 0 [2025-04-30T09:09:03.442042261Z TRACE quiche_server] recv() would block [2025-04-30T09:09:03.442047541Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 pmtud probe status false hs_con=true hs_sent=true cwnd_avail=12929 out_len=1350 left=1327 [2025-04-30T09:09:03.442052159Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx pkt Short dcid= key_phase=false len=1034 pn=7 [2025-04-30T09:09:03.442054904Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm ACK delay=8 blocks=[5..7] ecn_counts=None [2025-04-30T09:09:03.442058151Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 tx frm STREAM id=0 off=0 len=1024 fin=true [2025-04-30T09:09:03.442065414Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 timer=4.533851587s latest_rtt=1.502624272s srtt=1.502624272s min_rtt=1.502624272s rttvar=751.312136ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1623 app_limited=true congestion_recovery_start_time=None Rate { delivered: 764, delivered_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, first_sent_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, end_of_app_limited: 6, last_sent_packet: 7, largest_acked: 1, rate_sample: RateSample { delivery_rate: 508, is_app_limited: true, interval: 1.502624272s, delivered: 764, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 248, tv_nsec: 193828475 }), send_elapsed: 0ns, ack_elapsed: 1.502624272s, rtt: 1.502624272s } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 11230, last_update: Instant { tv_sec: 249, tv_nsec: 239839007 }, next_time: Instant { tv_sec: 249, tv_nsec: 239839007 }, 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-30T09:09:03.442139562Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 written 1052 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:46090, at: Instant { tv_sec: 249, tv_nsec: 239839007 } }) [2025-04-30T09:09:03.442145803Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:03.442150382Z TRACE quiche_server] recv() would block [2025-04-30T09:09:03.442153187Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:03.442155411Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:04.943615032Z TRACE quiche_server] got 46 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:04.943650308Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:04.943665506Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=25 pn=8 [2025-04-30T09:09:04.943689761Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm ACK delay=0 blocks=[6..7] ecn_counts=None [2025-04-30T09:09:04.943699930Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 packet newly acked 6 [2025-04-30T09:09:04.943704288Z TRACE quiche::recovery::congestion::recovery] e7baa4e53691b4fa765fc6c81836d3d861924b24 packet newly acked 7 [2025-04-30T09:09:04.943734413Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 46 bytes [2025-04-30T09:09:04.943742408Z TRACE quiche_server] recv() would block [2025-04-30T09:09:04.943747468Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:04.943750834Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:04.944599749Z TRACE quiche_server] got 1332 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:04.944611440Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:04.944618123Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=1311 pn=9 [2025-04-30T09:09:04.944625156Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PING mtu_probe=None [2025-04-30T09:09:04.944632389Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm PADDING len=1290 [2025-04-30T09:09:04.944639763Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 1332 bytes [2025-04-30T09:09:04.944645273Z TRACE quiche_server] got 44 bytes from [::ffff:193.167.0.100]:46090 to [::]:443 [2025-04-30T09:09:04.944648399Z TRACE quiche_server] got packet Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false [2025-04-30T09:09:04.944652486Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx pkt Short dcid=e7baa4e53691b4fa765fc6c81836d3d861924b24 key_phase=false len=23 pn=10 [2025-04-30T09:09:04.944674127Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 rx frm APPLICATION_CLOSE err=0 reason=[] [2025-04-30T09:09:04.944685878Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 processed 44 bytes [2025-04-30T09:09:04.944689545Z TRACE quiche_server] recv() would block [2025-04-30T09:09:04.944691949Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:04.944694294Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:17.768559416Z TRACE quiche_server] timed out [2025-04-30T09:09:17.768624136Z TRACE quiche] e7baa4e53691b4fa765fc6c81836d3d861924b24 draining timeout expired [2025-04-30T09:09:17.768678938Z TRACE quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 done writing [2025-04-30T09:09:17.768684488Z TRACE quiche_server] Collecting garbage [2025-04-30T09:09:17.768690589Z INFO quiche_server] e7baa4e53691b4fa765fc6c81836d3d861924b24 connection collected recv=11 sent=8 lost=0 retrans=1 sent_bytes=2838 recv_bytes=7770 lost_bytes=0 [local_addr=[::]:443 peer_addr=[::ffff:193.167.0.100]:46090 validation_state=Validated active=true recv=11 sent=8 lost=0 retrans=1 rtt=1.559702266s min_rtt=Some(1.502624272s) rttvar=677.640091ms cwnd=13500 sent_bytes=2838 recv_bytes=7770 lost_bytes=0 stream_retrans_bytes=90 pmtu=1350 delivery_rate=828]