From 0087a0e8aeadf8028aae445e4b9db3aa6be18868 Mon Sep 17 00:00:00 2001 From: Diva M Date: Mon, 4 Dec 2023 16:00:26 -0500 Subject: [PATCH 01/30] add metrics layer --- Cargo.lock | 12 +++-- common/logging/Cargo.toml | 2 + common/logging/src/lib.rs | 1 + common/logging/src/tracing_metrics_layer.rs | 59 +++++++++++++++++++++ 4 files changed, 69 insertions(+), 5 deletions(-) create mode 100644 common/logging/src/tracing_metrics_layer.rs diff --git a/Cargo.lock b/Cargo.lock index 9c1b591349b..ffa373f3e48 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4646,6 +4646,8 @@ dependencies = [ "sloggers", "take_mut", "tokio", + "tracing-core", + "tracing-subscriber", ] [[package]] @@ -8057,20 +8059,20 @@ dependencies = [ [[package]] name = "tracing-log" -version = "0.1.3" +version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" dependencies = [ - "lazy_static", "log", + "once_cell", "tracing-core", ] [[package]] name = "tracing-subscriber" -version = "0.3.17" +version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" +checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ "matchers", "nu-ansi-term", diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index 9c5321591bc..a75eb8b049b 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -20,3 +20,5 @@ parking_lot = { workspace = true } serde = { workspace = true } serde_json = { workspace = true } chrono = { version = "0.4", default-features = false, features = ["clock", "std"] } +tracing-subscriber = "0.3.18" +tracing-core = "0.1.32" diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index a9ad25f3f3e..8496d4881f0 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -14,6 +14,7 @@ pub const MAX_MESSAGE_WIDTH: usize = 40; pub mod async_record; mod sse_logging_components; pub use sse_logging_components::SSELoggingComponents; +pub mod tracing_metrics_layer; /// The minimum interval between log messages indicating that a queue is full. const LOG_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(30); diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs new file mode 100644 index 00000000000..e5bc9617fac --- /dev/null +++ b/common/logging/src/tracing_metrics_layer.rs @@ -0,0 +1,59 @@ +//! Exposes [`MetricsLayer`]: A tracing layer that registers metrics of logging events. + +use lighthouse_metrics as metrics; + +lazy_static! { + pub static ref DEP_INFOS_TOTAL: metrics::Result = + metrics::try_create_int_counter_vec( + "dep_info_total", + "Count of infos logged per enabled dependecy", + &["target"] + ); + pub static ref DEP_WARNS_TOTAL: metrics::Result = + metrics::try_create_int_counter_vec( + "dep_warn_total", + "Count of warns logged per enabled dependecy", + &["target"] + ); + pub static ref DEP_ERRORS_TOTAL: metrics::Result = + metrics::try_create_int_counter_vec( + "dep_error_total", + "Count of errors logged per enabled dependecy", + &["target"] + ); +} + +/// Depedencies that get a metric label on their own. Any other dep will be registered as `"other"`. +const ENABLED_DEPENDENCY_TARGETS: &[&'static str] = &["discv5", "libp2p"]; + +pub struct MetricsLayer {} + +impl tracing_subscriber::layer::Layer for MetricsLayer { + fn on_event( + &self, + event: &tracing_core::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let meta = event.metadata(); + if !meta.is_event() { + return; + } + let target = match meta.target().split_once("::") { + Some((crate_name, _)) => { + if ENABLED_DEPENDENCY_TARGETS.contains(&crate_name) { + crate_name + } else { + "other" + } + } + 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), + _ => {} + } + } +} From 39b25336dec66bbfa2fc270cc36d619e7cf47ee9 Mon Sep 17 00:00:00 2001 From: Diva M Date: Mon, 4 Dec 2023 17:15:10 -0500 Subject: [PATCH 02/30] add metrics --- Cargo.lock | 3 ++- lighthouse/Cargo.toml | 3 ++- lighthouse/src/main.rs | 21 +++++++++++++++++++-- 3 files changed, 23 insertions(+), 4 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index ffa373f3e48..39bf827a01c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4462,7 +4462,6 @@ dependencies = [ "clap_utils", "database_manager", "directory", - "env_logger 0.9.3", "environment", "eth1", "eth2", @@ -4473,6 +4472,7 @@ dependencies = [ "lighthouse_metrics", "lighthouse_network", "lighthouse_version", + "logging", "malloc_utils", "sensitive_url", "serde", @@ -4484,6 +4484,7 @@ dependencies = [ "sloggers", "task_executor", "tempfile", + "tracing-subscriber", "types", "unused_port", "validator_client", diff --git a/lighthouse/Cargo.toml b/lighthouse/Cargo.toml index 48b4eb037ab..30475b4085a 100644 --- a/lighthouse/Cargo.toml +++ b/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 = "0.3.18" +logging = { workspace = true } [dev-dependencies] tempfile = { workspace = true } diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index edf661abab3..00a7bdd8983 100644 --- a/lighthouse/src/main.rs +++ b/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; @@ -366,7 +366,24 @@ 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() { + Ok(filter) => filter, + Err(e) => { + eprintln!("Failed to initialize dependecy logging {e}"); + exit(1) + } + }; + + if let Err(e) = tracing_subscriber::fmt() + .with_env_filter(filter_layer) + .finish() + .with(logging::tracing_metrics_layer::MetricsLayer {}) + .try_init() + { + eprintln!("Failed to initialize dependecy logging {e}"); + exit(1) + } } let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| { From 57baf2dfbae68856251e23cd070341a2e567480e Mon Sep 17 00:00:00 2001 From: Diva M Date: Mon, 4 Dec 2023 18:31:01 -0500 Subject: [PATCH 03/30] simplify getting the target --- common/logging/src/tracing_metrics_layer.rs | 13 ++----------- 1 file changed, 2 insertions(+), 11 deletions(-) diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index e5bc9617fac..33e2d3dbd82 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -23,9 +23,6 @@ lazy_static! { ); } -/// Depedencies that get a metric label on their own. Any other dep will be registered as `"other"`. -const ENABLED_DEPENDENCY_TARGETS: &[&'static str] = &["discv5", "libp2p"]; - pub struct MetricsLayer {} impl tracing_subscriber::layer::Layer for MetricsLayer { @@ -39,14 +36,8 @@ impl tracing_subscriber::layer::Layer for Metric return; } let target = match meta.target().split_once("::") { - Some((crate_name, _)) => { - if ENABLED_DEPENDENCY_TARGETS.contains(&crate_name) { - crate_name - } else { - "other" - } - } - None => "unknown", + Some((crate_name, _)) => crate_name, + None => "unknown" /* TODO(@divma): not sure if leaving here the full target is a good idea, maybe? maybe not?*/, }; let target = &[target]; match meta.level() { From 71ad6a04d8058ce873acc4e6a9bea64bdaf02fd4 Mon Sep 17 00:00:00 2001 From: Diva M Date: Tue, 5 Dec 2023 09:29:57 -0500 Subject: [PATCH 04/30] make clippy happy --- common/logging/src/tracing_metrics_layer.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index 33e2d3dbd82..666e657daa0 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -37,13 +37,13 @@ impl tracing_subscriber::layer::Layer for Metric } let target = match meta.target().split_once("::") { Some((crate_name, _)) => crate_name, - None => "unknown" /* TODO(@divma): not sure if leaving here the full target is a good idea, maybe? maybe not?*/, + 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), + 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), _ => {} } } From dc46e9294605a60a5eaf46fd48716bdec6853714 Mon Sep 17 00:00:00 2001 From: Diva M Date: Tue, 5 Dec 2023 10:51:17 -0500 Subject: [PATCH 05/30] fix typos --- common/logging/src/tracing_metrics_layer.rs | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index 666e657daa0..1425d2e25f1 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -3,26 +3,31 @@ use lighthouse_metrics as metrics; lazy_static! { + /// Count of `INFO` logs registered per enabled dependency. pub static ref DEP_INFOS_TOTAL: metrics::Result = metrics::try_create_int_counter_vec( "dep_info_total", - "Count of infos logged per enabled dependecy", + "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::try_create_int_counter_vec( "dep_warn_total", - "Count of warns logged per enabled dependecy", + "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::try_create_int_counter_vec( "dep_error_total", - "Count of errors logged per enabled dependecy", + "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 tracing_subscriber::layer::Layer for MetricsLayer { @@ -33,6 +38,7 @@ impl tracing_subscriber::layer::Layer for Metric ) { let meta = event.metadata(); if !meta.is_event() { + // ignore tracing span events return; } let target = match meta.target().split_once("::") { From b3e5ea09e331c1f3cb950ab2224165ce5a56be4b Mon Sep 17 00:00:00 2001 From: Diva M Date: Tue, 5 Dec 2023 10:51:33 -0500 Subject: [PATCH 06/30] unify deps under workspace --- Cargo.toml | 2 ++ common/logging/Cargo.toml | 4 ++-- lighthouse/Cargo.toml | 2 +- 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 9adb913ff5e..c7eeb6a333f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -160,6 +160,8 @@ 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-subscriber = "0.3" tree_hash = "0.5" tree_hash_derive = "0.5" url = "2" diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index a75eb8b049b..da2efb252e8 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -20,5 +20,5 @@ parking_lot = { workspace = true } serde = { workspace = true } serde_json = { workspace = true } chrono = { version = "0.4", default-features = false, features = ["clock", "std"] } -tracing-subscriber = "0.3.18" -tracing-core = "0.1.32" +tracing-subscriber = { workspace = true } +tracing-core = { workspace = true } diff --git a/lighthouse/Cargo.toml b/lighthouse/Cargo.toml index 30475b4085a..f36c3a8c7c7 100644 --- a/lighthouse/Cargo.toml +++ b/lighthouse/Cargo.toml @@ -56,7 +56,7 @@ unused_port = { workspace = true } database_manager = { path = "../database_manager" } slasher = { workspace = true } validator_manager = { path = "../validator_manager" } -tracing-subscriber = "0.3.18" +tracing-subscriber = { workspace = true } logging = { workspace = true } [dev-dependencies] From 94573c7dec150a62bda1b10d022790f230eeebe2 Mon Sep 17 00:00:00 2001 From: Diva M Date: Tue, 5 Dec 2023 10:56:03 -0500 Subject: [PATCH 07/30] make import statement shorter, fix typos --- common/logging/src/lib.rs | 4 +++- common/logging/src/tracing_metrics_layer.rs | 2 +- lighthouse/src/main.rs | 8 ++++---- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index 8496d4881f0..80fc00a00f2 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -13,8 +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 mod tracing_metrics_layer; +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); diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index 1425d2e25f1..c048bb74146 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -28,7 +28,7 @@ lazy_static! { /// 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 {} +pub struct MetricsLayer; impl tracing_subscriber::layer::Layer for MetricsLayer { fn on_event( diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 00a7bdd8983..3a60cade597 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -364,13 +364,13 @@ fn main() { } } - // Debugging output for libp2p and external crates. + // Debugging output for discv5, libp2p and external crates. if matches.is_present("env_log") { // read the `RUST_LOG` statement let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env() { Ok(filter) => filter, Err(e) => { - eprintln!("Failed to initialize dependecy logging {e}"); + eprintln!("Failed to initialize dependency logging {e}"); exit(1) } }; @@ -378,10 +378,10 @@ fn main() { if let Err(e) = tracing_subscriber::fmt() .with_env_filter(filter_layer) .finish() - .with(logging::tracing_metrics_layer::MetricsLayer {}) + .with(logging::MetricsLayer) .try_init() { - eprintln!("Failed to initialize dependecy logging {e}"); + eprintln!("Failed to initialize dependency logging {e}"); exit(1) } } From a18c1895c6d51741fe3165da7ebac8ebb8a0de2f Mon Sep 17 00:00:00 2001 From: Diva M Date: Wed, 6 Dec 2023 10:57:17 -0500 Subject: [PATCH 08/30] enable warn by default, mark flag as deprecated --- lighthouse/src/main.rs | 35 ++++++++++++++++++++--------------- 1 file changed, 20 insertions(+), 15 deletions(-) diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 3a60cade597..1219c3e1ec3 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -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), ) @@ -366,24 +367,28 @@ fn main() { // Debugging output for discv5, libp2p and external crates. if matches.is_present("env_log") { - // read the `RUST_LOG` statement - let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env() { - Ok(filter) => filter, - Err(e) => { - eprintln!("Failed to initialize dependency logging {e}"); - exit(1) - } - }; + eprintln!("The -l flag is DEPRECATED. Dependency logging will be on by default."); + } - if let Err(e) = tracing_subscriber::fmt() - .with_env_filter(filter_layer) - .finish() - .with(logging::MetricsLayer) - .try_init() - { + // read the `RUST_LOG` statement + 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 logging {e}"); exit(1) } + }; + + if let Err(e) = tracing_subscriber::fmt() + .with_env_filter(filter_layer) + .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| { From 908ad21b40d7b013e60038351e83ddaebbada900 Mon Sep 17 00:00:00 2001 From: Diva M Date: Wed, 6 Dec 2023 12:02:59 -0500 Subject: [PATCH 09/30] do not exit on error when initializing logging fails --- lighthouse/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 1219c3e1ec3..0afce3fefe6 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -388,7 +388,7 @@ fn main() { .try_init() { eprintln!("Failed to initialize dependency logging {e}"); - exit(1) + // NOTE: this can fail in testing environments where a logger is already set } let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| { From 9dd307d361ba75d75bb2642e27e1dd29b46cc0ce Mon Sep 17 00:00:00 2001 From: Diva M Date: Wed, 6 Dec 2023 13:08:36 -0500 Subject: [PATCH 10/30] revert exit on error --- lighthouse/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 0afce3fefe6..1219c3e1ec3 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -388,7 +388,7 @@ fn main() { .try_init() { eprintln!("Failed to initialize dependency logging {e}"); - // NOTE: this can fail in testing environments where a logger is already set + exit(1) } let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| { From 9a6d862ebd374f06a3487bd3b8ec6effd9f74805 Mon Sep 17 00:00:00 2001 From: Diva M Date: Wed, 6 Dec 2023 14:03:42 -0500 Subject: [PATCH 11/30] adjust bootnode logging --- boot_node/src/lib.rs | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/boot_node/src/lib.rs b/boot_node/src/lib.rs index d76e7906b20..0421ce2684d 100644 --- a/boot_node/src/lib.rs +++ b/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 => { From 5b2395ba9239757c53dbb43f5d7a7cd6ec09876a Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Wed, 6 Dec 2023 14:39:20 -0800 Subject: [PATCH 12/30] add logging layer --- Cargo.lock | 13 ++++ Cargo.toml | 1 + common/logging/Cargo.toml | 1 + common/logging/src/lib.rs | 2 + common/logging/src/tracing_logging_layer.rs | 83 +++++++++++++++++++++ lighthouse/src/main.rs | 1 + 6 files changed, 101 insertions(+) create mode 100644 common/logging/src/tracing_logging_layer.rs diff --git a/Cargo.lock b/Cargo.lock index 39bf827a01c..bac85c68ecb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4647,6 +4647,7 @@ dependencies = [ "sloggers", "take_mut", "tokio", + "tracing-appender", "tracing-core", "tracing-subscriber", ] @@ -8027,6 +8028,18 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf" +dependencies = [ + "crossbeam-channel", + "thiserror", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.27" diff --git a/Cargo.toml b/Cargo.toml index c7eeb6a333f..14336d3f25c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -160,6 +160,7 @@ 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" diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index da2efb252e8..8aba08bd257 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -20,5 +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 } diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index 80fc00a00f2..b90ad307ef8 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -14,9 +14,11 @@ pub const MAX_MESSAGE_WIDTH: usize = 40; pub mod async_record; mod sse_logging_components; mod tracing_metrics_layer; +mod tracing_logging_layer; pub use sse_logging_components::SSELoggingComponents; pub use tracing_metrics_layer::MetricsLayer; +pub use tracing_logging_layer::LoggingLayer; /// The minimum interval between log messages indicating that a queue is full. const LOG_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(30); diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs new file mode 100644 index 00000000000..3065e9c74e6 --- /dev/null +++ b/common/logging/src/tracing_logging_layer.rs @@ -0,0 +1,83 @@ +use std::fs; +use std::path::{Path, PathBuf}; +use std::time::{SystemTime, Duration}; + +/// 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; + +impl tracing_subscriber::layer::Layer 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 target = &[target]; + + match *meta.level() { + tracing_core::Level::INFO => {}, + tracing_core::Level::WARN => {}, + tracing_core::Level::ERROR => {}, + _ => {} + } + } +} + +// Delete the oldest file in a supplied directory +// as long as the directory contains file count >= min_file_count. +// Note that we ignore child directories. +fn delete_oldest_file(dir: &Path, min_file_count: u32) -> std::io::Result<()> { + let mut oldest_write: Option = None; + let mut file_to_delete: Option = None; + let mut file_count = 0u32; + if dir.is_dir() { + for entry in fs::read_dir(dir)? { + let entry = entry?; + let path = entry.path(); + if path.is_dir() { + // TODO raise an error + return Ok(()) + } else { + let last_write = get_last_modified_date(&path)?; + + file_count += 1; + + let Some(write) = oldest_write else { + oldest_write = Some(last_write); + file_to_delete = Some(path); + continue + }; + + if last_write < write { + oldest_write = Some(last_write); + file_to_delete = Some(path); + } + } + } + } + + let Some(file) = file_to_delete else { + // TODO + return Ok(()); + }; + + if file_count >= min_file_count { + + // TODO delete file + } + + Ok(()) +} + +fn get_last_modified_date(path: &std::path::Path) -> std::io::Result { + let metadata = fs::metadata(path)?; + let last_modified = metadata.modified()?; + Ok(last_modified) +} \ No newline at end of file diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 1219c3e1ec3..f9da48dde05 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -385,6 +385,7 @@ fn main() { .with_env_filter(filter_layer) .finish() .with(logging::MetricsLayer) + .with(logging::LoggingLayer) .try_init() { eprintln!("Failed to initialize dependency logging {e}"); From de2840e875b861869ab74e91f3a966bc03613e33 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Wed, 6 Dec 2023 15:57:28 -0800 Subject: [PATCH 13/30] non blocking file writer --- common/logging/src/tracing_logging_layer.rs | 91 +++++++++++---------- 1 file changed, 49 insertions(+), 42 deletions(-) diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 3065e9c74e6..2d27041285c 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,5 +1,8 @@ -use std::fs; +use std::fs::{self, File, OpenOptions}; use std::path::{Path, PathBuf}; +use std::sync::mpsc::{Sender, self}; +use std::thread; +use std::io::Write; use std::time::{SystemTime, Duration}; /// Layer that handles `INFO`, `WARN` and `ERROR` logs emitted per dependency and @@ -30,54 +33,58 @@ impl tracing_subscriber::layer::Layer for Loggin } } -// Delete the oldest file in a supplied directory -// as long as the directory contains file count >= min_file_count. -// Note that we ignore child directories. -fn delete_oldest_file(dir: &Path, min_file_count: u32) -> std::io::Result<()> { - let mut oldest_write: Option = None; - let mut file_to_delete: Option = None; - let mut file_count = 0u32; - if dir.is_dir() { - for entry in fs::read_dir(dir)? { - let entry = entry?; - let path = entry.path(); - if path.is_dir() { - // TODO raise an error - return Ok(()) - } else { - let last_write = get_last_modified_date(&path)?; - - file_count += 1; - - let Some(write) = oldest_write else { - oldest_write = Some(last_write); - file_to_delete = Some(path); - continue +struct NonBlockingFileWriter { + sender: Sender, + path: PathBuf, +} + +impl NonBlockingFileWriter { + fn new(path: &std::path::Path) -> Result { + let (sender, receiver) = mpsc::channel(); + let path = path.to_path_buf(); + + thread::spawn(move || { + let mut file = match OpenOptions::new().create(true).append(true).open(&path) { + Ok(file) => file, + Err(e) => { + eprintln!("Failed to open file: {:?}", e); + return; + } + }; + + let mut should_clear_file = false; + + for message in receiver { + should_clear_file = match NonBlockingFileWriter::get_file_size(&path) { + Ok(file_size) => file_size > 0u64, + Err(_) => false, }; - if last_write < write { - oldest_write = Some(last_write); - file_to_delete = Some(path); + if should_clear_file { + NonBlockingFileWriter::clear_file(&path); + } + + if let Err(e) = writeln!(file, "{}", message) { + eprintln!("Failed to write to file: {:?}", e); } } - } - } + }); - let Some(file) = file_to_delete else { - // TODO - return Ok(()); - }; + Ok(NonBlockingFileWriter { sender, path }) - if file_count >= min_file_count { - - // TODO delete file } - Ok(()) -} + 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_last_modified_date(path: &std::path::Path) -> std::io::Result { - let metadata = fs::metadata(path)?; - let last_modified = metadata.modified()?; - Ok(last_modified) + fn get_file_size(path: &PathBuf) -> std::io::Result { + let metadata = fs::metadata(path)?; + Ok(metadata.len()) + } + + fn clear_file(path: &PathBuf) -> std::io::Result<()> { + File::create(path)?; + Ok(()) + } } \ No newline at end of file From d6ff17e72dbc7efe340b65ffee02dc2f78e89940 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Wed, 6 Dec 2023 18:57:46 -0800 Subject: [PATCH 14/30] non blocking file writer --- common/logging/src/lib.rs | 4 +- common/logging/src/tracing_logging_layer.rs | 70 ++++++++++++++------- 2 files changed, 51 insertions(+), 23 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index b90ad307ef8..03eb654adfc 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -13,12 +13,12 @@ pub const MAX_MESSAGE_WIDTH: usize = 40; pub mod async_record; mod sse_logging_components; -mod tracing_metrics_layer; mod tracing_logging_layer; +mod tracing_metrics_layer; pub use sse_logging_components::SSELoggingComponents; -pub use tracing_metrics_layer::MetricsLayer; pub use tracing_logging_layer::LoggingLayer; +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); diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 2d27041285c..43b2b12a259 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,9 +1,24 @@ +use std::collections::HashMap; use std::fs::{self, File, OpenOptions}; +use std::io::Write; use std::path::{Path, PathBuf}; -use std::sync::mpsc::{Sender, self}; +use std::sync::mpsc::{self, Sender}; use std::thread; -use std::io::Write; -use std::time::{SystemTime, Duration}; + +pub const MAX_FILE_SIZE_IN_BYTES: u64 = 100_000_000; + +pub const BASE_FILE_PATH: &str = ""; + +lazy_static! { + pub static ref FILE_WRITER_STREAMS: HashMap> = { + let mut m = HashMap::new(); + let libp2p_logging_thread = NonBlockingFileWriter::new(Path::new("libp2p")).ok(); + let discv5_logging_thread = NonBlockingFileWriter::new(Path::new("discv5")).ok(); + m.insert("libp2p".to_string(), libp2p_logging_thread); + m.insert("discv5".to_string(), discv5_logging_thread); + m + }; +} /// 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. @@ -22,24 +37,38 @@ impl tracing_subscriber::layer::Layer for Loggin None => "unknown", }; - let target = &[target]; + let Some(get_file_writer_stream) = FILE_WRITER_STREAMS.get(target) else { + return; + }; + + let Some(file_writer) = get_file_writer_stream else { + return; + }; match *meta.level() { - tracing_core::Level::INFO => {}, - tracing_core::Level::WARN => {}, - tracing_core::Level::ERROR => {}, + tracing_core::Level::INFO => { + let _ = file_writer.write("TEST".to_string()); + () + } + tracing_core::Level::WARN => { + let _ = file_writer.write("TEST".to_string()); + () + } + tracing_core::Level::ERROR => { + let _ = file_writer.write("TEST".to_string()); + () + } _ => {} } } } -struct NonBlockingFileWriter { +pub struct NonBlockingFileWriter { sender: Sender, - path: PathBuf, } impl NonBlockingFileWriter { - fn new(path: &std::path::Path) -> Result { + pub fn new(path: &std::path::Path) -> Result { let (sender, receiver) = mpsc::channel(); let path = path.to_path_buf(); @@ -52,16 +81,14 @@ impl NonBlockingFileWriter { } }; - let mut should_clear_file = false; - for message in receiver { - should_clear_file = match NonBlockingFileWriter::get_file_size(&path) { - Ok(file_size) => file_size > 0u64, + let should_clear_file = match NonBlockingFileWriter::get_file_size(&path) { + Ok(file_size) => file_size > MAX_FILE_SIZE_IN_BYTES, Err(_) => false, }; if should_clear_file { - NonBlockingFileWriter::clear_file(&path); + let _ = NonBlockingFileWriter::clear_file(&path); } if let Err(e) = writeln!(file, "{}", message) { @@ -70,21 +97,22 @@ impl NonBlockingFileWriter { } }); - Ok(NonBlockingFileWriter { sender, path }) - + Ok(NonBlockingFileWriter { sender }) } - 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)) + 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 { let metadata = fs::metadata(path)?; Ok(metadata.len()) } - + fn clear_file(path: &PathBuf) -> std::io::Result<()> { File::create(path)?; Ok(()) } -} \ No newline at end of file +} From a158865d1e73fd38b5532c2f73f7aeebda27a869 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Thu, 7 Dec 2023 14:08:14 -0800 Subject: [PATCH 15/30] add tracing visitor --- common/logging/src/tracing_logging_layer.rs | 20 +++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 43b2b12a259..2ffc798285c 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -45,17 +45,21 @@ impl tracing_subscriber::layer::Layer for Loggin return; }; + let mut visitor = LogMessageExtractor { message: String::default()}; + + event.record(&mut visitor); + match *meta.level() { tracing_core::Level::INFO => { - let _ = file_writer.write("TEST".to_string()); + let _ = file_writer.write(visitor.message); () } tracing_core::Level::WARN => { - let _ = file_writer.write("TEST".to_string()); + let _ = file_writer.write(visitor.message); () } tracing_core::Level::ERROR => { - let _ = file_writer.write("TEST".to_string()); + let _ = file_writer.write(visitor.message); () } _ => {} @@ -116,3 +120,13 @@ impl NonBlockingFileWriter { Ok(()) } } + +struct LogMessageExtractor { + message: String, +} + +impl tracing_core::field::Visit for LogMessageExtractor { + fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) { + self.message= format!("{}\n{}={:?}", self.message, field.name(), value); + } +} \ No newline at end of file From 85deec7358eb3da5f6f362e4a55918088761c07b Mon Sep 17 00:00:00 2001 From: Diva M Date: Sun, 10 Dec 2023 11:24:27 -0500 Subject: [PATCH 16/30] use target as is by default --- common/logging/src/tracing_metrics_layer.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index c048bb74146..7e24a542026 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -43,7 +43,7 @@ impl tracing_subscriber::layer::Layer for Metric } let target = match meta.target().split_once("::") { Some((crate_name, _)) => crate_name, - None => "unknown", + None => meta.target(), }; let target = &[target]; match *meta.level() { From 46e0ec981a34a511427d4c37a837b9ed4e584ccb Mon Sep 17 00:00:00 2001 From: Diva M Date: Sun, 10 Dec 2023 21:41:39 -0500 Subject: [PATCH 17/30] make libp2p events register correctly --- Cargo.lock | 1 + Cargo.toml | 1 + common/logging/Cargo.toml | 19 ++++++++++--------- common/logging/src/tracing_metrics_layer.rs | 17 ++++++++++++----- 4 files changed, 24 insertions(+), 14 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 39bf827a01c..e722626b1dc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4648,6 +4648,7 @@ dependencies = [ "take_mut", "tokio", "tracing-core", + "tracing-log", "tracing-subscriber", ] diff --git a/Cargo.toml b/Cargo.toml index c7eeb6a333f..4ac1b3dba2d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -161,6 +161,7 @@ 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" diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index da2efb252e8..6975711651b 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -8,17 +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"] } -tracing-subscriber = { workspace = true } +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 } diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs index 7e24a542026..08c323ee890 100644 --- a/common/logging/src/tracing_metrics_layer.rs +++ b/common/logging/src/tracing_metrics_layer.rs @@ -1,6 +1,7 @@ //! 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. @@ -36,15 +37,21 @@ impl tracing_subscriber::layer::Layer for Metric event: &tracing_core::Event<'_>, _ctx: tracing_subscriber::layer::Context<'_, S>, ) { - let meta = event.metadata(); + // 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 target = match meta.target().split_once("::") { - Some((crate_name, _)) => crate_name, - None => meta.target(), - }; + + 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), From f6c4d27e6c7efeef064af0703ca398dfea3c6b52 Mon Sep 17 00:00:00 2001 From: Diva M Date: Sun, 10 Dec 2023 22:23:19 -0500 Subject: [PATCH 18/30] adjust repilcated cli help --- book/src/help_general.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/book/src/help_general.md b/book/src/help_general.md index 7169884cdc5..fbe05693e70 100644 --- a/book/src/help_general.md +++ b/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 From bedf55f75cf400fbaa8ae03845bff1988e3dc50c Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Mon, 11 Dec 2023 14:02:50 -0800 Subject: [PATCH 19/30] refactor tracing layer --- common/directory/src/lib.rs | 1 + common/logging/src/lib.rs | 58 +++++++++++++++++++ common/logging/src/tracing_logging_layer.rs | 62 ++++++++++++--------- lighthouse/src/main.rs | 46 ++++++++++----- 4 files changed, 129 insertions(+), 38 deletions(-) diff --git a/common/directory/src/lib.rs b/common/directory/src/lib.rs index 62b98aab94e..e8585c504a0 100644 --- a/common/directory/src/lib.rs +++ b/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"; diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index 03eb654adfc..3b3d6119764 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -6,8 +6,12 @@ use lighthouse_metrics::{ }; use slog::Logger; use slog_term::Decorator; +use sloggers::file; +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; @@ -18,7 +22,9 @@ 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); @@ -219,6 +225,58 @@ 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 = 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, + ); + } + + if let Err(e) = tracing_subscriber::fmt() + .with_env_filter(filter_layer) + .finish() + .with(MetricsLayer) + .with(LoggingLayer { + file_writer_streams, + }) + .try_init() + { + // TODO + eprintln!("Failed to initialize dependency tracing {e}"); + return; + } +} + +fn init_file_writer_stream( + file_writer_streams: &mut HashMap, + 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 diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 2ffc798285c..1d3a61517fd 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,28 +1,20 @@ use std::collections::HashMap; -use std::fs::{self, File, OpenOptions}; +use std::fs::{self, create_dir_all, File, OpenOptions}; use std::io::Write; -use std::path::{Path, PathBuf}; +use std::path::PathBuf; use std::sync::mpsc::{self, Sender}; use std::thread; -pub const MAX_FILE_SIZE_IN_BYTES: u64 = 100_000_000; - -pub const BASE_FILE_PATH: &str = ""; - lazy_static! { - pub static ref FILE_WRITER_STREAMS: HashMap> = { - let mut m = HashMap::new(); - let libp2p_logging_thread = NonBlockingFileWriter::new(Path::new("libp2p")).ok(); - let discv5_logging_thread = NonBlockingFileWriter::new(Path::new("discv5")).ok(); - m.insert("libp2p".to_string(), libp2p_logging_thread); - m.insert("discv5".to_string(), discv5_logging_thread); - m - }; + pub static ref TRACING_LOGGING_DEPENDENCIES: Vec = + 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 struct LoggingLayer { + pub file_writer_streams: HashMap, +} impl tracing_subscriber::layer::Layer for LoggingLayer { fn on_event( @@ -37,16 +29,14 @@ impl tracing_subscriber::layer::Layer for Loggin None => "unknown", }; - let Some(get_file_writer_stream) = FILE_WRITER_STREAMS.get(target) else { + let Some(file_writer) = self.file_writer_streams.get(target) else { return; }; - let Some(file_writer) = get_file_writer_stream else { - return; + let mut visitor = LogMessageExtractor { + message: String::default(), }; - let mut visitor = LogMessageExtractor { message: String::default()}; - event.record(&mut visitor); match *meta.level() { @@ -72,11 +62,31 @@ pub struct NonBlockingFileWriter { } impl NonBlockingFileWriter { - pub fn new(path: &std::path::Path) -> Result { + pub fn new(path: &std::path::Path, max_file_size: u64) -> Result { 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); + + // If the directories cannot be created, warn and disable the logger. + match res { + Ok(_) => (), + Err(e) => { + eprintln!("Failed to create dir: {:?}", e); + return; + } + } + } + } + + eprintln!("{:?}", path); let mut file = match OpenOptions::new().create(true).append(true).open(&path) { Ok(file) => file, Err(e) => { @@ -87,7 +97,7 @@ impl NonBlockingFileWriter { for message in receiver { let should_clear_file = match NonBlockingFileWriter::get_file_size(&path) { - Ok(file_size) => file_size > MAX_FILE_SIZE_IN_BYTES, + Ok(file_size) => file_size > max_file_size, Err(_) => false, }; @@ -126,7 +136,9 @@ struct LogMessageExtractor { } impl tracing_core::field::Visit for LogMessageExtractor { - fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) { - self.message= format!("{}\n{}={:?}", self.message, field.name(), value); + fn record_debug(&mut self, _: &tracing_core::Field, value: &dyn std::fmt::Debug) { + self.message = format!("{:?}", value); } -} \ No newline at end of file +} + +pub fn create_tracing_logging_layer() {} diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index f9da48dde05..34813481b19 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -3,7 +3,10 @@ mod metrics; 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 directory::{ + parse_path_or_default, DEFAULT_BEACON_NODE_DIR, DEFAULT_ROOT_DIR, DEFAULT_TRACING_DIR, + DEFAULT_VALIDATOR_DIR, +}; use environment::{EnvironmentBuilder, LoggerConfig}; use eth2_network_config::{Eth2NetworkConfig, DEFAULT_HARDCODED_NETWORK, HARDCODED_NET_NAMES}; use ethereum_hashing::have_sha_extensions; @@ -11,6 +14,7 @@ use futures::TryFutureExt; use lighthouse_version::VERSION; use malloc_utils::configure_memory_allocator; use slog::{crit, info}; +use std::collections::HashMap; use std::path::PathBuf; use std::process::exit; use task_executor::ShutdownReason; @@ -381,17 +385,6 @@ fn main() { } }; - if let Err(e) = tracing_subscriber::fmt() - .with_env_filter(filter_layer) - .finish() - .with(logging::MetricsLayer) - .with(logging::LoggingLayer) - .try_init() - { - eprintln!("Failed to initialize dependency logging {e}"); - exit(1) - } - let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| { let eth_spec_id = eth2_network_config.eth_spec_id()?; @@ -533,7 +526,7 @@ fn run( }; let logger_config = LoggerConfig { - path: log_path, + path: log_path.clone(), debug_level: String::from(debug_level), logfile_debug_level: String::from(logfile_debug_level), log_format: log_format.map(String::from), @@ -556,6 +549,33 @@ fn run( let log = environment.core_context().log().clone(); + // read the `RUST_LOG` statement + 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 logging {e}"); + exit(1) + } + }; + + let mut tracing_log_path: Option = clap_utils::parse_optional(matches, "logfile")?; + + if tracing_log_path.is_none() { + tracing_log_path = match matches.subcommand() { + (&_, _) => Some( + parse_path_or_default(matches, "datadir")? + .join(DEFAULT_BEACON_NODE_DIR) + .join("tracing"), + ), + } + }; + + let path = tracing_log_path.clone().unwrap(); + + logging::create_tracing_layer(logfile_max_size, path); + // Allow Prometheus to export the time at which the process was started. metrics::expose_process_start_time(&log); From 7e227a0c0e05497c1fcbd5c078dcb9f1f108dd37 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Mon, 11 Dec 2023 14:17:32 -0800 Subject: [PATCH 20/30] linting --- common/logging/src/lib.rs | 3 -- common/logging/src/tracing_logging_layer.rs | 5 --- lighthouse/src/main.rs | 43 ++++----------------- 3 files changed, 7 insertions(+), 44 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index 3b3d6119764..843f0f44fc6 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -6,7 +6,6 @@ use lighthouse_metrics::{ }; use slog::Logger; use slog_term::Decorator; -use sloggers::file; use std::collections::HashMap; use std::io::{Result, Write}; use std::path::PathBuf; @@ -256,9 +255,7 @@ pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBu }) .try_init() { - // TODO eprintln!("Failed to initialize dependency tracing {e}"); - return; } } diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 1d3a61517fd..7464e8633ae 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -42,15 +42,12 @@ impl tracing_subscriber::layer::Layer for Loggin 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); - () } _ => {} } @@ -140,5 +137,3 @@ impl tracing_core::field::Visit for LogMessageExtractor { self.message = format!("{:?}", value); } } - -pub fn create_tracing_logging_layer() {} diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 34813481b19..71af3496b83 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -3,10 +3,7 @@ mod metrics; 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_ROOT_DIR, DEFAULT_TRACING_DIR, - DEFAULT_VALIDATOR_DIR, -}; +use directory::{parse_path_or_default, DEFAULT_BEACON_NODE_DIR, DEFAULT_VALIDATOR_DIR}; use environment::{EnvironmentBuilder, LoggerConfig}; use eth2_network_config::{Eth2NetworkConfig, DEFAULT_HARDCODED_NETWORK, HARDCODED_NET_NAMES}; use ethereum_hashing::have_sha_extensions; @@ -14,11 +11,9 @@ use futures::TryFutureExt; use lighthouse_version::VERSION; use malloc_utils::configure_memory_allocator; use slog::{crit, info}; -use std::collections::HashMap; 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; @@ -374,17 +369,6 @@ fn main() { eprintln!("The -l flag is DEPRECATED. Dependency logging will be on by default."); } - // read the `RUST_LOG` statement - 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 logging {e}"); - exit(1) - } - }; - let result = get_eth2_network_config(&matches).and_then(|eth2_network_config| { let eth_spec_id = eth2_network_config.eth_spec_id()?; @@ -549,28 +533,15 @@ fn run( let log = environment.core_context().log().clone(); - // read the `RUST_LOG` statement - 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 logging {e}"); - exit(1) - } - }; - let mut tracing_log_path: Option = clap_utils::parse_optional(matches, "logfile")?; if tracing_log_path.is_none() { - tracing_log_path = match matches.subcommand() { - (&_, _) => Some( - parse_path_or_default(matches, "datadir")? - .join(DEFAULT_BEACON_NODE_DIR) - .join("tracing"), - ), - } - }; + tracing_log_path = Some( + parse_path_or_default(matches, "datadir")? + .join(DEFAULT_BEACON_NODE_DIR) + .join("tracing"), + ) + } let path = tracing_log_path.clone().unwrap(); From 5bbf27f677eab3b6408bc06f8c050ae492dccf27 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Mon, 11 Dec 2023 14:57:04 -0800 Subject: [PATCH 21/30] filesize --- common/logging/src/lib.rs | 2 +- common/logging/src/tracing_logging_layer.rs | 2 -- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index 843f0f44fc6..750d7acef01 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -242,7 +242,7 @@ pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBu &mut file_writer_streams, base_tracing_log_path.clone(), dependency, - logfile_max_size, + logfile_max_size * 1_024 * 1_024, ); } diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 7464e8633ae..833809c4372 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -72,7 +72,6 @@ impl NonBlockingFileWriter { if !dir.exists() { let res = create_dir_all(dir); - // If the directories cannot be created, warn and disable the logger. match res { Ok(_) => (), Err(e) => { @@ -83,7 +82,6 @@ impl NonBlockingFileWriter { } } - eprintln!("{:?}", path); let mut file = match OpenOptions::new().create(true).append(true).open(&path) { Ok(file) => file, Err(e) => { From 6ce1a4eb4ce5a4421bf134ad213064943f76dcd0 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Mon, 11 Dec 2023 17:16:16 -0800 Subject: [PATCH 22/30] log gossipsub, dont filter by log level --- common/logging/src/tracing_logging_layer.rs | 17 +++-------------- 1 file changed, 3 insertions(+), 14 deletions(-) diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 833809c4372..3a8159b9aa7 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -7,7 +7,7 @@ use std::thread; lazy_static! { pub static ref TRACING_LOGGING_DEPENDENCIES: Vec = - vec!["libp2p".to_string(), "discv5".to_string()]; + vec!["libp2p_gossipsub".to_string(), "discv5".to_string()]; } /// Layer that handles `INFO`, `WARN` and `ERROR` logs emitted per dependency and @@ -39,18 +39,7 @@ impl tracing_subscriber::layer::Layer for Loggin 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); - } - _ => {} - } + let _ = file_writer.write(visitor.message); } } @@ -132,6 +121,6 @@ struct LogMessageExtractor { impl tracing_core::field::Visit for LogMessageExtractor { fn record_debug(&mut self, _: &tracing_core::Field, value: &dyn std::fmt::Debug) { - self.message = format!("{:?}", value); + self.message = format!("{} {:?}", self.message, value); } } From c222b3690f7b6e84978abadd085b47bad90ceded Mon Sep 17 00:00:00 2001 From: Diva M Date: Wed, 13 Dec 2023 11:57:51 -0500 Subject: [PATCH 23/30] turn on debug logs by default, remove deprecation warning --- lighthouse/src/main.rs | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 1219c3e1ec3..470e6af4c86 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -365,14 +365,9 @@ fn main() { } } - // Debugging output for discv5, libp2p and external crates. - if matches.is_present("env_log") { - eprintln!("The -l flag is DEPRECATED. Dependency logging will be on by default."); - } - // read the `RUST_LOG` statement let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env() - .or_else(|_| tracing_subscriber::EnvFilter::try_new("warn")) + .or_else(|_| tracing_subscriber::EnvFilter::try_new("debug")) { Ok(filter) => filter, Err(e) => { From 509a421b7c8425f11616af5fc0a1e5de16d3232a Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Wed, 13 Dec 2023 16:51:59 -0800 Subject: [PATCH 24/30] truncate file, add timestamp, add unit test --- Cargo.lock | 1 + Cargo.toml | 2 +- common/logging/Cargo.toml | 1 + common/logging/src/lib.rs | 3 +- common/logging/src/tracing_logging_layer.rs | 84 ++++++++++++++++++--- 5 files changed, 77 insertions(+), 14 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index bdc4a84df6e..9b041cfa16d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4711,6 +4711,7 @@ dependencies = [ "slog-term", "sloggers", "take_mut", + "tempfile", "tokio", "tracing-core", "tracing-log", diff --git a/Cargo.toml b/Cargo.toml index 003130888f7..24b38a572a5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -163,7 +163,7 @@ tokio-util = { version = "0.6", features = ["codec", "compat", "time"] } tracing-appender = "0.2" tracing-core = "0.1" tracing-log = "0.2" -tracing-subscriber = "0.3" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } tree_hash = "0.5" tree_hash_derive = "0.5" url = "2" diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index 6975711651b..83856106d4c 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -23,3 +23,4 @@ tokio = { workspace = true } tracing-core = { workspace = true } tracing-log = { workspace = true } tracing-subscriber = { workspace = true } +tempfile = { workspace = true } diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index e09e6006d1e..d260dc17d67 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -11,6 +11,7 @@ use std::io::{Result, Write}; use std::path::PathBuf; use std::time::{Duration, Instant}; use tracing_logging_layer::TRACING_LOGGING_DEPENDENCIES; +use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; pub const MAX_MESSAGE_WIDTH: usize = 40; @@ -23,7 +24,6 @@ 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); @@ -225,7 +225,6 @@ 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("debug")) { diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 3a8159b9aa7..10e63e33db9 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,7 +1,7 @@ +use chrono::prelude::Local; use std::collections::HashMap; -use std::fs::{self, create_dir_all, File, OpenOptions}; -use std::io::Write; -use std::path::PathBuf; +use std::fs::{create_dir_all, File, OpenOptions}; +use std::io::{Seek, SeekFrom, Write}; use std::sync::mpsc::{self, Sender}; use std::thread; @@ -80,13 +80,13 @@ impl NonBlockingFileWriter { }; for message in receiver { - let should_clear_file = match NonBlockingFileWriter::get_file_size(&path) { + let should_truncate_file = match NonBlockingFileWriter::get_file_size(&file) { Ok(file_size) => file_size > max_file_size, Err(_) => false, }; - if should_clear_file { - let _ = NonBlockingFileWriter::clear_file(&path); + if should_truncate_file { + let _ = NonBlockingFileWriter::truncate_file(&mut file, max_file_size / 2); } if let Err(e) = writeln!(file, "{}", message) { @@ -98,19 +98,25 @@ impl NonBlockingFileWriter { Ok(NonBlockingFileWriter { sender }) } - pub fn write(&self, message: String) -> Result<(), std::io::Error> { + pub fn write(&self, mut message: String) -> Result<(), std::io::Error> { + message = format!("{} {}", self.timestamp_now(), message); 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 { - let metadata = fs::metadata(path)?; + pub fn get_file_size(file: &File) -> std::io::Result { + let metadata = file.metadata()?; Ok(metadata.len()) } - fn clear_file(path: &PathBuf) -> std::io::Result<()> { - File::create(path)?; + pub fn timestamp_now(&self) -> String { + Local::now().format("%Y-%m-%d %H:%M:%S").to_string() + } + + fn truncate_file(file: &mut File, truncate_position: u64) -> std::io::Result<()> { + file.set_len(truncate_position)?; + file.seek(SeekFrom::End(0))?; Ok(()) } } @@ -124,3 +130,59 @@ impl tracing_core::field::Visit for LogMessageExtractor { self.message = format!("{} {:?}", self.message, value); } } + +#[cfg(test)] +mod test { + use crate::NonBlockingFileWriter; + use std::{ + fs::{self}, + thread, + time::Duration, + }; + use tempfile::{Builder as TempDirBuilder, TempDir}; + + const DUMMY_TEXT: &str = r#" + Lorem ipsum dolor sit amet, + consectetur adipiscing elit, + sed do eiusmod tempor incididunt + ut labore et dolore magna aliqua. + Ut enim ad minim veniam, quis nostrud + exercitation ullamco laboris nisi ut + aliquip ex ea commodo consequat. + Duis aute irure dolor in reprehenderit + in voluptate velit esse cillum dolore eu + fugiat nulla pariatur. Excepteur sint occaecat + cupidatat non proident, sunt in culpa qui officia + deserunt mollit anim id est laborum. + "#; + + const MAX_FILE_SIZE: u64 = 100; + + #[test] + fn test_file_truncate() { + let file_path = tempdir().path().join("foo.log"); + let non_blocking_file_writer = + NonBlockingFileWriter::new(file_path.as_path(), MAX_FILE_SIZE).unwrap(); + + non_blocking_file_writer + .write(DUMMY_TEXT.to_string()) + .unwrap(); + thread::sleep(Duration::from_millis(100)); + let file = fs::File::open(&file_path).unwrap(); + let file_size = NonBlockingFileWriter::get_file_size(&file).unwrap(); + assert!(file_size > MAX_FILE_SIZE); + + non_blocking_file_writer.write("".to_string()).unwrap(); + thread::sleep(Duration::from_millis(100)); + let file = fs::File::open(&file_path).unwrap(); + let file_size = NonBlockingFileWriter::get_file_size(&file).unwrap(); + assert!(file_size <= MAX_FILE_SIZE); + } + + fn tempdir() -> TempDir { + TempDirBuilder::new() + .prefix("non_blocking_file_writer_test") + .tempdir() + .expect("Cannot create a temporary directory") + } +} From 0d73f766ed64661a1265983498b21f2b904281a0 Mon Sep 17 00:00:00 2001 From: Divma <26765164+divagant-martian@users.noreply.github.com> Date: Sun, 17 Dec 2023 20:13:30 -0500 Subject: [PATCH 25/30] suppress output (#5) --- lighthouse/src/main.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 470e6af4c86..ccdfa60f114 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -376,8 +376,15 @@ fn main() { } }; + 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::::from( + turn_on_terminal_logs.then(std::io::stdout), + ) + }) .finish() .with(logging::MetricsLayer) .try_init() From f25dcb611ee9af0beb0e22657738f15ea5c14972 Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Sat, 30 Dec 2023 09:32:48 +0200 Subject: [PATCH 26/30] use tracing appender --- Cargo.lock | 14 ++ common/logging/Cargo.toml | 2 + common/logging/src/lib.rs | 53 +++--- common/logging/src/tracing_logging_layer.rs | 186 +++----------------- lighthouse/src/main.rs | 2 +- 5 files changed, 65 insertions(+), 192 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9b041cfa16d..564f83b7992 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4713,6 +4713,8 @@ dependencies = [ "take_mut", "tempfile", "tokio", + "tracing", + "tracing-appender", "tracing-core", "tracing-log", "tracing-subscriber", @@ -8113,6 +8115,18 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf" +dependencies = [ + "crossbeam-channel", + "thiserror", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.27" diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index 83856106d4c..ac83d8e039e 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -20,7 +20,9 @@ slog-term = { workspace = true } sloggers = { workspace = true } take_mut = "0.2.2" tokio = { workspace = true } +tracing = "0.1" tracing-core = { workspace = true } tracing-log = { workspace = true } tracing-subscriber = { workspace = true } +tracing-appender = { workspace = true } tempfile = { workspace = true } diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index d260dc17d67..591280b244a 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -6,11 +6,12 @@ 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; +use tracing_appender::non_blocking::NonBlocking; +use tracing_logging_layer::LoggingLayer; +use tracing_subscriber::fmt::format::Format; use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; pub const MAX_MESSAGE_WIDTH: usize = 40; @@ -21,8 +22,6 @@ 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; /// The minimum interval between log messages indicating that a queue is full. @@ -224,9 +223,9 @@ impl TimeLatch { } } -pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBuf) { +pub fn create_tracing_layer(base_tracing_log_path: PathBuf) { let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env() - .or_else(|_| tracing_subscriber::EnvFilter::try_new("debug")) + .or_else(|_| tracing_subscriber::EnvFilter::try_new("info")) { Ok(filter) => filter, Err(e) => { @@ -235,45 +234,33 @@ pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBu } }; - let mut file_writer_streams: HashMap = HashMap::new(); + let libp2p_writer = + tracing_appender::rolling::daily(base_tracing_log_path.clone(), "libp2p.log"); + let discv5_writer = + tracing_appender::rolling::daily(base_tracing_log_path.clone(), "discv5.log"); - 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, - ); - } + let (libp2p_non_blocking_writer, libp2p_guard) = NonBlocking::new(libp2p_writer); + let (discv5_non_blocking_writer, discv5_guard) = NonBlocking::new(discv5_writer); + + let custom_layer = LoggingLayer { + libp2p_non_blocking_writer, + libp2p_guard, + discv5_non_blocking_writer, + discv5_guard, + formatter: Format::default(), + }; if let Err(e) = tracing_subscriber::fmt() .with_env_filter(filter_layer) .finish() .with(MetricsLayer) - .with(LoggingLayer { - file_writer_streams, - }) + .with(custom_layer) .try_init() { eprintln!("Failed to initialize dependency tracing {e}"); } } -fn init_file_writer_stream( - file_writer_streams: &mut HashMap, - 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 diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 10e63e33db9..995b7a4912f 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,36 +1,37 @@ use chrono::prelude::Local; -use std::collections::HashMap; -use std::fs::{create_dir_all, File, OpenOptions}; -use std::io::{Seek, SeekFrom, Write}; -use std::sync::mpsc::{self, Sender}; -use std::thread; +use std::io::Write; +use tracing::Subscriber; +use tracing_appender::non_blocking::{NonBlocking, WorkerGuard}; +use tracing_subscriber::fmt::format::Format; +use tracing_subscriber::layer::Context; +use tracing_subscriber::Layer; -lazy_static! { - pub static ref TRACING_LOGGING_DEPENDENCIES: Vec = - vec!["libp2p_gossipsub".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, -} - -impl tracing_subscriber::layer::Layer for LoggingLayer { - fn on_event( - &self, - event: &tracing_core::Event<'_>, - _ctx: tracing_subscriber::layer::Context<'_, S>, - ) { + pub libp2p_non_blocking_writer: NonBlocking, + pub libp2p_guard: WorkerGuard, + pub discv5_non_blocking_writer: NonBlocking, + pub discv5_guard: WorkerGuard, + pub formatter: Format, +} + +impl Layer for LoggingLayer +where + S: Subscriber, +{ + fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context) { let meta = event.metadata(); + let log_level = meta.level(); + let timestamp = Local::now().format("%Y-%m-%d %H:%M:%S").to_string(); 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 writer = match target { + "libp2p_gossipsub" => self.libp2p_non_blocking_writer.clone(), + "discv5" => self.discv5_non_blocking_writer.clone(), + _ => return, }; let mut visitor = LogMessageExtractor { @@ -38,86 +39,11 @@ impl tracing_subscriber::layer::Layer for Loggin }; event.record(&mut visitor); + let message = format!("{} {} {}\n", timestamp, log_level, visitor.message); - let _ = file_writer.write(visitor.message); - } -} - -pub struct NonBlockingFileWriter { - sender: Sender, -} - -impl NonBlockingFileWriter { - pub fn new(path: &std::path::Path, max_file_size: u64) -> Result { - 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_truncate_file = match NonBlockingFileWriter::get_file_size(&file) { - Ok(file_size) => file_size > max_file_size, - Err(_) => false, - }; - - if should_truncate_file { - let _ = NonBlockingFileWriter::truncate_file(&mut file, max_file_size / 2); - } - - if let Err(e) = writeln!(file, "{}", message) { - eprintln!("Failed to write to file: {:?}", e); - } - } - }); - - Ok(NonBlockingFileWriter { sender }) - } - - pub fn write(&self, mut message: String) -> Result<(), std::io::Error> { - message = format!("{} {}", self.timestamp_now(), message); - self.sender - .send(message) - .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e)) - } - - pub fn get_file_size(file: &File) -> std::io::Result { - let metadata = file.metadata()?; - Ok(metadata.len()) - } - - pub fn timestamp_now(&self) -> String { - Local::now().format("%Y-%m-%d %H:%M:%S").to_string() - } - - fn truncate_file(file: &mut File, truncate_position: u64) -> std::io::Result<()> { - file.set_len(truncate_position)?; - file.seek(SeekFrom::End(0))?; - Ok(()) + if let Err(e) = writer.write_all(message.as_bytes()) { + eprintln!("Failed to write log: {}", e); + } } } @@ -130,59 +56,3 @@ impl tracing_core::field::Visit for LogMessageExtractor { self.message = format!("{} {:?}", self.message, value); } } - -#[cfg(test)] -mod test { - use crate::NonBlockingFileWriter; - use std::{ - fs::{self}, - thread, - time::Duration, - }; - use tempfile::{Builder as TempDirBuilder, TempDir}; - - const DUMMY_TEXT: &str = r#" - Lorem ipsum dolor sit amet, - consectetur adipiscing elit, - sed do eiusmod tempor incididunt - ut labore et dolore magna aliqua. - Ut enim ad minim veniam, quis nostrud - exercitation ullamco laboris nisi ut - aliquip ex ea commodo consequat. - Duis aute irure dolor in reprehenderit - in voluptate velit esse cillum dolore eu - fugiat nulla pariatur. Excepteur sint occaecat - cupidatat non proident, sunt in culpa qui officia - deserunt mollit anim id est laborum. - "#; - - const MAX_FILE_SIZE: u64 = 100; - - #[test] - fn test_file_truncate() { - let file_path = tempdir().path().join("foo.log"); - let non_blocking_file_writer = - NonBlockingFileWriter::new(file_path.as_path(), MAX_FILE_SIZE).unwrap(); - - non_blocking_file_writer - .write(DUMMY_TEXT.to_string()) - .unwrap(); - thread::sleep(Duration::from_millis(100)); - let file = fs::File::open(&file_path).unwrap(); - let file_size = NonBlockingFileWriter::get_file_size(&file).unwrap(); - assert!(file_size > MAX_FILE_SIZE); - - non_blocking_file_writer.write("".to_string()).unwrap(); - thread::sleep(Duration::from_millis(100)); - let file = fs::File::open(&file_path).unwrap(); - let file_size = NonBlockingFileWriter::get_file_size(&file).unwrap(); - assert!(file_size <= MAX_FILE_SIZE); - } - - fn tempdir() -> TempDir { - TempDirBuilder::new() - .prefix("non_blocking_file_writer_test") - .tempdir() - .expect("Cannot create a temporary directory") - } -} diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 51c11137649..68a93412631 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -540,7 +540,7 @@ fn run( let path = tracing_log_path.clone().unwrap(); - logging::create_tracing_layer(logfile_max_size, path); + logging::create_tracing_layer(path); // Allow Prometheus to export the time at which the process was started. metrics::expose_process_start_time(&log); From 958bb7bbfb3589b9e7b667a91106c3cb9682312b Mon Sep 17 00:00:00 2001 From: Eitan Seri-Levi Date: Sat, 30 Dec 2023 09:56:08 +0200 Subject: [PATCH 27/30] cleanup --- common/logging/src/lib.rs | 3 --- common/logging/src/tracing_logging_layer.rs | 2 -- 2 files changed, 5 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index ff9d2a1d7be..c71600bf842 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -11,7 +11,6 @@ use std::path::PathBuf; use std::time::{Duration, Instant}; use tracing_appender::non_blocking::NonBlocking; use tracing_logging_layer::LoggingLayer; -use tracing_subscriber::fmt::format::Format; use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; pub const MAX_MESSAGE_WIDTH: usize = 40; @@ -247,7 +246,6 @@ pub fn create_tracing_layer(base_tracing_log_path: PathBuf, turn_on_terminal_log libp2p_guard, discv5_non_blocking_writer, discv5_guard, - formatter: Format::default(), }; if let Err(e) = tracing_subscriber::fmt() @@ -263,7 +261,6 @@ pub fn create_tracing_layer(base_tracing_log_path: PathBuf, turn_on_terminal_log .try_init() { eprintln!("Failed to initialize dependency logging {e}"); - return; } } diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 995b7a4912f..bea817b37ed 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -2,7 +2,6 @@ use chrono::prelude::Local; use std::io::Write; use tracing::Subscriber; use tracing_appender::non_blocking::{NonBlocking, WorkerGuard}; -use tracing_subscriber::fmt::format::Format; use tracing_subscriber::layer::Context; use tracing_subscriber::Layer; @@ -11,7 +10,6 @@ pub struct LoggingLayer { pub libp2p_guard: WorkerGuard, pub discv5_non_blocking_writer: NonBlocking, pub discv5_guard: WorkerGuard, - pub formatter: Format, } impl Layer for LoggingLayer From f7dea99fec7766cd878df58e85deb1bb8eebdd4f Mon Sep 17 00:00:00 2001 From: Age Manning Date: Tue, 16 Jan 2024 17:33:22 +1100 Subject: [PATCH 28/30] Add a task to remove old log files and upgrade to warn level --- common/logging/src/lib.rs | 3 +- common/logging/src/tracing_logging_layer.rs | 59 ++++++++++++++++++++- lighthouse/src/main.rs | 35 ++---------- 3 files changed, 65 insertions(+), 32 deletions(-) diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index c71600bf842..5217d541cf5 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -21,6 +21,7 @@ mod tracing_logging_layer; mod tracing_metrics_layer; pub use sse_logging_components::SSELoggingComponents; +pub use tracing_logging_layer::cleanup_logging_task; pub use tracing_metrics_layer::MetricsLayer; /// The minimum interval between log messages indicating that a queue is full. @@ -224,7 +225,7 @@ impl TimeLatch { pub fn create_tracing_layer(base_tracing_log_path: PathBuf, turn_on_terminal_logs: bool) { let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env() - .or_else(|_| tracing_subscriber::EnvFilter::try_new("debug")) + .or_else(|_| tracing_subscriber::EnvFilter::try_new("warn")) { Ok(filter) => filter, Err(e) => { diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index bea817b37ed..30695e74d9c 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,9 +1,10 @@ -use chrono::prelude::Local; +use chrono::{prelude::*, naive::Days}; use std::io::Write; use tracing::Subscriber; use tracing_appender::non_blocking::{NonBlocking, WorkerGuard}; use tracing_subscriber::layer::Context; use tracing_subscriber::Layer; +use slog::{debug,warn}; pub struct LoggingLayer { pub libp2p_non_blocking_writer: NonBlocking, @@ -54,3 +55,59 @@ impl tracing_core::field::Visit for LogMessageExtractor { self.message = format!("{} {:?}", self.message, value); } } + +/// Creates a long lived async task that routinely deletes old tracing log files +pub async fn cleanup_logging_task(path: std::path::PathBuf, log: slog::Logger) { + + loop { + // Delay for 1 day and then prune old logs + tokio::time::sleep(std::time::Duration::from_secs(60*60*24)).await; + + let Some(yesterday_date) = chrono::prelude::Local::now().naive_local().checked_sub_days(Days::new(1)) else { + warn!(log, "Could not calculate the current date"); + return; + }; + + // Search for old log files + let dir = path.as_path(); + + if dir.is_dir() { + let Ok(files) = std::fs::read_dir(dir) else { + warn!(log, "Could not read log directory contents"; "path" => ?dir); + break; + }; + + for file in files { + let Ok(dir_entry) = file else { + warn!(log, "Could not read file"); + continue; + }; + + let Ok(file_name) = dir_entry.file_name().into_string() else { + warn!(log, "Could not read file"; "file" => ?dir_entry); + continue; + }; + + if file_name.starts_with("libp2p.log") | file_name.starts_with("discv5.log") { + let log_file_date = file_name.split('.').collect::>(); + if log_file_date.len() == 3 { + let Ok(log_file_date_type) = NaiveDate::parse_from_str(log_file_date[2], "%Y-%m-%d") else { + warn!(log, "Could not parse log file date"; "file" => file_name); + continue; + }; + + if log_file_date_type < yesterday_date.into() { + // Delete the file, its too old + debug!(log, "Removing old log file"; "file" => &file_name); + if let Err(e) = std::fs::remove_file(dir_entry.path()) { + warn!(log, "Failed to remove log file"; "file" => file_name, "error" => %e); + } + } + + } + + } + } + } + } +} diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 77b8da280f9..0820e3ee5bb 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -14,7 +14,6 @@ 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; @@ -365,34 +364,6 @@ fn main() { } } - // 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::::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| { let eth_spec_id = eth2_network_config.eth_spec_id()?; @@ -563,7 +534,7 @@ fn run( tracing_log_path = Some( parse_path_or_default(matches, "datadir")? .join(DEFAULT_BEACON_NODE_DIR) - .join("tracing"), + .join("logs"), ) } @@ -571,6 +542,10 @@ fn run( let turn_on_terminal_logs = matches.is_present("env_log"); + // Run a task to clean up old tracing logs. + let log_cleaner_context = environment.service_context("log_cleaner".to_string()); + log_cleaner_context.executor.spawn(logging::cleanup_logging_task(path.clone(), log.clone()), "log_cleaner"); + logging::create_tracing_layer(path, turn_on_terminal_logs); // Allow Prometheus to export the time at which the process was started. From 32bbbfdac47cd3ac6c211c01b208e80917d4c6fa Mon Sep 17 00:00:00 2001 From: Age Manning Date: Tue, 16 Jan 2024 18:12:11 +1100 Subject: [PATCH 29/30] Add the time feature for tokio --- common/logging/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index ac83d8e039e..f3684997728 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -19,7 +19,7 @@ slog-async = { workspace = true } slog-term = { workspace = true } sloggers = { workspace = true } take_mut = "0.2.2" -tokio = { workspace = true } +tokio = { workspace = true, features = [ "time" ] } tracing = "0.1" tracing-core = { workspace = true } tracing-log = { workspace = true } From b2f9d96a61d7423b42e31cf78e23ccd3f4fcdcab Mon Sep 17 00:00:00 2001 From: Age Manning Date: Tue, 16 Jan 2024 18:42:20 +1100 Subject: [PATCH 30/30] Udeps and fmt --- Cargo.lock | 1 - common/logging/Cargo.toml | 1 - common/logging/src/tracing_logging_layer.rs | 70 +++++++++++---------- lighthouse/src/main.rs | 5 +- 4 files changed, 40 insertions(+), 37 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6c0044b29e8..306580e4303 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4792,7 +4792,6 @@ dependencies = [ "slog-term", "sloggers", "take_mut", - "tempfile", "tokio", "tracing", "tracing-appender", diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index f3684997728..1fad56d475c 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -25,4 +25,3 @@ tracing-core = { workspace = true } tracing-log = { workspace = true } tracing-subscriber = { workspace = true } tracing-appender = { workspace = true } -tempfile = { workspace = true } diff --git a/common/logging/src/tracing_logging_layer.rs b/common/logging/src/tracing_logging_layer.rs index 30695e74d9c..a74e24bdb69 100644 --- a/common/logging/src/tracing_logging_layer.rs +++ b/common/logging/src/tracing_logging_layer.rs @@ -1,10 +1,10 @@ -use chrono::{prelude::*, naive::Days}; +use chrono::{naive::Days, prelude::*}; +use slog::{debug, warn}; use std::io::Write; use tracing::Subscriber; use tracing_appender::non_blocking::{NonBlocking, WorkerGuard}; use tracing_subscriber::layer::Context; use tracing_subscriber::Layer; -use slog::{debug,warn}; pub struct LoggingLayer { pub libp2p_non_blocking_writer: NonBlocking, @@ -58,12 +58,14 @@ impl tracing_core::field::Visit for LogMessageExtractor { /// Creates a long lived async task that routinely deletes old tracing log files pub async fn cleanup_logging_task(path: std::path::PathBuf, log: slog::Logger) { - loop { // Delay for 1 day and then prune old logs - tokio::time::sleep(std::time::Duration::from_secs(60*60*24)).await; + tokio::time::sleep(std::time::Duration::from_secs(60 * 60 * 24)).await; - let Some(yesterday_date) = chrono::prelude::Local::now().naive_local().checked_sub_days(Days::new(1)) else { + let Some(yesterday_date) = chrono::prelude::Local::now() + .naive_local() + .checked_sub_days(Days::new(1)) + else { warn!(log, "Could not calculate the current date"); return; }; @@ -78,35 +80,35 @@ pub async fn cleanup_logging_task(path: std::path::PathBuf, log: slog::Logger) { }; for file in files { - let Ok(dir_entry) = file else { - warn!(log, "Could not read file"); - continue; - }; - - let Ok(file_name) = dir_entry.file_name().into_string() else { - warn!(log, "Could not read file"; "file" => ?dir_entry); - continue; - }; - - if file_name.starts_with("libp2p.log") | file_name.starts_with("discv5.log") { - let log_file_date = file_name.split('.').collect::>(); - if log_file_date.len() == 3 { - let Ok(log_file_date_type) = NaiveDate::parse_from_str(log_file_date[2], "%Y-%m-%d") else { - warn!(log, "Could not parse log file date"; "file" => file_name); - continue; - }; - - if log_file_date_type < yesterday_date.into() { - // Delete the file, its too old - debug!(log, "Removing old log file"; "file" => &file_name); - if let Err(e) = std::fs::remove_file(dir_entry.path()) { - warn!(log, "Failed to remove log file"; "file" => file_name, "error" => %e); - } - } - - } - - } + let Ok(dir_entry) = file else { + warn!(log, "Could not read file"); + continue; + }; + + let Ok(file_name) = dir_entry.file_name().into_string() else { + warn!(log, "Could not read file"; "file" => ?dir_entry); + continue; + }; + + if file_name.starts_with("libp2p.log") | file_name.starts_with("discv5.log") { + let log_file_date = file_name.split('.').collect::>(); + if log_file_date.len() == 3 { + let Ok(log_file_date_type) = + NaiveDate::parse_from_str(log_file_date[2], "%Y-%m-%d") + else { + warn!(log, "Could not parse log file date"; "file" => file_name); + continue; + }; + + if log_file_date_type < yesterday_date.into() { + // Delete the file, its too old + debug!(log, "Removing old log file"; "file" => &file_name); + if let Err(e) = std::fs::remove_file(dir_entry.path()) { + warn!(log, "Failed to remove log file"; "file" => file_name, "error" => %e); + } + } + } + } } } } diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index 0820e3ee5bb..b8cedfde0d7 100644 --- a/lighthouse/src/main.rs +++ b/lighthouse/src/main.rs @@ -544,7 +544,10 @@ fn run( // Run a task to clean up old tracing logs. let log_cleaner_context = environment.service_context("log_cleaner".to_string()); - log_cleaner_context.executor.spawn(logging::cleanup_logging_task(path.clone(), log.clone()), "log_cleaner"); + log_cleaner_context.executor.spawn( + logging::cleanup_logging_task(path.clone(), log.clone()), + "log_cleaner", + ); logging::create_tracing_layer(path, turn_on_terminal_logs);