hyperhive/hive-log/src/lib.rs

//! Log-sink selection for the hyperhive daemons: exactly one sink per
//! process, chosen at startup.
//!
//! Under a systemd unit the process's stdout already *is* the journal, so
//! installing a journald layer on top of the `fmt` layer stores every
//! record twice. There the daemon logs natively instead, which is the
//! only way the journal learns a record's severity: a line written to
//! stdout carries no priority, so the log store files it all as `info`
//! whatever level `tracing` gave it. Off a unit — by hand, or in a test —
//! the ordinary `fmt` stdout layer keeps the output human-readable.
//!
//! systemd sets `JOURNAL_STREAM` to the device and inode numbers of the
//! journal-connected descriptor, in decimal, separated by a colon.
//! Testing that the variable merely exists does not work: a child process
//! inherits it even when its own stdout points somewhere else. So this
//! crate stats the descriptor the `fmt` layer would write to and compares
//! both numbers against the parsed pair.

use std::io;
use std::os::fd::{AsFd, BorrowedFd};

use tracing_subscriber::EnvFilter;
use tracing_subscriber::layer::SubscriberExt as _;
use tracing_subscriber::util::SubscriberInitExt as _;

/// The environment variable systemd sets on a journal-connected stream.
const JOURNAL_STREAM: &str = "JOURNAL_STREAM";

/// Installs the process-wide subscriber with whichever single sink fits
/// the context.
///
/// The filter is the one every caller built before this crate existed:
/// `RUST_LOG` when it parses, `info` otherwise. The `fmt` layer turns ANSI
/// escapes off, because neither sink is a human terminal and journald does
/// not strip escapes, so they reach the log store as raw byte-array spam
/// otherwise.
pub fn init() {
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));

    if !stdout_is_journal() {
        init_fmt(filter);
        return;
    }

    match tracing_journald::layer() {
        Ok(layer) => tracing_subscriber::registry()
            .with(filter)
            .with(layer.with_priority_mappings(priority_mappings()))
            .init(),
        // A process must never fail to start because of its logger, and a
        // logger that silently drops every record is worse than a degraded
        // one. Take the stdout layer and say so, loudly, through it.
        Err(err) => {
            init_fmt(filter);
            tracing::warn!(
                error = %err,
                "journald sink unavailable under a journal-connected stdout; \
                 falling back to the stdout layer, so records reach the log \
                 store without a severity"
            );
        }
    }
}

/// Maps each `tracing` level onto the journal priority of the same name.
///
/// `tracing-journald` defaults to a one-notch shift — `INFO` to `Notice`,
/// `DEBUG` to `Informational` — which would rename every level on the way
/// to the log store. Naming the mappings keeps an `info!` call readable as
/// `info` there, which is the whole point of sending the severity at all.
fn priority_mappings() -> tracing_journald::PriorityMappings {
    use tracing_journald::Priority;

    tracing_journald::PriorityMappings {
        error: Priority::Error,
        warn: Priority::Warning,
        info: Priority::Informational,
        debug: Priority::Debug,
        trace: Priority::Debug,
    }
}

fn init_fmt(filter: EnvFilter) {
    tracing_subscriber::registry()
        .with(filter)
        .with(tracing_subscriber::fmt::layer().with_ansi(false))
        .init();
}

/// Reports whether stdout is the descriptor systemd named in
/// `JOURNAL_STREAM`.
///
/// Stdout, not stderr: the `fmt` layer writes there by default and none of
/// the callers change that, so stdout is the descriptor a second journald
/// layer would double up on.
fn stdout_is_journal() -> bool {
    let raw = std::env::var(JOURNAL_STREAM).ok();
    fd_is_journal_stream(raw.as_deref(), io::stdout().as_fd())
}

/// Parses `dev:inode` out of a `JOURNAL_STREAM` value.
///
/// Returns `None` when the value is absent, carries no colon, or holds a
/// part that is not a decimal number.
fn parse_journal_stream(raw: Option<&str>) -> Option<(u64, u64)> {
    let (dev, inode) = raw?.split_once(':')?;
    Some((dev.parse().ok()?, inode.parse().ok()?))
}

/// Compares a parsed `JOURNAL_STREAM` value against a live descriptor.
///
/// Returns `false` for anything `parse_journal_stream` rejects, for a
/// descriptor that cannot be stated, and — the case presence alone misses
/// — for a well-formed pair naming some *other* descriptor, which is what
/// a child sees once its parent redirected its stdout.
fn fd_is_journal_stream(raw: Option<&str>, fd: BorrowedFd<'_>) -> bool {
    let Some((dev, inode)) = parse_journal_stream(raw) else {
        return false;
    };
    let Ok(stat) = rustix::fs::fstat(fd) else {
        return false;
    };
    stat.st_dev == dev && stat.st_ino == inode
}

#[cfg(test)]
mod tests {
    use super::*;

    /// The `dev:inode` pair systemd would export for this descriptor.
    fn own_stream(fd: BorrowedFd<'_>) -> String {
        let stat = rustix::fs::fstat(fd).expect("fstat of a live descriptor");
        format!("{}:{}", stat.st_dev, stat.st_ino)
    }

    #[test]
    fn unset_variable_is_not_a_journal_stream() {
        let fd = io::stdout();
        assert!(!fd_is_journal_stream(None, fd.as_fd()));
    }

    #[test]
    fn malformed_values_are_not_a_journal_stream() {
        let fd = io::stdout();
        for raw in ["", "12", "8:", ":42", "eight:42", "8:forty-two", "8:42:7"] {
            assert!(
                !fd_is_journal_stream(Some(raw), fd.as_fd()),
                "{raw:?} parsed as a journal stream"
            );
        }
    }

    #[test]
    fn a_well_formed_pair_naming_another_fd_does_not_match() {
        let fd = io::stdout();
        let stat = rustix::fs::fstat(fd.as_fd()).expect("fstat of a live descriptor");
        // What a child inherits after its parent redirected its stdout:
        // the variable is set and parses, and names a descriptor that is
        // no longer this one.
        let other = format!("{}:{}", stat.st_dev, stat.st_ino.wrapping_add(1));
        assert!(!fd_is_journal_stream(Some(&other), fd.as_fd()));

        let other_dev = format!("{}:{}", stat.st_dev.wrapping_add(1), stat.st_ino);
        assert!(!fd_is_journal_stream(Some(&other_dev), fd.as_fd()));
    }

    #[test]
    fn a_pair_naming_this_fd_matches() {
        let fd = io::stdout();
        assert!(fd_is_journal_stream(
            Some(&own_stream(fd.as_fd())),
            fd.as_fd()
        ));
    }

    /// The comparison reads the descriptor handed to it, not descriptor 1:
    /// a pair naming one fd must not match a different one.
    #[test]
    fn the_compared_descriptor_is_the_one_passed_in() {
        let out = io::stdout();
        let err = io::stderr();
        let out_stream = own_stream(out.as_fd());
        let err_stream = own_stream(err.as_fd());
        // Under a harness that gives both streams the same pipe there is
        // nothing to tell apart, so this asserts only when they differ.
        if out_stream != err_stream {
            assert!(!fd_is_journal_stream(Some(&err_stream), out.as_fd()));
            assert!(fd_is_journal_stream(Some(&err_stream), err.as_fd()));
        }
    }

    #[test]
    fn parsing_keeps_both_numbers_in_order() {
        assert_eq!(parse_journal_stream(Some("8:4242")), Some((8, 4242)));
        assert_eq!(parse_journal_stream(Some("0:0")), Some((0, 0)));
        assert_eq!(parse_journal_stream(None), None);
        assert_eq!(parse_journal_stream(Some("no-colon")), None);
    }
}