path: root/src/logging.rs

//! Logging: a compact fmt logger whose filter can be replaced while the node runs
//! (`/admin/log`), and, with the `tokio-console` feature, a tokio-console layer.
//!
//! The filter starts from `RUST_LOG`, or `info` without it. It applies to the fmt
//! logger only, so the console layer keeps getting the runtime events it needs.
//!
//! Each line is written with members named by their alias (`Renaming`): wherever a
//! member's node ID or one of its addresses appears, in a field, a message or a dump of
//! a value, it reads `<scheme>:<alias>` (`continuum:<alias>` for the node ID,
//! `libp2p:<alias>` for its libp2p peer ID, with its scheme or bare). The names and
//! aliases are as `set_aliases` last gave them (`swarm::topology`, whenever it looks at
//! the member list); at start, as the state file remembers them, so they show from the
//! first line (stale, perhaps: a member's alias that changed meanwhile is logged as such
//! once the member list says so). `--log-raw-ids` leaves IDs as they are.

use std::borrow::Cow;
use std::collections::{BTreeMap, HashMap};
use std::io::Write;
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::{OnceLock, RwLock};

use anyhow::{Result, anyhow};
use tracing_subscriber::fmt::MakeWriter;
use tracing_subscriber::{EnvFilter, Registry, prelude::*, reload};

use crate::locks::RwLockExt;

type FilterHandle = reload::Handle<EnvFilter, Registry>;

static FILTER: OnceLock<FilterHandle> = OnceLock::new();

/// Members' aliases, by the names that stand for them (`set_aliases`), and the
/// replacements made of them, longest first.
static ALIASES: RwLock<Aliases> = RwLock::new(Aliases {
    given: None,
    renames: Vec::new(),
});
/// `--log-raw-ids`.
static RAW_IDS: AtomicBool = AtomicBool::new(false);

struct Aliases {
    given: Option<HashMap<String, String>>,
    renames: Vec<(String, String)>,
}

/// Leave IDs in the log as they are (`--log-raw-ids`).
pub(crate) fn set_raw_ids(raw: bool) {
    RAW_IDS.store(raw, Ordering::Relaxed);
}

/// The aliases to name members by from now on, by the names that stand for them: node
/// IDs and addresses (`<scheme>:<transport identity>`).
pub(crate) fn set_aliases(aliases: HashMap<String, String>) {
    let previous = {
        let mut current = ALIASES.write_or_recover();
        if current.given.as_ref() == Some(&aliases) {
            return;
        }
        current.renames = renames(&aliases);
        current.given.replace(aliases.clone())
    };
    // A member's alias that changed, after the lock: the line itself is renamed.
    let Some(previous) = previous else {
        return;
    };
    for (name, before) in &previous {
        if !crate::identity::is_node_id(name) {
            continue;
        }
        match aliases.get(name) {
            Some(after) if after != before => {
                tracing::info!(peer = %name, previous = %before, "A member's alias changed");
            }
            None => tracing::info!(peer = %name, previous = %before, "A member's alias is gone"),
            _ => {}
        }
    }
}

/// What each name becomes: `<scheme>:<alias>`, for the name with its scheme and bare.
/// Longest first, so that an address is renamed whole before its bare identity could be.
fn renames(aliases: &HashMap<String, String>) -> Vec<(String, String)> {
    let mut renames: BTreeMap<String, String> = BTreeMap::new();
    for (name, alias) in aliases {
        let Some((scheme, identity)) = name.split_once(':') else {
            continue;
        };
        let renamed = format!("{scheme}:{alias}");
        renames.insert(name.clone(), renamed.clone());
        // A node ID's hex alone is no name of it.
        if !crate::identity::is_node_id(name) && !identity.is_empty() {
            renames.entry(identity.to_owned()).or_insert(renamed);
        }
    }
    let mut renames: Vec<(String, String)> = renames.into_iter().collect();
    renames.sort_by(|a, b| b.0.len().cmp(&a.0.len()).then_with(|| a.0.cmp(&b.0)));
    renames
}

/// The aliases `set_aliases` was last given, sorted (for the state file).
pub(crate) fn aliases() -> BTreeMap<String, String> {
    ALIASES
        .read_or_recover()
        .given
        .iter()
        .flatten()
        .map(|(name, alias)| (name.clone(), alias.clone()))
        .collect()
}

/// `line` with members named by their alias (module docs).
fn rename(line: &str) -> Cow<'_, str> {
    if RAW_IDS.load(Ordering::Relaxed) {
        return Cow::Borrowed(line);
    }
    rename_with(line, &ALIASES.read_or_recover().renames)
}

fn rename_with<'a>(line: &'a str, renames: &[(String, String)]) -> Cow<'a, str> {
    let mut renamed = Cow::Borrowed(line);
    for (name, alias) in renames {
        if renamed.contains(name.as_str()) {
            renamed = Cow::Owned(renamed.replace(name.as_str(), alias));
        }
    }
    renamed
}

/// Writes the log to stdout, a line (one event) at a time, renamed (`rename`).
struct Renaming;

impl<'a> MakeWriter<'a> for Renaming {
    type Writer = RenamingLine;

    fn make_writer(&'a self) -> Self::Writer {
        RenamingLine(Vec::new())
    }
}

/// One event's text, written renamed when the logger is done with it.
struct RenamingLine(Vec<u8>);

impl Write for RenamingLine {
    fn write(&mut self, bytes: &[u8]) -> std::io::Result<usize> {
        self.0.extend_from_slice(bytes);
        Ok(bytes.len())
    }

    fn flush(&mut self) -> std::io::Result<()> {
        Ok(())
    }
}

impl Drop for RenamingLine {
    fn drop(&mut self) {
        let text = String::from_utf8_lossy(&self.0);
        let _ = std::io::stdout().write_all(rename(&text).as_bytes());
    }
}

/// Installs the global subscriber. Call once, first thing in main.
pub(crate) fn init() {
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    let (filter, handle) = reload::Layer::new(filter);

    let registry = tracing_subscriber::registry().with(
        tracing_subscriber::fmt::layer()
            .compact()
            .with_writer(Renaming)
            .with_filter(filter),
    );

    #[cfg(feature = "tokio-console")]
    let registry = registry
        .with(console_subscriber::spawn().with_filter(EnvFilter::new("tokio=trace,runtime=trace")));

    registry.init();
    let _ = FILTER.set(handle);
}

/// The filter in effect, in `RUST_LOG` syntax.
pub(crate) fn filter() -> Result<String> {
    handle()?
        .with_current(|filter| filter.to_string())
        .map_err(|error| anyhow!("Reading the log filter: {error}"))
}

/// Replaces the filter. `directives` uses `RUST_LOG` syntax, e.g.
/// `info,continuum::swarm::sync=trace`. An invalid one leaves the old filter in place.
pub(crate) fn set_filter(directives: &str) -> Result<String> {
    let filter = EnvFilter::try_new(directives)
        .map_err(|error| anyhow!("Invalid log filter {directives:?}: {error}"))?;
    let applied = filter.to_string();
    handle()?
        .reload(filter)
        .map_err(|error| anyhow!("Replacing the log filter: {error}"))?;
    Ok(applied)
}

fn handle() -> Result<&'static FilterHandle> {
    FILTER
        .get()
        .ok_or_else(|| anyhow!("Logging is not initialised"))
}

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

    #[test]
    fn members_are_named_by_their_alias() {
        let node = crate::identity::node_id_of(&[1; 32]);
        let renames = renames(&HashMap::from([
            (node.clone(), "kitchen".to_owned()),
            ("libp2p:12D3KooWexample".to_owned(), "kitchen".to_owned()),
            ("tor:abc.onion:9662".to_owned(), "kitchen".to_owned()),
        ]));
        let line = format!(
            "peer={node} to=libp2p:12D3KooWexample event=PeerId(\"12D3KooWexample\") at=abc.onion:9662 other=12D3KooWother"
        );
        assert_eq!(
            rename_with(&line, &renames),
            "peer=continuum:kitchen to=libp2p:kitchen event=PeerId(\"libp2p:kitchen\") at=tor:kitchen other=12D3KooWother"
        );
        // A node ID's hex alone stays.
        let hex = node.split_once(':').unwrap().1;
        assert_eq!(rename_with(hex, &renames), hex);
    }
}