diff --git a/crates/ecstore/src/core/sets.rs b/crates/ecstore/src/core/sets.rs index 8bbcc474e..1a74bd7f9 100644 --- a/crates/ecstore/src/core/sets.rs +++ b/crates/ecstore/src/core/sets.rs @@ -749,7 +749,7 @@ impl crate::storage_api_contracts::list::ListOperations for Sets { type WalkCancellation = CancellationToken; type WalkResultSender = tokio::sync::mpsc::Sender; - #[tracing::instrument(skip(self))] + #[tracing::instrument(level = "trace", skip(self))] async fn list_objects_v2( self: Arc, bucket: &str, diff --git a/crates/ecstore/src/set_disk/ops/list.rs b/crates/ecstore/src/set_disk/ops/list.rs index 85eaaa188..d6786ddd5 100644 --- a/crates/ecstore/src/set_disk/ops/list.rs +++ b/crates/ecstore/src/set_disk/ops/list.rs @@ -134,7 +134,7 @@ impl crate::storage_api_contracts::list::ListOperations for SetDisks { type WalkCancellation = CancellationToken; type WalkResultSender = Sender; - #[tracing::instrument(skip(self))] + #[tracing::instrument(level = "trace", skip(self))] async fn list_objects_v2( self: Arc, bucket: &str, diff --git a/crates/ecstore/src/set_disk/ops/locking.rs b/crates/ecstore/src/set_disk/ops/locking.rs index 7b120723a..bfead3a53 100644 --- a/crates/ecstore/src/set_disk/ops/locking.rs +++ b/crates/ecstore/src/set_disk/ops/locking.rs @@ -28,7 +28,7 @@ impl crate::storage_api_contracts::namespace::NamespaceLocking for SetDisks { type Error = Error; type NamespaceLock = NamespaceLockWrapper; - #[tracing::instrument(skip(self))] + #[tracing::instrument(level = "trace", skip(self))] async fn new_ns_lock(&self, bucket: &str, object: &str) -> Result { // Resolved from this set's own instance context (backlog#1052), not the // ambient facade: the facade tracks whichever context is currently diff --git a/crates/ecstore/src/set_disk/ops/object.rs b/crates/ecstore/src/set_disk/ops/object.rs index de44edcd0..cd669a875 100644 --- a/crates/ecstore/src/set_disk/ops/object.rs +++ b/crates/ecstore/src/set_disk/ops/object.rs @@ -4343,7 +4343,7 @@ impl crate::storage_api_contracts::object::ObjectOperations for SetDisks { Ok(obj_info) } - #[tracing::instrument(skip(self))] + #[tracing::instrument(level = "trace", skip(self))] async fn get_object_info(&self, bucket: &str, object: &str, opts: &ObjectOptions) -> Result { crate::hp_guard!("SetDisks::get_object_info"); // Acquire a shared read-lock to protect consistency during info fetch diff --git a/crates/ecstore/src/store/list.rs b/crates/ecstore/src/store/list.rs index 2651797c6..5f7f480b5 100644 --- a/crates/ecstore/src/store/list.rs +++ b/crates/ecstore/src/store/list.rs @@ -15,7 +15,7 @@ use super::*; impl ECStore { - #[instrument(skip(self))] + #[instrument(level = "trace", skip(self))] #[allow(clippy::too_many_arguments)] pub(super) async fn handle_list_objects_v2( self: Arc, diff --git a/crates/ecstore/src/store/mod.rs b/crates/ecstore/src/store/mod.rs index 120a6ae0c..cf2bc4c74 100644 --- a/crates/ecstore/src/store/mod.rs +++ b/crates/ecstore/src/store/mod.rs @@ -582,7 +582,7 @@ impl crate::storage_api_contracts::list::ListOperations for ECStore { // @start_after as marker when continuation_token empty // @delimiter default="/", empty when recursive // @max_keys limit - #[instrument(skip(self))] + #[instrument(level = "trace", skip(self))] async fn list_objects_v2( self: Arc, bucket: &str, diff --git a/crates/ecstore/src/store/object.rs b/crates/ecstore/src/store/object.rs index 78f6ead15..58b37de22 100644 --- a/crates/ecstore/src/store/object.rs +++ b/crates/ecstore/src/store/object.rs @@ -1253,7 +1253,7 @@ impl ECStore { .await } - #[instrument(skip(self))] + #[instrument(level = "trace", skip(self))] pub(super) async fn handle_get_object_info(&self, bucket: &str, object: &str, opts: &ObjectOptions) -> Result { check_object_args(bucket, object)?; diff --git a/crates/ecstore/src/store/rebalance.rs b/crates/ecstore/src/store/rebalance.rs index 334b87d85..e4ca6fd24 100644 --- a/crates/ecstore/src/store/rebalance.rs +++ b/crates/ecstore/src/store/rebalance.rs @@ -661,7 +661,7 @@ impl ECStore { unique_disks.into_values().collect() } - #[instrument(skip(self))] + #[instrument(level = "trace", skip(self))] pub(super) async fn handle_new_ns_lock(&self, bucket: &str, object: &str) -> Result { self.pools[0].new_ns_lock(bucket, object).await } diff --git a/crates/obs/src/lib.rs b/crates/obs/src/lib.rs index 55b079e6b..43ca252ee 100644 --- a/crates/obs/src/lib.rs +++ b/crates/obs/src/lib.rs @@ -79,7 +79,7 @@ pub use metrics::{ MetricsRuntimeShutdownHandle, MetricsRuntimeStatusSnapshot, MetricsRuntimeWorkerMutation, init_metrics_runtime, metrics_runtime_controller_snapshot, metrics_runtime_status_snapshot, }; -pub use telemetry::{OtelGuard, Recorder}; +pub use telemetry::{HTTP_SERVER_LOG_TARGET, OtelGuard, Recorder}; // Dial9 Tokio runtime telemetry // Re-export dial9 types at crate root level for easier access diff --git a/crates/obs/src/telemetry/filter.rs b/crates/obs/src/telemetry/filter.rs index 9ef639eb0..1237ca502 100644 --- a/crates/obs/src/telemetry/filter.rs +++ b/crates/obs/src/telemetry/filter.rs @@ -24,6 +24,8 @@ use tracing_subscriber::{ filter::{FilterFn, LevelFilter, filter_fn}, }; +pub const HTTP_SERVER_LOG_TARGET: &str = "rustfs::server::http"; + /// Pyroscope emits raw reqwest errors from its background session manager. /// Those errors can include the configured endpoint, so they must never reach /// a RustFS logging sink even when an operator enables verbose dependency logs. @@ -43,9 +45,9 @@ pub(super) fn pyroscope_log_filter() -> FilterFn { /// /// If `default_level` is provided, it is used directly. Otherwise, the /// `RUST_LOG` environment variable takes precedence over `logger_level`. -/// For non-verbose levels (`info`, `warn`, `error`), noisy internal crates -/// (`hyper`, `tonic`, `h2`, `reqwest`, `tower`) are automatically silenced -/// based on the effective log configuration. +/// For non-verbose levels (`info`, `warn`, `error`), noisy dependency targets +/// are automatically suppressed based on the effective log configuration. +/// Transport internals are disabled, while `s3s` remains visible at WARN. /// /// # Arguments /// * `logger_level` - The desired log level string (e.g., `"info"`, `"debug"`). @@ -157,7 +159,26 @@ fn should_demote_http_request_logs(logger_level: &str, default_level: Option<&st } if let Some(rust_log) = rust_log { - if let Some(level) = effective_level_for_target(rust_log, "rustfs::server::http") { + if let Some(level) = effective_level_for_target(rust_log, HTTP_SERVER_LOG_TARGET) { + let level = level.trim().to_ascii_lowercase(); + return matches!(level.as_str(), "info" | "warn"); + } + + return false; + } + + let level = logger_level.trim().to_ascii_lowercase(); + matches!(level.as_str(), "info" | "warn") +} + +fn should_demote_s3s_logs(logger_level: &str, default_level: Option<&str>, rust_log: Option<&str>) -> bool { + if let Some(level) = default_level { + let level = level.trim().to_ascii_lowercase(); + return matches!(level.as_str(), "info" | "warn"); + } + + if let Some(rust_log) = rust_log { + if let Some(level) = effective_level_for_target(rust_log, "s3s") { let level = level.trim().to_ascii_lowercase(); return matches!(level.as_str(), "info" | "warn"); } @@ -214,7 +235,14 @@ pub(super) fn build_env_filter(logger_level: &str, default_level: Option<&str>) if should_demote_http_request_logs(logger_level, default_level, rust_log_env.as_deref()) { // HTTP request logs are demoted to WARN to reduce volume in production, // but only when the effective log level is not stricter than WARN. - directives.push(("rustfs::server::http", LevelFilter::WARN)); + directives.push((HTTP_SERVER_LOG_TARGET, LevelFilter::WARN)); + } + + if should_demote_s3s_logs(logger_level, default_level, rust_log_env.as_deref()) { + // s3s instruments each authentication request through multiple + // nested INFO spans. Keep warnings and errors in normal production + // logs without promoting it when the effective base is stricter. + directives.push(("s3s", LevelFilter::WARN)); } for (crate_name, level) in directives { @@ -250,6 +278,54 @@ pub(super) fn build_env_filter(logger_level: &str, default_level: Option<&str>) #[cfg(test)] mod tests { use super::*; + use std::{ + io::{self, Write}, + sync::{Arc, Mutex}, + }; + use tracing::subscriber::with_default; + + #[derive(Clone, Default)] + struct SharedWriter(Arc>>); + + struct SharedWriterGuard(Arc>>); + + impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for SharedWriter { + type Writer = SharedWriterGuard; + + fn make_writer(&'a self) -> Self::Writer { + SharedWriterGuard(Arc::clone(&self.0)) + } + } + + impl Write for SharedWriterGuard { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.0.lock().expect("log buffer").extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + fn capture_with_filter(filter: EnvFilter, emit: impl FnOnce()) -> String { + let writer = SharedWriter::default(); + let captured = Arc::clone(&writer.0); + let subscriber = tracing_subscriber::fmt() + .without_time() + .with_ansi(false) + .with_env_filter(filter) + .with_writer(writer) + .finish(); + + with_default(subscriber, emit); + let bytes = captured.lock().expect("captured logs").clone(); + String::from_utf8(bytes).expect("utf8 logs") + } + + fn http_log_directive(level: &str) -> String { + format!("{HTTP_SERVER_LOG_TARGET}={level}") + } #[test] fn test_is_verbose_level() { @@ -302,9 +378,30 @@ mod tests { assert!(!should_demote_http_request_logs("info", None, Some("foo=warn"))); assert!(!should_demote_http_request_logs("info", None, Some("rustfs=error"))); assert!(!should_demote_http_request_logs("info", None, Some("rustfs::server=error"))); - assert!(!should_demote_http_request_logs("info", None, Some("rustfs::server::http=error"))); - assert!(!should_demote_http_request_logs("info", None, Some("WARN,rustfs::server::http=error"))); - assert!(should_demote_http_request_logs("error", None, Some("WARN,rustfs::server::http=warn"))); + assert!(!should_demote_http_request_logs("info", None, Some(&http_log_directive("error")))); + assert!(!should_demote_http_request_logs( + "info", + None, + Some(&format!("WARN,{}", http_log_directive("error"))) + )); + assert!(should_demote_http_request_logs( + "error", + None, + Some(&format!("WARN,{}", http_log_directive("warn"))) + )); + } + + #[test] + fn test_should_demote_s3s_logs() { + assert!(should_demote_s3s_logs("info", None, None)); + assert!(should_demote_s3s_logs("warn", None, None)); + assert!(!should_demote_s3s_logs("error", None, None)); + assert!(!should_demote_s3s_logs("off", None, None)); + assert!(!should_demote_s3s_logs("info", None, Some("ERROR"))); + assert!(should_demote_s3s_logs("error", None, Some("WARN"))); + assert!(!should_demote_s3s_logs("info", None, Some("foo=warn"))); + assert!(!should_demote_s3s_logs("info", None, Some("s3s=error"))); + assert!(should_demote_s3s_logs("error", None, Some("WARN,s3s=warn"))); } #[test] @@ -315,7 +412,7 @@ mod tests { let filter = build_env_filter("info", None); let filter_str = filter.to_string(); - for noisy_crate in ["hyper", "tonic", "h2", "reqwest", "tower"] { + for noisy_crate in ["hyper", "tonic", "h2", "reqwest", "tower", "s3s"] { assert!( filter_str.contains(noisy_crate), "expected EnvFilter to contain suppression directive for `{}`; got `{}`", @@ -385,7 +482,7 @@ mod tests { let filter_str = filter.to_string().to_ascii_lowercase(); assert!( - !filter_str.contains("rustfs::server::http=warn"), + !filter_str.contains(&http_log_directive("warn")), "http logs must not be promoted above error level when RUST_LOG=ERROR overrides logger_level=info: {filter_str}" ); }); @@ -395,12 +492,25 @@ mod tests { let filter_str = filter.to_string().to_ascii_lowercase(); assert!( - !filter_str.contains("rustfs::server::http=warn"), + !filter_str.contains(&http_log_directive("warn")), "http logs must not be promoted above error level when RUST_LOG=rustfs=error overrides logger_level=info: {filter_str}" ); }); } + #[test] + fn test_build_env_filter_does_not_promote_s3s_above_error() { + temp_env::with_var("RUST_LOG", Some("ERROR"), || { + let filter = build_env_filter("info", None).to_string().to_ascii_lowercase(); + assert!(!filter.contains("s3s=warn"), "s3s must not be promoted above ERROR: {filter}"); + }); + + temp_env::with_var("RUST_LOG", Some("foo=warn"), || { + let filter = build_env_filter("info", None).to_string().to_ascii_lowercase(); + assert!(!filter.contains("s3s=warn"), "an unrelated target must not enable s3s: {filter}"); + }); + } + #[test] fn test_build_env_filter_does_not_fallback_to_logger_level_for_http_demotion() { temp_env::with_var("RUST_LOG", Some("foo=warn"), || { @@ -408,7 +518,7 @@ mod tests { let filter_str = filter.to_string().to_ascii_lowercase(); assert!( - !filter_str.contains("rustfs::server::http=warn"), + !filter_str.contains(&http_log_directive("warn")), "http log demotion must not fall back to logger_level when RUST_LOG only defines unrelated targets: {filter_str}" ); }); @@ -426,4 +536,41 @@ mod tests { ); }); } + + #[test] + fn test_production_filter_suppresses_s3s_info_but_keeps_warn() { + temp_env::with_var("RUST_LOG", None::<&str>, || { + let output = capture_with_filter(build_env_filter("info", None), || { + tracing::info!(target: "s3s::auth", "s3s info must be suppressed"); + tracing::warn!(target: "s3s::auth", "s3s warning must remain"); + }); + + assert!(!output.contains("s3s info must be suppressed"), "{output}"); + assert!(output.contains("s3s warning must remain"), "{output}"); + }); + } + + #[test] + fn test_explicit_s3s_target_restores_info_diagnostics() { + temp_env::with_var("RUST_LOG", Some("info,s3s=info"), || { + let output = capture_with_filter(build_env_filter("info", None), || { + tracing::info!(target: "s3s::auth", "explicit s3s info"); + }); + + assert!(output.contains("explicit s3s info"), "{output}"); + }); + } + + #[test] + fn test_http_target_suppresses_success_but_keeps_errors() { + temp_env::with_var("RUST_LOG", None::<&str>, || { + let output = capture_with_filter(build_env_filter("info", None), || { + tracing::info!(target: HTTP_SERVER_LOG_TARGET, "healthy readiness response"); + tracing::error!(target: HTTP_SERVER_LOG_TARGET, "failed readiness response"); + }); + + assert!(!output.contains("healthy readiness response"), "{output}"); + assert!(output.contains("failed readiness response"), "{output}"); + }); + } } diff --git a/crates/obs/src/telemetry/mod.rs b/crates/obs/src/telemetry/mod.rs index cc5414a9f..051c52324 100644 --- a/crates/obs/src/telemetry/mod.rs +++ b/crates/obs/src/telemetry/mod.rs @@ -51,6 +51,7 @@ mod rolling; use crate::TelemetryError; use crate::config::OtelConfig; +pub use filter::HTTP_SERVER_LOG_TARGET; pub use guard::OtelGuard; pub use recorder::{Recorder, retire_metric_series}; use rustfs_config::observability::ENV_OBS_LOG_DIRECTORY; diff --git a/rustfs/src/app/bucket_usecase.rs b/rustfs/src/app/bucket_usecase.rs index 8ae420f8e..ee160a7f4 100644 --- a/rustfs/src/app/bucket_usecase.rs +++ b/rustfs/src/app/bucket_usecase.rs @@ -2550,7 +2550,7 @@ impl DefaultBucketUsecase { Ok(S3Response::new(PutBucketVersioningOutput {})) } - #[instrument(level = "info", skip(self, req))] + #[instrument(level = "trace", skip(self, req))] pub async fn execute_list_objects_v2(&self, req: S3Request) -> S3Result> { // warn!("list_objects_v2 req {:?}", &req.input); let ListObjectsV2Input { diff --git a/rustfs/src/server/layer.rs b/rustfs/src/server/layer.rs index 9d02b0e39..fcd2c8923 100644 --- a/rustfs/src/server/layer.rs +++ b/rustfs/src/server/layer.rs @@ -35,6 +35,7 @@ use http_body_util::{BodyExt, Full}; use hyper::body::Incoming; use pin_project_lite::pin_project; use quick_xml::events::Event; +use rustfs_obs::HTTP_SERVER_LOG_TARGET; #[cfg(feature = "swift")] use rustfs_protocols::swift::SwiftRouter; use rustfs_trusted_proxies::ClientInfo; @@ -391,6 +392,7 @@ impl RequestLogContext { if status.is_server_error() { error!( + target: HTTP_SERVER_LOG_TARGET, event = HTTP_REQUEST_COMPLETED_EVENT, component = LOG_COMPONENT_SERVER, subsystem = LOG_SUBSYSTEM_HTTP, @@ -407,6 +409,7 @@ impl RequestLogContext { ); } else { info!( + target: HTTP_SERVER_LOG_TARGET, event = HTTP_REQUEST_COMPLETED_EVENT, component = LOG_COMPONENT_SERVER, subsystem = LOG_SUBSYSTEM_HTTP, @@ -429,6 +432,7 @@ impl RequestLogContext { E: std::fmt::Display, { error!( + target: HTTP_SERVER_LOG_TARGET, event = HTTP_REQUEST_FAILED_EVENT, component = LOG_COMPONENT_SERVER, subsystem = LOG_SUBSYSTEM_HTTP, diff --git a/scripts/check_logging_guardrails.sh b/scripts/check_logging_guardrails.sh index fac8bf0bd..9c2f5cab2 100755 --- a/scripts/check_logging_guardrails.sh +++ b/scripts/check_logging_guardrails.sh @@ -875,6 +875,43 @@ if [[ "$erasure_sampled_sites" -lt 2 ]]; then exit 1 fi +# Object-read request fan-out crosses several thin wrappers. These spans are +# useful for opt-in latency attribution, but default INFO turns one S3 request +# into many redundant span-close records. Keep only the measured hot wrappers +# TRACE-only; write, heal, rebalance, and admin operations are intentionally not +# included here. +trace_hot_spans=( + "crates/ecstore/src/set_disk/ops/locking.rs:new_ns_lock" + "crates/ecstore/src/store/rebalance.rs:handle_new_ns_lock" + "crates/ecstore/src/store/object.rs:handle_get_object_info" + "crates/ecstore/src/set_disk/ops/object.rs:get_object_info" + "crates/ecstore/src/store/mod.rs:list_objects_v2" + "crates/ecstore/src/store/list.rs:handle_list_objects_v2" + "crates/ecstore/src/core/sets.rs:list_objects_v2" + "crates/ecstore/src/set_disk/ops/list.rs:list_objects_v2" + "rustfs/src/app/bucket_usecase.rs:execute_list_objects_v2" +) + +for hot_span in "${trace_hot_spans[@]}"; do + file="${hot_span%%:*}" + function="${hot_span##*:}" + trace_span_pattern="#\\[(tracing::)?instrument\\([^]]*level = \\\"trace\\\"[^]]*\\)\\]([[:space:]]+#\\[[^]]+\\])*[[:space:]]+(pub(\\([^)]*\\))?[[:space:]]+)?(super[[:space:]]+)?async fn ${function}\\b" + if ! rg -U "$trace_span_pattern" "$file" >/dev/null; then + echo "❌ logging guardrail violation: $file::$function must remain TRACE-only" >&2 + exit 1 + fi +done + +if ! rg -U 'info!\([[:space:]]+target: HTTP_SERVER_LOG_TARGET,[[:space:]]+event = HTTP_REQUEST_COMPLETED_EVENT' rustfs/src/server/layer.rs >/dev/null; then + echo "❌ logging guardrail violation: successful HTTP completion events must use HTTP_SERVER_LOG_TARGET" >&2 + exit 1 +fi + +if rg -n -F 'target: "rustfs::server::http"' rustfs/src/server/layer.rs >/dev/null; then + echo "❌ logging guardrail violation: HTTP request log target must use HTTP_SERVER_LOG_TARGET" >&2 + exit 1 +fi + demoted_admission_sites="$(rg -c -F 'demote_to_debug_when!(' crates/heal/src/heal/manager.rs || echo 0)" if [[ "$demoted_admission_sites" -lt 6 ]]; then echo "❌ logging guardrail violation: heal queue admission/scheduler warns for per-object requests must stay level-split via demote_to_debug_when! (expected >= 6 sites in crates/heal/src/heal/manager.rs, found $demoted_admission_sites)" >&2