Critical dependency logging

Cargo.toml

@@ -160,6 +160,9 @@ tempfile = "3"
 tokio = { version = "1", features = ["rt-multi-thread", "sync", "signal"] }
 tokio-stream = { version = "0.1", features = ["sync"] }
 tokio-util = { version = "0.6", features = ["codec", "compat", "time"] }
+tracing-appender = "0.2"
+tracing-core = "0.1"
+tracing-subscriber = "0.3"
 tree_hash = "0.5"
 tree_hash_derive = "0.5"
 url = "2"

boot_node/src/lib.rs

@@ -48,11 +48,8 @@ pub fn run(
         log::Level::Error => drain.filter_level(Level::Error),
     };
 
-    let logger = Logger::root(drain.fuse(), o!());
-    let _scope_guard = slog_scope::set_global_logger(logger);
-    slog_stdlog::init_with_level(debug_level).unwrap();
+    let log = Logger::root(drain.fuse(), o!());
 
-    let log = slog_scope::logger();
     // Run the main function emitting any errors
     if let Err(e) = match eth_spec_id {
         EthSpecId::Minimal => {

common/directory/src/lib.rs

@@ -10,6 +10,7 @@ pub const DEFAULT_NETWORK_DIR: &str = "network";
 pub const DEFAULT_VALIDATOR_DIR: &str = "validators";
 pub const DEFAULT_SECRET_DIR: &str = "secrets";
 pub const DEFAULT_WALLET_DIR: &str = "wallets";
+pub const DEFAULT_TRACING_DIR: &str = "tracing";
 
 /// Base directory name for unnamed testnets passed through the --testnet-dir flag
 pub const CUSTOM_TESTNET_DIR: &str = "custom";

common/logging/Cargo.toml

@@ -20,3 +20,6 @@ parking_lot = { workspace = true }
 serde = { workspace = true }
 serde_json = { workspace = true }
 chrono = { version = "0.4", default-features = false, features = ["clock", "std"] }
+tracing-appender = { workspace = true }
+tracing-subscriber = { workspace = true }
+tracing-core = { workspace = true }

common/logging/src/lib.rs

@@ -6,14 +6,24 @@ use lighthouse_metrics::{
 };
 use slog::Logger;
 use slog_term::Decorator;
+use std::collections::HashMap;
 use std::io::{Result, Write};
+use std::path::PathBuf;
 use std::time::{Duration, Instant};
+use tracing_logging_layer::TRACING_LOGGING_DEPENDENCIES;
 
 pub const MAX_MESSAGE_WIDTH: usize = 40;
 
 pub mod async_record;
 mod sse_logging_components;
+mod tracing_logging_layer;
+mod tracing_metrics_layer;
+
 pub use sse_logging_components::SSELoggingComponents;
+pub use tracing_logging_layer::LoggingLayer;
+pub use tracing_logging_layer::NonBlockingFileWriter;
+pub use tracing_metrics_layer::MetricsLayer;
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
 /// The minimum interval between log messages indicating that a queue is full.
 const LOG_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(30);
@@ -214,6 +224,56 @@ impl TimeLatch {
     }
 }
 
+pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBuf) {
+    let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env()
+        .or_else(|_| tracing_subscriber::EnvFilter::try_new("warn"))
+    {
+        Ok(filter) => filter,
+        Err(e) => {
+            eprintln!("Failed to initialize dependency tracing {e}");
+            return;
+        }
+    };
+
+    let mut file_writer_streams: HashMap<String, NonBlockingFileWriter> = HashMap::new();
+
+    for dependency in TRACING_LOGGING_DEPENDENCIES.iter() {
+        init_file_writer_stream(
+            &mut file_writer_streams,
+            base_tracing_log_path.clone(),
+            dependency,
+            logfile_max_size * 1_024 * 1_024,
+        );
+    }
+
+    if let Err(e) = tracing_subscriber::fmt()
+        .with_env_filter(filter_layer)
+        .finish()
+        .with(MetricsLayer)
+        .with(LoggingLayer {
+            file_writer_streams,
+        })
+        .try_init()
+    {
+        eprintln!("Failed to initialize dependency tracing {e}");
+    }
+}
+
+fn init_file_writer_stream(
+    file_writer_streams: &mut HashMap<String, NonBlockingFileWriter>,
+    base_path: PathBuf,
+    file_name: &str,
+    max_file_size: u64,
+) {
+    let file_path = base_path.join(file_name).with_extension("log");
+    let Ok(file_writer) = NonBlockingFileWriter::new(file_path.as_path(), max_file_size) else {
+        eprintln!("Failed to create tracing file stream for {file_name}");
+        return;
+    };
+
+    file_writer_streams.insert(file_name.to_string(), file_writer);
+}
+
 /// Return a logger suitable for test usage.
 ///
 /// By default no logs will be printed, but they can be enabled via

common/logging/src/tracing_logging_layer.rs

@@ -0,0 +1,137 @@
+use std::collections::HashMap;
+use std::fs::{self, create_dir_all, File, OpenOptions};
+use std::io::Write;
+use std::path::PathBuf;
+use std::sync::mpsc::{self, Sender};
+use std::thread;
+
+lazy_static! {
+    pub static ref TRACING_LOGGING_DEPENDENCIES: Vec<String> =
+        vec!["libp2p".to_string(), "discv5".to_string()];
+}
+
+/// Layer that handles `INFO`, `WARN` and `ERROR` logs emitted per dependency and
+/// writes them to a file. Dependencies are enabled via the `RUST_LOG` env flag.
+pub struct LoggingLayer {
+    pub file_writer_streams: HashMap<String, NonBlockingFileWriter>,
+}
+
+impl<S: tracing_core::Subscriber> tracing_subscriber::layer::Layer<S> for LoggingLayer {
+    fn on_event(
+        &self,
+        event: &tracing_core::Event<'_>,
+        _ctx: tracing_subscriber::layer::Context<'_, S>,
+    ) {
+        let meta = event.metadata();
+
+        let target = match meta.target().split_once("::") {
+            Some((crate_name, _)) => crate_name,
+            None => "unknown",
+        };
+
+        let Some(file_writer) = self.file_writer_streams.get(target) else {
+            return;
+        };
+
+        let mut visitor = LogMessageExtractor {
+            message: String::default(),
+        };
+
+        event.record(&mut visitor);
+
+        match *meta.level() {
+            tracing_core::Level::INFO => {
+                let _ = file_writer.write(visitor.message);
+            }
+            tracing_core::Level::WARN => {
+                let _ = file_writer.write(visitor.message);
+            }
+            tracing_core::Level::ERROR => {
+                let _ = file_writer.write(visitor.message);
+            }
+            _ => {}
+        }
+    }
+}
+
+pub struct NonBlockingFileWriter {
+    sender: Sender<String>,
+}
+
+impl NonBlockingFileWriter {
+    pub fn new(path: &std::path::Path, max_file_size: u64) -> Result<Self, std::io::Error> {
+        let (sender, receiver) = mpsc::channel();
+        let path = path.to_path_buf();
+
+        thread::spawn(move || {
+            if !path.exists() {
+                let mut dir = path.clone();
+                dir.pop();
+
+                // Create the necessary directories for the correct service and network.
+                if !dir.exists() {
+                    let res = create_dir_all(dir);
+
+                    match res {
+                        Ok(_) => (),
+                        Err(e) => {
+                            eprintln!("Failed to create dir: {:?}", e);
+                            return;
+                        }
+                    }
+                }
+            }
+
+            let mut file = match OpenOptions::new().create(true).append(true).open(&path) {
+                Ok(file) => file,
+                Err(e) => {
+                    eprintln!("Failed to open file: {:?}", e);
+                    return;
+                }
+            };
+
+            for message in receiver {
+                let should_clear_file = match NonBlockingFileWriter::get_file_size(&path) {
+                    Ok(file_size) => file_size > max_file_size,
+                    Err(_) => false,
+                };
+
+                if should_clear_file {
+                    let _ = NonBlockingFileWriter::clear_file(&path);
+                }
+
+                if let Err(e) = writeln!(file, "{}", message) {
+                    eprintln!("Failed to write to file: {:?}", e);
+                }
+            }
+        });
+
+        Ok(NonBlockingFileWriter { sender })
+    }
+
+    pub fn write(&self, message: String) -> Result<(), std::io::Error> {
+        self.sender
+            .send(message)
+            .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e))
+    }
+
+    fn get_file_size(path: &PathBuf) -> std::io::Result<u64> {
+        let metadata = fs::metadata(path)?;
+        Ok(metadata.len())
+    }
+
+    fn clear_file(path: &PathBuf) -> std::io::Result<()> {
+        File::create(path)?;
+        Ok(())
+    }
+}
+
+struct LogMessageExtractor {
+    message: String,
+}
+
+impl tracing_core::field::Visit for LogMessageExtractor {
+    fn record_debug(&mut self, _: &tracing_core::Field, value: &dyn std::fmt::Debug) {
+        self.message = format!("{:?}", value);
+    }
+}

common/logging/src/tracing_metrics_layer.rs

@@ -0,0 +1,56 @@
+//! Exposes [`MetricsLayer`]: A tracing layer that registers metrics of logging events.
+
+use lighthouse_metrics as metrics;
+
+lazy_static! {
+    /// Count of `INFO` logs registered per enabled dependency.
+    pub static ref DEP_INFOS_TOTAL: metrics::Result<metrics::IntCounterVec> =
+        metrics::try_create_int_counter_vec(
+            "dep_info_total",
+            "Count of infos logged per enabled dependency",
+            &["target"]
+        );
+    /// Count of `WARN` logs registered per enabled dependency.
+    pub static ref DEP_WARNS_TOTAL: metrics::Result<metrics::IntCounterVec> =
+        metrics::try_create_int_counter_vec(
+            "dep_warn_total",
+            "Count of warns logged per enabled dependency",
+            &["target"]
+        );
+    /// Count of `ERROR` logs registered per enabled dependency.
+    pub static ref DEP_ERRORS_TOTAL: metrics::Result<metrics::IntCounterVec> =
+        metrics::try_create_int_counter_vec(
+            "dep_error_total",
+            "Count of errors logged per enabled dependency",
+            &["target"]
+        );
+}
+
+/// Layer that registers Prometheus metrics for `INFO`, `WARN` and `ERROR` logs emitted per dependency.
+/// Dependencies are enabled via the `RUST_LOG` env flag.
+pub struct MetricsLayer;
+
+impl<S: tracing_core::Subscriber> tracing_subscriber::layer::Layer<S> for MetricsLayer {
+    fn on_event(
+        &self,
+        event: &tracing_core::Event<'_>,
+        _ctx: tracing_subscriber::layer::Context<'_, S>,
+    ) {
+        let meta = event.metadata();
+        if !meta.is_event() {
+            // ignore tracing span events
+            return;
+        }
+        let target = match meta.target().split_once("::") {
+            Some((crate_name, _)) => crate_name,
+            None => "unknown",
+        };
+        let target = &[target];
+        match *meta.level() {
+            tracing_core::Level::INFO => metrics::inc_counter_vec(&DEP_INFOS_TOTAL, target),
+            tracing_core::Level::WARN => metrics::inc_counter_vec(&DEP_WARNS_TOTAL, target),
+            tracing_core::Level::ERROR => metrics::inc_counter_vec(&DEP_ERRORS_TOTAL, target),
+            _ => {}
+        }
+    }
+}