diff --git a/Cargo.lock b/Cargo.lock index d324764..320c097 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -886,6 +886,15 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d85363c37faeca707aef026efa9f3b34d077bce547e48f770770625c6013679e" +dependencies = [ + "crossbeam-utils", +] + [[package]] name = "crossbeam-queue" version = "0.3.13" @@ -998,6 +1007,12 @@ dependencies = [ "zeroize", ] +[[package]] +name = "deranged" +version = "0.5.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7cd812cc2bc1d69d4764bd80df88b4317eaef9e773c75226407d9bc0876b211c" + [[package]] name = "derivative" version = "2.2.0" @@ -2223,6 +2238,15 @@ dependencies = [ "encoding_rs", ] +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.8.4" @@ -2410,6 +2434,12 @@ dependencies = [ "num-traits", ] +[[package]] +name = "num-conv" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "521739c6d2bac4aa25192232afe6841231376b2b26d4d9fae5ecf8ca5772e441" + [[package]] name = "num-integer" version = "0.1.46" @@ -2667,6 +2697,7 @@ dependencies = [ "tokio-stream", "tonic", "tracing", + "tracing-appender", "tracing-subscriber", "wiremock", "zeroize", @@ -2978,6 +3009,12 @@ dependencies = [ "zerovec", ] +[[package]] +name = "powerfmt" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391" + [[package]] name = "ppv-lite86" version = "0.2.21" @@ -4220,6 +4257,12 @@ version = "2.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" +[[package]] +name = "symlink" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7973cce6668464ea31f176d85b13c7ab3bba2cb3b77a2ed26abd7801688010a" + [[package]] name = "syn" version = "1.0.109" @@ -4346,6 +4389,36 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "time" +version = "0.3.54" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3e1d5e639ff6bab73cb6885cc7e7b1de96c3f32c68ec55f3952614bec1092244" +dependencies = [ + "deranged", + "num-conv", + "powerfmt", + "serde_core", + "time-core", + "time-macros", +] + +[[package]] +name = "time-core" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9e1c906769ad99c88eaa54e728060edef082f8e358ff32030cb7c7d315e81109" + +[[package]] +name = "time-macros" +version = "0.2.32" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7e689342a48d2ea927c87ea50cabf8594854bf940e9310208848d680d668ed85" +dependencies = [ + "num-conv", + "time-core", +] + [[package]] name = "tinystr" version = "0.8.3" @@ -4591,6 +4664,19 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "050686193eb999b4bb3bc2acfa891a13da00f79734704c4b8b4ef1a10b368a3c" +dependencies = [ + "crossbeam-channel", + "symlink", + "thiserror 2.0.19", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.31" @@ -4623,18 +4709,35 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", + "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index b64c612..b045994 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -40,7 +40,8 @@ serde = { version = "1.0", features = ["derive"] } serde_json = "1.0" thiserror = "1.0" tracing = "0.1" -tracing-subscriber = "0.3" +tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] } +tracing-appender = "0.2" sqlx = { version = "0.8", features = ["runtime-tokio", "sqlite"] } ratatui = "0.28" crossterm = { version = "0.28", features = ["event-stream"] } diff --git a/crates/nunciod/Cargo.toml b/crates/nunciod/Cargo.toml index 060404f..fd79f30 100644 --- a/crates/nunciod/Cargo.toml +++ b/crates/nunciod/Cargo.toml @@ -26,7 +26,8 @@ serde.workspace = true serde_json.workspace = true thiserror.workspace = true tracing.workspace = true -tracing-subscriber = "0.3" +tracing-subscriber.workspace = true +tracing-appender.workspace = true tempfile.workspace = true tonic.workspace = true async-trait.workspace = true diff --git a/crates/nunciod/src/lib.rs b/crates/nunciod/src/lib.rs index 8c24ff7..b37803f 100644 --- a/crates/nunciod/src/lib.rs +++ b/crates/nunciod/src/lib.rs @@ -7,6 +7,7 @@ pub mod contacts_sync; pub mod grpc; pub mod lifecycle; pub mod lock; +pub mod logging; pub mod orchestrator; pub mod outbox; pub mod pagination; diff --git a/crates/nunciod/src/logging.rs b/crates/nunciod/src/logging.rs new file mode 100644 index 0000000..6a0aad4 --- /dev/null +++ b/crates/nunciod/src/logging.rs @@ -0,0 +1,323 @@ +//! Layered `tracing` subscriber for `nunciod`. +//! +//! This replaces the previous stderr-only `tracing_subscriber::fmt::init()` +//! bootstrap, which pinned the level at INFO, ignored `RUST_LOG` (the +//! `env-filter` feature was not even enabled), had no file sink, no JSON +//! output, and no way to change levels at runtime -- leaving the daemon +//! effectively unfollowable and unauditable. +//! +//! The subscriber is a layered [`Registry`] with three layers: +//! +//! 1. A reloadable [`EnvFilter`] applied as the global filter, resolved from +//! the environment (see [`resolve_filter_directive`]). It is wrapped in a +//! [`reload::Layer`] so a future control RPC can change verbosity at +//! runtime without a restart; the [`reload::Handle`] is returned from +//! [`init`]. A malformed filter string never panics -- it degrades to the +//! default and a `warn!` is emitted once the subscriber is live. +//! 2. A human-readable console layer to stderr (ANSI, target + span context). +//! 3. A rotating daily file layer under `/logs/`, written through a +//! non-blocking background writer. +//! +//! ## Environment variables +//! +//! * `NUNCIO_LOG` -- filter directive; takes precedence over `RUST_LOG`. +//! * `RUST_LOG` -- filter directive; used when `NUNCIO_LOG` is unset/empty. +//! * (default) -- when neither is set, the filter is [`DEFAULT_FILTER`]. +//! * `NUNCIO_LOG_FORMAT=json` -- emit the *file* sink as JSON. The console +//! sink always stays human-readable (it is for an operator watching a +//! terminal); the file sink is the one a machine parses, so JSON is applied +//! there. Any other value (or unset) keeps the file sink human-readable. +//! +//! ## Worker guard lifetime (CRITICAL) +//! +//! The rotating file layer uses [`tracing_appender::non_blocking`], which +//! hands back a [`WorkerGuard`]. That guard MUST be held for the entire +//! process lifetime: when it drops, the background writer thread is joined and +//! any buffered-but-unflushed log lines are discarded. [`init`] therefore +//! returns it inside [`LoggingGuards`], and `main` binds that value (e.g. +//! `let _guards = ...;`) so it lives until the daemon exits. Dropping it early +//! silently loses file logs. +//! +//! ## Failure handling +//! +//! Logging must never crash the daemon. If the log directory cannot be +//! created, the file layer is skipped and the daemon logs to stderr only +//! (with a `warn!`). If a global subscriber is already installed (e.g. a test +//! harness set one), [`init`] leaves it in place and returns empty guards. + +use std::path::{Path, PathBuf}; + +use tracing_appender::non_blocking::WorkerGuard; +use tracing_subscriber::layer::{Layered, SubscriberExt}; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::{reload, EnvFilter, Layer, Registry}; + +/// Filter directive used when neither `NUNCIO_LOG` nor `RUST_LOG` is set. +pub const DEFAULT_FILTER: &str = "info"; + +/// Environment variable that overrides the log filter, taking precedence over +/// `RUST_LOG`. +pub const LOG_FILTER_ENV_VAR: &str = "NUNCIO_LOG"; + +/// Environment variable that, when equal to `"json"` (case-insensitive), +/// switches the file sink to JSON output. +pub const LOG_FORMAT_ENV_VAR: &str = "NUNCIO_LOG_FORMAT"; + +/// The output encoding of a log sink. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum LogFormat { + /// Human-readable, single-line-per-event text. + Human, + /// One JSON object per event, for machine ingestion. + Json, +} + +/// The base registry with the reloadable [`EnvFilter`] applied. The concrete +/// fmt layers are boxed against this type so the JSON and human variants (and +/// the presence/absence of the file layer) can be chosen at runtime without +/// leaking their differing types into the subscriber's type signature. +type FilteredRegistry = Layered, Registry>; + +/// A type-erased layer compatible with the filtered registry. +type DynLayer = Box + Send + Sync>; + +/// Handle that can swap the global [`EnvFilter`] at runtime. Exposed so a +/// future control RPC can raise or lower verbosity without restarting the +/// daemon. +pub type FilterReloadHandle = reload::Handle; + +/// Guards and handles that must outlive the process. +/// +/// Hold this for the whole daemon lifetime. See the module docs on the +/// [`WorkerGuard`] lifetime requirement. +pub struct LoggingGuards { + reload_handle: Option, + // Kept alive purely for its `Drop`: dropping it flushes and shuts down the + // non-blocking file writer. Never read directly. + _file_guard: Option, +} + +impl LoggingGuards { + /// Returns the runtime filter-reload handle, if the subscriber this crate + /// installed is the active one. `None` means a subscriber was already set + /// by someone else (e.g. a test harness) and this handle would not affect + /// it. + pub fn reload_handle(&self) -> Option<&FilterReloadHandle> { + self.reload_handle.as_ref() + } +} + +/// Resolves the effective filter directive with precedence +/// `NUNCIO_LOG` > `RUST_LOG` > [`DEFAULT_FILTER`]. +/// +/// An env var set to an empty/whitespace-only string is treated as unset so a +/// stray `NUNCIO_LOG=` does not silence all output. +pub fn resolve_filter_directive() -> String { + env_directive(LOG_FILTER_ENV_VAR) + .or_else(|| env_directive("RUST_LOG")) + .unwrap_or_else(|| DEFAULT_FILTER.to_string()) +} + +fn env_directive(var: &str) -> Option { + match std::env::var(var) { + Ok(value) if !value.trim().is_empty() => Some(value), + _ => None, + } +} + +/// Builds an [`EnvFilter`] from `directive`, degrading to [`DEFAULT_FILTER`] +/// on a parse error instead of panicking. +/// +/// The second element is `Some(directive)` when the directive was malformed +/// and the default was substituted, so the caller can emit a `warn!` once the +/// subscriber is live (warning before init would go nowhere). +pub fn build_filter(directive: &str) -> (EnvFilter, Option) { + match EnvFilter::try_new(directive) { + Ok(filter) => (filter, None), + Err(_) => (EnvFilter::new(DEFAULT_FILTER), Some(directive.to_string())), + } +} + +/// Reads the desired file-sink format from [`LOG_FORMAT_ENV_VAR`]. +pub fn log_format_from_env() -> LogFormat { + match std::env::var(LOG_FORMAT_ENV_VAR) { + Ok(value) if value.trim().eq_ignore_ascii_case("json") => LogFormat::Json, + _ => LogFormat::Human, + } +} + +/// Derives the log directory (`/logs/`) from the database path, +/// whose parent is the daemon's data directory. +pub fn log_dir_for_db_path(db_path: &Path) -> PathBuf { + match db_path.parent() { + Some(dir) if !dir.as_os_str().is_empty() => dir.join("logs"), + _ => PathBuf::from("logs"), + } +} + +/// Installs the global layered subscriber and returns the guards that must be +/// held for the process lifetime. +/// +/// `db_path` is the resolved database path; logs are written to a sibling +/// `logs/` directory. This never panics and never returns an error: any +/// problem (unwritable log directory, an already-installed subscriber) is +/// degraded to a lesser-but-working configuration and reported via `warn!`. +pub fn init(db_path: &Path) -> LoggingGuards { + let directive = resolve_filter_directive(); + let (filter, malformed) = build_filter(&directive); + let (filter_layer, reload_handle) = reload::Layer::new(filter); + + let format = log_format_from_env(); + let log_dir = log_dir_for_db_path(db_path); + + // Try to stand up the rotating file sink. A failure to create the log + // directory must not stop the daemon; it just falls back to stderr-only. + let (file_layer, file_guard, file_error) = match std::fs::create_dir_all(&log_dir) { + Ok(()) => { + let appender = tracing_appender::rolling::daily(&log_dir, "nunciod.log"); + let (writer, guard) = tracing_appender::non_blocking(appender); + let layer: DynLayer = match format { + LogFormat::Json => tracing_subscriber::fmt::layer() + .json() + .with_writer(writer) + .with_ansi(false) + .boxed(), + LogFormat::Human => tracing_subscriber::fmt::layer() + .with_writer(writer) + .with_ansi(false) + .boxed(), + }; + (Some(layer), Some(guard), None) + } + Err(err) => (None, None, Some(format!("{}: {err}", log_dir.display()))), + }; + + // Human-readable console sink for an operator watching the terminal. This + // stays text even when the file sink is JSON. + let console_layer: DynLayer = tracing_subscriber::fmt::layer() + .with_writer(std::io::stderr) + .with_ansi(true) + .with_target(true) + .boxed(); + + let mut layers: Vec = vec![console_layer]; + if let Some(layer) = file_layer { + layers.push(layer); + } + + let subscriber = tracing_subscriber::registry() + .with(filter_layer) + .with(layers); + + if subscriber.try_init().is_err() { + // A subscriber is already installed (commonly a test harness). Leave + // it untouched and hand back empty guards; our reload handle would not + // apply to it, so do not expose it. + return LoggingGuards { + reload_handle: None, + _file_guard: None, + }; + } + + if let Some(bad) = malformed { + tracing::warn!( + directive = %bad, + default = %DEFAULT_FILTER, + "ignoring malformed log filter directive; using default" + ); + } + if let Some(err) = file_error { + tracing::warn!(error = %err, "could not open log directory; logging to stderr only"); + } + + LoggingGuards { + reload_handle: Some(reload_handle), + _file_guard: file_guard, + } +} + +#[cfg(test)] +mod tests { + use super::*; + + // The process environment is global mutable state; serialize every test + // that reads or writes the log env vars so they cannot interleave. + static ENV_GUARD: std::sync::Mutex<()> = std::sync::Mutex::new(()); + + fn clear_env() { + std::env::remove_var(LOG_FILTER_ENV_VAR); + std::env::remove_var("RUST_LOG"); + std::env::remove_var(LOG_FORMAT_ENV_VAR); + } + + #[test] + fn nuncio_log_beats_rust_log_beats_default() { + let _guard = ENV_GUARD.lock().unwrap_or_else(|e| e.into_inner()); + clear_env(); + + // Default when neither is set. + assert_eq!(resolve_filter_directive(), DEFAULT_FILTER); + + // RUST_LOG wins over the default. + std::env::set_var("RUST_LOG", "warn"); + assert_eq!(resolve_filter_directive(), "warn"); + + // NUNCIO_LOG wins over RUST_LOG. + std::env::set_var(LOG_FILTER_ENV_VAR, "debug"); + assert_eq!(resolve_filter_directive(), "debug"); + + // An empty NUNCIO_LOG is treated as unset, so RUST_LOG applies again. + std::env::set_var(LOG_FILTER_ENV_VAR, " "); + assert_eq!(resolve_filter_directive(), "warn"); + + clear_env(); + } + + #[test] + fn malformed_filter_falls_back_to_default_without_panicking() { + // A valid directive parses and signals no fallback. + let (_filter, malformed) = build_filter("info,nunciod=debug"); + assert!(malformed.is_none()); + + // A directive with an invalid level degrades to the default and + // reports the offending string, rather than panicking. + let (_filter, malformed) = build_filter("nunciod=not_a_level"); + assert_eq!(malformed.as_deref(), Some("nunciod=not_a_level")); + } + + #[test] + fn json_format_is_selected_only_by_the_json_value() { + let _guard = ENV_GUARD.lock().unwrap_or_else(|e| e.into_inner()); + clear_env(); + + assert_eq!(log_format_from_env(), LogFormat::Human); + + std::env::set_var(LOG_FORMAT_ENV_VAR, "json"); + assert_eq!(log_format_from_env(), LogFormat::Json); + + // Case-insensitive. + std::env::set_var(LOG_FORMAT_ENV_VAR, "JSON"); + assert_eq!(log_format_from_env(), LogFormat::Json); + + // Any other value stays human-readable. + std::env::set_var(LOG_FORMAT_ENV_VAR, "text"); + assert_eq!(log_format_from_env(), LogFormat::Human); + + clear_env(); + } + + #[test] + fn log_dir_is_a_logs_sibling_of_the_database_file() { + let db = PathBuf::from("/var/lib/nuncio/nuncio.db"); + assert_eq!( + log_dir_for_db_path(&db), + PathBuf::from("/var/lib/nuncio/logs") + ); + + // A bare filename (no parent) still yields a usable relative dir. + assert_eq!( + log_dir_for_db_path(Path::new("nuncio.db")), + PathBuf::from("logs") + ); + } +} diff --git a/crates/nunciod/src/main.rs b/crates/nunciod/src/main.rs index f483522..3b9a892 100644 --- a/crates/nunciod/src/main.rs +++ b/crates/nunciod/src/main.rs @@ -17,7 +17,22 @@ const SHUTDOWN_GRACE_PERIOD: Duration = Duration::from_secs(10); #[tokio::main] async fn main() -> Result<(), Box> { - tracing_subscriber::fmt::init(); + // PERSISTENT database path: defaults to `~/.nuncio/nuncio.db` -- NOT a + // temp/ephemeral path -- so accounts (and everything else) survive a + // daemon restart. `NUNCIO_DB_PATH` overrides it, which tests/CI use to + // point at an isolated temp path instead of touching a real user's home + // directory. Resolved first so logging can place its rotating files in the + // sibling `logs/` directory of the same data root. + let db_path = std::env::var("NUNCIO_DB_PATH") + .map(std::path::PathBuf::from) + .unwrap_or_else(|_| nunciod::default_db_path()); + + // Install the layered tracing subscriber (EnvFilter + stderr console + + // rotating daily file sink). `_log_guards` owns the non-blocking writer's + // `WorkerGuard`; it MUST stay bound until the end of `main` or buffered + // file logs are dropped on exit. Logging never crashes the daemon: a bad + // filter or an unwritable log directory degrades to a working subset. + let _log_guards = nunciod::logging::init(&db_path); tracing::info!("Starting Nuncio Central Daemon Service (nunciod)..."); // The `CoreCommand` receiver must be claimed BEFORE the `EventBus` is @@ -37,14 +52,6 @@ async fn main() -> Result<(), Box> { let (shutdown_controller, shutdown_signal) = ShutdownController::new(event_bus.clone()); let shutdown_controller = Arc::new(shutdown_controller); let signal_task = tokio::spawn(install_signal_handlers(shutdown_controller)); - // PERSISTENT database path: defaults to `~/.nuncio/nuncio.db` -- NOT a - // temp/ephemeral path -- so accounts (and everything else) survive a - // daemon restart. - // `NUNCIO_DB_PATH` overrides it, which tests/CI use to point at an - // isolated temp path instead of touching a real user's home directory. - let db_path = std::env::var("NUNCIO_DB_PATH") - .map(std::path::PathBuf::from) - .unwrap_or_else(|_| nunciod::default_db_path()); // Exclusive single-instance lock on the database path, acquired BEFORE // the store is opened. Held for the entire process lifetime (dropped at