fix(otel): honor RUST_LOG directives for logs (#11360)

Signed-off-by: Jasper Hugo <jasper@spiral.xyz>
2026-08-19 21:53:53 +00:00
parent 6d6abf74a1
commit b7eef328df
1 changed files with 125 additions and 19 deletions
@@ -11,7 +11,7 @@ use std::env;
 use std::sync::{Arc, Mutex};
 use tracing::{Level, Metadata};
 use tracing_opentelemetry::{MetricsLayer, OpenTelemetryLayer};
-use tracing_subscriber::filter::FilterFn;
+use tracing_subscriber::filter::{EnvFilter, FilterExt, FilterFn};
 use tracing_subscriber::Layer as _;

 pub type OtlpTracingLayer =
@@ -534,14 +534,9 @@ fn parse_level(s: &str) -> Option<Level> {
 }

 fn otel_logs_level() -> Level {
-    env::var("RUST_LOG")
+    env::var("OTEL_LOG_LEVEL")
        .ok()
        .and_then(|s| parse_level(&s))
-        .or_else(|| {
-            env::var("OTEL_LOG_LEVEL")
-                .ok()
-                .and_then(|s| parse_level(&s))
-        })
        .unwrap_or(Level::INFO)
 }

@@ -554,19 +549,23 @@ fn otel_logs_level() -> Level {
 const OTLP_LOGS_SUPPRESSED_TARGETS: &[&str] = &["rmcp::service"];

 /// Creates a custom filter for OTLP logs.
-/// Level is resolved via RUST_LOG → OTEL_LOG_LEVEL → default INFO.
+/// Valid RUST_LOG directives take precedence over OTEL_LOG_LEVEL and default INFO.
+/// Invalid RUST_LOG values fall back to OTEL_LOG_LEVEL and default INFO.
 /// Suppresses targets listed in `OTLP_LOGS_SUPPRESSED_TARGETS`.
-fn create_otlp_logs_filter() -> FilterFn<impl Fn(&Metadata<'_>) -> bool> {
-    let min_level = otel_logs_level();
-    FilterFn::new(move |metadata: &Metadata<'_>| {
-        if metadata.level() > &min_level {
-            return false;
-        }
+fn create_otlp_logs_filter() -> impl tracing_subscriber::layer::Filter<tracing_subscriber::Registry>
+{
+    let filter = match env::var("RUST_LOG") {
+        Ok(value) if !value.trim().is_empty() => EnvFilter::try_new(value)
+            .unwrap_or_else(|_| EnvFilter::new(otel_logs_level().to_string())),
+        _ => EnvFilter::new(otel_logs_level().to_string()),
+    };
+
+    filter.and(FilterFn::new(|metadata: &Metadata<'_>| {
        let target = metadata.target();
        !OTLP_LOGS_SUPPRESSED_TARGETS
            .iter()
            .any(|suppressed| target.starts_with(suppressed))
-    })
+    }))
 }

 pub fn shutdown_otlp() {
@@ -625,7 +624,32 @@ mod tests {
    use crate::session_context::{session_host, session_user};
    use goose_test_support::otel::clear_otel_env;
    use opentelemetry_sdk::metrics::Temporality;
+    use std::sync::atomic::{AtomicUsize, Ordering};
    use test_case::test_case;
+    use tracing::{Event, Subscriber};
+    use tracing_subscriber::layer::{Context, SubscriberExt};
+
+    #[derive(Clone)]
+    struct EventCounter(Arc<AtomicUsize>);
+
+    impl<S> tracing_subscriber::Layer<S> for EventCounter
+    where
+        S: Subscriber,
+    {
+        fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {
+            self.0.fetch_add(1, Ordering::Relaxed);
+        }
+    }
+
+    fn count_otlp_log_events(env: &[(&'static str, &'static str)], emit: impl FnOnce()) -> usize {
+        let _guard = clear_otel_env(env);
+        let seen = Arc::new(AtomicUsize::new(0));
+        let subscriber = tracing_subscriber::Registry::default()
+            .with(EventCounter(Arc::clone(&seen)).with_filter(create_otlp_logs_filter()));
+
+        tracing::subscriber::with_default(subscriber, emit);
+        seen.load(Ordering::Relaxed)
+    }

    #[test]
    fn exporter_type_from_env_value() {
@@ -897,11 +921,7 @@ mod tests {
    }

    #[test_case(&[("RUST_LOG", "")], Level::INFO; "default is info")]
-    #[test_case(&[("RUST_LOG", "debug")], Level::DEBUG; "RUST_LOG takes precedence")]
    #[test_case(&[("RUST_LOG", ""), ("OTEL_LOG_LEVEL", "error")], Level::ERROR; "OTEL_LOG_LEVEL fallback")]
-    #[test_case(&[("RUST_LOG", "warn"), ("OTEL_LOG_LEVEL", "error")], Level::WARN; "RUST_LOG wins over OTEL_LOG_LEVEL")]
-    #[test_case(&[("RUST_LOG", "goose=debug"), ("OTEL_LOG_LEVEL", "trace")], Level::TRACE; "directive RUST_LOG falls through to OTEL_LOG_LEVEL")]
-    #[test_case(&[("RUST_LOG", "goose=debug")], Level::INFO; "directive RUST_LOG falls through to default")]
    #[test_case(&[("RUST_LOG", ""), ("OTEL_LOG_LEVEL", "INFO")], Level::INFO; "case insensitive")]
    #[test_case(&[("RUST_LOG", ""), ("OTEL_LOG_LEVEL", "bogus")], Level::INFO; "unknown defaults to info")]
    fn otel_logs_level_from_env(env: &[(&'static str, &'static str)], expected: Level) {
@@ -909,6 +929,92 @@ mod tests {
        assert_eq!(otel_logs_level(), expected);
    }

+    #[test]
+    fn otlp_logs_filter_honors_bare_rust_log_level() {
+        let seen = count_otlp_log_events(&[("RUST_LOG", "warn")], || {
+            tracing::error!(target: "goose::test", "error event");
+            tracing::warn!(target: "goose::test", "warn event");
+            tracing::info!(target: "goose::test", "info event");
+        });
+
+        assert_eq!(seen, 2);
+    }
+
+    #[test]
+    fn otlp_logs_filter_honors_scoped_and_mixed_rust_log_directives() {
+        let seen = count_otlp_log_events(
+            &[(
+                "RUST_LOG",
+                "goose=error,goose::agents::retry=debug,other=warn",
+            )],
+            || {
+                tracing::debug!(target: "goose::agents::retry", "retry detail");
+                tracing::info!(target: "goose::providers", "provider detail");
+                tracing::warn!(target: "other::component", "other warning");
+                tracing::info!(target: "other::component", "other detail");
+            },
+        );
+
+        assert_eq!(seen, 2);
+    }
+
+    #[test]
+    fn otlp_logs_filter_falls_back_for_invalid_rust_log() {
+        let seen = count_otlp_log_events(
+            &[
+                ("RUST_LOG", "goose=definitely-not-a-level"),
+                ("OTEL_LOG_LEVEL", "error"),
+            ],
+            || {
+                tracing::error!(target: "goose::test", "error event");
+                tracing::warn!(target: "goose::test", "warn event");
+            },
+        );
+
+        assert_eq!(seen, 1);
+    }
+
+    #[test]
+    fn otlp_logs_filter_uses_otel_and_default_fallbacks() {
+        let otel_seen =
+            count_otlp_log_events(&[("RUST_LOG", ""), ("OTEL_LOG_LEVEL", "error")], || {
+                tracing::error!(target: "goose::test", "error event");
+                tracing::warn!(target: "goose::test", "warn event");
+            });
+        let default_seen = count_otlp_log_events(&[("RUST_LOG", "")], || {
+            tracing::info!(target: "goose::test", "info event");
+            tracing::debug!(target: "goose::test", "debug event");
+        });
+
+        assert_eq!(otel_seen, 1);
+        assert_eq!(default_seen, 1);
+    }
+
+    #[test]
+    fn otlp_logs_filter_always_suppresses_sensitive_targets() {
+        let seen =
+            count_otlp_log_events(&[("RUST_LOG", "trace,rmcp::service::client=trace")], || {
+                tracing::info!(target: "rmcp::service", "suppressed root");
+                tracing::error!(target: "rmcp::service::client", "suppressed descendant");
+                tracing::info!(target: "goose::test", "allowed event");
+            });
+
+        assert_eq!(seen, 1);
+    }
+
+    #[test]
+    fn otlp_logs_filter_excludes_sensitive_info_event_for_goose_error() {
+        let seen = count_otlp_log_events(&[("RUST_LOG", "goose=error")], || {
+            tracing::info!(
+                target: "goose::agents::retry",
+                command = "curl -H Authorization:Bearer_REDACTED_TEST_VALUE",
+                "success check passed"
+            );
+        });
+
+        assert_eq!(seen, 0);
+    }
+
    fn test_config(
        params: &[(&str, &str)],
    ) -> (