From f6137f9f7720f1ec1dba5ea6d349b004a38da2a8 Mon Sep 17 00:00:00 2001 From: houseme Date: Thu, 11 Jun 2026 18:08:41 +0800 Subject: [PATCH] refactor(auth): tighten startup log redaction (#3358) --- rustfs/src/auth.rs | 141 ++++++++++++++++++----- rustfs/src/license.rs | 41 ++++++- rustfs/src/main.rs | 202 ++++++++++++++++++++++++--------- rustfs/src/protocols/client.rs | 128 +++++++++++++++++---- rustfs/src/startup_iam.rs | 29 ++++- 5 files changed, 430 insertions(+), 111 deletions(-) diff --git a/rustfs/src/auth.rs b/rustfs/src/auth.rs index 249365b98..c0a1317bd 100644 --- a/rustfs/src/auth.rs +++ b/rustfs/src/auth.rs @@ -36,7 +36,18 @@ use std::net::SocketAddr; use subtle::ConstantTimeEq; use time::OffsetDateTime; use time::format_description::well_known::Rfc3339; -use tracing::{debug, warn}; +use tracing::{debug, trace, warn}; + +const LOG_COMPONENT_AUTH: &str = "auth"; +const LOG_SUBSYSTEM_CREDENTIALS: &str = "credentials"; +const LOG_SUBSYSTEM_KEYSTONE: &str = "keystone"; +const LOG_SUBSYSTEM_REQUEST: &str = "request"; +const EVENT_SECRET_KEY_LOOKUP_FAILED: &str = "secret_key_lookup_failed"; +const EVENT_ACCESS_KEY_VALIDATION_STARTED: &str = "access_key_validation_started"; +const EVENT_KEYSTONE_CREDENTIALS_DETECTED: &str = "keystone_credentials_detected"; +const EVENT_KEYSTONE_CREDENTIALS_VALIDATED: &str = "keystone_credentials_validated"; +const EVENT_KEYSTONE_CONTEXT_MISSING: &str = "keystone_context_missing"; +const EVENT_SESSION_TOKEN_EXTRACTION: &str = "session_token_extraction"; /// Performs constant-time string comparison to prevent timing attacks. /// @@ -134,7 +145,14 @@ impl S3Auth for IAMAuth { use rustfs_keystone::KEYSTONE_CREDENTIALS; if let Ok(Some(creds)) = KEYSTONE_CREDENTIALS.try_with(|c| c.clone()) { - debug!("IAMAuth: Keystone credentials found in task-local storage for user {}", creds.parent_user); + debug!( + event = EVENT_KEYSTONE_CREDENTIALS_DETECTED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + principal = %MaskedAccessKey(&creds.parent_user), + result = "token_auth", + "Keystone credentials found in task-local storage" + ); // Return empty secret key - Keystone uses token validation, not AWS signatures return Ok(SecretKey::from(String::new())); } @@ -147,8 +165,12 @@ impl S3Auth for IAMAuth { // Keystone credentials use token authentication, not signature verification if access_key.starts_with("keystone:") { debug!( - "IAMAuth: Keystone access key detected ({}), returning empty secret for token-based auth", - access_key + event = EVENT_KEYSTONE_CREDENTIALS_DETECTED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + access_key = %MaskedAccessKey(access_key), + result = "token_auth", + "Keystone access key detected for token-based auth" ); // Return empty secret key - Keystone uses token validation, not AWS signatures // The actual credentials are stored in task-local storage by KeystoneAuthMiddleware @@ -174,15 +196,37 @@ impl S3Auth for IAMAuth { return Ok(SecretKey::from(id.credentials.secret_key)); } Ok((None, _)) => { - warn!(access_key = %MaskedAccessKey(access_key), "get_secret_key failed: no such user"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + reason = "no_such_user", + "Secret key lookup failed" + ); } Err(e) => { - warn!(access_key = %MaskedAccessKey(access_key), error = ?e, "get_secret_key failed: check_key error"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + error = ?e, + reason = "check_key_error", + "Secret key lookup failed" + ); return Err(iam_lookup_error_to_s3_error(&e)); } } } else { - warn!(access_key = %MaskedAccessKey(access_key), "get_secret_key failed: iam not initialized"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + reason = "iam_not_initialized", + "Secret key lookup failed" + ); } Err(s3_error!( @@ -208,26 +252,38 @@ pub async fn check_key_valid(session_token: &str, access_key: &str) -> S3Result< // Try to get Keystone credentials from task-local storage first // Add debug logging for UI authentication tracking debug!( + event = EVENT_ACCESS_KEY_VALIDATION_STARTED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, access_key = %MaskedAccessKey(access_key), - session_token_len = session_token.len(), - "check_key_valid: starting validation" + has_session_token = !session_token.is_empty(), + "Starting access key validation" ); if let Ok(Some(credentials)) = KEYSTONE_CREDENTIALS.try_with(|creds| creds.clone()) { - debug!("check_key_valid: Keystone credentials found in task-local storage"); + debug!( + event = EVENT_KEYSTONE_CREDENTIALS_DETECTED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + result = "task_local", + "Keystone credentials found in task-local storage" + ); if !auth_keystone::is_keystone_enabled() { return Err(s3_error!(InvalidAccessKeyId, "Keystone authentication is not enabled")); } - tracing::info!( - "check_key_valid: Retrieved Keystone credentials for user: {} (project: {})", - credentials.parent_user, - credentials + debug!( + event = EVENT_KEYSTONE_CREDENTIALS_VALIDATED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + principal = %MaskedAccessKey(&credentials.parent_user), + has_project_name = credentials .claims .as_ref() .and_then(|c| c.get("keystone_project_name")) .and_then(|v| v.as_str()) - .unwrap_or("unknown") + .is_some(), + "Validated Keystone credentials from task-local storage" ); // Determine if user is admin (owner-level access) @@ -246,8 +302,12 @@ pub async fn check_key_valid(session_token: &str, access_key: &str) -> S3Result< .unwrap_or(false); debug!( - "check_key_valid: Keystone user {} has owner permissions: {}", - credentials.parent_user, is_owner + event = EVENT_KEYSTONE_CREDENTIALS_VALIDATED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + principal = %MaskedAccessKey(&credentials.parent_user), + is_owner, + "Evaluated Keystone owner permissions" ); return Ok((credentials, is_owner)); @@ -256,8 +316,11 @@ pub async fn check_key_valid(session_token: &str, access_key: &str) -> S3Result< // Legacy check for explicit "keystone:" prefix (for backwards compatibility) if access_key.starts_with("keystone:") { warn!( - "check_key_valid: Keystone access key detected but no credentials in task-local storage. \ - This indicates middleware was bypassed or not configured." + event = EVENT_KEYSTONE_CONTEXT_MISSING, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_KEYSTONE, + access_key = %MaskedAccessKey(access_key), + "Keystone access key detected without task-local credentials" ); if !auth_keystone::is_keystone_enabled() { @@ -291,16 +354,37 @@ pub async fn check_key_valid(session_token: &str, access_key: &str) -> S3Result< if !ok { let Some(ref u) = u else { - warn!(access_key = %MaskedAccessKey(access_key), "check_key_valid: user not found"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + reason = "user_not_found", + "Access key validation failed" + ); return Err(s3_error!(InvalidAccessKeyId, "check key failed")); }; if u.credentials.status == "off" { - warn!(access_key = %MaskedAccessKey(access_key), "check_key_valid: account disabled"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + reason = "account_disabled", + "Access key validation failed" + ); return Err(s3_error!(InvalidRequest, "ErrAccessKeyDisabled")); } - warn!(access_key = %MaskedAccessKey(access_key), "check_key_valid: validation failed"); + warn!( + event = EVENT_SECRET_KEY_LOOKUP_FAILED, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_CREDENTIALS, + access_key = %MaskedAccessKey(access_key), + reason = "validation_failed", + "Access key validation failed" + ); return Err(s3_error!(InvalidRequest, "check key failed")); } @@ -414,12 +498,13 @@ pub fn get_session_token<'a>(uri: &'a Uri, hds: &'a HeaderMap) -> Option<&'a str .map(|v| v.to_str().unwrap_or_default()) .or_else(|| get_query_param(uri.query().unwrap_or_default(), "x-amz-security-token")); - // Add debug logging to track session token extraction - if token.is_some() { - debug!("get_session_token: session token found in request (header or query param)"); - } else { - debug!("get_session_token: no session token found in request headers or query params"); - } + trace!( + event = EVENT_SESSION_TOKEN_EXTRACTION, + component = LOG_COMPONENT_AUTH, + subsystem = LOG_SUBSYSTEM_REQUEST, + has_session_token = token.is_some(), + "Completed session token extraction" + ); token } diff --git a/rustfs/src/license.rs b/rustfs/src/license.rs index e64868dcb..5163e58bf 100644 --- a/rustfs/src/license.rs +++ b/rustfs/src/license.rs @@ -19,7 +19,11 @@ use std::sync::Arc; use std::sync::OnceLock; use std::sync::RwLock; use std::time::{SystemTime, UNIX_EPOCH}; -use tracing::{error, info, warn}; +use tracing::{error, warn}; + +const LOG_COMPONENT_LICENSE: &str = "license"; +const LOG_SUBSYSTEM_RUNTIME: &str = "runtime"; +const EVENT_LICENSE_INITIALIZATION_FAILED: &str = "license_initialization_failed"; pub type LicenseResult = std::result::Result; pub type SharedLicenseVerifier = Arc; @@ -217,7 +221,36 @@ pub fn set_license_verifier(verifier: SharedLicenseVerifier) -> bool { /// This keeps the default API signature stable and is safe to call multiple times. pub fn initialize_license(raw_license: Option) { if let Err(err) = initialize_license_result(raw_license) { - error!("license initialization failed: {err}"); + match err { + LicenseError::Missing | LicenseError::Invalid(_) => { + warn!( + event = EVENT_LICENSE_INITIALIZATION_FAILED, + component = LOG_COMPONENT_LICENSE, + subsystem = LOG_SUBSYSTEM_RUNTIME, + error = %err, + "License initialization failed" + ); + } + #[cfg(feature = "license")] + LicenseError::Expired { .. } => { + warn!( + event = EVENT_LICENSE_INITIALIZATION_FAILED, + component = LOG_COMPONENT_LICENSE, + subsystem = LOG_SUBSYSTEM_RUNTIME, + error = %err, + "License initialization failed" + ); + } + LicenseError::StatePoisoned | LicenseError::Clock(_) => { + error!( + event = EVENT_LICENSE_INITIALIZATION_FAILED, + component = LOG_COMPONENT_LICENSE, + subsystem = LOG_SUBSYSTEM_RUNTIME, + error = %err, + "License initialization failed" + ); + } + } } } @@ -231,13 +264,11 @@ pub fn initialize_license_result(raw_license: Option) -> LicenseResult<( let now = now_epoch_secs()?; match license_verifier().validate(&raw_license, now) { Ok(token) => { - apply_valid_status(&mut state, token.clone()); - info!("license loaded, subject: {}", token.name); + apply_valid_status(&mut state, token); Ok(()) } Err(err) => { apply_invalid_status(&mut state, err.clone()); - warn!("license verification failed: {err}"); Err(err) } } diff --git a/rustfs/src/main.rs b/rustfs/src/main.rs index a99a161fc..2851afae5 100644 --- a/rustfs/src/main.rs +++ b/rustfs/src/main.rs @@ -28,7 +28,7 @@ use rustfs::init::init_sftp_system; use futures_util::future::join_all; use rustfs::capacity::capacity_integration::init_capacity_management; -use rustfs::license::{current_license, init_license, license_status}; +use rustfs::license::{init_license, license_status}; use rustfs::server::{ ServiceState, ServiceStateManager, ShutdownHandle, ShutdownSignal, init_event_notifier, shutdown_event_notifier, start_audit_system, start_http_server, stop_audit_system, wait_for_shutdown, @@ -73,6 +73,22 @@ const ENV_SCANNER_ENABLED: &str = "RUSTFS_SCANNER_ENABLED"; const ENV_SCANNER_ENABLED_DEPRECATED: &str = "RUSTFS_ENABLE_SCANNER"; const ENV_HEAL_ENABLED: &str = "RUSTFS_HEAL_ENABLED"; const ENV_HEAL_ENABLED_DEPRECATED: &str = "RUSTFS_ENABLE_HEAL"; +const LOG_COMPONENT_MAIN: &str = "main"; +const LOG_SUBSYSTEM_STARTUP: &str = "startup"; +const LOG_SUBSYSTEM_LICENSE: &str = "license"; +const LOG_SUBSYSTEM_AUTH: &str = "auth"; +const EVENT_EXTERNAL_ENV_COMPAT_CONFLICT: &str = "external_env_compat_conflict"; +const EVENT_EXTERNAL_ENV_COMPAT_APPLIED: &str = "external_env_compat_applied"; +const EVENT_DIAL9_RUNTIME_STATUS: &str = "dial9_runtime_status"; +const EVENT_RUNTIME_LICENSE_STATUS: &str = "runtime_license_status"; +const EVENT_TLS_OUTBOUND_INITIALIZED: &str = "tls_outbound_initialized"; +const EVENT_DEFAULT_CREDENTIALS_DETECTED: &str = "default_credentials_detected"; +const EVENT_SERVER_CONFIG_SANITIZED: &str = "server_config_sanitized"; +const EVENT_SERVER_STARTING: &str = "server_starting"; +const EVENT_KEYSTONE_AUTH_INITIALIZED: &str = "keystone_auth_initialized"; +const EVENT_OIDC_INITIALIZATION_FAILED: &str = "oidc_initialization_failed"; +const EVENT_BACKGROUND_SERVICES_CONFIGURED: &str = "background_services_configured"; +const EVENT_SERVER_READY: &str = "server_ready"; #[cfg(all(target_os = "linux", target_env = "gnu", target_arch = "x86_64"))] #[global_allocator] static GLOBAL: tikv_jemallocator::Jemalloc = tikv_jemallocator::Jemalloc; @@ -82,10 +98,6 @@ static GLOBAL: tikv_jemallocator::Jemalloc = tikv_jemallocator::Jemalloc; static GLOBAL: mimalloc::MiMalloc = mimalloc::MiMalloc; fn main() { - if let Err(err) = bootstrap_external_prefix_compat() { - eprintln!("[WARN] Failed to bootstrap external-prefix compatibility: {err}"); - } - // Build Tokio runtime with optional dial9 telemetry support let runtime = rustfs::server::build_tokio_runtime().expect("Failed to build Tokio runtime"); let result = runtime.block_on(async_main()); @@ -96,29 +108,9 @@ fn main() { } } -fn bootstrap_external_prefix_compat() -> Result<()> { +fn bootstrap_external_prefix_compat() -> Result { let env_compat_report = apply_external_env_compat(); - if env_compat_report.conflict_count() > 0 { - // RUSTFS_* is the canonical namespace in this codebase, so on key conflicts we keep RUSTFS_* - // to preserve explicit user/operator overrides and avoid changing existing runtime behavior. - eprintln!( - "[WARN] Found {} source/RUSTFS_ conflict(s), keeping RUSTFS_ values: {}", - env_compat_report.conflict_count(), - env_compat_report.conflict_keys.join(", ") - ); - } - - if env_compat_report.mapped_count() == 0 { - return Ok(()); - } - - eprintln!( - "[INFO] Applying external-prefix compatibility in-process for {} variable(s): {}", - env_compat_report.mapped_count(), - format_external_prefix_mappings(&env_compat_report) - ); - - Ok(()) + Ok(env_compat_report) } fn format_external_prefix_mappings(report: &ExternalEnvCompatReport) -> String { @@ -137,6 +129,8 @@ fn is_using_default_credentials(config: &rustfs::config::Config) -> bool { const DEFAULT_CREDENTIALS_WARNING_MESSAGE: &str = "Detected default root credentials; set RUSTFS_ACCESS_KEY and RUSTFS_SECRET_KEY to non-default values for production deployments"; async fn async_main() -> Result<()> { + let env_compat_report = bootstrap_external_prefix_compat()?; + // Parse command line arguments let args: Vec = std::env::args().collect(); let command_result = match rustfs::config::Opt::parse_command(args) { @@ -176,7 +170,7 @@ async fn async_main() -> Result<()> { // Store in global storage match set_global_guard(guard).map_err(Error::other) { Ok(_) => { - info!(target: "rustfs::main", "Global observability guard set successfully."); + debug!(target: "rustfs::main", "Global observability guard set successfully."); } Err(e) => { error!("Failed to set global observability guard: {}", e); @@ -184,22 +178,42 @@ async fn async_main() -> Result<()> { } } + log_external_prefix_compat_report(&env_compat_report); + // Check dial9 Tokio runtime telemetry status // Note: The actual telemetry session is created in build_tokio_runtime() // which stores the TelemetryGuard globally for the program duration. if rustfs_obs::dial9::is_enabled() { - info!(target: "rustfs::main", "Dial9 Tokio telemetry is configured as enabled; runtime guard was installed during startup."); + info!( + target: "rustfs::main", + event = EVENT_DIAL9_RUNTIME_STATUS, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + enabled = true, + "Dial9 Tokio runtime telemetry is enabled" + ); } else { - info!(target: "rustfs::main", "Dial9 Tokio telemetry is not configured (set RUSTFS_RUNTIME_DIAL9_ENABLED=true to enable)."); + debug!( + target: "rustfs::main", + event = EVENT_DIAL9_RUNTIME_STATUS, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + enabled = false, + "Dial9 Tokio runtime telemetry is disabled" + ); } - info!("license status: {}", license_status()); - if let Some(token) = current_license() { - info!("runtime license loaded: {}", token.name); - } + info!( + target: "rustfs::main", + event = EVENT_RUNTIME_LICENSE_STATUS, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_LICENSE, + license_status = %license_status(), + "Initialized runtime license state" + ); // print startup logo - info!("{}", rustfs::server::LOGO); + debug!("{}", rustfs::server::LOGO); // Initialize performance profiling if enabled rustfs::profiling::init_from_env().await; @@ -223,7 +237,15 @@ async fn async_main() -> Result<()> { let generation = TlsGeneration(rustfs_common::get_global_outbound_tls_generation().saturating_add(1)); publish_global_outbound_tls_state(generation, &snapshot.outbound).await; record_tls_generation("rustfs_server_startup", generation.0); - info!(target: "rustfs::main", "TLS outbound material initialized from {}", tls_path); + info!( + target: "rustfs::main", + event = EVENT_TLS_OUTBOUND_INITIALIZED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + tls_path, + generation = generation.0, + "Initialized TLS outbound material" + ); } Err(e) => { error!("Failed to initialize TLS from {}: {}", tls_path, e); @@ -247,7 +269,23 @@ async fn async_main() -> Result<()> { #[instrument(skip(config))] async fn run(config: rustfs::config::Config) -> Result<()> { - debug!("config: {:?}", &config); + debug!( + target: "rustfs::main::run", + event = EVENT_SERVER_CONFIG_SANITIZED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + address = %config.address, + volume_count = config.volumes.len(), + server_domain_count = config.server_domains.len(), + console_enable = config.console_enable, + console_address = %config.console_address, + tls_enabled = config.tls_path.as_deref().is_some_and(|value| !value.trim().is_empty()), + kms_enable = config.kms_enable, + kms_backend = %config.kms_backend, + region = config.region.as_deref().unwrap_or_default(), + buffer_profile = %config.buffer_profile, + "Loaded sanitized server configuration" + ); // 1. Initialize global readiness tracker let readiness = Arc::new(GlobalReadiness::new()); @@ -263,23 +301,32 @@ async fn run(config: rustfs::config::Config) -> Result<()> { let server_address = server_addr.to_string(); if is_using_default_credentials(&config) { - warn!("{}", DEFAULT_CREDENTIALS_WARNING_MESSAGE); + warn!( + target: "rustfs::main::run", + event = EVENT_DEFAULT_CREDENTIALS_DETECTED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_AUTH, + warning = DEFAULT_CREDENTIALS_WARNING_MESSAGE, + "{DEFAULT_CREDENTIALS_WARNING_MESSAGE}" + ); } info!( target: "rustfs::main::run", + event = EVENT_SERVER_STARTING, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, server_address = %server_address, ip = %server_addr.ip(), port = %server_port, version = %rustfs::version::get_version(), - "Starting RustFS server at {}", - &server_address + "Starting RustFS server" ); // Set up AK and SK match init_global_action_credentials(Some(config.access_key.clone()), Some(config.secret_key.clone())) { Ok(_) => { - info!(target: "rustfs::main::run", "Global action credentials initialized successfully."); + debug!(target: "rustfs::main::run", "Global action credentials initialized successfully."); } Err(e) => { let msg = format!("init global action credentials failed: {e:?}"); @@ -316,7 +363,7 @@ async fn run(config: rustfs::config::Config) -> Result<()> { update_erasure_type(setup_type).await; // Initialize the local disk - info!( + debug!( target: "rustfs::main::run", "starting local disk initialization" ); @@ -339,6 +386,11 @@ async fn run(config: rustfs::config::Config) -> Result<()> { for (i, eps) in endpoint_pools.as_ref().iter().enumerate() { info!( target: "rustfs::main::run", + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + pool_id = i + 1, + set_count = eps.set_count, + drives_per_set = eps.drives_per_set, "Formatting {}st pool, {} set(s), {} drives per set.", i + 1, eps.set_count, @@ -351,7 +403,7 @@ async fn run(config: rustfs::config::Config) -> Result<()> { } for (i, eps) in endpoint_pools.as_ref().iter().enumerate() { - info!( + debug!( target: "rustfs::main::run", id = i, set_count = eps.set_count, @@ -362,7 +414,7 @@ async fn run(config: rustfs::config::Config) -> Result<()> { ); for ep in eps.endpoints.as_ref().iter() { - info!( + debug!( target: "rustfs::main::run", " - endpoint: {}", ep ); @@ -394,7 +446,7 @@ async fn run(config: rustfs::config::Config) -> Result<()> { // init store // 2. Start Storage Engine (ECStore) - info!( + debug!( target: "rustfs::main::run", "starting ECStore initialization" ); @@ -566,7 +618,12 @@ async fn run(config: rustfs::config::Config) -> Result<()> { let keystone_config = rustfs_keystone::KeystoneConfig::from_env().map_err(Error::other)?; if keystone_config.enable { match rustfs::auth_keystone::init_keystone_auth(keystone_config).await { - Ok(_) => info!("Keystone authentication initialized successfully"), + Ok(_) => info!( + event = EVENT_KEYSTONE_AUTH_INITIALIZED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_AUTH, + "Initialized Keystone authentication" + ), Err(e) => { error!("Failed to initialize Keystone authentication: {}", e); // Continue without Keystone - fall back to standard auth @@ -576,7 +633,13 @@ async fn run(config: rustfs::config::Config) -> Result<()> { // 3b. Initialize OIDC System (non-fatal if no providers configured) if let Err(e) = init_oidc_sys().await { - warn!("OIDC initialization failed (non-fatal): {}", e); + warn!( + event = EVENT_OIDC_INITIALIZATION_FAILED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_AUTH, + error = %e, + "OIDC initialization failed; continuing without OIDC providers" + ); } add_bucket_notification_configuration(buckets.clone()).await; @@ -596,9 +659,12 @@ async fn run(config: rustfs::config::Config) -> Result<()> { info!( target: "rustfs::main::run", + event = EVENT_BACKGROUND_SERVICES_CONFIGURED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, enable_scanner = enable_scanner, enable_heal = enable_heal, - "Background services configuration: scanner={}, heal={}", enable_scanner, enable_heal + "Configured background services" ); // Scanner depends on the heal channel/manager, so scanner implies heal. @@ -608,7 +674,7 @@ async fn run(config: rustfs::config::Config) -> Result<()> { } if !enable_heal && !enable_scanner { - info!(target: "rustfs::main::run","Both scanner and heal are disabled, skipping AHM service initialization"); + debug!(target: "rustfs::main::run","Both scanner and heal are disabled, skipping AHM service initialization"); } // print server info @@ -628,10 +694,14 @@ async fn run(config: rustfs::config::Config) -> Result<()> { info!( target: "rustfs::main::run", - "RustFS server version: {} started successfully at {}, current time: {}", - rustfs::version::get_version(), - &server_address, - jiff::Zoned::now() + event = EVENT_SERVER_READY, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + version = %rustfs::version::get_version(), + server_address = %server_address, + started_at = %jiff::Zoned::now(), + iam_bootstrap = ?iam_bootstrap, + "RustFS server started successfully" ); if iam_bootstrap == IamBootstrapDisposition::ReadyInline { rustfs::server::publish_ready_when_runtime_ready(readiness.as_ref(), Some(state_manager.as_ref())).await?; @@ -664,6 +734,32 @@ async fn run(config: rustfs::config::Config) -> Result<()> { Ok(()) } +fn log_external_prefix_compat_report(report: &ExternalEnvCompatReport) { + if report.conflict_count() > 0 { + warn!( + target: "rustfs::main", + event = EVENT_EXTERNAL_ENV_COMPAT_CONFLICT, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + conflict_count = report.conflict_count(), + conflict_keys = %report.conflict_keys.join(", "), + "Detected external-prefix compatibility conflicts; keeping RUSTFS_ values" + ); + } + + if report.mapped_count() > 0 { + info!( + target: "rustfs::main", + event = EVENT_EXTERNAL_ENV_COMPAT_APPLIED, + component = LOG_COMPONENT_MAIN, + subsystem = LOG_SUBSYSTEM_STARTUP, + mapped_count = report.mapped_count(), + mapped_pairs = %format_external_prefix_mappings(report), + "Applied external-prefix compatibility mappings" + ); + } +} + /// Shutdown channels for every protocol server. None means the protocol was /// disabled at startup. struct ProtocolShutdownSenders { diff --git a/rustfs/src/protocols/client.rs b/rustfs/src/protocols/client.rs index 74631a91f..24a7f6f2e 100644 --- a/rustfs/src/protocols/client.rs +++ b/rustfs/src/protocols/client.rs @@ -22,6 +22,10 @@ use s3s::{S3, S3Request, S3Result}; use tokio_stream::Stream; use tracing::trace; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_STORAGE_CLIENT: &str = "storage_client"; +const EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST: &str = "protocol_storage_client_request"; + const PATH_SEGMENT_ENCODE_SET: &AsciiSet = &CONTROLS .add(b' ') .add(b'"') @@ -73,6 +77,18 @@ fn parse_protocol_uri(uri: String, context: String) -> S3Result { .map_err(|e| s3s::S3Error::with_message(s3s::S3ErrorCode::InvalidRequest, format!("invalid URI for {context}: {e}"))) } +fn trace_protocol_request(operation: &str, bucket: Option<&str>, object: Option<&str>) { + trace!( + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation, + bucket = bucket.unwrap_or_default(), + object = object.unwrap_or_default(), + "Protocol storage client request" + ); +} + fn build_bucket_uri(bucket: &str, query: &[(&str, Option<&str>)]) -> S3Result { let mut uri = format!("/{}", encode_path_segment(bucket)); let mut first = true; @@ -182,9 +198,16 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, start_pos: Option, ) -> Result { + trace_protocol_request("get_object", Some(bucket), Some(key)); trace!( - "Protocol storage client GetObject request: bucket={}, key={}, start_pos={:?}", - bucket, key, start_pos + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "get_object", + bucket, + object = %key, + start_pos = ?start_pos, + "Protocol storage client request details" ); let mut builder = GetObjectInput::builder().bucket(bucket.to_string()).key(key.to_string()); @@ -229,7 +252,15 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli access_key: &str, secret_key: &str, ) -> Result { - trace!("Protocol storage client PutObject request: bucket={}, key={:?}", input.bucket, input.key); + trace!( + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "put_object", + bucket = %input.bucket, + object = %input.key, + "Protocol storage client request" + ); let bucket = input.bucket.clone(); let key = input.key.clone(); @@ -274,7 +305,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli access_key: &str, secret_key: &str, ) -> Result { - trace!("Protocol storage client DeleteObject request: bucket={}, key={}", bucket, key); + trace_protocol_request("delete_object", Some(bucket), Some(key)); let input = DeleteObjectInput::builder() .bucket(bucket.to_string()) @@ -312,7 +343,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli access_key: &str, secret_key: &str, ) -> Result { - trace!("Protocol storage client HeadObject request: bucket={}, key={}", bucket, key); + trace_protocol_request("head_object", Some(bucket), Some(key)); let input = HeadObjectInput::builder() .bucket(bucket.to_string()) @@ -344,7 +375,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli } async fn head_bucket(&self, bucket: &str, access_key: &str, secret_key: &str) -> Result { - trace!("Protocol storage client HeadBucket request: bucket={}", bucket); + trace_protocol_request("head_bucket", Some(bucket), None); let input = HeadBucketInput::builder().bucket(bucket.to_string()).build().map_err(|e| { s3s::S3Error::with_message(s3s::S3ErrorCode::InvalidRequest, format!("Failed to build HeadBucketInput: {}", e)) @@ -377,7 +408,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli access_key: &str, secret_key: &str, ) -> Result { - trace!("Protocol storage client ListObjectsV2 request: bucket={}", input.bucket); + trace_protocol_request("list_objects_v2", Some(&input.bucket), None); let bucket = input.bucket.clone(); let uri = build_bucket_uri(&bucket, &[("list-type", Some("2"))])?; @@ -402,7 +433,14 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli } async fn list_buckets(&self, access_key: &str, secret_key: &str) -> Result { - trace!(access_key = %MaskedAccessKey(access_key), "Protocol storage client ListBuckets request"); + trace!( + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "list_buckets", + access_key = %MaskedAccessKey(access_key), + "Protocol storage client request" + ); let input = ListBucketsInput::builder().build().map_err(|e| { s3s::S3Error::with_message(s3s::S3ErrorCode::InvalidRequest, format!("Failed to build ListBucketsInput: {}", e)) @@ -429,7 +467,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli } async fn create_bucket(&self, bucket: &str, access_key: &str, secret_key: &str) -> Result { - trace!("Protocol storage client CreateBucket request: bucket={}", bucket); + trace_protocol_request("create_bucket", Some(bucket), None); let input = CreateBucketInput::builder().bucket(bucket.to_string()).build().map_err(|e| { s3s::S3Error::with_message(s3s::S3ErrorCode::InvalidRequest, format!("Failed to build CreateBucketInput: {}", e)) @@ -465,9 +503,17 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli start_pos: u64, length: u64, ) -> Result { + trace_protocol_request("get_object_range", Some(bucket), Some(key)); trace!( - "Protocol storage client GetObjectRange request: bucket={}, key={}, start={}, length={}", - bucket, key, start_pos, length + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "get_object_range", + bucket, + object = %key, + range_start = start_pos, + range_length = length, + "Protocol storage client request details" ); let range = s3s::dto::Range::Int { @@ -511,7 +557,15 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli access_key: &str, secret_key: &str, ) -> Result { - trace!("Protocol storage client CopyObject request: bucket={}, key={}", input.bucket, input.key); + trace!( + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "copy_object", + bucket = %input.bucket, + object = %input.key, + "Protocol storage client request" + ); let bucket = input.bucket.clone(); let key = input.key.clone(); @@ -538,7 +592,7 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli } async fn delete_bucket(&self, bucket: &str, access_key: &str, secret_key: &str) -> Result { - trace!("Protocol storage client DeleteBucket request: bucket={}", bucket); + trace_protocol_request("delete_bucket", Some(bucket), None); let input = DeleteBucketInput::builder().bucket(bucket.to_string()).build().map_err(|e| { s3s::S3Error::with_message(s3s::S3ErrorCode::InvalidRequest, format!("Failed to build DeleteBucketInput: {}", e)) @@ -572,8 +626,13 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, ) -> Result { trace!( - "Protocol storage client CreateMultipartUpload request: bucket={}, key={}", - input.bucket, input.key + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "create_multipart_upload", + bucket = %input.bucket, + object = %input.key, + "Protocol storage client request" ); let bucket = input.bucket.clone(); @@ -607,8 +666,14 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, ) -> Result { trace!( - "Protocol storage client UploadPart request: bucket={}, key={}, part_number={}", - input.bucket, input.key, input.part_number + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "upload_part", + bucket = %input.bucket, + object = %input.key, + part_number = input.part_number, + "Protocol storage client request" ); let bucket = input.bucket.clone(); @@ -673,8 +738,13 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, ) -> Result { trace!( - "Protocol storage client CompleteMultipartUpload request: bucket={}, key={}", - input.bucket, input.key + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "complete_multipart_upload", + bucket = %input.bucket, + object = %input.key, + "Protocol storage client request" ); let bucket = input.bucket.clone(); @@ -709,8 +779,14 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, ) -> Result { trace!( - "Protocol storage client AbortMultipartUpload request: bucket={}, key={}, upload_id={}", - input.bucket, input.key, input.upload_id + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "abort_multipart_upload", + bucket = %input.bucket, + object = %input.key, + upload_id = %input.upload_id, + "Protocol storage client request" ); let bucket = input.bucket.clone(); @@ -745,8 +821,14 @@ impl rustfs_protocols::common::client::s3::StorageBackend for ProtocolStorageCli secret_key: &str, ) -> Result { trace!( - "Protocol storage client UploadPartCopy request: bucket={}, key={}, part_number={}", - input.bucket, input.key, input.part_number + event = EVENT_PROTOCOL_STORAGE_CLIENT_REQUEST, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_STORAGE_CLIENT, + operation = "upload_part_copy", + bucket = %input.bucket, + object = %input.key, + part_number = input.part_number, + "Protocol storage client request" ); let bucket = input.bucket.clone(); diff --git a/rustfs/src/startup_iam.rs b/rustfs/src/startup_iam.rs index 841b94052..ae95cef1c 100644 --- a/rustfs/src/startup_iam.rs +++ b/rustfs/src/startup_iam.rs @@ -25,6 +25,14 @@ use std::sync::Arc; use std::time::Duration; use tracing::{error, info, warn}; +const LOG_COMPONENT_STARTUP_IAM: &str = "startup_iam"; +const LOG_SUBSYSTEM_BOOTSTRAP: &str = "bootstrap"; +const EVENT_IAM_BOOTSTRAP_RECOVERED: &str = "iam_bootstrap_recovered"; +const EVENT_IAM_BOOTSTRAP_RETRY_FAILED: &str = "iam_bootstrap_retry_failed"; +const EVENT_IAM_READINESS_PUBLISHED: &str = "iam_readiness_published"; +const EVENT_IAM_READINESS_PUBLICATION_FAILED: &str = "iam_readiness_publication_failed"; +const EVENT_IAM_BOOTSTRAP_DEFERRED: &str = "iam_bootstrap_deferred"; + const IAM_RETRY_INITIAL_INTERVAL: Duration = Duration::from_secs(5); const IAM_RETRY_MAX_INTERVAL: Duration = Duration::from_secs(30); /// After this many retries (~5 min at initial interval), escalate log level to ERROR. @@ -137,6 +145,9 @@ async fn run_iam_recovery_loop( Ok(()) => { let degraded_secs = degraded_since.elapsed().as_secs(); info!( + event = EVENT_IAM_BOOTSTRAP_RECOVERED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, attempts, degraded_duration_secs = degraded_secs, "IAM bootstrap recovered after startup; publishing IAM readiness" @@ -147,15 +158,20 @@ async fn run_iam_recovery_loop( let next_interval = compute_backoff_interval(attempts + 1, initial_interval, max_interval); if attempts >= IAM_RETRY_ESCALATION_THRESHOLD { error!( + event = EVENT_IAM_BOOTSTRAP_RETRY_FAILED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, attempts, next_retry_secs = next_interval.as_secs(), degraded_duration_secs = degraded_since.elapsed().as_secs(), error = %err, - "IAM bootstrap retry failed after {} attempts; service remains degraded", - attempts + "IAM bootstrap retry failed; service remains degraded" ); } else { warn!( + event = EVENT_IAM_BOOTSTRAP_RETRY_FAILED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, attempts, next_retry_secs = next_interval.as_secs(), error = %err, @@ -173,6 +189,9 @@ async fn run_iam_recovery_loop( match finalize_fn().await { Ok(()) => { info!( + event = EVENT_IAM_READINESS_PUBLISHED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, init_attempts = attempts, finalize_attempts, degraded_duration_secs = degraded_since.elapsed().as_secs(), @@ -183,6 +202,9 @@ async fn run_iam_recovery_loop( Err(err) => { let retry_interval = compute_backoff_interval(finalize_attempts, initial_interval, max_interval); warn!( + event = EVENT_IAM_READINESS_PUBLICATION_FAILED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, finalize_attempts, retry_secs = retry_interval.as_secs(), error = %err, @@ -290,6 +312,9 @@ pub async fn bootstrap_or_defer_iam_init( Err(err) => { let interval = initial_retry_interval(); warn!( + event = EVENT_IAM_BOOTSTRAP_DEFERRED, + component = LOG_COMPONENT_STARTUP_IAM, + subsystem = LOG_SUBSYSTEM_BOOTSTRAP, error = %err, initial_retry_secs = interval.as_secs(), max_retry_secs = IAM_RETRY_MAX_INTERVAL.as_secs(),