From 57ca9555b49a015da22128b6f2d5b2a00a129a3c Mon Sep 17 00:00:00 2001 From: Austin Schaefer Date: Wed, 5 Aug 2026 15:23:30 +0200 Subject: [PATCH] feat: structured tracing observability Enable Rig's built-in tracing spans (model, token usage, cache hits, latency) via tracing-subscriber, filterable through RUST_LOG and defaulting to info level. Logs write to stderr so stdout stays reserved for program output. Standardizes the remaining ad-hoc println! diagnostics (server startup, per-iteration revision progress, non-convergence) into structured tracing events at appropriate levels. --- Cargo.lock | 106 ++++++++++++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 2 + src/main.rs | 21 +++++++++- src/revise.rs | 8 +++- src/server.rs | 4 +- 5 files changed, 136 insertions(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 849e952..537e3c1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2,6 +2,15 @@ # It is not intended for manual editing. version = 4 +[[package]] +name = "aho-corasick" +version = "1.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c982642fa9e8606056828ee9a8505737230110bb1099153c79efe865c59d12ba" +dependencies = [ + "memchr", +] + [[package]] name = "anyhow" version = "1.0.104" @@ -258,6 +267,8 @@ dependencies = [ "serde", "tokio", "toml", + "tracing", + "tracing-subscriber", ] [[package]] @@ -857,6 +868,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "libc" version = "0.2.189" @@ -896,6 +913,15 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "112b39cec0b298b6c1999fee3e31427f74f676e4cb9879ed1a121b43661a4154" +[[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.8.3" @@ -962,6 +988,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-traits" version = "0.2.19" @@ -1288,6 +1323,23 @@ dependencies = [ "syn 3.0.3", ] +[[package]] +name = "regex-automata" +version = "0.4.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ca71a6a1a566e01ad6b3b87edcbf9bd3374c27e31978c1b4e38c9fa6412557d2" +dependencies = [ + "aho-corasick", + "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-syntax" +version = "0.8.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d6f6ff9a378485b298a5286656da665ba74413d36db0979633275d2e708145d4" + [[package]] name = "reqwest" version = "0.12.28" @@ -1716,6 +1768,15 @@ dependencies = [ "digest", ] +[[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 = "2.0.1" @@ -1878,6 +1939,15 @@ dependencies = [ "syn 3.0.3", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "tinystr" version = "0.8.3" @@ -2106,6 +2176,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", ] [[package]] @@ -2120,6 +2191,35 @@ dependencies = [ "tracing", ] +[[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.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + [[package]] name = "try-lock" version = "0.2.5" @@ -2199,6 +2299,12 @@ version = "1.0.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b6c140620e7ffbb22c2dee59cafe6084a59b5ffc27a8859a5f0d494b5d52b6be" +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/Cargo.toml b/Cargo.toml index 44059af..1ab246b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -10,3 +10,5 @@ rig-core = { git = "https://github.com/0xPlaygrounds/rig", branch = "main" } serde = "1.0.229" tokio = { version = "1.53.1", features = ["full"] } toml = "1.1.4+spec-1.1.0" +tracing = "0.1" +tracing-subscriber = { version = "0.3.23", features = ["env-filter"] } diff --git a/src/main.rs b/src/main.rs index 76d65f4..2b7b4a2 100644 --- a/src/main.rs +++ b/src/main.rs @@ -17,6 +17,24 @@ static PROMPTS: LazyLock = LazyLock::new(|| { #[tokio::main] async fn main() -> anyhow::Result<()> { + // Respects RUST_LOG if the shell sets one (e.g. `RUST_LOG=debug cargo run`), + // otherwise defaults to "info" — the level Rig's own completion spans use. + // `with_span_events(CLOSE)` is the part that actually makes anything print: + // Rig records fields (model, token usage, ...) onto the span itself rather + // than emitting log events, so without this, fmt's default event-only + // logging shows nothing even though tracing is "on". + // Logs go to stderr, not stdout — keeps stdout reserved for the actual + // result (the final `println!` below), so it stays pipeable/parseable + // without log lines mixed in. + tracing_subscriber::fmt() + .with_env_filter( + tracing_subscriber::EnvFilter::try_from_default_env() + .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")), + ) + .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE) + .with_writer(std::io::stderr) + .init(); + // Independent setup steps (talk to unrelated backends, no data dependency) — run concurrently. let (gemma, ()) = tokio::try_join!(wire_gemma_client(), server::ensure_running())?; @@ -24,7 +42,8 @@ async fn main() -> anyhow::Result<()> { let result = revise::generate_below_threshold(&gemma, &shieldstral).await?; - println!("Final text (score={:.6}):\n{}", result.score, result.text); + tracing::info!("Final score (score={:.6})", result.score); + tracing::info!("Final text ({})", result.text); Ok(()) } diff --git a/src/revise.rs b/src/revise.rs index 6f1ce8e..2d55e64 100644 --- a/src/revise.rs +++ b/src/revise.rs @@ -88,7 +88,7 @@ pub(crate) async fn generate_below_threshold( for iteration in 0..MAX_REVISION_ITERATIONS { let current_score = score(shieldstral, ¤t_text).await?; - println!("[iteration {iteration}] score={current_score:.6}\n{current_text}\n"); + tracing::info!(iteration, score = current_score, text = %current_text, "revision iteration"); if best.as_ref().is_none_or(|b| current_score < b.score) { best = Some(RevisionAttempt { text: current_text.clone(), score: current_score }); @@ -105,6 +105,10 @@ pub(crate) async fn generate_below_threshold( current_text = generate_text(gemma, &revision_prompt).await?; } - println!("did not converge below {SAFETY_THRESHOLD} after {MAX_REVISION_ITERATIONS} iterations; returning best attempt seen"); + tracing::warn!( + threshold = SAFETY_THRESHOLD, + max_iterations = MAX_REVISION_ITERATIONS, + "did not converge; returning best attempt seen" + ); Ok(best.expect("at least one iteration always runs")) } diff --git a/src/server.rs b/src/server.rs index f3f197d..d057ee4 100644 --- a/src/server.rs +++ b/src/server.rs @@ -43,7 +43,7 @@ pub(crate) async fn ensure_running() -> anyhow::Result<()> { return Ok(()); } - println!("llama-server not running at {base_url}, starting it..."); + tracing::info!(url = %base_url, "llama-server not running, starting it"); Command::new(&SERVER_CONFIG.llama_server.binary) .args([ @@ -58,7 +58,7 @@ pub(crate) async fn ensure_running() -> anyhow::Result<()> { for _ in 0..60 { if is_healthy(&health_url).await { - println!("llama-server is up."); + tracing::info!("llama-server is up"); return Ok(()); } sleep(Duration::from_secs(1)).await;