//! 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 `:` (`continuum:` for the node ID, //! `libp2p:` 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; static FILTER: OnceLock = OnceLock::new(); /// Members' aliases, by the names that stand for them (`set_aliases`), and the /// replacements made of them, longest first. static ALIASES: RwLock = RwLock::new(Aliases { given: None, renames: Vec::new(), }); /// `--log-raw-ids`. static RAW_IDS: AtomicBool = AtomicBool::new(false); struct Aliases { given: Option>, 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 (`:`). pub(crate) fn set_aliases(aliases: HashMap) { 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: `:`, 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) -> Vec<(String, String)> { let mut renames: BTreeMap = 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 { 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); impl Write for RenamingLine { fn write(&mut self, bytes: &[u8]) -> std::io::Result { 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 { 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 { 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); } }