feat(iroh-cli): add file logging by default for start commands (#2175)

## Description

Adds file logging by default to commands that start a node.

Parameters are:
- the "RUST_LOG" directive, in the form of and env var
`IROH_FILE_RUST_LOG` or in the configuration file.
- rotation: how often a new file is created. Either daily, hourly or
never.
- max files: Maximum number of files to keep

File logging can be disabled by either setting the max_files to 0 in the
configuration file or by setting the rust log statement to off, in
either the env var or the config file.

(example config file)
```toml
[file_logs]
rust_log = "iroh=trace"
rotation = "daily"
max_files = 1
```

The files created live the `IROH_DATA_DIR/logs` dir and are named
`iroh-2024-03-02.log` (for a daily rotation, or with the hour, for an
hourly rotation)

By default, we log everything in debug, rotating hourly, keeping at most
4 files (so total 4 hours of logs). This is short default since debug
logs, even in an idle node, are a lot

## Notes & open questions

n/a

## Change checklist

- [x] Self-review.
- [x] Documentation updates if relevant.
- [ ] Tests if relevant.

---------

Co-authored-by: Floris Bruynooghe <flub@devork.be>

iroh-cli/Cargo.toml

@@ -33,30 +33,32 @@ 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" }
 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"

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<i32>,
-
     /// Port to serve metrics on. -1 to disable.
     #[clap(long)]
     pub(crate) metrics_port: Option<MetricsPort>,
@@ -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
                 }

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,

iroh-cli/src/commands/start.rs

@@ -37,6 +37,7 @@ where
     F: FnOnce(iroh::client::mem::Iroh) -> T + Send + 'static,
     T: Future<Output = Result<()>> + '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;

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_<key>` from the current process.
 pub(crate) fn env_var(key: &str) -> std::result::Result<String, env::VarError> {
@@ -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<SocketAddr>,
+    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<Option<NamespaceId>> {
     }
 }
 
+/// Parse [`ENV_FILE_RUST_LOG`] as [`tracing_subscriber::EnvFilter`]. Returns `None` if not
+/// present.
+fn env_file_rust_log() -> Option<Result<crate::logging::EnvFilter>> {
+    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";
 

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-<ROTATION_BASED_NAME>.log` (ex: iroh-2024-02-02.log)
+pub(crate) fn init_terminal_and_file_logging(
+    file_log_config: &FileLogging,
+    logs_dir: &Path,
+) -> anyhow::Result<non_blocking::WorkerGuard> {
+    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 = <tracing_subscriber::EnvFilter as FromStr>::Err;
+
+    fn from_str(s: &str) -> Result<Self, Self::Err> {
+        // 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();
+    }
+}