diff --git a/Cargo.lock b/Cargo.lock index 042c091..0e56aca 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2534,6 +2534,7 @@ dependencies = [ "tokio-stream", "tonic", "tracing", + "tracing-subscriber", ] [[package]] diff --git a/crates/nuncio-cli/Cargo.toml b/crates/nuncio-cli/Cargo.toml index f680cdc..31eb58e 100644 --- a/crates/nuncio-cli/Cargo.toml +++ b/crates/nuncio-cli/Cargo.toml @@ -25,6 +25,7 @@ serde.workspace = true serde_json.workspace = true thiserror.workspace = true tracing.workspace = true +tracing-subscriber.workspace = true rpassword.workspace = true chrono.workspace = true hex.workspace = true diff --git a/crates/nuncio-cli/src/args.rs b/crates/nuncio-cli/src/args.rs index 4994093..b4059af 100644 --- a/crates/nuncio-cli/src/args.rs +++ b/crates/nuncio-cli/src/args.rs @@ -70,14 +70,18 @@ pub struct Cli { #[arg(long, global = true, help = "Target a specific configured account ID")] pub account: Option, - /// Enable verbose log output to stderr. + /// Increase log verbosity on stderr. Repeatable: `-v` = info, `-vv` = + /// debug, `-vvv` = trace. Omitted entirely, the CLI logs only warnings. + /// `NUNCIO_LOG`/`RUST_LOG`, if set, override this (see + /// [`crate::logging`]). #[arg( short, long, global = true, - help = "Enable detailed verbose execution logs on stderr" + action = clap::ArgAction::Count, + help = "Increase log verbosity on stderr (-v info, -vv debug, -vvv trace)" )] - pub verbose: bool, + pub verbose: u8, /// Subcommand resource noun. #[command(subcommand)] @@ -594,7 +598,7 @@ mod tests { fn parse_pure_noun_verb_mail_commands() { let cli_sync = Cli::parse_from(["nuncio", "--json", "--verbose", "mail", "sync"]); assert!(cli_sync.json); - assert!(cli_sync.verbose); + assert_eq!(cli_sync.verbose, 1); assert_eq!( cli_sync.command, Commands::Mail { @@ -602,6 +606,11 @@ mod tests { } ); + // `-v` is repeatable and counts occurrences, mapped to a log level by + // `nuncio_cli::logging::verbosity_directive`. + let cli_vv = Cli::parse_from(["nuncio", "-vv", "mail", "sync"]); + assert_eq!(cli_vv.verbose, 2); + let cli_read = Cli::parse_from(["nuncio", "mail", "read", "--id", "msg-123"]); assert_eq!( cli_read.command, diff --git a/crates/nuncio-cli/src/lib.rs b/crates/nuncio-cli/src/lib.rs index a5b9de4..3b35cac 100644 --- a/crates/nuncio-cli/src/lib.rs +++ b/crates/nuncio-cli/src/lib.rs @@ -3,6 +3,7 @@ #![cfg_attr(test, allow(clippy::unwrap_used, clippy::expect_used, clippy::panic))] pub mod args; +pub mod logging; pub mod output; pub mod runner; diff --git a/crates/nuncio-cli/src/logging.rs b/crates/nuncio-cli/src/logging.rs new file mode 100644 index 0000000..e97dfa7 --- /dev/null +++ b/crates/nuncio-cli/src/logging.rs @@ -0,0 +1,136 @@ +//! CLI-local `tracing` subscriber. +//! +//! This controls `nuncio-cli`'s OWN log output -- it is entirely separate +//! from `nunciod`'s own layered subscriber (`nunciod::logging`), which +//! governs the daemon process the CLI merely talks to over gRPC. The CLI +//! prints its normal command output on stdout regardless of this +//! configuration; this subscriber only ever writes to stderr, so scripts that +//! parse stdout (especially `--json` mode) are never polluted by log lines. +//! +//! ## Verbosity mapping +//! +//! `-v`/`--verbose` is a repeatable flag (`clap`'s `ArgAction::Count`), not a +//! boolean: `nuncio ` with none is quiet (`warn`), `-v` is `info`, `-vv` +//! is `debug`, and `-vvv` or more is `trace`. [`verbosity_directive`] is the +//! pure mapping and is unit-tested directly, without touching the process's +//! single global subscriber slot. +//! +//! ## Environment override +//! +//! `NUNCIO_LOG` (if set and non-blank) wins over `RUST_LOG`, which wins over +//! the `-v` count -- mirroring `nunciod`'s own precedence so the two +//! processes behave consistently for an operator who sets `NUNCIO_LOG` +//! globally. + +use tracing_subscriber::EnvFilter; + +/// Environment variable that overrides the log filter, taking precedence over +/// `RUST_LOG` and the `-v` count. +pub const LOG_FILTER_ENV_VAR: &str = "NUNCIO_LOG"; + +/// Maps a `-v` occurrence count to a filter directive. `0` is the quiet +/// default (`warn`); each additional `-v` steps up one level, capping at +/// `trace`. +#[must_use] +pub fn verbosity_directive(verbosity: u8) -> &'static str { + match verbosity { + 0 => "warn", + 1 => "info", + 2 => "debug", + _ => "trace", + } +} + +/// Resolves the effective filter directive with precedence `NUNCIO_LOG` > +/// `RUST_LOG` > the `-v` count (via [`verbosity_directive`]). +/// +/// An env var set to an empty/whitespace-only string is treated as unset so a +/// stray `NUNCIO_LOG=` does not silently override an explicit `-v`. +#[must_use] +pub fn resolve_filter_directive(verbosity: u8) -> String { + env_directive(LOG_FILTER_ENV_VAR) + .or_else(|| env_directive("RUST_LOG")) + .unwrap_or_else(|| verbosity_directive(verbosity).to_string()) +} + +fn env_directive(var: &str) -> Option { + match std::env::var(var) { + Ok(value) if !value.trim().is_empty() => Some(value), + _ => None, + } +} + +/// Installs a stderr-only `tracing` subscriber for the CLI process, driven by +/// [`resolve_filter_directive`]. +/// +/// Never panics: a malformed filter directive (from a hand-edited +/// `NUNCIO_LOG`/`RUST_LOG`) degrades to the `-v`-derived default rather than +/// crashing the CLI before it can even report an error. Idempotent -- if a +/// subscriber is already installed (e.g. a test harness), this is a silent +/// no-op rather than a panic, since `nuncio-cli`'s own tests run many +/// commands in the same process. +pub fn init(verbosity: u8) { + let directive = resolve_filter_directive(verbosity); + let filter = EnvFilter::try_new(&directive) + .unwrap_or_else(|_| EnvFilter::new(verbosity_directive(verbosity))); + let _ = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(std::io::stderr) + .try_init(); +} + +#[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"); + } + + #[test] + fn verbosity_count_maps_to_expected_level() { + assert_eq!(verbosity_directive(0), "warn"); + assert_eq!(verbosity_directive(1), "info"); + assert_eq!(verbosity_directive(2), "debug"); + assert_eq!(verbosity_directive(3), "trace"); + // Anything beyond -vvv still caps at trace rather than erroring. + assert_eq!(verbosity_directive(255), "trace"); + } + + #[test] + fn nuncio_log_beats_rust_log_beats_verbosity_count() { + let _guard = ENV_GUARD.lock().unwrap_or_else(|e| e.into_inner()); + clear_env(); + + // No env override: falls back to the -v count mapping. + assert_eq!(resolve_filter_directive(0), "warn"); + assert_eq!(resolve_filter_directive(2), "debug"); + + // RUST_LOG wins over the -v count. + std::env::set_var("RUST_LOG", "nuncio_cli=warn"); + assert_eq!(resolve_filter_directive(2), "nuncio_cli=warn"); + + // NUNCIO_LOG wins over RUST_LOG. + std::env::set_var(LOG_FILTER_ENV_VAR, "nuncio_cli=trace"); + assert_eq!(resolve_filter_directive(0), "nuncio_cli=trace"); + + // 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(0), "nuncio_cli=warn"); + + clear_env(); + } + + #[test] + fn init_never_panics_even_when_a_subscriber_is_already_installed() { + // Calling init() twice must not panic: the second call finds the + // global subscriber slot occupied and silently no-ops. + init(1); + init(1); + } +} diff --git a/crates/nuncio-cli/src/main.rs b/crates/nuncio-cli/src/main.rs index cf58f64..15d87e7 100644 --- a/crates/nuncio-cli/src/main.rs +++ b/crates/nuncio-cli/src/main.rs @@ -1,10 +1,16 @@ use clap::Parser; -use nuncio_cli::{args::Cli, AccountSubcommand, Commands, HeadlessRunner, PasswordArg}; +use nuncio_cli::{args::Cli, logging, AccountSubcommand, Commands, HeadlessRunner, PasswordArg}; #[tokio::main] async fn main() -> Result<(), Box> { let mut cli = Cli::parse(); + // Wire the CLI's own `-v`/`-vv`/`-vvv` flag (or `NUNCIO_LOG`/`RUST_LOG`) + // to a real stderr subscriber before anything else runs, so every RPC + // this process makes is followable. This is the CLI's own log stream -- + // entirely separate from the daemon's file-based logging. + logging::init(cli.verbose); + // `account add`'s password is deliberately never a Clap-parsed CLI // flag (see `PasswordArg`'s doc comment): read it here, interactively // and without echo, immediately after parsing argv and before any diff --git a/crates/nuncio-cli/src/output.rs b/crates/nuncio-cli/src/output.rs index 7281ea5..789b311 100644 --- a/crates/nuncio-cli/src/output.rs +++ b/crates/nuncio-cli/src/output.rs @@ -1,5 +1,7 @@ //! Standardized JSON machine-readable output formatters for Unix scripting. +use std::collections::BTreeMap; + use serde::Serialize; /// Standardized JSON response envelope for CLI machine output. @@ -13,6 +15,18 @@ pub struct JsonResponse { /// Error message string (present if status is "error"). #[serde(skip_serializing_if = "Option::is_none")] pub error: Option, + /// The gRPC status code name (e.g. `"NotFound"`), when the error came + /// from a daemon RPC. + #[serde(skip_serializing_if = "Option::is_none")] + pub code: Option, + /// The typed `nuncio.v1.ErrorReason` name (e.g. `"ACCOUNT_NOT_FOUND"`), + /// decoded from the daemon's `ErrorInfo` status details, when present. + #[serde(skip_serializing_if = "Option::is_none")] + pub reason: Option, + /// Structured error context (e.g. `{"account_id": "acct-1"}`) carried in + /// the daemon's `ErrorInfo`, when present and non-empty. + #[serde(skip_serializing_if = "Option::is_none")] + pub metadata: Option>, } impl JsonResponse { @@ -22,17 +36,47 @@ impl JsonResponse { status: "ok", data: Some(data), error: None, + code: None, + reason: None, + metadata: None, } } } impl JsonResponse<()> { - /// Construct an error JSON response wrapping an error string. + /// Construct an error JSON response wrapping an error string, with no + /// typed gRPC code/reason/metadata (e.g. a purely client-side failure + /// such as an unreachable daemon). pub fn error(message: &str) -> Self { Self { status: "error", data: None, error: Some(message.to_string()), + code: None, + reason: None, + metadata: None, + } + } + + /// Construct an error JSON response carrying the gRPC code and, when the + /// daemon attached a WS-A1 `ErrorInfo`, the typed reason and metadata. + pub fn error_with_info( + message: &str, + code: Option, + reason: Option, + metadata: BTreeMap, + ) -> Self { + Self { + status: "error", + data: None, + error: Some(message.to_string()), + code, + reason, + metadata: if metadata.is_empty() { + None + } else { + Some(metadata) + }, } } } @@ -51,6 +95,20 @@ pub fn format_json_error(message: &str) -> String { .unwrap_or_else(|_| r#"{"status":"error","error":"JSON serialization failed"}"#.to_string()) } +/// Serialize a typed daemon RPC error (gRPC code, optional `ErrorReason` +/// name, and optional metadata) to a formatted JSON string. See +/// [`JsonResponse::error_with_info`]. +pub fn format_json_error_with_info( + message: &str, + code: Option, + reason: Option, + metadata: BTreeMap, +) -> String { + let response = JsonResponse::error_with_info(message, code, reason, metadata); + serde_json::to_string(&response) + .unwrap_or_else(|_| r#"{"status":"error","error":"JSON serialization failed"}"#.to_string()) +} + /// Print ANSI color ASCII art splash banner for CLI startup. pub fn print_splash_banner() { let banner = get_splash_banner_text(); @@ -94,6 +152,42 @@ mod tests { let err_str = format_json_error("account not found"); assert!(err_str.contains(r#""status":"error""#)); assert!(err_str.contains(r#""error":"account not found""#)); + // A plain error carries no typed code/reason/metadata. + assert!(!err_str.contains("\"code\"")); + assert!(!err_str.contains("\"reason\"")); + assert!(!err_str.contains("\"metadata\"")); + } + + #[test] + fn format_json_error_with_info_carries_code_reason_and_metadata() { + let mut metadata = BTreeMap::new(); + metadata.insert("account_id".to_string(), "acct-1".to_string()); + + let out = format_json_error_with_info( + "nunciod daemon rejected account_show: account 'acct-1' not found", + Some("NotFound".to_string()), + Some("ACCOUNT_NOT_FOUND".to_string()), + metadata, + ); + assert!(out.contains(r#""status":"error""#)); + assert!(out.contains(r#""code":"NotFound""#)); + assert!(out.contains(r#""reason":"ACCOUNT_NOT_FOUND""#)); + assert!(out.contains(r#""account_id":"acct-1""#)); + } + + #[test] + fn format_json_error_with_info_omits_reason_and_metadata_when_absent() { + // Falls back cleanly when the status carried no typed `ErrorInfo`: + // still structured (code present), but no fabricated reason/metadata. + let out = format_json_error_with_info( + "daemon unreachable", + Some("Unavailable".to_string()), + None, + BTreeMap::new(), + ); + assert!(out.contains(r#""code":"Unavailable""#)); + assert!(!out.contains("\"reason\"")); + assert!(!out.contains("\"metadata\"")); } #[test] diff --git a/crates/nuncio-cli/src/runner.rs b/crates/nuncio-cli/src/runner.rs index a74ef3a..4512f84 100644 --- a/crates/nuncio-cli/src/runner.rs +++ b/crates/nuncio-cli/src/runner.rs @@ -12,7 +12,7 @@ use crate::args::{ FilterSubcommand, FolderSubcommand, MailSubcommand, SystemSubcommand, UpdateSubcommand, }; -use crate::output::{format_json, format_json_error}; +use crate::output::{format_json, format_json_error, format_json_error_with_info}; /// Parses a `--imap-mode`/`--smtp-mode` CLI string into `nuncio_core::TlsMode`. /// Rejects anything else rather than silently defaulting, since silently @@ -777,13 +777,7 @@ impl HeadlessRunner { format!("Synchronization complete: {synced_count} message(s) synced") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected sync: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("sync", &status, json_mode), } } @@ -820,13 +814,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_messages: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_messages", &status, json_mode); } } } @@ -892,13 +880,7 @@ impl HeadlessRunner { ) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected send_message: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("send_message", &status, json_mode), } } @@ -932,13 +914,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected search_messages: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("search_messages", &status, json_mode); } } } @@ -991,13 +967,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_folders: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_folders", &status, json_mode); } } } @@ -1055,13 +1025,7 @@ impl HeadlessRunner { Err(status) if status.code() == tonic::Code::NotFound => { Self::render_error(&format!("message '{}' not found", id), json_mode) } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected get_message: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("get_message", &status, json_mode), } } @@ -1111,13 +1075,7 @@ impl HeadlessRunner { Err(status) if status.code() == tonic::Code::NotFound => { Self::render_error(&format!("message '{}' not found", id), json_mode) } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected mark_read: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("mark_read", &status, json_mode), } } @@ -1181,13 +1139,7 @@ impl HeadlessRunner { ) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected export_mailbox: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("export_mailbox", &status, json_mode), } } @@ -1238,13 +1190,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_records: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_records", &status, json_mode); } } } @@ -1305,13 +1251,7 @@ impl HeadlessRunner { ) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected verify_chain: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("verify_chain", &status, json_mode), } } @@ -1363,13 +1303,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_rules: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_rules", &status, json_mode); } } } @@ -1431,16 +1365,7 @@ impl HeadlessRunner { json_mode, ), }, - Err(status) if status.code() == tonic::Code::InvalidArgument => { - Self::render_error(status.message(), json_mode) - } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected create_rule: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("create_rule", &status, json_mode), } } @@ -1467,13 +1392,7 @@ impl HeadlessRunner { format!("✓ Filter rule '{}' deleted.", id) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected delete_rule: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("delete_rule", &status, json_mode), } } @@ -1505,13 +1424,7 @@ impl HeadlessRunner { format!("Validation Error: {}", response.error) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected validate_rule: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("validate_rule", &status, json_mode), } } @@ -1560,16 +1473,7 @@ impl HeadlessRunner { ) } } - Err(status) if status.code() == tonic::Code::InvalidArgument => { - Self::render_error(status.message(), json_mode) - } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected preview_rule: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("preview_rule", &status, json_mode), } } @@ -1612,19 +1516,7 @@ impl HeadlessRunner { json_mode, ), }, - Err(status) - if status.code() == tonic::Code::InvalidArgument - || status.code() == tonic::Code::NotFound => - { - Self::render_error(status.message(), json_mode) - } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected update_rule: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("update_rule", &status, json_mode), } } @@ -1657,13 +1549,7 @@ impl HeadlessRunner { content } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected export_rules: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("export_rules", &status, json_mode), } } @@ -1711,13 +1597,7 @@ impl HeadlessRunner { out } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected import_rules: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("import_rules", &status, json_mode), } } @@ -1762,13 +1642,7 @@ impl HeadlessRunner { out } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected get_execution_logs: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("get_execution_logs", &status, json_mode), } } @@ -1796,15 +1670,7 @@ impl HeadlessRunner { .await { Ok(response) => response.into_inner(), - Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected triage: {}", - Self::clean_status_message(&status) - ), - json_mode, - ) - } + Err(status) => return Self::render_status_error("triage", &status, json_mode), }; let mut updates = Vec::new(); @@ -1829,13 +1695,7 @@ impl HeadlessRunner { } Ok(None) => break, Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon triage stream failed: {}", - Self::clean_status_message(&status) - ), - json_mode, - ) + return Self::render_status_error("triage stream", &status, json_mode) } } } @@ -2041,13 +1901,7 @@ impl HeadlessRunner { ) } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected add_account: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("add_account", &status, json_mode), } } @@ -2101,13 +1955,7 @@ impl HeadlessRunner { out } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected list_accounts: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("list_accounts", &status, json_mode), } } @@ -2124,12 +1972,7 @@ impl HeadlessRunner { let accounts = client .list_accounts(nuncio_proto::v1::ListAccountsRequest {}) .await - .map_err(|status| { - format!( - "nunciod daemon rejected list_accounts: {}", - Self::clean_status_message(&status) - ) - })? + .map_err(|status| Self::describe_status_error("list_accounts", &status))? .into_inner() .accounts; accounts @@ -2262,13 +2105,7 @@ impl HeadlessRunner { format!("Account '{id}' updated via nunciod daemon.") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected update_account: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("update_account", &status, json_mode), } } @@ -2295,13 +2132,7 @@ impl HeadlessRunner { format!("Account '{id}' removed via nunciod daemon.") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected remove_account: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("remove_account", &status, json_mode), } } @@ -2352,13 +2183,7 @@ impl HeadlessRunner { format!("Connection test for '{id}'\n {imap}\n {smtp}") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected test_account_connection: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("test_account_connection", &status, json_mode), } } @@ -2455,13 +2280,7 @@ impl HeadlessRunner { page_token = page.next_page_token; } Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_events: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_events", &status, json_mode); } } } @@ -2517,13 +2336,7 @@ impl HeadlessRunner { format!("Calendar synchronization complete: {synced_count} event(s) synced") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected calendar sync: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("calendar sync", &status, json_mode), } } @@ -2557,13 +2370,7 @@ impl HeadlessRunner { let contacts = match self.fetch_all_contacts(&mut client, account).await { Ok(contacts) => contacts, Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_contacts: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_contacts", &status, json_mode); } }; @@ -2620,13 +2427,7 @@ impl HeadlessRunner { let contacts = match self.fetch_all_contacts(&mut client, account).await { Ok(contacts) => contacts, Err(status) => { - return Self::render_error( - &format!( - "nunciod daemon rejected list_contacts: {}", - Self::clean_status_message(&status) - ), - json_mode, - ); + return Self::render_status_error("list_contacts", &status, json_mode); } }; @@ -2702,13 +2503,7 @@ impl HeadlessRunner { json_mode, ), }, - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected create_contact: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("create_contact", &status, json_mode), } } @@ -2739,13 +2534,7 @@ impl HeadlessRunner { format!("Contacts synchronization complete: {synced_count} contact(s) synced") } } - Err(status) => Self::render_error( - &format!( - "nunciod daemon rejected contacts sync: {}", - Self::clean_status_message(&status) - ), - json_mode, - ), + Err(status) => Self::render_status_error("contacts sync", &status, json_mode), } } @@ -2775,6 +2564,64 @@ impl HeadlessRunner { } } + /// Strips the `ERROR_REASON_` prefix off a decoded [`v1::ErrorReason`]'s + /// generated `as_str_name()`, so the CLI renders the short, readable form + /// (`ACCOUNT_NOT_FOUND`) rather than the wire enum's full name. + fn reason_name(reason: nuncio_proto::v1::ErrorReason) -> String { + reason + .as_str_name() + .trim_start_matches("ERROR_REASON_") + .to_string() + } + + /// Builds the full human-readable text for a failed daemon RPC: the + /// server-provided message, the gRPC status code, and -- when the daemon + /// attached a WS-A1 [`nuncio_proto::v1::ErrorInfo`] to the status details + /// -- the typed [`nuncio_proto::v1::ErrorReason`]. Falls back to just the + /// code when no typed details are present (e.g. a status raised by a + /// library this client talks to that predates `ErrorInfo`). + fn describe_status_error(context: &str, status: &tonic::Status) -> String { + let message = Self::clean_status_message(status); + let code = status.code(); + match nuncio_proto::errors::error_reason(status) { + Some(reason) => format!( + "nunciod daemon rejected {context}: {message} (code: {code:?}, reason: {})", + Self::reason_name(reason) + ), + None => format!("nunciod daemon rejected {context}: {message} (code: {code:?})"), + } + } + + /// Renders a failed daemon RPC for both text and `--json` output modes, + /// decoding the WS-A1 `ErrorInfo` from the status details when present. + /// + /// Text mode gets the human message, the gRPC code, and the typed reason + /// (see [`Self::describe_status_error`]). JSON mode gets a coherent + /// `{error, code, reason, metadata}` shape via + /// [`format_json_error_with_info`] -- `reason`/`metadata` are omitted + /// (rather than fabricated) when the status carried no typed + /// `ErrorInfo`, so a caller can tell "no reason given" apart from an + /// actual reason. + fn render_status_error(context: &str, status: &tonic::Status, json_mode: bool) -> String { + if json_mode { + let info = nuncio_proto::errors::error_info(status); + let message = format!( + "nunciod daemon rejected {context}: {}", + Self::clean_status_message(status) + ); + let reason = info.as_ref().map(|i| Self::reason_name(i.reason())); + let metadata = info.map(|i| i.metadata).unwrap_or_default(); + format_json_error_with_info( + &message, + Some(format!("{:?}", status.code())), + reason, + metadata.into_iter().collect(), + ) + } else { + format!("Error: {}", Self::describe_status_error(context, status)) + } + } + /// `system status`: a real thin gRPC client of the running `nunciod` /// daemon's `nuncio.v1.System` API. /// @@ -3853,6 +3700,132 @@ mod tests { assert!(!out.contains("status:")); } + /// Proves the CLI decodes a WS-A1 `ErrorInfo` from a daemon RPC's status + /// details and renders the human message, the gRPC code, and the typed + /// reason -- in both text and `--json` mode -- instead of dropping the + /// code or the reason the daemon went to the trouble of attaching. + #[tokio::test] + async fn typed_error_info_renders_code_reason_and_metadata_in_text_and_json() { + use nuncio_proto::v1::mail_server::{Mail as MailService, MailServer}; + use nuncio_proto::v1::ErrorReason; + use nuncio_proto::v1::{ + GetMessageRequest, GetMessageResponse, ListFoldersRequest, ListFoldersResponse, + ListMessagesRequest, ListMessagesResponse, MarkReadRequest, MarkReadResponse, + SearchMessagesRequest, SearchMessagesResponse, SendMessageRequest, SendMessageResponse, + SyncRequest, SyncResponse, + }; + + /// Minimal test-only stub of `nuncio.v1.Mail` whose `ListFolders` + /// always fails with a typed `ErrorInfo` (account-not-found), so this + /// test can assert on exactly how the CLI decodes and renders it. + struct StubMailTypedError; + + #[tonic::async_trait] + impl MailService for StubMailTypedError { + async fn list_folders( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(nuncio_proto::errors::status_with_metadata( + ErrorReason::AccountNotFound, + "account 'acct-missing' not found", + [("account_id".to_string(), "acct-missing".to_string())], + )) + } + + async fn list_messages( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + + async fn get_message( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + + async fn mark_read( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + + async fn search_messages( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + + async fn send_message( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + + async fn sync( + &self, + _request: tonic::Request, + ) -> Result, tonic::Status> { + Err(tonic::Status::internal("unused in this test")) + } + } + + let listener = tokio::net::TcpListener::bind("127.0.0.1:0") + .await + .expect("bind ephemeral loopback port"); + let addr = listener.local_addr().expect("listener has local addr"); + tokio::spawn(async move { + let _ = tonic::transport::Server::builder() + .add_service(MailServer::new(StubMailTypedError)) + .serve_with_incoming(tokio_stream::wrappers::TcpListenerStream::new(listener)) + .await; + }); + + let runner = + HeadlessRunner::ephemeral_with(Arc::new(SecretManager::mock()), addr.to_string()) + .await + .expect("ephemeral runner initializes"); + + // Text mode: human message, gRPC code, and the typed reason -- not a + // raw status dump, and not silently dropping the code/reason. + let text_out = runner + .execute_command( + &Commands::Folder { + action: FolderSubcommand::List, + }, + false, + ) + .await; + assert!(text_out.contains("account 'acct-missing' not found")); + assert!(text_out.contains("code: NotFound")); + assert!(text_out.contains("reason: ACCOUNT_NOT_FOUND")); + + // JSON mode: a coherent {error, code, reason, metadata} shape. + let json_out = runner + .execute_command( + &Commands::Folder { + action: FolderSubcommand::List, + }, + true, + ) + .await; + let parsed: serde_json::Value = serde_json::from_str(&json_out).expect("valid JSON output"); + assert_eq!(parsed["status"], "error"); + assert!(parsed["error"] + .as_str() + .expect("error is a string") + .contains("account 'acct-missing' not found")); + assert_eq!(parsed["code"], "NotFound"); + assert_eq!(parsed["reason"], "ACCOUNT_NOT_FOUND"); + assert_eq!(parsed["metadata"]["account_id"], "acct-missing"); + } + /// Reference-client proof: boots a stub `nuncio.v1.Calendar` gRPC server /// (mirroring the `Mail` stub pattern above) and drives the real /// `HeadlessRunner`'s `cal list`/`cal sync` gRPC client paths against it. diff --git a/docs/RUNNING.md b/docs/RUNNING.md index b8b9dfc..481523d 100644 --- a/docs/RUNNING.md +++ b/docs/RUNNING.md @@ -69,6 +69,90 @@ nuncio-cli.exe folder list Add `--json` to any command for machine-readable output. `nuncio-cli.exe --help` lists every verb and flag. +## Following & auditing the daemon + +`nunciod` runs a layered `tracing` subscriber (`crates/nunciod/src/logging.rs`); +`nuncio-cli` runs its own, separate, stderr-only subscriber for its own logs. +Neither ever writes a bearer token or an account password to a log line. + +### Daemon log levels + +`nunciod`'s console (stderr) and rotating file sinks share one filter, +resolved once at startup with this precedence: + +1. **`NUNCIO_LOG`** — a `tracing-subscriber` `EnvFilter` directive (e.g. + `info`, `debug`, `nunciod=debug,tower=warn`). Wins over `RUST_LOG` if set + to a non-blank value. +2. **`RUST_LOG`** — same directive syntax; used when `NUNCIO_LOG` is + unset/blank. +3. Default: `info`. + +A malformed directive never crashes the daemon — it falls back to the +default and logs a `warn!` once the subscriber is live. + +``` +:: run the daemon at debug level for one session +set NUNCIO_LOG=debug +target\release\nunciod.exe +``` + +### Log file location + +The rotating file sink writes daily-rotated files next to the database, under +a `logs/` sibling directory: `\logs\nunciod.log.` (e.g. +`%USERPROFILE%\.nuncio\logs\nunciod.log.2026-07-30`). If the log directory +cannot be created, the daemon degrades to stderr-only logging (with a +`warn!`) rather than failing to start. + +### JSON log output + +Set `NUNCIO_LOG_FORMAT=json` to switch the **file** sink to one JSON object +per line, for machine ingestion (e.g. shipping to a log aggregator). The +console sink always stays human-readable, since it's for an operator watching +a terminal. Any other value (or unset) keeps the file sink human-readable too. + +### Correlating one request's logs (`request_id`) + +Every gRPC call `nunciod` handles opens a root tracing span carrying a +per-process `request_id` (`-`), the RPC method +path, and the peer address; every log line emitted while that call is +handled — auth accept/reject, handler-level events, the terminal +`gRPC request completed` line with status + elapsed time — inherits it. To +follow one request end-to-end, grep the daemon log for its `request_id`: + +``` +:: human-readable file sink +findstr "a1b2c3d4e5f6-00000017" "%USERPROFILE%\.nuncio\logs\nunciod.log.2026-07-30" + +:: JSON file sink (NUNCIO_LOG_FORMAT=json), pick a request_id from the +:: completion line's fields, then filter every line for it: +findstr "\"request_id\":\"a1b2c3d4e5f6-00000017\"" "%USERPROFILE%\.nuncio\logs\nunciod.log.2026-07-30" +``` + +(On macOS/Linux, use `grep` in place of `findstr`.) There is currently no way +to read a request's `request_id` back from the CLI's own output — it is +visible only in the daemon's logs, since it is a server-side correlation +identifier assigned when the RPC arrives. + +### CLI verbosity (`-v`/`-vv`/`-vvv`) + +`nuncio-cli` logs to stderr only — command output (including `--json` +payloads) always goes to stdout, so redirecting or piping stdout is never +polluted by log lines. By default the CLI logs only warnings. Repeat `-v` to +raise the level: + +``` +nuncio-cli.exe mail sync :: warn only (default) +nuncio-cli.exe -v mail sync :: info +nuncio-cli.exe -vv mail sync :: debug +nuncio-cli.exe -vvv mail sync :: trace +``` + +`NUNCIO_LOG`/`RUST_LOG`, if set (same precedence as the daemon: `NUNCIO_LOG` +beats `RUST_LOG`), override the `-v` count entirely — useful for scoping a +directive to a specific module (e.g. `NUNCIO_LOG=nuncio_cli=trace`) without +turning on trace logging for every dependency `-vvv` would also enable. + ## The dogfooding loop Use it for real; when something breaks or feels wrong, tell me (or I'll hit it