fix(logging): bound hot-path span amplification (#5763)

* fix(logging): bound hot-path span amplification

* refactor(logging): reuse HTTP log target constant

Co-Authored-By: heihutu <heihutu@gmail.com>

---------

Co-authored-by: Anthony Martin <949506+anthonymartin@users.noreply.github.com>
Co-authored-by: houseme <housemecn@gmail.com>
Co-authored-by: heihutu <heihutu@gmail.com>

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<ObjectInfoOrErr>;
 
-    #[tracing::instrument(skip(self))]
+    #[tracing::instrument(level = "trace", skip(self))]
     async fn list_objects_v2(
         self: Arc<Self>,
         bucket: &str,

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<ObjectInfoOrErr>;
 
-    #[tracing::instrument(skip(self))]
+    #[tracing::instrument(level = "trace", skip(self))]
     async fn list_objects_v2(
         self: Arc<Self>,
         bucket: &str,

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<NamespaceLockWrapper> {
         // Resolved from this set's own instance context (backlog#1052), not the
         // ambient facade: the facade tracks whichever context is currently

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<ObjectInfo> {
         crate::hp_guard!("SetDisks::get_object_info");
         // Acquire a shared read-lock to protect consistency during info fetch

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<Self>,

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<Self>,
         bucket: &str,

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<ObjectInfo> {
         check_object_args(bucket, object)?;
 

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<NamespaceLockWrapper> {
         self.pools[0].new_ns_lock(bucket, object).await
     }

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

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
+/// For non-verbose levels (`info`, `warn`, `error`), noisy dependency targets
-/// (`hyper`, `tonic`, `h2`, `reqwest`, `tower`) are automatically silenced
+/// are automatically suppressed based on the effective log configuration.
-/// 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<Mutex<Vec<u8>>>);
+
+    struct SharedWriterGuard(Arc<Mutex<Vec<u8>>>);
+
+    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<usize> {
+            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(&http_log_directive("error"))));
-        assert!(!should_demote_http_request_logs("info", None, Some("WARN,rustfs::server::http=error")));
+        assert!(!should_demote_http_request_logs(
-        assert!(should_demote_http_request_logs("error", None, Some("WARN,rustfs::server::http=warn")));
+            "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}");
+        });
+    }
 }

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;

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<ListObjectsV2Input>) -> S3Result<S3Response<ListObjectsV2Output>> {
         // warn!("list_objects_v2 req {:?}", &req.input);
         let ListObjectsV2Input {

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,

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