Another handshake issue

Matthias247 commented 3 years ago

This issue is interesting because it only happens over particular internet connections, but not when client and server are close to each other:

Client side log:

Click to expand

``` Mar 19 11:11:27.284 TRACE conn{thread_id=0 conn_id=0}: quinn_proto::endpoint: initial_dcid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 11:11:27.294 TRACE conn{thread_id=0 conn_id=0}: quinn_proto::connection: wrote 290 Initial CRYPTO bytes Mar 19 11:11:27.294 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:27.294 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:27.294 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:27.348 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=1200 count=0 space=Initial Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:28.352 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:28.352 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:30.297 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 11:11:30.297 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=3600 count=1 space=Initial Mar 19 11:11:30.297 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:30.297 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:30.297 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:30.297 TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:30.297 TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:30.297 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:30.350 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:30.350 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:34.294 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 11:11:34.294 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=6000 count=2 space=Initial Mar 19 11:11:34.294 TRACE drive{id=0}:send{space=Initial pn=5}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:34.294 TRACE drive{id=0}:send{space=Initial pn=5}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:34.294 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:34.294 TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 11:11:34.294 TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection: PADDING * 851 Mar 19 11:11:34.294 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 11:11:34.338 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:34.338 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 11:11:37.296 TRACE drive{id=0}: quinn_proto::connection: timeout timer=Idle Mar 19 11:11:37.296 TRACE drive{id=0}: quinn_proto::connection: connection closed ```

==> Seems like the client does not receive the Initial packet or at least thinks it does't receive it and discards packets from the server.

Server log:

Click to expand

``` Mar 19 18:11:27.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:27.317 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:27.317 INFO first recv:frame{ty=CRYPTO}: quickstep::certs: Resolve SNI Some(DNSNameRef("")). Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:27.319 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822415, tv_nsec: 360117720 } Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.321 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:28.321 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:28.321 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:28.321 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:28.323 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:28.323 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822416, tv_nsec: 364614832 } Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822416, tv_nsec: 364643483 } Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.319 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:30.319 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:30.320 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:30.320 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:30.321 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822418, tv_nsec: 362620980 } Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:30.322 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822418, tv_nsec: 363616433 } Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:34.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:34.316 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:34.316 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:34.318 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.318 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:34.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:34.319 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:34.319 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822422, tv_nsec: 359660433 } Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822422, tv_nsec: 359686606 } Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplificationMar 19 18:11:27.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:27.317 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:27.319 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:27.319 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:27.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822415, tv_nsec: 360117720 } Mar 19 18:11:27.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:28.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.321 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:28.321 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:28.321 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:28.321 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:28.323 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822416, tv_nsec: 364614832 } Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822416, tv_nsec: 364643483 } Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:28.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:29.323 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:29.324 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.319 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:30.319 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:30.320 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:30.320 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:30.321 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:30.321 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:30.321 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.321 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822418, tv_nsec: 362620980 } Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:30.322 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:30.322 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:30.322 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822418, tv_nsec: 363616433 } Mar 19 18:11:30.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:31.321 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:31.322 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:34.316 TRACE first recv: quinn_proto::connection: authenticated Mar 19 18:11:34.316 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:34.316 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:34.318 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:34.318 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.318 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:34.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 19 18:11:34.318 TRACE first recv: quinn_proto::connection: Data keys ready Mar 19 18:11:34.319 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 19 18:11:34.319 TRACE quinn_proto::endpoint: connection incoming id=0 icid=7c5da6bcb1d57d8c2a9063a5b9404ca7d6c289c6 Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822422, tv_nsec: 359660433 } Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 19 18:11:34.319 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 822422, tv_nsec: 359686606 } Mar 19 18:11:34.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:35.318 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2452 count=0 space=Initial Mar 19 18:11:35.319 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification ```

Some thoughts around what looks wrong here:

The server only can send 2 packets until blocked by anti-amplification? It should be 3?
The server seems to see multiple connection attempts, which all seem to get into the semi-succeeding state. I guess every retry is interpreted as a new connection attempt. Now this might actually be caused by a load balancing layer routing those packets to a different quinn endpoint, and therefore should be ignorable.

Overall the main questions I have are:

Why only 2 packets?
Why is even the first server response interpreted as "unexpected Handshake packet (1220 bytes)"

Ralith commented 3 years ago

Why is even the first server response interpreted as "unexpected Handshake packet (1220 bytes)"

If the client receives a Handshake packet before any Initial packet, it can't do anything with it as it doesn't have Handshake keys yet. Is the first of the two datagrams sent by the server consistently getting lost? What does wireshark show?

I guess every retry is interpreted as a new connection attempt.

The client's initial dest CIDs seem to match, so Endpoint::connection_ids_initial should be routing these to the same connection if they're arriving at the same endpoint. If these log messages are aggregated from different endpoints, and the load balancer is indeed routing each successive Initial with the same dest CID to a different endpoint, then I think this is a bug in the load balancer; the client's retransmitted initials must be delivered to the server to relax the server's anti-amplification constraints in the event of a lost first server flight.

Why only 2 packets?

The server has received exactly 1200 bytes, so it may send at most 3 1200. Our anti-amplification check assumes MTU-sized packets, and our default MTU is 1232. 3 1232 > 3 * 1200, so the third packet would violate anti-amplification and is forbidden. Either this is working as intended, or our default MTU is too high (did we forget to subtract some headers?), or we're undercounting received data (did we forget to add some headers?).

Matthias247 commented 3 years ago

There's actually one more question about the client-side behavior:

Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=1200 count=0 space=Initial
Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 290
Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: PADDING * 851
Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 290
Mar 19 11:11:28.298 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: PADDING * 851
Mar 19 11:11:28.298 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams

Seems like on PTO the initial packet is retransmitted 2 times. But 1 time should be enough?

Matthias247 commented 3 years ago

Why is even the first server response interpreted as "unexpected Handshake packet (1220 bytes)"

If the client receives a Handshake packet before any Initial packet, it can't do anything with it as it doesn't have Handshake keys yet. Is the first of the two datagrams sent by the server consistently getting lost? What does wireshark show?

No further logs so far. Agree on the logic that the loss of the Initial packet can cause this. But it's getting so consistently lost that its just weird to purely blame it on packet loss.

I guess every retry is interpreted as a new connection attempt.

The client's initial dest CIDs seem to match, so Endpoint::connection_ids_initial should be routing these to the same connection if they're arriving at the same endpoint. If these log messages are aggregated from different endpoints, and the load balancer is indeed routing each successive Initial with the same dest CID to a different endpoint, then I think this is a bug in the load balancer; the client's retransmitted initials must be delivered to the server to relax the server's anti-amplification constraints in the event of a lost first server flight.

It's different endpoints, and definitely a LB limitation. we can ignore the issue here.

Why only 2 packets?

The server has received exactly 1200 bytes, so it may send at most 3 1200. Our anti-amplification check assumes MTU-sized packets, and our default MTU is 1232. 3 1232 > 3 * 1200, so the third packet would violate anti-amplification and is forbidden. Either this is working as intended, or our default MTU is too high (did we forget to subtract some headers?), or we're undercounting received data (did we forget to add some headers?).

Ok. I somewhat remembered that the check is relaxed, and rounds up (always allows another full-sized packet) instead of down. But I guess I should re-read that code.

Ralith commented 3 years ago

But it's getting so consistently lost that its just weird to purely blame it on packet loss.

Yeah, agreed that this is suspicious.

Seems like on PTO the initial packet is retransmitted 2 times. But 1 time should be enough?

This is intended behavior; see QUIC recovery (Sending Probe Packets):

Sending two packets on PTO expiration increases resilience to packet drops, thus reducing the probability of consecutive PTO events.

Matthias247 commented 3 years ago

This is intended behavior; see QUIC recovery (Sending Probe Packets):

Sending two packets on PTO expiration increases resilience to packet drops, thus reducing the probability of consecutive PTO events.

Interesting. In general that makes sense. However I'm wondering whether this actually helps without any delay between those - seems likely that both packets would get dropped if the first gets dropped. For servers without state the double retransmitted INITIAL packets can unfortunately be super expensive, since each of them can cause another handshake.

Ralith commented 3 years ago

However I'm wondering whether this actually helps without any delay between those - seems likely that both packets would get dropped if the first gets dropped.

I dunno, so I'm inclined to trust the draft's word on it.

each of them can cause another handshake.

They shouldn't, since they share initial destination CIDs. That was only happening above due to bad load balancer behavior.

Matthias247 commented 3 years ago

Ok, I learned a lot of things today:

When using GSO, all datagrams except the last in a server -> client flight got lost due to a path MTU limitation of that path which was apparently between the 1220 bytes and 1232 bytes. Therefore we don't see the INITIAL packet on the client arriving in the first flight, but the HANDSHAKE on. And in the second flight, when the client retransmits the INITIAL packet, the server generates 2 datagrams containing the not yet transmitted CRYPTO data of size 1232, and one of size 146. Only the last frame arrives. Only then the client then sends 2 more INITIAL packets the server starts retransmissions, and gets non-padded 1200 byte INITIAL packets to the client. The handshake then starts to recover.

While the original issue seems to have been caused by the path MTU (which might be called incompatible with Quic), I think there are still some interesting learnings in this:

The retransmit strategy doesn't seem optimal in this case. When the server gets 2 retransmitted INITIAL packets after 1s, it doesn't immediately start retransmitting old data. Instead it starts enqueuing more CRYPTO frames. Those are at this point in time absolutely not useful for the client and will just got dropped there. It seems like the PTO timer and the retransmits start 1ms later and enqueue the retransmits. But it would be a tad nicer if that would happer earlier.
The anti-amplification limit currently doesn't make optimal use of the peers budget, and in fact got worse with GSO. Without GSO the first 2 packets had 1200 bytes, and with a 1200 byte INITIAL packet from the peer we could send a third packet. With GSO, the first packet will be padded to 1232 bytes for a GSO burst, and in combination with a second packet of size 1220 bytes that doesn't allow for a third packet anymore. I guess this could be improved by either allowing a small non full datagram which still fits into the anti-amplification limit, by reducing the path MTU size during the handshake (allow for 3x 1200 bytes - but that makes things less efficient if the client sends a bigger MTU like Chrome does with 1350 bytes), or by rounding up.

Client log:

``` Mar 19 15:34:33.289 TRACE conn{thread_id=0 conn_id=0}: quinn_proto::endpoint: initial_dcid=da1295706e86e3bed4a72ef813e75bff00cc995c Mar 19 15:34:33.294 TRACE conn{thread_id=0 conn_id=0}: quinn_proto::connection: wrote 290 Initial CRYPTO bytes Mar 19 15:34:33.294 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 15:34:33.294 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: PADDING * 851 Mar 19 15:34:33.294 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 15:34:33.337 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:33.337 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Handshake packet (1220 bytes) Mar 19 15:34:34.296 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 19 15:34:34.296 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=1200 count=0 space=Initial Mar 19 15:34:34.296 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 15:34:34.296 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: PADDING * 851 Mar 19 15:34:34.296 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 15:34:34.296 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 290 Mar 19 15:34:34.296 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: PADDING * 851 Mar 19 15:34:34.296 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 15:34:34.337 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:34.338 DEBUG drive{id=0}: quinn_proto::connection: discarding unexpected Data packet (146 bytes) Mar 19 15:34:34.338 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:34.338 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (60 bytes) from [::ffff:52.46.47.93]:443 using id ab3ce46f020bd1c8 Mar 19 15:34:34.338 TRACE drive{id=0}:recv{space=Initial pn=2}: quinn_proto::connection: authenticated Mar 19 15:34:34.338 TRACE drive{id=0}:recv{space=Initial pn=2}: quinn_proto::connection: switching remote CID to 2a8e00abba1cd9181c5b09b858ceb513d004ef82 Mar 19 15:34:34.338 DEBUG drive{id=0}:recv{space=Initial pn=2}:frame{ty=ACK}: quinn_proto::connection: ECN not acknowledged by peer Mar 19 15:34:34.338 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:34.338 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from [::ffff:52.46.47.93]:443 using id ab3ce46f020bd1c8 Mar 19 15:34:34.338 TRACE drive{id=0}:recv{space=Initial pn=3}: quinn_proto::connection: authenticated Mar 19 15:34:34.338 TRACE drive{id=0}:recv{space=Initial pn=3}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes Mar 19 15:34:34.339 TRACE drive{id=0}:recv{space=Initial pn=3}: quinn_proto::connection: Handshake keys ready Mar 19 15:34:34.339 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: ACK Mar 19 15:34:34.339 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: PADDING * 1140 Mar 19 15:34:34.339 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 15:34:34.339 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:34.339 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from [::ffff:52.46.47.93]:443 using id ab3ce46f020bd1c8 Mar 19 15:34:34.339 TRACE drive{id=0}:recv{space=Initial pn=4}: quinn_proto::connection: authenticated Mar 19 15:34:34.339 TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: ACK Mar 19 15:34:34.339 TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: PADDING * 1140 Mar 19 15:34:34.339 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 19 15:34:34.437 TRACE quinn::endpoint: Received 1 datagrams Mar 19 15:34:34.437 TRACE quinn::endpoint: Received 1 datagrams ```

Server log:

``` TRACE first recv: quinn_proto::connection: authenticated Mar 20 01:48:40.873 TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 290 CRYPTO bytes Mar 20 01:48:40.873 INFO first recv:frame{ty=CRYPTO}: quickstep::certs: Resolve SNI Some(DNSNameRef("")). Mar 20 01:48:40.875 TRACE first recv: quinn_proto::connection: Handshake keys ready Mar 20 01:48:40.875 TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes Mar 20 01:48:40.875 TRACE first recv: quinn_proto::connection: Data keys ready Mar 20 01:48:40.875 TRACE first recv: quinn_proto::connection: wrote 4371 Handshake CRYPTO bytes Mar 20 01:48:40.875 TRACE quinn_proto::endpoint: connection incoming id=0 icid=63be8e7529ce4ab77ef1eaca0b0b70603545076f Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Initial of size 154. Padding: false Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1078. Padding: true Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1232 for MTU 1232 Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 20 01:48:40.876 TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: blocked by anti-amplification Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1220. Padding: false Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1220 for MTU 1232 Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection: sending 2452 bytes in 2 datagrams Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 20 01:48:40.876 TRACE quinn::platform::imp: Transmitting 2452 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:40.876 TRACE quinn::platform::imp: Setting segment size to 1232 Mar 20 01:48:40.876 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection::cid_state: CID 4 will expire at Instant { tv_sec: 849848, tv_nsec: 916917303 } Mar 20 01:48:40.876 TRACE drive{id=0}: quinn_proto::connection: blocked by anti-amplification Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from [::ffff:54.240.196.188]:29399 using id 63be8e7529ce4ab77ef1eaca0b0b70603545076f Mar 20 01:48:41.874 TRACE drive{id=0}:recv{space=Initial pn=1}: quinn_proto::connection: authenticated Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from [::ffff:54.240.196.188]:29399 using id 63be8e7529ce4ab77ef1eaca0b0b70603545076f Mar 20 01:48:41.874 TRACE drive{id=0}:recv{space=Initial pn=2}: quinn_proto::connection: authenticated Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: ACK Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Initial of size 60. Padding: false Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection: CRYPTO: off 2168 len 1101 Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection::packet_builder: PADDING * 12 Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1172. Padding: true Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1232 for MTU 1232 Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Handshake pn=3}: quinn_proto::connection: CRYPTO: off 3269 len 1102 Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1161. Padding: false Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=0c8e0073b497108c74a629a9643172c939c81fff Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 5 Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 71. Padding: true Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1232 for MTU 1232 Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=0c8e00670924281adee63cbfa4fe8ce62cc1d2a9 Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=0c8e008b886f04fc9368ffa511252ae8794bc830 Mar 20 01:48:41.874 TRACE drive{id=0}:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=0c8e00da801769e01ea32e49b78b38aa15fc05e5 Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 146. Padding: false Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 146 for MTU 1232 Mar 20 01:48:41.874 TRACE drive{id=0}: quinn_proto::connection: sending 2610 bytes in 3 datagrams Mar 20 01:48:41.874 TRACE quinn::platform::imp: Transmitting 2610 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:41.874 TRACE quinn::platform::imp: Setting segment size to 1232 Mar 20 01:48:41.874 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=5002 count=0 space=Initial Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: ACK Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection::packet_builder: PADDING * 1046 Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Initial of size 1200. Padding: true Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1200 for MTU 1232 Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: ACK Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: CRYPTO: off 0 len 90 Mar 20 01:48:41.875 TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection::packet_builder: PADDING * 1046 Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Initial of size 1200. Padding: true Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1200 for MTU 1232 Mar 20 01:48:41.875 TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams Mar 20 01:48:41.875 TRACE quinn::platform::imp: Transmitting 1200 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:41.875 TRACE quinn::platform::imp: Transmitting 1200 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:41.876 TRACE quinn::platform::imp: Sent 2 datagrams Mar 20 01:48:41.912 TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:41.912 TRACE drive{id=0}:recv{space=Initial pn=3}: quinn_proto::connection: authenticated Mar 20 01:48:41.912 TRACE drive{id=0}:recv{space=Initial pn=3}:frame{ty=ACK}: quinn_proto::connection: packets lost: [0] Mar 20 01:48:41.912 DEBUG drive{id=0}:recv{space=Initial pn=3}:frame{ty=ACK}: quinn_proto::connection: ECN not acknowledged by peer Mar 20 01:48:41.916 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 20 01:48:41.916 TRACE drive{id=0}: quinn_proto::connection: packets lost: [1] Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=4848 count=0 space=Handshake Mar 20 01:48:41.983 TRACE drive{id=0}:send{space=Handshake pn=4}: quinn_proto::connection: CRYPTO: off 0 len 1007 Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1065. Padding: false Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1065 for MTU 1232 Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: sending 1065 bytes in 1 datagrams Mar 20 01:48:41.983 TRACE drive{id=0}:send{space=Handshake pn=5}: quinn_proto::connection: CRYPTO: off 1007 len 1161 Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1220. Padding: false Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1220 for MTU 1232 Mar 20 01:48:41.983 TRACE drive{id=0}: quinn_proto::connection: sending 1220 bytes in 1 datagrams Mar 20 01:48:41.983 TRACE quinn::platform::imp: Transmitting 1065 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:41.983 TRACE quinn::platform::imp: Transmitting 1220 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:41.983 TRACE quinn::platform::imp: Sent 2 datagrams Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (59 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.020 TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: authenticated Mar 20 01:48:42.020 TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys Mar 20 01:48:42.020 TRACE drive{id=0}:recv{space=Handshake pn=0}:frame{ty=ACK}: quinn_proto::connection: packets lost: [0, 1, 2, 3] Mar 20 01:48:42.020 TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: handshake ongoing Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=6}: quinn_proto::connection: ACK Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=6}: quinn_proto::connection: CRYPTO: off 3269 len 1102 Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=6}: quinn_proto::connection: CRYPTO: off 2168 len 49 Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=6}: quinn_proto::connection::packet_builder: PADDING * 13 Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1232. Padding: true Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1232 for MTU 1232 Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=7}: quinn_proto::connection: ACK Mar 20 01:48:42.020 TRACE drive{id=0}:send{space=Handshake pn=7}: quinn_proto::connection: CRYPTO: off 2217 len 1052 Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1116. Padding: false Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1116 for MTU 1232 Mar 20 01:48:42.020 TRACE drive{id=0}: quinn_proto::connection: sending 2348 bytes in 2 datagrams Mar 20 01:48:42.020 TRACE quinn::platform::imp: Transmitting 2348 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.020 TRACE quinn::platform::imp: Setting segment size to 1232 Mar 20 01:48:42.020 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.056 TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (59 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.056 TRACE drive{id=0}:recv{space=Handshake pn=1}: quinn_proto::connection: authenticated Mar 20 01:48:42.056 TRACE drive{id=0}:recv{space=Handshake pn=1}: quinn_proto::connection: handshake ongoing Mar 20 01:48:42.062 TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection Mar 20 01:48:42.062 TRACE drive{id=0}: quinn_proto::connection: packets lost: [6] Mar 20 01:48:42.062 TRACE drive{id=0}:send{space=Handshake pn=8}: quinn_proto::connection: ACK Mar 20 01:48:42.062 TRACE drive{id=0}:send{space=Handshake pn=8}: quinn_proto::connection: CRYPTO: off 3269 len 1102 Mar 20 01:48:42.062 TRACE drive{id=0}:send{space=Handshake pn=8}: quinn_proto::connection: CRYPTO: off 2168 len 49 Mar 20 01:48:42.062 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Handshake of size 1219. Padding: false Mar 20 01:48:42.062 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 1219 for MTU 1232 Mar 20 01:48:42.062 TRACE drive{id=0}: quinn_proto::connection: sending 1219 bytes in 1 datagrams Mar 20 01:48:42.062 TRACE quinn::platform::imp: Transmitting 1219 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.062 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (98 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.098 TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: authenticated Mar 20 01:48:42.098 TRACE drive{id=0}:recv{space=Handshake pn=2}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 36 CRYPTO bytes Mar 20 01:48:42.098 TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: wrote 89 Data CRYPTO bytes Mar 20 01:48:42.098 TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: discarding Handshake keys Mar 20 01:48:42.098 TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: established Mar 20 01:48:42.098 TRACE drive{id=0}:send{space=Data pn=2}: quinn_proto::connection: CRYPTO: off 0 len 89 Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 120. Padding: false Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 120 for MTU 1232 Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection: sending 120 bytes in 1 datagrams Mar 20 01:48:42.098 TRACE quinn::platform::imp: Transmitting 120 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.098 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.098 TRACE quinn_proto::connection::streams: wrote 1 bytes stream=server unidirectional stream 0 Mar 20 01:48:42.098 TRACE quinn_proto::connection::streams: wrote 1 bytes stream=server unidirectional stream 1 Mar 20 01:48:42.098 TRACE quinn_proto::connection::streams: wrote 1 bytes stream=server unidirectional stream 2 Mar 20 01:48:42.098 TRACE quinn_proto::connection::streams: wrote 2 bytes stream=server unidirectional stream 0 Mar 20 01:48:42.098 TRACE drive{id=0}:send{space=Data pn=3}: quinn_proto::connection::streams::state: STREAM id=server unidirectional stream 0 off=0 len=3 fin=false Mar 20 01:48:42.098 TRACE drive{id=0}:send{space=Data pn=3}: quinn_proto::connection::streams::state: STREAM id=server unidirectional stream 1 off=0 len=1 fin=false Mar 20 01:48:42.098 TRACE drive{id=0}:send{space=Data pn=3}: quinn_proto::connection::streams::state: STREAM id=server unidirectional stream 2 off=0 len=1 fin=false Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 40. Padding: false Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 40 for MTU 1232 Mar 20 01:48:42.098 TRACE drive{id=0}: quinn_proto::connection: sending 40 bytes in 1 datagrams Mar 20 01:48:42.098 TRACE quinn::platform::imp: Transmitting 40 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.098 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.099 TRACE drive{id=0}: quinn_proto::connection: got Data packet (150 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.099 TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: authenticated Mar 20 01:48:42.099 TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=bd496ba2ed470b5d retire_prior_to=0 Mar 20 01:48:42.099 TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=c8844f5a5e6afa53 retire_prior_to=0 Mar 20 01:48:42.099 TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=7660d6ddf4c31df6 retire_prior_to=0 Mar 20 01:48:42.099 TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=4896bc8131e368bd retire_prior_to=0 Mar 20 01:48:42.099 TRACE drive{id=0}:send{space=Data pn=4}: quinn_proto::connection: ACK Mar 20 01:48:42.099 TRACE drive{id=0}:send{space=Data pn=4}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 Mar 20 01:48:42.099 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 33. Padding: false Mar 20 01:48:42.099 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 33 for MTU 1232 Mar 20 01:48:42.099 TRACE drive{id=0}: quinn_proto::connection: sending 33 bytes in 1 datagrams Mar 20 01:48:42.099 TRACE quinn::platform::imp: Transmitting 33 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.099 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.100 TRACE drive{id=0}: quinn_proto::connection: got Data packet (59 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.100 TRACE drive{id=0}:recv{space=Data pn=1}: quinn_proto::connection: authenticated Mar 20 01:48:42.100 TRACE drive{id=0}: quinn_proto::connection: connection closed Mar 20 01:48:42.100 TRACE drive{id=0}:send{space=Data pn=5}: quinn_proto::connection: sending CONNECTION_CLOSE Mar 20 01:48:42.100 TRACE drive{id=0}: quinn_proto::connection::packet_builder: Finished packet for space Data of size 30. Padding: false Mar 20 01:48:42.100 TRACE drive{id=0}: quinn_proto::connection: Built datagram with a final size of 30 for MTU 1232 Mar 20 01:48:42.100 TRACE drive{id=0}: quinn_proto::connection: sending 30 bytes in 1 datagrams Mar 20 01:48:42.100 TRACE quinn::platform::imp: Transmitting 30 bytes to SockAddr { family: 10, inet6: [::ffff:54.240.196.188]:29399 } Mar 20 01:48:42.100 TRACE quinn::platform::imp: Sent 1 datagrams Mar 20 01:48:42.134 TRACE drive{id=0}: quinn_proto::connection: got Data packet (59 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.134 TRACE drive{id=0}: quinn_proto::connection: got Data packet (59 bytes) from [::ffff:54.240.196.188]:29399 using id 0c8e00b82ef1b870967d081a309e490250dcb78f Mar 20 01:48:42.304 TRACE drive{id=0}: quinn_proto::connection: timeout timer=Close ```

Ralith commented 3 years ago

While the original issue seems to have been caused by the path MTU (which might be called incompatible with Quic)

Part of why Initial-bearing datagrams must be padded is to trivially enforce path compatibility. If the initial got through, and later packets don't, that's our fault; either our default MTU is too high or we're padding Initial-bearing datagrams inadequately (but probably the former). Correcting this will probably also improve anti-amplification behavior.

The retransmit strategy doesn't seem optimal

I vaguely recall other implementers advocating special behavior for handshake retransmits, though I'm not sure if it was recorded and I don't recall the details. Probably worth asking about on the slack.

Ralith commented 3 months ago

The anti-amplification limit currently doesn't make optimal use of the peers budget, and in fact got worse with GSO

This issue has been fixed in https://github.com/quinn-rs/quinn/pull/1837.

quinn-rs / quinn

Another handshake issue #1075