refactor(auth): tighten startup log redaction (#3358)

This commit is contained in:
houseme
2026-06-11 18:08:41 +08:00
committed by GitHub
parent 69549634ea
commit f6137f9f77
5 changed files with 430 additions and 111 deletions
+113 -28
View File
@@ -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
}
+36 -5
View File
@@ -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<T> = std::result::Result<T, LicenseError>;
pub type SharedLicenseVerifier = Arc<dyn LicenseVerifier>;
@@ -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<String>) {
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<String>) -> 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)
}
}
+149 -53
View File
@@ -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<ExternalEnvCompatReport> {
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<String> = 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 {
+105 -23
View File
@@ -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<http::Uri> {
.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<http::Uri> {
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<u64>,
) -> Result<GetObjectOutput, Self::Error> {
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<PutObjectOutput, Self::Error> {
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<DeleteObjectOutput, Self::Error> {
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<HeadObjectOutput, Self::Error> {
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<HeadBucketOutput, Self::Error> {
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<ListObjectsV2Output, Self::Error> {
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<ListBucketsOutput, Self::Error> {
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<CreateBucketOutput, Self::Error> {
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<GetObjectOutput, Self::Error> {
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<CopyObjectOutput, Self::Error> {
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<DeleteBucketOutput, Self::Error> {
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<CreateMultipartUploadOutput, Self::Error> {
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<UploadPartOutput, Self::Error> {
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<CompleteMultipartUploadOutput, Self::Error> {
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<AbortMultipartUploadOutput, Self::Error> {
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<UploadPartCopyOutput, Self::Error> {
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();
+27 -2
View File
@@ -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<InitFn, FinalizeFn>(
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<InitFn, FinalizeFn>(
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<InitFn, FinalizeFn>(
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<InitFn, FinalizeFn>(
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(),