[2025-09-12T02:03:49.154700748Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE
[2025-09-12T02:03:49.154992915Z INFO  quiche_apps::client] connecting to 193.167.100.100:443 from 0.0.0.0:36168 with scid 2f1a67f420c07bc55b9f66865d6ad5fd0341da42
[2025-09-12T02:03:49.155033391Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 write message lvl=Initial len=266
[2025-09-12T02:03:49.155050754Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Initial version=1 dcid=7cee2dc227c70df25c1fb28062a289db scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=270 pn=0 
[2025-09-12T02:03:49.155053950Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm CRYPTO off=0 len=266
[2025-09-12T02:03:49.155068056Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=998.931723ms 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: 787, tv_nsec: 682874081 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { bandwidth: 0.00 Kbps, 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: 787, tv_nsec: 682874081 }, next_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, 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-09-12T02:03:49.155123640Z TRACE quiche_apps::client] written 1200
[2025-09-12T02:03:50.155202141Z TRACE quiche_apps::client] timed out
[2025-09-12T02:03:50.155223772Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 loss detection timeout expired
[2025-09-12T02:03:50.155230825Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=997.768302ms 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: 787, tv_nsec: 682874081 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 1, last_sent_packet: 0, largest_acked: 0, rate_sample: RateSample { bandwidth: 0.00 Kbps, 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: 787, tv_nsec: 682874081 }, next_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, 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-09-12T02:03:50.155256283Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:50.155294284Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Initial version=1 dcid=7cee2dc227c70df25c1fb28062a289db scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=270 pn=1 
[2025-09-12T02:03:50.155298863Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm CRYPTO off=0 len=266
[2025-09-12T02:03:50.155318509Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=1.997951529s 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: 787, tv_nsec: 682874081 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { bandwidth: 0.00 Kbps, 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: 788, tv_nsec: 683144411 }, next_time: Instant { tv_sec: 788, tv_nsec: 683144411 }, 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-09-12T02:03:50.155380145Z TRACE quiche_apps::client] written 1200 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:50.155388400Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:50.663945052Z TRACE quiche_apps::client] got 1280 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:50.663979306Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Initial version=1 dcid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 scid=58542814 token= len=310 pn=0 
[2025-09-12T02:03:50.663996358Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm ACK delay=0 blocks=[0..0] ecn_counts=None
[2025-09-12T02:03:50.664003561Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 packet newly acked 0
[2025-09-12T02:03:50.664011186Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm PADDING len=193
[2025-09-12T02:03:50.664015364Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm CRYPTO off=0 len=90
[2025-09-12T02:03:50.664168791Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 set write secret lvl=Handshake
[2025-09-12T02:03:50.664182707Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 set read secret lvl=Handshake
[2025-09-12T02:03:50.664224686Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Handshake version=1 dcid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 scid=58542814 len=744 pn=0 
[2025-09-12T02:03:50.664231899Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm CRYPTO off=0 len=722
[2025-09-12T02:03:50.664467340Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 write message lvl=Handshake len=36
[2025-09-12T02:03:50.664472099Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 set write secret lvl=OneRTT
[2025-09-12T02:03:50.664480445Z TRACE quiche::tls] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 set read secret lvl=OneRTT
[2025-09-12T02:03:50.664499400Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 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(7cee2dc227c70df25c1fb28062a289db), max_idle_timeout: 30000, stateless_reset_token: Some(119865324168565946231746691341782583775), max_udp_payload_size: 1452, initial_max_data: 786432, initial_max_stream_data_bidi_local: 524288, initial_max_stream_data_bidi_remote: 524288, initial_max_stream_data_uni: 524288, initial_max_streams_bidi: 100, initial_max_streams_uni: 100, ack_delay_exponent: 3, max_ack_delay: 26, disable_active_migration: false, active_conn_id_limit: 4, initial_source_connection_id: Some(58542814), retry_source_connection_id: None, max_datagram_frame_size: None, unknown_params: None }
[2025-09-12T02:03:50.664525128Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Short dcid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 key_phase=false len=138 pn=0 
[2025-09-12T02:03:50.664532462Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[63, e9, 9d, 91] reset_token=[1a, 9f, db, 49, 84, b9, 94, f0, 2e, f6, 10, 46, 07, 6e, 6e, 1a]
[2025-09-12T02:03:50.664546498Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[85, 2e, ae, db] reset_token=[5b, 30, e2, 8d, 8e, 22, 2a, ef, 7e, ed, 0d, f4, 1b, e0, 3c, ce]
[2025-09-12T02:03:50.664551919Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=0 conn_id=[72, 9a, 5e, 2e] reset_token=[34, 45, 0c, ae, 6c, c1, 74, 23, 35, 0b, 6a, 36, 2b, 73, e4, 8f]
[2025-09-12T02:03:50.664556918Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[84, 8f, fb, de] reset_token=[f2, ce, f8, b5, 65, 75, 5b, 36, 64, b3, 2f, 0c, 0d, ff, 2a, 1f]
[2025-09-12T02:03:50.664562819Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_CONNECTION_ID seq_num=5 retire_prior_to=0 conn_id=[28, cc, 74, 1b] reset_token=[0a, 24, c1, f0, f3, 70, 25, 37, fe, 57, a0, 2b, 51, b8, df, b3]
[2025-09-12T02:03:50.664571725Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1280 bytes
[2025-09-12T02:03:50.664577136Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:50.664580281Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:50.664594769Z DEBUG quiche_apps::common] sending HTTP request "GET /qnwobndyve\r\n"
[2025-09-12T02:03:50.664668817Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Initial version=1 dcid=58542814 scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=6 pn=2 
[2025-09-12T02:03:50.664673556Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=86 blocks=[0..0] ecn_counts=None
[2025-09-12T02:03:50.664685889Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=4.017501701s latest_rtt=1.508972524s srtt=1.508972524s min_rtt=1.508972524s rttvar=754.486262ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=333 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 789, tv_nsec: 191846605 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { bandwidth: 1.76 Kbps, is_app_limited: true, interval: 1.508972524s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 787, tv_nsec: 682874081 }), send_elapsed: 0ns, ack_elapsed: 1.508972524s, rtt: 1.508972524s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11183, last_update: Instant { tv_sec: 789, tv_nsec: 192371178 }, next_time: Instant { tv_sec: 789, tv_nsec: 192371218 }, 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-09-12T02:03:50.664710856Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Handshake version=1 dcid=58542814 scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=45 pn=3 
[2025-09-12T02:03:50.664714543Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=60 blocks=[0..0] ecn_counts=None
[2025-09-12T02:03:50.664717739Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm CRYPTO off=0 len=36
[2025-09-12T02:03:50.664725103Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=4.017462818s latest_rtt=1.508972524s srtt=1.508972524s min_rtt=1.508972524s rttvar=754.486262ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=428 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 789, tv_nsec: 191846605 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 2, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { bandwidth: 1.76 Kbps, is_app_limited: true, interval: 1.508972524s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 787, tv_nsec: 682874081 }), send_elapsed: 0ns, ack_elapsed: 1.508972524s, rtt: 1.508972524s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11183, last_update: Instant { tv_sec: 789, tv_nsec: 192532880 }, next_time: Instant { tv_sec: 789, tv_nsec: 192371218 }, max_datagram_size: 1350, last_packet_size: None, iv: 8.495037ms, 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-09-12T02:03:50.664744188Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped epoch 0 state
[2025-09-12T02:03:50.664759828Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Short dcid=58542814 key_phase=false len=1176 pn=4 
[2025-09-12T02:03:50.664763354Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=28 blocks=[0..0] ecn_counts=None
[2025-09-12T02:03:50.664766480Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[52, f1, 5b, ff, f6, c0, 7b, da, 95, 5f, 71, 89, 57, 23, 1b, 1e, c7, 12, fa, 40] reset_token=[e2, 94, 7f, f4, 35, 84, f3, d5, d5, 0b, ce, d5, b7, 2a, 0b, 50]
[2025-09-12T02:03:50.664773363Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm NEW_CONNECTION_ID seq_num=2 retire_prior_to=0 conn_id=[4f, d7, fc, 0c, 7d, e9, d0, c0, 2e, 4b, 0e, 16, de, 8d, 32, 6b, 9f, 75, dc, a2] reset_token=[18, 41, 11, 79, c7, 42, 9e, 78, bc, 4c, 3d, 28, 35, b1, 2d, bd]
[2025-09-12T02:03:50.664779565Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm NEW_CONNECTION_ID seq_num=3 retire_prior_to=0 conn_id=[aa, 36, 01, 4e, 34, 95, 5f, b3, 7a, 3d, 4e, a2, 34, 7b, cf, c3, b4, 7d, e9, 71] reset_token=[26, 7a, cb, c1, 52, f3, 48, 12, 9c, f0, c8, 42, 8a, c8, 9e, 1f]
[2025-09-12T02:03:50.664785486Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm STREAM id=0 off=0 len=17 fin=true
[2025-09-12T02:03:50.664788622Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm PADDING len=1029
[2025-09-12T02:03:50.664797779Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=4.526778621s latest_rtt=1.508972524s srtt=1.508972524s min_rtt=1.508972524s rttvar=754.486262ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1293 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 789, tv_nsec: 191846605 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 3, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { bandwidth: 1.76 Kbps, is_app_limited: true, interval: 1.508972524s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 787, tv_nsec: 682874081 }), send_elapsed: 0ns, ack_elapsed: 1.508972524s, rtt: 1.508972524s } } pacer=Pacer { enabled: true, capacity: 13500, used: 1198, rate: 11183, last_update: Instant { tv_sec: 789, tv_nsec: 192532880 }, next_time: Instant { tv_sec: 789, tv_nsec: 201027917 }, max_datagram_size: 1350, last_packet_size: Some(1198), 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-09-12T02:03:50.664853203Z TRACE quiche_apps::client] written 1350 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:50.664859184Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:50.864405274Z TRACE quiche_apps::client] got 1280 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:50.864423518Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped invalid packet
[2025-09-12T02:03:50.864435861Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1280 bytes
[2025-09-12T02:03:50.864441251Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:50.864446391Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:50.864460588Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:50.865407150Z TRACE quiche_apps::client] got 1280 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:50.865419574Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped invalid packet
[2025-09-12T02:03:50.865422920Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1280 bytes
[2025-09-12T02:03:50.865426597Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:50.865428931Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:50.865438189Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:51.657828506Z TRACE quiche_apps::client] got 777 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:51.657865285Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Handshake version=1 dcid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 scid=58542814 len=744 pn=1 
[2025-09-12T02:03:51.657891334Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm CRYPTO off=0 len=722
[2025-09-12T02:03:51.657916300Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 777 bytes
[2025-09-12T02:03:51.657921831Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:51.657925307Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:51.657939854Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Handshake version=1 dcid=58542814 scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=5 pn=5 
[2025-09-12T02:03:51.657943782Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=9 blocks=[0..1] ecn_counts=None
[2025-09-12T02:03:51.657957648Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=3.533618131s latest_rtt=1.508972524s srtt=1.508972524s min_rtt=1.508972524s rttvar=754.486262ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1293 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 789, tv_nsec: 191846605 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 3, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { bandwidth: 1.76 Kbps, is_app_limited: true, interval: 1.508972524s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 787, tv_nsec: 682874081 }), send_elapsed: 0ns, ack_elapsed: 1.508972524s, rtt: 1.508972524s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11183, last_update: Instant { tv_sec: 790, tv_nsec: 185805200 }, next_time: Instant { tv_sec: 789, tv_nsec: 201027917 }, max_datagram_size: 1350, last_packet_size: None, iv: 107.126889ms, 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-09-12T02:03:51.658023722Z TRACE quiche_apps::client] written 55 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:51.658029733Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:51.658401730Z TRACE quiche_apps::client] got 777 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:51.658418962Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Handshake version=1 dcid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 scid=58542814 len=744 pn=2 
[2025-09-12T02:03:51.658428700Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm CRYPTO off=0 len=722
[2025-09-12T02:03:51.658443718Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 777 bytes
[2025-09-12T02:03:51.658460509Z TRACE quiche_apps::client] got 57 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:51.658465329Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped invalid packet
[2025-09-12T02:03:51.658469246Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 57 bytes
[2025-09-12T02:03:51.658473664Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:51.658476840Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:51.658488612Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Handshake version=1 dcid=58542814 scid=2f1a67f420c07bc55b9f66865d6ad5fd0341da42 len=5 pn=6 
[2025-09-12T02:03:51.658492480Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=8 blocks=[0..2] ecn_counts=None
[2025-09-12T02:03:51.658502739Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=3.533073401s latest_rtt=1.508972524s srtt=1.508972524s min_rtt=1.508972524s rttvar=754.486262ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1293 app_limited=true congestion_recovery_start_time=None Rate { delivered: 333, delivered_time: Instant { tv_sec: 789, tv_nsec: 191846605 }, first_sent_time: Instant { tv_sec: 787, tv_nsec: 682874081 }, end_of_app_limited: 3, last_sent_packet: 6, largest_acked: 0, rate_sample: RateSample { bandwidth: 1.76 Kbps, is_app_limited: true, interval: 1.508972524s, delivered: 333, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 787, tv_nsec: 682874081 }), send_elapsed: 0ns, ack_elapsed: 1.508972524s, rtt: 1.508972524s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11183, last_update: Instant { tv_sec: 790, tv_nsec: 185805200 }, next_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, 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-09-12T02:03:51.658569053Z TRACE quiche_apps::client] written 55 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:51.658576948Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:51.664599998Z TRACE quiche_apps::client] got 1280 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:51.664616529Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped invalid packet
[2025-09-12T02:03:51.664621037Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1280 bytes
[2025-09-12T02:03:51.664625976Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:51.664629122Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:51.664636807Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:51.665637621Z TRACE quiche_apps::client] got 1280 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:51.665654082Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped invalid packet
[2025-09-12T02:03:51.665658580Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1280 bytes
[2025-09-12T02:03:51.665663530Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:51.665666685Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:51.665677906Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:52.167321250Z TRACE quiche_apps::client] got 313 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:52.167351758Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Short dcid=52f15bfff6c07bda955f718957231b1ec712fa40 key_phase=false len=292 pn=1 
[2025-09-12T02:03:52.167364081Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 path ID 0 now see SCID with seq num 1
[2025-09-12T02:03:52.167372456Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm ACK delay=45 blocks=[4..4] ecn_counts=None
[2025-09-12T02:03:52.167400138Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 packet newly acked 4
[2025-09-12T02:03:52.167414074Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm NEW_TOKEN len=89
[2025-09-12T02:03:52.167417882Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm RETIRE_CONNECTION_ID seq_num=0
[2025-09-12T02:03:52.167422640Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm CRYPTO off=0 len=170
[2025-09-12T02:03:52.167452276Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm HANDSHAKE_DONE
[2025-09-12T02:03:52.167458698Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 dropped epoch 1 state
[2025-09-12T02:03:52.167509453Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 313 bytes
[2025-09-12T02:03:52.167515053Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:52.167518550Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:52.167522848Z INFO  quiche_apps::client] Retiring source CID 2f1a67f420c07bc55b9f66865d6ad5fd0341da42
[2025-09-12T02:03:52.167542195Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Short dcid=58542814 key_phase=false len=45 pn=7 
[2025-09-12T02:03:52.167546452Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm ACK delay=23 blocks=[1..1] ecn_counts=None
[2025-09-12T02:03:52.167550540Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm NEW_CONNECTION_ID seq_num=4 retire_prior_to=1 conn_id=[88, bf, 41, ee, da, 89, 63, d3, 36, 15, b7, 23, 55, f4, bf, e2, f5, 63, 45, 7b] reset_token=[ed, ff, 0b, ad, 88, 7b, 2d, 13, 92, df, d8, 04, 07, e3, 88, f9]
[2025-09-12T02:03:52.167566249Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=3.811330361s latest_rtt=1.49419153s srtt=1.507124899s min_rtt=1.49419153s rttvar=569.559944ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=67 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1531, delivered_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, first_sent_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, end_of_app_limited: 6, last_sent_packet: 7, largest_acked: 4, rate_sample: RateSample { bandwidth: 6.31 Kbps, is_app_limited: true, interval: 1.518153836s, delivered: 1198, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 789, tv_nsec: 191846605 }), send_elapsed: 1.518153836s, ack_elapsed: 1.503372842s, rtt: 1.49419153s } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 11196, last_update: Instant { tv_sec: 790, tv_nsec: 695406338 }, next_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, max_datagram_size: 1350, last_packet_size: None, iv: 5.98428ms, 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-09-12T02:03:52.167629969Z TRACE quiche_apps::client] written 67 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:52.167636151Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:52.168144754Z TRACE quiche_apps::client] got 1065 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:52.168157397Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx pkt Short dcid=52f15bfff6c07bda955f718957231b1ec712fa40 key_phase=false len=1044 pn=2 
[2025-09-12T02:03:52.168165312Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 rx frm STREAM id=0 off=0 len=1024 fin=true
[2025-09-12T02:03:52.168174159Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 1065 bytes
[2025-09-12T02:03:52.168178026Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:52.168180401Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:52.168186642Z TRACE quiche_apps::common] received 1024 bytes
[2025-09-12T02:03:52.168190690Z TRACE quiche_apps::common] stream 0 has 1024 bytes (fin? true)
[2025-09-12T02:03:52.168204676Z DEBUG quiche_apps::common] 1/1 responses received
[2025-09-12T02:03:52.168207171Z INFO  quiche_apps::common] 1/1 response(s) received in 3.013059476s, closing...
[2025-09-12T02:03:52.168215056Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx pkt Short dcid=58542814 key_phase=false len=10 pn=8 
[2025-09-12T02:03:52.168217851Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 tx frm APPLICATION_CLOSE err=0 reason=[6b, 74, 68, 78, 62, 79, 65]
[2025-09-12T02:03:52.168225705Z TRACE quiche::recovery::congestion::recovery] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 timer=3.811350078s latest_rtt=1.49419153s srtt=1.507124899s min_rtt=1.49419153s rttvar=569.559944ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=99 app_limited=true congestion_recovery_start_time=None Rate { delivered: 1531, delivered_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, first_sent_time: Instant { tv_sec: 790, tv_nsec: 293482380 }, end_of_app_limited: 7, last_sent_packet: 8, largest_acked: 4, rate_sample: RateSample { bandwidth: 6.31 Kbps, is_app_limited: true, interval: 1.518153836s, delivered: 1198, prior_delivered: 333, prior_time: Some(Instant { tv_sec: 789, tv_nsec: 191846605 }), send_elapsed: 1.518153836s, ack_elapsed: 1.503372842s, rtt: 1.49419153s } } pacer=Pacer { enabled: true, capacity: 13500, used: 32, rate: 11196, last_update: Instant { tv_sec: 790, tv_nsec: 695406338 }, next_time: Instant { tv_sec: 790, tv_nsec: 702069621 }, max_datagram_size: 1350, last_packet_size: Some(32), 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-09-12T02:03:52.168262735Z TRACE quiche_apps::client] written 32 bytes from 0.0.0.0:36168 to 193.167.100.100:443
[2025-09-12T02:03:52.168266632Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:03:53.668624054Z TRACE quiche_apps::client] got 44 bytes from 193.167.100.100:443 to 0.0.0.0:36168
[2025-09-12T02:03:53.668652828Z TRACE quiche_apps::client] 0.0.0.0:36168: processed 44 bytes
[2025-09-12T02:03:53.668660172Z TRACE quiche_apps::client] 0.0.0.0:36168: recv() would block
[2025-09-12T02:03:53.668664961Z TRACE quiche_apps::client] done reading
[2025-09-12T02:03:53.668681342Z TRACE quiche_apps::client] 0.0.0.0:36168 -> 193.167.100.100:443: done writing
[2025-09-12T02:04:03.534598798Z TRACE quiche_apps::client] timed out
[2025-09-12T02:04:03.534630607Z TRACE quiche] 2f1a67f420c07bc55b9f66865d6ad5fd0341da42 draining timeout expired
[2025-09-12T02:04:03.534678727Z TRACE quiche_apps::client] done reading
[2025-09-12T02:04:03.534687243Z INFO  quiche_apps::client] connection closed, recv=7 sent=9 lost=0 retrans=1 sent_bytes=2225 recv_bytes=4212 lost_bytes=0 [local_addr=0.0.0.0:36168 peer_addr=193.167.100.100:443 validation_state=Validated active=true recv=7 sent=9 lost=0 retrans=1 rtt=1.507124899s min_rtt=Some(1.49419153s) rttvar=569.559944ms cwnd=13500 sent_bytes=2225 recv_bytes=4212 lost_bytes=0 stream_retrans_bytes=266 pmtu=1350 delivery_rate=789]