Remove env_logger and use telemetry logging in tests (#1247)

* Remove env_logger and reuse telemetry logging in tests * Use test-captured writer for telemetry logs in tests * Isolate test logging init from OTEL and keep tests quiet
2026-03-15 15:43:39 +01:00
parent 4e00acd36b
commit 8db4f036b8
7 changed files with 79 additions and 110 deletions
@@ -354,21 +354,6 @@ dependencies = [
 "libc",
 ]

-[[package]]
-name = "anstream"
-version = "0.6.21"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "43d5b281e737544384e969a5ccad3f1cdd24b48086a0fc1b2a5262a26b8f4f4a"
-dependencies = [
- "anstyle",
- "anstyle-parse 0.2.7",
- "anstyle-query",
- "anstyle-wincon",
- "colorchoice",
- "is_terminal_polyfill",
- "utf8parse",
-]
-
 [[package]]
 name = "anstream"
 version = "1.0.0"
@@ -376,7 +361,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "824a212faf96e9acacdbd09febd34438f8f711fb84e09a8916013cd7815ca28d"
 dependencies = [
 "anstyle",
- "anstyle-parse 1.0.0",
+ "anstyle-parse",
 "anstyle-query",
 "anstyle-wincon",
 "colorchoice",
@@ -390,15 +375,6 @@ version = "1.0.14"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "940b3a0ca603d1eade50a4846a2afffd5ef57a9feac2c0e2ec2e14f9ead76000"

-[[package]]
-name = "anstyle-parse"
-version = "0.2.7"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4e7644824f0aa2c7b9384579234ef10eb7efb6a0deb83f9630a49594dd9c15c2"
-dependencies = [
- "utf8parse",
-]
-
 [[package]]
 name = "anstyle-parse"
 version = "1.0.0"
@@ -944,7 +920,7 @@ version = "4.6.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "714a53001bf66416adb0e2ef5ac857140e7dc3a0c48fb28b2f10762fc4b5069f"
 dependencies = [
- "anstream 1.0.0",
+ "anstream",
 "anstyle",
 "clap_lex",
 "strsim",
@@ -1634,29 +1610,6 @@ dependencies = [
 "cfg-if",
 ]

-[[package]]
-name = "env_filter"
-version = "1.0.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "7a1c3cc8e57274ec99de65301228b537f1e4eedc1b8e0f9411c6caac8ae7308f"
-dependencies = [
- "log",
- "regex",
-]
-
-[[package]]
-name = "env_logger"
-version = "0.11.9"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "b2daee4ea451f429a58296525ddf28b45a3b64f1acf6587e2067437bb11e218d"
-dependencies = [
- "anstream 0.6.21",
- "anstyle",
- "env_filter",
- "jiff",
- "log",
-]
-
 [[package]]
 name = "equivalent"
 version = "1.0.2"
@@ -2509,30 +2462,6 @@ version = "1.0.17"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "92ecc6618181def0457392ccd0ee51198e065e016d1d527a7ac1b6dc7c1f09d2"

-[[package]]
-name = "jiff"
-version = "0.2.23"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1a3546dc96b6d42c5f24902af9e2538e82e39ad350b0c766eb3fbf2d8f3d8359"
-dependencies = [
- "jiff-static",
- "log",
- "portable-atomic",
- "portable-atomic-util",
- "serde_core",
-]
-
-[[package]]
-name = "jiff-static"
-version = "0.2.23"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "2a8c8b344124222efd714b73bb41f8b5120b27a7cc1c75593a6ff768d9d05aa4"
-dependencies = [
- "proc-macro2",
- "quote",
- "syn",
-]
-
 [[package]]
 name = "jni"
 version = "0.21.1"
@@ -3674,21 +3603,6 @@ dependencies = [
 "windows-sys 0.61.2",
 ]

-[[package]]
-name = "portable-atomic"
-version = "1.13.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "c33a9471896f1c69cecef8d20cbe2f7accd12527ce60845ff44c153bb2a21b49"
-
-[[package]]
-name = "portable-atomic-util"
-version = "0.2.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "7a9db96d7fa8782dd8c15ce32ffe8680bbd1e978a43bf51a34d39483540495f5"
-dependencies = [
- "portable-atomic",
-]
-
 [[package]]
 name = "potential_utf"
 version = "0.1.4"
@@ -4604,7 +4518,6 @@ dependencies = [
 "csv-async",
 "dotenvy",
 "encoding_rs",
- "env_logger",
 "futures-util",
 "handlebars",
 "hmac",
@@ -37,7 +37,6 @@ actix-web = { version = "4", features = ["rustls-0_23", "cookies"] }
 percent-encoding = "2.2.0"
 handlebars = "6.2.0"
 log = "0.4.17"
-env_logger = "0.11.1"
 mime_guess = "2.0.4"
 futures-util = "0.3.21"
 tokio = { version = "1.24.1", features = ["macros", "rt", "process", "sync"] }
@@ -7,29 +7,45 @@
 //! fields for human readability and machine parseability.

 use std::env;
-use std::sync::OnceLock;
+use std::sync::{Once, OnceLock};

 use opentelemetry_sdk::metrics::SdkMeterProvider;
 use opentelemetry_sdk::trace::SdkTracerProvider;

 static TRACER_PROVIDER: OnceLock<SdkTracerProvider> = OnceLock::new();
 static METER_PROVIDER: OnceLock<SdkMeterProvider> = OnceLock::new();
+static TEST_LOGGING_INIT: Once = Once::new();
+const DEFAULT_ENV_FILTER_DIRECTIVES: &str = "sqlpage=info,actix_web=info,tracing_actix_web=info";

 /// Initializes logging / tracing. Returns `true` if `OTel` was activated.
 #[must_use]
 pub fn init_telemetry() -> bool {
+    init_telemetry_with_log_layer(logfmt::LogfmtLayer::new())
+}
+
+fn init_telemetry_with_log_layer(logfmt_layer: logfmt::LogfmtLayer) -> bool {
    let otel_endpoint = env::var("OTEL_EXPORTER_OTLP_ENDPOINT").ok();
    let otel_active = otel_endpoint.as_deref().is_some_and(|v| !v.is_empty());

    if otel_active {
-        init_otel_tracing();
+        init_otel_tracing(logfmt_layer);
    } else {
-        init_tracing();
+        init_tracing(logfmt_layer);
    }

    otel_active
 }

+/// Initializes logging once for tests using the same formatter as production.
+///
+/// Unlike `init_telemetry`, this does not initialize OTEL exporters and does
+/// not panic on invalid `LOG_LEVEL` / `RUST_LOG` values.
+pub fn init_test_logging() {
+    TEST_LOGGING_INIT.call_once(|| {
+        init_test_tracing();
+    });
+}
+
 /// Shuts down the `OTel` tracer provider, flushing pending spans.
 pub fn shutdown_telemetry() {
    if let Some(provider) = TRACER_PROVIDER.get() {
@@ -45,17 +61,27 @@ pub fn shutdown_telemetry() {
 }

 /// Tracing subscriber without `OTel` export — logfmt output only.
-fn init_tracing() {
+fn init_tracing(logfmt_layer: logfmt::LogfmtLayer) {
    use tracing_subscriber::layer::SubscriberExt;

    let subscriber = tracing_subscriber::registry()
        .with(default_env_filter())
-        .with(logfmt::LogfmtLayer::new());
+        .with(logfmt_layer);

    set_global_subscriber(subscriber);
 }

-fn init_otel_tracing() {
+fn init_test_tracing() {
+    use tracing_subscriber::layer::SubscriberExt;
+
+    let subscriber = tracing_subscriber::registry()
+        .with(test_env_filter())
+        .with(logfmt::LogfmtLayer::test_writer());
+
+    set_global_subscriber(subscriber);
+}
+
+fn init_otel_tracing(logfmt_layer: logfmt::LogfmtLayer) {
    use opentelemetry::global;
    use opentelemetry::trace::TracerProvider as _;
    use opentelemetry_sdk::propagation::TraceContextPropagator;
@@ -117,7 +143,7 @@ fn init_otel_tracing() {

    let subscriber = tracing_subscriber::registry()
        .with(default_env_filter())
-        .with(logfmt::LogfmtLayer::new())
+        .with(logfmt_layer)
        .with(otel_layer)
        .with(tracing_opentelemetry::MetricsLayer::new(meter_provider));

@@ -133,13 +159,26 @@ fn default_env_filter() -> tracing_subscriber::EnvFilter {
    .expect("Invalid log filter value in LOG_LEVEL or RUST_LOG")
 }

+fn test_env_filter() -> tracing_subscriber::EnvFilter {
+    env_filter_directives(
+        env::var("LOG_LEVEL").ok().as_deref(),
+        env::var("RUST_LOG").ok().as_deref(),
+    )
+    .parse()
+    .unwrap_or_else(|_| {
+        DEFAULT_ENV_FILTER_DIRECTIVES
+            .parse()
+            .expect("Default filter directives should always be valid")
+    })
+}
+
 fn env_filter_directives(log_level: Option<&str>, rust_log: Option<&str>) -> String {
    match (
        log_level.filter(|value| !value.is_empty()),
        rust_log.filter(|value| !value.is_empty()),
    ) {
        (Some(value), _) | (None, Some(value)) => value.to_owned(),
-        (None, None) => "sqlpage=info,actix_web=info,tracing_actix_web=info".to_owned(),
+        (None, None) => DEFAULT_ENV_FILTER_DIRECTIVES.to_owned(),
    }
 }

@@ -217,14 +256,29 @@ mod logfmt {
    const BOLD: &str = "\x1b[1m";
    const RESET: &str = "\x1b[0m";

+    #[derive(Copy, Clone)]
+    enum OutputMode {
+        Stderr,
+        TestWriter,
+    }
+
    pub(super) struct LogfmtLayer {
        use_colors: bool,
+        output_mode: OutputMode,
    }

    impl LogfmtLayer {
        pub fn new() -> Self {
            Self {
                use_colors: io::stderr().is_terminal(),
+                output_mode: OutputMode::Stderr,
+            }
+        }
+
+        pub fn test_writer() -> Self {
+            Self {
+                use_colors: false,
+                output_mode: OutputMode::TestWriter,
            }
        }
    }
@@ -280,7 +334,14 @@ mod logfmt {

            buf.push('\n');
            write_multiline_message(&mut buf, msg, multiline_msg);
-            let _ = io::Write::write_all(&mut io::stderr().lock(), buf.as_bytes());
+            match self.output_mode {
+                OutputMode::Stderr => {
+                    let _ = io::Write::write_all(&mut io::stderr().lock(), buf.as_bytes());
+                }
+                OutputMode::TestWriter => {
+                    eprint!("{buf}");
+                }
+            }
        }
    }

@@ -174,10 +174,7 @@ mod tests {
    use sqlx::Connection;

    fn setup_logging() {
-        let _ = env_logger::builder()
-            .parse_default_env()
-            .is_test(true)
-            .try_init();
+        crate::telemetry::init_test_logging();
    }

    fn db_specific_test(db_type: &str) -> Option<String> {
@@ -371,7 +371,7 @@ mod test {

    #[actix_web::test]
    async fn test_extract_multipart_form_data() {
-        let _ = env_logger::try_init();
+        crate::telemetry::init_test_logging();
        let config =
            serde_json::from_str::<AppConfig>(r#"{"listen_on": "localhost:1234"}"#).unwrap();
        let mut service_request = TestRequest::get()
@@ -11,6 +11,7 @@ use actix_web::{
 };
 use sqlpage::{
    app_config::{test_database_url, AppConfig},
+    telemetry,
    webserver::http::{form_config, main_handler, payload_config},
    AppState,
 };
@@ -111,10 +112,7 @@ pub fn test_config() -> AppConfig {
 }

 pub fn init_log() {
-    let _ = env_logger::builder()
-        .parse_default_env()
-        .is_test(true)
-        .try_init();
+    telemetry::init_test_logging();
 }

 fn format_request_line_and_headers(req: &ServiceRequest) -> String {
@@ -141,9 +141,10 @@ async fn test_file_upload_too_large() -> actix_web::Result<()> {
        .await
        .expect_err("Expected an error response")
        .to_string();
+    let msg = "max file size";
    assert!(
-        err_str.to_ascii_lowercase().contains("max file size"),
-        "{err_str}\nexpected to contain: File too large"
+        err_str.to_ascii_lowercase().contains(msg),
+        "{err_str}\nexpected to contain: {msg}"
    );
    Ok(())
 }