diff --git a/Cargo.lock b/Cargo.lock index 71ee1b6..da4e295 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -706,6 +706,15 @@ 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" @@ -1560,12 +1569,16 @@ 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 8240015..f991b36 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"] } +tracing-subscriber = { version = "0.3", features = ["json", "env-filter"] } 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 2b1ac3a..60386df 100644 --- a/sdk/README.md +++ b/sdk/README.md @@ -16,7 +16,9 @@ API. This crate provides: context keys, required resources and schemas, credentials, capabilities, results, conditions, readiness, and desired resource updates from any `serde::Serialize` source. -- `logging` - JSON-lines logging with a human-readable debug mode. +- `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. 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 0d27cbc..ce89854 100644 --- a/sdk/src/logging.rs +++ b/sdk/src/logging.rs @@ -1,23 +1,140 @@ //! Logging setup for composition functions. -/// Configures process-wide logging. +use tracing_subscriber::EnvFilter; + +/// 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 +/// `--debug` leaves them at INFO. +const TRANSPORT_TARGETS: [&str; 6] = ["h2", "hyper", "hyper_util", "tonic", "tower", "rustls"]; + +/// Configures process-wide logging to stderr. Call once, before serving. /// -/// Logs are emitted as JSON lines at info level. With debug enabled, logs -/// are emitted in a human-readable format at debug level instead. Call once, -/// before serving. +/// 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`]. pub fn configure(debug: bool) { - if debug { - tracing_subscriber::fmt() - .with_max_level(tracing::Level::DEBUG) - .with_file(true) - .with_line_number(true) - .init(); - } else { - tracing_subscriber::fmt() - .json() - .with_max_level(tracing::Level::INFO) + Builder::new(debug).init(); +} + +/// Process-wide logging with options beyond [`configure`]. Create it with +/// [`Builder::new`], chain the options, then call [`Builder::init`]. New +/// options arrive as new methods, so code that builds logging keeps +/// compiling. +/// +/// ```no_run +/// function_sdk_rust::logging::Builder::new(true) +/// .quiet(["wasmtime", "cranelift_codegen"]) +/// .init(); +/// ``` +#[derive(Debug)] +pub struct Builder { + debug: bool, + quiet: Vec, +} + +impl Builder { + /// Starts from [`configure`]'s defaults for the given `--debug` flag. + pub fn new(debug: bool) -> Self { + Self { + debug, + quiet: Vec::new(), + } + } + + /// Keeps these tracing targets (usually crate names, such as + /// `wasmtime`) at INFO under debug, like the gRPC transport stack the + /// SDK already holds back. A `RUST_LOG` that is set replaces the level + /// selection, quiet targets included. + pub fn quiet(mut self, targets: I) -> Self + where + I: IntoIterator, + S: Into, + { + self.quiet.extend(targets.into_iter().map(Into::into)); + self + } + + /// Installs the global subscriber, writing to stderr. Call once, + /// 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 builder = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(std::io::stderr) .with_file(true) - .with_line_number(true) - .init(); + .with_line_number(true); + if self.debug { + builder.init(); + } else { + builder.json().init(); + } + } + + /// 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(); + } + if !self.debug { + return "info".to_string(); + } + let mut directives = String::from("debug"); + for target in TRANSPORT_TARGETS + .iter() + .copied() + .chain(self.quiet.iter().map(String::as_str)) + { + directives.push_str(&format!(",{target}=info")); + } + directives + } +} + +#[cfg(test)] +mod tests { + use super::*; + + const TRANSPORT_AT_INFO: &str = + "debug,h2=info,hyper=info,hyper_util=info,tonic=info,tower=info,rustls=info"; + + #[test] + fn info_by_default() { + assert_eq!(Builder::new(false).directives(None), "info"); + assert_eq!(Builder::new(false).directives(Some(" ")), "info"); + } + + #[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"); + } + + #[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" + ); + } + + #[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" + ); } } diff --git a/sdk/src/response.rs b/sdk/src/response.rs index 4a955ed..f0e1efc 100644 --- a/sdk/src/response.rs +++ b/sdk/src/response.rs @@ -59,8 +59,10 @@ pub fn warning(rsp: &mut RunFunctionResponse, message: impl Into) -> &mu /// Adds a fatal result to the response. /// -/// The pipeline run is considered a failure and the first fatal result is -/// returned as an error, but subsequent pipeline steps may still run. +/// Crossplane stops the pipeline at the first fatal result: later steps do +/// not run, and for that reconcile Crossplane applies no desired state and +/// garbage-collects nothing. The reconcile error carries the message: +/// `pipeline step "" returned a fatal result: `. pub fn fatal(rsp: &mut RunFunctionResponse, message: impl Into) -> &mut FnResult { add_result(rsp, Severity::Fatal, message) }