Compatibility issues with quic-go server

[nathanejohnson]

I've been seeing issues connecting to a quic-go server from a quiche based client. This works fine with 0.22.0 based quiche, but no newer published versions will work properly. This commit seems to be the culprit:

b17904e

Below are some trace logs. Initial connection works, handshake succeeds, but then sometime later I get a CryptoFail error from quiche::send_on_path method.

[TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 write message lvl=Initial len=261
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Initial version=1 dcid=286c9160ef2b9748421b2723d2df60fd scid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 len=265 pn=0 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm CRYPTO off=0 len=261
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=998.941208ms latest_rtt=0ns srtt=333ms min_rtt=333ms rttvar=166.5ms cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=328 app_limited=true congestion_recovery_start_time=None Rate { delivered: 0, delivered_time: Instant { tv_sec: 220838, tv_nsec: 587762083 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 587762083 }, 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: 220838, tv_nsec: 587762083 }, next_time: Instant { tv_sec: 220838, tv_nsec: 587762083 }, 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 } 
[TRACE quiche_test::connectiontest] written 1200
[DEBUG quiche_test::connectiontest] polling
[DEBUG quiche_test::connectiontest] normal socket selected
[DEBUG quiche_test::connectiontest] read 1280 bytes
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Initial version=1 dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 scid=30fe429d token= len=117 pn=0 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm ACK delay=0 blocks=[0..0] ecn_counts=None
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 packet newly acked 0
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm CRYPTO off=0 len=90
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 set write secret lvl=Handshake
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 set read secret lvl=Handshake
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Handshake version=1 dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 scid=30fe429d len=1096 pn=0 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm CRYPTO off=0 len=1074
[TRACE quiche_test::connectiontest] read 0.0.0.0:54372: processed 1280 bytes
[DEBUG quiche_test::connectiontest] read 1280 bytes
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Handshake version=1 dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 scid=30fe429d len=1247 pn=1 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm CRYPTO off=1074 len=1224
[TRACE quiche_test::connectiontest] read 0.0.0.0:54372: processed 1280 bytes
[DEBUG quiche_test::connectiontest] read 133 bytes
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Handshake version=1 dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 scid=30fe429d len=37 pn=2 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm CRYPTO off=2298 len=15
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 write message lvl=Handshake len=36
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 set write secret lvl=OneRTT
[TRACE quiche::tls] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 set read secret lvl=OneRTT
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 connection established: proto=Ok("h3") cipher=Some(AES128_GCM) curve=Some("X25519") sigalg=Some("ecdsa_secp256r1_sha256") resumed=false TransportParams { original_destination_connection_id: Some(286c9160ef2b9748421b2723d2df60fd), max_idle_timeout: 30000, stateless_reset_token: Some(322861833387078862669263359729604088135), 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(30fe429d), retry_source_connection_id: None, max_datagram_frame_size: Some(16383), unknown_params: None }
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Short dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 key_phase=false len=42 pn=0 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[58, 20, 56, a4] reset_token=[20, 4c, 72, be, 7d, 28, 18, 29, ed, 62, 94, ad, 5b, 44, 8f, de]
[TRACE quiche_test::connectiontest] read 0.0.0.0:54372: processed 133 bytes
[DEBUG quiche_test::connectiontest] read 53 bytes
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx pkt Short dcid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 key_phase=false len=32 pn=1 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm STREAM id=3 off=0 len=12 fin=false
[TRACE quiche_test::connectiontest] read 0.0.0.0:54372: processed 53 bytes
[TRACE quiche_test::connectiontest] 0.0.0.0:54372: recv() would block
[TRACE quiche_test::connectiontest] done reading
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm SETTINGS stream=2 len=18
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 open GREASE stream 14
[DEBUG quiche_test::connectiontest] in send_http3_request()
[DEBUG quiche_test::connectiontest] Sent HTTP request [":method: POST", ":scheme: https", ":authority: localtest.localhost:8080", ":path: /test", "user-agent: test", "transfer-method: chunked", "chunk-size: 80000", "chunk-count: 40", "content-length: 3200000"]
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm GREASE stream=0 len=0
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm GREASE stream=0 len=18
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm HEADERS stream=0 len=111 fin=false
[DEBUG quiche_test::connectiontest] write called
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm DATA stream=0 len=13298 fin=false
[DEBUG quiche_test::connectiontest] write returning, written: 13298 finsihed: false total bytes_sent: 13298
[DEBUG quiche_test::connectiontest] in read_http3_response
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 stream id 3 is readable
[TRACE quiche::h3::stream] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 read 1 bytes on stream 3
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 open peer's control stream 3
[TRACE quiche::h3::stream] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 read 1 bytes on stream 3
[TRACE quiche::h3::stream] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 read 1 bytes on stream 3
[TRACE quiche::h3::stream] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 read 9 bytes on stream 3
[TRACE quiche::h3] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 rx frm SETTINGS max_field_section=None, qpack_max_table=None, qpack_blocked=None raw=Some([(51, 1), (8, 1), (727725890, 1)]), additional_settings=Some([(727725890, 1)]) stream=3 payload_len=9
[DEBUG quiche_test::connectiontest] about to handle events
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Initial version=1 dcid=30fe429d scid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 len=6 pn=1 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm ACK delay=172 blocks=[0..0] ecn_counts=None
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=337.956µs latest_rtt=575.875µs srtt=575.875µs min_rtt=575.875µs rttvar=287.937µs cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=0 app_limited=true congestion_recovery_start_time=None Rate { delivered: 328, delivered_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, end_of_app_limited: 1, last_sent_packet: 1, largest_acked: 0, rate_sample: RateSample { bandwidth: 4.56 Mbps, is_app_limited: true, interval: 575.875µs, delivered: 328, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 220838, tv_nsec: 587762083 }), send_elapsed: 0ns, ack_elapsed: 575.875µs, rtt: 575.875µs } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 29303234, last_update: Instant { tv_sec: 220838, tv_nsec: 589717458 }, next_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, 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 } 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Handshake version=1 dcid=30fe429d scid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 len=45 pn=2 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm ACK delay=62 blocks=[0..2] ecn_counts=None
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm CRYPTO off=0 len=36
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=1.692873ms latest_rtt=575.875µs srtt=575.875µs min_rtt=575.875µs rttvar=287.937µs cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=95 app_limited=true congestion_recovery_start_time=None Rate { delivered: 328, delivered_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, end_of_app_limited: 1, last_sent_packet: 2, largest_acked: 0, rate_sample: RateSample { bandwidth: 4.56 Mbps, is_app_limited: true, interval: 575.875µs, delivered: 328, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 220838, tv_nsec: 587762083 }), send_elapsed: 0ns, ack_elapsed: 575.875µs, rtt: 575.875µs } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 29303234, last_update: Instant { tv_sec: 220838, tv_nsec: 589717458 }, next_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, max_datagram_size: 1350, last_packet_size: None, iv: 3.242µs, 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 } 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 dropped epoch 0 state
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Short dcid=30fe429d key_phase=false len=1176 pn=3 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm ACK delay=57 blocks=[0..1] ecn_counts=None
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm NEW_CONNECTION_ID seq_num=1 retire_prior_to=0 conn_id=[5e, 6e, 0a, 47, 42, 66, 5d, fd, c6, 57, ef, c9, dd, 09, 55, 70, c0, 20, 6f, cc] reset_token=[15, 25, fb, 86, 07, 03, 51, b1, 0f, fe, da, 72, 2b, 8b, 92, f1]
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm STREAM id=2 off=0 len=19 fin=false
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm PADDING len=1107
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=1.65304ms latest_rtt=575.875µs srtt=575.875µs min_rtt=575.875µs rttvar=287.937µs cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1293 app_limited=true congestion_recovery_start_time=None Rate { delivered: 328, delivered_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, end_of_app_limited: 1, last_sent_packet: 3, largest_acked: 0, rate_sample: RateSample { bandwidth: 4.56 Mbps, is_app_limited: true, interval: 575.875µs, delivered: 328, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 220838, tv_nsec: 587762083 }), send_elapsed: 0ns, ack_elapsed: 575.875µs, rtt: 575.875µs } } pacer=Pacer { enabled: true, capacity: 13500, used: 1198, rate: 29303234, last_update: Instant { tv_sec: 220838, tv_nsec: 589717458 }, next_time: Instant { tv_sec: 220838, tv_nsec: 589720700 }, 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 } 
[DEBUG quiche_test::connectiontest] pulled 1350 bytes from conn, about to send to socket
[DEBUG quiche_test::connectiontest] written 1350
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Short dcid=30fe429d key_phase=false len=6 pn=4 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm STREAM id=6 off=0 len=1 fin=false
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=1.612498ms latest_rtt=575.875µs srtt=575.875µs min_rtt=575.875µs rttvar=287.937µs cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1321 app_limited=true congestion_recovery_start_time=None Rate { delivered: 328, delivered_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, end_of_app_limited: 1, last_sent_packet: 4, largest_acked: 0, rate_sample: RateSample { bandwidth: 4.56 Mbps, is_app_limited: true, interval: 575.875µs, delivered: 328, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 220838, tv_nsec: 587762083 }), send_elapsed: 0ns, ack_elapsed: 575.875µs, rtt: 575.875µs } } pacer=Pacer { enabled: true, capacity: 13500, used: 0, rate: 29303234, last_update: Instant { tv_sec: 220838, tv_nsec: 589825833 }, next_time: Instant { tv_sec: 220838, tv_nsec: 589720700 }, max_datagram_size: 1350, last_packet_size: None, iv: 41.838µs, 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 } 
[DEBUG quiche_test::connectiontest] pulled 28 bytes from conn, about to send to socket
[DEBUG quiche_test::connectiontest] written 28
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Short dcid=30fe429d key_phase=false len=6 pn=5 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm STREAM id=10 off=0 len=1 fin=false
[ERROR quiche_test::connectiontest] send failed: CryptoFail
[DEBUG quiche_test::connectiontest] polling
[DEBUG quiche_test::connectiontest] normal socket selected
[DEBUG quiche_test::connectiontest] read 317 bytes
[TRACE quiche_test::connectiontest] read 0.0.0.0:54372: processed 317 bytes
[TRACE quiche_test::connectiontest] 0.0.0.0:54372: recv() would block
[TRACE quiche_test::connectiontest] done reading
[DEBUG quiche_test::connectiontest] write called
[DEBUG quiche_test::connectiontest] write() Err::Done
[DEBUG quiche_test::connectiontest] write returning, written: 0 finsihed: false total bytes_sent: 13298
[DEBUG quiche_test::connectiontest] in read_http3_response
[DEBUG quiche_test::connectiontest] about to handle events
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx pkt Handshake version=1 dcid=30fe429d scid=ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 len=8 pn=5 
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 tx frm CONNECTION_CLOSE err=1 frame=0 reason=[66, 61, 69, 6c]
[TRACE quiche::recovery::congestion::recovery] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 timer=1.717623ms latest_rtt=575.875µs srtt=575.875µs min_rtt=575.875µs rttvar=287.937µs cwnd=13500 ssthresh=18446744073709551615 bytes_in_flight=1379 app_limited=true congestion_recovery_start_time=None Rate { delivered: 328, delivered_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, first_sent_time: Instant { tv_sec: 220838, tv_nsec: 589717458 }, end_of_app_limited: 1, last_sent_packet: 5, largest_acked: 0, rate_sample: RateSample { bandwidth: 4.56 Mbps, is_app_limited: true, interval: 575.875µs, delivered: 328, prior_delivered: 0, prior_time: Some(Instant { tv_sec: 220838, tv_nsec: 587762083 }), send_elapsed: 0ns, ack_elapsed: 575.875µs, rtt: 575.875µs } } pacer=Pacer { enabled: true, capacity: 13500, used: 58, rate: 29303234, last_update: Instant { tv_sec: 220838, tv_nsec: 589825833 }, next_time: Instant { tv_sec: 220838, tv_nsec: 590073379 }, max_datagram_size: 1350, last_packet_size: Some(58), 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 } 
[DEBUG quiche_test::connectiontest] pulled 58 bytes from conn, about to send to socket
[DEBUG quiche_test::connectiontest] written 58
[DEBUG quiche_test::connectiontest] done writing
[DEBUG quiche_test::connectiontest] polling
[TRACE quiche_test::connectiontest] timed out
[TRACE quiche] ccc6ccf2d1124ff11c5bebe6075e027a395e32a1 draining timeout expired
[TRACE quiche_test::connectiontest] done reading
[INFO  quiche_test::connectiontest] connection closed, recv=6 sent=6 lost=0 retrans=0 sent_bytes=1764 recv_bytes=2746 lost_bytes=0 [local_addr=0.0.0.0:54372 peer_addr=127.0.0.1:8080 validation_state=Validated active=true recv=6 sent=6 lost=0 retrans=0 rtt=575.875µs min_rtt=Some(575.875µs) rttvar=287.937µs cwnd=13500 sent_bytes=1764 recv_bytes=2746 lost_bytes=0 stream_retrans_bytes=0 pmtu=1350 delivery_rate=569568]
failed to communicate with upstream

[ghedo]

Could you provide a way to reproduce the issue? Or at least describe what the scenario is (e.g. from the logs it looks like a POST request, so are you uploading data?). Also, are you using the quiche-client command or some other client?

[ghedo]

FTR, I tried reproducing using quiche-client against the server at https://quic-go.net, e.g.

RUST_LOG=trace cargo run --bin quiche-client -- https://quic-go.net/docs/ --wire-version 1

but the request seems to complete just fine, and the connection closes gracefully.

EDIT: the above is with latest quiche master, not sure if it makes any difference TBH.

[ghedo]

It's also maybe worth noting that we've fixed a few related issues in the past (e.g. 987dc66 and linked commits from that), but as of quiche 0.23.3 those should be fixed, so if you are using a version of quiche newer than that it might be a new issue that we haven't run into before.

[nathanejohnson]

As far as reproducing the issue, I will try to work on a minimal code example to reproduce, but I can't share the actual code in question. But generally: POST request for a fairly large amount of data, say 3-4 MB at least. I have tried this against the tip of quiche master, same result as with 0.23.x or with 0.24.4. The client in question is my own code, basically a minimal cli app that tests an exported library we use elsewhere. My guess is that at some point the quic-go server maybe sends an AEAD counter that isn't strictly monotonically increasing, but I have no idea how to verify that. Moving the AEAD calls to the non _tls13() calls does fix the issue (as in the PR), but I'm not sure exactly why.

[nathanejohnson]

@ghedo would a packet capture with session keys be helpful?

[nathanejohnson]

So right before the error, this is sent from server (quic-go) to client (quiche):

And this is the response:

[nathanejohnson]

quiche_issue_2108.tar.gz

This has the pcap as well as the keylog file.

[ghedo]

So, as far as I can tell the issue is caused by a failure to encrypt packets, so I don't think it would be caused by anything quic-go specifically sent, and I imagine you could maybe see the same issue against other servers. Is quic-go the only server implementation you tested against? I wonder if using something else would change the outcome.

It would also be useful if you could try quiche-client against your server as well if possible (see https://github.com/cloudflare/quiche?tab=readme-ov-file#command-line-apps), just to exclude issues that might be due to specific client implementation (we'd still want to debug the problem if it was just your client, but it would help investigate).

Something else that you could maybe try is to add a line like println!("{counter}"); at the beginning of this method https://github.com/cloudflare/quiche/blob/master/quiche/src/crypto/boringssl.rs#L123, what you should see is the first counter starting from 0 and then incrementing in order with each call. If that is not the case then there might be a call missing somewhere or potentially reordered calls. Does your client implementation use multiple threads by any chance?

Also, another thing maybe worth trying would be to build quiche with the boringssl-boring-crate feature enabled (see https://docs.rs/quiche/latest/quiche/#feature-flags), which uses a different BoringSSL version (and you could provide an even more recent version using the BORING_BSSL_SOURCE_PATH environment variable) since the vendored version in this repo is quite old and will be removed soon anyway (#2080).

Other than that I don't see anything obviously wrong in the PCAP or the trace logs (other than the fact that the connection shouldn't be closed obviously), so having minimal code reproducers for both the quiche-based client and the quic-go-based server would probably be the most useful thing to debug the issue, if you can provide them.

If the issue with sharing the code is just with putting it in the public issue we could maybe figure out a way for you to share the code in question privately if it'd help, but it's by no means a requirement (and totally understandable if you don't want to share in private either).

In any case thanks for reporting the issue and helping with the on-going debugging! ✨

[nathanejohnson]

So, as far as I can tell the issue is caused by a failure to encrypt packets, so I don't think it would be caused by anything quic-go specifically sent, and I imagine you could maybe see the same issue against other servers. Is quic-go the only server implementation you tested against? I wonder if using something else would change the outcome.

have only tested with quic-go. this is not a general purpose client / server, it's for a very specific use case, only one endpoint etc. but if I get time I will experiment with other server implementations.

It would also be useful if you could try quiche-client against your server as well if possible (see https://github.com/cloudflare/quiche?tab=readme-ov-file#command-line-apps), just to exclude issues that might be due to specific client implementation (we'd still want to debug the problem if it was just your client, but it would help investigate).

I will work on a trivial test with this, probably the easiest path forward.

Something else that you could maybe try is to add a line like println!("{counter}"); at the beginning of this method https://github.com/cloudflare/quiche/blob/master/quiche/src/crypto/boringssl.rs#L123, what you should see is the first counter starting from 0 and then incrementing in order with each call. If that is not the case then there might be a call missing somewhere or potentially reordered calls. Does your client implementation use multiple threads by any chance?

single threaded app, single connection, using mio. Here is the result of adding the println:

0
0
1
2
0
1

Other than that I don't see anything obviously wrong in the PCAP or the trace logs (other than the fact that the connection shouldn't be closed obviously), so having minimal code reproducers for both the quiche-based client and the quic-go-based server would probably be the most useful thing to debug the issue, if you can provide them.

I will work on this, but it might take me a minute with juggling other things. But I will come up with something my emloyer doesn't consider prorpietary.

Thanks again!

EDIT - I accidentally added the prinln statement to open_with_u64_counter instead of seal_with_u64_counter , my line numbers don't match up to yours since I'm using my local fork and the contents look very similar. Sorry about that. Here is my updated println output:

0
0
0
0
0
1
2
3
4
5

and I added a println right before it returns CryptoFail to verify I was in the right place, and sure enough:

crypto fail: 5

[nathanejohnson]

Also, forgot to mention, I've tried this with the vendored boringssl as well as the crate version - both 4.17 and tip on that one as well. Same results.

[nathanejohnson]

so... went down some rabbit holes. I have a few answers, but more questions.

Here is a trivial quiche http3 client that reproduces the issue.

https://github.com/nathanejohnson/quiche-http3-client

This is a copy of the quiche/examples/http3-client.rs with some minor tweaks. If you notice in the Cargo.toml, I have this:

[profile.release]
panic = "abort"

I have a trival quic-go based server that always returns a hello world payload:

https://github.com/nathanejohnson/quicgotest

If I compile with --release, I get this in the logs:

[2025-07-18T02:08:11.131329000Z ERROR http3_client] send failed: CryptoFail

if I compile without, I get this in the logs:

<html><head><title>hello world</title></head>
Hello World!
</html>

I'm on macos 15.5, rust version 1.88 installed from rustup.

curiouser and curiouser. I think you're right though, this probably has nothing to do with quic-go at this point.

[nathanejohnson]

as a followup, I cannot reproduce the issue on ubuntu 24.04.2, but I have reproduced it on two macs running 15.5, one intel, one arm.

[nathanejohnson]

another followup: back to my earlier PR (which you were right to reject), but still, this is interesting: if you replace the Cargo.toml from the http3 example linked above with this:

[package]
name = "http3-client"
version = "0.1.0"
edition = "2024"

[dependencies]

mio = { version = "1.0", features = ["net", "os-poll"] }
url = "1"
log = "0.4"
ring = "0.17"
env_logger = "0.11.8"

[dependencies.quiche]
version = "0.24.4"
default-features = false

[features]
default = ["quiche-boringssl-vendored", "quiche-relax-aead"]
quiche-boringssl-vendored = ["quiche/boringssl-vendored"]
quiche-boringssl-boring-crate = ["quiche/boringssl-boring-crate"]
quiche-relax-aead = ["quiche/relax-aead"]

[profile.release]
panic = "abort"

[patch.crates-io]
quiche = { git = "https://github.com/nathanejohnson/quiche.git", rev = "b382ef07602906492872ff22033605afb8dbd24f" }

this works properly on mac with --release. So I'm not actually insane. Can you think of any reason why the _tls13() methods might conflict with panic = "abort"?