key_update_reordered is flaky

[djc]

This looks... weird?

https://github.com/quinn-rs/quinn/actions/runs/6611503872/job/17955509790

[Ralith]

The assertion in question:

assert_eq!(pair.client_conn_mut(client_ch).lost_packets(), 0);

If it doesn't reproduce consistently then it's probably due to the randomized packet number skipping. I don't think packet loss should be a consequence, so there may be an issue here, but I'll need to investigate closely to be sure.

[Ralith]

Initial notes from the logs: failed case has the server skipping pn 4, which shouldn't matter, as the key update happens on client packet 11. The server fails to decrypt packet 11, then oddly detects a key update on both packets 10 and 12... and then continues communication, even though that's too many updates.

Failed:

2023-10-23T09:45:35.3000745Z 2023-10-23T09:45:34.955758Z  INFO quinn_proto::tests: updated keys
2023-10-23T09:45:35.3002788Z 2023-10-23T09:45:34.955768Z TRACE quinn_proto::connection::streams: wrote 3 bytes stream=client bidirectional stream 0
2023-10-23T09:45:35.3005884Z 2023-10-23T09:45:34.955824Z TRACE send{space=Data pn=11}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false
2023-10-23T09:45:35.3008624Z 2023-10-23T09:45:34.955871Z TRACE quinn_proto::connection: sending 33 bytes in 1 datagrams
2023-10-23T09:45:35.3010741Z 2023-10-23T09:45:34.955933Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id c40ae82aa9b490fc
2023-10-23T09:45:35.3013307Z 2023-10-23T09:45:34.955958Z TRACE server: quinn_proto::connection::packet_crypto: decryption failed with packet number 11
2023-10-23T09:45:35.3015643Z 2023-10-23T09:45:34.955975Z DEBUG server: quinn_proto::connection: failed to authenticate packet
2023-10-23T09:45:35.3017609Z 2023-10-23T09:45:34.955989Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id c40ae82aa9b490fc
2023-10-23T09:45:35.3025235Z 2023-10-23T09:45:34.956007Z TRACE server: quinn_proto::connection: key update authenticated
2023-10-23T09:45:35.3027431Z 2023-10-23T09:45:34.956016Z TRACE server: quinn_proto::connection: executing key update
2023-10-23T09:45:35.3030566Z 2023-10-23T09:45:34.956087Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=1 fin=false
2023-10-23T09:45:35.3033455Z 2023-10-23T09:45:34.956147Z TRACE quinn_proto::tests::util: advancing to 25ms for server
2023-10-23T09:45:35.3035280Z 2023-10-23T09:45:34.956181Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay
2023-10-23T09:45:35.3037118Z 2023-10-23T09:45:34.956195Z TRACE server: quinn_proto::connection: max ack delay reached
2023-10-23T09:45:35.3039243Z 2023-10-23T09:45:34.956225Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 25000us
2023-10-23T09:45:35.3041515Z 2023-10-23T09:45:34.956267Z TRACE server: quinn_proto::connection: sending 35 bytes in 1 datagrams
2023-10-23T09:45:35.3043478Z 2023-10-23T09:45:34.956322Z TRACE client: quinn_proto::connection: got Data packet (35 bytes) from [::1]:4476 using id e11fa3bd3e60e510
2023-10-23T09:45:35.3047021Z 2023-10-23T09:45:34.956375Z TRACE client:recv{space=Data pn=10}: quinn_proto::connection: got frame Ack(Ack { largest: 10, delay: 3125, ecn: Some(EcnCounts { ect0: 11, ect1: 0, ce: 0 }), ranges: "[9..=10]" })
2023-10-23T09:45:35.3049634Z 2023-10-23T09:45:34.956578Z TRACE quinn_proto::tests::util: advancing to 26ms for client
2023-10-23T09:45:35.3051202Z 2023-10-23T09:45:34.956595Z TRACE client: quinn_proto::connection: timeout timer=LossDetection
2023-10-23T09:45:35.3053372Z 2023-10-23T09:45:34.956633Z TRACE client: quinn_proto::connection: PTO fired in_flight=33 count=0 space=Data
2023-10-23T09:45:35.3055579Z 2023-10-23T09:45:34.956689Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: PING
2023-10-23T09:45:35.3058073Z 2023-10-23T09:45:34.956705Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: IMMEDIATE_ACK
2023-10-23T09:45:35.3060576Z 2023-10-23T09:45:34.956720Z TRACE client:send{space=Data pn=12}: quinn_proto::connection::packet_builder: PADDING * 1
2023-10-23T09:45:35.3062528Z 2023-10-23T09:45:34.956758Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams
2023-10-23T09:45:35.3064439Z 2023-10-23T09:45:34.956797Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: PING
2023-10-23T09:45:35.3067202Z 2023-10-23T09:45:34.956811Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: IMMEDIATE_ACK
2023-10-23T09:45:35.3070207Z 2023-10-23T09:45:34.956826Z TRACE client:send{space=Data pn=13}: quinn_proto::connection::packet_builder: PADDING * 1
2023-10-23T09:45:35.3073315Z 2023-10-23T09:45:34.956861Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams
2023-10-23T09:45:35.3076524Z 2023-10-23T09:45:34.956934Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id c40ae82aa9b490fc
2023-10-23T09:45:35.3078853Z 2023-10-23T09:45:34.956959Z TRACE server: quinn_proto::connection: key update authenticated
2023-10-23T09:45:35.3081332Z 2023-10-23T09:45:34.956968Z TRACE server: quinn_proto::connection: executing key update
2023-10-23T09:45:35.3083863Z 2023-10-23T09:45:34.957039Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame Ping
2023-10-23T09:45:35.3086605Z 2023-10-23T09:45:34.957075Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame ImmediateAck
2023-10-23T09:45:35.3089389Z 2023-10-23T09:45:34.957110Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id c40ae82aa9b490fc
2023-10-23T09:45:35.3091638Z 2023-10-23T09:45:34.957157Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame Ping
2023-10-23T09:45:35.3094082Z 2023-10-23T09:45:34.957190Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame ImmediateAck
2023-10-23T09:45:35.3096677Z 2023-10-23T09:45:34.957244Z TRACE server:send{space=Data pn=11}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..14]), Delay = 0us
2023-10-23T09:45:35.3099121Z 2023-10-23T09:45:34.957287Z TRACE server: quinn_proto::connection: sending 36 bytes in 1 datagrams
2023-10-23T09:45:35.3101439Z 2023-10-23T09:45:34.957387Z TRACE client: quinn_proto::connection: got Data packet (36 bytes) from [::1]:4476 using id e11fa3bd3e60e510
2023-10-23T09:45:35.3104579Z 2023-10-23T09:45:34.957444Z TRACE client:recv{space=Data pn=11}: quinn_proto::connection: got frame Ack(Ack { largest: 13, delay: 0, ecn: Some(EcnCounts { ect0: 13, ect1: 0, ce: 0 }), ranges: "[12..=13,9..=10]" })
2023-10-23T09:45:35.3108301Z 2023-10-23T09:45:34.957483Z TRACE client:recv{space=Data pn=11}:frame{ty=ACK}: quinn_proto::connection: packets lost: [11], bytes lost: 33
2023-10-23T09:45:35.3113232Z 2023-10-23T09:45:34.957571Z TRACE client:send{space=Data pn=14}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false
2023-10-23T09:45:35.3116228Z 2023-10-23T09:45:34.957657Z TRACE client: quinn_proto::connection: sending 33 bytes in 1 datagrams
2023-10-23T09:45:35.3119129Z 2023-10-23T09:45:34.957715Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id c40ae82aa9b490fc
2023-10-23T09:45:35.3123826Z 2023-10-23T09:45:34.957772Z TRACE server:recv{space=Data pn=14}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=1 len=3 fin=false
2023-10-23T09:45:35.3127122Z 2023-10-23T09:45:34.957857Z TRACE quinn_proto::tests::util: advancing to 51ms for server
2023-10-23T09:45:35.3128803Z 2023-10-23T09:45:34.957970Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay
2023-10-23T09:45:35.3130920Z 2023-10-23T09:45:34.957989Z TRACE server: quinn_proto::connection: max ack delay reached
2023-10-23T09:45:35.3133211Z 2023-10-23T09:45:34.958024Z TRACE server:send{space=Data pn=12}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..15]), Delay = 25000us
2023-10-23T09:45:35.3135633Z 2023-10-23T09:45:34.958072Z TRACE server: quinn_proto::connection: sending 37 bytes in 1 datagrams
2023-10-23T09:45:35.3137959Z 2023-10-23T09:45:34.958133Z TRACE client: quinn_proto::connection: got Data packet (37 bytes) from [::1]:4476 using id e11fa3bd3e60e510
2023-10-23T09:45:35.3141250Z 2023-10-23T09:45:34.958192Z TRACE client:recv{space=Data pn=12}: quinn_proto::connection: got frame Ack(Ack { largest: 14, delay: 3125, ecn: Some(EcnCounts { ect0: 14, ect1: 0, ce: 0 }), ranges: "[12..=14,9..=10]" })
2023-10-23T09:45:35.3144039Z 2023-10-23T09:45:34.958310Z TRACE quinn_proto::tests::util: advancing to 104ms for client
2023-10-23T09:45:35.3146086Z 2023-10-23T09:45:34.958327Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard
2023-10-23T09:45:35.3148240Z 2023-10-23T09:45:34.958360Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard

Succeeded:

2023-10-23T16:49:34.207550Z  INFO quinn_proto::tests: updated keys
2023-10-23T16:49:34.207575Z TRACE quinn_proto::connection::streams: wrote 3 bytes stream=client bidirectional stream 0
2023-10-23T16:49:34.207612Z TRACE send{space=Data pn=11}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false
2023-10-23T16:49:34.207647Z TRACE quinn_proto::connection: sending 33 bytes in 1 datagrams
2023-10-23T16:49:34.207692Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44433 using id 5c31a1c145faa434
2023-10-23T16:49:34.207714Z TRACE server: quinn_proto::connection: key update authenticated
2023-10-23T16:49:34.207723Z TRACE server: quinn_proto::connection: executing key update
2023-10-23T16:49:34.207775Z TRACE server:recv{space=Data pn=11}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=1 len=3 fin=false
2023-10-23T16:49:34.207812Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44433 using id 5c31a1c145faa434
2023-10-23T16:49:34.207850Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=1 fin=false
2023-10-23T16:49:34.207898Z TRACE server:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([9..12]), Delay = 0us
2023-10-23T16:49:34.207930Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams
2023-10-23T16:49:34.207971Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id 55f87d9f909a3ae2
2023-10-23T16:49:34.208010Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 11, delay: 0, ecn: Some(EcnCounts { ect0: 12, ect1: 0, ce: 0 }), ranges: "[9..=11]" })
2023-10-23T16:49:34.208082Z TRACE quinn_proto::tests::util: advancing to 78ms for client
2023-10-23T16:49:34.208097Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard
2023-10-23T16:49:34.208125Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard

[Ralith]

Saw this again on stable in FreeBSD at https://github.com/quinn-rs/quinn/actions/runs/7535071853/job/20510448889. This time there doesn't seem to have been any PN skipping at all, so I guess that was a red herring.

Complete logs

``` 2024-01-15T23:48:37.213313Z INFO quinn_proto::tests::util: connecting 2024-01-15T23:48:37.213362Z TRACE client: quinn_proto::endpoint: initial_dcid=4484607ac95a1c4281fac7e77ce792e71a448fde 2024-01-15T23:48:37.214141Z TRACE client: quinn_proto::connection: wrote 273 Initial CRYPTO bytes 2024-01-15T23:48:37.214220Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 273 2024-01-15T23:48:37.214239Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 868 2024-01-15T23:48:37.214279Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:48:37.214719Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 273 CRYPTO bytes 2024-01-15T23:48:37.216255Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready 2024-01-15T23:48:37.216278Z TRACE server:first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes 2024-01-15T23:48:37.216364Z TRACE server:first recv: quinn_proto::connection: Data keys ready 2024-01-15T23:48:37.216434Z TRACE server:first recv: quinn_proto::connection: wrote 632 Handshake CRYPTO bytes 2024-01-15T23:48:37.216503Z TRACE server: quinn_proto::endpoint: connection incoming id=0 icid=4484607ac95a1c4281fac7e77ce792e71a448fde 2024-01-15T23:48:37.216564Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:48:37.216586Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 2024-01-15T23:48:37.216660Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 632 2024-01-15T23:48:37.216681Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 377 2024-01-15T23:48:37.216716Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:48:37.216804Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=2ffde98915a93a06 2024-01-15T23:48:37.216825Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=bf69301201aea1f9 2024-01-15T23:48:37.216840Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=47842f64c85fd7f1 2024-01-15T23:48:37.216856Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=3c3a7d0d5e7590e8 2024-01-15T23:48:37.216896Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-01-15T23:48:37.216961Z TRACE client: quinn_proto::connection: got Initial packet (145 bytes) from [::1]:4476 using id 687ffca30c4fec7f 2024-01-15T23:48:37.217010Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to fff640abb5837652 2024-01-15T23:48:37.217082Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes 2024-01-15T23:48:37.217751Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready 2024-01-15T23:48:37.217792Z TRACE client: quinn_proto::connection: got Handshake packet (1055 bytes) from [::1]:4476 using id 687ffca30c4fec7f 2024-01-15T23:48:37.217910Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 632 CRYPTO bytes 2024-01-15T23:48:37.218555Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready 2024-01-15T23:48:37.218625Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes 2024-01-15T23:48:37.218681Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-01-15T23:48:37.218708Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4476 using id 687ffca30c4fec7f 2024-01-15T23:48:37.218753Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [47, 253, 233, 137, 21, 169, 58, 6], reset_token: ResetToken([47, 179, 62, 36, 183, 222, 202, 179, 29, 10, 8, 63, 12, 234, 139, 170]) }) 2024-01-15T23:48:37.218772Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=2ffde98915a93a06 retire_prior_to=0 2024-01-15T23:48:37.218807Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [191, 105, 48, 18, 1, 174, 161, 249], reset_token: ResetToken([141, 21, 224, 254, 243, 38, 114, 51, 119, 167, 64, 168, 104, 28, 111, 134]) }) 2024-01-15T23:48:37.218824Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=bf69301201aea1f9 retire_prior_to=0 2024-01-15T23:48:37.218855Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [71, 132, 47, 100, 200, 95, 215, 241], reset_token: ResetToken([29, 233, 5, 221, 60, 99, 197, 44, 228, 120, 220, 45, 161, 33, 91, 174]) }) 2024-01-15T23:48:37.218872Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=47842f64c85fd7f1 retire_prior_to=0 2024-01-15T23:48:37.218914Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [60, 58, 125, 13, 94, 117, 144, 232], reset_token: ResetToken([179, 34, 216, 110, 6, 189, 44, 67, 13, 154, 101, 0, 177, 221, 214, 110]) }) 2024-01-15T23:48:37.218936Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=3c3a7d0d5e7590e8 retire_prior_to=0 2024-01-15T23:48:37.219004Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:48:37.219042Z TRACE client: quinn_proto::connection: discarding Initial keys 2024-01-15T23:48:37.219078Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:48:37.219096Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52 2024-01-15T23:48:37.219116Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 1044 2024-01-15T23:48:37.219160Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:48:37.219198Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 1297 2024-01-15T23:48:37.219240Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-01-15T23:48:37.219257Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-01-15T23:48:37.219343Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=bb6273c14fa6f169 2024-01-15T23:48:37.219367Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=436a6a5113b446f4 2024-01-15T23:48:37.219387Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=090d381ee51f8427 2024-01-15T23:48:37.219407Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=707a1dfe6f77fd2e 2024-01-15T23:48:37.219452Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-01-15T23:48:37.219516Z TRACE server: quinn_proto::connection: got Initial packet (51 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.219605Z TRACE server: quinn_proto::connection: got Handshake packet (1149 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.219644Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys 2024-01-15T23:48:37.219702Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes 2024-01-15T23:48:37.220174Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes 2024-01-15T23:48:37.220195Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys 2024-01-15T23:48:37.220214Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-01-15T23:48:37.220245Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.220301Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.220338Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.220667Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.220715Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [187, 98, 115, 193, 79, 166, 241, 105], reset_token: ResetToken([231, 110, 31, 11, 56, 109, 133, 230, 28, 101, 161, 98, 179, 144, 89, 34]) }) 2024-01-15T23:48:37.220738Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=bb6273c14fa6f169 retire_prior_to=0 2024-01-15T23:48:37.220787Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [67, 106, 106, 81, 19, 180, 70, 244], reset_token: ResetToken([100, 56, 37, 119, 42, 214, 45, 174, 101, 87, 20, 63, 20, 40, 34, 136]) }) 2024-01-15T23:48:37.220809Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=436a6a5113b446f4 retire_prior_to=0 2024-01-15T23:48:37.220854Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [9, 13, 56, 30, 229, 31, 132, 39], reset_token: ResetToken([129, 228, 213, 68, 216, 109, 55, 243, 40, 250, 54, 105, 186, 65, 237, 24]) }) 2024-01-15T23:48:37.220881Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=090d381ee51f8427 retire_prior_to=0 2024-01-15T23:48:37.220930Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [112, 122, 29, 254, 111, 119, 253, 46], reset_token: ResetToken([109, 170, 190, 249, 186, 217, 48, 125, 76, 2, 198, 56, 54, 66, 22, 69]) }) 2024-01-15T23:48:37.220951Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=707a1dfe6f77fd2e retire_prior_to=0 2024-01-15T23:48:37.221031Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us 2024-01-15T23:48:37.221050Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356 2024-01-15T23:48:37.221069Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 2024-01-15T23:48:37.221116Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams 2024-01-15T23:48:37.221154Z TRACE server:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1297 2024-01-15T23:48:37.221194Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-01-15T23:48:37.221207Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-01-15T23:48:37.221267Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.221315Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone 2024-01-15T23:48:37.221329Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys 2024-01-15T23:48:37.221367Z 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-01-15T23:48:37.221392Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-01-15T23:48:37.221433Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356 2024-01-15T23:48:37.221452Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes 2024-01-15T23:48:37.221663Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 } 2024-01-15T23:48:37.221708Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.221764Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.221811Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.222169Z TRACE client:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us 2024-01-15T23:48:37.222209Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.222237Z TRACE client:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1360 2024-01-15T23:48:37.222269Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-01-15T23:48:37.222280Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-01-15T23:48:37.222295Z TRACE client: quinn_proto::endpoint: peer retired CID 0: 687ffca30c4fec7f 2024-01-15T23:48:37.222351Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=db9ec3def5eabab6 2024-01-15T23:48:37.222405Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams 2024-01-15T23:48:37.222466Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.222520Z 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-01-15T23:48:37.222559Z TRACE server:recv{space=Data pn=2}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-01-15T23:48:37.222615Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.222668Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.222703Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.223055Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.223100Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [219, 158, 195, 222, 245, 234, 186, 182], reset_token: ResetToken([39, 23, 152, 251, 255, 69, 47, 115, 162, 187, 54, 114, 96, 184, 161, 194]) }) 2024-01-15T23:48:37.223119Z TRACE server:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=db9ec3def5eabab6 retire_prior_to=0 2024-01-15T23:48:37.223175Z TRACE server:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([2..5]), Delay = 0us 2024-01-15T23:48:37.223210Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.223242Z TRACE server:send{space=Data pn=4}: quinn_proto::connection::packet_builder: PADDING * 1360 2024-01-15T23:48:37.223283Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-01-15T23:48:37.223297Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-01-15T23:48:37.223353Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.223409Z 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-01-15T23:48:37.223439Z TRACE client:recv{space=Data pn=3}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-01-15T23:48:37.223489Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.223543Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.223577Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.223937Z TRACE client:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([3..5]), Delay = 0us 2024-01-15T23:48:37.223982Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.224019Z TRACE client:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1391 2024-01-15T23:48:37.224064Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-01-15T23:48:37.224080Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-01-15T23:48:37.224135Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.224195Z 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-01-15T23:48:37.224229Z TRACE server:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-01-15T23:48:37.224283Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.224338Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.224375Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.224763Z TRACE server:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us 2024-01-15T23:48:37.224809Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.224845Z TRACE server:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1391 2024-01-15T23:48:37.224890Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-01-15T23:48:37.224905Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-01-15T23:48:37.224966Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.225028Z 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-01-15T23:48:37.225059Z TRACE client:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-01-15T23:48:37.225112Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.225171Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.225215Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.225637Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us 2024-01-15T23:48:37.225744Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.225784Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1423 2024-01-15T23:48:37.225826Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-01-15T23:48:37.225843Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-01-15T23:48:37.225895Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.225953Z 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-01-15T23:48:37.225985Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-01-15T23:48:37.226093Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.226152Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.226190Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.226584Z TRACE server:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us 2024-01-15T23:48:37.226630Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.226666Z TRACE server:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1423 2024-01-15T23:48:37.226718Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-01-15T23:48:37.226735Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-01-15T23:48:37.226788Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.226846Z 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-01-15T23:48:37.226879Z TRACE client:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-01-15T23:48:37.226935Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.226985Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.227021Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.227413Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us 2024-01-15T23:48:37.227460Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:48:37.227509Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.227566Z 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-01-15T23:48:37.227598Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-01-15T23:48:37.227669Z TRACE quinn_proto::connection::streams: wrote 1 bytes stream=client bidirectional stream 0 2024-01-15T23:48:37.227695Z TRACE quinn_proto::connection: executing key update 2024-01-15T23:48:37.227780Z TRACE send{space=Data pn=10}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=0 len=1 fin=false 2024-01-15T23:48:37.227833Z TRACE quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:48:37.227850Z TRACE quinn_proto::connection: executing key update 2024-01-15T23:48:37.227917Z INFO quinn_proto::tests: updated keys 2024-01-15T23:48:37.227931Z TRACE quinn_proto::connection::streams: wrote 3 bytes stream=client bidirectional stream 0 2024-01-15T23:48:37.227970Z TRACE send{space=Data pn=11}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-01-15T23:48:37.228021Z TRACE quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-01-15T23:48:37.228078Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.228102Z TRACE server: quinn_proto::connection::packet_crypto: decryption failed with packet number 11 2024-01-15T23:48:37.228121Z DEBUG server: quinn_proto::connection: failed to authenticate packet 2024-01-15T23:48:37.228137Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.228159Z TRACE server: quinn_proto::connection: key update authenticated 2024-01-15T23:48:37.228172Z TRACE server: quinn_proto::connection: executing key update 2024-01-15T23:48:37.228269Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=1 fin=false 2024-01-15T23:48:37.228328Z TRACE quinn_proto::tests::util: advancing to 25ms for server 2024-01-15T23:48:37.228361Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-01-15T23:48:37.228377Z TRACE server: quinn_proto::connection: max ack delay reached 2024-01-15T23:48:37.228406Z TRACE server:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 25000us 2024-01-15T23:48:37.228453Z TRACE server: quinn_proto::connection: sending 35 bytes in 1 datagrams 2024-01-15T23:48:37.228511Z TRACE client: quinn_proto::connection: got Data packet (35 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.228565Z 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-01-15T23:48:37.228658Z TRACE quinn_proto::tests::util: advancing to 26ms for client 2024-01-15T23:48:37.228676Z TRACE client: quinn_proto::connection: timeout timer=LossDetection 2024-01-15T23:48:37.228693Z TRACE client: quinn_proto::connection: PTO fired in_flight=33 count=0 space=Data 2024-01-15T23:48:37.228736Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: PING 2024-01-15T23:48:37.228751Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: IMMEDIATE_ACK 2024-01-15T23:48:37.228771Z TRACE client:send{space=Data pn=12}: quinn_proto::connection::packet_builder: PADDING * 1 2024-01-15T23:48:37.228814Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:48:37.228861Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: PING 2024-01-15T23:48:37.228880Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: IMMEDIATE_ACK 2024-01-15T23:48:37.228898Z TRACE client:send{space=Data pn=13}: quinn_proto::connection::packet_builder: PADDING * 1 2024-01-15T23:48:37.228939Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:48:37.228994Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.229021Z TRACE server: quinn_proto::connection: key update authenticated 2024-01-15T23:48:37.229035Z TRACE server: quinn_proto::connection: executing key update 2024-01-15T23:48:37.229126Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.229162Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.229206Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.229261Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame Ping 2024-01-15T23:48:37.229297Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:48:37.229388Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..14]), Delay = 0us 2024-01-15T23:48:37.229437Z TRACE server: quinn_proto::connection: sending 36 bytes in 1 datagrams 2024-01-15T23:48:37.229493Z TRACE client: quinn_proto::connection: got Data packet (36 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.229555Z TRACE client:recv{space=Data pn=10}: quinn_proto::connection: got frame Ack(Ack { largest: 13, delay: 0, ecn: Some(EcnCounts { ect0: 13, ect1: 0, ce: 0 }), ranges: "[12..=13,9..=10]" }) 2024-01-15T23:48:37.229629Z TRACE client:recv{space=Data pn=10}:frame{ty=ACK}: quinn_proto::connection: packets lost: [11], bytes lost: 33 2024-01-15T23:48:37.229714Z TRACE client:send{space=Data pn=14}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-01-15T23:48:37.229766Z TRACE client: quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-01-15T23:48:37.229817Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id fff640abb5837652 2024-01-15T23:48:37.229870Z TRACE server:recv{space=Data pn=14}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=1 len=3 fin=false 2024-01-15T23:48:37.229933Z TRACE quinn_proto::tests::util: advancing to 51ms for server 2024-01-15T23:48:37.229972Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-01-15T23:48:37.229986Z TRACE server: quinn_proto::connection: max ack delay reached 2024-01-15T23:48:37.230018Z TRACE server:send{space=Data pn=11}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..15]), Delay = 25000us 2024-01-15T23:48:37.230063Z TRACE server: quinn_proto::connection: sending 37 bytes in 1 datagrams 2024-01-15T23:48:37.230115Z TRACE client: quinn_proto::connection: got Data packet (37 bytes) from [::1]:4476 using id bb6273c14fa6f169 2024-01-15T23:48:37.230174Z TRACE client:recv{space=Data pn=11}: quinn_proto::connection: got frame Ack(Ack { largest: 14, delay: 3125, ecn: Some(EcnCounts { ect0: 14, ect1: 0, ce: 0 }), ranges: "[12..=14,9..=10]" }) 2024-01-15T23:48:37.230275Z TRACE quinn_proto::tests::util: advancing to 104ms for client 2024-01-15T23:48:37.230293Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard 2024-01-15T23:48:37.230331Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard thread 'tests::key_update_reordered' panicked at quinn-proto/src/tests/mod.rs:856:5: assertion `left == right` failed left: 1 right: 0 ```

[Ralith]

Another failure on Ubuntu beta: https://github.com/quinn-rs/quinn/actions/runs/7535119285/job/20510576738?pr=1740

Logs

``` 2024-01-15T23:54:23.893633Z INFO quinn_proto::tests::util: connecting 2024-01-15T23:54:23.893695Z TRACE client: quinn_proto::endpoint: initial_dcid=d4e84704fc6ce6b84bddd195430f106dbffdef15 2024-01-15T23:54:23.894521Z TRACE client: quinn_proto::connection: wrote 273 Initial CRYPTO bytes 2024-01-15T23:54:23.894606Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 273 2024-01-15T23:54:23.894629Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 868 2024-01-15T23:54:23.894673Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:54:23.895173Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 273 CRYPTO bytes 2024-01-15T23:54:23.896604Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready 2024-01-15T23:54:23.896619Z TRACE server:first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes 2024-01-15T23:54:23.896696Z TRACE server:first recv: quinn_proto::connection: Data keys ready 2024-01-15T23:54:23.896753Z TRACE server:first recv: quinn_proto::connection: wrote 633 Handshake CRYPTO bytes 2024-01-15T23:54:23.896812Z TRACE server: quinn_proto::endpoint: connection incoming id=0 icid=d4e84704fc6ce6b84bddd195430f106dbffdef15 2024-01-15T23:54:23.896858Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:54:23.896875Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 2024-01-15T23:54:23.896933Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 633 2024-01-15T23:54:23.896951Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 376 2024-01-15T23:54:23.896990Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:54:23.897076Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=7ed698e23c8dc8eb 2024-01-15T23:54:23.897099Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=d23627bc5943b68f 2024-01-15T23:54:23.897119Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=d42b8f6dce168a2a 2024-01-15T23:54:23.897136Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=7e0e96411d97cdba 2024-01-15T23:54:23.897180Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-01-15T23:54:23.897247Z TRACE client: quinn_proto::connection: got Initial packet (145 bytes) from [::1]:4476 using id ce4b32bacb92c283 2024-01-15T23:54:23.897292Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to 162cee60587fa758 2024-01-15T23:54:23.897371Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes 2024-01-15T23:54:23.897972Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready 2024-01-15T23:54:23.898010Z TRACE client: quinn_proto::connection: got Handshake packet (1055 bytes) from [::1]:4476 using id ce4b32bacb92c283 2024-01-15T23:54:23.898065Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 633 CRYPTO bytes 2024-01-15T23:54:23.898677Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready error: test failed, to rerun pass `-p quinn-proto --lib` 2024-01-15T23:54:23.898746Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes 2024-01-15T23:54:23.898805Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-01-15T23:54:23.898840Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4476 using id ce4b32bacb92c283 2024-01-15T23:54:23.898897Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [126, 214, 152, 226, 60, 141, 200, 235], reset_token: ResetToken([58, 3, 216, 90, 117, 219, 83, 37, 36, 39, 168, 115, 192, 217, 7, 106]) }) 2024-01-15T23:54:23.898919Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=7ed698e23c8dc8eb retire_prior_to=0 2024-01-15T23:54:23.898963Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [210, 54, 39, 188, 89, 67, 182, 143], reset_token: ResetToken([159, 129, 238, 98, 60, 30, 46, 176, 130, 38, 240, 220, 58, 6, 64, 161]) }) 2024-01-15T23:54:23.898984Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=d23627bc5943b68f retire_prior_to=0 2024-01-15T23:54:23.899021Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [212, 43, 143, 109, 206, 22, 138, 42], reset_token: ResetToken([4, 203, 103, 31, 201, 188, 21, 184, 51, 37, 250, 44, 55, 195, 144, 213]) }) 2024-01-15T23:54:23.899038Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=d42b8f6dce168a2a retire_prior_to=0 2024-01-15T23:54:23.899071Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [126, 14, 150, 65, 29, 151, 205, 186], reset_token: ResetToken([139, 41, 25, 223, 229, 171, 205, 154, 199, 172, 199, 242, 150, 10, 92, 66]) }) 2024-01-15T23:54:23.899088Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=7e0e96411d97cdba retire_prior_to=0 2024-01-15T23:54:23.899140Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:54:23.899179Z TRACE client: quinn_proto::connection: discarding Initial keys 2024-01-15T23:54:23.899209Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-01-15T23:54:23.899224Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52 2024-01-15T23:54:23.899240Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 1044 2024-01-15T23:54:23.899274Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-01-15T23:54:23.899307Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 1297 2024-01-15T23:54:23.899350Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-01-15T23:54:23.899366Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-01-15T23:54:23.899455Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=e00e478408e635f4 2024-01-15T23:54:23.899478Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=58fdb9530a2eea04 2024-01-15T23:54:23.899498Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=61ec6729e2264366 2024-01-15T23:54:23.899517Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=2dd736d67f77949d 2024-01-15T23:54:23.899561Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-01-15T23:54:23.899630Z TRACE server: quinn_proto::connection: got Initial packet (51 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.899734Z TRACE server: quinn_proto::connection: got Handshake packet (1149 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.899782Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys 2024-01-15T23:54:23.899856Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes 2024-01-15T23:54:23.900307Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes 2024-01-15T23:54:23.900328Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys 2024-01-15T23:54:23.900344Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-01-15T23:54:23.900374Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.900432Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.900473Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.900796Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.900843Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [224, 14, 71, 132, 8, 230, 53, 244], reset_token: ResetToken([170, 38, 110, 197, 65, 94, 81, 148, 76, 208, 49, 182, 232, 66, 8, 192]) }) 2024-01-15T23:54:23.900861Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=e00e478408e635f4 retire_prior_to=0 2024-01-15T23:54:23.900899Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [88, 253, 185, 83, 10, 46, 234, 4], reset_token: ResetToken([168, 239, 143, 169, 77, 252, 75, 138, 91, 109, 192, 206, 107, 79, 130, 88]) }) 2024-01-15T23:54:23.900915Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=58fdb9530a2eea04 retire_prior_to=0 2024-01-15T23:54:23.900947Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [97, 236, 103, 41, 226, 38, 67, 102], reset_token: ResetToken([214, 69, 195, 95, 188, 147, 198, 82, 225, 240, 242, 73, 178, 156, 147, 112]) }) 2024-01-15T23:54:23.900967Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=61ec6729e2264366 retire_prior_to=0 2024-01-15T23:54:23.901012Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [45, 215, 54, 214, 127, 119, 148, 157], reset_token: ResetToken([156, 117, 86, 229, 17, 140, 252, 20, 57, 229, 115, 88, 225, 221, 241, 237]) }) 2024-01-15T23:54:23.901035Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=2dd736d67f77949d retire_prior_to=0 2024-01-15T23:54:23.901101Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us 2024-01-15T23:54:23.901122Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356 2024-01-15T23:54:23.901139Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 2024-01-15T23:54:23.901189Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams 2024-01-15T23:54:23.901228Z TRACE server:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1297 2024-01-15T23:54:23.901272Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-01-15T23:54:23.901286Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-01-15T23:54:23.901360Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.901412Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone 2024-01-15T23:54:23.901430Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys 2024-01-15T23:54:23.901471Z 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-01-15T23:54:23.901497Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-01-15T23:54:23.901538Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356 2024-01-15T23:54:23.901557Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes 2024-01-15T23:54:23.901701Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 } 2024-01-15T23:54:23.901739Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.901793Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.901833Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.902180Z TRACE client:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us 2024-01-15T23:54:23.902222Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.902251Z TRACE client:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1360 2024-01-15T23:54:23.902283Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-01-15T23:54:23.902294Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-01-15T23:54:23.902309Z TRACE client: quinn_proto::endpoint: peer retired CID 0: ce4b32bacb92c283 2024-01-15T23:54:23.902364Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=437c8ff00a053df9 2024-01-15T23:54:23.902410Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams 2024-01-15T23:54:23.902459Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.902509Z 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-01-15T23:54:23.902547Z TRACE server:recv{space=Data pn=2}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-01-15T23:54:23.902596Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.902652Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.902689Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.903029Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.903077Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [67, 124, 143, 240, 10, 5, 61, 249], reset_token: ResetToken([186, 105, 48, 186, 136, 59, 144, 205, 167, 178, 136, 1, 114, 82, 201, 189]) }) 2024-01-15T23:54:23.903096Z TRACE server:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=437c8ff00a053df9 retire_prior_to=0 2024-01-15T23:54:23.903135Z TRACE server: quinn_proto::connection::spaces: skipping pn 3 2024-01-15T23:54:23.903159Z TRACE server:send{space=Data pn=4}: quinn_proto::connection: ACK ArrayRangeSet([2..5]), Delay = 0us 2024-01-15T23:54:23.903194Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.903223Z TRACE server:send{space=Data pn=5}: quinn_proto::connection::packet_builder: PADDING * 1360 2024-01-15T23:54:23.903255Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-01-15T23:54:23.903267Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-01-15T23:54:23.903324Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.903386Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame Ack(Ack { largest: 4, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[2..=4]" }) 2024-01-15T23:54:23.903420Z TRACE client:recv{space=Data pn=4}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-01-15T23:54:23.903477Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.903533Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.903571Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.903932Z TRACE client:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([4..6]), Delay = 0us 2024-01-15T23:54:23.903974Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.904013Z TRACE client:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1391 2024-01-15T23:54:23.904059Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-01-15T23:54:23.904075Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-01-15T23:54:23.904154Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.904221Z TRACE server:recv{space=Data pn=5}: quinn_proto::connection: got frame Ack(Ack { largest: 5, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[4..=5]" }) 2024-01-15T23:54:23.904254Z TRACE server:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-01-15T23:54:23.904305Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.904358Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.904399Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.904765Z TRACE server:send{space=Data pn=6}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us 2024-01-15T23:54:23.904820Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.904857Z TRACE server:send{space=Data pn=7}: quinn_proto::connection::packet_builder: PADDING * 1391 2024-01-15T23:54:23.904904Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-01-15T23:54:23.904920Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-01-15T23:54:23.904982Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.905044Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[5..=6]" }) 2024-01-15T23:54:23.905076Z TRACE client:recv{space=Data pn=6}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-01-15T23:54:23.905133Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.905186Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.905224Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.905593Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([6..8]), Delay = 0us 2024-01-15T23:54:23.905639Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.905678Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1423 2024-01-15T23:54:23.905720Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-01-15T23:54:23.905735Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-01-15T23:54:23.905790Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.905849Z TRACE server:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 7, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[6..=7]" }) 2024-01-15T23:54:23.905884Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-01-15T23:54:23.905939Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.905994Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.906035Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.906414Z TRACE server:send{space=Data pn=8}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us 2024-01-15T23:54:23.906463Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.906501Z TRACE server:send{space=Data pn=9}: quinn_proto::connection::packet_builder: PADDING * 1423 2024-01-15T23:54:23.906542Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-01-15T23:54:23.906559Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-01-15T23:54:23.906621Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.906680Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[7..=8]" }) 2024-01-15T23:54:23.906710Z TRACE client:recv{space=Data pn=8}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-01-15T23:54:23.906766Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.906825Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.906862Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.907238Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([8..10]), Delay = 0us 2024-01-15T23:54:23.907282Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-01-15T23:54:23.907337Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.907398Z TRACE server:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 9, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[8..=9]" }) 2024-01-15T23:54:23.907433Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-01-15T23:54:23.907511Z TRACE quinn_proto::connection::streams: wrote 1 bytes stream=client bidirectional stream 0 2024-01-15T23:54:23.907533Z TRACE quinn_proto::connection: executing key update 2024-01-15T23:54:23.907617Z TRACE send{space=Data pn=10}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=0 len=1 fin=false 2024-01-15T23:54:23.907670Z TRACE quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:54:23.907686Z TRACE quinn_proto::connection: executing key update 2024-01-15T23:54:23.907748Z INFO quinn_proto::tests: updated keys 2024-01-15T23:54:23.907762Z TRACE quinn_proto::connection::streams: wrote 3 bytes stream=client bidirectional stream 0 2024-01-15T23:54:23.907802Z TRACE send{space=Data pn=11}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-01-15T23:54:23.907853Z TRACE quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-01-15T23:54:23.907914Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.907943Z TRACE server: quinn_proto::connection::packet_crypto: decryption failed with packet number 11 2024-01-15T23:54:23.907963Z DEBUG server: quinn_proto::connection: failed to authenticate packet 2024-01-15T23:54:23.907980Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.908003Z TRACE server: quinn_proto::connection: key update authenticated 2024-01-15T23:54:23.908013Z TRACE server: quinn_proto::connection: executing key update 2024-01-15T23:54:23.908135Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=1 fin=false 2024-01-15T23:54:23.908201Z TRACE quinn_proto::tests::util: advancing to 25ms for server 2024-01-15T23:54:23.908237Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-01-15T23:54:23.908253Z TRACE server: quinn_proto::connection: max ack delay reached 2024-01-15T23:54:23.908282Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 25000us 2024-01-15T23:54:23.908326Z TRACE server: quinn_proto::connection: sending 35 bytes in 1 datagrams 2024-01-15T23:54:23.908383Z TRACE client: quinn_proto::connection: got Data packet (35 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.908436Z TRACE client:recv{space=Data pn=10}: quinn_proto::connection: got frame Ack(Ack { largest: 10, delay: 3125, ecn: Some(EcnCounts { ect0: 11, ect1: 0, ce: 0 }), ranges: "[9..=10]" }) 2024-01-15T23:54:23.908519Z TRACE quinn_proto::tests::util: advancing to 26ms for client 2024-01-15T23:54:23.908535Z TRACE client: quinn_proto::connection: timeout timer=LossDetection 2024-01-15T23:54:23.908550Z TRACE client: quinn_proto::connection: PTO fired in_flight=33 count=0 space=Data 2024-01-15T23:54:23.908585Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: PING 2024-01-15T23:54:23.908599Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: IMMEDIATE_ACK 2024-01-15T23:54:23.908616Z TRACE client:send{space=Data pn=12}: quinn_proto::connection::packet_builder: PADDING * 1 2024-01-15T23:54:23.908655Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:54:23.908699Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: PING 2024-01-15T23:54:23.908715Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: IMMEDIATE_ACK 2024-01-15T23:54:23.908734Z TRACE client:send{space=Data pn=13}: quinn_proto::connection::packet_builder: PADDING * 1 2024-01-15T23:54:23.908772Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-01-15T23:54:23.908826Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.908855Z TRACE server: quinn_proto::connection: key update authenticated 2024-01-15T23:54:23.908867Z TRACE server: quinn_proto::connection: executing key update 2024-01-15T23:54:23.908961Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.909000Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.909046Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.909094Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame Ping 2024-01-15T23:54:23.909130Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame ImmediateAck 2024-01-15T23:54:23.909186Z TRACE server:send{space=Data pn=11}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..14]), Delay = 0us 2024-01-15T23:54:23.909233Z TRACE server: quinn_proto::connection: sending 36 bytes in 1 datagrams 2024-01-15T23:54:23.909289Z TRACE client: quinn_proto::connection: got Data packet (36 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.909350Z TRACE client:recv{space=Data pn=11}: quinn_proto::connection: got frame Ack(Ack { largest: 13, delay: 0, ecn: Some(EcnCounts { ect0: 13, ect1: 0, ce: 0 }), ranges: "[12..=13,9..=10]" }) 2024-01-15T23:54:23.909391Z TRACE client:recv{space=Data pn=11}:frame{ty=ACK}: quinn_proto::connection: packets lost: [11], bytes lost: 33 2024-01-15T23:54:23.909465Z TRACE client:send{space=Data pn=14}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-01-15T23:54:23.909505Z TRACE client: quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-01-15T23:54:23.909559Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44476 using id 162cee60587fa758 2024-01-15T23:54:23.909616Z TRACE server:recv{space=Data pn=14}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=1 len=3 fin=false 2024-01-15T23:54:23.909669Z TRACE quinn_proto::tests::util: advancing to 51ms for server 2024-01-15T23:54:23.909704Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-01-15T23:54:23.909720Z TRACE server: quinn_proto::connection: max ack delay reached 2024-01-15T23:54:23.909749Z TRACE server:send{space=Data pn=12}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..15]), Delay = 25000us 2024-01-15T23:54:23.909798Z TRACE server: quinn_proto::connection: sending 37 bytes in 1 datagrams 2024-01-15T23:54:23.909856Z TRACE client: quinn_proto::connection: got Data packet (37 bytes) from [::1]:4476 using id e00e478408e635f4 2024-01-15T23:54:23.909914Z TRACE client:recv{space=Data pn=12}: quinn_proto::connection: got frame Ack(Ack { largest: 14, delay: 3125, ecn: Some(EcnCounts { ect0: 14, ect1: 0, ce: 0 }), ranges: "[12..=14,9..=10]" }) 2024-01-15T23:54:23.910006Z TRACE quinn_proto::tests::util: advancing to 104ms for client 2024-01-15T23:54:23.910026Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard 2024-01-15T23:54:23.910063Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard thread 'tests::key_update_reordered' panicked at quinn-proto/src/tests/mod.rs:856:5: assertion `left == right` failed left: 1 right: 0 ```

[Ralith]

Again: https://github.com/quinn-rs/quinn/actions/runs/10185475414/job/28175129233

Logs

``` 2024-07-31T18:16:25.847294Z INFO quinn_proto::tests::util: connecting 2024-07-31T18:16:25.847359Z TRACE client: quinn_proto::endpoint: initial_dcid=ba61a6c3391916180361ec9ec0ce5f8ce0088592 2024-07-31T18:16:25.848191Z TRACE client: quinn_proto::connection: wrote 271 Initial CRYPTO bytes 2024-07-31T18:16:25.848259Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 271 2024-07-31T18:16:25.848282Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 870 2024-07-31T18:16:25.848338Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-07-31T18:16:25.848854Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 271 CRYPTO bytes 2024-07-31T18:16:25.850477Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready 2024-07-31T18:16:25.850505Z TRACE server:first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes 2024-07-31T18:16:25.850609Z TRACE server:first recv: quinn_proto::connection: Data keys ready 2024-07-31T18:16:25.850688Z TRACE server:first recv: quinn_proto::connection: wrote 633 Handshake CRYPTO bytes 2024-07-31T18:16:25.850757Z TRACE server: quinn_proto::endpoint: new connection id=0 icid=ba61a6c3391916180361ec9ec0ce5f8ce0088592 error: test failed, to rerun pass `-p quinn-proto --lib` 2024-07-31T18:16:25.850818Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-07-31T18:16:25.850843Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 2024-07-31T18:16:25.850915Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 633 2024-07-31T18:16:25.850939Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 376 2024-07-31T18:16:25.850990Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-07-31T18:16:25.851087Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=c80cf84a75800a5e 2024-07-31T18:16:25.851114Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=cb6c3ab2169593fb 2024-07-31T18:16:25.851138Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=42bbff4be4c2959f 2024-07-31T18:16:25.851168Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=262bb689b89a8676 2024-07-31T18:16:25.851219Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-07-31T18:16:25.851297Z TRACE client: quinn_proto::connection: got Initial packet (145 bytes) from [::1]:4478 using id 6eedec0c126b1ab8 2024-07-31T18:16:25.851354Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to af3ac66550318166 2024-07-31T18:16:25.851431Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes 2024-07-31T18:16:25.852065Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready 2024-07-31T18:16:25.852107Z TRACE client: quinn_proto::connection: got Handshake packet (1055 bytes) from [::1]:4478 using id 6eedec0c126b1ab8 2024-07-31T18:16:25.852179Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 633 CRYPTO bytes 2024-07-31T18:16:25.852872Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready 2024-07-31T18:16:25.852959Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes 2024-07-31T18:16:25.853022Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-07-31T18:16:25.853060Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4478 using id 6eedec0c126b1ab8 2024-07-31T18:16:25.853129Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [200, 12, 248, 74, 117, 128, 10, 94], reset_token: ResetToken([216, 237, 77, 23, 178, 216, 139, 155, 205, 207, 52, 135, 178, 131, 52, 48]) }) 2024-07-31T18:16:25.853158Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=c80cf84a75800a5e retire_prior_to=0 2024-07-31T18:16:25.853214Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [203, 108, 58, 178, 22, 149, 147, 251], reset_token: ResetToken([48, 16, 207, 126, 58, 220, 118, 44, 161, 242, 6, 27, 139, 180, 181, 7]) }) 2024-07-31T18:16:25.853243Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=cb6c3ab2169593fb retire_prior_to=0 2024-07-31T18:16:25.853300Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [66, 187, 255, 75, 228, 194, 149, 159], reset_token: ResetToken([4, 132, 123, 144, 215, 208, 178, 176, 143, 38, 197, 202, 4, 237, 245, 140]) }) 2024-07-31T18:16:25.853331Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=42bbff4be4c2959f retire_prior_to=0 2024-07-31T18:16:25.853388Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [38, 43, 182, 137, 184, 154, 134, 118], reset_token: ResetToken([165, 3, 31, 47, 167, 159, 156, 156, 71, 166, 78, 191, 228, 120, 160, 20]) }) 2024-07-31T18:16:25.853420Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=262bb689b89a8676 retire_prior_to=0 2024-07-31T18:16:25.853514Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-07-31T18:16:25.853583Z TRACE client: quinn_proto::connection: discarding Initial keys 2024-07-31T18:16:25.853656Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us 2024-07-31T18:16:25.853680Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52 2024-07-31T18:16:25.853702Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 1044 2024-07-31T18:16:25.853763Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams 2024-07-31T18:16:25.853803Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 1298 2024-07-31T18:16:25.853863Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-07-31T18:16:25.853884Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-07-31T18:16:25.853998Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=dced0a6ee7196dc2 2024-07-31T18:16:25.854034Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=1f2f433238c3158c 2024-07-31T18:16:25.854061Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=37b77e3c384e2f10 2024-07-31T18:16:25.854087Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=c149438d1664e736 2024-07-31T18:16:25.854149Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams 2024-07-31T18:16:25.854222Z TRACE server: quinn_proto::connection: got Initial packet (51 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.854327Z TRACE server: quinn_proto::connection: got Handshake packet (1149 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.854387Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys 2024-07-31T18:16:25.854458Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes 2024-07-31T18:16:25.855075Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes 2024-07-31T18:16:25.855103Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys 2024-07-31T18:16:25.855126Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established 2024-07-31T18:16:25.855159Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.855227Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.855271Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.855711Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.855781Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [220, 237, 10, 110, 231, 25, 109, 194], reset_token: ResetToken([37, 34, 197, 190, 236, 194, 70, 242, 113, 59, 3, 3, 112, 23, 206, 166]) }) 2024-07-31T18:16:25.855808Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=dced0a6ee7196dc2 retire_prior_to=0 2024-07-31T18:16:25.855857Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [31, 47, 67, 50, 56, 195, 21, 140], reset_token: ResetToken([0, 18, 83, 89, 34, 183, 14, 19, 167, 133, 199, 225, 149, 207, 75, 221]) }) 2024-07-31T18:16:25.855882Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=1f2f433238c3158c retire_prior_to=0 2024-07-31T18:16:25.855923Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [55, 183, 126, 60, 56, 78, 47, 16], reset_token: ResetToken([210, 207, 70, 26, 27, 35, 49, 77, 10, 9, 51, 155, 124, 70, 36, 62]) }) 2024-07-31T18:16:25.855946Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=37b77e3c384e2f10 retire_prior_to=0 2024-07-31T18:16:25.855987Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [193, 73, 67, 141, 22, 100, 231, 54], reset_token: ResetToken([78, 243, 127, 19, 103, 52, 172, 11, 248, 143, 137, 65, 161, 191, 114, 143]) }) 2024-07-31T18:16:25.856011Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=c149438d1664e736 retire_prior_to=0 2024-07-31T18:16:25.856077Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us 2024-07-31T18:16:25.856100Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356 2024-07-31T18:16:25.856119Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 2024-07-31T18:16:25.856171Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams 2024-07-31T18:16:25.856209Z TRACE server:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1298 2024-07-31T18:16:25.856264Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326 2024-07-31T18:16:25.856279Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams 2024-07-31T18:16:25.856350Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.856410Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone 2024-07-31T18:16:25.856430Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys 2024-07-31T18:16:25.856488Z 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-07-31T18:16:25.856524Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-07-31T18:16:25.856593Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356 2024-07-31T18:16:25.856625Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes 2024-07-31T18:16:25.856820Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 } 2024-07-31T18:16:25.856865Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.856920Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.856952Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.857390Z TRACE client:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us 2024-07-31T18:16:25.857445Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.857487Z TRACE client:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1361 2024-07-31T18:16:25.857546Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-07-31T18:16:25.857564Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-07-31T18:16:25.857587Z TRACE client: quinn_proto::endpoint: peer retired CID 0: 6eedec0c126b1ab8 2024-07-31T18:16:25.857692Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=f1170dda04b8ee85 2024-07-31T18:16:25.857757Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams 2024-07-31T18:16:25.857826Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.857891Z 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-07-31T18:16:25.857938Z TRACE server:recv{space=Data pn=2}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 2024-07-31T18:16:25.858001Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.858057Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.858097Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.858558Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.858628Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [241, 23, 13, 218, 4, 184, 238, 133], reset_token: ResetToken([119, 89, 37, 233, 241, 182, 96, 182, 165, 101, 217, 115, 203, 134, 229, 225]) }) 2024-07-31T18:16:25.858659Z TRACE server:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=f1170dda04b8ee85 retire_prior_to=0 2024-07-31T18:16:25.858734Z TRACE server:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([2..5]), Delay = 0us 2024-07-31T18:16:25.858788Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.858832Z TRACE server:send{space=Data pn=4}: quinn_proto::connection::packet_builder: PADDING * 1361 2024-07-31T18:16:25.858897Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389 2024-07-31T18:16:25.858914Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams 2024-07-31T18:16:25.858990Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.859059Z 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-07-31T18:16:25.859097Z TRACE client:recv{space=Data pn=3}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-07-31T18:16:25.859163Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.859228Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.859268Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.859725Z TRACE client:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([3..5]), Delay = 0us 2024-07-31T18:16:25.859779Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.859820Z TRACE client:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1392 2024-07-31T18:16:25.859886Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-07-31T18:16:25.859904Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-07-31T18:16:25.859966Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.860027Z 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-07-31T18:16:25.860063Z TRACE server:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 2024-07-31T18:16:25.860120Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.860181Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.860225Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.860712Z TRACE server:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us 2024-07-31T18:16:25.860766Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.860794Z TRACE server: quinn_proto::connection::spaces: skipping pn 6 2024-07-31T18:16:25.860831Z TRACE server:send{space=Data pn=7}: quinn_proto::connection::packet_builder: PADDING * 1392 2024-07-31T18:16:25.860895Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420 2024-07-31T18:16:25.860916Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams 2024-07-31T18:16:25.860984Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.861053Z 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-07-31T18:16:25.861089Z TRACE client:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-07-31T18:16:25.861147Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.861223Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.861268Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.861755Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([5..6, 7..8]), Delay = 0us 2024-07-31T18:16:25.861808Z TRACE client: quinn_proto::connection: sending 36 bytes in 1 datagrams 2024-07-31T18:16:25.861849Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1424 2024-07-31T18:16:25.861911Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-07-31T18:16:25.861928Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-07-31T18:16:25.861982Z TRACE server: quinn_proto::connection: got Data packet (36 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.862038Z TRACE server:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 7, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[7..=7,5..=5]" }) 2024-07-31T18:16:25.862074Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 2024-07-31T18:16:25.862123Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.862174Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.862206Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.862674Z TRACE server:send{space=Data pn=8}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us 2024-07-31T18:16:25.862721Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.862759Z TRACE server:send{space=Data pn=9}: quinn_proto::connection::packet_builder: PADDING * 1424 2024-07-31T18:16:25.862822Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452 2024-07-31T18:16:25.862839Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams 2024-07-31T18:16:25.862905Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.862969Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[7..=8]" }) 2024-07-31T18:16:25.863007Z TRACE client:recv{space=Data pn=8}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-07-31T18:16:25.863063Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.863128Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.863169Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.863640Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([8..10]), Delay = 0us 2024-07-31T18:16:25.863690Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams 2024-07-31T18:16:25.863740Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.863795Z TRACE server:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 9, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[8..=9]" }) 2024-07-31T18:16:25.863828Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 2024-07-31T18:16:25.863898Z TRACE quinn_proto::connection::streams: wrote 1 bytes stream=client bidirectional stream 0 2024-07-31T18:16:25.863927Z TRACE quinn_proto::connection: executing key update 2024-07-31T18:16:25.864038Z TRACE send{space=Data pn=10}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=0 len=1 fin=false 2024-07-31T18:16:25.864095Z TRACE quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-07-31T18:16:25.864115Z TRACE quinn_proto::connection: executing key update 2024-07-31T18:16:25.864204Z INFO quinn_proto::tests: updated keys 2024-07-31T18:16:25.864219Z TRACE quinn_proto::connection::streams: wrote 3 bytes stream=client bidirectional stream 0 2024-07-31T18:16:25.864263Z TRACE send{space=Data pn=11}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-07-31T18:16:25.864321Z TRACE quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-07-31T18:16:25.864393Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.864427Z TRACE server: quinn_proto::connection::packet_crypto: decryption failed with packet number 11 2024-07-31T18:16:25.864451Z DEBUG server: quinn_proto::connection: failed to authenticate packet 2024-07-31T18:16:25.864470Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.864504Z TRACE server: quinn_proto::connection: key update authenticated 2024-07-31T18:16:25.864519Z TRACE server: quinn_proto::connection: executing key update 2024-07-31T18:16:25.864638Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=1 fin=false 2024-07-31T18:16:25.864700Z TRACE quinn_proto::tests::util: advancing to 25ms for server 2024-07-31T18:16:25.864730Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-07-31T18:16:25.864746Z TRACE server: quinn_proto::connection: max ack delay reached 2024-07-31T18:16:25.864775Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 25000us 2024-07-31T18:16:25.864823Z TRACE server: quinn_proto::connection: sending 35 bytes in 1 datagrams 2024-07-31T18:16:25.864876Z TRACE client: quinn_proto::connection: got Data packet (35 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.864933Z TRACE client:recv{space=Data pn=10}: quinn_proto::connection: got frame Ack(Ack { largest: 10, delay: 3125, ecn: Some(EcnCounts { ect0: 11, ect1: 0, ce: 0 }), ranges: "[9..=10]" }) 2024-07-31T18:16:25.865024Z TRACE quinn_proto::tests::util: advancing to 26ms for client 2024-07-31T18:16:25.865044Z TRACE client: quinn_proto::connection: timeout timer=LossDetection 2024-07-31T18:16:25.865065Z TRACE client: quinn_proto::connection: PTO fired in_flight=33 count=0 space=Data 2024-07-31T18:16:25.865112Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: PING 2024-07-31T18:16:25.865130Z TRACE client:send{space=Data pn=12}: quinn_proto::connection: IMMEDIATE_ACK 2024-07-31T18:16:25.865150Z TRACE client:send{space=Data pn=12}: quinn_proto::connection::packet_builder: PADDING * 2 2024-07-31T18:16:25.865194Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-07-31T18:16:25.865235Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: PING 2024-07-31T18:16:25.865255Z TRACE client:send{space=Data pn=13}: quinn_proto::connection: IMMEDIATE_ACK 2024-07-31T18:16:25.865277Z TRACE client:send{space=Data pn=13}: quinn_proto::connection::packet_builder: PADDING * 2 2024-07-31T18:16:25.865322Z TRACE client: quinn_proto::connection: sending 30 bytes in 1 datagrams 2024-07-31T18:16:25.865382Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.865414Z TRACE server: quinn_proto::connection: key update authenticated 2024-07-31T18:16:25.865431Z TRACE server: quinn_proto::connection: executing key update 2024-07-31T18:16:25.865550Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.865595Z TRACE server:recv{space=Data pn=12}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.865676Z TRACE server: quinn_proto::connection: got Data packet (30 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.865731Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame Ping 2024-07-31T18:16:25.865769Z TRACE server:recv{space=Data pn=13}: quinn_proto::connection: got frame ImmediateAck 2024-07-31T18:16:25.865827Z TRACE server:send{space=Data pn=11}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..14]), Delay = 0us 2024-07-31T18:16:25.865886Z TRACE server: quinn_proto::connection: sending 36 bytes in 1 datagrams 2024-07-31T18:16:25.865953Z TRACE client: quinn_proto::connection: got Data packet (36 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.866009Z TRACE client:recv{space=Data pn=11}: quinn_proto::connection: got frame Ack(Ack { largest: 13, delay: 0, ecn: Some(EcnCounts { ect0: 13, ect1: 0, ce: 0 }), ranges: "[12..=13,9..=10]" }) 2024-07-31T18:16:25.866049Z TRACE client:recv{space=Data pn=11}:frame{ty=ACK}: quinn_proto::connection: packets lost: [11], bytes lost: 33 2024-07-31T18:16:25.866124Z TRACE client:send{space=Data pn=14}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=1 len=3 fin=false 2024-07-31T18:16:25.866180Z TRACE client: quinn_proto::connection: sending 33 bytes in 1 datagrams 2024-07-31T18:16:25.866237Z TRACE server: quinn_proto::connection: got Data packet (33 bytes) from [::1]:44478 using id af3ac66550318166 2024-07-31T18:16:25.866314Z TRACE server:recv{space=Data pn=14}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=1 len=3 fin=false 2024-07-31T18:16:25.866382Z TRACE quinn_proto::tests::util: advancing to 51ms for server 2024-07-31T18:16:25.866422Z TRACE server: quinn_proto::connection: timeout timer=MaxAckDelay 2024-07-31T18:16:25.866439Z TRACE server: quinn_proto::connection: max ack delay reached 2024-07-31T18:16:25.866477Z TRACE server:send{space=Data pn=12}: quinn_proto::connection: ACK ArrayRangeSet([9..11, 12..15]), Delay = 25000us 2024-07-31T18:16:25.866534Z TRACE server: quinn_proto::connection: sending 37 bytes in 1 datagrams 2024-07-31T18:16:25.866601Z TRACE client: quinn_proto::connection: got Data packet (37 bytes) from [::1]:4478 using id dced0a6ee7196dc2 2024-07-31T18:16:25.866670Z TRACE client:recv{space=Data pn=12}: quinn_proto::connection: got frame Ack(Ack { largest: 14, delay: 3125, ecn: Some(EcnCounts { ect0: 14, ect1: 0, ce: 0 }), ranges: "[12..=14,9..=10]" }) 2024-07-31T18:16:25.866773Z TRACE quinn_proto::tests::util: advancing to 104ms for client 2024-07-31T18:16:25.866791Z TRACE client: quinn_proto::connection: timeout timer=KeyDiscard 2024-07-31T18:16:25.866825Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard thread 'tests::key_update_reordered' panicked at quinn-proto/src/tests/mod.rs:1065:5: assertion `left == right` failed left: 1 right: 0 ```