search

quinn-rs / quinn

Async-friendly QUIC implementation in Rust
Apache License 2.0
3.88k stars 395 forks source link

Flaky test: `single_ack_eliciting_packet_triggers_ack_after_delay` #2014

Open Darksonn opened 1 month ago

Darksonn commented 1 month ago

The single_ack_eliciting_packet_triggers_ack_after_delay test just failed in Tokio's CI on https://github.com/tokio-rs/tokio/pull/6899 which should not have impacted this test.

failures:

---- tests::single_ack_eliciting_packet_triggers_ack_after_delay stdout ----
2024-10-16T14:39:26.074622Z  INFO quinn_proto::tests::util: connecting
2024-10-16T14:39:26.074699Z TRACE client: quinn_proto::endpoint: initial_dcid=3426b078460b06cd9e6aabaabacd0c960910f9ec
2024-10-16T14:39:26.075843Z TRACE client: quinn_proto::connection: wrote 271 Initial CRYPTO bytes
2024-10-16T14:39:26.075918Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 271
2024-10-16T14:39:26.075939Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 870
2024-10-16T14:39:26.075984Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2024-10-16T14:39:26.076529Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 271 CRYPTO bytes
2024-10-16T14:39:26.079346Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready
2024-10-16T14:39:26.079363Z TRACE server:first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes
2024-10-16T14:39:26.079475Z TRACE server:first recv: quinn_proto::connection: Data keys ready
2024-10-16T14:39:26.079566Z TRACE server:first recv: quinn_proto::connection: wrote 635 Handshake CRYPTO bytes
2024-10-16T14:39:26.079643Z TRACE server: quinn_proto::endpoint: new connection id=0 icid=3426b078460b06cd9e6aabaabacd0c960910f9ec
2024-10-16T14:39:26.079716Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2024-10-16T14:39:26.079743Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90
2024-10-16T14:39:26.079814Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 635
2024-10-16T14:39:26.079838Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 374
2024-10-16T14:39:26.079879Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2024-10-16T14:39:26.079971Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=41c37c7d408d1348
2024-10-16T14:39:26.080002Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=db644b1873534bf3
2024-10-16T14:39:26.080029Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=7b31918fa7361050
2024-10-16T14:39:26.080056Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=26734e01f51b7d56
2024-10-16T14:39:26.080109Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams
2024-10-16T14:39:26.080175Z TRACE client: quinn_proto::connection: got Initial packet (145 bytes) from [::1]:4500 using id 373a1d00fb4ed8fd
2024-10-16T14:39:26.080223Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to d105da0e0ee7f035
2024-10-16T14:39:26.080294Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes
2024-10-16T14:39:26.081782Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready
2024-10-16T14:39:26.081821Z TRACE client: quinn_proto::connection: got Handshake packet (1055 bytes) from [::1]:4500 using id 373a1d00fb4ed8fd
2024-10-16T14:39:26.081885Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 635 CRYPTO bytes
2024-10-16T14:39:26.082565Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready
2024-10-16T14:39:26.082656Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes
2024-10-16T14:39:26.082719Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established
2024-10-16T14:39:26.082752Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4500 using id 373a1d00fb4ed8fd
2024-10-16T14:39:26.082812Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [65, 195, 124, 125, 64, 141, 19, 72], reset_token: ResetToken([68, 159, 251, 49, 63, 65, 219, 8, 246, 149, 85, 64, 187, 34, 138, 207]) })
2024-10-16T14:39:26.082840Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=41c37c7d408d1348 retire_prior_to=0
2024-10-16T14:39:26.082891Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [219, 100, 75, 24, 115, 83, 75, 243], reset_token: ResetToken([13, 50, 58, 133, 125, 74, 211, 189, 68, 169, 160, 42, 167, 233, 193, 147]) })
2024-10-16T14:39:26.082916Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=db644b1873534bf3 retire_prior_to=0
2024-10-16T14:39:26.082967Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [123, 49, 145, 143, 167, 54, 16, 80], reset_token: ResetToken([136, 152, 150, 226, 252, 45, 255, 47, 122, 98, 132, 190, 144, 69, 158, 96]) })
2024-10-16T14:39:26.082991Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=7b31918fa7361050 retire_prior_to=0
2024-10-16T14:39:26.083044Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [38, 115, 78, 1, 245, 27, 125, 86], reset_token: ResetToken([164, 219, 91, 84, 95, 55, 114, 79, 92, 216, 21, 252, 218, 139, 103, 229]) })
2024-10-16T14:39:26.083070Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=26734e01f51b7d56 retire_prior_to=0
2024-10-16T14:39:26.083145Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2024-10-16T14:39:26.083198Z TRACE client: quinn_proto::connection: discarding Initial keys
2024-10-16T14:39:26.083236Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2024-10-16T14:39:26.083256Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52
2024-10-16T14:39:26.083278Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 1044
2024-10-16T14:39:26.083322Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2024-10-16T14:39:26.083360Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 1298
2024-10-16T14:39:26.083421Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326
2024-10-16T14:39:26.083438Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams
2024-10-16T14:39:26.083543Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=6643870c980dea9a
2024-10-16T14:39:26.083574Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=5eed99a582064533
2024-10-16T14:39:26.083598Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=b184fbc48c1fe7a5
2024-10-16T14:39:26.083620Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=445e6b5f13b2f56a
2024-10-16T14:39:26.083670Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams
2024-10-16T14:39:26.083733Z TRACE server: quinn_proto::connection: got Initial packet (51 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.083830Z TRACE server: quinn_proto::connection: got Handshake packet (1149 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.083876Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys
2024-10-16T14:39:26.083944Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes
2024-10-16T14:39:26.084559Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes
2024-10-16T14:39:26.084583Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys
2024-10-16T14:39:26.084604Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established
2024-10-16T14:39:26.084632Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.084688Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.084722Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.085182Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.085246Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [102, 67, 135, 12, 152, 13, 234, 154], reset_token: ResetToken([99, 189, 54, 190, 16, 246, 247, 22, 176, 45, 222, 39, 131, 164, 169, 11]) })
2024-10-16T14:39:26.085273Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=6643870c980dea9a retire_prior_to=0
2024-10-16T14:39:26.085331Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [94, 237, 153, 165, 130, 6, 69, 51], reset_token: ResetToken([116, 155, 93, 216, 242, 220, 8, 195, 202, 74, 185, 19, 213, 151, 220, 177]) })
2024-10-16T14:39:26.085358Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=5eed99a582064533 retire_prior_to=0
2024-10-16T14:39:26.085401Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [177, 132, 251, 196, 140, 31, 231, 165], reset_token: ResetToken([254, 229, 21, 46, 57, 100, 238, 236, 147, 11, 2, 56, 169, 182, 195, 146]) })
2024-10-16T14:39:26.085427Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=b184fbc48c1fe7a5 retire_prior_to=0
2024-10-16T14:39:26.085476Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [68, 94, 107, 95, 19, 178, 245, 106], reset_token: ResetToken([23, 90, 82, 236, 211, 41, 141, 86, 58, 121, 234, 125, 214, 57, 64, 52]) })
2024-10-16T14:39:26.085502Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=445e6b5f13b2f56a retire_prior_to=0
2024-10-16T14:39:26.085580Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us
2024-10-16T14:39:26.085607Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356
2024-10-16T14:39:26.085627Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0
2024-10-16T14:39:26.085674Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams
2024-10-16T14:39:26.085711Z TRACE server:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1298
2024-10-16T14:39:26.085763Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326
2024-10-16T14:39:26.085780Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams
2024-10-16T14:39:26.085853Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.085913Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone
2024-10-16T14:39:26.085933Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys
2024-10-16T14:39:26.085986Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame Ack(Ack { largest: 1, delay: 0, ecn: Some(EcnCounts { ect0: 2, ect1: 0, ce: 0 }), ranges: "[0..=1]" })
2024-10-16T14:39:26.086021Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326
2024-10-16T14:39:26.086077Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356
2024-10-16T14:39:26.086105Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes
2024-10-16T14:39:26.086320Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 }
2024-10-16T14:39:26.086362Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.086421Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.086457Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.086944Z TRACE client:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us
2024-10-16T14:39:26.086995Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.087037Z TRACE client:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1361
2024-10-16T14:39:26.087096Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389
2024-10-16T14:39:26.087113Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams
2024-10-16T14:39:26.087136Z TRACE client: quinn_proto::endpoint: peer retired CID 0: 373a1d00fb4ed8fd
2024-10-16T14:39:26.087198Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=5e175d265a7298ac
2024-10-16T14:39:26.087252Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams
2024-10-16T14:39:26.087317Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.087[386](https://github.com/tokio-rs/tokio/actions/runs/11367899879/job/31621769987?pr=6899#step:8:387)Z TRACE server:recv{space=Data pn=2}: quinn_proto::connection: got frame Ack(Ack { largest: 2, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[0..=2]" })
2024-10-16T14:39:26.087433Z TRACE server:recv{space=Data pn=2}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326
2024-10-16T14:39:26.087492Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.087548Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.087580Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.088040Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.088089Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [94, 23, 93, 38, 90, 114, 152, 172], reset_token: ResetToken([181, 122, 224, 225, 132, 247, 202, 0, 6, 60, 231, 240, 66, 190, 250, 129]) })
2024-10-16T14:39:26.088115Z TRACE server:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=5e175d265a7298ac retire_prior_to=0
2024-10-16T14:39:26.088177Z TRACE server:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([2..5]), Delay = 0us
2024-10-16T14:39:26.088219Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.088253Z TRACE server:send{space=Data pn=4}: quinn_proto::connection::packet_builder: PADDING * 1361
2024-10-16T14:39:26.088304Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389
2024-10-16T14:39:26.088318Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams
2024-10-16T14:39:26.088371Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4500 using id 664[387](https://github.com/tokio-rs/tokio/actions/runs/11367899879/job/31621769987?pr=6899#step:8:388)0c980dea9a
2024-10-16T14:39:26.088428Z TRACE client:recv{space=Data pn=3}: quinn_proto::connection: got frame Ack(Ack { largest: 4, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[2..=4]" })
2024-10-16T14:39:26.088466Z TRACE client:recv{space=Data pn=3}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1[389](https://github.com/tokio-rs/tokio/actions/runs/11367899879/job/31621769987?pr=6899#step:8:390)
2024-10-16T14:39:26.088522Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.088573Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.088619Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.089062Z TRACE client:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([3..5]), Delay = 0us
2024-10-16T14:39:26.089103Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.089131Z TRACE client:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1392
2024-10-16T14:39:26.089170Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420
2024-10-16T14:39:26.089179Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams
2024-10-16T14:39:26.089220Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.089261Z TRACE server:recv{space=Data pn=5}: quinn_proto::connection: got frame Ack(Ack { largest: 4, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[3..=4]" })
2024-10-16T14:39:26.089287Z TRACE server:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389
2024-10-16T14:39:26.089322Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.089359Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.089381Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.089863Z TRACE server:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us
2024-10-16T14:39:26.089903Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.089929Z TRACE server:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1392
2024-10-16T14:39:26.089965Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420
2024-10-16T14:39:26.089975Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams
2024-10-16T14:39:26.090018Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.090059Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[5..=6]" })
2024-10-16T14:39:26.090085Z TRACE client:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420
2024-10-16T14:39:26.090121Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.090158Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.090180Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.090480Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us
2024-10-16T14:39:26.090512Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.090537Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1424
2024-10-16T14:39:26.090572Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452
2024-10-16T14:39:26.090582Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams
2024-10-16T14:39:26.090620Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.090660Z TRACE server:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[5..=6]" })
2024-10-16T14:39:26.090684Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420
2024-10-16T14:39:26.090720Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.090757Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.090779Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.091083Z TRACE server:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us
2024-10-16T14:39:26.091114Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.091139Z TRACE server:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1424
2024-10-16T14:39:26.091180Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452
2024-10-16T14:39:26.091190Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams
2024-10-16T14:39:26.091232Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.091271Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[7..=8]" })
2024-10-16T14:39:26.091296Z TRACE client:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452
2024-10-16T14:39:26.091332Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.091369Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.091[391](https://github.com/tokio-rs/tokio/actions/runs/11367899879/job/31621769987?pr=6899#step:8:392)Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck
2024-10-16T14:39:26.091704Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us
2024-10-16T14:39:26.091737Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams
2024-10-16T14:39:26.091774Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.091814Z TRACE server:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[7..=8]" })
2024-10-16T14:39:26.091839Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452
2024-10-16T14:39:26.091913Z TRACE client: quinn_proto::connection: executing key update
2024-10-16T14:39:26.091981Z TRACE client:send{space=Data pn=10}: quinn_proto::connection: PING
2024-10-16T14:39:26.091996Z TRACE client:send{space=Data pn=10}: quinn_proto::connection::packet_builder: PADDING * 3
2024-10-16T14:39:26.092025Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams
2024-10-16T14:39:26.092063Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44502 using id d105da0e0ee7f035
2024-10-16T14:39:26.092083Z TRACE server: quinn_proto::connection: key update authenticated
2024-10-16T14:39:26.092090Z TRACE server: quinn_proto::connection: executing key update
2024-10-16T14:39:26.092161Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got frame Ping
2024-10-16T14:39:26.092224Z TRACE quinn_proto::tests::util: advancing to 25ms for server
2024-10-16T14:39:26.092244Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay
2024-10-16T14:39:26.092255Z TRACE server: quinn_proto::connection: max ack delay reached
2024-10-16T14:39:26.092310Z TRACE server:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 25000us
2024-10-16T14:39:26.092364Z TRACE server: quinn_proto::connection: sending 35 bytes in 1 datagrams
2024-10-16T14:39:26.092479Z TRACE client: quinn_proto::connection: got Data packet (35 bytes) from [::1]:4500 using id 6643870c980dea9a
2024-10-16T14:39:26.092553Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 10, delay: 3125, ecn: Some(EcnCounts { ect0: 11, ect1: 0, ce: 0 }), ranges: "[9..=10]" })
2024-10-16T14:39:26.092623Z TRACE quinn_proto::tests::util: advancing to 78ms for server
2024-10-16T14:39:26.092642Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard
2024-10-16T14:39:26.092661Z TRACE quinn_proto::tests::util: advancing to 103ms for client
2024-10-16T14:39:26.092671Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard
thread 'tests::single_ack_eliciting_packet_triggers_ack_after_delay' panicked at quinn-proto\src\tests\mod.rs:2475:5:
assertion `left == right` failed
  left: Instant { t: 441.7954904s }
 right: Instant { t: 441.7174904s }
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library\std\src\panicking.rs:665
   1: core::panicking::panic_fmt
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library\core\src\panicking.rs:74
   2: core::panicking::assert_failed_inner
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library\core\src\panicking.rs:[410](https://github.com/tokio-rs/tokio/actions/runs/11367899879/job/31621769987?pr=6899#step:8:411)
   3: core::panicking::assert_failed<std::time::Instant,std::time::Instant>
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c\library\core\src\panicking.rs:365
   4: quinn_proto::tests::single_ack_eliciting_packet_triggers_ack_after_delay
             at .\src\tests\mod.rs:2475
   5: quinn_proto::tests::single_ack_eliciting_packet_triggers_ack_after_delay::closure$0
             at .\src\tests\mod.rs:2438
   6: core::ops::function::FnOnce::call_once<quinn_proto::tests::single_ack_eliciting_packet_triggers_ack_after_delay::closure_env$0,tuple$<> >
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c\library\core\src\ops\function.rs:250
   7: core::ops::function::FnOnce::call_once
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

failures:
    tests::single_ack_eliciting_packet_triggers_ack_after_delay
Ralith commented 1 month ago

Thanks for the report! I concur that this shouldn't have been affected. Most notably, it's a quinn-proto test, and those don't involve tokio at all. You could probably avoid exposure to this issue by only running tests from the quinn crate, if that suits your purposes.

Darksonn commented 1 month ago

Yeah, it may make sense to disable those on our sides. Be aware that this is the first time I see this in Tokio's CI, so either it's a new bug, or it's flaking extremely rarely.