Merge pull request #1400 from input-output-hk/ensemble/1234/enhance-m…

…achine-readable-logs-in-client

Enhance machine readable logs in client

docs/website/root/manual/developer-docs/nodes/mithril-client.md

@@ -137,6 +137,10 @@ Options:
           Directory where configuration file is located [default: ./config]
       --aggregator-endpoint <AGGREGATOR_ENDPOINT>
           Override configuration Aggregator endpoint URL
+      --log-format-json
+          Enable JSON output for logs displayed according to verbosity level
+      --log-output <LOG_OUTPUT>
+          Redirect the logs to a file
   -h, --help
           Print help
   -V, --version
@@ -296,20 +300,35 @@ Here is a list of the available parameters:
 | `network` | - | - | `NETWORK` | Cardano network | - | `testnet` or `mainnet` or `devnet` | :heavy_check_mark: |
 | `aggregator_endpoint` | `--aggregator-endpoint` | - | `AGGREGATOR_ENDPOINT` | Aggregator node endpoint | - | `https://aggregator.pre-release-preview.api.mithril.network/aggregator` | :heavy_check_mark: |
 | `genesis_verification_key` | - | - | `GENESIS_VERIFICATION_KEY` | Genesis verification key | - | - | :heavy_check_mark: |
-| `json_output` | `--json` | `-j` | - | Enable JSON output | no | - | - |
+| `log_format_json` | `--log-format-json` | - | - | Enable JSON output for logs | - | - | - |
+| `log_output` | `--log-output` | `-o` | - | Redirect the logs to a file | - | `./mithril-client.log` | - |
 
 `snapshot show` command:
 
 | Parameter | Command line (long) |  Command line (short) | Environment variable | Description | Default value | Example | Mandatory |
 |-----------|---------------------|:---------------------:|----------------------|-------------|---------------|---------|:---------:|
 | `digest` | `--digest` | - | `DIGEST` | Snapshot digest or `latest` for the latest digest | - | - | :heavy_check_mark: |
+| `json` | `--json` | - | - | Enable JSON output for command results | - | - | - |
+
+`snapshot list` command:
+
+| Parameter | Command line (long) |  Command line (short) | Environment variable | Description | Default value | Example | Mandatory |
+|-----------|---------------------|:---------------------:|----------------------|-------------|---------------|---------|:---------:|
+| `json` | `--json` | - | - | Enable JSON output for command results | - | - | - |
 
 `snapshot download` command:
 
 | Parameter | Command line (long) |  Command line (short) | Environment variable | Description | Default value | Example | Mandatory |
 |-----------|---------------------|:---------------------:|----------------------|-------------|---------------|---------|:---------:|
 | `digest` | `--digest` | - | `DIGEST` | Snapshot digest or `latest` for the latest digest | - | - | :heavy_check_mark: |
 | `download_dir` | `--download-dir` | - | - | Directory where the snapshot will be downloaded | . | - | - |
+| `json` | `--json` | - | - | Enable JSON output for progress logs | - | - | - |
+
+`mithril-stake-distribution list` command:
+
+| Parameter | Command line (long) |  Command line (short) | Environment variable | Description | Default value | Example | Mandatory |
+|-----------|---------------------|:---------------------:|----------------------|-------------|---------------|---------|:---------:|
+| `json` | `--json` | - | - | Enable JSON output for command results | - | - | - |
 
 `mithril-stake-distribution download` command:
 

mithril-client-cli/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "mithril-client-cli"
-version = "0.5.11"
+version = "0.5.12"
 description = "A Mithril Client"
 authors = { workspace = true }
 edition = { workspace = true }
@@ -46,6 +46,7 @@ slog = { version = "2.7.0", features = [
     "release_max_level_debug",
 ] }
 slog-async = "2.8.0"
+slog-bunyan = "2.4.0"
 slog-scope = "4.4.0"
 slog-term = "2.9.0"
 thiserror = "1.0.49"

mithril-client-cli/src/commands/snapshot/download.rs

@@ -1,4 +1,5 @@
 use anyhow::{anyhow, Context};
+use chrono::Utc;
 use clap::Parser;
 use config::{builder::DefaultState, ConfigBuilder, Map, Source, Value, ValueKind};
 use slog_scope::{debug, logger, warn};
@@ -183,7 +184,8 @@ impl SnapshotDownloadCommand {
 
         if self.json {
             println!(
-                r#"{{"db_directory": "{}"}}"#,
+                r#"{{"timestamp": "{}", "db_directory": "{}"}}"#,
+                Utc::now().to_rfc3339(),
                 canonicalized_filepath.display()
             );
         } else {

mithril-client-cli/src/main.rs

@@ -2,20 +2,42 @@
 
 mod commands;
 
-use std::path::PathBuf;
-use std::sync::Arc;
-
+use anyhow::Context;
 use clap::{Parser, Subcommand};
 use config::{builder::DefaultState, ConfigBuilder, Map, Source, Value, ValueKind};
-use slog::{Drain, Level, Logger};
+use slog::{Drain, Fuse, Level, Logger};
+use slog_async::Async;
 use slog_scope::debug;
+use slog_term::Decorator;
+use std::io::Write;
+use std::sync::Arc;
+use std::{fs::File, path::PathBuf};
 
 use mithril_client_cli::common::StdResult;
 
 use commands::{
     mithril_stake_distribution::MithrilStakeDistributionCommands, snapshot::SnapshotCommands,
 };
 
+enum LogOutputType {
+    Stdout,
+    File(String),
+}
+
+impl LogOutputType {
+    fn get_writer(&self) -> StdResult<Box<dyn Write + Send>> {
+        let writer: Box<dyn Write + Send> = match self {
+            LogOutputType::Stdout => Box::new(std::io::stdout()),
+            LogOutputType::File(filepath) => Box::new(
+                File::create(filepath)
+                    .with_context(|| format!("Can not create output log file: {}", filepath))?,
+            ),
+        };
+
+        Ok(writer)
+    }
+}
+
 #[derive(Parser, Debug, Clone)]
 #[clap(name = "mithril-client")]
 #[clap(
@@ -43,6 +65,14 @@ pub struct Args {
     /// Override configuration Aggregator endpoint URL.
     #[clap(long, env = "AGGREGATOR_ENDPOINT")]
     aggregator_endpoint: Option<String>,
+
+    /// Enable JSON output for logs displayed according to verbosity level
+    #[clap(long)]
+    log_format_json: bool,
+
+    /// Redirect the logs to a file
+    #[clap(long, alias("o"))]
+    log_output: Option<String>,
 }
 
 impl Args {
@@ -68,13 +98,38 @@ impl Args {
         }
     }
 
-    fn build_logger(&self) -> Logger {
-        let decorator = slog_term::TermDecorator::new().build();
+    fn get_log_output_type(&self) -> LogOutputType {
+        if let Some(output_filepath) = &self.log_output {
+            LogOutputType::File(output_filepath.to_string())
+        } else {
+            LogOutputType::Stdout
+        }
+    }
+
+    fn wrap_drain<D: Decorator + Send + 'static>(&self, decorator: D) -> Fuse<Async> {
         let drain = slog_term::CompactFormat::new(decorator).build().fuse();
         let drain = slog::LevelFilter::new(drain, self.log_level()).fuse();
-        let drain = slog_async::Async::new(drain).build().fuse();
 
-        Logger::root(Arc::new(drain), slog::o!())
+        slog_async::Async::new(drain).build().fuse()
+    }
+
+    fn build_logger(&self) -> StdResult<Logger> {
+        let log_output_type = self.get_log_output_type();
+        let writer = log_output_type.get_writer()?;
+
+        let drain = if self.log_format_json {
+            let drain = slog_bunyan::new(writer).set_pretty(false).build().fuse();
+            let drain = slog::LevelFilter::new(drain, self.log_level()).fuse();
+
+            slog_async::Async::new(drain).build().fuse()
+        } else {
+            match log_output_type {
+                LogOutputType::Stdout => self.wrap_drain(slog_term::TermDecorator::new().build()),
+                LogOutputType::File(_) => self.wrap_drain(slog_term::PlainDecorator::new(writer)),
+            }
+        };
+
+        Ok(Logger::root(Arc::new(drain), slog::o!()))
     }
 }
 
@@ -120,7 +175,7 @@ impl ArtifactCommands {
 async fn main() -> StdResult<()> {
     // Load args
     let args = Args::parse();
-    let _guard = slog_scope::set_global_logger(args.build_logger());
+    let _guard = slog_scope::set_global_logger(args.build_logger()?);
 
     #[cfg(feature = "bundle_openssl")]
     openssl_probe::init_ssl_cert_env_vars();

mithril-client-cli/src/utils/progress_reporter.rs

@@ -1,3 +1,4 @@
+use chrono::Utc;
 use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget};
 use mithril_common::StdResult;
 use slog_scope::warn;
@@ -49,8 +50,9 @@ impl ProgressPrinter {
     pub fn report_step(&self, step_number: u16, text: &str) -> StdResult<()> {
         match self.output_type {
             ProgressOutputType::JsonReporter => println!(
-                r#"{{"step_num": {step_number}, "total_steps": {}, "message": "{text}"}}"#,
-                self.number_of_steps
+                r#"{{"timestamp": "{timestamp}", "step_num": {step_number}, "total_steps": {number_of_steps}, "message": "{text}"}}"#,
+                timestamp = Utc::now().to_rfc3339(),
+                number_of_steps = self.number_of_steps,
             ),
             ProgressOutputType::TTY => self
                 .multi_progress
@@ -70,6 +72,23 @@ impl Deref for ProgressPrinter {
     }
 }
 
+pub struct ProgressBarJsonFormatter;
+
+impl ProgressBarJsonFormatter {
+    pub fn format(progress_bar: &ProgressBar) -> String {
+        format!(
+            r#"{{"timestamp": "{}", "bytes_downloaded": {}, "bytes_total": {}, "seconds_left": {}.{:0>3}, "seconds_elapsed": {}.{:0>3}}}"#,
+            Utc::now().to_rfc3339(),
+            progress_bar.position(),
+            progress_bar.length().unwrap_or(0),
+            progress_bar.eta().as_secs(),
+            progress_bar.eta().subsec_millis(),
+            progress_bar.elapsed().as_secs(),
+            progress_bar.elapsed().subsec_millis(),
+        )
+    }
+}
+
 /// Wrapper of a indicatif [ProgressBar] to allow reporting to json.
 pub struct DownloadProgressReporter {
     progress_bar: ProgressBar,
@@ -98,15 +117,7 @@ impl DownloadProgressReporter {
             };
 
             if should_report {
-                println!(
-                    r#"{{ "bytesDownloaded": {}, "bytesTotal": {}, "secondsLeft": {}.{}, "secondsElapsed": {}.{} }}"#,
-                    self.progress_bar.position(),
-                    self.progress_bar.length().unwrap_or(0),
-                    self.progress_bar.eta().as_secs(),
-                    self.progress_bar.eta().subsec_millis(),
-                    self.progress_bar.elapsed().as_secs(),
-                    self.progress_bar.elapsed().subsec_millis(),
-                );
+                println!("{}", ProgressBarJsonFormatter::format(&self.progress_bar));
 
                 match self.last_json_report_instant.write() {
                     Ok(mut instant) => *instant = Some(Instant::now()),
@@ -129,3 +140,75 @@ impl DownloadProgressReporter {
         }
     }
 }
+
+#[cfg(test)]
+mod tests {
+    use std::thread::sleep;
+
+    use super::*;
+    use indicatif::ProgressBar;
+
+    #[test]
+    fn check_seconds_elapsed_in_json_report_with_more_than_100_milliseconds() {
+        let progress_bar = ProgressBar::new(10).with_elapsed(Duration::from_millis(5124));
+
+        let json_string = ProgressBarJsonFormatter::format(&progress_bar);
+
+        assert!(
+            json_string.contains(r#""seconds_elapsed": 5.124"#),
+            "Not expected value in json output: {}",
+            json_string
+        );
+    }
+
+    #[test]
+    fn check_seconds_elapsed_in_json_report_with_less_than_100_milliseconds() {
+        let progress_bar = ProgressBar::new(10).with_elapsed(Duration::from_millis(5004));
+
+        let json_string = ProgressBarJsonFormatter::format(&progress_bar);
+
+        assert!(
+            json_string.contains(r#""seconds_elapsed": 5.004"#),
+            "Not expected value in json output: {}",
+            json_string
+        );
+    }
+
+    #[test]
+    fn check_seconds_left_in_json_report_with_more_than_100_milliseconds() {
+        let half_position = 5;
+        let progress_bar = ProgressBar::new(half_position * 2);
+        sleep(Duration::from_millis(123));
+        progress_bar.set_position(half_position);
+        let json_string = ProgressBarJsonFormatter::format(&progress_bar);
+
+        let milliseconds = progress_bar.eta().subsec_millis();
+        assert!(milliseconds > 100);
+        assert!(
+            json_string.contains(&format!(r#""seconds_left": 0.{}"#, milliseconds)),
+            "Not expected value in json output: {}",
+            json_string
+        );
+    }
+
+    #[test]
+    fn check_seconds_left_in_json_report_with_less_than_100_milliseconds() {
+        let half_position = 5;
+        let progress_bar = ProgressBar::new(half_position * 2);
+        sleep(Duration::from_millis(1));
+        progress_bar.set_position(half_position);
+        let json_string = ProgressBarJsonFormatter::format(&progress_bar);
+
+        assert!(
+            json_string.contains(r#""seconds_left": 0.0"#),
+            "Not expected value in json output: {}",
+            json_string
+        );
+
+        assert!(
+            !json_string.contains(r#""seconds_left": 0.000"#),
+            "Not expected value in json output: {}",
+            json_string
+        );
+    }
+}