cellos_core/

observability.rs

//! Operator-facing tracing-subscriber primitives.
//!
//! # HIGH-B5 — redact bearer/Authorization in tracing output
//!
//! `reqwest` (and the surrounding `hyper` / `h2` / `rustls` stack) emit
//! verbose, byte-level diagnostics at TRACE. Those diagnostics include the
//! raw outbound request — and that means `Authorization: Bearer <secret>`,
//! `Cookie:`, `Proxy-Authorization:` and friends land in any log stream
//! whose `RUST_LOG` pulls those targets in at `trace`.
//!
//! `reqwest` does not provide a redaction hook because the offending log
//! calls happen *inside* the crate. The right fix is to attach a filter to
//! the `fmt` layer at the workspace's tracing-init sites so the dangerous
//! events never reach a writer.
//!
//! This module ships that filter. Binaries that initialize the global
//! subscriber compose it onto their existing `fmt` layer:
//!
//! ```ignore
//! use tracing_subscriber::layer::SubscriberExt;
//! use tracing_subscriber::util::SubscriberInitExt;
//!
//! let fmt_layer = tracing_subscriber::fmt::layer()
//!     .with_filter(cellos_core::observability::redacted_filter());
//!
//! tracing_subscriber::registry()
//!     .with(tracing_subscriber::EnvFilter::from_default_env())
//!     .with(fmt_layer)
//!     .init();
//! ```
//!
//! # What the filter drops
//!
//! 1. **HTTP-stack TRACE events.** Any event whose `target` starts with one
//!    of [`HTTP_STACK_TARGETS`] at `Level::TRACE` is suppressed unconditionally.
//!    reqwest's TRACE log lines are not structured — the bearer token is
//!    embedded in a `Debug`-formatted `HeaderMap`, so field-name redaction
//!    cannot reach it. Suppression is the only reliable mitigation.
//!
//! 2. **Sensitive field names anywhere.** Any event whose recorded fields
//!    include a name in [`SENSITIVE_HEADER_NAMES`] (case-insensitive) is
//!    suppressed regardless of target or level. Catches our own code paths
//!    that might accidentally `info!(authorization = %h, ...)`.
//!
//! Operators still see `reqwest=debug` (status codes, request URLs without
//! headers) and every workspace-emitted event at INFO/DEBUG. The escape
//! hatch — `RUST_LOG=reqwest=trace` in production — is closed.
//!
//! Approach C from the wave-1 audit. ADR-0018 (FIX-B4 — credential
//! redaction posture) cross-references this module.

use tracing::field::{Field, Visit};
#[cfg(feature = "tracing-layer")]
use tracing::{Event, Metadata, Subscriber};
#[cfg(feature = "tracing-layer")]
use tracing_subscriber::layer::{Context, Filter};

/// Targets whose TRACE-level events are suppressed wholesale.
///
/// Prefix-matched against `Metadata::target()`. Each entry covers the crate
/// root **and** its child modules (e.g. `"reqwest"` matches
/// `reqwest::connect`, `reqwest::async_impl::client`, …).
///
/// Ordered roughly by likelihood; the linear scan is cheap.
pub const HTTP_STACK_TARGETS: &[&str] = &[
    "reqwest",
    "hyper",
    "hyper_util",
    "hyper_rustls",
    "h2",
    "rustls",
    "tokio_rustls",
    // `tower-http` and `tower` can emit request/response spans whose fields
    // include header maps. Trace-level only — DEBUG and above stay visible.
    "tower_http",
    "tower",
];

/// Header / field names whose presence in *any* event causes the event to be
/// dropped. Case-insensitive match on the field name reported by
/// [`tracing::field::Field::name`].
///
/// Includes both the canonical HTTP header forms (`authorization`,
/// `cookie`, …) and the structured-logging conventions our own code uses
/// (`bearer_token`, `api_key`, …). When in doubt, add — false positives
/// only cost a missing log line.
pub const SENSITIVE_HEADER_NAMES: &[&str] = &[
    // Standard HTTP request/response credential headers.
    "authorization",
    "proxy-authorization",
    "cookie",
    "set-cookie",
    // Vendor-specific bearer carriers (AWS SigV4, Vault, GCP, generic API keys).
    "x-amz-security-token",
    "x-vault-token",
    "x-api-key",
    "x-auth-token",
    "x-csrf-token",
    // Variant spellings we might see when code records header values into
    // events using snake_case field names rather than HTTP-header spelling.
    "authorization_header",
    "bearer_token",
    "access_token",
    "refresh_token",
    "id_token",
    "api_key",
    "session_token",
    "secret",
    "secret_value",
];

/// Build the [`Filter`] that drops events matching the HIGH-B5 policy.
///
/// Wire onto a fmt layer with [`tracing_subscriber::Layer::with_filter`]:
///
/// ```ignore
/// let fmt_layer = tracing_subscriber::fmt::layer()
///     .with_filter(cellos_core::observability::redacted_filter());
/// ```
///
/// Combine with an existing [`tracing_subscriber::EnvFilter`] by stacking
/// the filters in a [`tracing_subscriber::filter::Filtered`] chain — or
/// simpler, attach the env filter to the registry and this filter to the
/// fmt layer (see the module-level example).
///
/// The returned filter is stateless and `Copy`, so it can be cloned
/// freely if multiple fmt layers each need their own copy.
#[cfg(feature = "tracing-layer")]
#[must_use]
pub fn redacted_filter() -> RedactedFilter {
    RedactedFilter::new()
}

/// A [`Filter`] that suppresses TRACE-level HTTP-stack events and any event
/// carrying a sensitive header field name.
///
/// Created via [`redacted_filter`]. Public so downstream code can hold the
/// concrete type when needed (otherwise prefer the constructor).
#[cfg(feature = "tracing-layer")]
#[derive(Debug, Default, Clone, Copy)]
pub struct RedactedFilter {
    _private: (),
}

#[cfg(feature = "tracing-layer")]
impl RedactedFilter {
    /// Construct a fresh filter. Stateless — every instance behaves
    /// identically. Provided as a method primarily so `RedactedFilter::new()`
    /// reads naturally at call sites.
    #[must_use]
    pub fn new() -> Self {
        Self { _private: () }
    }
}

#[cfg(feature = "tracing-layer")]
impl<S> Filter<S> for RedactedFilter
where
    S: Subscriber,
{
    /// Cheap, metadata-only gate. Drops HTTP-stack TRACE without needing to
    /// inspect fields.
    fn enabled(&self, metadata: &Metadata<'_>, _: &Context<'_, S>) -> bool {
        if is_http_stack_trace(metadata) {
            return false;
        }
        true
    }

    /// Field-level gate. Runs only for events `enabled` already approved —
    /// inspects the field names recorded on this specific event and drops
    /// the event if any name matches a sensitive header.
    fn event_enabled(&self, event: &Event<'_>, _: &Context<'_, S>) -> bool {
        if is_http_stack_trace(event.metadata()) {
            return false;
        }
        let mut visitor = SensitiveFieldVisitor::default();
        event.record(&mut visitor);
        !visitor.found_sensitive
    }
}

/// Internal: does this event metadata point at the HTTP stack at TRACE?
#[cfg(feature = "tracing-layer")]
fn is_http_stack_trace(metadata: &Metadata<'_>) -> bool {
    if *metadata.level() != tracing::Level::TRACE {
        return false;
    }
    let target = metadata.target();
    HTTP_STACK_TARGETS.iter().any(|prefix| {
        target == *prefix
            || target
                .strip_prefix(*prefix)
                .is_some_and(|rest| rest.starts_with("::"))
    })
}

/// Tracing `Visit` impl that sets `found_sensitive` if any recorded field
/// name appears in [`SENSITIVE_HEADER_NAMES`] (case-insensitive).
///
/// Public so integration tests in downstream crates can reuse it without
/// re-implementing the lookup. Field *values* are not inspected — once the
/// name matches, the event is dropped wholesale; we never read the secret.
#[derive(Debug, Default)]
pub struct SensitiveFieldVisitor {
    /// Set to `true` the first time a sensitive field name is observed.
    /// Sticky — subsequent non-sensitive fields cannot reset it.
    pub found_sensitive: bool,
}

impl Visit for SensitiveFieldVisitor {
    fn record_debug(&mut self, field: &Field, _value: &dyn std::fmt::Debug) {
        self.check(field);
    }

    fn record_str(&mut self, field: &Field, _value: &str) {
        self.check(field);
    }

    fn record_i64(&mut self, field: &Field, _value: i64) {
        self.check(field);
    }

    fn record_u64(&mut self, field: &Field, _value: u64) {
        self.check(field);
    }

    fn record_bool(&mut self, field: &Field, _value: bool) {
        self.check(field);
    }

    fn record_f64(&mut self, field: &Field, _value: f64) {
        self.check(field);
    }

    fn record_error(&mut self, field: &Field, _value: &(dyn std::error::Error + 'static)) {
        self.check(field);
    }
}

impl SensitiveFieldVisitor {
    fn check(&mut self, field: &Field) {
        if self.found_sensitive {
            return;
        }
        if is_sensitive_field_name(field.name()) {
            self.found_sensitive = true;
        }
    }
}

/// Case-insensitive membership check against [`SENSITIVE_HEADER_NAMES`].
///
/// Free function so downstream code can use the same canonical list when
/// rendering its own logs (e.g. a custom `Display` for an outbound request
/// that elides matching headers before formatting).
#[must_use]
pub fn is_sensitive_field_name(name: &str) -> bool {
    SENSITIVE_HEADER_NAMES
        .iter()
        .any(|candidate| candidate.eq_ignore_ascii_case(name))
}

#[cfg(all(test, feature = "tracing-layer"))]
mod tests {
    use super::*;
    use std::sync::{Arc, Mutex};
    use tracing::Level;
    use tracing_subscriber::fmt::MakeWriter;
    use tracing_subscriber::layer::SubscriberExt;
    use tracing_subscriber::Layer;

    /// `MakeWriter` that buffers everything into a shared `Vec<u8>`. Used by
    /// the integration-shape tests below so we can assert on what the
    /// subscriber actually emitted.
    #[derive(Clone, Default)]
    struct CapturingWriter {
        buf: Arc<Mutex<Vec<u8>>>,
    }

    impl CapturingWriter {
        fn snapshot(&self) -> String {
            let guard = self.buf.lock().unwrap();
            String::from_utf8_lossy(&guard).into_owned()
        }
    }

    impl std::io::Write for CapturingWriter {
        fn write(&mut self, b: &[u8]) -> std::io::Result<usize> {
            self.buf.lock().unwrap().extend_from_slice(b);
            Ok(b.len())
        }
        fn flush(&mut self) -> std::io::Result<()> {
            Ok(())
        }
    }

    impl<'a> MakeWriter<'a> for CapturingWriter {
        type Writer = Self;
        fn make_writer(&'a self) -> Self::Writer {
            self.clone()
        }
    }

    #[test]
    fn sensitive_field_visitor_flags_authorization() {
        // Build a synthetic event by emitting via a private subscriber and
        // capturing the visit. Easier: drive the lookup directly.
        assert!(is_sensitive_field_name("authorization"));
        assert!(is_sensitive_field_name("AUTHORIZATION"));
        assert!(is_sensitive_field_name("Authorization"));
        assert!(is_sensitive_field_name("cookie"));
        assert!(is_sensitive_field_name("x-vault-token"));
        assert!(is_sensitive_field_name("X-Vault-Token"));
        assert!(is_sensitive_field_name("bearer_token"));
    }

    #[test]
    fn sensitive_field_visitor_lets_normal_fields_through() {
        assert!(!is_sensitive_field_name("status"));
        assert!(!is_sensitive_field_name("url"));
        assert!(!is_sensitive_field_name("method"));
        assert!(!is_sensitive_field_name("duration_ms"));
        // Substring matches must NOT trigger — only exact (case-insensitive)
        // name equality. The threat is a field literally named
        // "authorization", not a field named "authorization_method".
        // (If it WAS named "authorization_method" with a Bearer value, that's
        // already a separate bug; we don't try to read field values.)
        assert!(!is_sensitive_field_name("authorize_route"));
        assert!(!is_sensitive_field_name("cookies_accepted"));
    }

    #[test]
    fn http_stack_target_match_is_prefix_aware() {
        // Direct prefix-match assertion — avoids the gymnastics of
        // synthesizing a `tracing::Metadata` (which requires a static
        // callsite) just to drive `is_http_stack_trace` from the outside.
        // The function is private; the prefix logic is what we're testing.
        for tgt in [
            "reqwest",
            "reqwest::connect",
            "reqwest::async_impl::client",
            "hyper",
            "hyper::client::conn",
            "hyper_util::client::legacy::pool",
            "h2::proto::streams::send",
            "rustls::client::tls13",
        ] {
            assert!(
                HTTP_STACK_TARGETS.iter().any(|p| tgt == *p
                    || tgt.strip_prefix(*p).is_some_and(|r| r.starts_with("::"))),
                "expected target {tgt} to match HTTP_STACK_TARGETS"
            );
        }
        // Non-matches.
        for tgt in [
            "reqwesting",        // not a real crate; guards against bare prefix match
            "cellos_supervisor", // workspace code
            "tokio",             // runtime — operator may want trace
            "tracing",           // tracing internals
        ] {
            assert!(
                !HTTP_STACK_TARGETS.iter().any(|p| tgt == *p
                    || tgt.strip_prefix(*p).is_some_and(|r| r.starts_with("::"))),
                "did NOT expect target {tgt} to match HTTP_STACK_TARGETS"
            );
        }
    }

    /// End-to-end: drive a real subscriber with the redacted filter, emit a
    /// synthetic "reqwest-shaped" event carrying a bearer-looking string,
    /// and assert that the captured output contains neither the field name
    /// nor the secret.
    ///
    /// Uses obviously-fake values per gitleaks contract.
    #[test]
    fn integration_drops_event_with_authorization_field() {
        let writer = CapturingWriter::default();
        let fmt_layer = tracing_subscriber::fmt::layer()
            .with_writer(writer.clone())
            .with_target(true)
            .with_filter(RedactedFilter::new());

        let subscriber = tracing_subscriber::registry().with(fmt_layer);

        tracing::subscriber::with_default(subscriber, || {
            // Emitted via tracing::info!: workspace code accidentally
            // recording a header value into a structured event.
            tracing::info!(
                authorization = "Bearer test-bearer-xyzzy-not-real",
                "outbound request"
            );
            // Also test a target NOT in the HTTP stack list — the field
            // name alone should suffice to suppress the event.
            tracing::info!(
                target: "cellos_export_http::client",
                authorization = "Bearer test-bearer-xyzzy-not-real",
                "outbound request"
            );
        });

        let captured = writer.snapshot();
        assert!(
            !captured.contains("xyzzy"),
            "captured tracing output leaked the bearer token: {captured}"
        );
        assert!(
            !captured.contains("Bearer"),
            "captured tracing output leaked the Bearer prefix: {captured}"
        );
        // The whole event should be gone — including the message.
        assert!(
            !captured.contains("outbound request"),
            "expected event to be suppressed entirely; got: {captured}"
        );
    }

    #[test]
    fn integration_passes_non_sensitive_event_through() {
        let writer = CapturingWriter::default();
        let fmt_layer = tracing_subscriber::fmt::layer()
            .with_writer(writer.clone())
            .with_target(true)
            .with_ansi(false) // strip color codes — assertions are substring-based
            .with_filter(RedactedFilter::new());

        let subscriber = tracing_subscriber::registry().with(fmt_layer);

        tracing::subscriber::with_default(subscriber, || {
            tracing::info!(
                target: "cellos_export_http::client",
                status = 200_u64,
                url = "https://example.invalid/health",
                duration_ms = 42_u64,
                "request completed"
            );
        });

        let captured = writer.snapshot();
        assert!(
            captured.contains("request completed"),
            "non-sensitive event was suppressed unexpectedly: {captured}"
        );
        assert!(
            captured.contains("status=200"),
            "non-sensitive structured field missing: {captured}"
        );
    }

    #[test]
    fn integration_drops_reqwest_trace_target() {
        let writer = CapturingWriter::default();
        let fmt_layer = tracing_subscriber::fmt::layer()
            .with_writer(writer.clone())
            .with_target(true)
            .with_filter(RedactedFilter::new());

        // EnvFilter at TRACE so the runtime would normally let everything
        // through; the redacted filter is the line of defense.
        let env_filter = tracing_subscriber::EnvFilter::new("trace");
        let subscriber = tracing_subscriber::registry()
            .with(env_filter)
            .with(fmt_layer);

        tracing::subscriber::with_default(subscriber, || {
            // Simulate reqwest's TRACE log: arbitrary message, no
            // structured fields. The threat is the message body
            // containing the header dump.
            tracing::event!(
                target: "reqwest::async_impl::client",
                Level::TRACE,
                "request headers: Authorization=Bearer test-bearer-xyzzy-not-real"
            );
            // Hyper TRACE event with header value embedded in message.
            tracing::event!(
                target: "hyper::proto::h1::role",
                Level::TRACE,
                "writing header: Authorization: Bearer test-bearer-xyzzy-not-real"
            );
            // h2 TRACE event.
            tracing::event!(
                target: "h2::proto::streams::send",
                Level::TRACE,
                "sending frame: Authorization=Bearer test-bearer-xyzzy-not-real"
            );
            // And one that should NOT be dropped: reqwest at DEBUG.
            tracing::event!(
                target: "reqwest::async_impl::client",
                Level::DEBUG,
                "request completed"
            );
        });

        let captured = writer.snapshot();
        assert!(
            !captured.contains("xyzzy"),
            "reqwest TRACE event leaked secret: {captured}"
        );
        assert!(
            !captured.contains("Bearer"),
            "reqwest TRACE event leaked Bearer prefix: {captured}"
        );
        assert!(
            captured.contains("request completed"),
            "expected reqwest DEBUG event to survive the filter: {captured}"
        );
    }

    #[test]
    fn every_sensitive_name_round_trips_through_the_lookup() {
        // Sweep across the full constant. Catches typos and (importantly)
        // catches any new entry that someone adds in uppercase / mixed case
        // — the constant must stay lowercase for the case-insensitive
        // compare to remain canonical.
        for &name in SENSITIVE_HEADER_NAMES {
            assert!(
                is_sensitive_field_name(name),
                "SENSITIVE_HEADER_NAMES entry {name:?} failed self-lookup"
            );
            // Round-trip uppercase to prove case-insensitivity.
            let upper = name.to_ascii_uppercase();
            assert!(
                is_sensitive_field_name(&upper),
                "SENSITIVE_HEADER_NAMES entry {name:?} failed uppercase lookup"
            );
            // Canonical form is lowercase ASCII — anchor it.
            assert_eq!(
                name,
                name.to_ascii_lowercase(),
                "SENSITIVE_HEADER_NAMES entry {name:?} is not lowercase"
            );
        }
    }
}