diff --git a/Cargo.lock b/Cargo.lock index 2e2b0d8018..ffa2ae6e3a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2420,6 +2420,7 @@ dependencies = [ "regex", "rustyline", "serde", + "serde_with", "shell-words", "shellexpand", "strum 0.26.2", @@ -2429,6 +2430,7 @@ dependencies = [ "time", "tokio", "tracing", + "tracing-appender", "tracing-subscriber", "walkdir", ] @@ -5333,6 +5335,18 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.3" +source = "registry+/~https://github.com/rust-lang/crates.io-index" +checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf" +dependencies = [ + "crossbeam-channel", + "thiserror", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.27" diff --git a/iroh-cli/Cargo.toml b/iroh-cli/Cargo.toml index ad85af38bf..0d2c63a0a5 100644 --- a/iroh-cli/Cargo.toml +++ b/iroh-cli/Cargo.toml @@ -33,6 +33,7 @@ console = { version = "0.15.5" } derive_more = { version = "1.0.0-beta.1", features = ["display"] } dialoguer = { version = "0.11.0", default-features = false } dirs-next = { version = "2.0.0" } +flume = "0.11.0" futures = "0.3.30" hex = "0.4.3" human-time = { version = "0.1.6" } @@ -40,23 +41,24 @@ indicatif = { version = "0.17", features = ["tokio"] } iroh = { version = "0.13.0", path = "../iroh", features = ["metrics"] } iroh-metrics = { version = "0.13.0", path = "../iroh-metrics" } parking_lot = "0.12.1" -postcard = "1.0.8" portable-atomic = "1" +postcard = "1.0.8" quic-rpc = { version = "0.7.0", features = ["flume-transport", "quinn-transport"] } quinn = "0.10.2" rand = "0.8.5" rustyline = { version = "12.0.0" } +serde = { version = "1.0.197", features = ["derive"] } +serde_with = "3.7.0" shell-words = { version = "1.1.0" } shellexpand = { version = "3.1.0" } -serde = { version = "1.0.197", features = ["derive"] } strum = { version = "0.26.2", features = ["derive"] } +tempfile = "3.10.1" thiserror = "1.0.58" time = { version = "0.3", features = ["formatting"] } +tokio = { version = "1.36.0", features = ["full"] } tracing = "0.1.40" +tracing-appender = "0.2.3" tracing-subscriber = { version = "0.3", features = ["env-filter"] } -tokio = { version = "1.36.0", features = ["full"] } -tempfile = "3.10.1" -flume = "0.11.0" [dev-dependencies] duct = "0.13.6" diff --git a/iroh-cli/src/commands.rs b/iroh-cli/src/commands.rs index 4f1ebe08aa..bdeb06c56f 100644 --- a/iroh-cli/src/commands.rs +++ b/iroh-cli/src/commands.rs @@ -37,11 +37,6 @@ pub(crate) struct Cli { #[clap(long, global = true)] start: bool, - /// Send log output to specified file descriptor. - #[cfg(unix)] - #[clap(long)] - pub(crate) log_fd: Option, - /// Port to serve metrics on. -1 to disable. #[clap(long)] pub(crate) metrics_port: Option, @@ -131,6 +126,7 @@ impl Cli { ) .await } else { + crate::logging::init_terminal_logging()?; let iroh = IrohRpc::connect(data_dir).await.context("rpc connect")?; console::run(&iroh, &env).await } @@ -147,6 +143,7 @@ impl Cli { ) .await } else { + crate::logging::init_terminal_logging()?; let iroh = IrohRpc::connect(data_dir).await.context("rpc connect")?; command.run(&iroh, &env).await } diff --git a/iroh-cli/src/commands/doctor.rs b/iroh-cli/src/commands/doctor.rs index 95777e829f..81615d87cd 100644 --- a/iroh-cli/src/commands/doctor.rs +++ b/iroh-cli/src/commands/doctor.rs @@ -932,6 +932,8 @@ fn inspect_ticket(ticket: &str) -> anyhow::Result<()> { } pub async fn run(command: Commands, config: &NodeConfig) -> anyhow::Result<()> { + let data_dir = iroh_data_root()?; + let _guard = crate::logging::init_terminal_and_file_logging(&config.file_logs, &data_dir)?; match command { Commands::Report { stun_host, diff --git a/iroh-cli/src/commands/start.rs b/iroh-cli/src/commands/start.rs index ad523507a2..e529254c32 100644 --- a/iroh-cli/src/commands/start.rs +++ b/iroh-cli/src/commands/start.rs @@ -37,6 +37,7 @@ where F: FnOnce(iroh::client::mem::Iroh) -> T + Send + 'static, T: Future> + 'static, { + let _guard = crate::logging::init_terminal_and_file_logging(&config.file_logs, iroh_data_root)?; let metrics_fut = start_metrics_server(config.metrics_addr); let res = run_with_command_inner(config, iroh_data_root, run_type, command).await; diff --git a/iroh-cli/src/config.rs b/iroh-cli/src/config.rs index 0b8aee4a17..9d171629be 100644 --- a/iroh-cli/src/config.rs +++ b/iroh-cli/src/config.rs @@ -31,6 +31,7 @@ pub(crate) const ENV_PREFIX: &str = "IROH"; const ENV_AUTHOR: &str = "AUTHOR"; const ENV_DOC: &str = "DOC"; +const ENV_FILE_RUST_LOG: &str = "IROH_FILE_RUST_LOG"; /// Fetches the environment variable `IROH_` from the current process. pub(crate) fn env_var(key: &str) -> std::result::Result { @@ -91,6 +92,7 @@ pub(crate) struct NodeConfig { pub(crate) gc_policy: GcPolicy, /// Bind address on which to serve Prometheus metrics pub(crate) metrics_addr: Option, + pub(crate) file_logs: super::logging::FileLogging, } impl Default for NodeConfig { @@ -100,6 +102,7 @@ impl Default for NodeConfig { relay_nodes: [default_na_relay_node(), default_eu_relay_node()].into(), gc_policy: GcPolicy::Disabled, metrics_addr: Some(([127, 0, 0, 1], 9090).into()), + file_logs: Default::default(), } } } @@ -174,7 +177,13 @@ impl NodeConfig { let cfg = builder.build()?; debug!("make_config:\n{:#?}\n", cfg); - let cfg = cfg.try_deserialize()?; + let mut cfg: NodeConfig = cfg.try_deserialize()?; + + // override from env var + // NOTE: explicitely doing this since `dep:config` will be removed. + if let Some(env_filter) = env_file_rust_log().transpose()? { + cfg.file_logs.rust_log = env_filter; + } Ok(cfg) } @@ -332,6 +341,18 @@ fn env_doc() -> Result> { } } +/// Parse [`ENV_FILE_RUST_LOG`] as [`tracing_subscriber::EnvFilter`]. Returns `None` if not +/// present. +fn env_file_rust_log() -> Option> { + match env::var(ENV_FILE_RUST_LOG) { + Ok(s) => Some(crate::logging::EnvFilter::from_str(&s).map_err(Into::into)), + Err(e) => match e { + env::VarError::NotPresent => None, + e @ env::VarError::NotUnicode(_) => Some(Err(e.into())), + }, + } +} + /// Name of directory that wraps all iroh files in a given application directory const IROH_DIR: &str = "iroh"; diff --git a/iroh-cli/src/logging.rs b/iroh-cli/src/logging.rs new file mode 100644 index 0000000000..620c70a5d2 --- /dev/null +++ b/iroh-cli/src/logging.rs @@ -0,0 +1,167 @@ +use std::path::Path; + +use derive_more::FromStr; +use serde::{Deserialize, Serialize}; +use serde_with::{DeserializeFromStr, SerializeDisplay}; +use tracing_appender::{non_blocking, rolling}; +use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, Layer}; + +/// `RUST_LOG` statement used by default in file logging. +// rustyline is annoying +pub(crate) const DEFAULT_FILE_RUST_LOG: &str = "rustyline=warn,debug"; + +/// Initialize logging both in the terminal and file based. +/// +/// The terminal based logging layer will: +/// - use the default [`fmt::format::Format`]. +/// - log to [`std::io::Stderr`] +/// +/// The file base logging layer will: +/// - use the default [`fmt::format::Format`] save for: +/// - including line numbers. +/// - not using ansi colors. +/// - create log files in the `logs` dir inside the given `iroh_data_root`. +/// - rotate files every [`Self::rotation`]. +/// - keep at most [`Self::max_files`] log files. +/// - use the filtering defined by [`Self::rust_log`]. When not provided, the default +/// [`DEFAULT_FILE_RUST_LOG`] is used. +/// - create log files with the name `iroh-.log` (ex: iroh-2024-02-02.log) +pub(crate) fn init_terminal_and_file_logging( + file_log_config: &FileLogging, + logs_dir: &Path, +) -> anyhow::Result { + let terminal_layer = fmt::layer() + .with_writer(std::io::stderr) + .with_filter(tracing_subscriber::EnvFilter::from_default_env()); + let (file_layer, guard) = { + let FileLogging { + rust_log, + max_files, + rotation, + } = file_log_config; + + let filter = rust_log.layer(); + + let (file_logger, guard) = { + let file_appender = if *max_files == 0 || &filter.to_string() == "off" { + fmt::writer::OptionalWriter::none() + } else { + let rotation = match rotation { + Rotation::Hourly => rolling::Rotation::HOURLY, + Rotation::Daily => rolling::Rotation::DAILY, + Rotation::Never => rolling::Rotation::NEVER, + }; + let logs_path = logs_dir.join("logs"); + + let file_appender = rolling::Builder::new() + .rotation(rotation) + .max_log_files(*max_files) + .filename_prefix("iroh") + .filename_suffix("log") + .build(logs_path)?; + fmt::writer::OptionalWriter::some(file_appender) + }; + non_blocking(file_appender) + }; + + let layer = fmt::Layer::new() + .with_ansi(false) + .with_line_number(true) + .with_writer(file_logger) + .with_filter(filter); + (layer, guard) + }; + tracing_subscriber::registry() + .with(file_layer) + .with(terminal_layer) + .try_init()?; + Ok(guard) +} + +/// Initialize logging in the terminal. +/// +/// This will: +/// - use the default [`fmt::format::Format`]. +/// - log to [`std::io::Stderr`] +pub(crate) fn init_terminal_logging() -> anyhow::Result<()> { + let terminal_layer = fmt::layer() + .with_writer(std::io::stderr) + .with_filter(tracing_subscriber::EnvFilter::from_default_env()); + tracing_subscriber::registry() + .with(terminal_layer) + .try_init()?; + Ok(()) +} + +#[derive(Debug, Clone, PartialEq, Eq, Deserialize, Serialize)] +#[serde(default)] +pub(crate) struct FileLogging { + /// RUST_LOG directive to filter file logs. + pub(crate) rust_log: EnvFilter, + /// Maximum number of files to keep. + pub(crate) max_files: usize, + /// How often should a new log file be produced. + pub(crate) rotation: Rotation, +} + +impl Default for FileLogging { + fn default() -> Self { + Self { + rust_log: EnvFilter::default(), + max_files: 4, + rotation: Rotation::default(), + } + } +} + +/// Wrapper to obtain a [`tracing_subscriber::EnvFilter`] that satisfies required bounds. +#[derive( + Debug, Clone, PartialEq, Eq, SerializeDisplay, DeserializeFromStr, derive_more::Display, +)] +#[display("{_0}")] +pub(crate) struct EnvFilter(String); + +impl FromStr for EnvFilter { + type Err = ::Err; + + fn from_str(s: &str) -> Result { + // validate the RUST_LOG statement + let _valid_env = tracing_subscriber::EnvFilter::from_str(s)?; + Ok(EnvFilter(s.into())) + } +} + +impl Default for EnvFilter { + fn default() -> Self { + Self(DEFAULT_FILE_RUST_LOG.into()) + } +} + +impl EnvFilter { + pub(crate) fn layer(&self) -> tracing_subscriber::EnvFilter { + tracing_subscriber::EnvFilter::from_str(&self.0).expect("validated RUST_LOG statement") + } +} + +/// How often should a new file be created for file logs. +/// +/// Akin to [`tracing_appender::rolling::Rotation`]. +#[derive(Debug, Clone, PartialEq, Eq, Deserialize, Serialize, Default)] +#[serde(rename_all = "lowercase")] +pub(crate) enum Rotation { + #[default] + Hourly, + Daily, + Never, +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Tests that the default file logging `RUST_LOG` statement produces a valid layer. + #[test] + fn test_default_file_rust_log() { + let _ = EnvFilter::default().layer(); + } +} diff --git a/iroh-cli/src/main.rs b/iroh-cli/src/main.rs index bbc3a7ae53..24e8b2e3d0 100644 --- a/iroh-cli/src/main.rs +++ b/iroh-cli/src/main.rs @@ -2,10 +2,10 @@ use std::time::Duration; use anyhow::Result; use clap::Parser; -use tracing_subscriber::{prelude::*, EnvFilter}; mod commands; mod config; +mod logging; use crate::commands::Cli; @@ -26,45 +26,5 @@ fn main() -> Result<()> { async fn main_impl() -> Result<()> { let data_dir = config::iroh_data_root()?; let cli = Cli::parse(); - - #[cfg(unix)] - if let Some(log_fd) = cli.log_fd { - use std::fs::File; - use std::mem::ManuallyDrop; - use std::os::unix::io::FromRawFd; - - // SAFETY: We take ownership but ensure it is never dropped, thus we never close the - // filedescriptor. So even if the users chooses 0, 1 or 2 we do not close it, - // making sure those keep working as expected until process termination. - let inner = unsafe { ManuallyDrop::new(File::from_raw_fd(log_fd)) }; - let writer = ManuallyDropFile(inner); - tracing_subscriber::registry() - .with( - tracing_subscriber::fmt::layer() - .event_format(tracing_subscriber::fmt::format().with_line_number(true)) - .with_writer(writer), - ) - .with(EnvFilter::from_default_env()) - .init(); - return cli.run(&data_dir).await; - } - - tracing_subscriber::registry() - .with(tracing_subscriber::fmt::layer().with_writer(std::io::stderr)) - .with(EnvFilter::from_default_env()) - .init(); cli.run(&data_dir).await } - -/// Newtype for `ManuallyDrop` so we can impl a foreign trait. -#[cfg(unix)] -struct ManuallyDropFile(std::mem::ManuallyDrop); - -#[cfg(unix)] -impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for ManuallyDropFile { - type Writer = &'a std::fs::File; - - fn make_writer(&'a self) -> Self::Writer { - &self.0 - } -}