From 015e1ed9635ad4025823b3abaaeed4075363427b Mon Sep 17 00:00:00 2001 From: Roland Sherwin Date: Mon, 18 Mar 2024 19:47:04 +0530 Subject: [PATCH] test(log): add test to verify log reload functionality --- .github/workflows/merge.yml | 4 ++ .github/workflows/nightly.yml | 4 ++ Cargo.lock | 69 ++++++++++++++++++++++++++---- sn_logging/Cargo.toml | 4 ++ sn_logging/src/layers.rs | 4 +- sn_logging/src/lib.rs | 80 +++++++++++++++++++++++++++++++++++ 6 files changed, 155 insertions(+), 10 deletions(-) diff --git a/.github/workflows/merge.yml b/.github/workflows/merge.yml index 84b8b7674e..672051b2d6 100644 --- a/.github/workflows/merge.yml +++ b/.github/workflows/merge.yml @@ -123,6 +123,10 @@ jobs: timeout-minutes: 25 run: cargo test --release --package sn_transfers + - name: Run logging tests + timeout-minutes: 25 + run: cargo test --release --package sn_logging + - name: Run register tests timeout-minutes: 25 run: cargo test --release --package sn_registers diff --git a/.github/workflows/nightly.yml b/.github/workflows/nightly.yml index 124f2ae3a6..e773fe623a 100644 --- a/.github/workflows/nightly.yml +++ b/.github/workflows/nightly.yml @@ -160,6 +160,10 @@ jobs: timeout-minutes: 25 run: cargo test --release --package sn_transfers + - name: Run logging tests + timeout-minutes: 25 + run: cargo test --release --package sn_logging + - name: Run register tests shell: bash timeout-minutes: 50 diff --git a/Cargo.lock b/Cargo.lock index b5e711380a..83ddc0cd81 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -687,7 +687,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "05efc5cfd9110c8416e471df0e96702d58690178e206e61b7173706673c93706" dependencies = [ "memchr", - "regex-automata", + "regex-automata 0.4.6", "serde", ] @@ -1869,8 +1869,8 @@ dependencies = [ "aho-corasick", "bstr", "log", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.6", + "regex-syntax 0.8.2", ] [[package]] @@ -2301,7 +2301,7 @@ dependencies = [ "globset", "log", "memchr", - "regex-automata", + "regex-automata 0.4.6", "same-file", "walkdir", "winapi-util", @@ -3007,6 +3007,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matchit" version = "0.7.3" @@ -3978,7 +3987,7 @@ dependencies = [ "rand", "rand_chacha", "rand_xorshift", - "regex-syntax", + "regex-syntax 0.8.2", "rusty-fork", "tempfile", "unarray", @@ -4279,8 +4288,17 @@ checksum = "b62dbe01f0b06f9d8dc7d49e05a0785f153b00b2c227856282f671e0318c9b15" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.6", + "regex-syntax 0.8.2", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -4291,9 +4309,15 @@ checksum = "86b83b8b9847f9bf95ef68afb0b8e6cdb80f498442f5179a29fad448fcc1eaea" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.2", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.2" @@ -5023,6 +5047,7 @@ name = "sn_logging" version = "0.2.23" dependencies = [ "chrono", + "color-eyre", "dirs-next", "file-rotate", "opentelemetry", @@ -5039,6 +5064,7 @@ dependencies = [ "tracing-core", "tracing-opentelemetry", "tracing-subscriber", + "tracing-test", ] [[package]] @@ -6042,17 +6068,44 @@ version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "regex", "serde", "serde_json", "sharded-slab", "smallvec", "thread_local", + "tracing", "tracing-core", "tracing-log 0.2.0", "tracing-serde", ] +[[package]] +name = "tracing-test" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3a2c0ff408fe918a94c428a3f2ad04e4afd5c95bbc08fcf868eff750c15728a4" +dependencies = [ + "lazy_static", + "tracing-core", + "tracing-subscriber", + "tracing-test-macro", +] + +[[package]] +name = "tracing-test-macro" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "258bc1c4f8e2e73a977812ab339d503e6feeb92700f6d07a6de4d321522d5c08" +dependencies = [ + "lazy_static", + "quote", + "syn 1.0.109", +] + [[package]] name = "tracing-wasm" version = "0.2.1" diff --git a/sn_logging/Cargo.toml b/sn_logging/Cargo.toml index c6b9fcf897..9929754160 100644 --- a/sn_logging/Cargo.toml +++ b/sn_logging/Cargo.toml @@ -29,6 +29,10 @@ tracing-core = "0.1.30" tracing-opentelemetry = { version = "0.21", optional = true } tracing-subscriber = { version = "0.3.16", features=["json"] } +[dev-dependencies] +color-eyre = "~0.6" +tracing-test = "0.2.4" + [features] otlp = [ "opentelemetry", diff --git a/sn_logging/src/layers.rs b/sn_logging/src/layers.rs index bbeb3c5134..a97f665e4d 100644 --- a/sn_logging/src/layers.rs +++ b/sn_logging/src/layers.rs @@ -37,7 +37,7 @@ const ALL_SN_LOGS: &str = "all"; const VERBOSE_SN_LOGS: &str = "v"; /// Handle that implements functions to change the log level on the fly. -pub struct ReloadHandle(Handle + Send + Sync>, Registry>); +pub struct ReloadHandle(pub(crate) Handle + Send + Sync>, Registry>); impl ReloadHandle { /// Modify the log level to the provided CSV value @@ -59,7 +59,7 @@ impl ReloadHandle { #[derive(Default)] /// Tracing log formatter setup for easier span viewing -struct LogFormatter; +pub(crate) struct LogFormatter; impl FormatEvent for LogFormatter where diff --git a/sn_logging/src/lib.rs b/sn_logging/src/lib.rs index 82e05509f5..bd43057ec8 100644 --- a/sn_logging/src/lib.rs +++ b/sn_logging/src/lib.rs @@ -200,3 +200,83 @@ impl LogBuilder { layers } } + +#[cfg(test)] +mod tests { + use crate::{layers::LogFormatter, ReloadHandle}; + use color_eyre::Result; + use tracing::{trace, warn, Level}; + use tracing_subscriber::{ + filter::Targets, + fmt as tracing_fmt, + layer::{Filter, SubscriberExt}, + reload, + util::SubscriberInitExt, + Layer, Registry, + }; + use tracing_test::internal::GLOBAL_BUF; + + #[test] + // todo: break down the TracingLayers so that we can plug in the writer without having to rewrite the whole function + // here. + fn reload_handle_should_change_log_levels() -> Result<()> { + // A mock write that writes to stdout + collects events to a global buffer. We can later read from this buffer. + let mock_writer = tracing_test::internal::MockWriter::new(&GLOBAL_BUF); + + // Constructing the fmt layer manually. + let layer = tracing_fmt::layer() + .with_ansi(false) + .with_target(false) + .event_format(LogFormatter) + .with_writer(mock_writer) + .boxed(); + + let test_target = "sn_logging::tests".to_string(); + // to enable logs just for the test. + let target_filters: Box + Send + Sync> = + Box::new(Targets::new().with_targets(vec![(test_target.clone(), Level::TRACE)])); + + // add the reload layer + let (filter, handle) = reload::Layer::new(target_filters); + let reload_handle = ReloadHandle(handle); + let layer = layer.with_filter(filter); + tracing_subscriber::registry().with(layer).try_init()?; + + // Span is not controlled by the ReloadHandle. So we can set any span here. + let _span = tracing::info_span!("info span"); + + trace!("First trace event"); + + { + let buf = GLOBAL_BUF.lock().unwrap(); + + let events: Vec<&str> = std::str::from_utf8(&buf) + .expect("Logs contain invalid UTF8") + .lines() + .collect(); + assert_eq!(events.len(), 1); + assert!(events[0].contains("First trace event")); + } + + reload_handle.modify_log_level("sn_logging::tests=WARN")?; + + // trace should not be logged now. + trace!("Second trace event"); + warn!("First warn event"); + + { + let buf = GLOBAL_BUF.lock().unwrap(); + + let events: Vec<&str> = std::str::from_utf8(&buf) + .expect("Logs contain invalid UTF8") + .lines() + .collect(); + + assert_eq!(events.len(), 2); + assert!(events[0].contains("First trace event")); + assert!(events[1].contains("First warn event")); + } + + Ok(()) + } +}