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.
This commit is contained in:
Austin Schaefer
parent
5843a49cc2
commit
57ca9555b4
5 changed files with 136 additions and 5 deletions
106
Cargo.lock
generated
106
Cargo.lock
generated
|
|
@ -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"
|
||||
|
|
|
|||
|
|
@ -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"] }
|
||||
|
|
|
|||
21
src/main.rs
21
src/main.rs
|
|
@ -17,6 +17,24 @@ static PROMPTS: LazyLock<Prompts> = 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(())
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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"))
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
|
|
|||
Loading…
Reference in a new issue