From 61304664042cc27f745d44d16c92126ef7346e16 Mon Sep 17 00:00:00 2001 From: Chris O'Neil Date: Mon, 14 Sep 2026 14:14:00 +0100 Subject: [PATCH] feat: stamp node_version and node_commit on every json log line Every document in production Elasticsearch carries `tag.node_version = "unknown"`, so the build a node is running cannot be read from telemetry at all. That made the 0.18.1 staged rollout unreadable: fleet-wide `relay recv stream closed` errors rose 6x across the window, which looked like a regression in the build that fixed them, and only splitting by the build each service was actually running (inferred from process start time) showed the new build was ~4x better. The tag is a static Telegraf `[global_tags]` value set at provisioning time and never passed by any caller. Even if it were passed, a provisioning-time string can never be right across an auto-upgrade, so the process itself has to report its build. `WithBuildInfo` wraps the JSON event formatter: it renders the inner event into a thread-local buffer and replaces the closing brace with a compile-time `,"node_version":"","node_commit":""}` tail. Cost is one memcpy per line on top of the serialisation already done. tracing-subscriber's JSON formatter has no hook for constant fields and span fields do not survive `tokio::spawn`, hence the wrapper. Both JSON sinks (stdout and rolling file) use it; the text format and the startup line's `version`/`commit` fields are unchanged, so the beta forwarder in ant-client keeps working. After an auto-upgrade the new process stamps its own constants, so the value is correct on both sides of the restart by construction. Telegraf promotes the fields to tags via `tag_keys` in saorsa-testnet-registry; until that config is re-provisioned the values still land as top-level `node_version` / `node_commit` fields. Test evidence: - 3 new unit tests (fields kept, stamp after a nested `span` object, version is semver) - cargo test: 1088 lib + 16 integration passed, 0 failed - smoke run in development mode: 295/295 stdout lines and 81/81 file-sink lines carried `node_version=0.18.1 node_commit=31fcbae`, 0 invalid JSON; text format byte-identical - clippy clean under both the CLAUDE.md deny set and CI's `--all-targets -D warnings`; `--no-default-features` still builds Closes V2-1153 Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01MYvuVpFYXXNrY9YFVBswvp --- src/bin/ant-node/main.rs | 15 ++- src/logging.rs | 214 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 227 insertions(+), 2 deletions(-) diff --git a/src/bin/ant-node/main.rs b/src/bin/ant-node/main.rs index 6849103d..7ec3d534 100644 --- a/src/bin/ant-node/main.rs +++ b/src/bin/ant-node/main.rs @@ -9,6 +9,8 @@ mod cli; mod platform; use ant_node::config::BootstrapSource; +#[cfg(feature = "logging")] +use ant_node::logging::WithBuildInfo; use ant_node::NodeBuilder; use clap::Parser; use cli::Cli; @@ -19,6 +21,15 @@ use tracing_subscriber::prelude::*; #[cfg(feature = "logging")] use tracing_subscriber::{fmt, EnvFilter, Layer}; +/// JSON event format shared by the stdout and file sinks: flattened event +/// fields, stamped with the running build's `node_version` / `node_commit` +/// on every line so telemetry can attribute each document to the binary +/// that wrote it (see `ant_node::logging::WithBuildInfo`). +#[cfg(feature = "logging")] +fn json_event_format() -> WithBuildInfo> { + WithBuildInfo(fmt::format().json().flatten_event(true)) +} + /// Initialize the tracing subscriber when the `logging` feature is active /// **and** the user passed `--enable-logging`. /// @@ -48,7 +59,7 @@ fn init_logging( } (CliLogFormat::Json, None) => { guard = None; - Box::new(fmt::layer().json().flatten_event(true)) + Box::new(fmt::layer().json().event_format(json_event_format())) } (CliLogFormat::Text, Some(dir)) => { let file_appender = tracing_appender::rolling::Builder::new() @@ -73,7 +84,7 @@ fn init_logging( Box::new( fmt::layer() .json() - .flatten_event(true) + .event_format(json_event_format()) .with_writer(non_blocking) .with_ansi(false), ) diff --git a/src/logging.rs b/src/logging.rs index d3cd9e36..14333e3c 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -111,3 +111,217 @@ impl Level { /// Trace level stub. pub const TRACE: Self = Self; } + +// ---- Build-info stamp for JSON logs ---- + +/// JSON tail spliced onto every event: `,"node_version":"…","node_commit":"…"}`. +/// +/// Both values are compile-time constants of the binary writing the line, so +/// after an auto-upgrade restart the new process stamps its own version with +/// no runtime state involved. Neither value can contain a quote or backslash +/// (Cargo validates the version as semver; the commit is `git rev-parse +/// --short` or the literal `unknown`), so no escaping is needed. +#[cfg(feature = "logging")] +const BUILD_INFO_TAIL: &str = concat!( + ",\"node_version\":\"", + env!("CARGO_PKG_VERSION"), + "\",\"node_commit\":\"", + env!("ANT_GIT_COMMIT"), + "\"}" +); + +/// Event formatter that stamps `node_version` and `node_commit` onto every +/// JSON log line produced by the wrapped formatter. +/// +/// Telemetry needs the running build on *every* document, not just the +/// startup line: a staged rollout is only readable if each log line can be +/// attributed to the build that wrote it. `tracing_subscriber`'s JSON +/// formatter has no hook for constant fields and span fields do not survive +/// `tokio::spawn`, so this wraps the formatter instead: the inner output is +/// rendered into a thread-local buffer, its closing brace is replaced with +/// [`BUILD_INFO_TAIL`], and the result is copied to the real writer. Cost is +/// one memcpy per line on top of the serialisation the inner formatter +/// already does. +/// +/// Only meaningful around a JSON formatter. If the inner output does not end +/// in `}` it is passed through untouched rather than corrupted. +#[cfg(feature = "logging")] +pub struct WithBuildInfo(pub F); + +#[cfg(feature = "logging")] +impl tracing_subscriber::fmt::FormatEvent for WithBuildInfo +where + S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>, + N: for<'a> tracing_subscriber::fmt::FormatFields<'a> + 'static, + F: tracing_subscriber::fmt::FormatEvent, +{ + fn format_event( + &self, + ctx: &tracing_subscriber::fmt::FmtContext<'_, S, N>, + mut writer: tracing_subscriber::fmt::format::Writer<'_>, + event: &tracing::Event<'_>, + ) -> std::fmt::Result { + use std::cell::RefCell; + use tracing_subscriber::fmt::format::Writer; + + thread_local! { + static BUF: RefCell = const { RefCell::new(String::new()) }; + } + + let render = |buf: &mut String| -> std::fmt::Result { + buf.clear(); + self.0.format_event(ctx, Writer::new(buf), event) + }; + + // Re-entrancy (an event emitted while formatting an event) would find + // the buffer already borrowed; fall back to a fresh allocation for that + // one line rather than panic. + let stamped = BUF.with(|cell| { + let mut buf = cell.try_borrow_mut().ok()?; + Some(render(&mut buf).and_then(|()| stamp_build_info(&mut writer, &buf))) + }); + if let Some(result) = stamped { + return result; + } + let mut buf = String::new(); + render(&mut buf)?; + stamp_build_info(&mut writer, &buf) + } +} + +/// Copy `rendered` to `writer`, replacing its closing brace with +/// [`BUILD_INFO_TAIL`]. Output that is not a JSON object is copied verbatim. +#[cfg(feature = "logging")] +fn stamp_build_info( + writer: &mut tracing_subscriber::fmt::format::Writer<'_>, + rendered: &str, +) -> std::fmt::Result { + let body = rendered.trim_end(); + let Some(open) = body.strip_suffix('}') else { + return writer.write_str(rendered); + }; + // An empty object needs no leading comma before the first field. + let tail = if open.ends_with('{') { + &BUILD_INFO_TAIL[1..] + } else { + BUILD_INFO_TAIL + }; + writer.write_str(open)?; + writer.write_str(tail)?; + writer.write_char('\n') +} + +#[cfg(all(test, feature = "logging"))] +#[allow(clippy::unwrap_used, clippy::expect_used, clippy::panic)] +mod tests { + use super::WithBuildInfo; + use std::sync::{Arc, Mutex}; + use tracing_subscriber::fmt; + use tracing_subscriber::fmt::writer::{MakeWriter, MutexGuardWriter}; + use tracing_subscriber::prelude::*; + + /// Shared in-memory sink so the test can read back what the layer wrote. + #[derive(Clone, Default)] + struct Sink(Arc>>); + + impl<'a> MakeWriter<'a> for Sink { + type Writer = MutexGuardWriter<'a, Vec>; + + fn make_writer(&'a self) -> Self::Writer { + self.0.make_writer() + } + } + + /// Run `emit` under a JSON subscriber wrapped in `WithBuildInfo` and + /// return the captured lines parsed as JSON objects. + fn capture( + with_current_span: bool, + emit: impl FnOnce(), + ) -> Vec> { + let sink = Sink::default(); + let layer = fmt::layer() + .json() + .with_writer(sink.clone()) + .event_format(WithBuildInfo( + fmt::format() + .json() + .flatten_event(true) + .with_current_span(with_current_span), + )); + let subscriber = tracing_subscriber::registry().with(layer); + tracing::subscriber::with_default(subscriber, emit); + + let bytes = sink.0.lock().expect("sink poisoned").clone(); + let text = String::from_utf8(bytes).expect("log output is not UTF-8"); + text.lines() + .map(|line| { + serde_json::from_str::(line) + .unwrap_or_else(|e| panic!("line is not valid JSON ({e}): {line}")) + .as_object() + .cloned() + .unwrap_or_else(|| panic!("line is not a JSON object: {line}")) + }) + .collect() + } + + fn assert_stamped(doc: &serde_json::Map) { + assert_eq!( + doc.get("node_version").and_then(|v| v.as_str()), + Some(env!("CARGO_PKG_VERSION")) + ); + assert_eq!( + doc.get("node_commit").and_then(|v| v.as_str()), + Some(env!("ANT_GIT_COMMIT")) + ); + } + + #[test] + fn stamps_every_line_and_keeps_existing_fields() { + let docs = capture(false, || { + tracing::info!(peer = "12D3KooW", count = 3, "first"); + tracing::warn!("second"); + }); + assert_eq!(docs.len(), 2, "one JSON line per event"); + + assert_stamped(&docs[0]); + assert_eq!(docs[0]["message"], "first"); + assert_eq!(docs[0]["level"], "INFO"); + assert_eq!(docs[0]["peer"], "12D3KooW"); + assert_eq!(docs[0]["count"], 3); + assert!(docs[0].contains_key("timestamp")); + assert!(docs[0].contains_key("target")); + + assert_stamped(&docs[1]); + assert_eq!(docs[1]["message"], "second"); + assert_eq!(docs[1]["level"], "WARN"); + } + + #[test] + fn stamps_when_the_last_inner_entry_is_a_nested_object() { + // With `with_current_span`, the JSON formatter ends the object with a + // nested `"span":{...}` entry, so the splice must land after the + // outer brace, not the inner one. + let docs = capture(true, || { + let span = tracing::info_span!("handler", request = 7); + let _guard = span.enter(); + tracing::info!("inside span"); + }); + assert_eq!(docs.len(), 1); + assert_stamped(&docs[0]); + assert_eq!(docs[0]["span"]["name"], "handler"); + assert_eq!(docs[0]["span"]["request"], 7); + } + + #[test] + fn version_matches_the_crate_version() { + // The stamp must be the build's own version — the whole point is that + // a freshly upgraded binary reports itself, not a provisioned string. + let docs = capture(false, || tracing::info!("v")); + let stamped = docs[0]["node_version"].as_str().expect("string"); + assert_eq!(stamped, env!("CARGO_PKG_VERSION")); + assert!( + semver::Version::parse(stamped).is_ok(), + "node_version should be a semver string: {stamped}" + ); + } +}