From 3f366f5cda31d665dbd22175ad4fca53b27b0e16 Mon Sep 17 00:00:00 2001 From: Phoenix K Date: Sat, 16 Mar 2024 10:17:18 -0500 Subject: [PATCH] tls debugging --- Cargo.toml | 3 + log | 0 patches/rustls | 1 + quinn-proto/src/connection/mod.rs | 12 +- quinn-proto/src/crypto.rs | 2 +- quinn-proto/src/crypto/rustls.rs | 2 + quinn-proto/src/tests/mod.rs | 2 +- quinn/Cargo.toml | 1 + quinn/examples/client.rs | 174 +++++++--- quinn/examples/server.rs | 3 +- testoutput.txt | 517 ++++++++++++++++++++++++++++++ 11 files changed, 667 insertions(+), 50 deletions(-) create mode 100644 log create mode 160000 patches/rustls create mode 100644 testoutput.txt diff --git a/Cargo.toml b/Cargo.toml index f90603ec0..4c369968d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,3 +8,6 @@ debug = true [profile.release] debug = true + +[patch.crates-io] +rustls = { path = "./patches/rustls/rustls" } diff --git a/log b/log new file mode 100644 index 000000000..e69de29bb diff --git a/patches/rustls b/patches/rustls new file mode 160000 index 000000000..cf6aa80cb --- /dev/null +++ b/patches/rustls @@ -0,0 +1 @@ +Subproject commit cf6aa80cbfb1f18e308138fdd59ac8255ac931ce diff --git a/quinn-proto/src/connection/mod.rs b/quinn-proto/src/connection/mod.rs index d420b44d6..5b62a086b 100644 --- a/quinn-proto/src/connection/mod.rs +++ b/quinn-proto/src/connection/mod.rs @@ -1867,13 +1867,21 @@ impl Connection { } fn init_0rtt(&mut self) { + eprintln!("call to init_0rtt"); let (header, packet) = match self.crypto.early_crypto() { - Some(x) => x, - None => return, + Some(x) => { + eprintln!("early crypto found"); + x + }, + None => { + eprintln!("early crypto not found"); + return + }, }; if self.side.is_client() { match self.crypto.transport_parameters() { Ok(params) => { + eprintln!("init_0rtt, params = {:#?}", params); let params = params .expect("crypto layer didn't supply transport parameters with ticket"); // Certain values must not be cached diff --git a/quinn-proto/src/crypto.rs b/quinn-proto/src/crypto.rs index 3c2cb5c04..9b43eb397 100644 --- a/quinn-proto/src/crypto.rs +++ b/quinn-proto/src/crypto.rs @@ -8,7 +8,7 @@ //! Note that usage of any protocol (version) other than TLS 1.3 does not conform to any //! published versions of the specification, and will not be supported in QUIC v1. -use std::{any::Any, str, sync::Arc}; +use std::{any::Any, str, sync::Arc, fmt::Debug}; use bytes::BytesMut; diff --git a/quinn-proto/src/crypto/rustls.rs b/quinn-proto/src/crypto/rustls.rs index 7d325508a..3b8c22c8b 100644 --- a/quinn-proto/src/crypto/rustls.rs +++ b/quinn-proto/src/crypto/rustls.rs @@ -67,7 +67,9 @@ impl crypto::Session for TlsSession { } fn early_crypto(&self) -> Option<(Box, Box)> { + eprintln!("rustls::early_crypto"); let keys = self.inner.zero_rtt_keys()?; + eprintln!("rustls::early_crypto proceeding with Some path"); Some((Box::new(keys.header), Box::new(keys.packet))) } diff --git a/quinn-proto/src/tests/mod.rs b/quinn-proto/src/tests/mod.rs index c41f3592d..a1bb173ee 100644 --- a/quinn-proto/src/tests/mod.rs +++ b/quinn-proto/src/tests/mod.rs @@ -462,7 +462,7 @@ fn zero_rtt_happypath() { let mut pair = Pair::new( Default::default(), ServerConfig { - use_retry: true, + use_retry: false, ..server_config() }, ); diff --git a/quinn/Cargo.toml b/quinn/Cargo.toml index 88fc2a439..642590dca 100644 --- a/quinn/Cargo.toml +++ b/quinn/Cargo.toml @@ -63,6 +63,7 @@ tokio = { version = "1.28.1", features = ["rt", "rt-multi-thread", "time", "macr tracing-subscriber = { version = "0.3.0", default-features = false, features = ["env-filter", "fmt", "ansi", "time", "local-time"] } tracing-futures = { version = "0.2.0", default-features = false, features = ["std-future"] } url = "2" +backtrace = "0.3" [[example]] name = "server" diff --git a/quinn/examples/client.rs b/quinn/examples/client.rs index 3e85dd66f..6a3bf97d9 100644 --- a/quinn/examples/client.rs +++ b/quinn/examples/client.rs @@ -2,6 +2,9 @@ //! //! Checkout the `README.md` for guidance. +#[macro_use] +extern crate tracing; + use std::{ fs, io::{self, Write}, @@ -42,12 +45,13 @@ struct Opt { } fn main() { - tracing::subscriber::set_global_default( - tracing_subscriber::FmtSubscriber::builder() - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) - .finish(), - ) - .unwrap(); + logging::init_logging(); + //tracing::subscriber::set_global_default( + // tracing_subscriber::FmtSubscriber::builder() + // .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + // .finish(), + //) + //.unwrap(); let opt = Opt::parse(); let code = { if let Err(e) = run(opt) { @@ -95,9 +99,10 @@ async fn run(options: Opt) -> Result<()> { if options.keylog { client_crypto.key_log = Arc::new(rustls::KeyLogFile::new()); } + client_crypto.enable_early_data = true; let client_config = quinn::ClientConfig::new(Arc::new(client_crypto)); - let mut endpoint = quinn::Endpoint::client("[::]:0".parse().unwrap())?; + let mut endpoint = quinn::Endpoint::client("127.0.0.1:0".parse().unwrap())?; endpoint.set_default_client_config(client_config); let request = format!("GET {}\r\n", url.path()); @@ -105,44 +110,58 @@ async fn run(options: Opt) -> Result<()> { let rebind = options.rebind; let host = options.host.as_deref().unwrap_or(url_host); - eprintln!("connecting to {host} at {remote}"); - let conn = endpoint - .connect(remote, host)? - .await - .map_err(|e| anyhow!("failed to connect: {}", e))?; - eprintln!("connected at {:?}", start.elapsed()); - let (mut send, mut recv) = conn - .open_bi() - .await - .map_err(|e| anyhow!("failed to open stream: {}", e))?; - if rebind { - let socket = std::net::UdpSocket::bind("[::]:0").unwrap(); - let addr = socket.local_addr().unwrap(); - eprintln!("rebinding to {addr}"); - endpoint.rebind(socket).expect("rebind failed"); - } + for i in 1..=2 { + eprintln!("round {}", i); + eprintln!("connecting to {host} at {remote}"); + let conn = match endpoint.connect(remote, host)?.into_0rtt() { + Ok((conn, _)) => { + eprintln!("0-rtt accepted"); + conn + }, + Err(connecting) => { + eprintln!("0-rtt rejected"); + connecting.await.map_err(|e| anyhow!("failed to connect: {}", e))? + }, + }; + /*let conn = endpoint + .connect(remote, host)? + .await + .map_err(|e| anyhow!("failed to connect: {}", e))?;*/ + eprintln!("connected at {:?}", start.elapsed()); + let (mut send, mut recv) = conn + .open_bi() + .await + .map_err(|e| anyhow!("failed to open stream: {}", e))?; + if rebind { + let socket = std::net::UdpSocket::bind("[::]:0").unwrap(); + let addr = socket.local_addr().unwrap(); + eprintln!("rebinding to {addr}"); + endpoint.rebind(socket).expect("rebind failed"); + } - send.write_all(request.as_bytes()) - .await - .map_err(|e| anyhow!("failed to send request: {}", e))?; - send.finish() - .await - .map_err(|e| anyhow!("failed to shutdown stream: {}", e))?; - let response_start = Instant::now(); - eprintln!("request sent at {:?}", response_start - start); - let resp = recv - .read_to_end(usize::max_value()) - .await - .map_err(|e| anyhow!("failed to read response: {}", e))?; - let duration = response_start.elapsed(); - eprintln!( - "response received in {:?} - {} KiB/s", - duration, - resp.len() as f32 / (duration_secs(&duration) * 1024.0) - ); - io::stdout().write_all(&resp).unwrap(); - io::stdout().flush().unwrap(); - conn.close(0u32.into(), b"done"); + send.write_all(request.as_bytes()) + .await + .map_err(|e| anyhow!("failed to send request: {}", e))?; + send.finish() + .await + .map_err(|e| anyhow!("failed to shutdown stream: {}", e))?; + let response_start = Instant::now(); + eprintln!("request sent at {:?}", response_start - start); + let resp = recv + .read_to_end(usize::max_value()) + .await + .map_err(|e| anyhow!("failed to read response: {}", e))?; + let duration = response_start.elapsed(); + eprintln!( + "response received in {:?} - {} KiB/s", + duration, + resp.len() as f32 / (duration_secs(&duration) * 1024.0) + ); + io::stdout().write_all(&resp).unwrap(); + io::stdout().flush().unwrap(); + conn.close(0u32.into(), b"done"); + eprintln!(""); + } // Give the server a fair chance to receive the close packet endpoint.wait_idle().await; @@ -163,3 +182,70 @@ fn strip_ipv6_brackets(host: &str) -> &str { fn duration_secs(x: &Duration) -> f32 { x.as_secs() as f32 + x.subsec_nanos() as f32 * 1e-9 } + + +mod logging { + //! Global logging system. + + use std::{ + fs::File, + sync::Arc, + env, + panic, + }; + use backtrace::Backtrace; + use tracing_subscriber::{ + fmt::{ + self, + time::uptime, + }, + prelude::*, + Registry, + EnvFilter, + }; + + + /// Default logging environment filter. Our crates are debug, everything else is warn. + const DEFAULT_FILTER: &'static str = "warn"; + + /// Initializes a `tracing` logging backend which outputs to stdout and also a `log` file. Accepts + /// ecosystem-standard `RUST_LOG` env filters. Configures some other logging tweaks too. + pub fn init_logging() { + // initialize and install logging system + let format = fmt::format() + .compact() + .with_timer(uptime()) + .with_line_number(true); + let stdout_log = fmt::layer() + .event_format(format); + + let log_file = File::create("log") + .expect("unable to create log file"); + let log_file_log = tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_line_number(true) + .with_writer(Arc::new(log_file)); + + let mut filter = DEFAULT_FILTER.to_owned(); + if let Ok(env_filter) = env::var(EnvFilter::DEFAULT_ENV) { + filter.push(','); + filter.push_str(&env_filter); + } + + let subscriber = Registry::default() + .with(EnvFilter::new(filter)) + .with(stdout_log) + .with(log_file_log); + tracing::subscriber::set_global_default(subscriber) + .expect("unable to install log subscriber"); + + // make panic messages and backtrace go through logging system + panic::set_hook(Box::new(|info| { + error!("{}", info); + if env::var("RUST_BACKTRACE").map(|val| val == "1").unwrap_or(true) { + error!("{:?}", Backtrace::new()); + } + })); + } + +} diff --git a/quinn/examples/server.rs b/quinn/examples/server.rs index 70e71be77..c0e1ecdc6 100644 --- a/quinn/examples/server.rs +++ b/quinn/examples/server.rs @@ -128,14 +128,13 @@ async fn run(options: Opt) -> Result<()> { if options.keylog { server_crypto.key_log = Arc::new(rustls::KeyLogFile::new()); } - + server_crypto.max_early_data_size = u32::MAX; let mut server_config = quinn::ServerConfig::with_crypto(Arc::new(server_crypto)); let transport_config = Arc::get_mut(&mut server_config.transport).unwrap(); transport_config.max_concurrent_uni_streams(0_u8.into()); if options.stateless_retry { server_config.use_retry(true); } - let root = Arc::::from(options.root.clone()); if !root.exists() { bail!("root path does not exist"); diff --git a/testoutput.txt b/testoutput.txt new file mode 100644 index 000000000..80fd666ad --- /dev/null +++ b/testoutput.txt @@ -0,0 +1,517 @@ + +running 1 test +test tests::zero_rtt_happypath ... ok + +successes: + +---- tests::zero_rtt_happypath stdout ---- +2024-03-15T23:47:03.664072Z TRACE client: quinn_proto::endpoint: initial_dcid=96c463a37af68e0a11b1b94fd18bcf411d0ad320 +2024-03-15T23:47:03.664474Z TRACE client: quinn_proto::connection: wrote 273 Initial CRYPTO bytes +call to init_0rtt +rustls::early_crypto +rustls ConnectionCommon zero_rtt_keys +rustls ConnectionCommon zero_rtt_keys thing1.is_some() false +early crypto not found +2024-03-15T23:47:03.664540Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 273 +2024-03-15T23:47:03.664551Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 868 +2024-03-15T23:47:03.664582Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.664712Z TRACE client: quinn_proto::connection: got Initial packet (116 bytes) from [::1]:4433 using id 68936da7fe064bb5 +2024-03-15T23:47:03.664737Z TRACE client:recv{space=Initial}: quinn_proto::connection: retrying with CID 75d909d4a9a560eb +2024-03-15T23:47:03.664755Z TRACE client:recv{space=Initial}: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.664805Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 273 +2024-03-15T23:47:03.664814Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection::packet_builder: PADDING * 802 +2024-03-15T23:47:03.664833Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.665035Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 273 CRYPTO bytes +2024-03-15T23:47:03.665614Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready +2024-03-15T23:47:03.665624Z TRACE server:first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes +2024-03-15T23:47:03.665655Z TRACE server:first recv: quinn_proto::connection: Data keys ready +2024-03-15T23:47:03.665681Z TRACE server:first recv: quinn_proto::connection: wrote 642 Handshake CRYPTO bytes +call to init_0rtt +rustls::early_crypto +rustls ConnectionCommon zero_rtt_keys +rustls ConnectionCommon zero_rtt_keys thing1.is_some() true +rustls ConnectionCommon zero_rtt_keys thing2.is_some() false +early crypto not found +2024-03-15T23:47:03.665711Z TRACE server: quinn_proto::endpoint: connection incoming id=0 icid=75d909d4a9a560eb +2024-03-15T23:47:03.665742Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([1..2]), Delay = 0us +2024-03-15T23:47:03.665751Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90 +2024-03-15T23:47:03.665781Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 642 +2024-03-15T23:47:03.665792Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 367 +2024-03-15T23:47:03.665809Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.665850Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=b78399e6604a40b8 +2024-03-15T23:47:03.665860Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=a372f3934d951c13 +2024-03-15T23:47:03.665867Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=116459198318817d +2024-03-15T23:47:03.665874Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=267d45978e6c0bc5 +2024-03-15T23:47:03.665900Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams +2024-03-15T23:47:03.665946Z TRACE client: quinn_proto::connection: got Initial packet (145 bytes) from [::1]:4433 using id 68936da7fe064bb5 +2024-03-15T23:47:03.665975Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to d9a97eaafa61d6f4 +2024-03-15T23:47:03.666017Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes +2024-03-15T23:47:03.666233Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready +2024-03-15T23:47:03.666250Z TRACE client: quinn_proto::connection: got Handshake packet (1055 bytes) from [::1]:4433 using id 68936da7fe064bb5 +2024-03-15T23:47:03.666277Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 642 CRYPTO bytes +2024-03-15T23:47:03.666555Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready +2024-03-15T23:47:03.666582Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes +2024-03-15T23:47:03.666606Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established +2024-03-15T23:47:03.666619Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4433 using id 68936da7fe064bb5 +2024-03-15T23:47:03.666646Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [183, 131, 153, 230, 96, 74, 64, 184], reset_token: ResetToken([96, 85, 158, 3, 192, 174, 152, 54, 181, 114, 245, 41, 239, 53, 29, 244]) }) +2024-03-15T23:47:03.666657Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=b78399e6604a40b8 retire_prior_to=0 +2024-03-15T23:47:03.666675Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [163, 114, 243, 147, 77, 149, 28, 19], reset_token: ResetToken([68, 6, 176, 126, 42, 112, 239, 92, 193, 17, 60, 221, 155, 83, 124, 89]) }) +2024-03-15T23:47:03.666683Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=a372f3934d951c13 retire_prior_to=0 +2024-03-15T23:47:03.666698Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [17, 100, 89, 25, 131, 24, 129, 125], reset_token: ResetToken([21, 240, 145, 223, 141, 34, 73, 117, 43, 182, 150, 86, 28, 151, 175, 62]) }) +2024-03-15T23:47:03.666706Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=116459198318817d retire_prior_to=0 +2024-03-15T23:47:03.666721Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [38, 125, 69, 151, 142, 108, 11, 197], reset_token: ResetToken([175, 210, 240, 96, 138, 12, 167, 132, 164, 211, 244, 142, 86, 78, 222, 60]) }) +2024-03-15T23:47:03.666729Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=267d45978e6c0bc5 retire_prior_to=0 +2024-03-15T23:47:03.666755Z TRACE client:send{space=Initial pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us +2024-03-15T23:47:03.666776Z TRACE client: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.666798Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us +2024-03-15T23:47:03.666805Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52 +2024-03-15T23:47:03.666813Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 966 +2024-03-15T23:47:03.666830Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.666847Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 1297 +2024-03-15T23:47:03.666864Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326 +2024-03-15T23:47:03.666870Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams +2024-03-15T23:47:03.666907Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=b0d1974f83dc7e07 +2024-03-15T23:47:03.666916Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=10098d031b4ea268 +2024-03-15T23:47:03.666923Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=383f9c85c8f417d1 +2024-03-15T23:47:03.666930Z TRACE client:send{space=Data pn=1}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=02b3dda3fabb0bdb +2024-03-15T23:47:03.666950Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams +2024-03-15T23:47:03.666981Z TRACE server: quinn_proto::connection: got Initial packet (129 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.667026Z TRACE server: quinn_proto::connection: got Handshake packet (1071 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.667045Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.667074Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes +2024-03-15T23:47:03.667250Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes +2024-03-15T23:47:03.667260Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys +2024-03-15T23:47:03.667267Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established +2024-03-15T23:47:03.667279Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.667302Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.667317Z TRACE server:recv{space=Data pn=0}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.667440Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.667462Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [176, 209, 151, 79, 131, 220, 126, 7], reset_token: ResetToken([169, 50, 221, 134, 18, 162, 251, 86, 140, 212, 27, 95, 224, 156, 119, 172]) }) +2024-03-15T23:47:03.667471Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=b0d1974f83dc7e07 retire_prior_to=0 +2024-03-15T23:47:03.667490Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [16, 9, 141, 3, 27, 78, 162, 104], reset_token: ResetToken([166, 219, 104, 4, 141, 22, 44, 138, 86, 40, 56, 233, 52, 46, 86, 251]) }) +2024-03-15T23:47:03.667497Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=10098d031b4ea268 retire_prior_to=0 +2024-03-15T23:47:03.667513Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [56, 63, 156, 133, 200, 244, 23, 209], reset_token: ResetToken([41, 72, 108, 101, 37, 242, 183, 5, 129, 88, 153, 11, 168, 183, 237, 57]) }) +2024-03-15T23:47:03.667520Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=383f9c85c8f417d1 retire_prior_to=0 +2024-03-15T23:47:03.667536Z TRACE server:recv{space=Data pn=1}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [2, 179, 221, 163, 250, 187, 11, 219], reset_token: ResetToken([49, 27, 9, 212, 116, 158, 55, 232, 70, 217, 200, 20, 235, 162, 149, 120]) }) +2024-03-15T23:47:03.667543Z TRACE server:recv{space=Data pn=1}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=02b3dda3fabb0bdb retire_prior_to=0 +2024-03-15T23:47:03.667569Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us +2024-03-15T23:47:03.667577Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356 +2024-03-15T23:47:03.667584Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 +2024-03-15T23:47:03.667604Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams +2024-03-15T23:47:03.667613Z TRACE server: quinn_proto::connection::spaces: skipping pn 2 +2024-03-15T23:47:03.667625Z TRACE server:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1297 +2024-03-15T23:47:03.667640Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326 +2024-03-15T23:47:03.667646Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams +2024-03-15T23:47:03.667675Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.667698Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone +2024-03-15T23:47:03.667705Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys +2024-03-15T23:47:03.667724Z 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-03-15T23:47:03.667737Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 +2024-03-15T23:47:03.667760Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356 +2024-03-15T23:47:03.667769Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes +2024-03-15T23:47:03.667851Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 } +2024-03-15T23:47:03.667870Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.667893Z TRACE client:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.667907Z TRACE client:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.668038Z TRACE client:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..2, 3..4]), Delay = 0us +2024-03-15T23:47:03.668057Z TRACE client: quinn_proto::connection: sending 36 bytes in 1 datagrams +2024-03-15T23:47:03.668073Z TRACE client:send{space=Data pn=3}: quinn_proto::connection::packet_builder: PADDING * 1360 +2024-03-15T23:47:03.668089Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389 +2024-03-15T23:47:03.668094Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams +2024-03-15T23:47:03.668102Z TRACE client: quinn_proto::endpoint: peer retired CID 0: 68936da7fe064bb5 +2024-03-15T23:47:03.668127Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=b5b3fc4944781de3 +2024-03-15T23:47:03.668148Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams +2024-03-15T23:47:03.668171Z TRACE server: quinn_proto::connection: got Data packet (36 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.668195Z TRACE server:recv{space=Data pn=2}: quinn_proto::connection: got frame Ack(Ack { largest: 3, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[3..=3,0..=1]" }) +2024-03-15T23:47:03.668211Z TRACE server:recv{space=Data pn=2}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 +2024-03-15T23:47:03.668232Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.668253Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.668267Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.668395Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.668415Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [181, 179, 252, 73, 68, 120, 29, 227], reset_token: ResetToken([191, 167, 189, 0, 188, 169, 63, 9, 118, 189, 190, 97, 26, 192, 249, 160]) }) +2024-03-15T23:47:03.668423Z TRACE server:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=b5b3fc4944781de3 retire_prior_to=0 +2024-03-15T23:47:03.668448Z TRACE server:send{space=Data pn=4}: quinn_proto::connection: ACK ArrayRangeSet([2..5]), Delay = 0us +2024-03-15T23:47:03.668465Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.668479Z TRACE server:send{space=Data pn=5}: quinn_proto::connection::packet_builder: PADDING * 1360 +2024-03-15T23:47:03.668496Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389 +2024-03-15T23:47:03.668501Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams +2024-03-15T23:47:03.668524Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.668547Z 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-03-15T23:47:03.668560Z TRACE client:recv{space=Data pn=4}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 +2024-03-15T23:47:03.668581Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.668602Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.668616Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.668752Z TRACE client:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([4..6]), Delay = 0us +2024-03-15T23:47:03.668770Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.668783Z TRACE client:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1391 +2024-03-15T23:47:03.668798Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420 +2024-03-15T23:47:03.668803Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams +2024-03-15T23:47:03.668824Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.668846Z 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-03-15T23:47:03.668858Z TRACE server:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 +2024-03-15T23:47:03.668877Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.668898Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.668912Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.669053Z TRACE server:send{space=Data pn=6}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us +2024-03-15T23:47:03.669071Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.669084Z TRACE server:send{space=Data pn=7}: quinn_proto::connection::packet_builder: PADDING * 1391 +2024-03-15T23:47:03.669099Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420 +2024-03-15T23:47:03.669105Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams +2024-03-15T23:47:03.669127Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.669149Z 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-03-15T23:47:03.669161Z TRACE client:recv{space=Data pn=6}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 +2024-03-15T23:47:03.669181Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.669202Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.669216Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.669354Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([6..8]), Delay = 0us +2024-03-15T23:47:03.669371Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.669386Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1423 +2024-03-15T23:47:03.669401Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452 +2024-03-15T23:47:03.669406Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams +2024-03-15T23:47:03.669427Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.669449Z 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-03-15T23:47:03.669461Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 +2024-03-15T23:47:03.669483Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.669504Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.669518Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.669733Z TRACE server:send{space=Data pn=8}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us +2024-03-15T23:47:03.669753Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.669767Z TRACE server:send{space=Data pn=9}: quinn_proto::connection::packet_builder: PADDING * 1423 +2024-03-15T23:47:03.669783Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452 +2024-03-15T23:47:03.669788Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams +2024-03-15T23:47:03.669812Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.669835Z 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-03-15T23:47:03.669847Z TRACE client:recv{space=Data pn=8}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 +2024-03-15T23:47:03.669868Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.669917Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.669939Z TRACE client:recv{space=Data pn=9}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.670116Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([8..10]), Delay = 0us +2024-03-15T23:47:03.670135Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.670157Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.670180Z 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-03-15T23:47:03.670195Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 +2024-03-15T23:47:03.670221Z TRACE quinn_proto::connection: connection closed +2024-03-15T23:47:03.670238Z TRACE client:send{space=Data pn=10}: quinn_proto::connection: sending CONNECTION_CLOSE +2024-03-15T23:47:03.670245Z TRACE client:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([8..10]), Delay = 0us +2024-03-15T23:47:03.670261Z TRACE client: quinn_proto::connection: sending 37 bytes in 1 datagrams +2024-03-15T23:47:03.670280Z TRACE server: quinn_proto::connection: got Data packet (37 bytes) from [::1]:44433 using id d9a97eaafa61d6f4 +2024-03-15T23:47:03.670302Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got frame Ack(Ack { largest: 9, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[8..=9]" }) +2024-03-15T23:47:03.670321Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got frame Close(Application(ApplicationClose { error_code: 0, reason: b"" })) +2024-03-15T23:47:03.670334Z TRACE server: quinn_proto::connection: connection closed +2024-03-15T23:47:03.670347Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: sending CONNECTION_CLOSE +2024-03-15T23:47:03.670353Z TRACE server:send{space=Data pn=10}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 0us +2024-03-15T23:47:03.670368Z TRACE server: quinn_proto::connection: sending 38 bytes in 1 datagrams +2024-03-15T23:47:03.670389Z TRACE client: quinn_proto::connection: got Data packet (38 bytes) from [::1]:4433 using id b0d1974f83dc7e07 +2024-03-15T23:47:03.670409Z TRACE client:recv{space=Data pn=10}: quinn_proto::connection: draining +2024-03-15T23:47:03.670431Z TRACE quinn_proto::tests::util: advancing to 78ms for client +2024-03-15T23:47:03.670438Z TRACE client: quinn_proto::connection: timeout timer=Close +2024-03-15T23:47:03.670461Z TRACE server: quinn_proto::connection: timeout timer=Close +2024-03-15T23:47:03.670478Z  INFO quinn_proto::tests: resuming session +2024-03-15T23:47:03.670498Z TRACE client: quinn_proto::endpoint: initial_dcid=49f8a781499f10dfc754e91e9be8fb10374d1490 +>>> client_early_traffic_secret +2024-03-15T23:47:03.670839Z TRACE client: quinn_proto::connection: wrote 368 Initial CRYPTO bytes +call to init_0rtt +rustls::early_crypto +rustls ConnectionCommon zero_rtt_keys +rustls ConnectionCommon zero_rtt_keys thing1.is_some() true +rustls ConnectionCommon zero_rtt_keys thing2.is_some() true +rustls::early_crypto proceeding with Some path +early crypto found +init_0rtt, params = Some( + TransportParameters { + max_idle_timeout: 10000, + max_udp_payload_size: 1472, + initial_max_data: 4611686018427387903, + initial_max_stream_data_bidi_local: 1250000, + initial_max_stream_data_bidi_remote: 1250000, + initial_max_stream_data_uni: 1250000, + initial_max_streams_bidi: 100, + initial_max_streams_uni: 100, + ack_delay_exponent: 3, + max_ack_delay: 25, + active_connection_id_limit: 5, + disable_active_migration: false, + max_datagram_frame_size: Some( + 65535, + ), + initial_src_cid: Some( + [ + 217, + 169, + 126, + 170, + 250, + 97, + 214, + 244, + ], + ), + grease_quic_bit: true, + min_ack_delay: Some( + 1000, + ), + original_dst_cid: Some( + [ + 150, + 196, + 99, + 163, + 122, + 246, + 142, + 10, + 17, + 177, + 185, + 79, + 209, + 139, + 207, + 65, + 29, + 10, + 211, + 32, + ], + ), + retry_src_cid: Some( + [ + 117, + 217, + 9, + 212, + 169, + 165, + 96, + 235, + ], + ), + stateless_reset_token: Some( + ResetToken( + [ + 209, + 139, + 49, + 203, + 140, + 97, + 231, + 138, + 243, + 153, + 203, + 101, + 168, + 194, + 220, + 6, + ], + ), + ), + preferred_address: None, + }, +) +2024-03-15T23:47:03.670897Z TRACE client: quinn_proto::connection: 0-RTT enabled +2024-03-15T23:47:03.670931Z TRACE quinn_proto::connection::streams: wrote 13 bytes stream=client unidirectional stream 0 +2024-03-15T23:47:03.670953Z TRACE client:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 368 +2024-03-15T23:47:03.670989Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::streams::state: STREAM id=client unidirectional stream 0 off=0 len=13 fin=false +2024-03-15T23:47:03.671002Z TRACE client:send{space=Data pn=0}: quinn_proto::connection::packet_builder: PADDING * 703 +2024-03-15T23:47:03.671018Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.671096Z TRACE client: quinn_proto::connection: got Initial packet (116 bytes) from [::1]:4433 using id 7e1c6c0207fda575 +2024-03-15T23:47:03.671114Z TRACE client:recv{space=Initial}: quinn_proto::connection: retrying with CID 0dd7892b09eb7b57 +2024-03-15T23:47:03.671123Z TRACE client:recv{space=Initial}: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.671172Z TRACE client:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 368 +2024-03-15T23:47:03.671204Z TRACE client:send{space=Data pn=1}: quinn_proto::connection::streams::state: STREAM id=client unidirectional stream 0 off=0 len=13 fin=false +2024-03-15T23:47:03.671216Z TRACE client:send{space=Data pn=1}: quinn_proto::connection::packet_builder: PADDING * 649 +2024-03-15T23:47:03.671232Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.671407Z TRACE server:first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 368 CRYPTO bytes +>>> client_early_traffic_secret +2024-03-15T23:47:03.671880Z TRACE server:first recv: quinn_proto::connection: Handshake keys ready +2024-03-15T23:47:03.671889Z TRACE server:first recv: quinn_proto::connection: wrote 96 Initial CRYPTO bytes +2024-03-15T23:47:03.671917Z TRACE server:first recv: quinn_proto::connection: Data keys ready +2024-03-15T23:47:03.671939Z TRACE server:first recv: quinn_proto::connection: wrote 196 Handshake CRYPTO bytes +call to init_0rtt +rustls::early_crypto +rustls ConnectionCommon zero_rtt_keys +rustls ConnectionCommon zero_rtt_keys thing1.is_some() true +rustls ConnectionCommon zero_rtt_keys thing2.is_some() true +rustls::early_crypto proceeding with Some path +early crypto found +2024-03-15T23:47:03.671969Z TRACE server:first recv: quinn_proto::connection: 0-RTT enabled +2024-03-15T23:47:03.671979Z TRACE server:first recv: quinn_proto::connection: got Data packet (707 bytes) from [::1]:44434 using id 0dd7892b09eb7b57 +2024-03-15T23:47:03.672015Z TRACE server:first recv:recv{space=Data pn=1}: quinn_proto::connection: got stream frame id=client unidirectional stream 0 offset=0 len=13 fin=false +2024-03-15T23:47:03.672099Z TRACE server: quinn_proto::endpoint: connection incoming id=0 icid=0dd7892b09eb7b57 +2024-03-15T23:47:03.672130Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([1..2]), Delay = 0us +2024-03-15T23:47:03.672138Z TRACE server:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 96 +2024-03-15T23:47:03.672167Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 196 +2024-03-15T23:47:03.672176Z TRACE server:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 807 +2024-03-15T23:47:03.672193Z TRACE server: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.672228Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=5d12418ce3947269 +2024-03-15T23:47:03.672238Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=9027101309f1b2b4 +2024-03-15T23:47:03.672245Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=a1a864795c5510ad +2024-03-15T23:47:03.672252Z TRACE server:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=4460ccba1c540b95 +2024-03-15T23:47:03.672270Z TRACE server: quinn_proto::connection: sending 138 bytes in 1 datagrams +2024-03-15T23:47:03.672296Z TRACE client: quinn_proto::connection: got Initial packet (151 bytes) from [::1]:4433 using id 7e1c6c0207fda575 +2024-03-15T23:47:03.672315Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to 046c268edbe978d0 +2024-03-15T23:47:03.672347Z TRACE client:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 96 CRYPTO bytes +2024-03-15T23:47:03.672569Z TRACE client:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready +2024-03-15T23:47:03.672587Z TRACE client: quinn_proto::connection: got Handshake packet (1049 bytes) from [::1]:4433 using id 7e1c6c0207fda575 +2024-03-15T23:47:03.672617Z TRACE client:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 196 CRYPTO bytes +2024-03-15T23:47:03.672822Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: Data keys ready +2024-03-15T23:47:03.672850Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 52 Handshake CRYPTO bytes +2024-03-15T23:47:03.672876Z TRACE client:recv{space=Handshake pn=0}: quinn_proto::connection: established +2024-03-15T23:47:03.672893Z TRACE client: quinn_proto::connection: got Data packet (138 bytes) from [::1]:4433 using id 7e1c6c0207fda575 +2024-03-15T23:47:03.672921Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [93, 18, 65, 140, 227, 148, 114, 105], reset_token: ResetToken([191, 161, 242, 100, 217, 171, 26, 218, 219, 102, 41, 208, 48, 76, 140, 19]) }) +2024-03-15T23:47:03.672939Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=5d12418ce3947269 retire_prior_to=0 +2024-03-15T23:47:03.672959Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [144, 39, 16, 19, 9, 241, 178, 180], reset_token: ResetToken([15, 71, 255, 51, 44, 19, 157, 54, 41, 72, 71, 5, 142, 188, 215, 89]) }) +2024-03-15T23:47:03.672968Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=9027101309f1b2b4 retire_prior_to=0 +2024-03-15T23:47:03.672986Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [161, 168, 100, 121, 92, 85, 16, 173], reset_token: ResetToken([36, 148, 150, 135, 209, 224, 217, 184, 255, 224, 131, 155, 198, 186, 15, 229]) }) +2024-03-15T23:47:03.672994Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=a1a864795c5510ad retire_prior_to=0 +2024-03-15T23:47:03.673012Z TRACE client:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [68, 96, 204, 186, 28, 84, 11, 149], reset_token: ResetToken([88, 38, 159, 148, 155, 216, 135, 200, 9, 162, 145, 143, 227, 126, 193, 99]) }) +2024-03-15T23:47:03.673020Z TRACE client:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=4460ccba1c540b95 retire_prior_to=0 +2024-03-15T23:47:03.673049Z TRACE client:send{space=Initial pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us +2024-03-15T23:47:03.673072Z TRACE client: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.673089Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us +2024-03-15T23:47:03.673097Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 52 +2024-03-15T23:47:03.673106Z TRACE client:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 966 +2024-03-15T23:47:03.673125Z TRACE client: quinn_proto::connection: sending 1200 bytes in 1 datagrams +2024-03-15T23:47:03.673147Z TRACE client:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1297 +2024-03-15T23:47:03.673170Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1326 +2024-03-15T23:47:03.673176Z TRACE client: quinn_proto::connection: sending 1326 bytes in 1 datagrams +2024-03-15T23:47:03.673216Z TRACE client:send{space=Data pn=3}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=8db66f6bbf5c4767 +2024-03-15T23:47:03.673226Z TRACE client:send{space=Data pn=3}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=30367ca9cb3921ee +2024-03-15T23:47:03.673234Z TRACE client:send{space=Data pn=3}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=6da576a0d76800e2 +2024-03-15T23:47:03.673242Z TRACE client:send{space=Data pn=3}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=a11d55f94f71f1c0 +2024-03-15T23:47:03.673263Z TRACE client: quinn_proto::connection: sending 138 bytes in 1 datagrams +2024-03-15T23:47:03.673294Z TRACE server: quinn_proto::connection: got Initial packet (129 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.673344Z TRACE server: quinn_proto::connection: got Handshake packet (1071 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.673366Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys +2024-03-15T23:47:03.673398Z TRACE server:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 52 CRYPTO bytes +2024-03-15T23:47:03.673600Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: wrote 356 Data CRYPTO bytes +2024-03-15T23:47:03.673611Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Handshake keys +2024-03-15T23:47:03.673619Z TRACE server:recv{space=Handshake pn=0}: quinn_proto::connection: established +2024-03-15T23:47:03.673632Z TRACE server: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.673659Z TRACE server:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.673677Z TRACE server:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.673824Z TRACE server: quinn_proto::connection: got Data packet (138 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.673868Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [141, 182, 111, 107, 191, 92, 71, 103], reset_token: ResetToken([250, 53, 154, 221, 174, 192, 94, 84, 73, 34, 176, 12, 60, 125, 90, 30]) }) +2024-03-15T23:47:03.673884Z TRACE server:recv{space=Data pn=3}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=8db66f6bbf5c4767 retire_prior_to=0 +2024-03-15T23:47:03.673908Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [48, 54, 124, 169, 203, 57, 33, 238], reset_token: ResetToken([98, 39, 220, 77, 109, 239, 125, 201, 59, 73, 176, 236, 44, 196, 1, 104]) }) +2024-03-15T23:47:03.673917Z TRACE server:recv{space=Data pn=3}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=30367ca9cb3921ee retire_prior_to=0 +2024-03-15T23:47:03.673935Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [109, 165, 118, 160, 215, 104, 0, 226], reset_token: ResetToken([128, 248, 10, 98, 207, 117, 187, 171, 133, 179, 118, 18, 112, 110, 212, 38]) }) +2024-03-15T23:47:03.673944Z TRACE server:recv{space=Data pn=3}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=6da576a0d76800e2 retire_prior_to=0 +2024-03-15T23:47:03.673961Z TRACE server:recv{space=Data pn=3}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [161, 29, 85, 249, 79, 113, 241, 192], reset_token: ResetToken([127, 32, 51, 13, 68, 198, 225, 177, 30, 137, 154, 201, 27, 108, 118, 217]) }) +2024-03-15T23:47:03.673970Z TRACE server:recv{space=Data pn=3}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=a11d55f94f71f1c0 retire_prior_to=0 +2024-03-15T23:47:03.673998Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([1..4]), Delay = 0us +2024-03-15T23:47:03.674007Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 356 +2024-03-15T23:47:03.674014Z TRACE server:send{space=Data pn=1}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0 +2024-03-15T23:47:03.674037Z TRACE server: quinn_proto::connection: sending 397 bytes in 1 datagrams +2024-03-15T23:47:03.674054Z TRACE server:send{space=Data pn=2}: quinn_proto::connection::packet_builder: PADDING * 1297 +2024-03-15T23:47:03.674070Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1326 +2024-03-15T23:47:03.674075Z TRACE server: quinn_proto::connection: sending 1326 bytes in 1 datagrams +2024-03-15T23:47:03.674110Z TRACE client: quinn_proto::connection: got Data packet (397 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.674134Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone +2024-03-15T23:47:03.674140Z TRACE client:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys +2024-03-15T23:47:03.674161Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame Ack(Ack { largest: 3, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[1..=3]" }) +2024-03-15T23:47:03.674182Z TRACE client:recv{space=Data pn=1}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 +2024-03-15T23:47:03.674208Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=356 +2024-03-15T23:47:03.674218Z TRACE client:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 356 CRYPTO bytes +2024-03-15T23:47:03.674289Z TRACE client:recv{space=Data pn=1}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 } +2024-03-15T23:47:03.674309Z TRACE client: quinn_proto::connection: got Data packet (1326 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.674331Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.674345Z TRACE client:recv{space=Data pn=2}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.674478Z TRACE client:send{space=Data pn=4}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us +2024-03-15T23:47:03.674497Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.674511Z TRACE client:send{space=Data pn=5}: quinn_proto::connection::packet_builder: PADDING * 1360 +2024-03-15T23:47:03.674530Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1389 +2024-03-15T23:47:03.674536Z TRACE client: quinn_proto::connection: sending 1389 bytes in 1 datagrams +2024-03-15T23:47:03.674543Z TRACE client: quinn_proto::endpoint: peer retired CID 0: 7e1c6c0207fda575 +2024-03-15T23:47:03.674580Z TRACE client:send{space=Data pn=6}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=a137d208642812c5 +2024-03-15T23:47:03.674601Z TRACE client: quinn_proto::connection: sending 54 bytes in 1 datagrams +2024-03-15T23:47:03.674628Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.674652Z TRACE server:recv{space=Data pn=4}: quinn_proto::connection: got frame Ack(Ack { largest: 2, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[0..=2]" }) +2024-03-15T23:47:03.674669Z TRACE server:recv{space=Data pn=4}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1326 +2024-03-15T23:47:03.674690Z TRACE server: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.674712Z TRACE server:recv{space=Data pn=5}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.674726Z TRACE server:recv{space=Data pn=5}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.674855Z TRACE server: quinn_proto::connection: got Data packet (54 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.674875Z TRACE server:recv{space=Data pn=6}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [161, 55, 210, 8, 100, 40, 18, 197], reset_token: ResetToken([201, 229, 98, 114, 172, 140, 110, 240, 151, 28, 90, 230, 48, 67, 208, 237]) }) +2024-03-15T23:47:03.674883Z TRACE server:recv{space=Data pn=6}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=a137d208642812c5 retire_prior_to=0 +2024-03-15T23:47:03.674908Z TRACE server:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([4..7]), Delay = 0us +2024-03-15T23:47:03.674929Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.674955Z TRACE server:send{space=Data pn=4}: quinn_proto::connection::packet_builder: PADDING * 1360 +2024-03-15T23:47:03.674971Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1389 +2024-03-15T23:47:03.674979Z TRACE server: quinn_proto::connection: sending 1389 bytes in 1 datagrams +2024-03-15T23:47:03.675003Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.675027Z TRACE client:recv{space=Data pn=3}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 6, ect1: 0, ce: 0 }), ranges: "[4..=6]" }) +2024-03-15T23:47:03.675039Z TRACE client:recv{space=Data pn=3}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 +2024-03-15T23:47:03.675060Z TRACE client: quinn_proto::connection: got Data packet (1389 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.675082Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.675096Z TRACE client:recv{space=Data pn=4}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.675232Z TRACE client:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([3..5]), Delay = 0us +2024-03-15T23:47:03.675250Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.675264Z TRACE client:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1391 +2024-03-15T23:47:03.675279Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1420 +2024-03-15T23:47:03.675284Z TRACE client: quinn_proto::connection: sending 1420 bytes in 1 datagrams +2024-03-15T23:47:03.675305Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.675328Z TRACE server:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 4, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[3..=4]" }) +2024-03-15T23:47:03.675340Z TRACE server:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1389 +2024-03-15T23:47:03.675359Z TRACE server: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.675380Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.675394Z TRACE server:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.675533Z TRACE server:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us +2024-03-15T23:47:03.675553Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.675567Z TRACE server:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 1391 +2024-03-15T23:47:03.675582Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1420 +2024-03-15T23:47:03.675587Z TRACE server: quinn_proto::connection: sending 1420 bytes in 1 datagrams +2024-03-15T23:47:03.675609Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.675632Z TRACE client:recv{space=Data pn=5}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 8, ect1: 0, ce: 0 }), ranges: "[7..=8]" }) +2024-03-15T23:47:03.675644Z TRACE client:recv{space=Data pn=5}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 +2024-03-15T23:47:03.675664Z TRACE client: quinn_proto::connection: got Data packet (1420 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.675685Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.675698Z TRACE client:recv{space=Data pn=6}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.675836Z TRACE client:send{space=Data pn=9}: quinn_proto::connection: ACK ArrayRangeSet([5..7]), Delay = 0us +2024-03-15T23:47:03.675854Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.675869Z TRACE client:send{space=Data pn=10}: quinn_proto::connection::packet_builder: PADDING * 1423 +2024-03-15T23:47:03.675884Z TRACE client: quinn_proto::connection: writing MTUD probe probe_size=1452 +2024-03-15T23:47:03.675889Z TRACE client: quinn_proto::connection: sending 1452 bytes in 1 datagrams +2024-03-15T23:47:03.675910Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.675933Z TRACE server:recv{space=Data pn=9}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[5..=6]" }) +2024-03-15T23:47:03.675944Z TRACE server:recv{space=Data pn=9}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1420 +2024-03-15T23:47:03.675964Z TRACE server: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.675987Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.676002Z TRACE server:recv{space=Data pn=10}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.676143Z TRACE server:send{space=Data pn=7}: quinn_proto::connection: ACK ArrayRangeSet([9..11]), Delay = 0us +2024-03-15T23:47:03.676161Z TRACE server: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.676175Z TRACE server:send{space=Data pn=8}: quinn_proto::connection::packet_builder: PADDING * 1423 +2024-03-15T23:47:03.676190Z TRACE server: quinn_proto::connection: writing MTUD probe probe_size=1452 +2024-03-15T23:47:03.676195Z TRACE server: quinn_proto::connection: sending 1452 bytes in 1 datagrams +2024-03-15T23:47:03.676218Z TRACE client: quinn_proto::connection: got Data packet (34 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.676241Z TRACE client:recv{space=Data pn=7}: quinn_proto::connection: got frame Ack(Ack { largest: 10, delay: 0, ecn: Some(EcnCounts { ect0: 10, ect1: 0, ce: 0 }), ranges: "[9..=10]" }) +2024-03-15T23:47:03.676253Z TRACE client:recv{space=Data pn=7}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 +2024-03-15T23:47:03.676272Z TRACE client: quinn_proto::connection: got Data packet (1452 bytes) from [::1]:4433 using id 8db66f6bbf5c4767 +2024-03-15T23:47:03.676294Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame Ping +2024-03-15T23:47:03.676307Z TRACE client:recv{space=Data pn=8}: quinn_proto::connection: got frame ImmediateAck +2024-03-15T23:47:03.676449Z TRACE client:send{space=Data pn=11}: quinn_proto::connection: ACK ArrayRangeSet([7..9]), Delay = 0us +2024-03-15T23:47:03.676467Z TRACE client: quinn_proto::connection: sending 34 bytes in 1 datagrams +2024-03-15T23:47:03.676487Z TRACE server: quinn_proto::connection: got Data packet (34 bytes) from [::1]:44434 using id 046c268edbe978d0 +2024-03-15T23:47:03.676509Z TRACE server:recv{space=Data pn=11}: quinn_proto::connection: got frame Ack(Ack { largest: 8, delay: 0, ecn: Some(EcnCounts { ect0: 9, ect1: 0, ce: 0 }), ranges: "[7..=8]" }) +2024-03-15T23:47:03.676521Z TRACE server:recv{space=Data pn=11}:frame{ty=ACK}: quinn_proto::connection::mtud: new MTU detected current_mtu=1452 +2024-03-15T23:47:03.676555Z TRACE quinn_proto::tests::util: advancing to 156ms for server +2024-03-15T23:47:03.676571Z TRACE server: quinn_proto::connection: timeout timer=KeyDiscard + + +successes: + tests::zero_rtt_happypath + +test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 210 filtered out; finished in 0.01s + + +running 0 tests + +successes: + +successes: + +test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 3 filtered out; finished in 0.00s +