Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

key_update_reordered is flaky #1695

Open
djc opened this issue Oct 23, 2023 · 4 comments
Open

key_update_reordered is flaky #1695

djc opened this issue Oct 23, 2023 · 4 comments

Comments

@djc
Copy link
Collaborator

djc commented Oct 23, 2023

This looks... weird?

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

Screenshot 2023-10-23 at 12 06 52
@Ralith
Copy link
Collaborator

Ralith commented Oct 23, 2023

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
Copy link
Collaborator

Ralith commented Oct 23, 2023

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
Copy link
Collaborator

Ralith commented Jan 15, 2024 •
edited

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
Copy link
Collaborator

Ralith commented Jan 15, 2024 •
edited

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 Ralith changed the title KeyUpdate reordered on beta but not stable key_update_reordered is flaky Jan 16, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Ralith @djc