[2025-04-30T12:24:05.017317434Z INFO quiche_server] listening on [::]:443 [2025-04-30T12:24:05.017339305Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T12:24:05.017345857Z TRACE quiche_server] GSO detected: false [2025-04-30T12:24:05.818157203Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:51299 to [::]:443 [2025-04-30T12:24:05.818189564Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T12:24:05.818197198Z WARN quiche_server] Doing version negotiation [2025-04-30T12:24:05.818292185Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:51299 to [::]:443 [2025-04-30T12:24:05.818298467Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T12:24:05.818302574Z WARN quiche_server] Doing version negotiation [2025-04-30T12:24:05.818336758Z TRACE quiche_server] got 1207 bytes from [::ffff:193.167.100.2]:51299 to [::]:443 [2025-04-30T12:24:05.818344082Z TRACE quiche_server] got packet Initial version=57414954 dcid= scid= token= [2025-04-30T12:24:05.818350163Z WARN quiche_server] Doing version negotiation [2025-04-30T12:24:05.818377915Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.040202776Z TRACE quiche_server] got 1200 bytes from [::ffff:193.167.0.100]:48937 to [::]:443 [2025-04-30T12:24:06.040224897Z TRACE quiche_server] got packet Initial version=1 dcid=9bba14cc1cf809e5 scid=8e4c07e264056c37 token= [2025-04-30T12:24:06.040234115Z DEBUG quiche_server] New connection: dcid=9bba14cc1cf809e5 scid=90abb04eb733e084c8fada96531f7f21d4e0ad12 [2025-04-30T12:24:06.040429249Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Initial version=1 dcid=9bba14cc1cf809e5 scid=8e4c07e264056c37 token= len=270 pn=0 [2025-04-30T12:24:06.040442984Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm CRYPTO off=0 len=249 [2025-04-30T12:24:06.040471918Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("h3") [2025-04-30T12:24:06.040476497Z TRACE quiche::tls] checking peer ALPN Ok("hq-interop") against Ok("hq-interop") [2025-04-30T12:24:06.040575411Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 write message lvl=Initial len=90 [2025-04-30T12:24:06.040603904Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 set write secret lvl=Handshake [2025-04-30T12:24:06.040679195Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 write message lvl=Handshake len=697 [2025-04-30T12:24:06.040683332Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 set write secret lvl=OneRTT [2025-04-30T12:24:06.040691247Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 set read secret lvl=Handshake [2025-04-30T12:24:06.040726893Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 dropped invalid packet [2025-04-30T12:24:06.040730560Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 processed 1200 bytes [2025-04-30T12:24:06.040740449Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.040753423Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx pkt Initial version=1 dcid=8e4c07e264056c37 scid=90abb04eb733e084c8fada96531f7f21d4e0ad12 len=99 pn=0 [2025-04-30T12:24:06.040757381Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm ACK delay=42 blocks=[0..0] ecn_counts=None [2025-04-30T12:24:06.040762760Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm CRYPTO off=0 len=90 [2025-04-30T12:24:06.040773571Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 timer=998.968973ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=154 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, 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: 540762388 }, next_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, 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-30T12:24:06.040806762Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx pkt Handshake version=1 dcid=8e4c07e264056c37 scid=90abb04eb733e084c8fada96531f7f21d4e0ad12 len=701 pn=1 [2025-04-30T12:24:06.040810309Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm CRYPTO off=0 len=697 [2025-04-30T12:24:06.040817292Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 timer=998.925602ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=909 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, 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: 540762388 }, next_time: Instant { tv_sec: 248, tv_nsec: 540762388 }, 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-30T12:24:06.040870501Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 written 1200 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:48937, at: Instant { tv_sec: 248, tv_nsec: 540762388 } }) [2025-04-30T12:24:06.040880831Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.040886782Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.040891460Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 done writing [2025-04-30T12:24:06.040894366Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.073907793Z TRACE quiche_server] got 1200 bytes from [::ffff:193.167.0.100]:48937 to [::]:443 [2025-04-30T12:24:06.073920817Z TRACE quiche_server] got packet Initial version=1 dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 scid=8e4c07e264056c37 token= [2025-04-30T12:24:06.073928491Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Initial version=1 dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 scid=8e4c07e264056c37 token= len=22 pn=1 [2025-04-30T12:24:06.073935174Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm ACK delay=0 blocks=[0..0] ecn_counts=None [2025-04-30T12:24:06.073940203Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 packet newly acked 0 [2025-04-30T12:24:06.073956313Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Handshake version=1 dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 scid=8e4c07e264056c37 len=61 pn=0 [2025-04-30T12:24:06.073960872Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm ACK delay=0 blocks=[1..1] ecn_counts=None [2025-04-30T12:24:06.073963607Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 packet newly acked 1 [2025-04-30T12:24:06.073966722Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm CRYPTO off=0 len=36 [2025-04-30T12:24:06.073976561Z TRACE quiche::tls] 90abb04eb733e084c8fada96531f7f21d4e0ad12 set read secret lvl=OneRTT [2025-04-30T12:24:06.074019591Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 dropped epoch 1 state [2025-04-30T12:24:06.074024080Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 connection established: proto=Ok("hq-interop") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=None resumed=false TransportParams { original_destination_connection_id: None, max_idle_timeout: 0, stateless_reset_token: None, max_udp_payload_size: 1472, initial_max_data: 1048576, initial_max_stream_data_bidi_local: 1048576, initial_max_stream_data_bidi_remote: 1048576, initial_max_stream_data_uni: 1048576, initial_max_streams_bidi: 0, initial_max_streams_uni: 0, ack_delay_exponent: 3, max_ack_delay: 25, disable_active_migration: true, active_conn_id_limit: 2, initial_source_connection_id: Some(8e4c07e264056c37), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T12:24:06.074041773Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 dropped epoch 0 state [2025-04-30T12:24:06.074044828Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false len=1021 pn=0 [2025-04-30T12:24:06.074050779Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[fe, 56, fe, 88, d3, 5a, a8, 7d] reset_token=[92, 2a, 06, 6e, 0f, df, f7, dd, dd, f4, 79, 06, 69, 47, e0, e0] [2025-04-30T12:24:06.074057903Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[be, 5d, 21, 9d, 50, f4, 17, c7] reset_token=[b2, 20, aa, 6b, 07, f8, f4, b1, e9, de, 60, a8, 89, 3c, 5d, 37] [2025-04-30T12:24:06.074062411Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[76, 9a, 55, 9f, 6f, b1, e5, c9] reset_token=[be, cb, 7c, 00, ba, 7b, a2, 9a, ea, 67, b3, 30, e6, b0, 3d, 81] [2025-04-30T12:24:06.074068673Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm PADDING len=920 [2025-04-30T12:24:06.074074714Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 processed 1200 bytes [2025-04-30T12:24:06.074086265Z TRACE quiche_server] got 58 bytes from [::ffff:193.167.0.100]:48937 to [::]:443 [2025-04-30T12:24:06.074089562Z TRACE quiche_server] got packet Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false [2025-04-30T12:24:06.074093519Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false len=37 pn=1 [2025-04-30T12:24:06.074097426Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T12:24:06.074103528Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 processed 58 bytes [2025-04-30T12:24:06.074106273Z DEBUG quiche_apps::common] 90abb04eb733e084c8fada96531f7f21d4e0ad12 response stream 0 is writable with capacity Ok(13500) [2025-04-30T12:24:06.074111964Z TRACE quiche_apps::common] 90abb04eb733e084c8fada96531f7f21d4e0ad12 received 17 bytes [2025-04-30T12:24:06.074114528Z TRACE quiche_apps::common] 90abb04eb733e084c8fada96531f7f21d4e0ad12 stream 0 has 17 bytes (fin? true) [2025-04-30T12:24:06.074118405Z INFO quiche_apps::common] 90abb04eb733e084c8fada96531f7f21d4e0ad12 got GET request for "/www/ggqiihjnre" on stream 0 [2025-04-30T12:24:06.074137701Z INFO quiche_apps::common] 90abb04eb733e084c8fada96531f7f21d4e0ad12 sending response of size 1024 on stream 0 [2025-04-30T12:24:06.074143973Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.074150846Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13500 out_len=1350 left=1319 [2025-04-30T12:24:06.074157338Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx pkt Short dcid=8e4c07e264056c37 key_phase=false len=1075 pn=2 [2025-04-30T12:24:06.074159993Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm ACK delay=7 blocks=[0..1] ecn_counts=None [2025-04-30T12:24:06.074167487Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[39, d7, 13, ab, 09, f5, 50, 70, 24, 7f, 5e, 82, 98, 20, 5a, 09, f0, e5, 9f, 31] reset_token=[0b, 77, 43, 1f, fe, 55, d4, e8, 3b, 97, bd, 7b, b5, 50, ff, 00] [2025-04-30T12:24:06.074173178Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm HANDSHAKE_DONE [2025-04-30T12:24:06.074175532Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 tx frm STREAM id=0 off=0 len=1024 fin=true [2025-04-30T12:24:06.074184388Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 timer=107.953562ms latest_rtt=33.212487ms srtt=33.187572ms min_rtt=33.184014ms rttvar=12.451123ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1101 app_limited=true congestion_recovery_start_time=None Rate { delivered: 909, delivered_time: Instant { tv_sec: 248, tv_nsec: 574165371 }, first_sent_time: Instant { tv_sec: 248, tv_nsec: 574165371 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 1, rate_sample: RateSample { delivery_rate: 27392, is_app_limited: true, interval: 33.184014ms, delivered: 909, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 248, tv_nsec: 540762388 }), send_elapsed: 0ns, ack_elapsed: 33.184014ms, rtt: 33.184014ms } } pacer=Pacer { enabled: false, capacity: 13500, used: 0, rate: 508473, last_update: Instant { tv_sec: 248, tv_nsec: 574165371 }, next_time: Instant { tv_sec: 248, tv_nsec: 574165371 }, 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-30T12:24:06.074233801Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 written 1101 bytes with Some(SendInfo { from: [::]:443, to: [::ffff:193.167.0.100]:48937, at: Instant { tv_sec: 248, tv_nsec: 574165371 } }) [2025-04-30T12:24:06.074242687Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.074248488Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.074253277Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 done writing [2025-04-30T12:24:06.074257014Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.105656979Z TRACE quiche_server] got 43 bytes from [::ffff:193.167.0.100]:48937 to [::]:443 [2025-04-30T12:24:06.105670224Z TRACE quiche_server] got packet Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false [2025-04-30T12:24:06.105678118Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false len=22 pn=2 [2025-04-30T12:24:06.105685643Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm ACK delay=0 blocks=[2..2] ecn_counts=None [2025-04-30T12:24:06.105690432Z TRACE quiche::recovery::congestion::recovery] 90abb04eb733e084c8fada96531f7f21d4e0ad12 packet newly acked 2 [2025-04-30T12:24:06.105706762Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 processed 43 bytes [2025-04-30T12:24:06.105712422Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.105716209Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 done writing [2025-04-30T12:24:06.105719165Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.105802581Z TRACE quiche_server] got 42 bytes from [::ffff:193.167.0.100]:48937 to [::]:443 [2025-04-30T12:24:06.105807530Z TRACE quiche_server] got packet Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false [2025-04-30T12:24:06.105812749Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx pkt Short dcid=90abb04eb733e084c8fada96531f7f21d4e0ad12 key_phase=false len=21 pn=3 [2025-04-30T12:24:06.105818160Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 rx frm CONNECTION_CLOSE err=0 frame=0 reason=[] [2025-04-30T12:24:06.105833218Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 processed 42 bytes [2025-04-30T12:24:06.105837746Z TRACE quiche_server] recv() would block [2025-04-30T12:24:06.105840641Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 done writing [2025-04-30T12:24:06.105843326Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.322112763Z TRACE quiche_server] timed out [2025-04-30T12:24:06.322137098Z TRACE quiche] 90abb04eb733e084c8fada96531f7f21d4e0ad12 draining timeout expired [2025-04-30T12:24:06.322187071Z TRACE quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 done writing [2025-04-30T12:24:06.322190828Z TRACE quiche_server] Collecting garbage [2025-04-30T12:24:06.322194725Z INFO quiche_server] 90abb04eb733e084c8fada96531f7f21d4e0ad12 connection collected recv=7 sent=3 lost=0 retrans=0 sent_bytes=2010 recv_bytes=1639 lost_bytes=0 [local_addr=[::]:443 peer_addr=[::ffff:193.167.0.100]:48937 validation_state=Validated active=true recv=7 sent=3 lost=0 retrans=0 rtt=32.980439ms min_rtt=Some(31.530518ms) rttvar=9.752605ms cwnd=13500 sent_bytes=2010 recv_bytes=1639 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=34918]