add tracing metrics layer for dependency logging (sigp#4979)

* add metrics layer

* add metrics

* simplify getting the target

* make clippy happy

* fix typos

* unify deps under workspace

* make import statement shorter, fix typos

* enable warn by default, mark flag as deprecated

* do not exit on error when initializing logging fails

* revert exit on error

* adjust bootnode logging

* use target as is by default

* make libp2p events register correctly

* adjust repilcated cli help

* turn on debug logs by default, remove deprecation warning

* suppress output (#5)

---------

Co-authored-by: Age Manning <Age@AgeManning.com>

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-core = "0.1"
+tracing-log = "0.2"
+tracing-subscriber = "0.3"
 tree_hash = "0.5"
 tree_hash_derive = "0.5"
 url = "2"

book/src/help_general.md

@@ -13,8 +13,8 @@ FLAGS:
         --disable-malloc-tuning          If present, do not configure the system allocator. Providing this flag will
                                          generally increase memory usage, it should only be provided when debugging
                                          specific memory allocation issues.
-    -l                                   Enables environment logging giving access to sub-protocol logs such as discv5
-                                         and libp2p
+    -l                                   DEPRECATED Enables environment logging giving access to sub-protocol logs such
+                                         as discv5 and libp2p
     -h, --help                           Prints help information
         --log-color                      Force outputting colors when emitting logs to the terminal.
         --logfile-compress               If present, compress old log files. This can help reduce the space needed to

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/logging/Cargo.toml

@@ -8,15 +8,18 @@ edition = { workspace = true }
 test_logger = [] # Print log output to stderr when running tests instead of dropping it
 
 [dependencies]
-slog = { workspace = true }
-slog-term = { workspace = true }
-tokio = { workspace = true }
-lighthouse_metrics = { workspace = true }
+chrono = { version = "0.4", default-features = false, features = ["clock", "std"] }
 lazy_static = { workspace = true }
-sloggers = { workspace = true }
-slog-async = { workspace = true }
-take_mut = "0.2.2"
+lighthouse_metrics = { workspace = true }
 parking_lot = { workspace = true }
 serde = { workspace = true }
 serde_json = { workspace = true }
-chrono = { version = "0.4", default-features = false, features = ["clock", "std"] }
+slog = { workspace = true }
+slog-async = { workspace = true }
+slog-term = { workspace = true }
+sloggers = { workspace = true }
+take_mut = "0.2.2"
+tokio = { workspace = true }
+tracing-core = { workspace = true }
+tracing-log = { workspace = true }
+tracing-subscriber = { workspace = true }

common/logging/src/lib.rs

@@ -13,7 +13,10 @@ pub const MAX_MESSAGE_WIDTH: usize = 40;
 
 pub mod async_record;
 mod sse_logging_components;
+mod tracing_metrics_layer;
+
 pub use sse_logging_components::SSELoggingComponents;
+pub use tracing_metrics_layer::MetricsLayer;
 
 /// The minimum interval between log messages indicating that a queue is full.
 const LOG_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(30);

common/logging/src/tracing_metrics_layer.rs

@@ -0,0 +1,63 @@
+//! Exposes [`MetricsLayer`]: A tracing layer that registers metrics of logging events.
+
+use lighthouse_metrics as metrics;
+use tracing_log::NormalizeEvent;
+
+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>,
+    ) {
+        // get the event's normalized metadata
+        // this is necessary to get the correct module path for libp2p events
+        let normalized_meta = event.normalized_metadata();
+        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+
+        if !meta.is_event() {
+            // ignore tracing span events
+            return;
+        }
+
+        let full_target = meta.module_path().unwrap_or_else(|| meta.target());
+        let target = full_target
+            .split_once("::")
+            .map(|(name, _rest)| name)
+            .unwrap_or(full_target);
+        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),
+            _ => {}
+        }
+    }
+}

lighthouse/Cargo.toml

@@ -35,7 +35,6 @@ types = { workspace = true }
 bls = { workspace = true }
 ethereum_hashing = { workspace = true }
 clap = { workspace = true }
-env_logger = { workspace = true }
 environment = { workspace = true }
 boot_node = { path = "../boot_node" }
 futures = { workspace = true }
@@ -57,6 +56,8 @@ unused_port = { workspace = true }
 database_manager = { path = "../database_manager" }
 slasher = { workspace = true }
 validator_manager = { path = "../validator_manager" }
+tracing-subscriber = { workspace = true }
+logging = { workspace = true }
 
 [dev-dependencies]
 tempfile = { workspace = true }

lighthouse/src/main.rs

@@ -4,7 +4,6 @@ use beacon_node::ProductionBeaconNode;
 use clap::{App, Arg, ArgMatches};
 use clap_utils::{flags::DISABLE_MALLOC_TUNING_FLAG, get_eth2_network_config};
 use directory::{parse_path_or_default, DEFAULT_BEACON_NODE_DIR, DEFAULT_VALIDATOR_DIR};
-use env_logger::{Builder, Env};
 use environment::{EnvironmentBuilder, LoggerConfig};
 use eth2_network_config::{Eth2NetworkConfig, DEFAULT_HARDCODED_NETWORK, HARDCODED_NET_NAMES};
 use ethereum_hashing::have_sha_extensions;
@@ -15,6 +14,7 @@ use slog::{crit, info};
 use std::path::PathBuf;
 use std::process::exit;
 use task_executor::ShutdownReason;
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 use types::{EthSpec, EthSpecId};
 use validator_client::ProductionValidatorClient;
 
@@ -84,7 +84,8 @@ fn main() {
         .arg(
             Arg::with_name("env_log")
                 .short("l")
-                .help("Enables environment logging giving access to sub-protocol logs such as discv5 and libp2p",
+                .help(
+                    "DEPRECATED Enables environment logging giving access to sub-protocol logs such as discv5 and libp2p",
                 )
                 .takes_value(false),
         )
@@ -364,9 +365,32 @@ fn main() {
         }
     }
 
-    // Debugging output for libp2p and external crates.
-    if matches.is_present("env_log") {
-        Builder::from_env(Env::default()).init();
+    // read the `RUST_LOG` statement
+    let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env()
+        .or_else(|_| tracing_subscriber::EnvFilter::try_new("debug"))
+    {
+        Ok(filter) => filter,
+        Err(e) => {
+            eprintln!("Failed to initialize dependency logging {e}");
+            exit(1)
+        }
+    };
+
+    let turn_on_terminal_logs = matches.is_present("env_log");
+
+    if let Err(e) = tracing_subscriber::fmt()
+        .with_env_filter(filter_layer)
+        .with_writer(move || {
+            tracing_subscriber::fmt::writer::OptionalWriter::<std::io::Stdout>::from(
+                turn_on_terminal_logs.then(std::io::stdout),
+            )
+        })
+        .finish()
+        .with(logging::MetricsLayer)
+        .try_init()
+    {
+        eprintln!("Failed to initialize dependency logging {e}");
+        exit(1)
     }
 
     let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| {