feat(rust): add a custom log format to change the fields order

Author: adrianbenavides

Cargo.lock

@@ -78,6 +78,7 @@ log = "0.4"
 miette = { version = "7.2.0", features = ["fancy-no-backtrace"] }
 minicbor = { version = "0.25.1", default-features = false, features = ["alloc", "derive"] }
 nix = { version = "0.29", features = ["signal"] }
+nu-ansi-term = "0.50"
 once_cell = { version = "1", default-features = false }
 open = "5.3.0"
 opentelemetry = { version = "0.26.0", features = ["logs", "metrics", "trace"] }

implementations/rust/ockam/ockam_api/Cargo.toml

@@ -118,7 +118,6 @@ impl CliState {
     }
 
     fn notify(&self, notification: Notification) {
-        debug!("{:?}", notification.contents());
         let _ = self.notifications.send(notification);
     }
 }

implementations/rust/ockam/ockam_api/src/cli_state/cli_state.rs

@@ -1,6 +1,11 @@
+use nu_ansi_term::{Color, Style};
 use ockam_core::env::FromString;
 use ockam_core::errcode::{Kind, Origin};
-use std::fmt::{Display, Formatter};
+use std::fmt::{Debug, Display, Formatter};
+use tracing_core::{Event, Level, Subscriber};
+use tracing_subscriber::fmt::format::Writer;
+use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields, FormattedFields};
+use tracing_subscriber::registry::LookupSpan;
 
 #[derive(Debug, PartialEq, Eq, Copy, Clone)]
 pub enum LoggingEnabled {
@@ -85,12 +90,158 @@ impl FromString for LogFormat {
     }
 }
 
-impl std::fmt::Display for LogFormat {
-    fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
+impl Display for LogFormat {
+    fn fmt(&self, f: &mut Formatter) -> std::fmt::Result {
         match self {
             LogFormat::Default => write!(f, "default"),
             LogFormat::Pretty => write!(f, "pretty"),
             LogFormat::Json => write!(f, "json"),
         }
     }
 }
+
+#[derive(Default)]
+pub struct OckamLogFormat {}
+
+impl OckamLogFormat {
+    pub fn new() -> Self {
+        Self {}
+    }
+
+    fn format_timestamp(&self, writer: &mut Writer<'_>) -> std::fmt::Result {
+        let now = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
+        if writer.has_ansi_escapes() {
+            let style = Style::new().dimmed();
+            write!(writer, "{}", style.prefix())?;
+            write!(writer, "{}", now)?;
+            write!(writer, "{} ", style.suffix())?;
+        } else {
+            write!(writer, "{}", now)?;
+            writer.write_char(' ')?;
+        }
+        Ok(())
+    }
+}
+
+impl<S, N> FormatEvent<S, N> for OckamLogFormat
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(
+        &self,
+        ctx: &FmtContext<'_, S, N>,
+        mut writer: Writer<'_>,
+        event: &Event<'_>,
+    ) -> std::fmt::Result {
+        let meta = event.metadata();
+        let dimmed = if writer.has_ansi_escapes() {
+            Style::new().dimmed()
+        } else {
+            Style::new()
+        };
+        let bold = if writer.has_ansi_escapes() {
+            Style::new().bold()
+        } else {
+            Style::new()
+        };
+
+        // Timestamp
+        self.format_timestamp(&mut writer)?;
+
+        // Level
+        let fmt_level = FmtLevel::new(meta.level(), writer.has_ansi_escapes());
+        write!(writer, "{} ", fmt_level)?;
+
+        // Event
+        ctx.format_fields(writer.by_ref(), event)?;
+        writer.write_char(' ')?;
+
+        // Scope
+        if let Some(scope) = ctx.event_scope() {
+            let mut seen = false;
+
+            for span in scope.from_root() {
+                write!(writer, "{}", bold.paint(span.metadata().name()))?;
+                seen = true;
+
+                let ext = span.extensions();
+                if let Some(fields) = &ext.get::<FormattedFields<N>>() {
+                    if !fields.is_empty() {
+                        write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
+                    }
+                }
+                write!(writer, "{}", dimmed.paint(":"))?;
+            }
+
+            if seen {
+                writer.write_char(' ')?;
+            }
+        };
+
+        // Target
+        write!(writer, "{} ", dimmed.paint(meta.target()))?;
+
+        // File and line
+        let line_number = meta.line();
+        if let Some(filename) = meta.file() {
+            write!(
+                writer,
+                "{}{}{}",
+                dimmed.paint(filename),
+                dimmed.paint(":"),
+                if line_number.is_some() { "" } else { " " }
+            )?;
+        }
+        if let Some(line_number) = line_number {
+            write!(
+                writer,
+                "{}{}{}",
+                dimmed.prefix(),
+                line_number,
+                dimmed.suffix()
+            )?;
+        }
+
+        writeln!(writer)
+    }
+}
+
+struct FmtLevel<'a> {
+    level: &'a Level,
+    ansi: bool,
+}
+
+impl<'a> FmtLevel<'a> {
+    pub(crate) fn new(level: &'a Level, ansi: bool) -> Self {
+        Self { level, ansi }
+    }
+}
+
+const TRACE_STR: &str = "TRACE";
+const DEBUG_STR: &str = "DEBUG";
+const INFO_STR: &str = " INFO";
+const WARN_STR: &str = " WARN";
+const ERROR_STR: &str = "ERROR";
+
+impl Display for FmtLevel<'_> {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        if self.ansi {
+            match *self.level {
+                Level::TRACE => write!(f, "{}", Color::Purple.paint(TRACE_STR)),
+                Level::DEBUG => write!(f, "{}", Color::Blue.paint(DEBUG_STR)),
+                Level::INFO => write!(f, "{}", Color::Green.paint(INFO_STR)),
+                Level::WARN => write!(f, "{}", Color::Yellow.paint(WARN_STR)),
+                Level::ERROR => write!(f, "{}", Color::Red.paint(ERROR_STR)),
+            }
+        } else {
+            match *self.level {
+                Level::TRACE => f.pad(TRACE_STR),
+                Level::DEBUG => f.pad(DEBUG_STR),
+                Level::INFO => f.pad(INFO_STR),
+                Level::WARN => f.pad(WARN_STR),
+                Level::ERROR => f.pad(ERROR_STR),
+            }
+        }
+    }
+}

implementations/rust/ockam/ockam_api/src/logs/logging_options.rs

@@ -30,6 +30,7 @@ use ockam_node::Executor;
 use crate::logs::tracing_guard::TracingGuard;
 use crate::logs::{
     ExportingConfiguration, GlobalErrorHandler, LoggingConfiguration, OckamLogExporter,
+    OckamLogFormat,
 };
 use crate::logs::{LogFormat, OckamSpanExporter};
 
@@ -109,7 +110,9 @@ impl LoggingTracing {
         let result = match logging_configuration.format() {
             LogFormat::Pretty => layers.with(appender.pretty()).try_init(),
             LogFormat::Json => layers.with(appender.json()).try_init(),
-            LogFormat::Default => layers.with(appender).try_init(),
+            LogFormat::Default => layers
+                .with(appender.event_format(OckamLogFormat::new()))
+                .try_init(),
         };
         result.expect("Failed to initialize tracing subscriber");
 
@@ -130,7 +133,9 @@ impl LoggingTracing {
             let result = match logging_configuration.format() {
                 LogFormat::Pretty => layers.with(appender.pretty()).try_init(),
                 LogFormat::Json => layers.with(appender.json()).try_init(),
-                LogFormat::Default => layers.with(appender).try_init(),
+                LogFormat::Default => layers
+                    .with(appender.event_format(OckamLogFormat::new()))
+                    .try_init(),
             };
             result.expect("Failed to initialize tracing subscriber");
         };
@@ -230,7 +235,7 @@ fn create_opentelemetry_tracing_layer<
     exporting_configuration: &ExportingConfiguration,
     span_exporter: S,
 ) -> (
-    OpenTelemetryLayer<R, sdk::trace::Tracer>,
+    OpenTelemetryLayer<R, opentelemetry_sdk::trace::Tracer>,
     opentelemetry_sdk::trace::TracerProvider,
 ) {
     let app = app_name.to_string();
@@ -243,7 +248,8 @@ fn create_opentelemetry_tracing_layer<
     let is_ockam_developer = exporting_configuration.is_ockam_developer();
     let span_export_cutoff = exporting_configuration.span_export_cutoff();
     Executor::execute_future(async move {
-        let trace_config = sdk::trace::Config::default().with_resource(make_resource(app));
+        let trace_config =
+            opentelemetry_sdk::trace::Config::default().with_resource(make_resource(app));
         let (tracer, tracer_provider) = create_tracer(
             trace_config,
             batch_config,
@@ -410,11 +416,14 @@ fn set_global_error_handler(logging_configuration: &LoggingConfiguration) {
 
 /// Create a Tracer using the provided span exporter
 fn create_tracer<S: SpanExporter + 'static>(
-    trace_config: sdk::trace::Config,
+    trace_config: opentelemetry_sdk::trace::Config,
     batch_config: BatchConfig,
     exporter: S,
-) -> (sdk::trace::Tracer, opentelemetry_sdk::trace::TracerProvider) {
-    let span_processor = BatchSpanProcessor::builder(exporter, sdk::runtime::Tokio)
+) -> (
+    opentelemetry_sdk::trace::Tracer,
+    opentelemetry_sdk::trace::TracerProvider,
+) {
+    let span_processor = BatchSpanProcessor::builder(exporter, opentelemetry_sdk::runtime::Tokio)
         .with_batch_config(batch_config)
         .build();
     let provider = opentelemetry_sdk::trace::TracerProvider::builder()

implementations/rust/ockam/ockam_api/src/logs/setup.rs

@@ -10,8 +10,9 @@ use opentelemetry_sdk as sdk;
 use sdk::testing::logs::*;
 use sdk::testing::trace::*;
 
+use opentelemetry_sdk::testing::logs::InMemoryLogsExporter;
+use opentelemetry_sdk::testing::trace::InMemorySpanExporter;
 use std::fs;
-
 use tempfile::NamedTempFile;
 
 use ockam_api::cli_state::{random_name, CliStateMode};
@@ -81,12 +82,12 @@ fn test_log_and_traces() {
         if file_path.to_string_lossy().contains("stdout") {
             let contents = fs::read_to_string(file_path).unwrap();
             assert!(
-                contents.contains("INFO logging_tracing: inside span"),
+                contents.contains("INFO inside span logging_tracing"),
                 "{:?}",
                 contents
             );
             assert!(
-                contents.contains("ERROR logging_tracing: something went wrong!"),
+                contents.contains("ERROR something went wrong! logging_tracing"),
                 "{:?}",
                 contents
             );

implementations/rust/ockam/ockam_api/tests/logging_tracing.rs

@@ -185,7 +185,7 @@ impl CommandGlobalOpts {
         debug!("Arguments: {}", arguments.join(" "));
         debug!("Global arguments: {:#?}", &global_args);
         debug!("Command: {:#?}", &cmd);
-        debug!("Version: {}", Version::new());
+        debug!("Version: {}", Version::new().no_color());
 
         info!("Tracing initialized");
         debug!("{:#?}", logging_configuration);

implementations/rust/ockam/ockam_command/src/command_global_opts.rs

@@ -53,7 +53,17 @@ impl CreateCommand {
 
         // Set node_name so that node can isolate its data in the storage from other nodes
         self.get_or_create_identity(&opts, &self.identity).await?;
-        let _notification_handler = NotificationHandler::start(&opts.state, opts.terminal.clone());
+        let _notification_handler = if self.foreground_args.child_process {
+            // If enabled, the user's terminal will receive notifications
+            // from the node after the command exited.
+            None
+        } else {
+            // Enable the notifications only on explicit foreground nodes.
+            Some(NotificationHandler::start(
+                &opts.state,
+                opts.terminal.clone(),
+            ))
+        };
         let node_info = opts
             .state
             .start_node_with_optional_values(