From 4046254aa995191b0611e1a916980c1948329574 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jonasz=20Ma=C5=82ecki?= Date: Sun, 11 Oct 2026 17:56:26 +0200 Subject: [PATCH] fix(logging): drop the env-filter feature MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #38 enabled tracing-subscriber's env-filter feature, and Cargo unifies features across a build, so it was on in every function that depends on the SDK. That changes tracing_subscriber::fmt::init(): with RUST_LOG unset it installs an EnvFilter that defaults to ERROR instead of INFO, so a function that sets up logging itself lost its info and warn logs. Filter with Targets instead, which needs no extra feature. RUST_LOG still replaces the level selection for target=level directives and bare levels; a RUST_LOG with span or field filters is ignored with a warning, and the --debug selection applies. Signed-off-by: Jonasz Małecki --- Cargo.lock | 13 ----- sdk/Cargo.toml | 2 +- sdk/README.md | 4 +- sdk/src/logging.rs | 115 ++++++++++++++++++++++++++++----------------- 4 files changed, 75 insertions(+), 59 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5229314..40f0efc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -706,15 +706,6 @@ version = "0.4.34" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f9f8bd3e56ce4dfc153cf470fffbfa98c7620958b312ca5c3a4b8d5181fd13c6" -[[package]] -name = "matchers" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" -dependencies = [ - "regex-automata", -] - [[package]] name = "matchit" version = "0.8.4" @@ -1569,16 +1560,12 @@ version = "0.3.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" dependencies = [ - "matchers", "nu-ansi-term", - "once_cell", - "regex-automata", "serde", "serde_json", "sharded-slab", "smallvec", "thread_local", - "tracing", "tracing-core", "tracing-log", "tracing-serde", diff --git a/sdk/Cargo.toml b/sdk/Cargo.toml index f991b36..8240015 100644 --- a/sdk/Cargo.toml +++ b/sdk/Cargo.toml @@ -28,7 +28,7 @@ clap = { version = "4", features = ["derive", "env"] } tracing = "0.1" tower-layer = "0.3" tower-service = "0.3" -tracing-subscriber = { version = "0.3", features = ["json", "env-filter"] } +tracing-subscriber = { version = "0.3", features = ["json"] } sha2 = "0.11" thiserror = "2" # Not used directly: raises the transitive rustls floor past RUSTSEC-2026-0285. diff --git a/sdk/README.md b/sdk/README.md index 60386df..3a35fc1 100644 --- a/sdk/README.md +++ b/sdk/README.md @@ -17,8 +17,8 @@ API. This crate provides: results, conditions, readiness, and desired resource updates from any `serde::Serialize` source. - `logging` - JSON-lines logging to stderr with a human-readable debug mode - that keeps the gRPC transport crates at info; `RUST_LOG` overrides the - level selection. + that keeps the gRPC transport crates at info; `RUST_LOG` (`target=level` + directives) overrides the level selection. See the [repository](https://github.com/crossplane/function-sdk-rust) for a complete example function. diff --git a/sdk/src/logging.rs b/sdk/src/logging.rs index ce89854..dde140d 100644 --- a/sdk/src/logging.rs +++ b/sdk/src/logging.rs @@ -1,6 +1,8 @@ //! Logging setup for composition functions. -use tracing_subscriber::EnvFilter; +use tracing_subscriber::filter::{LevelFilter, ParseError, Targets}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; /// The gRPC, HTTP/2 and TLS crates under every function's server. Their /// DEBUG output (h2 logs every frame) buries the function's own, so @@ -11,8 +13,11 @@ const TRANSPORT_TARGETS: [&str; 6] = ["h2", "hyper", "hyper_util", "tonic", "tow /// /// Logs are JSON lines at info level. With debug enabled they are /// human-readable, at debug level for everything but the gRPC transport -/// stack. `RUST_LOG`, when set, replaces the level selection in full. To -/// hold back more crates under debug, use [`Builder`]. +/// stack. `RUST_LOG`, when set, replaces the level selection in full. It +/// takes comma-separated `target=level` directives and bare levels, such as +/// `info,my_function=debug`; a `RUST_LOG` with span or field filters is +/// ignored with a warning. To hold back more crates under debug, use +/// [`Builder`]. pub fn configure(debug: bool) { Builder::new(debug).init(); } @@ -59,82 +64,106 @@ impl Builder { /// before serving. pub fn init(self) { let rust_log = std::env::var("RUST_LOG").ok(); - // parse_lossy reports a malformed directive on stderr and applies the rest. - let filter = EnvFilter::builder().parse_lossy(self.directives(rust_log.as_deref())); + let (filter, ignored) = self.filter(rust_log.as_deref()); + // The fmt builder caps events at INFO by default; the filter decides. let builder = tracing_subscriber::fmt() - .with_env_filter(filter) + .with_max_level(LevelFilter::TRACE) .with_writer(std::io::stderr) .with_file(true) .with_line_number(true); if self.debug { - builder.init(); + builder.finish().with(filter).init(); } else { - builder.json().init(); + builder.json().finish().with(filter).init(); + } + if let Some(error) = ignored { + tracing::warn!(%error, "ignoring RUST_LOG, which takes only target=level directives"); } } - /// The filter directives: `rust_log` verbatim when it is set and not - /// blank, else INFO everywhere - or, under debug, DEBUG everywhere - /// except the transport stack and the quiet targets. - fn directives(&self, rust_log: Option<&str>) -> String { - if let Some(set) = rust_log.map(str::trim).filter(|s| !s.is_empty()) { - return set.to_string(); - } + /// The level filter: `rust_log` when it is set, not blank and valid, + /// else INFO everywhere - or, under debug, DEBUG everywhere except the + /// transport stack and the quiet targets. Also returns why an invalid + /// `rust_log` was ignored. + fn filter(&self, rust_log: Option<&str>) -> (Targets, Option) { + let ignored = match rust_log.map(str::trim).filter(|s| !s.is_empty()) { + None => None, + Some(set) => match set.parse() { + Ok(filter) => return (filter, None), + Err(error) => Some(error), + }, + }; if !self.debug { - return "info".to_string(); + return (Targets::new().with_default(LevelFilter::INFO), ignored); } - let mut directives = String::from("debug"); - for target in TRANSPORT_TARGETS + let filter = TRANSPORT_TARGETS .iter() .copied() .chain(self.quiet.iter().map(String::as_str)) - { - directives.push_str(&format!(",{target}=info")); - } - directives + .fold( + Targets::new().with_default(LevelFilter::DEBUG), + |filter, target| filter.with_target(target, LevelFilter::INFO), + ); + (filter, ignored) } } #[cfg(test)] mod tests { use super::*; + use tracing::Level; - const TRANSPORT_AT_INFO: &str = - "debug,h2=info,hyper=info,hyper_util=info,tonic=info,tower=info,rustls=info"; + fn enabled(builder: &Builder, rust_log: Option<&str>, target: &str, level: Level) -> bool { + builder.filter(rust_log).0.would_enable(target, &level) + } #[test] fn info_by_default() { - assert_eq!(Builder::new(false).directives(None), "info"); - assert_eq!(Builder::new(false).directives(Some(" ")), "info"); + let builder = Builder::new(false); + for rust_log in [None, Some(" ")] { + assert!(enabled(&builder, rust_log, "my_function", Level::INFO)); + assert!(!enabled(&builder, rust_log, "my_function", Level::DEBUG)); + } } #[test] fn debug_leaves_the_transport_at_info() { - assert_eq!(Builder::new(true).directives(None), TRANSPORT_AT_INFO); - EnvFilter::try_new(Builder::new(true).directives(None)).expect("valid directives"); + let builder = Builder::new(true); + assert!(enabled(&builder, None, "my_function", Level::DEBUG)); + for target in TRANSPORT_TARGETS { + let module = format!("{target}::proto"); + assert!(!enabled(&builder, None, &module, Level::DEBUG), "{target}"); + assert!(enabled(&builder, None, &module, Level::INFO), "{target}"); + } } #[test] fn quiet_targets_join_the_transport_under_debug() { let builder = Builder::new(true).quiet(["wasmtime", "cranelift_codegen"]); - assert_eq!( - builder.directives(None), - format!("{TRANSPORT_AT_INFO},wasmtime=info,cranelift_codegen=info") - ); - EnvFilter::try_new(builder.directives(None)).expect("valid directives"); - assert_eq!( - Builder::new(false).quiet(["wasmtime"]).directives(None), - "info" - ); + assert!(!enabled(&builder, None, "wasmtime::module", Level::DEBUG)); + assert!(!enabled(&builder, None, "cranelift_codegen", Level::DEBUG)); + assert!(enabled(&builder, None, "my_function", Level::DEBUG)); + let builder = Builder::new(false).quiet(["wasmtime"]); + assert!(!enabled(&builder, None, "my_function", Level::DEBUG)); } #[test] fn rust_log_replaces_the_flag_and_the_quiet_targets() { - assert_eq!( - Builder::new(true) - .quiet(["wasmtime"]) - .directives(Some("info,my_function=trace")), - "info,my_function=trace" - ); + let builder = Builder::new(true).quiet(["wasmtime"]); + let rust_log = Some("info,my_function=trace,wasmtime=debug"); + assert!(enabled(&builder, rust_log, "my_function", Level::TRACE)); + assert!(enabled(&builder, rust_log, "wasmtime", Level::DEBUG)); + assert!(!enabled(&builder, rust_log, "h2", Level::DEBUG)); + assert!(builder.filter(rust_log).1.is_none()); + } + + #[test] + fn an_unsupported_rust_log_falls_back_to_the_flag() { + let builder = Builder::new(false); + let rust_log = Some("my_function[run{tag=x}]=debug"); + let (filter, ignored) = builder.filter(rust_log); + assert!(ignored.is_some()); + assert!(filter.would_enable("my_function", &Level::INFO)); + assert!(!filter.would_enable("my_function", &Level::DEBUG)); } }