From a68b7018071713a7aba699697e45431b453d91ed Mon Sep 17 00:00:00 2001 From: Divma <26765164+divagant-martian@users.noreply.github.com> Date: Mon, 15 Jan 2024 20:22:09 -0500 Subject: [PATCH] add tracing metrics layer for dependency logging (#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 --- Cargo.lock | 179 +++++++++++++------- Cargo.toml | 3 + book/src/help_general.md | 4 +- boot_node/src/lib.rs | 5 +- common/logging/Cargo.toml | 19 ++- common/logging/src/lib.rs | 3 + common/logging/src/tracing_metrics_layer.rs | 63 +++++++ lighthouse/Cargo.toml | 3 +- lighthouse/src/main.rs | 34 +++- 9 files changed, 234 insertions(+), 79 deletions(-) create mode 100644 common/logging/src/tracing_metrics_layer.rs diff --git a/Cargo.lock b/Cargo.lock index b22b601d6cb..532388cf4c7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -310,7 +310,7 @@ dependencies = [ "futures-lite", "parking", "polling", - "rustix 0.38.28", + "rustix 0.38.30", "slab", "tracing", "windows-sys 0.52.0", @@ -318,9 +318,9 @@ dependencies = [ [[package]] name = "async-lock" -version = "3.2.0" +version = "3.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7125e42787d53db9dd54261812ef17e937c95a51e4d291373b670342fa44310c" +checksum = "d034b430882f8381900d3fe6f0aaa3ad94f2cb4ac519b429692a1bc2dda4ae7b" dependencies = [ "event-listener 4.0.3", "event-listener-strategy", @@ -416,9 +416,9 @@ checksum = "d468802bab17cbc0cc575e9b053f41e72aa36bfa6b7f55e3529ffa43161b97fa" [[package]] name = "axum" -version = "0.7.3" +version = "0.7.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d09dbe0e490df5da9d69b36dca48a76635288a82f92eca90024883a56202026d" +checksum = "1236b4b292f6c4d6dc34604bb5120d85c3fe1d1aa596bd5cc52ca054d13e7b9e" dependencies = [ "async-trait", "axum-core", @@ -450,9 +450,9 @@ dependencies = [ [[package]] name = "axum-core" -version = "0.4.2" +version = "0.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e87c8503f93e6d144ee5690907ba22db7ba79ab001a932ab99034f0fe836b3df" +checksum = "a15c63fd72d41492dc4f497196f5da1fb04fb7529e631d73630d1b491e47a2e3" dependencies = [ "async-trait", "bytes", @@ -510,9 +510,9 @@ checksum = "9e1b586273c5702936fe7b7d6896644d8be71e6314cfe09d3167c95f712589e8" [[package]] name = "base64" -version = "0.21.6" +version = "0.21.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c79fed4cdb43e993fcdadc7e58a09fd0e3e649c4436fa11da71c9f1f3ee7feb9" +checksum = "9d297deb1925b89f2ccc13d7635fa0714f12c87adce1c75356b39ca9b7178567" [[package]] name = "base64ct" @@ -1972,7 +1972,7 @@ version = "0.10.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2a3d8dc56e02f954cac8eb489772c552c473346fc34f67412bb6244fd647f7e4" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "bytes", "ed25519-dalek", "hex", @@ -3084,9 +3084,9 @@ dependencies = [ [[package]] name = "h2" -version = "0.3.22" +version = "0.3.23" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4d6250322ef6e60f93f9a2162799302cd6f68f79f6e5d85c8c16f14d1d958178" +checksum = "b553656127a00601c8ae5590fcfdc118e4083a7924b6cf4ffc1ea4b99dc429d7" dependencies = [ "bytes", "fnv", @@ -3181,7 +3181,7 @@ version = "0.3.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06683b93020a07e3dbcf5f8c0f6d40080d725bea7936fc01ad345c01b97dc270" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "bytes", "headers-core", "http 0.2.11", @@ -3499,7 +3499,7 @@ dependencies = [ "futures-channel", "futures-core", "futures-util", - "h2 0.3.22", + "h2 0.3.23", "http 0.2.11", "http-body 0.4.6", "httparse", @@ -3691,9 +3691,9 @@ dependencies = [ [[package]] name = "igd-next" -version = "0.14.2" +version = "0.14.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "57e065e90a518ab5fedf79aa1e4b784e10f8e484a834f6bda85c42633a2cb7af" +checksum = "064d90fec10d541084e7b39ead8875a5a80d9114a2b18791565253bae25f49e4" dependencies = [ "async-trait", "attohttpc 0.24.1", @@ -3915,9 +3915,9 @@ dependencies = [ [[package]] name = "js-sys" -version = "0.3.66" +version = "0.3.67" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cee9c64da59eae3b50095c18d3e74f8b73c0b86d2792824ff01bbce68ba229ca" +checksum = "9a1d36f1235bc969acba30b7f5990b864423a6068a10f7c90ae8f0112e3a59d1" dependencies = [ "wasm-bindgen", ] @@ -3928,7 +3928,7 @@ version = "8.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6971da4d9c3aa03c3d8f3ff0f4155b534aad021292003895a469716b2a230378" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "pem 1.1.1", "ring 0.16.20", "serde", @@ -3965,9 +3965,9 @@ dependencies = [ [[package]] name = "keccak" -version = "0.1.4" +version = "0.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8f6d5ed8676d904364de097082f4e7d240b571b67989ced0240f08b7f966f940" +checksum = "ecc2af9a1119c51f12a14607e783cb977bde58bc069ff0c3da1095e635d70654" dependencies = [ "cpufeatures", ] @@ -4237,7 +4237,7 @@ source = "git+https://github.com/sigp/rust-libp2p/?rev=b96b90894faab0a1eed78e1c8 dependencies = [ "async-channel", "asynchronous-codec", - "base64 0.21.6", + "base64 0.21.7", "byteorder", "bytes", "either", @@ -4615,7 +4615,6 @@ dependencies = [ "clap_utils", "database_manager", "directory", - "env_logger 0.9.3", "environment", "eth1", "eth2", @@ -4626,6 +4625,7 @@ dependencies = [ "lighthouse_metrics", "lighthouse_network", "lighthouse_version", + "logging", "malloc_utils", "sensitive_url", "serde", @@ -4637,6 +4637,7 @@ dependencies = [ "sloggers", "task_executor", "tempfile", + "tracing-subscriber", "types", "unused_port", "validator_client", @@ -4792,6 +4793,9 @@ dependencies = [ "sloggers", "take_mut", "tokio", + "tracing-core", + "tracing-log", + "tracing-subscriber", ] [[package]] @@ -4888,9 +4892,9 @@ dependencies = [ [[package]] name = "mediatype" -version = "0.19.16" +version = "0.19.17" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bf0bc9784973713e4a90d515a4302991ca125a7c4516951cb607f2298cb757e5" +checksum = "83a018c36a54f4e12c30464bbc59311f85d3f6f4d6c1b4fa4ea9db2b174ddefc" [[package]] name = "memchr" @@ -5298,6 +5302,16 @@ dependencies = [ "winapi", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-bigint" version = "0.4.4" @@ -5521,6 +5535,12 @@ dependencies = [ "types", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "p256" version = "0.13.2" @@ -5698,7 +5718,7 @@ version = "3.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1b8fcc794035347fb64beda2d3b462595dd2753e3f268d89c5aae77e8cf2c310" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "serde", ] @@ -5845,14 +5865,14 @@ dependencies = [ [[package]] name = "polling" -version = "3.3.1" +version = "3.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cf63fa624ab313c11656b4cda960bfc46c410187ad493c41f6ba2d8c1e991c9e" +checksum = "545c980a3880efd47b2e262f6a4bb6daad6555cf3367aa9c4e52895f69537a41" dependencies = [ "cfg-if", "concurrent-queue", "pin-project-lite", - "rustix 0.38.28", + "rustix 0.38.30", "tracing", "windows-sys 0.52.0", ] @@ -5898,7 +5918,7 @@ version = "0.6.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "49b6c5ef183cd3ab4ba005f1ca64c21e8bd97ce4699cfea9e8d9a2c4958ca520" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "byteorder", "bytes", "fallible-iterator", @@ -6413,12 +6433,12 @@ version = "0.11.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "37b1ae8d9ac08420c66222fb9096fc5de435c3c48542bc5336c51892cffafb41" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "bytes", "encoding_rs", "futures-core", "futures-util", - "h2 0.3.22", + "h2 0.3.23", "http 0.2.11", "http-body 0.4.6", "hyper 0.14.28", @@ -6630,9 +6650,9 @@ dependencies = [ [[package]] name = "rustix" -version = "0.38.28" +version = "0.38.30" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "72e572a5e8ca657d7366229cdde4bd14c4eb5499a9573d4d366fe1b599daa316" +checksum = "322394588aaf33c24007e8bb3238ee3e4c5c09c084ab32bc73890b99ff326bca" dependencies = [ "bitflags 2.4.1", "errno", @@ -6673,7 +6693,7 @@ version = "1.0.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1c74cae0a4cf6ccbbf5f359f08efdf8ee7e1dc532573bf0db71968cb56b1448c" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", ] [[package]] @@ -6682,7 +6702,7 @@ version = "2.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "35e4980fa29e4c4b212ffb3db068a564cbf560e51d3944b7c88bd8bf5bec64f4" dependencies = [ - "base64 0.21.6", + "base64 0.21.7", "rustls-pki-types", ] @@ -7092,6 +7112,15 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.2.0" @@ -7353,9 +7382,9 @@ dependencies = [ [[package]] name = "smallvec" -version = "1.11.2" +version = "1.12.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4dccd0940a2dcdf68d092b8cbab7dc0ad8fa938bf95787e1b916b0e3d0e8e970" +checksum = "2593d31f82ead8df961d8bd23a64c2ccf2eb5dd34b0a34bfb4dd54011c72009e" [[package]] name = "snap" @@ -7728,7 +7757,7 @@ dependencies = [ "cfg-if", "fastrand", "redox_syscall 0.4.1", - "rustix 0.38.28", + "rustix 0.38.30", "windows-sys 0.52.0", ] @@ -7745,9 +7774,9 @@ dependencies = [ [[package]] name = "termcolor" -version = "1.4.0" +version = "1.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ff1bc3d3f05aff0403e8ac0d92ced918ec05b666a43f83297ccef5bea8a3d449" +checksum = "06794f8f6c5c898b3275aebefa6b8a1cb24cd2c6c79397ab15774837a0bc5755" dependencies = [ "winapi-util", ] @@ -8179,6 +8208,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", + "valuable", ] [[package]] @@ -8191,6 +8221,31 @@ dependencies = [ "tracing", ] +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", +] + [[package]] name = "trackable" version = "1.3.0" @@ -8560,6 +8615,12 @@ dependencies = [ "validator_client", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" @@ -8606,7 +8667,7 @@ dependencies = [ [[package]] name = "warp" version = "0.3.6" -source = "git+https://github.com/seanmonstar/warp.git#2c3581e8387e29bab2ac1aa5f9ae9602fe62339f" +source = "git+https://github.com/seanmonstar/warp.git#724e767173132de7c435b323e12d6bec68038de2" dependencies = [ "bytes", "futures-channel", @@ -8657,9 +8718,9 @@ checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423" [[package]] name = "wasm-bindgen" -version = "0.2.89" +version = "0.2.90" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0ed0d4f68a3015cc185aff4db9506a015f4b96f95303897bfa23f846db54064e" +checksum = "b1223296a201415c7fad14792dbefaace9bd52b62d33453ade1c5b5f07555406" dependencies = [ "cfg-if", "wasm-bindgen-macro", @@ -8667,9 +8728,9 @@ dependencies = [ [[package]] name = "wasm-bindgen-backend" -version = "0.2.89" +version = "0.2.90" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1b56f625e64f3a1084ded111c4d5f477df9f8c92df113852fa5a374dbda78826" +checksum = "fcdc935b63408d58a32f8cc9738a0bffd8f05cc7c002086c6ef20b7312ad9dcd" dependencies = [ "bumpalo", "log", @@ -8682,9 +8743,9 @@ dependencies = [ [[package]] name = "wasm-bindgen-futures" -version = "0.4.39" +version = "0.4.40" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ac36a15a220124ac510204aec1c3e5db8a22ab06fd6706d881dc6149f8ed9a12" +checksum = "bde2032aeb86bdfaecc8b261eef3cba735cc426c1f3a3416d1e0791be95fc461" dependencies = [ "cfg-if", "js-sys", @@ -8694,9 +8755,9 @@ dependencies = [ [[package]] name = "wasm-bindgen-macro" -version = "0.2.89" +version = "0.2.90" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0162dbf37223cd2afce98f3d0785506dcb8d266223983e4b5b525859e6e182b2" +checksum = "3e4c238561b2d428924c49815533a8b9121c664599558a5d9ec51f8a1740a999" dependencies = [ "quote", "wasm-bindgen-macro-support", @@ -8704,9 +8765,9 @@ dependencies = [ [[package]] name = "wasm-bindgen-macro-support" -version = "0.2.89" +version = "0.2.90" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f0eb82fcb7930ae6219a7ecfd55b217f5f0893484b7a13022ebb2b2bf20b5283" +checksum = "bae1abb6806dc1ad9e560ed242107c0f6c84335f1749dd4e8ddb012ebd5e25a7" dependencies = [ "proc-macro2", "quote", @@ -8717,9 +8778,9 @@ dependencies = [ [[package]] name = "wasm-bindgen-shared" -version = "0.2.89" +version = "0.2.90" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7ab9b36309365056cd639da3134bf87fa8f3d86008abf99e612384a6eecd459f" +checksum = "4d91413b1c31d7539ba5ef2451af3f0b833a005eb27a631cec32bc0635a8602b" [[package]] name = "wasm-streams" @@ -8786,9 +8847,9 @@ dependencies = [ [[package]] name = "web-sys" -version = "0.3.66" +version = "0.3.67" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "50c24a44ec86bb68fbecd1b3efed7e85ea5621b39b35ef2766b66cd984f8010f" +checksum = "58cd2333b6e0be7a39605f0e255892fd7418a682d8da8fe042fe25128794d2ed" dependencies = [ "js-sys", "wasm-bindgen", @@ -8835,7 +8896,7 @@ dependencies = [ "either", "home", "once_cell", - "rustix 0.38.28", + "rustix 0.38.30", ] [[package]] @@ -9137,9 +9198,9 @@ checksum = "dff9641d1cd4be8d1a070daf9e3773c5f67e78b4d9d42263020c057706765c04" [[package]] name = "winnow" -version = "0.5.33" +version = "0.5.34" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b7520bbdec7211caa7c4e682eb1fbe07abe20cee6756b6e00f537c82c11816aa" +checksum = "b7cf47b659b318dccbd69cc4797a39ae128f533dce7902a1096044d1967b9c16" dependencies = [ "memchr", ] diff --git a/Cargo.toml b/Cargo.toml index e059fa9f679..f43d375f0d9 100644 --- a/Cargo.toml +++ b/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" 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 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 => { diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index 9c5321591bc..6975711651b 100644 --- a/common/logging/Cargo.toml +++ b/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 } diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index a9ad25f3f3e..80fc00a00f2 100644 --- a/common/logging/src/lib.rs +++ b/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); diff --git a/common/logging/src/tracing_metrics_layer.rs b/common/logging/src/tracing_metrics_layer.rs new file mode 100644 index 00000000000..08c323ee890 --- /dev/null +++ b/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::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::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::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 tracing_subscriber::layer::Layer 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), + _ => {} + } + } +} diff --git a/lighthouse/Cargo.toml b/lighthouse/Cargo.toml index 87668656501..c402e5b9320 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 = { workspace = true } +logging = { workspace = true } [dev-dependencies] tempfile = { workspace = true } diff --git a/lighthouse/src/main.rs b/lighthouse/src/main.rs index edf661abab3..ccdfa60f114 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; @@ -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::::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| {