From b7eef328df297757c37ad233336ea0fd5eb932d7 Mon Sep 17 00:00:00 2001 From: Jasper Date: Wed, 19 Aug 2026 21:53:53 +0000 Subject: [PATCH] fix(otel): honor RUST_LOG directives for logs (#11360) Signed-off-by: Jasper Hugo --- crates/goose/src/otel/otlp.rs | 144 +++++++++++++++++++++++++++++----- 1 file changed, 125 insertions(+), 19 deletions(-) diff --git a/crates/goose/src/otel/otlp.rs b/crates/goose/src/otel/otlp.rs index d8a5d76fc..d710da3dc 100644 --- a/crates/goose/src/otel/otlp.rs +++ b/crates/goose/src/otel/otlp.rs @@ -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 { } 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) -> 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 +{ + 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); + + impl tracing_subscriber::Layer 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)], ) -> (