From 45c03ca37fcbb159981bcbbb890465b372e95ccf Mon Sep 17 00:00:00 2001 From: Zhengchao An Date: Wed, 26 Aug 2026 09:55:49 +0800 Subject: [PATCH] test(obs): move source-text logging tests into the logging guardrail script (#6610) test(obs): replace source-text logging tests with logging guardrail script coverage The seven fs::read_to_string source-text tests in crates/obs/src/logging.rs asserted retired logging patterns and required structured-logging fields across 13 files in other crates, four of them reverse reads into the rustfs binary crate. Their patterns are now enforced by scripts/check_logging_guardrails.sh, which runs in pre-commit and CI, covers the same files through checked_files plus require_patterns, and does not silently lapse when a governed file moves. Part of rustfs/backlog#1884. --- crates/obs/src/logging.rs | 185 ---------------------------- scripts/check_logging_guardrails.sh | 88 +++++++++++-- 2 files changed, 75 insertions(+), 198 deletions(-) diff --git a/crates/obs/src/logging.rs b/crates/obs/src/logging.rs index eca620ded..71c13d9b8 100644 --- a/crates/obs/src/logging.rs +++ b/crates/obs/src/logging.rs @@ -59,42 +59,6 @@ pub fn redacted_optional_log_value(value: Option<&str>) -> Option<&'static str> #[cfg(test)] mod tests { use super::*; - use std::fs; - use std::path::{Path, PathBuf}; - - fn workspace_root() -> PathBuf { - Path::new(env!("CARGO_MANIFEST_DIR")) - .parent() - .and_then(Path::parent) - .expect("workspace root should exist") - .to_path_buf() - } - - fn assert_no_unmasked_access_key_logging(rel_path: &str, forbidden_patterns: &[&str]) { - let path = workspace_root().join(rel_path); - let source = fs::read_to_string(&path).unwrap_or_else(|err| panic!("failed to read {}: {}", path.display(), err)); - for pattern in forbidden_patterns { - assert!( - !source.contains(pattern), - "found forbidden unmasked access_key logging pattern `{}` in {}", - pattern, - path.display() - ); - } - } - - fn assert_source_contains(rel_path: &str, required_patterns: &[&str]) { - let path = workspace_root().join(rel_path); - let source = fs::read_to_string(&path).unwrap_or_else(|err| panic!("failed to read {}: {}", path.display(), err)); - for pattern in required_patterns { - assert!( - source.contains(pattern), - "missing required logging governance pattern `{}` in {}", - pattern, - path.display() - ); - } - } #[test] fn logging_redaction_rules_are_valid() { @@ -133,153 +97,4 @@ mod tests { assert_eq!(MaskedAccessKey("AKIAIOSFODNN7EXAMPLE").to_string(), "AKIA***MPLE"); assert_eq!(format!("{:?}", MaskedAccessKey("keystone:user-1234")), "keys***1234"); } - - #[test] - fn runtime_auth_logging_does_not_use_previous_unmasked_access_key_patterns() { - assert_no_unmasked_access_key_logging( - "rustfs/src/auth.rs", - &[ - "get_secret_key failed: no such user, access_key: {access_key}", - "get_secret_key failed: check_key error, access_key: {access_key}, error: {e:?}", - "get_secret_key failed: iam not initialized, access_key: {access_key}", - "check_key_valid: user not found for access_key={}", - "check_key_valid: account disabled for access_key={}", - "check_key_valid: validation failed for access_key={}", - "check_key_valid: starting validation - access_key={}, session_token_len={}", - ], - ); - } - - #[test] - fn protocol_client_logging_does_not_use_previous_unmasked_access_key_pattern() { - assert_no_unmasked_access_key_logging( - "rustfs/src/protocols/client.rs", - &["Protocol storage client ListBuckets request: access_key={}"], - ); - } - - #[test] - fn startup_runtime_logging_does_not_dump_full_config_debug_output() { - for relative_path in ["rustfs/src/main.rs", "rustfs/src/startup_entrypoint.rs"] { - let path = workspace_root().join(relative_path); - let source = fs::read_to_string(&path).unwrap_or_else(|err| panic!("failed to read {}: {}", path.display(), err)); - assert!( - !source.contains("debug!(\"config: {:?}\", &config)"), - "found forbidden full config debug output in {}", - path.display() - ); - } - } - - #[test] - fn startup_fatal_stderr_uses_single_formatter_for_pre_observability_failures() { - assert_source_contains( - "rustfs/src/startup_entrypoint.rs", - &[ - "fn format_fatal_stderr_message(context: &str, error: impl std::fmt::Display) -> String", - "fn emit_fatal_stderr(context: &str, error: impl std::fmt::Display)", - "emit_fatal_stderr(\"Server runtime failed\", e)", - "emit_fatal_stderr(\"Command parse failed\", e)", - "emit_fatal_stderr(\"Observability initialization failed\", err)", - ], - ); - } - - #[test] - fn observability_runtime_logging_uses_tracing_for_fallback_and_guard_shutdown() { - assert_no_unmasked_access_key_logging( - "crates/obs/src/telemetry/local.rs", - &[ - "[WARN] Failed to initialize file observability logging", - "Falling back to stdout logging.", - ], - ); - assert_source_contains( - "crates/obs/src/telemetry/local.rs", - &[ - "warn!(", - "state = \"fallback_to_stdout\"", - "failed_sink = \"file\"", - "sink = \"stdout\"", - ], - ); - assert_no_unmasked_access_key_logging( - "crates/obs/src/telemetry/guard.rs", - &[ - "eprintln!(\"Tracer shutdown error: {err:?}\")", - "eprintln!(\"Meter shutdown error: {err:?}\")", - "eprintln!(\"Logger shutdown error: {err:?}\")", - "eprintln!(\"Log cleanup task stopped\")", - "eprintln!(\"Tracing guard dropped, flushing logs.\")", - "eprintln!(\"Stdout guard dropped, flushing logs.\")", - ], - ); - assert_source_contains( - "crates/obs/src/telemetry/guard.rs", - &[ - "EVENT_OBS_GUARD_SHUTDOWN", - "resource = \"tracer_provider\"", - "resource = \"meter_provider\"", - "resource = \"logger_provider\"", - "resource = \"log_cleaner\"", - "resource = \"tracing_guard\"", - "resource = \"stdout_guard\"", - ], - ); - } - - #[test] - fn low_level_logging_sink_stderr_exceptions_remain_explicit() { - assert_source_contains( - "crates/obs/src/telemetry/rolling.rs", - &[ - "Failed to flush log file before rotation", - "RollingAppender: Failed to rotate log file after", - "RollingAppender: failed to rotate log file", - ], - ); - } - - #[test] - fn audit_notify_runtime_logging_does_not_use_previous_sentence_first_noise_patterns() { - assert_no_unmasked_access_key_logging( - "crates/audit/src/pipeline.rs", - &[ - "No audit targets configured for dispatch", - "No audit targets configured for batch dispatch", - "Successfully sent audit entry, target: {}, key: {}", - "Target {} not connected, retrying...", - "Timeout sending to target {}, retrying...", - ], - ); - assert_no_unmasked_access_key_logging( - "crates/notify/src/runtime_facade.rs", - &[ - "Event stream processing for target {} is started successfully", - "Target {} has no replay worker to start", - ], - ); - assert_no_unmasked_access_key_logging( - "crates/notify/src/notifier.rs", - &[ - "Sending event to targets: {:?}", - "Event processing initiated for {} targets for bucket: {}", - ], - ); - assert_no_unmasked_access_key_logging( - "crates/notify/src/bucket_config_manager.rs", - &["Available ARNs: {:?}", "Loaded notification config for bucket: {}"], - ); - assert_no_unmasked_access_key_logging( - "crates/notify/src/rule_engine.rs", - &[ - "Updated notification rules for bucket: {}", - "Removed all notification rules for bucket: {}", - ], - ); - assert_no_unmasked_access_key_logging( - "crates/audit/src/observability.rs", - &["Audit configuration reloaded", "Audit system started", "Audit metrics reset"], - ); - } } diff --git a/scripts/check_logging_guardrails.sh b/scripts/check_logging_guardrails.sh index 02efba891..335075f39 100755 --- a/scripts/check_logging_guardrails.sh +++ b/scripts/check_logging_guardrails.sh @@ -6,6 +6,7 @@ cd "$repo_root" checked_files=( "rustfs/src/main.rs" + "rustfs/src/startup_entrypoint.rs" "rustfs/src/init.rs" "rustfs/src/profiling.rs" "rustfs/src/startup_iam.rs" @@ -113,6 +114,8 @@ checked_files=( "crates/obs/src/telemetry/dial9/config.rs" "crates/obs/src/telemetry/dial9/enabled.rs" "crates/obs/src/telemetry/local.rs" + "crates/obs/src/telemetry/guard.rs" + "crates/obs/src/telemetry/rolling.rs" "crates/obs/src/metrics/scheduler.rs" "crates/obs/src/cleaner/core.rs" "crates/obs/src/cleaner/compress.rs" @@ -144,17 +147,17 @@ forbidden_patterns=( 'debug!("http_client headers: {:?}"' 'warn!("err_body: {}"' 'debug!("config: {:?}"' - 'warn!("No audit targets configured for dispatch"' - 'warn!("No audit targets configured for batch dispatch"' - 'info!("Event stream processing for target {} is started successfully"' - 'info!("Target {} has no replay worker to start"' - 'info!("Sending event to targets: {:?}"' - 'info!("Event processing initiated for {} targets for bucket: {}"' + '"No audit targets configured for dispatch"' + '"No audit targets configured for batch dispatch"' + '"Event stream processing for target {} is started successfully"' + '"Target {} has no replay worker to start"' + '"Sending event to targets: {:?}"' + '"Event processing initiated for {} targets for bucket: {}"' 'warn!("{}", notify_configuration_hint())' - 'info!("Available ARNs: {:?}"' - 'info!("Loaded notification config for bucket: {}"' - 'info!("Updated notification rules for bucket: {}"' - 'info!("Removed all notification rules for bucket: {}"' + '"Available ARNs: {:?}"' + '"Loaded notification config for bucket: {}"' + '"Updated notification rules for bucket: {}"' + '"Removed all notification rules for bucket: {}"' 'info!(event = EVENT_NOTIFY_RUNTIME_LIFECYCLE,' 'info!("Notification system instance is being dropped"' 'info!("Notification shutdown metric snapshot"' @@ -174,9 +177,9 @@ forbidden_patterns=( 'info!(target_id = %self.id, "MQTT target close method finished.")' 'debug!("Wrote event to store: {}"' 'debug!("Deleted event from store: {}"' - 'info!("Audit configuration reloaded"' - 'info!("Audit system started"' - 'info!("Audit metrics reset"' + '"Audit configuration reloaded"' + '"Audit system started"' + '"Audit metrics reset"' 'error!("Failed to set global observability guard: {}"' 'error!("Failed to initialize TLS from {}: {}"' 'error!("Server encountered an error and is shutting down: {}"' @@ -661,6 +664,21 @@ forbidden_patterns=( 'error!("{} cache write lock poisoned: {}"' 'error!("metrics_metadata lock poisoned: {}"' 'warn!("Could not get GPU stats, recording 0 for GPU memory usage"' + # Migrated from the retired source-text tests in crates/obs/src/logging.rs + # (rustfs/backlog#1884): unmasked access-key interpolation, retired startup + # noise, and stderr prints that were converted to tracing events. + 'access_key: {access_key}' + '"Successfully sent audit entry, target: {}, key: {}"' + '"Target {} not connected, retrying..."' + '"Timeout sending to target {}, retrying..."' + '"[WARN] Failed to initialize file observability logging' + '"Falling back to stdout logging.' + 'eprintln!("Tracer shutdown error: {err:?}")' + 'eprintln!("Meter shutdown error: {err:?}")' + 'eprintln!("Logger shutdown error: {err:?}")' + 'eprintln!("Log cleanup task stopped")' + 'eprintln!("Tracing guard dropped, flushing logs.")' + 'eprintln!("Stdout guard dropped, flushing logs.")' ) for pattern in "${forbidden_patterns[@]}"; do @@ -671,6 +689,50 @@ for pattern in "${forbidden_patterns[@]}"; do fi done +# Positive structure guards migrated from the retired source-text tests in +# crates/obs/src/logging.rs (rustfs/backlog#1884). Each pattern below must keep +# existing: the single fatal-stderr formatter used before observability is up, +# the structured tracing fields that replaced eprintln! in telemetry +# fallback/shutdown paths, and the explicit stderr exceptions in the low-level +# rolling appender (which cannot log through the sink it implements). +require_patterns() { + local file="$1" + shift + for pattern in "$@"; do + if ! rg -n -F -- "$pattern" "$file" >/dev/null; then + echo "❌ logging guardrail violation: required pattern '$pattern' is missing from $file" >&2 + exit 1 + fi + done +} + +require_patterns "rustfs/src/startup_entrypoint.rs" \ + 'fn format_fatal_stderr_message(context: &str, error: impl std::fmt::Display) -> String' \ + 'fn emit_fatal_stderr(context: &str, error: impl std::fmt::Display)' \ + 'emit_fatal_stderr("Server runtime failed", e)' \ + 'emit_fatal_stderr("Command parse failed", e)' \ + 'emit_fatal_stderr("Observability initialization failed", err)' + +require_patterns "crates/obs/src/telemetry/local.rs" \ + 'warn!(' \ + 'state = "fallback_to_stdout"' \ + 'failed_sink = "file"' \ + 'sink = "stdout"' + +require_patterns "crates/obs/src/telemetry/guard.rs" \ + 'EVENT_OBS_GUARD_SHUTDOWN' \ + 'resource = "tracer_provider"' \ + 'resource = "meter_provider"' \ + 'resource = "logger_provider"' \ + 'resource = "log_cleaner"' \ + 'resource = "tracing_guard"' \ + 'resource = "stdout_guard"' + +require_patterns "crates/obs/src/telemetry/rolling.rs" \ + 'Failed to flush log file before rotation' \ + 'RollingAppender: Failed to rotate log file after' \ + 'RollingAppender: failed to rotate log file' + if rg -n -F -- 'warn!(name = %MaskedAccessKey(name), user_type = ?user_type, "IAM user identity missing")' crates/iam/src/store/object.rs >/dev/null; then echo "❌ logging guardrail violation: missing IAM identity is an expected debug event, not a warning" >&2 exit 1