From 29721630559d834ce4fdbc09a9235d6d6cba6bd4 Mon Sep 17 00:00:00 2001 From: Kristofers Solo Date: Wed, 4 Feb 2026 11:53:40 +0200 Subject: [PATCH] feat(runner): add structured logging with tracing - Add tracing, tracing-subscriber, uuid dependencies - Replace eprintln! with info! for structured logs - Add run_id, rust_version, os, arch to benchmark start log --- Cargo.lock | 216 +++++++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 3 + runner/Cargo.toml | 3 + runner/build.rs | 16 ++++ runner/src/main.rs | 74 ++++++++++------ 5 files changed, 283 insertions(+), 29 deletions(-) create mode 100644 runner/build.rs diff --git a/Cargo.lock b/Cargo.lock index c2639f0..a5b0a8c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -17,6 +17,15 @@ version = "2.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "320119579fcad9c21884f5c4861d16174d0e06250625266f50fe6898340abefa" +[[package]] +name = "aho-corasick" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ddd31a130427c27518df266943a5308ed92d4b226cc639f5a8f1002816174301" +dependencies = [ + "memchr", +] + [[package]] name = "anstream" version = "0.6.21" @@ -170,6 +179,12 @@ version = "2.10.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "812e12b5285cc515a9c72a5c1d3b6d46a19dac5acfef5265968c166106e31dd3" +[[package]] +name = "bumpalo" +version = "3.19.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5dd9dc738b7a8311c7ade152424974d8115f2cdad61e8dab8dac9f2362298510" + [[package]] name = "bytes" version = "1.11.0" @@ -398,6 +413,16 @@ dependencies = [ "libc", ] +[[package]] +name = "js-sys" +version = "0.3.85" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8c942ebf8e95485ca0d52d97da7c5a2c387d0e7f0ba4c35e93bfcaee045955b3" +dependencies = [ + "once_cell", + "wasm-bindgen", +] + [[package]] name = "lazy_static" version = "1.5.0" @@ -425,6 +450,21 @@ dependencies = [ "scopeguard", ] +[[package]] +name = "log" +version = "0.4.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5e5032e24019045c762d3c0f28f5b6b8bbf38563a65908389bf7978758920897" + +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.7.6" @@ -497,6 +537,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num-bigint" version = "0.4.6" @@ -659,6 +708,23 @@ dependencies = [ "bitflags", ] +[[package]] +name = "regex-automata" +version = "0.4.13" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5276caf25ac86c8d810222b3dbb938e512c55c6831a10f3e6ed1c93b84041f1c" +dependencies = [ + "aho-corasick", + "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-syntax" +version = "0.8.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7a2d987857b319362043e95f5353c0535c1f58eec5336fdfcf626430af7def58" + [[package]] name = "ring" version = "0.17.14" @@ -683,6 +749,9 @@ dependencies = [ "rustls", "tokio", "tokio-rustls", + "tracing", + "tracing-subscriber", + "uuid", ] [[package]] @@ -748,6 +817,12 @@ dependencies = [ "untrusted", ] +[[package]] +name = "rustversion" +version = "1.0.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b39cdef0fa800fc44525c84ccb54a029961a8215f9619753635a9c0d2538d46d" + [[package]] name = "scopeguard" version = "1.2.0" @@ -809,6 +884,15 @@ dependencies = [ "tokio-rustls", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -957,6 +1041,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", +] + [[package]] name = "time" version = "0.3.46" @@ -1026,6 +1119,67 @@ dependencies = [ "tokio", ] +[[package]] +name = "tracing" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + [[package]] name = "unicode-ident" version = "1.0.22" @@ -1062,6 +1216,23 @@ version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821" +[[package]] +name = "uuid" +version = "1.20.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee48d38b119b0cd71fe4141b30f5ba9c7c5d9f4e7a3a8b4a674e4b6ef789976f" +dependencies = [ + "getrandom 0.3.4", + "js-sys", + "wasm-bindgen", +] + +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "wasi" version = "0.11.1+wasi-snapshot-preview1" @@ -1077,6 +1248,51 @@ dependencies = [ "wit-bindgen", ] +[[package]] +name = "wasm-bindgen" +version = "0.2.108" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "64024a30ec1e37399cf85a7ffefebdb72205ca1c972291c51512360d90bd8566" +dependencies = [ + "cfg-if", + "once_cell", + "rustversion", + "wasm-bindgen-macro", + "wasm-bindgen-shared", +] + +[[package]] +name = "wasm-bindgen-macro" +version = "0.2.108" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "008b239d9c740232e71bd39e8ef6429d27097518b6b30bdf9086833bd5b6d608" +dependencies = [ + "quote", + "wasm-bindgen-macro-support", +] + +[[package]] +name = "wasm-bindgen-macro-support" +version = "0.2.108" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5256bae2d58f54820e6490f9839c49780dff84c65aeab9e772f15d5f0e913a55" +dependencies = [ + "bumpalo", + "proc-macro2", + "quote", + "syn", + "wasm-bindgen-shared", +] + +[[package]] +name = "wasm-bindgen-shared" +version = "0.2.108" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1f01b580c9ac74c8d8f0c0e4afb04eeef2acf145458e52c03845ee9cd23e3d12" +dependencies = [ + "unicode-ident", +] + [[package]] name = "windows-link" version = "0.2.1" diff --git a/Cargo.toml b/Cargo.toml index 1f4500a..4001bfe 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -32,6 +32,9 @@ tokio = { version = "1", features = ["full"] } tokio-rustls = { version = "0.26", default-features = false, features = [ "tls12", ] } +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["env-filter", "fmt"] } +uuid = { version = "1", features = ["v4"] } [workspace.lints.clippy] nursery = "warn" diff --git a/runner/Cargo.toml b/runner/Cargo.toml index 44df097..df32b2b 100644 --- a/runner/Cargo.toml +++ b/runner/Cargo.toml @@ -11,6 +11,9 @@ miette.workspace = true rustls.workspace = true tokio-rustls.workspace = true tokio.workspace = true +tracing.workspace = true +tracing-subscriber.workspace = true +uuid.workspace = true [lints] workspace = true diff --git a/runner/build.rs b/runner/build.rs new file mode 100644 index 0000000..1218380 --- /dev/null +++ b/runner/build.rs @@ -0,0 +1,16 @@ +use std::{env, process::Command}; + +fn main() { + let rustc_version = env::var("RUSTC_VERSION").unwrap_or_else(|_| { + Command::new("rustc") + .arg("--version") + .output() + .ok() + .and_then(|output| String::from_utf8(output.stdout).ok()) + .unwrap_or_else(|| "unknown".to_string()) + .trim() + .to_string() + }); + + println!("cargo:rustc-env=RUSTC_VERSION={rustc_version}"); +} diff --git a/runner/src/main.rs b/runner/src/main.rs index c0660d3..21e3f59 100644 --- a/runner/src/main.rs +++ b/runner/src/main.rs @@ -23,6 +23,8 @@ use rustls::{ version::TLS13, }; use std::{ + env, + fmt::Debug, fs::File, io::{BufWriter, Write, stdout}, net::SocketAddr, @@ -32,6 +34,9 @@ use std::{ }; use tokio::{net::TcpStream, sync::Semaphore, task::JoinHandle}; use tokio_rustls::TlsConnector; +use tracing::info; +use tracing_subscriber::EnvFilter; +use uuid::Uuid; /// TLS benchmark runner. #[derive(Debug, Parser)] @@ -165,15 +170,15 @@ async fn run_iteration( let handshake_ns = start.elapsed().as_nanos() as u64; - // Send request - write_request(&mut tls_stream, u64::from(payload_bytes)) - .await - .map_err(|e| miette!("write request failed: {e}"))?; + // Send request + write_request(&mut tls_stream, u64::from(payload_bytes)) + .await + .map_err(|e| miette!("write request failed: {e}"))?; - // Read response - read_payload(&mut tls_stream, u64::from(payload_bytes)) - .await - .map_err(|e| miette!("read payload failed: {e}"))?; + // Read response + read_payload(&mut tls_stream, u64::from(payload_bytes)) + .await + .map_err(|e| miette!("read payload failed: {e}"))?; let ttlb_ns = start.elapsed().as_nanos() as u64; @@ -198,11 +203,12 @@ async fn run_benchmark( None => Box::new(stdout()), }; - eprintln!( - "Running {} warmup + {} measured iterations (concurrency: {}, TLS 1.3)", - args.warmup, args.iters, args.concurrency + info!( + warmup = args.warmup, + iters = args.iters, + concurrency = args.concurrency, + "runnning benchmark iterations" ); - eprintln!(); for _ in 0..args.warmup { run_iteration( @@ -213,7 +219,7 @@ async fn run_benchmark( ) .await?; } - eprintln!("Warmup complete."); + info!("warmup complete"); #[allow(clippy::cast_possible_truncation)] // concurrency is limited to reasonable values let semaphore = Arc::new(Semaphore::new(args.concurrency as usize)); @@ -225,7 +231,7 @@ async fn run_benchmark( .flush() .map_err(|e| miette!("failed to flush output: {e}"))?; - eprintln!("Benchmark complete."); + info!("benchmark complete"); Ok(()) } @@ -256,7 +262,6 @@ fn spawn_benchmark_tasks( .collect() } -#[allow(clippy::too_many_arguments)] fn spawn_single_iteration( i: u32, payload_bytes: u32, @@ -303,22 +308,33 @@ async fn write_results( #[tokio::main] async fn main() -> miette::Result<()> { - let args = Args::parse(); + let run_id = Uuid::new_v4(); + tracing_subscriber::fmt() + .with_writer(std::io::stderr) + .with_env_filter(EnvFilter::from_default_env()) + .with_target(false) + .init(); - eprintln!("runner configuration:"); - eprintln!(" mode: {}", args.mode); - eprintln!(" server: {}", args.server); - eprintln!(" payload_bytes: {}", args.payload_bytes); - eprintln!(" iters: {}", args.iters); - eprintln!(" warmup: {}", args.warmup); - eprintln!(" concurrency: {}", args.concurrency); - eprintln!( - " out: {}", - args.out - .as_ref() - .map_or_else(|| "stdout".to_string(), |p| p.display().to_string()) + info!( + run_id=%run_id, + rust_version=env!("RUSTC_VERSION"), + on=env::consts::OS, + arch=env::consts::ARCH, + command=env::args().collect::>().join(" "), + "benchmark started" + ); + + let args = Args::parse(); + info!( + mode=%args.mode, + server=%args.server, + payload_bytes=%args.payload_bytes, + iters=%args.iters, + warmup=%args.warmup, + concurrency=%args.concurrency, + out=%args.out.as_ref().map_or("stdout", |p| p.to_str().unwrap_or("invalid")), + "runner configuration" ); - eprintln!(); // Build TLS config (skips certificate verification for benchmarking) let tls_config = build_tls_config(args.mode)?;