feat(node): separate tracing and logging files (consensus-shipyard#1090)

ipc/observability/src/config.rs

@@ -39,8 +39,8 @@ pub enum RotationKind {
     Never,
 }
 
-impl From<RotationKind> for tracing_appender::rolling::Rotation {
-    fn from(kind: RotationKind) -> tracing_appender::rolling::Rotation {
+impl From<&RotationKind> for tracing_appender::rolling::Rotation {
+    fn from(kind: &RotationKind) -> tracing_appender::rolling::Rotation {
         match kind {
             RotationKind::Minutely => tracing_appender::rolling::Rotation::MINUTELY,
             RotationKind::Hourly => tracing_appender::rolling::Rotation::HOURLY,

ipc/observability/src/lib.rs

@@ -10,9 +10,10 @@ pub mod observe;
 pub mod serde;
 
 use std::fmt::Debug;
+use std::time::Instant;
 use tracing::{debug, error, info, trace, warn};
 
-use std::time::Instant;
+use crate::traces::TRACING_TARGET;
 
 pub trait Recordable {
     fn record_metrics(&self);
@@ -37,11 +38,11 @@ where
     T: Recordable + Traceable + Debug,
 {
     match trace.trace_level() {
-        TraceLevel::Trace => trace!(domain=trace.domain(), event = ?trace),
-        TraceLevel::Debug => debug!(domain=trace.domain(), event = ?trace),
-        TraceLevel::Info => info!(domain=trace.domain(), event = ?trace),
-        TraceLevel::Warn => warn!(domain=trace.domain(), event = ?trace),
-        TraceLevel::Error => error!(domain=trace.domain(), event = ?trace),
+        TraceLevel::Trace => trace!(target:TRACING_TARGET, domain=trace.domain(), event = ?trace),
+        TraceLevel::Debug => debug!(target:TRACING_TARGET, domain=trace.domain(), event = ?trace),
+        TraceLevel::Info => info!(target:TRACING_TARGET, domain=trace.domain(), event = ?trace),
+        TraceLevel::Warn => warn!(target:TRACING_TARGET, domain=trace.domain(), event = ?trace),
+        TraceLevel::Error => error!(target:TRACING_TARGET, domain=trace.domain(), event = ?trace),
     }
 
     trace.record_metrics();

ipc/observability/src/traces.rs

@@ -1,15 +1,16 @@
 // Copyright 2022-2024 Protocol Labs
 // SPDX-License-Identifier: Apache-2.0, MIT
 
+use crate::config::{FileLayerSettings, LogLevel, TracingSettings};
+use crate::tracing_layers::DomainEventFilterLayer;
 use std::num::NonZeroUsize;
 use tracing::Level;
 pub use tracing_appender::non_blocking;
 pub use tracing_appender::non_blocking::WorkerGuard;
 use tracing_appender::rolling::RollingFileAppender;
-use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, EnvFilter, Layer};
+use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, EnvFilter, Layer, Registry};
 
-use crate::config::{FileLayerSettings, TracingSettings};
-use crate::tracing_layers::DomainEventFilterLayer;
+pub const TRACING_TARGET: &str = "tracing_event";
 
 // Creates a temporary subscriber that logs all traces to stderr. Useful when global tracing is not set yet.
 pub fn create_temporary_subscriber() -> Subscriber {
@@ -21,37 +22,48 @@ pub fn create_temporary_subscriber() -> Subscriber {
         .finish()
 }
 
-// Sets a global tracing subscriber with the given configuration. Returns a guard that can be used to drop the subscriber.
-pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Option<WorkerGuard> {
-    let console_filter: EnvFilter = config
-        .console
-        .as_ref()
-        .and_then(|c| c.level.clone())
-        .unwrap_or_default()
-        .into();
-
-    // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands)
-    let console_layer = fmt::layer()
-        .with_writer(std::io::stderr)
-        .with_target(false)
-        .with_file(true)
-        .with_line_number(true)
-        .with_filter(console_filter);
-
-    let (file_layer, file_guard) = match &config.file {
-        Some(file_settings) if file_settings.enabled => {
-            let (non_blocking, file_guard) = non_blocking(create_file_appender(file_settings));
-
-            let file_filter: EnvFilter = file_settings.level.clone().unwrap_or_default().into();
+// Sets the global tracing subscriber.
+//
+// All traces emitted through the tracing library will be routed to this subscriber.
+//
+// This subscriber bifurcates tracing events into two individual sinks: one for logs and one for
+// structured traces. We also set up the console sink, if requested by the configuration.
+//
+// Returns a guard that can be used to drop the subscriber.
+pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Vec<WorkerGuard> {
+    let console_layer = {
+        let filter: EnvFilter = config
+            .console
+            .as_ref()
+            .and_then(|c| c.level.clone())
+            .unwrap_or_default()
+            .into();
+
+        // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands)
+        fmt::layer()
+            .with_writer(std::io::stderr)
+            .with_target(false)
+            .with_file(true)
+            .with_line_number(true)
+            .with_filter(filter)
+    };
 
-            let file_layer = fmt::layer()
+    let (traces_layer, logs_layer, guards) = if let Some(file_settings) =
+        config.file.as_ref().filter(|s| s.enabled)
+    {
+        //
+        // Set up the traces layer.
+        //
+        let (traces_layer, traces_guard) = {
+            let (appender, guard) = non_blocking(create_file_appender(file_settings, "traces.log"));
+
+            // setup traces file layer - traces are logs that have the target set to TRACING_TARGET
+            let layer = fmt::layer()
                 .json()
-                .with_writer(non_blocking)
-                .with_span_events(fmt::format::FmtSpan::CLOSE)
+                .with_writer(appender)
                 .with_target(false)
-                .with_file(true)
-                .with_line_number(true)
-                .with_filter(file_filter);
+                .with_file(false)
+                .with_line_number(false);
 
             let domains = file_settings
                 .domain_filter
@@ -63,47 +75,87 @@ pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Option<WorkerG
                 .as_ref()
                 .map(|v| v.iter().map(|s| s.to_string()).collect());
 
-            let file_layer = DomainEventFilterLayer::new(domains, events, file_layer);
+            let level = &file_settings.level.clone().unwrap_or_default();
 
-            (Some(file_layer), Some(file_guard))
-        }
-        _ => (None, None),
+            let filter = EnvFilter::try_new(format!("{TRACING_TARGET}={}", level))
+                .expect("invalid traces level");
+
+            let filtered_layer =
+                DomainEventFilterLayer::new(domains, events, layer).with_filter(filter);
+
+            (filtered_layer, guard)
+        };
+
+        //
+        // Set up the logs layer.
+        //
+        let (logs_layer, logs_guard) = {
+            // setup logs file layer first - logs are traces that does not have the target set to TRACING_TARGET
+            let (appender, guard) = non_blocking(create_file_appender(file_settings, "app.log"));
+
+            let mut filter: EnvFilter = file_settings.level.clone().unwrap_or_default().into();
+            filter = filter.add_directive(
+                format!("{TRACING_TARGET}={}", LogLevel::Off)
+                    .parse()
+                    .expect("invalid logs level"),
+            );
+
+            let layer = fmt::layer()
+                .json()
+                .with_writer(appender)
+                .with_target(false)
+                .with_file(true)
+                .with_line_number(true)
+                .with_filter(filter);
+
+            (layer, guard)
+        };
+
+        (
+            Some(traces_layer),
+            Some(logs_layer),
+            vec![logs_guard, traces_guard],
+        )
+    } else {
+        (None, None, Vec::new())
     };
 
-    let registry = tracing_subscriber::registry()
+    // Start with the base registry
+    let subscriber = Registry::default()
         .with(console_layer)
-        .with(file_layer);
+        .with(traces_layer)
+        .with(logs_layer);
 
-    tracing::subscriber::set_global_default(registry)
-        .expect("Unable to set a global tracing subscriber");
+    // Set the global subscriber
+    tracing::subscriber::set_global_default(subscriber)
+        .expect("Unable to set global tracing subscriber");
 
-    file_guard
+    guards
 }
 
-fn create_file_appender(settings: &FileLayerSettings) -> RollingFileAppender {
+fn create_file_appender(settings: &FileLayerSettings, suffix: &str) -> RollingFileAppender {
     let directory = settings
         .directory
         .as_deref()
         .expect("missing file log directory");
-    let mut appender = RollingFileAppender::builder().filename_suffix("traces");
+    let mut appender = RollingFileAppender::builder().filename_suffix(suffix);
 
     if let Some(max_log_files) = settings.max_log_files {
-        println!("max log files: {}", max_log_files);
-
         appender = appender.max_log_files(
             NonZeroUsize::new(max_log_files)
                 .expect("max_log_files must be greater than 0")
                 .into(),
         );
     };
 
-    if let Some(rotation_kind) = &settings.rotation {
-        println!("rotation kind: {:?}", rotation_kind);
-        let rotation: tracing_appender::rolling::Rotation = rotation_kind.clone().into();
-        appender = appender.rotation(rotation);
-    };
+    let rotation: tracing_appender::rolling::Rotation = settings
+        .rotation
+        .as_ref()
+        .map(|r| r.into())
+        .unwrap_or(tracing_appender::rolling::Rotation::DAILY);
 
     appender
+        .rotation(rotation)
         .build(directory)
         .expect("failed to create traces appender")
 }

ipc/observability/src/tracing_layers.rs

@@ -28,6 +28,10 @@ where
     S: Subscriber,
     L: Layer<S>,
 {
+    fn on_layer(&mut self, subscriber: &mut S) {
+        self.inner.on_layer(subscriber);
+    }
+
     fn on_event(&self, event: &Event, ctx: Context<S>) {
         if self.domains.is_none() && self.events.is_none() {
             self.inner.on_event(event, ctx);