feat(server): add structured logging with tracing

This commit is contained in:
2026-02-04 15:11:26 +02:00
parent 2972163055
commit 46bc7960c1
7 changed files with 68 additions and 46 deletions

3
Cargo.lock generated
View File

@@ -882,6 +882,9 @@ dependencies = [
"rustls", "rustls",
"tokio", "tokio",
"tokio-rustls", "tokio-rustls",
"tracing",
"tracing-subscriber",
"uuid",
] ]
[[package]] [[package]]

View File

@@ -29,7 +29,7 @@
## Milestone 4 -- Concurrency & runner [MUST] ## Milestone 4 -- Concurrency & runner [MUST]
- [x] tokio-based runner - [x] tokio-based runner
- [ ] concurrency control and warmup - [X] concurrency control and warmup
- [ ] matrix runner over (mode, payload, concurrency) - [ ] matrix runner over (mode, payload, concurrency)
## Milestone 5 -- HTTP/1.1 mode (hyper) \[OPTIONAL\] ## Milestone 5 -- HTTP/1.1 mode (hyper) \[OPTIONAL\]

View File

@@ -1,7 +1,11 @@
export RUSTC_WRAPPER := "sccache"
set shell := ["bash", "-cu"]
# Default recipe # Default recipe
default: default:
@just --list @just --list
alias c := check
# Run all checks (fmt, clippy, docs, test) # Run all checks (fmt, clippy, docs, test)
check: fmt clippy docs test check: fmt clippy docs test
@@ -47,7 +51,6 @@ runner server mode="x25519" payload="1024" iters="100" warmup="10":
--iters {{iters}} \ --iters {{iters}} \
--warmup {{warmup}} --warmup {{warmup}}
alias c := clean
# Clean build artifacts # Clean build artifacts
clean: clean:
cargo clean cargo clean

View File

@@ -130,7 +130,6 @@ impl ServerCertVerifier for NoVerifier {
/// Build TLS client config for the given key exchange mode. /// Build TLS client config for the given key exchange mode.
fn build_tls_config(mode: KeyExchangeMode) -> miette::Result<Arc<ClientConfig>> { fn build_tls_config(mode: KeyExchangeMode) -> miette::Result<Arc<ClientConfig>> {
// Select crypto provider with appropriate key exchange groups
let mut provider = aws_lc_rs::default_provider(); let mut provider = aws_lc_rs::default_provider();
provider.kx_groups = match mode { provider.kx_groups = match mode {
KeyExchangeMode::X25519 => vec![X25519], KeyExchangeMode::X25519 => vec![X25519],
@@ -157,12 +156,10 @@ async fn run_iteration(
) -> miette::Result<IterationResult> { ) -> miette::Result<IterationResult> {
let start = Instant::now(); let start = Instant::now();
// TCP connect
let stream = TcpStream::connect(server) let stream = TcpStream::connect(server)
.await .await
.map_err(|e| miette!("TCP connection failed: {e}"))?; .map_err(|e| miette!("TCP connection failed: {e}"))?;
// TLS handshake
let mut tls_stream = tls_connector let mut tls_stream = tls_connector
.connect(server_name.clone(), stream) .connect(server_name.clone(), stream)
.await .await
@@ -170,12 +167,10 @@ async fn run_iteration(
let handshake_ns = start.elapsed().as_nanos() as u64; let handshake_ns = start.elapsed().as_nanos() as u64;
// Send request
write_request(&mut tls_stream, u64::from(payload_bytes)) write_request(&mut tls_stream, u64::from(payload_bytes))
.await .await
.map_err(|e| miette!("write request failed: {e}"))?; .map_err(|e| miette!("write request failed: {e}"))?;
// Read response
read_payload(&mut tls_stream, u64::from(payload_bytes)) read_payload(&mut tls_stream, u64::from(payload_bytes))
.await .await
.map_err(|e| miette!("read payload failed: {e}"))?; .map_err(|e| miette!("read payload failed: {e}"))?;
@@ -193,7 +188,6 @@ async fn run_benchmark(
tls_connector: TlsConnector, tls_connector: TlsConnector,
server_name: ServerName<'static>, server_name: ServerName<'static>,
) -> miette::Result<()> { ) -> miette::Result<()> {
// Open output file or use stdout
let mut output: Box<dyn Write + Send> = match &args.out { let mut output: Box<dyn Write + Send> = match &args.out {
Some(path) => { Some(path) => {
let file = let file =
@@ -318,7 +312,7 @@ async fn main() -> miette::Result<()> {
info!( info!(
run_id = %run_id, run_id = %run_id,
rust_version = env!("RUSTC_VERSION"), rust_version = env!("RUSTC_VERSION"),
on=env::consts::OS, os = env::consts::OS,
arch = env::consts::ARCH, arch = env::consts::ARCH,
command = env::args().collect::<Vec<_>>().join(" "), command = env::args().collect::<Vec<_>>().join(" "),
"benchmark started" "benchmark started"
@@ -336,11 +330,9 @@ async fn main() -> miette::Result<()> {
"runner configuration" "runner configuration"
); );
// Build TLS config (skips certificate verification for benchmarking)
let tls_config = build_tls_config(args.mode)?; let tls_config = build_tls_config(args.mode)?;
let tls_connector = TlsConnector::from(tls_config); let tls_connector = TlsConnector::from(tls_config);
// Server name for TLS (use "localhost" for local testing)
let server_name = ServerName::try_from("localhost".to_string()) let server_name = ServerName::try_from("localhost".to_string())
.map_err(|e| miette!("invalid server name: {e}"))?; .map_err(|e| miette!("invalid server name: {e}"))?;

View File

@@ -11,6 +11,9 @@ miette.workspace = true
rustls.workspace = true rustls.workspace = true
tokio-rustls.workspace = true tokio-rustls.workspace = true
tokio.workspace = true tokio.workspace = true
tracing.workspace = true
tracing-subscriber.workspace = true
uuid.workspace = true
[lints] [lints]
workspace = true workspace = true

16
server/build.rs Normal file
View File

@@ -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}");
}

View File

@@ -21,12 +21,14 @@ use rustls::{
server::Acceptor, server::Acceptor,
version::TLS13, version::TLS13,
}; };
use std::{fmt::Write, io::ErrorKind, net::SocketAddr, sync::Arc}; use std::{env, fmt::Write, io::ErrorKind, net::SocketAddr, sync::Arc};
use tokio::{ use tokio::{
io::AsyncWriteExt, io::AsyncWriteExt,
net::{TcpListener, TcpStream}, net::{TcpListener, TcpStream},
}; };
use tokio_rustls::LazyConfigAcceptor; use tokio_rustls::LazyConfigAcceptor;
use tracing::{debug, error, info, warn};
use tracing_subscriber::EnvFilter;
/// TLS benchmark server. /// TLS benchmark server.
#[derive(Debug, Parser)] #[derive(Debug, Parser)]
@@ -46,21 +48,18 @@ fn build_tls_config(
mode: KeyExchangeMode, mode: KeyExchangeMode,
server_cert: &ServerCertificate, server_cert: &ServerCertificate,
) -> miette::Result<Arc<ServerConfig>> { ) -> miette::Result<Arc<ServerConfig>> {
// Select crypto provider with appropriate key exchange groups
let mut provider = aws_lc_rs::default_provider(); let mut provider = aws_lc_rs::default_provider();
provider.kx_groups = match mode { provider.kx_groups = match mode {
KeyExchangeMode::X25519 => vec![X25519], KeyExchangeMode::X25519 => vec![X25519],
KeyExchangeMode::X25519Mlkem768 => vec![X25519MLKEM768], KeyExchangeMode::X25519Mlkem768 => vec![X25519MLKEM768],
}; };
// Convert certificate chain let certs = server_cert
let certs: Vec<CertificateDer<'static>> = server_cert
.cert_chain_der .cert_chain_der
.iter() .iter()
.map(|der| CertificateDer::from(der.clone())) .map(|der| CertificateDer::from(der.clone()))
.collect(); .collect::<Vec<_>>();
// Convert private key
let key = PrivateKeyDer::try_from(server_cert.private_key_der.clone()) let key = PrivateKeyDer::try_from(server_cert.private_key_der.clone())
.map_err(|e| miette!("invalid private key: {e}"))?; .map_err(|e| miette!("invalid private key: {e}"))?;
@@ -75,12 +74,11 @@ fn build_tls_config(
} }
async fn handle_connection(stream: TcpStream, peer: SocketAddr, tls_config: Arc<ServerConfig>) { async fn handle_connection(stream: TcpStream, peer: SocketAddr, tls_config: Arc<ServerConfig>) {
// Perform TLS handshake
let acceptor = LazyConfigAcceptor::new(Acceptor::default(), stream); let acceptor = LazyConfigAcceptor::new(Acceptor::default(), stream);
let start_handshake = match acceptor.await { let start_handshake = match acceptor.await {
Ok(sh) => sh, Ok(sh) => sh,
Err(e) => { Err(e) => {
eprintln!("[{peer}] TLS accept error: {e}"); warn!(peer = %peer, error = %e, "TLS accept error");
return; return;
} }
}; };
@@ -88,32 +86,32 @@ async fn handle_connection(stream: TcpStream, peer: SocketAddr, tls_config: Arc<
let mut tls_stream = match start_handshake.into_stream(tls_config).await { let mut tls_stream = match start_handshake.into_stream(tls_config).await {
Ok(s) => s, Ok(s) => s,
Err(e) => { Err(e) => {
eprintln!("[{peer}] TLS handshake error: {e}"); warn!(peer = %peer, error = %e, "TLS handshake error");
return; return;
} }
}; };
// Handle protocol
loop { loop {
let payload_size = match read_request(&mut tls_stream).await { let payload_size = match read_request(&mut tls_stream).await {
Ok(size) => size, Ok(size) => size,
Err(e) if e.kind() == ErrorKind::UnexpectedEof => { Err(e) if e.kind() == ErrorKind::UnexpectedEof => {
debug!(peer = %peer, "client disconnected");
break; break;
} }
Err(e) => { Err(e) => {
eprintln!("[{peer}] read error: {e}"); warn!(peer = %peer, error = %e, "connection error");
break; break;
} }
}; };
if let Err(e) = write_payload(&mut tls_stream, payload_size).await { if let Err(e) = write_payload(&mut tls_stream, payload_size).await {
eprintln!("[{peer}] write error: {e}"); warn!(peer = %peer, error = %e, "write error");
break; break;
} }
// Flush to ensure data is sent // Flush to ensure data is sent
if let Err(e) = tls_stream.flush().await { if let Err(e) = tls_stream.flush().await {
eprintln!("[{peer}] flush error: {e}"); warn!(peer = %peer, error = %e, "flush error");
break; break;
} }
} }
@@ -124,16 +122,13 @@ async fn run_server(args: Args, tls_config: Arc<ServerConfig>) -> miette::Result
.await .await
.map_err(|e| miette!("failed to bind to {}: {e}", args.listen))?; .map_err(|e| miette!("failed to bind to {}: {e}", args.listen))?;
eprintln!( info!(listen = %args.listen, mode = %args.mode, "listening");
"Listening on {} (TLS 1.3, mode: {})",
args.listen, args.mode
);
loop { loop {
let (stream, peer) = match listener.accept().await { let (stream, peer) = match listener.accept().await {
Ok(conn) => conn, Ok(conn) => conn,
Err(e) => { Err(e) => {
eprintln!("accept error: {e}"); error!(error = %e, "accept error");
continue; continue;
} }
}; };
@@ -145,27 +140,38 @@ async fn run_server(args: Args, tls_config: Arc<ServerConfig>) -> miette::Result
#[tokio::main] #[tokio::main]
async fn main() -> miette::Result<()> { async fn main() -> miette::Result<()> {
tracing_subscriber::fmt()
.with_env_filter(EnvFilter::from_default_env())
.with_target(false)
.init();
let args = Args::parse(); let args = Args::parse();
eprintln!("server configuration:"); info!(
eprintln!(" mode: {}", args.mode); rust_version = env!("RUSTC_VERSION"),
eprintln!(" listen: {}", args.listen); os = env::consts::OS,
eprintln!(); arch = env::consts::ARCH,
command = env::args().collect::<Vec<_>>().join(" "),
listen = %args.listen,
mode = %args.mode,
"server started"
);
// Generate certificates info!("Generating self-signed certificates...");
eprintln!("Generating self-signed certificates...");
let ca = CaCertificate::generate().map_err(|e| miette!("failed to generate CA: {e}"))?; let ca = CaCertificate::generate().map_err(|e| miette!("failed to generate CA: {e}"))?;
let server_cert = ca let server_cert = ca
.sign_server_cert("localhost") .sign_server_cert("localhost")
.map_err(|e| miette!("failed to generate server cert: {e}"))?; .map_err(|e| miette!("failed to generate server cert: {e}"))?;
// Build TLS config
let tls_config = build_tls_config(args.mode, &server_cert)?; let tls_config = build_tls_config(args.mode, &server_cert)?;
// Print CA certificate for client configuration info!(
eprintln!("CA certificate (base64 DER):"); ca_cert_base64 = base64_encode(&ca.cert_der)
eprintln!("{}", base64_encode(&ca.cert_der)); .lines()
eprintln!(); .take(3)
.collect::<String>(),
"CA cert (truncated)"
);
run_server(args, tls_config).await run_server(args, tls_config).await
} }
@@ -176,7 +182,7 @@ fn base64_encode(data: &[u8]) -> String {
let mut result = String::new(); let mut result = String::new();
for chunk in data.chunks(3) { for chunk in data.chunks(3) {
let mut n = 0u32; let mut n = 0;
for (i, &byte) in chunk.iter().enumerate() { for (i, &byte) in chunk.iter().enumerate() {
n |= u32::from(byte) << (16 - 8 * i); n |= u32::from(byte) << (16 - 8 * i);
} }
@@ -191,7 +197,6 @@ fn base64_encode(data: &[u8]) -> String {
} }
} }
// Wrap at 76 characters
let mut wrapped = String::new(); let mut wrapped = String::new();
for (i, c) in result.chars().enumerate() { for (i, c) in result.chars().enumerate() {
if i > 0 && i % 76 == 0 { if i > 0 && i % 76 == 0 {