aion_server/observability/

tracing.rs

//! Structured JSON tracing subscriber initialization, and the `log` bridge
//! that carries our dependencies' diagnostics into it.
//!
//! Aion's own code speaks `tracing`. Two of the crates it stands on —
//! haematite most importantly — speak the older `log` facade, and haematite is
//! where the minutes go on a big boot: WAL recovery reports per shard through
//! `log::info!`. Without a bridge those lines reach no logger at all and are
//! dropped on the floor, which is how a store that spent minutes replaying its
//! WAL did it in total silence.
//!
//! So the bridge is installed EXPLICITLY here, before the subscriber, at
//! `Trace` — the `log` facade's own level is deliberately wide open, because
//! this process has exactly one place where log policy is decided (the
//! `AION_LOG`/`RUST_LOG` filter below) and a second gate above it would
//! silently overrule the operator's directive.
//!
//! The subscriber is installed with [`tracing::subscriber::set_global_default`]
//! rather than `try_init`, deliberately: `try_init` installs a `LogTracer` of
//! its own as a side effect, which would collide with the explicit one above
//! and fail the whole initialization. One installer, named, in one place.

use tracing_subscriber::EnvFilter;

use crate::ServerError;

/// Initialize the process-global tracing subscriber for production server
/// output, and bridge the `log` facade into it.
///
/// Events are written as JSON to stdout. `AION_LOG` takes precedence over
/// `RUST_LOG`, and the subscriber falls back to `info` when neither is set.
///
/// # Errors
///
/// Returns [`ServerError`] when the configured filter directive is invalid,
/// when another `log` logger has already been installed, or when another
/// tracing subscriber has already been installed. Both collisions are real
/// double-initialization bugs — a process with two loggers has already lost
/// half its diagnostics — so they are propagated, never swallowed.
pub fn init() -> Result<(), ServerError> {
    let filter = env_filter()?;

    // BEFORE the subscriber: a `log` record emitted between the two
    // installations is better dropped by an absent subscriber than by an
    // absent logger, because only the second kind is invisible to the
    // dependency emitting it.
    tracing_log::LogTracer::init().map_err(|error| ServerError::Config {
        message: format!(
            "failed to install the log-to-tracing bridge: {error}. Another logger is \
             already installed in this process, which means half its diagnostics — \
             haematite's WAL recovery among them — go somewhere this server cannot see"
        ),
    })?;

    let subscriber = tracing_subscriber::fmt()
        .json()
        .with_env_filter(filter)
        .with_current_span(true)
        .with_span_list(true)
        .with_target(true)
        .with_timer(tracing_subscriber::fmt::time::SystemTime)
        .finish();

    tracing::subscriber::set_global_default(subscriber).map_err(|error| ServerError::Config {
        message: format!("failed to initialize tracing subscriber: {error}"),
    })
}

fn env_filter() -> Result<EnvFilter, ServerError> {
    let directive = std::env::var("AION_LOG")
        .or_else(|_| std::env::var("RUST_LOG"))
        .unwrap_or_else(|_| "info".to_owned());

    EnvFilter::try_new(&directive).map_err(|error| ServerError::Config {
        message: format!("invalid log filter `{directive}`: {error}"),
    })
}

#[cfg(test)]
mod tests {
    use std::sync::{Arc, Mutex};

    use tracing_log::{NormalizeEvent as _, log};
    use tracing_subscriber::layer::SubscriberExt as _;

    /// A layer that records the NORMALIZED target of every event it sees.
    ///
    /// Normalization is the load-bearing part. An event the `LogTracer`
    /// forwards wears the static target `"log"` in its raw metadata — the
    /// originating crate's target lives in the normalized metadata, which is
    /// `Some` only for a log-originated event. So recording the normalized
    /// target proves two things at once: the record arrived, and it arrived
    /// THROUGH THE BRIDGE rather than from a `tracing` macro.
    #[derive(Clone, Default)]
    struct TargetRecorder {
        targets: Arc<Mutex<Vec<String>>>,
    }

    impl<S: tracing::Subscriber> tracing_subscriber::Layer<S> for TargetRecorder {
        fn on_event(
            &self,
            event: &tracing::Event<'_>,
            _context: tracing_subscriber::layer::Context<'_, S>,
        ) {
            let Some(normalized) = event.normalized_metadata() else {
                return;
            };
            if let Ok(mut targets) = self.targets.lock() {
                targets.push(normalized.target().to_owned());
            }
        }
    }

    /// The bridge, proven end to end on the ONE channel that matters: a
    /// `log::info!` — the macro haematite's WAL recovery reports through —
    /// must arrive at a tracing subscriber as an event.
    ///
    /// This runs against a locally-scoped subscriber rather than the global
    /// one, because a test process cannot install the global default twice
    /// and the production `init` is not re-entrant. What it therefore proves
    /// is the half that was actually missing: that `LogTracer` is installed
    /// and forwarding. The production wiring above installs the same
    /// `LogTracer` and a global subscriber; nothing else stands between them.
    #[test]
    fn a_log_record_reaches_a_tracing_subscriber_through_the_bridge() {
        // Idempotent by construction: the global logger can only be set once
        // per process, and another test in this binary may have set it first.
        // Either way, what the assertion below needs is that a logger IS
        // installed and forwarding — not that this call is the one that did
        // it, which would make the specimen depend on test ordering.
        let already_installed = tracing_log::LogTracer::init().is_err();
        let recorder = TargetRecorder::default();
        let subscriber = tracing_subscriber::registry().with(recorder.clone());
        tracing::subscriber::with_default(subscriber, || {
            log::info!(target: "haematite::wal::recovery", "wal recovery completed");
        });
        let targets = recorder.targets.lock().map_or_else(
            |poisoned| poisoned.into_inner().clone(),
            |seen| seen.clone(),
        );
        assert!(
            targets
                .iter()
                .any(|target| target == "haematite::wal::recovery"),
            "a `log` record must reach the tracing subscriber through the LogTracer \
             bridge (logger already installed by another test: {already_installed}); \
             saw targets {targets:?}"
        );
    }
}