[2025-04-30T19:57:59.979348055Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE [2025-04-30T19:57:59.979619203Z INFO quiche_apps::client] connecting to 193.167.100.100:443 from 0.0.0.0:52727 with scid ca11d4d4bc0f784dabd4b6d3447120d2cad55411 [2025-04-30T19:57:59.979661742Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 write message lvl=Initial len=266 [2025-04-30T19:57:59.979680357Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Initial version=1 dcid=22de780632d65e4122f3d563118061f9 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=270 pn=0 [2025-04-30T19:57:59.979683413Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm CRYPTO off=0 len=266 [2025-04-30T19:57:59.979697319Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=998.928857ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, first_sent_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 277, tv_nsec: 315461809 }, next_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, 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-30T19:57:59.979754686Z TRACE quiche_apps::client] written 1200 [2025-04-30T19:58:00.979805545Z TRACE quiche_apps::client] timed out [2025-04-30T19:58:00.979819982Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 loss detection timeout expired [2025-04-30T19:58:00.979825592Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=997.800232ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, first_sent_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 277, tv_nsec: 315461809 }, next_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, 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-30T19:58:00.979842404Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:00.979865667Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Initial version=1 dcid=22de780632d65e4122f3d563118061f9 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=270 pn=1 [2025-04-30T19:58:00.979869545Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm CRYPTO off=0 len=266 [2025-04-30T19:58:00.979880856Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.997971537s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=666 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, first_sent_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 315687816 }, next_time: Instant { tv_sec: 278, tv_nsec: 315687816 }, 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-30T19:58:00.979943393Z TRACE quiche_apps::client] written 1200 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:00.979951007Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:01.488544709Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.488563514Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Initial version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 token= len=1158 pn=0 [2025-04-30T19:58:01.488575917Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=0 len=90 [2025-04-30T19:58:01.488713885Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 set write secret lvl=Handshake [2025-04-30T19:58:01.488726639Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 set read secret lvl=Handshake [2025-04-30T19:58:01.488742118Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm PADDING len=1044 [2025-04-30T19:58:01.488762176Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 1200 bytes [2025-04-30T19:58:01.488770331Z TRACE quiche_apps::client] got 211 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.488775871Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=170 pn=0 [2025-04-30T19:58:01.488782634Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=0 len=146 [2025-04-30T19:58:01.488802241Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 211 bytes [2025-04-30T19:58:01.488807260Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:01.488810466Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:01.488834331Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Initial version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=5 pn=2 [2025-04-30T19:58:01.488838168Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=34 blocks=[0..0] ecn_counts=None [2025-04-30T19:58:01.488848437Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.489003886s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=666 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, first_sent_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 824661769 }, next_time: Instant { tv_sec: 278, tv_nsec: 824661769 }, 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-30T19:58:01.488873765Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Handshake version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=5 pn=3 [2025-04-30T19:58:01.488877461Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=12 blocks=[0..0] ecn_counts=None [2025-04-30T19:58:01.488884695Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.488967738s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=666 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, first_sent_time: Instant { tv_sec: 277, tv_nsec: 315461809 }, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 824661769 }, next_time: Instant { tv_sec: 278, tv_nsec: 824661769 }, 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-30T19:58:01.488897218Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped epoch 0 state [2025-04-30T19:58:01.488947282Z TRACE quiche_apps::client] written 1200 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:01.488956981Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:01.489056557Z TRACE quiche_apps::client] got 535 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.489064131Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=494 pn=1 [2025-04-30T19:58:01.489070743Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=146 len=469 [2025-04-30T19:58:01.489135996Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 535 bytes [2025-04-30T19:58:01.489142548Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:01.489145063Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:01.489154300Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Handshake version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=5 pn=4 [2025-04-30T19:58:01.489156935Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=11 blocks=[0..1] ecn_counts=None [2025-04-30T19:58:01.489163838Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.997662598s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 824983772 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 824983772 }, end_of_app_limited: 1, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 824983772 }, next_time: Instant { tv_sec: 278, tv_nsec: 824983772 }, 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-30T19:58:01.489244409Z TRACE quiche_apps::client] written 63 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:01.489253626Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:01.489264977Z TRACE quiche_apps::client] got 145 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.489270898Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=104 pn=2 [2025-04-30T19:58:01.489280236Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=615 len=79 [2025-04-30T19:58:01.489444744Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 145 bytes [2025-04-30T19:58:01.489453741Z TRACE quiche_apps::client] got 101 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.489457919Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=60 pn=3 [2025-04-30T19:58:01.489463509Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=694 len=36 [2025-04-30T19:58:01.489491221Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 write message lvl=Handshake len=36 [2025-04-30T19:58:01.489494227Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 set write secret lvl=OneRTT [2025-04-30T19:58:01.489501209Z TRACE quiche::tls] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 set read secret lvl=OneRTT [2025-04-30T19:58:01.489512421Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 connection established: proto=Ok("hq-interop") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(22de780632d65e4122f3d563118061f9), max_idle_timeout: 120000, stateless_reset_token: Some(177664700448178525753787948231602361240), max_udp_payload_size: 1500, initial_max_data: 1048576, initial_max_stream_data_bidi_local: 16777216, initial_max_stream_data_bidi_remote: 16777216, initial_max_stream_data_uni: 16777216, 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(cf42cec5b05246cd257edc37), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None } [2025-04-30T19:58:01.489529242Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 101 bytes [2025-04-30T19:58:01.489534011Z TRACE quiche_apps::client] got 68 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:01.489537327Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped invalid packet [2025-04-30T19:58:01.489539912Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 68 bytes [2025-04-30T19:58:01.489543128Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:01.489545552Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:01.489552416Z DEBUG quiche_apps::common] sending HTTP request "GET /vgaomngxtb\r\n" [2025-04-30T19:58:01.489598001Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Handshake version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=45 pn=5 [2025-04-30T19:58:01.489601728Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=17 blocks=[0..3] ecn_counts=None [2025-04-30T19:58:01.489604994Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm CRYPTO off=0 len=36 [2025-04-30T19:58:01.489612217Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.99797882s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=103 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 825426371 }, next_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, 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-30T19:58:01.489629409Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=false hs_sent=false cwnd_avail=13397 out_len=1247 left=1217 [2025-04-30T19:58:01.489636092Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=302 pn=6 [2025-04-30T19:58:01.489638647Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[f4, f7, a5, d6, 8f, 7f, f5, 2b, 99, e0, 2e, 7c, 41, 82, f2, 97, 72, d7, 7d, 8c] reset_token=[00, 79, 5c, 56, c3, 5a, 67, 72, 3e, 54, 8d, 6e, 77, 78, 08, e2] [2025-04-30T19:58:01.489646001Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[46, bb, 5c, ec, 17, 0a, ed, b9, 70, d8, 48, 8e, 26, 78, 7f, 01, 95, 7d, ed, d5] reset_token=[de, 9d, 7a, f4, b2, 03, ca, e3, 39, 06, 3b, 3e, 92, 70, 50, 9a] [2025-04-30T19:58:01.489651290Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[c9, a8, 98, d0, 83, 72, df, cc, ba, be, 41, 99, ac, e2, ae, e4, 54, d0, ae, a2] reset_token=[ad, e8, ad, 69, 19, 83, 75, c9, 60, 5c, f5, 8d, ca, 21, ee, 27] [2025-04-30T19:58:01.489656280Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[91, 3e, f7, 83, 38, c6, 7f, d2, 39, ee, 19, cf, bc, 12, da, e9, 05, b0, da, fd] reset_token=[2c, 68, 73, 7b, 0b, f1, 1e, 69, c1, 18, 7b, 40, 92, 65, e9, b1] [2025-04-30T19:58:01.489661159Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[72, c5, 9d, 35, 54, f6, 30, 38, 92, c7, 90, 42, 4d, 09, 9c, 13, 6e, 31, d6, 93] reset_token=[25, c5, 4f, ae, 91, 48, 23, d7, 7f, 7a, 03, 32, 82, c3, 13, ce] [2025-04-30T19:58:01.489665968Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=6 retire_prior_to=0 conn_id=[ef, 71, 4a, 59, 59, 0a, 36, a8, eb, 6b, 33, 56, 20, 51, c5, 8c, 79, b6, 3a, 97] reset_token=[e5, 7d, 7b, 68, e9, 14, 58, 35, c6, 63, ff, 41, a6, 5b, 17, a1] [2025-04-30T19:58:01.489670697Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm NEW_CONNECTION_ID seq_num=7 retire_prior_to=0 conn_id=[33, 00, 62, f8, b8, e5, c4, 47, 67, e8, 38, 26, 13, c2, 45, 0e, b1, 55, e9, 09] reset_token=[c1, 66, 95, ce, 08, ed, 0a, 71, a0, e0, d9, 36, 53, 81, 49, 86] [2025-04-30T19:58:01.489675686Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm STREAM id=0 off=0 len=17 fin=true [2025-04-30T19:58:01.489684312Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=1.997906906s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=435 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 278, tv_nsec: 825426371 }, next_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, 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-30T19:58:01.489722775Z TRACE quiche_apps::client] written 435 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:01.489727413Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.240093414Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.240108492Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped invalid packet [2025-04-30T19:58:02.240113241Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 1200 bytes [2025-04-30T19:58:02.240118812Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.240122579Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.240129361Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.241028555Z TRACE quiche_apps::client] got 1200 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.241037882Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped invalid packet [2025-04-30T19:58:02.241040608Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 1200 bytes [2025-04-30T19:58:02.241044034Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.241046398Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.241050546Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.481706845Z TRACE quiche_apps::client] got 67 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.481718797Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped invalid packet [2025-04-30T19:58:02.481722264Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 67 bytes [2025-04-30T19:58:02.481725971Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.481728456Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.481733204Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.989677490Z TRACE quiche_apps::client] got 211 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.989689983Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=170 pn=4 [2025-04-30T19:58:02.989698208Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=0 len=146 [2025-04-30T19:58:02.989729748Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 211 bytes [2025-04-30T19:58:02.989734106Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.989736550Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.989745978Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Handshake version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=5 pn=7 [2025-04-30T19:58:02.989748913Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=7 blocks=[0..4] ecn_counts=None [2025-04-30T19:58:02.989757740Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=497.833248ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=435 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 325575250 }, next_time: Instant { tv_sec: 280, tv_nsec: 325575250 }, 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-30T19:58:02.989800490Z TRACE quiche_apps::client] written 63 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.989805289Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.990057362Z TRACE quiche_apps::client] got 535 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.990066789Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Handshake version=1 dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 scid=cf42cec5b05246cd257edc37 len=494 pn=5 [2025-04-30T19:58:02.990074203Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=146 len=469 [2025-04-30T19:58:02.990084883Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 535 bytes [2025-04-30T19:58:02.990088761Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.990091205Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.990100162Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Handshake version=1 dcid=cf42cec5b05246cd257edc37 scid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 len=5 pn=8 [2025-04-30T19:58:02.990102957Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=4 blocks=[0..5] ecn_counts=None [2025-04-30T19:58:02.990110511Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=497.480506ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=435 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 325929754 }, next_time: Instant { tv_sec: 280, tv_nsec: 325929754 }, 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-30T19:58:02.990147361Z TRACE quiche_apps::client] written 63 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.990151849Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.991864731Z TRACE quiche_apps::client] got 42 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.991875100Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=21 pn=0 [2025-04-30T19:58:02.991880791Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm HANDSHAKE_DONE [2025-04-30T19:58:02.991885279Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped epoch 1 state [2025-04-30T19:58:02.991897512Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 42 bytes [2025-04-30T19:58:02.991901219Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.991903744Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.991912120Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1315 [2025-04-30T19:58:02.991918181Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=5 pn=9 [2025-04-30T19:58:02.991922850Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=4 blocks=[0..0] ecn_counts=None [2025-04-30T19:58:02.991932388Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=545.658209ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, 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: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 327742944 }, next_time: Instant { tv_sec: 280, tv_nsec: 327742944 }, 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-30T19:58:02.991976009Z TRACE quiche_apps::client] written 35 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.991981720Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.991990076Z TRACE quiche_apps::client] got 52 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.991994003Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=31 pn=8 [2025-04-30T19:58:02.992000125Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm NEW_TOKEN len=9 [2025-04-30T19:58:02.992006447Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 52 bytes [2025-04-30T19:58:02.992009903Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.992012217Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.992019912Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1313 [2025-04-30T19:58:02.992025322Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=7 pn=10 [2025-04-30T19:58:02.992029229Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=3 blocks=[0..0, 8..8] ecn_counts=None [2025-04-30T19:58:02.992039048Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=545.55179ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, last_sent_packet: 10, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 327851368 }, next_time: Instant { tv_sec: 280, tv_nsec: 327851368 }, 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-30T19:58:02.992086888Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.992092238Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.992255023Z TRACE quiche_apps::client] got 302 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.992265392Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=281 pn=9 [2025-04-30T19:58:02.992271293Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=0 len=257 [2025-04-30T19:58:02.992302822Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 302 bytes [2025-04-30T19:58:02.992307962Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.992310437Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.992317059Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1313 [2025-04-30T19:58:02.992320415Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=7 pn=11 [2025-04-30T19:58:02.992322930Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=6 blocks=[0..0, 8..9] ecn_counts=None [2025-04-30T19:58:02.992329543Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=545.261516ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, last_sent_packet: 11, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 328148966 }, next_time: Instant { tv_sec: 280, tv_nsec: 328148966 }, 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-30T19:58:02.992363476Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.992367704Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.992484954Z TRACE quiche_apps::client] got 303 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.992492208Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=282 pn=10 [2025-04-30T19:58:02.992497938Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm CRYPTO off=257 len=257 [2025-04-30T19:58:02.992526762Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 303 bytes [2025-04-30T19:58:02.992530569Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.992533014Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.992539165Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1313 [2025-04-30T19:58:02.992550797Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=7 pn=12 [2025-04-30T19:58:02.992555576Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=5 blocks=[0..0, 8..10] ecn_counts=None [2025-04-30T19:58:02.992570985Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=545.019422ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, last_sent_packet: 12, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 328371413 }, next_time: Instant { tv_sec: 280, tv_nsec: 328371413 }, 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-30T19:58:02.992614086Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.992620959Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.992632431Z TRACE quiche_apps::client] got 67 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.992637921Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 dropped invalid packet [2025-04-30T19:58:02.992640506Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 67 bytes [2025-04-30T19:58:02.992644553Z TRACE quiche_apps::client] got 73 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.992647969Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=52 pn=11 [2025-04-30T19:58:02.992655734Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[81, 2e, b5, 49, 07, 1c, 8e, a3, d7, 2b, 80, 4d] reset_token=[16, a9, 83, 0c, f1, 54, 71, 1a, 76, 82, 10, 9f, 6a, 03, d2, 07] [2025-04-30T19:58:02.992669510Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 73 bytes [2025-04-30T19:58:02.992675421Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.992679428Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.992688686Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1313 [2025-04-30T19:58:02.992693755Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=7 pn=13 [2025-04-30T19:58:02.992697803Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=5 blocks=[0..0, 8..11] ecn_counts=None [2025-04-30T19:58:02.992707672Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=544.883036ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, last_sent_packet: 13, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 328519811 }, next_time: Instant { tv_sec: 280, tv_nsec: 328519811 }, 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-30T19:58:02.992752696Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.992757515Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.992767333Z TRACE quiche_apps::client] got 73 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.992772854Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=52 pn=12 [2025-04-30T19:58:02.992783263Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[5e, 36, bc, b6, 66, e9, ec, 79, 89, 4d, 08, fa] reset_token=[7d, 32, e7, ab, b1, 62, bc, 39, 09, 73, 49, 6c, e8, f8, 67, 79] [2025-04-30T19:58:02.992795827Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 73 bytes [2025-04-30T19:58:02.992801488Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.992805655Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.992814432Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1313 [2025-04-30T19:58:02.992818820Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=7 pn=14 [2025-04-30T19:58:02.992821555Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm ACK delay=5 blocks=[0..0, 8..12] ecn_counts=None [2025-04-30T19:58:02.992828258Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=544.76283ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=332 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 5, last_sent_packet: 14, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 328645547 }, next_time: Instant { tv_sec: 280, tv_nsec: 328645547 }, 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-30T19:58:02.992860428Z TRACE quiche_apps::client] written 37 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.992865117Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:02.993642795Z TRACE quiche_apps::client] got 1069 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:02.993652784Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx pkt Short dcid=ca11d4d4bc0f784dabd4b6d3447120d2cad55411 key_phase=false len=1048 pn=13 [2025-04-30T19:58:02.993659126Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 rx frm STREAM id=0 off=0 len=1024 fin=true [2025-04-30T19:58:02.993666590Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 1069 bytes [2025-04-30T19:58:02.993670266Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:02.993677560Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:02.993682439Z TRACE quiche_apps::common] received 1024 bytes [2025-04-30T19:58:02.993685034Z TRACE quiche_apps::common] stream 0 has 1024 bytes (fin? true) [2025-04-30T19:58:02.993687619Z DEBUG quiche_apps::common] 1/1 responses received [2025-04-30T19:58:02.993689994Z INFO quiche_apps::common] 1/1 response(s) received in 3.01393165s, closing... [2025-04-30T19:58:02.993696435Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 pmtud probe status false hs_con=true hs_sent=false cwnd_avail=13168 out_len=1350 left=1320 [2025-04-30T19:58:02.993699702Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx pkt Short dcid=cf42cec5b05246cd257edc37 key_phase=false len=10 pn=15 [2025-04-30T19:58:02.993702116Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65] [2025-04-30T19:58:02.993708959Z TRACE quiche::recovery::congestion::recovery] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 timer=2.047984911s latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=372 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, first_sent_time: Instant { tv_sec: 278, tv_nsec: 825426371 }, end_of_app_limited: 14, last_sent_packet: 15, largest_acked: 0, rate_sample: RateSample { delivery_rate: 0, is_app_limited: false, interval: 0ns, delivered: 0, prior_delivered: 0, prior_time: None, send_elapsed: 0ns, ack_elapsed: 0ns, rtt: 0ns } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 0, last_update: Instant { tv_sec: 280, tv_nsec: 329529093 }, next_time: Instant { tv_sec: 280, tv_nsec: 329529093 }, 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-30T19:58:02.993741671Z TRACE quiche_apps::client] written 40 bytes from 0.0.0.0:52727 to 193.167.100.100:443 [2025-04-30T19:58:02.993745197Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:03.016853949Z TRACE quiche_apps::client] got 47 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:03.016869989Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 47 bytes [2025-04-30T19:58:03.016875670Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:03.016879056Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:03.016884466Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:04.494320466Z TRACE quiche_apps::client] got 45 bytes from 193.167.100.100:443 to 0.0.0.0:52727 [2025-04-30T19:58:04.494341335Z TRACE quiche_apps::client] 0.0.0.0:52727: processed 45 bytes [2025-04-30T19:58:04.494348719Z TRACE quiche_apps::client] 0.0.0.0:52727: recv() would block [2025-04-30T19:58:04.494353889Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:04.494361964Z TRACE quiche_apps::client] 0.0.0.0:52727 -> 193.167.100.100:443: done writing [2025-04-30T19:58:05.992913069Z TRACE quiche_apps::client] timed out [2025-04-30T19:58:05.992928659Z TRACE quiche] ca11d4d4bc0f784dabd4b6d3447120d2cad55411 draining timeout expired [2025-04-30T19:58:05.992963093Z TRACE quiche_apps::client] done reading [2025-04-30T19:58:05.992969244Z INFO quiche_apps::client] connection closed, recv=14 sent=16 lost=0 retrans=1 sent_bytes=1677 recv_bytes=4852 lost_bytes=0 [local_addr=0.0.0.0:52727 peer_addr=193.167.100.100:443 validation_state=Validated active=true recv=14 sent=16 lost=0 retrans=1 rtt=333ms min_rtt=Some(333ms) rttvar=166.5ms cwnd=13500 sent_bytes=1677 recv_bytes=4852 lost_bytes=0 stream_retrans_bytes=266 pmtu=1350 delivery_rate=0]