From efa89a98ed941b7db2fc3988b1c65d7e425a41d6 Mon Sep 17 00:00:00 2001 From: houseme Date: Sun, 14 Jun 2026 07:14:45 +0800 Subject: [PATCH] refactor(logging): standardize protocol and observability events (#3419) * refactor(logging): standardize object capacity events * refactor(logging): standardize protocol server events * refactor(logging): standardize swift protocol events * refactor(logging): standardize observability events * refactor(logging): move masking helper and extend guardrails --- .../object-capacity/src/capacity_manager.rs | 134 ++++++- crates/object-capacity/src/scan.rs | 230 ++++++++++-- crates/obs/src/cleaner/compress.rs | 20 +- crates/obs/src/cleaner/core.rs | 74 +++- crates/obs/src/cleaner/scanner.rs | 12 +- crates/obs/src/global.rs | 18 +- crates/obs/src/logging.rs | 37 +- .../obs/src/metrics/collectors/system_gpu.rs | 13 +- crates/obs/src/metrics/scheduler.rs | 34 +- crates/obs/src/metrics/stats_collector.rs | 17 +- crates/obs/src/telemetry/dial9.rs | 56 ++- crates/obs/src/telemetry/local.rs | 41 ++- crates/obs/src/telemetry/recorder.rs | 10 +- crates/protocols/src/common/gateway.rs | 12 +- crates/protocols/src/ftps/driver.rs | 203 ++++++++++- crates/protocols/src/ftps/server.rs | 221 ++++++++++-- crates/protocols/src/sftp/config.rs | 83 ++++- crates/protocols/src/sftp/dir.rs | 10 +- crates/protocols/src/sftp/driver.rs | 73 +++- crates/protocols/src/sftp/errors.rs | 12 +- .../protocols/src/sftp/fallback_watchdog.rs | 10 +- crates/protocols/src/sftp/server.rs | 329 +++++++++++++++--- crates/protocols/src/sftp/wedge_watchdog.rs | 10 +- crates/protocols/src/sftp/write.rs | 128 ++++++- crates/protocols/src/swift/acl.rs | 44 ++- crates/protocols/src/swift/bulk.rs | 97 +++++- crates/protocols/src/swift/container.rs | 25 +- crates/protocols/src/swift/cors.rs | 14 +- crates/protocols/src/swift/encryption.rs | 50 ++- crates/protocols/src/swift/expiration.rs | 24 +- .../protocols/src/swift/expiration_worker.rs | 187 ++++++++-- crates/protocols/src/swift/formpost.rs | 23 +- crates/protocols/src/swift/handler.rs | 53 ++- crates/protocols/src/swift/object.rs | 23 +- crates/protocols/src/swift/quota.rs | 16 +- crates/protocols/src/swift/ratelimit.rs | 8 +- crates/protocols/src/swift/staticweb.rs | 58 ++- crates/protocols/src/swift/symlink.rs | 20 +- crates/protocols/src/swift/sync.rs | 18 +- crates/protocols/src/swift/versioning.rs | 197 ++++++++++- crates/protocols/src/webdav/driver.rs | 301 ++++++++++++++-- crates/protocols/src/webdav/server.rs | 190 +++++++++- crates/utils/src/lib.rs | 3 + crates/utils/src/logging.rs | 70 ++++ rustfs/src/auth.rs | 2 +- rustfs/src/auth_keystone.rs | 2 +- rustfs/src/protocols/client.rs | 2 +- scripts/check_logging_guardrails.sh | 196 +++++++++++ 48 files changed, 2976 insertions(+), 434 deletions(-) create mode 100644 crates/utils/src/logging.rs diff --git a/crates/object-capacity/src/capacity_manager.rs b/crates/object-capacity/src/capacity_manager.rs index 3104f7da6..a767a349c 100644 --- a/crates/object-capacity/src/capacity_manager.rs +++ b/crates/object-capacity/src/capacity_manager.rs @@ -43,6 +43,18 @@ use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; use tokio::sync::{Mutex, RwLock, watch}; use tracing::{debug, info, warn}; +const LOG_COMPONENT_CAPACITY: &str = "capacity"; +const LOG_SUBSYSTEM_REFRESH: &str = "refresh"; +const LOG_SUBSYSTEM_RUNTIME: &str = "runtime"; +const EVENT_CAPACITY_REFRESH_CACHE_UPDATED: &str = "capacity_refresh_cache_updated"; +const EVENT_CAPACITY_REFRESH_WRITE_RECORDED: &str = "capacity_refresh_write_recorded"; +const EVENT_CAPACITY_REFRESH_DEBOUNCE_STATE: &str = "capacity_refresh_debounce_state"; +const EVENT_CAPACITY_REFRESH_PANIC: &str = "capacity_refresh_panic"; +const EVENT_CAPACITY_REFRESH_RUNTIME_SUMMARY: &str = "capacity_refresh_runtime_summary"; +const EVENT_CAPACITY_REFRESH_INTERVAL_CLAMPED: &str = "capacity_refresh_interval_clamped"; +const EVENT_CAPACITY_REFRESH_SCHEDULED: &str = "capacity_refresh_scheduled"; +const EVENT_CAPACITY_REFRESH_SKIPPED: &str = "capacity_refresh_skipped"; + // ============================================================================ // Configuration Functions // ============================================================================ @@ -649,8 +661,16 @@ impl HybridCapacityManager { } debug!( - "Capacity updated: {} bytes, files={}, estimated={}, source: {:?}", - total_used, update.file_count, update.is_estimated, source + event = EVENT_CAPACITY_REFRESH_CACHE_UPDATED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + result = "updated", + total_used, + file_count = update.file_count, + estimated = update.is_estimated, + source = source.as_metric_label(), + elapsed_ms = start.elapsed().as_millis() as u64, + "capacity refresh cache updated" ); record_capacity_current_bytes(total_used); record_capacity_update_completed(source.as_metric_label(), start.elapsed(), total_used, update.is_estimated); @@ -664,8 +684,13 @@ impl HybridCapacityManager { record_capacity_write_operation(recent_write_count); debug!( - "Write operation recorded: total writes = {}, recent writes = {}", - record.write_count, recent_write_count + event = EVENT_CAPACITY_REFRESH_WRITE_RECORDED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + state = "recorded", + total_writes = record.write_count, + recent_writes = recent_write_count, + "capacity refresh write recorded" ); } @@ -721,15 +746,27 @@ impl HybridCapacityManager { if time_since_write < self.config.write_trigger_delay { debug!( - "Write-triggered refresh still debounced ({:?} ago, trigger_delay={:?}, writes/min={})", - time_since_write, self.config.write_trigger_delay, write_frequency + event = EVENT_CAPACITY_REFRESH_DEBOUNCE_STATE, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + state = "debounced", + time_since_write_ms = time_since_write.as_millis() as u64, + trigger_delay_ms = self.config.write_trigger_delay.as_millis() as u64, + writes_per_minute = write_frequency, + "capacity refresh debounce state changed" ); return false; } debug!( - "Write-triggered refresh eligible after debounce ({:?} ago, trigger_delay={:?}, writes/min={})", - time_since_write, self.config.write_trigger_delay, write_frequency + event = EVENT_CAPACITY_REFRESH_DEBOUNCE_STATE, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + state = "eligible", + time_since_write_ms = time_since_write.as_millis() as u64, + trigger_delay_ms = self.config.write_trigger_delay.as_millis() as u64, + writes_per_minute = write_frequency, + "capacity refresh debounce state changed" ); return true; } @@ -808,7 +845,15 @@ impl HybridCapacityManager { let refresh_start = Instant::now(); let result = AssertUnwindSafe(refresh_fn()).catch_unwind().await.unwrap_or_else(|err| { - warn!(error = ?err, "capacity refresh function panicked"); + warn!( + event = EVENT_CAPACITY_REFRESH_PANIC, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + result = "panic", + source = source.as_metric_label(), + error = ?err, + "capacity refresh panicked" + ); Err("capacity refresh panicked".to_string()) }); if let Ok(update) = &result { @@ -860,7 +905,15 @@ impl HybridCapacityManager { tokio::spawn(async move { let refresh_start = Instant::now(); let result = AssertUnwindSafe(refresh_fn()).catch_unwind().await.unwrap_or_else(|err| { - warn!(error = ?err, "capacity refresh function panicked"); + warn!( + event = EVENT_CAPACITY_REFRESH_PANIC, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_REFRESH, + result = "panic", + source = source.as_metric_label(), + error = ?err, + "capacity refresh panicked" + ); Err("capacity refresh panicked".to_string()) }); if let Ok(update) = &result { @@ -909,22 +962,30 @@ impl HybridCapacityManager { if let Some(cached) = cached { info!( + event = EVENT_CAPACITY_REFRESH_RUNTIME_SUMMARY, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + state = "cache_present", total_used = cached.total_used, file_count = cached.file_count, estimated = cached.is_estimated, - source = ?cached.source, + source = cached.source.as_metric_label(), cache_age_secs = cached.last_update.elapsed().as_secs(), writes_per_minute = recent_write_frequency, dirty_disk_count = dirty_disks.len(), refresh_inflight = refresh_running, - "Capacity metrics summary" + "capacity refresh runtime summary" ); } else { info!( + event = EVENT_CAPACITY_REFRESH_RUNTIME_SUMMARY, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + state = "cache_empty", writes_per_minute = recent_write_frequency, dirty_disk_count = dirty_disks.len(), refresh_inflight = refresh_running, - "Capacity metrics summary (cache empty)" + "capacity refresh runtime summary" ); } } @@ -967,11 +1028,31 @@ pub async fn start_background_task(disks: Vec) { // Prevent panic in tokio::time::interval when misconfigured to 0 if refresh_interval.is_zero() { - warn!("RUSTFS_CAPACITY_SCHEDULED_INTERVAL is configured as 0; clamping to 1s to avoid panic"); + warn!( + event = EVENT_CAPACITY_REFRESH_INTERVAL_CLAMPED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + result = "clamped", + env_var = ENV_CAPACITY_SCHEDULED_INTERVAL, + configured_secs = 0, + effective_secs = 1, + reason = "zero_interval", + "capacity refresh interval clamped" + ); refresh_interval = Duration::from_secs(1); } if metrics_interval.is_zero() { - warn!("RUSTFS_CAPACITY_METRICS_INTERVAL is configured as 0; clamping to 1s to avoid panic"); + warn!( + event = EVENT_CAPACITY_REFRESH_INTERVAL_CLAMPED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + result = "clamped", + env_var = ENV_CAPACITY_METRICS_INTERVAL, + configured_secs = 0, + effective_secs = 1, + reason = "zero_interval", + "capacity refresh interval clamped" + ); metrics_interval = Duration::from_secs(1); } @@ -981,10 +1062,10 @@ pub async fn start_background_task(disks: Vec) { loop { timer.tick().await; - info!("Starting scheduled capacity update"); let start = Instant::now(); let manager = manager_for_refresh.clone(); let disks = disks.clone(); + let disk_count = disks.len(); let started = manager .clone() .spawn_refresh_if_needed( @@ -994,9 +1075,26 @@ pub async fn start_background_task(disks: Vec) { .await; if started { - debug!("Scheduled capacity refresh started in {:?}", start.elapsed()); + debug!( + event = EVENT_CAPACITY_REFRESH_SCHEDULED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + state = "started", + source = DataSource::Scheduled.as_metric_label(), + disk_count, + enqueue_latency_ms = start.elapsed().as_millis() as u64, + "capacity refresh scheduled" + ); } else { - debug!("Scheduled capacity refresh skipped because another refresh is already in progress"); + debug!( + event = EVENT_CAPACITY_REFRESH_SKIPPED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_RUNTIME, + state = "inflight", + source = DataSource::Scheduled.as_metric_label(), + disk_count, + "capacity refresh skipped" + ); } } }); diff --git a/crates/object-capacity/src/scan.rs b/crates/object-capacity/src/scan.rs index 5b4b4355e..cacd224ad 100644 --- a/crates/object-capacity/src/scan.rs +++ b/crates/object-capacity/src/scan.rs @@ -32,6 +32,22 @@ use walkdir::WalkDir; const MAX_CAPACITY_SCAN_CONCURRENCY: usize = 4; const CAPACITY_PROGRESS_CHECK_STRIDE: usize = 512; +const LOG_COMPONENT_CAPACITY: &str = "capacity"; +const LOG_SUBSYSTEM_SCAN: &str = "scan"; +const LOG_SUBSYSTEM_SAMPLING: &str = "sampling"; +const EVENT_CAPACITY_SCAN_DISK_COMPLETED: &str = "capacity_scan_disk_completed"; +const EVENT_CAPACITY_SCAN_DISK_FAILED: &str = "capacity_scan_disk_failed"; +const EVENT_CAPACITY_SCAN_SUMMARY: &str = "capacity_scan_summary"; +const EVENT_CAPACITY_SCAN_SYMLINK_SKIPPED: &str = "capacity_scan_symlink_skipped"; +const EVENT_CAPACITY_SCAN_SYMLINK_SUMMARY: &str = "capacity_scan_symlink_summary"; +const EVENT_CAPACITY_SCAN_DYNAMIC_TIMEOUT: &str = "capacity_scan_dynamic_timeout"; +const EVENT_CAPACITY_SCAN_TIMEOUT: &str = "capacity_scan_timeout"; +const EVENT_CAPACITY_SCAN_STALL_DETECTED: &str = "capacity_scan_stall_detected"; +const EVENT_CAPACITY_SCAN_SAMPLING_CLAMPED: &str = "capacity_scan_sampling_clamped"; +const EVENT_CAPACITY_SCAN_TRAVERSAL_FAILED: &str = "capacity_scan_traversal_failed"; +const EVENT_CAPACITY_SCAN_METADATA_FAILED: &str = "capacity_scan_metadata_failed"; +const EVENT_CAPACITY_SCAN_SAMPLING_APPLIED: &str = "capacity_scan_sampling_applied"; +const EVENT_CAPACITY_SCAN_EXACT_COMPLETED: &str = "capacity_scan_exact_completed"; #[derive(Debug)] struct DiskScanOutcome { @@ -138,8 +154,19 @@ async fn calculate_data_dir_used_capacity_report( scan.had_partial_errors, ); debug!( - "Data directory {} size: {} bytes, files={}, sampled={}, estimated={}, duration={:?}", - outcome.drive_path, scan.used_bytes, scan.file_count, scan.sampled_count, scan.is_estimated, outcome.duration + event = EVENT_CAPACITY_SCAN_DISK_COMPLETED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "ok", + disk_label = %outcome.disk_label, + drive_path = %outcome.drive_path, + used_bytes = scan.used_bytes, + file_count = scan.file_count, + sampled_count = scan.sampled_count, + estimated = scan.is_estimated, + partial_errors = scan.had_partial_errors, + duration_ms = outcome.duration.as_millis() as u64, + "capacity scan disk completed" ); total_used += scan.used_bytes; total_files += scan.file_count; @@ -159,7 +186,17 @@ async fn calculate_data_dir_used_capacity_report( } Err(e) => { record_capacity_scan_disk(outcome.disk_label.as_str(), outcome.duration, 0, 0, false, true); - warn!("Failed to get size for directory {}: {:?}", outcome.drive_path, e); + warn!( + event = EVENT_CAPACITY_SCAN_DISK_FAILED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "error", + disk_label = %outcome.disk_label, + drive_path = %outcome.drive_path, + duration_ms = outcome.duration.as_millis() as u64, + error = ?e, + "capacity scan disk failed" + ); has_failure = true; } } @@ -170,7 +207,19 @@ async fn calculate_data_dir_used_capacity_report( } if has_failure { - warn!("Some directories failed to calculate size, result may be incomplete"); + warn!( + event = EVENT_CAPACITY_SCAN_SUMMARY, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "partial", + disk_count = disks.len(), + used_bytes = total_used, + file_count = total_files, + sampled_count = total_sampled, + estimated = is_estimated, + duration_ms = start.elapsed().as_millis() as u64, + "capacity scan completed with partial failures" + ); } let mut summary = CapacityScanResult { @@ -265,12 +314,30 @@ impl SymlinkTracker { fn should_follow(&self, path: &Path, depth: u8) -> bool { if depth >= self.max_depth { - debug!("Symlink depth limit reached: {} >= {}, not following {:?}", depth, self.max_depth, path); + debug!( + event = EVENT_CAPACITY_SCAN_SYMLINK_SKIPPED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "skipped", + reason = "depth_limit", + depth, + max_depth = self.max_depth, + path = ?path, + "capacity scan symlink skipped" + ); return false; } if self.visited.contains(path) { - warn!("Circular symlink reference detected: {:?}, skipping", path); + warn!( + event = EVENT_CAPACITY_SCAN_SYMLINK_SKIPPED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "skipped", + reason = "cycle_detected", + path = ?path, + "capacity scan symlink skipped" + ); return false; } @@ -343,8 +410,17 @@ impl ProgressMonitor { let clamped_timeout = adjusted_timeout.max(self.min_timeout).min(self.max_timeout); debug!( - "Dynamic timeout calculation: files={}, avg_size={}, multiplier={:.2}, base_timeout={:?}, adjusted_timeout={:?}, clamped_timeout={:?}", - file_count, avg_file_size, multiplier, self.timeout, adjusted_timeout, clamped_timeout + event = EVENT_CAPACITY_SCAN_DYNAMIC_TIMEOUT, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + state = "calculated", + file_count, + avg_file_size, + multiplier, + base_timeout_secs = self.timeout.as_secs(), + adjusted_timeout_secs = adjusted_timeout.as_secs(), + clamped_timeout_secs = clamped_timeout.as_secs(), + "capacity scan dynamic timeout calculated" ); clamped_timeout @@ -360,8 +436,15 @@ impl ProgressMonitor { if elapsed >= dynamic_timeout { warn!( - "Directory size calculation timeout after {} files, elapsed: {:?}, timeout: {:?}", - files_processed, elapsed, dynamic_timeout + event = EVENT_CAPACITY_SCAN_TIMEOUT, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "timeout", + file_count = files_processed, + elapsed_ms = elapsed.as_millis() as u64, + timeout_ms = dynamic_timeout.as_millis() as u64, + dynamic_timeout_enabled = self.enable_dynamic_timeout, + "capacity scan timed out" ); if self.enable_dynamic_timeout { @@ -380,8 +463,13 @@ impl ProgressMonitor { if files_per_checkpoint == 0 && files_processed > 0 { warn!( - "No progress detected for {:?}, possible stall at {} files", - self.stall_timeout, files_processed + event = EVENT_CAPACITY_SCAN_STALL_DETECTED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "stall", + file_count = files_processed, + stall_timeout_ms = self.stall_timeout.as_millis() as u64, + "capacity scan stall detected" ); record_capacity_stall_detected(); @@ -418,7 +506,16 @@ async fn get_dir_size_async(path: &Path) -> Result Result entry, Err(err) => { - warn!("Failed to traverse directory entry under {:?}: {}", path, err); + warn!( + event = EVENT_CAPACITY_SCAN_TRAVERSAL_FAILED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "partial", + root_path = ?path, + error = %err, + "capacity scan traversal failed" + ); had_partial_errors = true; continue; } @@ -479,7 +584,15 @@ async fn get_dir_size_async(path: &Path) -> Result meta, Err(err) => { - warn!("Failed to get metadata for {:?}: {}", entry.path(), err); + warn!( + event = EVENT_CAPACITY_SCAN_METADATA_FAILED, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "partial", + entry_path = ?entry.path(), + error = %err, + "capacity scan metadata failed" + ); had_partial_errors = true; continue; } @@ -502,8 +615,17 @@ async fn get_dir_size_async(path: &Path) -> Result Result Result Result 0 { info!( - "Symlink tracking: {} symlinks processed, total tracked size: {} bytes", - symlink_count, symlink_size + event = EVENT_CAPACITY_SCAN_SYMLINK_SUMMARY, + component = LOG_COMPONENT_CAPACITY, + subsystem = LOG_SUBSYSTEM_SCAN, + result = "observed", + symlink_count, + tracked_bytes = symlink_size, + "capacity scan symlink summary" ); } @@ -587,8 +730,19 @@ async fn get_dir_size_async(path: &Path) -> Result Result Result Result Ok(output) => Ok(output), Err(err) if options.zstd_fallback_to_gzip => { warn!( + event = EVENT_LOG_CLEANER_COMPRESSION_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?path, error = %err, - "zstd compression failed, fallback to gzip" + result = "zstd_failed_fallback_gzip", + "log cleaner compression state changed" ); compress_gzip(path, options.gzip_level, options.dry_run) } @@ -127,7 +135,7 @@ where // Keep idempotent behavior: existing archive means this file has already // been handled in a previous cleanup pass. if archive_path.exists() { - debug!(file = ?archive_path, "compressed archive already exists, skipping"); + debug!(event = EVENT_LOG_CLEANER_COMPRESSION_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?archive_path, state = "archive_exists", "log cleaner compression state changed"); let input_bytes = std::fs::metadata(path).map(|m| m.len()).unwrap_or(0); let output_bytes = std::fs::metadata(archive_path).map(|m| m.len()).unwrap_or(0); return Ok(CompressionOutput { @@ -140,7 +148,7 @@ where let input_bytes = std::fs::metadata(path).map(|m| m.len()).unwrap_or(0); if dry_run { - info!("[DRY RUN] Would compress file: {:?} -> {:?}", path, archive_path); + info!(event = EVENT_LOG_CLEANER_COMPRESSION_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "dry_run_compress", file = ?path, archive = ?archive_path, input_bytes, "log cleaner compression state changed"); return Ok(CompressionOutput { archive_path: archive_path.to_path_buf(), algorithm_used, @@ -185,12 +193,16 @@ where let output_bytes = std::fs::metadata(archive_path).map(|m| m.len()).unwrap_or(0); debug!( + event = EVENT_LOG_CLEANER_COMPRESSION_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?path, archive = ?archive_path, input_bytes, output_bytes, algorithm = %algorithm_used, - "compression finished" + state = "compression_finished", + "log cleaner compression state changed" ); Ok(CompressionOutput { diff --git a/crates/obs/src/cleaner/core.rs b/crates/obs/src/cleaner/core.rs index 13aead31f..f6707419c 100644 --- a/crates/obs/src/cleaner/core.rs +++ b/crates/obs/src/cleaner/core.rs @@ -37,6 +37,10 @@ use std::sync::atomic::{AtomicU64, Ordering}; use std::time::{Duration, Instant, SystemTime}; use tracing::{debug, error, info, warn}; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_LOG_CLEANER: &str = "log_cleaner"; +const EVENT_LOG_CLEANER_STATE: &str = "log_cleaner_state"; + #[derive(Debug)] struct CompressionTaskResult { /// Original file metadata so successful workers can be deleted later. @@ -108,7 +112,14 @@ impl LogCleaner { /// Perform one full cleanup pass. pub fn cleanup(&self) -> Result<(usize, u64), std::io::Error> { if !self.log_dir.exists() { - debug!("Log directory does not exist: {:?}", self.log_dir); + debug!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, + state = "log_dir_missing", + log_dir = ?self.log_dir, + "log cleaner state changed" + ); return Ok((0, 0)); } @@ -134,10 +145,14 @@ impl LogCleaner { let total_size: u64 = logs.iter().map(|f| f.size).sum(); info!( - "Found {} regular log files, total size: {} bytes ({:.2} MB)", - logs.len(), - total_size, - total_size as f64 / 1024.0 / 1024.0 + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, + state = "scan_completed", + regular_log_files = logs.len(), + total_bytes = total_size, + total_megabytes = total_size as f64 / 1024.0 / 1024.0, + "log cleaner state changed" ); // Select the oldest files first, then additionally trim any files @@ -167,10 +182,14 @@ impl LogCleaner { counter!(METRIC_LOG_CLEANER_DELETED_FILES_TOTAL).increment(total_deleted as u64); counter!(METRIC_LOG_CLEANER_FREED_BYTES_TOTAL).increment(total_freed); info!( - "Cleanup completed: deleted {} files, freed {} bytes ({:.2} MB)", - total_deleted, - total_freed, - total_freed as f64 / 1024.0 / 1024.0 + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, + state = "cleanup_completed", + deleted_files = total_deleted, + freed_bytes = total_freed, + freed_megabytes = total_freed as f64 / 1024.0 / 1024.0, + "log cleaner state changed" ); } @@ -324,17 +343,21 @@ impl LogCleaner { let compressed = match compress_file(&file.path, &options) { Ok(output) => { debug!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?file.path, archive = ?output.archive_path, algorithm = %output.algorithm_used, input_bytes = output.input_bytes, output_bytes = output.output_bytes, - "parallel compression done" + state = "parallel_compression_done", + "log cleaner state changed" ); true } Err(err) => { - warn!(file = ?file.path, error = %err, "parallel compression failed"); + warn!(event = EVENT_LOG_CLEANER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?file.path, error = %err, result = "parallel_compression_failed", "log cleaner state changed"); false } }; @@ -350,7 +373,14 @@ impl LogCleaner { // Any worker panic triggers deterministic fallback behavior. if scope_result.is_err() { - warn!("parallel compression worker panicked, falling back to serial path"); + warn!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, + result = "parallel_worker_panicked", + fallback = "serial", + "log cleaner state changed" + ); return self.serial_compress_and_delete(files); } @@ -376,6 +406,9 @@ impl LogCleaner { gauge!(METRIC_LOG_CLEANER_STEAL_SUCCESS_RATE).set(success_rate); info!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, workers = worker_count, algorithm = %self.compression_algorithm, deleted, @@ -384,7 +417,8 @@ impl LogCleaner { steal_attempts = attempts, steal_successes = successes, steal_success_rate = success_rate, - "parallel cleanup finished" + state = "parallel_cleanup_finished", + "log cleaner state changed" ); Ok((deleted, freed)) @@ -441,17 +475,21 @@ impl LogCleaner { match compress_file(&file.path, &options) { Ok(output) => { debug!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?file.path, archive = ?output.archive_path, algorithm = %output.algorithm_used, input_bytes = output.input_bytes, output_bytes = output.output_bytes, - "serial compression done" + state = "serial_compression_done", + "log cleaner state changed" ); deletable.push(file.clone()); } Err(err) => { - warn!(file = ?file.path, error = %err, "serial compression failed, source kept"); + warn!(event = EVENT_LOG_CLEANER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, file = ?file.path, error = %err, result = "serial_compression_failed", "log cleaner state changed"); } } } @@ -523,7 +561,7 @@ impl LogCleaner { for f in files { if self.dry_run { - info!("[DRY RUN] Would delete: {:?} ({} bytes)", f.path, f.size); + info!(event = EVENT_LOG_CLEANER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "dry_run_delete", file = ?f.path, bytes = f.size, "log cleaner state changed"); deleted += 1; freed += f.size; continue; @@ -533,10 +571,10 @@ impl LogCleaner { Ok(()) => { deleted += 1; freed += f.size; - debug!("Deleted: {:?}", f.path); + debug!(event = EVENT_LOG_CLEANER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "deleted", file = ?f.path, bytes = f.size, "log cleaner state changed"); } Err(e) => { - error!("Failed to delete {:?}: {}", f.path, e); + error!(event = EVENT_LOG_CLEANER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, result = "delete_failed", file = ?f.path, error = %e, "log cleaner state changed"); } } } diff --git a/crates/obs/src/cleaner/scanner.rs b/crates/obs/src/cleaner/scanner.rs index 3a7f76e9f..b48c1de40 100644 --- a/crates/obs/src/cleaner/scanner.rs +++ b/crates/obs/src/cleaner/scanner.rs @@ -30,6 +30,10 @@ use std::path::Path; use std::time::SystemTime; use tracing::debug; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_LOG_CLEANER: &str = "log_cleaner"; +const EVENT_LOG_CLEANER_SCAN_STATE: &str = "log_cleaner_scan_state"; + /// Result of a single pass directory scan. /// /// Separating regular logs from compressed archives keeps the selection logic @@ -125,7 +129,7 @@ pub(super) fn scan_log_directory( // 2. Check exclusion patterns early. if is_excluded(filename, exclude_patterns) { - debug!("Excluding file from cleanup: {:?}", filename); + debug!(event = EVENT_LOG_CLEANER_SCAN_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "excluded", filename = %filename, "log cleaner scan state changed"); continue; } @@ -171,12 +175,12 @@ pub(super) fn scan_log_directory( if !is_compressed && file_size == 0 && delete_empty_files { if !dry_run { if let Err(e) = fs::remove_file(&path) { - tracing::warn!("Failed to delete empty file {:?}: {}", path, e); + tracing::warn!(event = EVENT_LOG_CLEANER_SCAN_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, result = "empty_file_delete_failed", path = ?path, error = %e, "log cleaner scan state changed"); } else { - debug!("Deleted empty file: {:?}", path); + debug!(event = EVENT_LOG_CLEANER_SCAN_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "empty_file_deleted", path = ?path, "log cleaner scan state changed"); } } else { - tracing::info!("[DRY RUN] Would delete empty file: {:?}", path); + tracing::info!(event = EVENT_LOG_CLEANER_SCAN_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_LOG_CLEANER, state = "dry_run_empty_file_delete", path = ?path, "log cleaner scan state changed"); } continue; } diff --git a/crates/obs/src/global.rs b/crates/obs/src/global.rs index b40769442..f567c2529 100644 --- a/crates/obs/src/global.rs +++ b/crates/obs/src/global.rs @@ -17,6 +17,10 @@ use std::sync::{Arc, Mutex}; use tokio::sync::OnceCell; use tracing::{info, warn}; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_GLOBAL: &str = "global"; +const EVENT_OBS_GLOBAL_STATE: &str = "obs_global_state"; + /// Global guard for OpenTelemetry tracing static GLOBAL_GUARD: OnceCell>> = OnceCell::const_new(); @@ -50,9 +54,13 @@ pub(crate) fn set_observability_metric_enabled(enabled: bool) { && *current != enabled { warn!( + event = EVENT_OBS_GLOBAL_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GLOBAL, current = *current, requested = enabled, - "OBSERVABILITY_METRIC_ENABLED was already initialized; keeping original value" + result = "metrics_flag_already_initialized", + "obs global state changed" ); } } @@ -143,7 +151,13 @@ pub async fn init_obs_with_config(config: &OtelConfig) -> Result Result<(), GlobalError> { - info!("Initializing global guard"); + info!( + event = EVENT_OBS_GLOBAL_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GLOBAL, + state = "guard_initializing", + "obs global state changed" + ); GLOBAL_GUARD.set(Arc::new(Mutex::new(guard))).map_err(GlobalError::SetError) } diff --git a/crates/obs/src/logging.rs b/crates/obs/src/logging.rs index 4c683474e..937367f02 100644 --- a/crates/obs/src/logging.rs +++ b/crates/obs/src/logging.rs @@ -13,7 +13,7 @@ // limitations under the License. use rustfs_security_governance::{RedactionLevel, RedactionPolicyError, RedactionRule, validate_redaction_rules}; -use std::fmt; +pub use rustfs_utils::MaskedAccessKey; pub const REDACTED_LOG_VALUE: &str = "***redacted***"; @@ -56,41 +56,6 @@ pub fn redacted_optional_log_value(value: Option<&str>) -> Option<&'static str> value.map(redacted_log_value) } -#[derive(Clone, Copy)] -pub struct MaskedAccessKey<'a>(pub &'a str); - -impl fmt::Display for MaskedAccessKey<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let value = self.0; - if value.is_empty() { - return Ok(()); - } - - let chars: Vec = value.chars().collect(); - match chars.len() { - 0 => Ok(()), - 1..=4 => f.write_str("***"), - 5..=8 => write!(f, "{}***{}", chars[0], chars[chars.len() - 1]), - len => { - for ch in &chars[..4] { - write!(f, "{ch}")?; - } - f.write_str("***")?; - for ch in &chars[len - 4..] { - write!(f, "{ch}")?; - } - Ok(()) - } - } - } -} - -impl fmt::Debug for MaskedAccessKey<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - fmt::Display::fmt(self, f) - } -} - #[cfg(test)] mod tests { use super::*; diff --git a/crates/obs/src/metrics/collectors/system_gpu.rs b/crates/obs/src/metrics/collectors/system_gpu.rs index 183d48a1b..22d06420f 100644 --- a/crates/obs/src/metrics/collectors/system_gpu.rs +++ b/crates/obs/src/metrics/collectors/system_gpu.rs @@ -47,6 +47,10 @@ use thiserror::Error; use tracing::warn; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_GPU_METRICS: &str = "gpu_metrics"; +const EVENT_GPU_METRICS_STATE: &str = "gpu_metrics_state"; + /// GPU statistics. /// /// Contains GPU memory usage metrics for the monitored process. @@ -138,7 +142,14 @@ impl GpuCollector { } } } else { - warn!("Could not get GPU stats, recording 0 for GPU memory usage"); + warn!( + event = EVENT_GPU_METRICS_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GPU_METRICS, + result = "process_stats_unavailable", + fallback_memory_usage = 0, + "gpu metrics state changed" + ); } } else { return Err(GpuError::DeviceError("No GPU device found".to_string())); diff --git a/crates/obs/src/metrics/scheduler.rs b/crates/obs/src/metrics/scheduler.rs index 507c43485..5c5a4afac 100644 --- a/crates/obs/src/metrics/scheduler.rs +++ b/crates/obs/src/metrics/scheduler.rs @@ -94,6 +94,10 @@ use tokio::time::Instant; use tokio_util::sync::CancellationToken; use tracing::warn; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_METRICS_RUNTIME: &str = "metrics_runtime"; +const EVENT_METRICS_RUNTIME_STATE: &str = "metrics_runtime_state"; + /// Default interval for system monitoring metrics (15 seconds) const DEFAULT_SYSTEM_METRICS_INTERVAL: Duration = Duration::from_secs(15); /// Environment variable for system monitoring interval @@ -497,7 +501,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { report_metrics(&metrics); } _ = token_clone.cancelled() => { - warn!("Metrics collection for cluster stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "cluster_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -537,7 +541,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { } } _ = token_clone.cancelled() => { - warn!("Metrics collection for supplementary cluster stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "supplementary_cluster_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -556,7 +560,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { report_metrics(&metrics); } _ = token_clone.cancelled() => { - warn!("Metrics collection for bucket stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "bucket_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -577,7 +581,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { report_metrics(&metrics); } _ = token_clone.cancelled() => { - warn!("Metrics collection for node/disk stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "node_disk_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -601,7 +605,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { let current_live_keys = repl_bw_live_keys(&stats); if !monitor_available { - warn!("Bucket monitor unavailable; skip replication bandwidth key-state transition this cycle."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "bucket_replication_bandwidth", result = "bucket_monitor_unavailable", "metrics runtime state changed"); } update_repl_bw_zero_tombstones( monitor_available, @@ -626,7 +630,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { expire_repl_bw_zero_tombstones(monitor_available, &mut zero_tombstones); } _ = token_clone.cancelled() => { - warn!("Metrics collection for bucket replication bandwidth stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "bucket_replication_bandwidth", state = "cancelled", "metrics runtime state changed"); return; } } @@ -653,7 +657,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { report_metrics(&metrics); } _ = token_clone.cancelled() => { - warn!("Metrics collection for audit target stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "audit_target_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -689,7 +693,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { report_metrics(&metrics); } _ = token_clone.cancelled() => { - warn!("Metrics collection for notification stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "notification_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -718,7 +722,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { } } _ = token_clone.cancelled() => { - warn!("Metrics collection for background workflow stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "background_workflow_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -742,7 +746,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { let current_pid = match sysinfo::get_current_pid() { Ok(pid) => Some(pid), Err(e) => { - warn!("Failed to get current PID for system monitoring: {}", e); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "system_monitoring", result = "current_pid_unavailable", error = %e, "metrics runtime state changed"); None } }; @@ -776,11 +780,11 @@ pub fn init_metrics_runtime(token: CancellationToken) { metrics.extend(collect_gpu_metrics(&gpu_stats, &labels)); } Err(e) => { - warn!("GPU metrics collection failed: {}", e); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "gpu_metrics", result = "collect_failed", error = %e, "metrics runtime state changed"); } }, Err(e) => { - warn!("GPU collector initialization failed: {}", e); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "gpu_metrics", result = "collector_init_failed", error = %e, "metrics runtime state changed"); } } } @@ -790,7 +794,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { } } _ = token_clone.cancelled() => { - warn!("Process metrics collection cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "process_metrics", state = "cancelled", "metrics runtime state changed"); return; } } @@ -812,7 +816,7 @@ pub fn init_metrics_runtime(token: CancellationToken) { } } _ = token_clone.cancelled() => { - warn!("Metrics collection for internode network stats cancelled."); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "internode_network_stats", state = "cancelled", "metrics runtime state changed"); return; } } @@ -865,7 +869,7 @@ fn current_process_metric_labels() -> Vec<(&'static str, Cow<'static, str>)> { } fn fallback_process_metric_labels(err: ProcessAttributeError) -> Vec<(&'static str, Cow<'static, str>)> { - warn!("Failed to collect process attributes for metrics labels: {}", err); + warn!(event = EVENT_METRICS_RUNTIME_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_RUNTIME, collector = "process_metric_labels", result = "collect_failed", error = %err, "metrics runtime state changed"); vec![ ("process_pid", Cow::Owned(std::process::id().to_string())), ("process_executable_name", Cow::Borrowed("unknown")), diff --git a/crates/obs/src/metrics/stats_collector.rs b/crates/obs/src/metrics/stats_collector.rs index ee34cec6d..679262c66 100644 --- a/crates/obs/src/metrics/stats_collector.rs +++ b/crates/obs/src/metrics/stats_collector.rs @@ -46,6 +46,10 @@ use std::time::Duration; use sysinfo::{Networks, System}; use tracing::{instrument, warn}; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_METRICS_COLLECTOR: &str = "metrics_collector"; +const EVENT_METRICS_COLLECTOR_STATE: &str = "metrics_collector_state"; + fn current_scanner_cycle_age_seconds( current_cycle: u64, current_started: chrono::DateTime, @@ -178,7 +182,7 @@ pub async fn collect_cluster_and_health_stats() -> (ClusterStats, ClusterHealthS let (buckets_count, objects_count) = match load_data_usage_from_backend(store.clone()).await { Ok(data_usage) => (data_usage.buckets_count, data_usage.objects_total_count), Err(e) => { - warn!("Failed to load data usage from backend: {}", e); + warn!(event = EVENT_METRICS_COLLECTOR_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_COLLECTOR, collector = "cluster_stats", result = "data_usage_load_failed", error = %e, "metrics collector state changed"); // Fall back to bucket list for buckets_count, objects_count stays 0. let buckets = store .list_bucket(&BucketOptions { @@ -187,7 +191,7 @@ pub async fn collect_cluster_and_health_stats() -> (ClusterStats, ClusterHealthS }) .await .unwrap_or_else(|err| { - warn!("Failed to list buckets for cluster metrics: {}", err); + warn!(event = EVENT_METRICS_COLLECTOR_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_COLLECTOR, collector = "cluster_stats", result = "bucket_list_failed", error = %err, "metrics collector state changed"); Vec::new() }); (buckets.len() as u64, 0) @@ -246,7 +250,7 @@ pub async fn collect_bucket_stats() -> Vec { let data_usage = match load_data_usage_from_backend(store.clone()).await { Ok(info) => Some(info), Err(e) => { - warn!("Failed to load data usage for bucket metrics: {}", e); + warn!(event = EVENT_METRICS_COLLECTOR_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_COLLECTOR, collector = "bucket_stats", result = "data_usage_load_failed", error = %e, "metrics collector state changed"); None } }; @@ -261,7 +265,7 @@ pub async fn collect_bucket_stats() -> Vec { { Ok(buckets) => buckets, Err(e) => { - warn!("Failed to list buckets for bucket metrics: {}", e); + warn!(event = EVENT_METRICS_COLLECTOR_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_METRICS_COLLECTOR, collector = "bucket_stats", result = "bucket_list_failed", error = %e, "metrics collector state changed"); return Vec::new(); } }; @@ -310,10 +314,7 @@ pub fn collect_bucket_replication_bandwidth_stats() -> Vec Result, TelemetryError> { if !config.enabled { - info!("Dial9 telemetry disabled"); + info!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + state = "disabled", + "dial9 state changed" + ); return Ok(None); } info!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + state = "validating", output_dir = %config.output_dir, file_prefix = %config.file_prefix, sampling_rate = config.sampling_rate, - "Validating dial9 telemetry configuration" + "dial9 state changed" ); // Only create directory; writer will be created in build_traced_runtime if let Err(e) = tokio::fs::create_dir_all(&config.output_dir).await { - warn!("Failed to create dial9 output directory '{}': {}", config.output_dir, e); - warn!("Continuing without dial9 telemetry"); + warn!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + result = "output_dir_create_failed", + output_dir = %config.output_dir, + error = %e, + fallback = "disabled", + "dial9 state changed" + ); return Ok(None); } - info!("Dial9 telemetry configuration validated successfully"); + info!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + state = "validated", + output_dir = %config.output_dir, + file_prefix = %config.file_prefix, + "dial9 state changed" + ); Ok(Some(Self { _guard: None, config })) } @@ -168,7 +198,13 @@ impl Dial9SessionGuard { /// Flush any pending telemetry data. pub async fn shutdown(&self) { if let Some(_guard) = &self._guard { - info!("Dial9 telemetry data will be flushed on drop"); + info!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + state = "shutdown_requested", + "dial9 state changed" + ); // TelemetryGuard handles flushing automatically when dropped } } @@ -178,7 +214,13 @@ impl Drop for Dial9SessionGuard { fn drop(&mut self) { if let Some(_guard) = &self._guard { // TelemetryGuard flushes automatically when dropped - info!("Dial9 telemetry guard dropped, data flushed"); + info!( + event = EVENT_DIAL9_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_DIAL9, + state = "flushed", + "dial9 state changed" + ); } } } diff --git a/crates/obs/src/telemetry/local.rs b/crates/obs/src/telemetry/local.rs index 2fab5e220..2c4198b65 100644 --- a/crates/obs/src/telemetry/local.rs +++ b/crates/obs/src/telemetry/local.rs @@ -60,6 +60,11 @@ use tracing_subscriber::{ util::SubscriberInitExt, }; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_LOCAL_LOGGING: &str = "local_logging"; +const EVENT_LOCAL_LOGGING_STATE: &str = "local_logging_state"; +const EVENT_LOG_CLEANER_STATE: &str = "log_cleaner_state"; + pub(super) fn build_json_log_layer(writer: W, enable_ansi: bool, span_events: FmtSpan) -> impl tracing_subscriber::Layer where S: Subscriber + for<'span> LookupSpan<'span>, @@ -161,12 +166,16 @@ fn init_stdout_only(_config: &OtelConfig, logger_level: &str, is_production: boo set_observability_metric_enabled(false); counter!("rustfs_start_total").increment(1); info!( + event = EVENT_LOCAL_LOGGING_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + state = "initialized", backend = "local", sink = "stdout", output_format = "json", logger_level, is_production, - "Initialized local logging" + "local logging state changed" ); OtelGuard { @@ -271,6 +280,10 @@ fn init_file_logging_internal( let cleanup_handle = spawn_cleanup_task(config, log_directory, log_filename, keep_files); info!( + event = EVENT_LOCAL_LOGGING_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + state = "initialized", backend = "local", sink = "file", output_format = "json", @@ -280,7 +293,7 @@ fn init_file_logging_internal( stdout_mirror_enabled = stdout_guard.is_some(), is_production, logger_level, - "Initialized local logging" + "local logging state changed" ); Ok(OtelGuard { @@ -459,13 +472,17 @@ pub fn spawn_cleanup_task( ); info!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + state = "configured", compression_algorithm = %compression_algorithm, parallel_compress, parallel_workers, zstd_level, zstd_fallback_to_gzip, zstd_workers, - "log cleaner compression profile configured" + "log cleaner state changed" ); tokio::spawn(async move { @@ -483,11 +500,25 @@ pub fn spawn_cleanup_task( } Ok(Err(e)) => { counter!(METRIC_LOG_CLEANER_RUN_FAILURES_TOTAL).increment(1); - tracing::warn!("Log cleanup failed: {}", e); + tracing::warn!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + result = "cleanup_failed", + error = %e, + "log cleaner state changed" + ); } Err(e) => { counter!(METRIC_LOG_CLEANER_RUN_FAILURES_TOTAL).increment(1); - tracing::warn!("Log cleanup task panicked: {}", e); + tracing::warn!( + event = EVENT_LOG_CLEANER_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + result = "cleanup_task_panicked", + error = %e, + "log cleaner state changed" + ); } } } diff --git a/crates/obs/src/telemetry/recorder.rs b/crates/obs/src/telemetry/recorder.rs index ffeaa945c..9c0b3e30e 100644 --- a/crates/obs/src/telemetry/recorder.rs +++ b/crates/obs/src/telemetry/recorder.rs @@ -30,6 +30,10 @@ use std::{ }; use tracing::error; +const LOG_COMPONENT_OBS: &str = "obs"; +const LOG_SUBSYSTEM_RECORDER: &str = "recorder"; +const EVENT_RECORDER_STATE: &str = "recorder_state"; + macro_rules! configure_builder { ($builder:expr, $metadata:expr) => {{ let mut builder = $builder; @@ -151,7 +155,7 @@ impl Recorder { let cache = match lock.read() { Ok(g) => g, Err(e) => { - error!("{} cache read lock poisoned: {}", metric_type, e); + error!(event = EVENT_RECORDER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_RECORDER, metric_type = %metric_type, result = "cache_read_lock_poisoned", error = %e, "recorder state changed"); e.into_inner() } }; @@ -162,7 +166,7 @@ impl Recorder { let mut cache = match lock.write() { Ok(g) => g, Err(e) => { - error!("{} cache write lock poisoned: {}", metric_type, e); + error!(event = EVENT_RECORDER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_RECORDER, metric_type = %metric_type, result = "cache_write_lock_poisoned", error = %e, "recorder state changed"); e.into_inner() } }; @@ -179,7 +183,7 @@ impl Recorder { F: FnOnce(&mut HashMap) -> R, { let mut guard = self.metrics_metadata.lock().unwrap_or_else(|e| { - error!("metrics_metadata lock poisoned: {}", e); + error!(event = EVENT_RECORDER_STATE, component = LOG_COMPONENT_OBS, subsystem = LOG_SUBSYSTEM_RECORDER, result = "metrics_metadata_lock_poisoned", error = %e, "recorder state changed"); e.into_inner() }); f(&mut guard) diff --git a/crates/protocols/src/common/gateway.rs b/crates/protocols/src/common/gateway.rs index bb9e49757..5a7f13266 100644 --- a/crates/protocols/src/common/gateway.rs +++ b/crates/protocols/src/common/gateway.rs @@ -274,7 +274,17 @@ pub async fn is_authorized( let iam_sys = match rustfs_iam::get() { Ok(sys) => sys, Err(e) => { - error!("IAM system unavailable: {}", e); + error!( + event = "protocol_gateway_authz_state", + component = "protocols", + subsystem = "gateway", + result = "iam_unavailable", + action = action.as_str(), + bucket = %bucket, + object = %object.unwrap_or_default(), + error = %e, + "protocol gateway authz state changed" + ); return Err(AuthorizationError::IamUnavailable); } }; diff --git a/crates/protocols/src/ftps/driver.rs b/crates/protocols/src/ftps/driver.rs index 3ca01b348..bd6fc6ae7 100644 --- a/crates/protocols/src/ftps/driver.rs +++ b/crates/protocols/src/ftps/driver.rs @@ -17,6 +17,7 @@ use crate::common::gateway::S3Action; use crate::common::gateway::authorize_operation; use async_trait::async_trait; use futures_util::stream; +use rustfs_utils::MaskedAccessKey; use rustfs_utils::path; use s3s::dto::*; use std::fmt::Debug; @@ -25,6 +26,19 @@ use tokio::io::AsyncRead; use tracing::{debug, error}; use unftp_core::storage::{Error, ErrorKind, Fileinfo, Metadata, Result, StorageBackend}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_FTPS_DRIVER: &str = "ftps_driver"; +const EVENT_FTPS_BUCKET_DELETE_FAILED: &str = "ftps_bucket_delete_failed"; +const EVENT_FTPS_METADATA_FAILED: &str = "ftps_metadata_failed"; +const EVENT_FTPS_LIST_FAILED: &str = "ftps_list_failed"; +const EVENT_FTPS_STREAM_READ_FAILED: &str = "ftps_stream_read_failed"; +const EVENT_FTPS_OBJECT_GET_FAILED: &str = "ftps_object_get_failed"; +const EVENT_FTPS_OBJECT_PUT_FAILED: &str = "ftps_object_put_failed"; +const EVENT_FTPS_OBJECT_DELETE_STATE: &str = "ftps_object_delete_state"; +const EVENT_FTPS_DIRECTORY_STATE: &str = "ftps_directory_state"; +const EVENT_FTPS_CWD_FAILED: &str = "ftps_cwd_failed"; +const EVENT_FTPS_RENAME_STATE: &str = "ftps_rename_state"; + /// FTPS metadata implementation #[derive(Debug, Clone)] pub struct FtpsMetadata { @@ -210,7 +224,14 @@ where Ok(_) => Ok(()), Err(e) if e.to_string().contains("NoSuchBucket") => Ok(()), Err(e) => { - error!("Failed to delete bucket '{}': {}", bucket, e); + error!( + event = EVENT_FTPS_BUCKET_DELETE_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + bucket = %bucket, + error = %e, + "ftps bucket delete failed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("Delete bucket failed: {}", e))) } } @@ -263,7 +284,16 @@ where }) } Err(e) => { - error!("Failed to get metadata for '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_METADATA_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + path = %path_str, + bucket = %bucket, + object = %key, + error = %e, + "ftps metadata failed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("{}: {}", "Metadata failed", e))) } } @@ -290,7 +320,15 @@ where is_dir: true, }), Err(e) => { - error!("Failed to get bucket metadata for '{}': {}", bucket_clone, e); + error!( + event = EVENT_FTPS_METADATA_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + path = %path_str, + bucket = %bucket_clone, + error = %e, + "ftps metadata failed" + ); Err(Error::new( ErrorKind::PermanentFileNotAvailable, format!("{}: {}", "Bucket metadata failed", e), @@ -423,7 +461,15 @@ where Ok(fileinfos) } Err(e) => { - error!("Failed to list '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_LIST_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + path = %path_str, + bucket = %prefix_with_slash.unwrap_or_default(), + error = %e, + "ftps list failed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("{}: {}", "List failed", e))) } } @@ -437,6 +483,7 @@ where ) -> Result> { let path_str = path.as_ref().to_string_lossy(); let session_context = &user.session_context; + let masked_username = MaskedAccessKey(&user.username); let (bucket, key) = self .parse_s3_path(&path_str) @@ -472,7 +519,17 @@ where match chunk_result { Ok(bytes) => data.extend_from_slice(&bytes), Err(e) => { - error!("Error reading stream: {}", e); + error!( + event = EVENT_FTPS_STREAM_READ_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + username = %masked_username, + path = %path_str, + bucket = %bucket, + object = %key, + error = %e, + "ftps stream read failed" + ); return Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("Stream error: {}", e))); } } @@ -481,7 +538,18 @@ where Ok(Box::new(std::io::Cursor::new(data))) } Err(e) => { - error!("Failed to get '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_OBJECT_GET_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + username = %masked_username, + path = %path_str, + bucket = %bucket, + object = %key, + start_pos, + error = %e, + "ftps object get failed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("{}: {}", "Get failed", e))) } } @@ -496,6 +564,7 @@ where ) -> Result { let path_str = path.as_ref().to_string_lossy(); let session_context = &user.session_context; + let masked_username = MaskedAccessKey(&user.username); let (bucket, key) = self .parse_s3_path(&path_str) @@ -555,7 +624,18 @@ where Ok(file_size as u64) // Return the size of the uploaded object } Err(e) => { - error!("FTPS put - S3 error details: {:?}", e); + error!( + event = EVENT_FTPS_OBJECT_PUT_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + username = %masked_username, + path = %path_str, + bucket = %bucket, + object = %key, + file_size, + error = ?e, + "ftps object put failed" + ); Err(Error::new( ErrorKind::PermanentFileNotAvailable, format!("Failed to upload object: {:?}", e), @@ -567,7 +647,16 @@ where async fn del + Send>(&self, user: &super::server::FtpsUser, path: P) -> Result<()> { let path_str = path.as_ref().to_string_lossy(); let session_context = &user.session_context; - debug!("FTPS delete request for user '{}' path '{}'", user.username, path_str); + let masked_username = MaskedAccessKey(&user.username); + debug!( + event = EVENT_FTPS_OBJECT_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "requested", + username = %masked_username, + path = %path_str, + "ftps object delete state changed" + ); let (bucket, key) = self .parse_s3_path(&path_str) @@ -592,7 +681,18 @@ where { Ok(_) => Ok(()), Err(e) => { - error!("Failed to delete file '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_OBJECT_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "delete_failed", + username = %masked_username, + path = %path_str, + bucket = %bucket, + object = %key, + error = %e, + "ftps object delete state changed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("Delete failed: {}", e))) } } @@ -615,7 +715,16 @@ where async fn mkd + Send>(&self, user: &super::server::FtpsUser, path: P) -> Result<()> { let path_str = path.as_ref().to_string_lossy(); let session_context = &user.session_context; - debug!("FTPS mkdir request for user '{}' path '{}'", user.username, path_str); + let masked_username = MaskedAccessKey(&user.username); + debug!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "create_requested", + username = %masked_username, + path = %path_str, + "ftps directory state changed" + ); let (bucket, _key) = self .parse_s3_path(&path_str) @@ -632,11 +741,30 @@ where .await { Ok(_) => { - debug!("Successfully created directory/bucket '{}'", path_str); + debug!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "created", + username = %masked_username, + path = %path_str, + bucket = %bucket, + "ftps directory state changed" + ); Ok(()) } Err(e) => { - error!("Failed to create directory/bucket '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "create_failed", + username = %masked_username, + path = %path_str, + bucket = %bucket, + error = %e, + "ftps directory state changed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("Mkdir failed: {}", e))) } } @@ -658,17 +786,41 @@ where // Try to delete bucket recursively match self.delete_bucket_recursively(&bucket, session_context).await { Ok(_) => { - debug!("Successfully removed directory/bucket '{}'", path_str); + debug!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "removed", + path = %path_str, + bucket = %bucket, + "ftps directory state changed" + ); Ok(()) } Err(e) => { // Check if error is NoSuchBucket - treat as success (idempotent) let error_msg = e.to_string(); if error_msg.contains("NoSuchBucket") || error_msg.contains("does not exist") { - debug!("Bucket '{}' already deleted", bucket); + debug!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "already_removed", + bucket = %bucket, + "ftps directory state changed" + ); Ok(()) } else { - error!("Failed to remove directory/bucket '{}': {}", path_str, e); + error!( + event = EVENT_FTPS_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "remove_failed", + path = %path_str, + bucket = %bucket, + error = %e, + "ftps directory state changed" + ); Err(e) } } @@ -700,7 +852,15 @@ where { Ok(_) => Ok(()), Err(e) => { - error!("CWD to '{}' failed: {}", path_str, e); + error!( + event = EVENT_FTPS_CWD_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + path = %path_str, + bucket = %bucket, + error = %e, + "ftps cwd failed" + ); Err(Error::new(ErrorKind::PermanentFileNotAvailable, format!("CWD failed: {}", e))) } } @@ -709,7 +869,16 @@ where async fn rename + Send>(&self, user: &super::server::FtpsUser, from: P, to: P) -> Result<()> { let from_str = from.as_ref().to_string_lossy(); let to_str = to.as_ref().to_string_lossy(); - debug!("FTPS rename request for user '{}' from '{}' to '{}'", user.username, from_str, to_str); + debug!( + event = EVENT_FTPS_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_DRIVER, + state = "unsupported", + username = %MaskedAccessKey(&user.username), + from = %from_str, + to = %to_str, + "ftps rename state changed" + ); Err(Error::new( ErrorKind::CommandNotImplemented, diff --git a/crates/protocols/src/ftps/server.rs b/crates/protocols/src/ftps/server.rs index 09d9a7c17..893aaa061 100644 --- a/crates/protocols/src/ftps/server.rs +++ b/crates/protocols/src/ftps/server.rs @@ -20,6 +20,7 @@ use crate::constants::{network::DEFAULT_SOURCE_IP, paths::ROOT_PATH}; use libunftp::options::FtpsRequired; use rustfs_config::{DEFAULT_TLS_RELOAD_ENABLE, DEFAULT_TLS_RELOAD_INTERVAL, ENV_TLS_RELOAD_ENABLE, ENV_TLS_RELOAD_INTERVAL}; use rustfs_tls_runtime::{ReloadableServerCertResolver, TlsReloadOptions, spawn_server_cert_reload_loop}; +use rustfs_utils::MaskedAccessKey; use std::fmt::{Debug, Display, Formatter}; use std::net::IpAddr; use std::path::Path; @@ -32,6 +33,15 @@ use unftp_core::auth::{ AuthenticationError, Authenticator, Credentials, Principal, UserDetail, UserDetailError, UserDetailProvider, }; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_FTPS_SERVER: &str = "ftps_server"; +const LOG_SUBSYSTEM_FTPS_AUTH: &str = "ftps_auth"; +const EVENT_FTPS_SERVER_STATE: &str = "ftps_server_state"; +const EVENT_FTPS_TLS_STATE: &str = "ftps_tls_state"; +const EVENT_FTPS_CONFIG_STATE: &str = "ftps_config_state"; +const EVENT_FTPS_RUNTIME_STATE: &str = "ftps_runtime_state"; +const EVENT_FTPS_AUTH_STATE: &str = "ftps_auth_state"; + /// FTPS user implementation #[derive(Debug, Clone)] pub struct FtpsUser { @@ -89,7 +99,16 @@ where /// This method binds the listener first to ensure the port is available, /// then spawns the server loop in a background task. pub async fn start(&self, mut shutdown_rx: broadcast::Receiver<()>) -> Result<(), FtpsInitError> { - info!("Initializing FTPS server on {}", self.config.bind_addr); + info!( + event = EVENT_FTPS_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "starting", + bind_addr = %self.config.bind_addr, + tls_enabled = self.config.tls_enabled, + ftps_required = self.config.ftps_required, + "ftps server state changed" + ); let (reload_shutdown_tx, reload_shutdown_rx) = watch::channel(false); let storage_clone = self.storage.clone(); @@ -102,27 +121,62 @@ where // Configure passive ports for data connections if let Some(passive_ports) = &self.config.passive_ports { let range = self.config.parse_passive_ports()?; - info!("Configuring FTPS passive ports range: {:?} ({})", range, passive_ports); + info!( + event = EVENT_FTPS_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "passive_ports_configured", + passive_ports = %passive_ports, + passive_port_range = ?range, + "ftps config state changed" + ); server_builder = server_builder.passive_ports(range); } else { - warn!("No passive ports configured, using system-assigned ports"); + warn!( + event = EVENT_FTPS_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + result = "system_assigned_passive_ports", + "ftps config state changed" + ); } // Configure external IP address for passive mode if let Some(ref external_ip) = self.config.external_ip { - info!("Configuring FTPS external IP for passive mode: {}", external_ip); + info!( + event = EVENT_FTPS_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "external_ip_configured", + external_ip = %external_ip, + "ftps config state changed" + ); server_builder = server_builder.passive_host(external_ip.as_str()); } // Configure both active and passive mode support use libunftp::options::ActivePassiveMode; server_builder = server_builder.active_passive_mode(ActivePassiveMode::ActiveAndPassive); - info!("FTPS server configured for both active and passive mode support"); + info!( + event = EVENT_FTPS_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "active_passive_mode_enabled", + mode = "active_and_passive", + "ftps config state changed" + ); // Configure FTPS / TLS if self.config.tls_enabled { if let Some(cert_dir) = &self.config.cert_dir { - debug!("Enabling FTPS with multi-certificate support from directory: {}", cert_dir); + debug!( + event = EVENT_FTPS_TLS_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "enabled", + cert_dir = %cert_dir, + "ftps tls state changed" + ); let resolver = ReloadableServerCertResolver::load_from_directory(cert_dir) .map_err(|e| FtpsInitError::InvalidConfig(format!("Failed to create certificate resolver: {}", e)))?; @@ -143,7 +197,13 @@ where server_builder = server_builder.ftps_manual::(Arc::new(server_config)); if self.config.ftps_required { - info!("FTPS is explicitly required for all connections"); + info!( + event = EVENT_FTPS_TLS_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "required", + "ftps tls state changed" + ); server_builder = server_builder.ftps_required(FtpsRequired::All, FtpsRequired::All); } } else if self.config.ftps_required { @@ -152,7 +212,14 @@ where )); } } else { - info!("TLS disabled, running in plain FTP mode"); + info!( + event = EVENT_FTPS_TLS_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "disabled", + mode = "plain_ftp", + "ftps tls state changed" + ); } // Build the server instance @@ -162,7 +229,14 @@ where let bind_addr = self.config.bind_addr.to_string(); let server_handle = tokio::spawn(async move { if let Err(e) = server.listen(bind_addr).await { - error!("FTPS server runtime error: {}", e); + error!( + event = EVENT_FTPS_RUNTIME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + result = "runtime_error", + error = %e, + "ftps runtime state changed" + ); return Err(FtpsInitError::Server(e)); } Ok(()) @@ -174,21 +248,48 @@ where let _ = reload_shutdown_tx.send(true); match result { Ok(Ok(())) => { - info!("FTPS server stopped normally"); + info!( + event = EVENT_FTPS_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "stopped", + result = "ok", + "ftps server state changed" + ); Ok(()) } Ok(Err(e)) => { - error!("FTPS server internal error: {}", e); + error!( + event = EVENT_FTPS_RUNTIME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + result = "internal_error", + error = %e, + "ftps runtime state changed" + ); Err(e) } Err(e) => { - error!("FTPS server panic or task cancellation: {}", e); + error!( + event = EVENT_FTPS_RUNTIME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + result = "task_failed", + error = %e, + "ftps runtime state changed" + ); Err(FtpsInitError::Bind(std::io::Error::other(e.to_string()))) } } } _ = shutdown_rx.recv() => { - info!("FTPS server received shutdown signal"); + info!( + event = EVENT_FTPS_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_SERVER, + state = "shutdown_requested", + "ftps server state changed" + ); let _ = reload_shutdown_tx.send(true); // libunftp listen() is not easily cancellable gracefully without dropping the future. // The select! dropping server_handle will close the listener. @@ -218,20 +319,46 @@ impl UserDetailProvider for FtpsUserDetailProvider { async fn provide_user_detail(&self, principal: &Principal) -> Result { use rustfs_iam::get; + let masked_username = MaskedAccessKey(&principal.username); // Access IAM system let iam_sys = get().map_err(|e| { - error!("IAM system unavailable during FTPS user detail fetch: {}", e); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "iam_unavailable", + phase = "user_detail", + error = %e, + "ftps auth state changed" + ); UserDetailError::ImplPropagated("Internal authentication service unavailable".to_string(), Some(Box::new(e))) })?; let (user_identity, _is_valid) = iam_sys.check_key(&principal.username).await.map_err(|e| { - error!("IAM check_key failed for {}: {}", principal.username, e); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "check_key_failed", + phase = "user_detail", + username = %masked_username, + error = %e, + "ftps auth state changed" + ); UserDetailError::ImplPropagated("Authentication verification failed".to_string(), Some(Box::new(e))) })?; let identity = user_identity.ok_or_else(|| { - error!("User identity missing for {}", principal.username); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "identity_missing", + phase = "user_detail", + username = %masked_username, + "ftps auth state changed" + ); UserDetailError::UserNotFound { username: principal.username.clone(), } @@ -268,10 +395,19 @@ impl Authenticator for FtpsAuthenticator { async fn authenticate(&self, username: &str, creds: &Credentials) -> Result { use rustfs_credentials::Credentials as S3Credentials; use rustfs_iam::get; + let masked_username = MaskedAccessKey(username); // Access IAM system let iam_sys = get().map_err(|e| { - error!("IAM system unavailable during FTPS auth: {}", e); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "iam_unavailable", + phase = "authenticate", + error = %e, + "ftps auth state changed" + ); AuthenticationError::ImplPropagated("Internal authentication service unavailable".to_string(), Some(Box::new(e))) })?; @@ -289,26 +425,67 @@ impl Authenticator for FtpsAuthenticator { }; let (user_identity, is_valid) = iam_sys.check_key(&s3_creds.access_key).await.map_err(|e| { - error!("IAM check_key failed for {}: {}", username, e); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "check_key_failed", + phase = "authenticate", + username = %masked_username, + error = %e, + "ftps auth state changed" + ); AuthenticationError::ImplPropagated("Authentication verification failed".to_string(), Some(Box::new(e))) })?; if !is_valid { - warn!("FTPS login failed: Invalid access key '{}'", username); + warn!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "invalid_access_key", + phase = "authenticate", + username = %masked_username, + "ftps auth state changed" + ); return Err(AuthenticationError::BadUser); } let identity = user_identity.ok_or_else(|| { - error!("User identity missing despite valid key for {}", username); + error!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "identity_missing", + phase = "authenticate", + username = %masked_username, + "ftps auth state changed" + ); AuthenticationError::BadUser })?; if !identity.credentials.secret_key.eq(&s3_creds.secret_key) { - warn!("FTPS login failed: Invalid secret key for '{}'", username); + warn!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "invalid_secret_key", + phase = "authenticate", + username = %masked_username, + "ftps auth state changed" + ); return Err(AuthenticationError::BadPassword); } - info!("FTPS user '{}' authenticated successfully", username); + debug!( + event = EVENT_FTPS_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_FTPS_AUTH, + result = "authenticated", + phase = "authenticate", + username = %masked_username, + "ftps auth state changed" + ); Ok(Principal { username: username.to_string(), }) diff --git a/crates/protocols/src/sftp/config.rs b/crates/protocols/src/sftp/config.rs index dcb4b13d7..ccf603e56 100644 --- a/crates/protocols/src/sftp/config.rs +++ b/crates/protocols/src/sftp/config.rs @@ -36,6 +36,11 @@ use std::os::unix::fs::PermissionsExt; use std::path::{Path, PathBuf}; use thiserror::Error; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_CONFIG: &str = "sftp_config"; +const EVENT_SFTP_CONFIG_STATE: &str = "sftp_config_state"; +const EVENT_SFTP_HOST_KEY_STATE: &str = "sftp_host_key_state"; + /// Upper bound on file size accepted as a candidate host key (1 MiB). /// Guards against accidentally reading huge non-key files in the host /// key directory. Real keys are well under 10 KiB. @@ -203,11 +208,15 @@ impl SftpConfig { Some(n) if (HANDLES_PER_SESSION_MIN..=HANDLES_PER_SESSION_MAX).contains(&n) => Some(n), Some(n) => { tracing::warn!( + event = EVENT_SFTP_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, requested = n, min = HANDLES_PER_SESSION_MIN, max = HANDLES_PER_SESSION_MAX, default = DEFAULT_HANDLES_PER_SESSION, - "RUSTFS_SFTP_HANDLES_PER_SESSION out of range. Falling back to the default.", + result = "handles_per_session_out_of_range", + "sftp config state changed", ); None } @@ -227,11 +236,15 @@ impl SftpConfig { Some(n) if (BACKEND_OP_TIMEOUT_MIN_SECS..=BACKEND_OP_TIMEOUT_MAX_SECS).contains(&n) => Some(n), Some(n) => { tracing::warn!( + event = EVENT_SFTP_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, requested = n, min = BACKEND_OP_TIMEOUT_MIN_SECS, max = BACKEND_OP_TIMEOUT_MAX_SECS, default = DEFAULT_BACKEND_OP_TIMEOUT_SECS, - "RUSTFS_SFTP_BACKEND_OP_TIMEOUT_SECS out of range. Falling back to the default.", + result = "backend_timeout_out_of_range", + "sftp config state changed", ); None } @@ -254,11 +267,15 @@ impl SftpConfig { Some(n) if (READ_CACHE_WINDOW_MIN..=READ_CACHE_WINDOW_MAX).contains(&n) => Some(n), Some(n) => { tracing::warn!( + event = EVENT_SFTP_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, requested = n, min = READ_CACHE_WINDOW_MIN, max = READ_CACHE_WINDOW_MAX, default = READ_CACHE_WINDOW_DEFAULT, - "RUSTFS_SFTP_READ_CACHE_WINDOW_BYTES out of range. Set to 0 to disable the cache, or to a value between the named bounds. Falling back to the default.", + result = "read_cache_window_out_of_range", + "sftp config state changed", ); None } @@ -277,10 +294,14 @@ impl SftpConfig { Some(n) if n >= READ_CACHE_TOTAL_MEM_MIN => Some(n), Some(n) => { tracing::warn!( + event = EVENT_SFTP_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, requested = n, min = READ_CACHE_TOTAL_MEM_MIN, default = READ_CACHE_TOTAL_MEM_DEFAULT, - "RUSTFS_SFTP_READ_CACHE_TOTAL_MEM_BYTES below minimum. Falling back to the default.", + result = "read_cache_total_mem_below_minimum", + "sftp config state changed", ); None } @@ -337,9 +358,13 @@ impl SftpConfig { Ok(m) => m, Err(e) => { tracing::warn!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), err = %e, - "cannot stat file, skipping" + result = "stat_failed", + "sftp host key state changed" ); continue; } @@ -353,9 +378,13 @@ impl SftpConfig { let file_size = metadata.len(); if file_size == 0 || file_size > MAX_HOST_KEY_FILE_SIZE { tracing::debug!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), size = file_size, - "skipping file: size outside valid key range" + result = "size_out_of_range", + "sftp host key state changed" ); continue; } @@ -369,9 +398,13 @@ impl SftpConfig { Ok(d) => d, Err(e) => { tracing::warn!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), err = %e, - "cannot read file, skipping" + result = "read_failed", + "sftp host key state changed" ); continue; } @@ -380,9 +413,13 @@ impl SftpConfig { match russh::keys::decode_secret_key(&data, None) { Ok(key) => { tracing::info!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), algorithm = ?key.algorithm(), - "loaded host key" + state = "loaded", + "sftp host key state changed" ); keys.push(key); } @@ -396,15 +433,23 @@ impl SftpConfig { // reason in the log. if data.contains(PEM_BEGIN_MARKER) { tracing::warn!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), err = %e, - "file looks like a private key but failed to decode (passphrase-protected keys are not supported)" + result = "decode_failed", + "sftp host key state changed" ); } else { tracing::debug!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, path = %path.display(), err = %e, - "not a valid private key, skipping" + result = "not_a_private_key", + "sftp host key state changed" ); } } @@ -440,9 +485,13 @@ impl SftpConfig { }); tracing::info!( + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, count = keys.len(), dir = %host_key_dir.display(), - "host key loading complete" + state = "load_complete", + "sftp host key state changed" ); Ok(keys) @@ -467,14 +516,12 @@ fn warn_once_windows(host_key_dir: &Path) { static WARN: Once = Once::new(); WARN.call_once(|| { tracing::warn!( - target: "rustfs_protocols::sftp::host_key", + event = EVENT_SFTP_HOST_KEY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_CONFIG, host_key_dir = %host_key_dir.display(), - "SFTP host key file permission enforcement is not active on \ - Windows. rustfs trusts operator-managed NTFS ACLs on the \ - host-key directory. Restrict read access to the running rustfs \ - service account, NT AUTHORITY\\SYSTEM, and \ - BUILTIN\\Administrators. Default ProgramData inheritance grants \ - BUILTIN\\Users read access." + result = "windows_acl_operator_managed", + "sftp host key state changed" ); }); } diff --git a/crates/protocols/src/sftp/dir.rs b/crates/protocols/src/sftp/dir.rs index 2e22d26f7..24cd03e58 100644 --- a/crates/protocols/src/sftp/dir.rs +++ b/crates/protocols/src/sftp/dir.rs @@ -30,6 +30,10 @@ use russh_sftp::protocol::{File, Handle, Name, StatusCode}; use rustfs_utils::path; use s3s::dto::{ListObjectsV2Input, PutObjectInput, StreamingBlob}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_DIR: &str = "sftp_dir"; +const EVENT_SFTP_DIR_STATE: &str = "sftp_dir_state"; + /// Build the conventional "." and ".." directory entries that prefix /// the first READDIR response on every directory handle. SFTPv3 does /// not mandate these, but POSIX clients require them. Emitting both @@ -260,10 +264,14 @@ impl SftpDriver { } if let Some(total) = truncated_at { tracing::warn!( + event = EVENT_SFTP_DIR_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DIR, returned = entries.len(), total = total, cap = ROOT_LISTING_MAX_ENTRIES, - "root READDIR truncated: principal has more buckets than the cap", + result = "root_readdir_truncated", + "sftp dir state changed", ); } Ok(entries) diff --git a/crates/protocols/src/sftp/driver.rs b/crates/protocols/src/sftp/driver.rs index adc83db85..9b4259cf0 100644 --- a/crates/protocols/src/sftp/driver.rs +++ b/crates/protocols/src/sftp/driver.rs @@ -34,6 +34,7 @@ use crate::common::client::s3::StorageBackend; use crate::common::gateway::{AuthorizationError, S3Action, authorize_operation}; use crate::common::session::SessionContext; use russh_sftp::protocol::{Attrs, Data, File, FileAttributes, Handle, Name, OpenFlags, Packet, Status, StatusCode, Version}; +use rustfs_utils::MaskedAccessKey; use s3s::dto::{AbortMultipartUploadInput, CopyObjectInput, CopySource}; use std::collections::HashMap; use std::sync::atomic::AtomicU64; @@ -63,6 +64,12 @@ static ABORT_PERMITS: LazyLock> = LazyLock::new(|| { Arc::new(Semaphore::new(permits)) }); +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_DRIVER: &str = "sftp_driver"; +const EVENT_SFTP_DRIVER_STATE: &str = "sftp_driver_state"; +const EVENT_SFTP_BACKEND_STATE: &str = "sftp_backend_state"; +const EVENT_SFTP_AUTHZ_STATE: &str = "sftp_authz_state"; + /// Per-session SFTP operation handler. pub struct SftpDriver { pub(super) storage: Arc, @@ -175,9 +182,13 @@ impl SftpDriver { pub(super) fn enforce_server_readonly(&self) -> Result<(), SftpError> { if self.read_only { tracing::warn!( + event = EVENT_SFTP_DRIVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, peer = %self.session_context.source_ip, - user = %self.session_context.principal.user_identity.credentials.access_key, - "SFTP write rejected: server is in read-only mode" + user = %MaskedAccessKey(&self.session_context.principal.user_identity.credentials.access_key), + result = "read_only_rejected", + "sftp driver state changed" ); return Err(SftpError::code(StatusCode::PermissionDenied)); } @@ -232,7 +243,15 @@ impl SftpDriver { Ok(Ok(v)) => Ok(v), Ok(Err(e)) => Err(s3_error_to_sftp(op, e)), Err(_elapsed) => { - tracing::warn!(op = op, timeout_secs = self.backend_op_timeout_secs, "SFTP backend operation timed out"); + tracing::warn!( + event = EVENT_SFTP_BACKEND_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, + op = op, + timeout_secs = self.backend_op_timeout_secs, + result = "timeout", + "sftp backend state changed" + ); Err(SftpError::code(StatusCode::Failure)) } } @@ -251,7 +270,15 @@ impl SftpDriver { match tokio::time::timeout(std::time::Duration::from_secs(self.backend_op_timeout_secs), fut).await { Ok(inner) => Ok(inner), Err(_elapsed) => { - tracing::warn!(op = op, timeout_secs = self.backend_op_timeout_secs, "SFTP backend operation timed out"); + tracing::warn!( + event = EVENT_SFTP_BACKEND_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, + op = op, + timeout_secs = self.backend_op_timeout_secs, + result = "timeout", + "sftp backend state changed" + ); Err(SftpError::code(StatusCode::Failure)) } } @@ -274,13 +301,47 @@ impl SftpDriver { let outcome = match tokio::time::timeout(std::time::Duration::from_secs(self.backend_op_timeout_secs), auth_fut).await { Ok(inner) => inner, Err(_elapsed) => { + tracing::warn!( + event = EVENT_SFTP_AUTHZ_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, + action = action.as_str(), + bucket = %bucket, + key = %key.unwrap_or_default(), + result = "timeout", + "sftp authz state changed" + ); return Err(auth_err_unreachable(action.as_str(), bucket, key)); } }; match outcome { Ok(()) => Ok(()), - Err(AuthorizationError::AccessDenied) => Err(auth_err()), - Err(AuthorizationError::IamUnavailable) => Err(auth_err_unreachable(action.as_str(), bucket, key)), + Err(AuthorizationError::AccessDenied) => { + tracing::warn!( + event = EVENT_SFTP_AUTHZ_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, + action = action.as_str(), + bucket = %bucket, + key = %key.unwrap_or_default(), + result = "access_denied", + "sftp authz state changed" + ); + Err(auth_err()) + } + Err(AuthorizationError::IamUnavailable) => { + tracing::warn!( + event = EVENT_SFTP_AUTHZ_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_DRIVER, + action = action.as_str(), + bucket = %bucket, + key = %key.unwrap_or_default(), + result = "iam_unavailable", + "sftp authz state changed" + ); + Err(auth_err_unreachable(action.as_str(), bucket, key)) + } } } } diff --git a/crates/protocols/src/sftp/errors.rs b/crates/protocols/src/sftp/errors.rs index 9d57ed4f0..c64172af5 100644 --- a/crates/protocols/src/sftp/errors.rs +++ b/crates/protocols/src/sftp/errors.rs @@ -22,6 +22,10 @@ use russh_sftp::server::StatusReply; use s3s::{S3Error, S3ErrorCode}; use std::{any::Any, fmt::Display}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_ERRORS: &str = "sftp_errors"; +const EVENT_SFTP_ERROR_MAPPING: &str = "sftp_error_mapping"; + /// Error type for SFTP operations. Converts to StatusCode for the wire. #[derive(Debug)] pub struct SftpError(pub(super) StatusCode); @@ -111,7 +115,7 @@ pub(super) fn s3_error_to_sftp(op: &str, err: E) -> SftpEr BackendErrorKind::PermissionDenied => StatusCode::PermissionDenied, BackendErrorKind::NoSuchUpload | BackendErrorKind::Other => StatusCode::Failure, }; - tracing::warn!(op = %op, err = %msg, "SFTP backend error"); + tracing::warn!(event = EVENT_SFTP_ERROR_MAPPING, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SFTP_ERRORS, op = %op, err = %msg, mapped_status = ?code, "sftp error mapping"); SftpError::code(code) } @@ -128,10 +132,14 @@ pub(super) fn auth_err() -> SftpError { /// deny. pub(super) fn auth_err_unreachable(op: &str, bucket: &str, key: Option<&str>) -> SftpError { tracing::warn!( + event = EVENT_SFTP_ERROR_MAPPING, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_ERRORS, op = op, bucket = %bucket, key = key.unwrap_or("-"), - "SFTP authorisation rejected because the IAM system was unreachable" + result = "iam_unreachable", + "sftp error mapping" ); SftpError::code(StatusCode::Failure) } diff --git a/crates/protocols/src/sftp/fallback_watchdog.rs b/crates/protocols/src/sftp/fallback_watchdog.rs index 6aa84ddd2..f4c1e17ae 100644 --- a/crates/protocols/src/sftp/fallback_watchdog.rs +++ b/crates/protocols/src/sftp/fallback_watchdog.rs @@ -29,6 +29,10 @@ use std::sync::atomic::Ordering; use std::time::{Duration, SystemTime, UNIX_EPOCH}; use tokio_util::sync::CancellationToken; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_WATCHDOG: &str = "sftp_watchdog"; +const EVENT_SFTP_WATCHDOG_STATE: &str = "sftp_watchdog_state"; + /// Spawn a per-session silence backstop tick task. /// /// The task holds a clone of the per-session CancellationToken and an @@ -51,12 +55,14 @@ pub(super) fn spawn_for_session(session_diag: Arc, cancel_token: Ca let silence_secs = silence_secs(&session_diag); if fallback_threshold_reached(silence_secs) { tracing::warn!( - target: "rustfs_protocols::sftp::watchdog", + event = EVENT_SFTP_WATCHDOG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WATCHDOG, session_id, peer = %peer, silence_secs, reason = "fallback_silence", - "fallback watchdog cancelling session: silence exceeded fallback threshold", + "sftp watchdog state changed", ); cancel_token.cancel(); break; diff --git a/crates/protocols/src/sftp/server.rs b/crates/protocols/src/sftp/server.rs index ab038111a..33e03fe26 100644 --- a/crates/protocols/src/sftp/server.rs +++ b/crates/protocols/src/sftp/server.rs @@ -42,6 +42,7 @@ use rustfs_config::{ DEFAULT_SFTP_HOST_KEY_RELOAD_ENABLE, DEFAULT_SFTP_HOST_KEY_RELOAD_INTERVAL, ENV_SFTP_HOST_KEY_RELOAD_ENABLE, ENV_SFTP_HOST_KEY_RELOAD_INTERVAL, }; +use rustfs_utils::MaskedAccessKey; use std::borrow::Cow; use std::collections::HashMap; use std::collections::hash_map::DefaultHasher; @@ -56,9 +57,19 @@ use tokio::sync::broadcast; use tokio::task::JoinSet; use tokio::time::{Duration, MissedTickBehavior, timeout}; use tokio_util::sync::CancellationToken; +use tracing::{debug, error, info, warn}; use crate::sftp::constants::limits::SHUTDOWN_DRAIN_TIMEOUT_SECS; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_SERVER: &str = "sftp_server"; +const LOG_SUBSYSTEM_SFTP_AUTH: &str = "sftp_auth"; +const EVENT_SFTP_SERVER_STATE: &str = "sftp_server_state"; +const EVENT_SFTP_HOST_KEY_RELOAD_STATE: &str = "sftp_host_key_reload_state"; +const EVENT_SFTP_SESSION_STATE: &str = "sftp_session_state"; +const EVENT_SFTP_AUTH_STATE: &str = "sftp_auth_state"; +const EVENT_SFTP_SUBSYSTEM_STATE: &str = "sftp_subsystem_state"; + // Cipher, KEX, MAC, and host-key algorithm lists. All four are compile-time // constants with no environment-variable override, so operators cannot // accidentally downgrade to weak ciphers. @@ -223,9 +234,13 @@ fn host_key_algorithm_rank(algorithm: keys::Algorithm) -> u8 { fn spawn_host_key_reload_loop(config: SftpConfig, holder: Arc, shutdown_token: CancellationToken) { let enabled = rustfs_utils::get_env_bool(ENV_SFTP_HOST_KEY_RELOAD_ENABLE, DEFAULT_SFTP_HOST_KEY_RELOAD_ENABLE); if !enabled { - tracing::debug!( - "SFTP host key hot reload is disabled (set {}=1 to enable)", - ENV_SFTP_HOST_KEY_RELOAD_ENABLE + debug!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "disabled", + env_var = ENV_SFTP_HOST_KEY_RELOAD_ENABLE, + "sftp host key reload state changed" ); return; } @@ -233,10 +248,14 @@ fn spawn_host_key_reload_loop(config: SftpConfig, holder: Arc, let interval_secs = rustfs_utils::get_env_u64(ENV_SFTP_HOST_KEY_RELOAD_INTERVAL, DEFAULT_SFTP_HOST_KEY_RELOAD_INTERVAL).max(5); - tracing::info!( + info!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "enabled", host_key_dir = %config.host_key_dir.display(), interval_secs, - "SFTP host key hot reload enabled" + "sftp host key reload state changed" ); tokio::spawn(async move { @@ -246,7 +265,14 @@ fn spawn_host_key_reload_loop(config: SftpConfig, holder: Arc, loop { tokio::select! { _ = shutdown_token.cancelled() => { - tracing::info!(host_key_dir = %config.host_key_dir.display(), "SFTP host key hot reload task stopped"); + info!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "stopped", + host_key_dir = %config.host_key_dir.display(), + "sftp host key reload state changed" + ); break; } _ = interval.tick() => {} @@ -254,23 +280,35 @@ fn spawn_host_key_reload_loop(config: SftpConfig, holder: Arc, match holder.reload_from_config(&config).await { Ok(Some(host_key_count)) => { - tracing::info!( + info!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "reloaded", host_key_dir = %config.host_key_dir.display(), host_key_count, - "SFTP host keys reloaded successfully" + "sftp host key reload state changed" ); } Ok(None) => { - tracing::debug!( + debug!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "unchanged", host_key_dir = %config.host_key_dir.display(), - "SFTP host key material unchanged; skipping reload" + "sftp host key reload state changed" ); } Err(err) => { - tracing::warn!( + warn!( + event = EVENT_SFTP_HOST_KEY_RELOAD_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "reload_failed", host_key_dir = %config.host_key_dir.display(), err = %err, - "SFTP host key reload failed; keeping previous keys" + "sftp host key reload state changed" ); } } @@ -353,7 +391,15 @@ where let listener = TcpListener::bind(self.config.bind_addr) .await .map_err(|e| SftpInitError::Server(format!("failed to bind {}: {}", self.config.bind_addr, e)))?; - tracing::info!(bind_addr = %self.config.bind_addr, "SFTP server listening"); + info!( + event = EVENT_SFTP_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "listening", + bind_addr = %self.config.bind_addr, + read_only = self.config.read_only, + "sftp server state changed" + ); let mut sessions: JoinSet<()> = JoinSet::new(); // Parent cancellation token for the lifetime of this listener. @@ -383,9 +429,13 @@ where self.handle_accept(accept_result, &mut sessions, &server_shutdown_token); } _ = shutdown_rx.recv() => { - tracing::info!( + info!( + event = EVENT_SFTP_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "shutdown_requested", live_sessions = sessions.len(), - "SFTP server received shutdown signal", + "sftp server state changed", ); // Cascade cancellation to every live session and // its watchdog before the drain loop runs. Wedged @@ -412,11 +462,34 @@ where while let Some(res) = sessions.try_join_next() { let live = sessions.len(); match res { - Ok(()) => tracing::debug!(live_sessions = live, "SFTP session task finished"), + Ok(()) => debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "finished", + live_sessions = live, + "sftp session state changed" + ), Err(e) if e.is_panic() => { - tracing::error!(err = %e, live_sessions = live, "SFTP session task panicked") + error!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "task_panicked", + err = %e, + live_sessions = live, + "sftp session state changed" + ) } - Err(e) => tracing::debug!(err = %e, live_sessions = live, "SFTP session task cancelled"), + Err(e) => debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "cancelled", + err = %e, + live_sessions = live, + "sftp session state changed" + ), } } } @@ -434,7 +507,14 @@ where let (stream, peer_addr) = match accept_result { Ok(v) => v, Err(e) => { - tracing::warn!(err = %e, "failed to accept connection"); + warn!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "accept_failed", + err = %e, + "sftp session state changed" + ); return; } }; @@ -454,7 +534,13 @@ where // is still consistent across panics, and the accept loop // must keep running. let mut reg = self.session_registry.lock().unwrap_or_else(|poisoned| { - tracing::warn!("session registry mutex poisoned, recovering"); + warn!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "registry_poisoned", + "sftp session state changed" + ); poisoned.into_inner() }); reg.push(Arc::downgrade(&session_diag)); @@ -472,10 +558,14 @@ where let watchdog_socket = { let socket = wedge_watchdog::dup_socket(&stream); if socket.is_none() { - tracing::warn!( + warn!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "watchdog_socket_unavailable", peer = %peer_addr, session_id = session_diag.session_id, - "wedge watchdog: dup_socket failed, session has no wedge protection (rare; usually fd exhaustion)", + "sftp session state changed", ); } socket @@ -500,13 +590,17 @@ where session_diag: handler_session_diag, }; - tracing::debug!( + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "spawned", peer = %peer_addr, // sessions.len() reads pre-spawn, so add one to include // the session about to be inserted. live_sessions = sessions.len() + 1, session_id = session_diag.session_id, - "SFTP accept: spawning session task", + "sftp session state changed", ); #[cfg(target_os = "linux")] sessions.spawn(run_session( @@ -670,7 +764,14 @@ async fn run_session( ) where S: StorageBackend + Send + Sync + 'static, { - tracing::debug!(peer = %peer_addr, "SFTP session task entered"); + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "task_entered", + peer = %peer_addr, + "sftp session state changed" + ); // run_stream covers SSH KEX and password auth. Cap with a // wallclock deadline so a peer that completes TCP but stalls // before KEXINIT (or that drives KEX or auth so slowly that no @@ -681,19 +782,38 @@ async fn run_session( let session = match timeout(handshake_deadline, russh::server::run_stream(ssh_config, stream, handler)).await { Ok(Ok(s)) => s, Ok(Err(e)) => { - tracing::debug!(peer = %peer_addr, err = %e, "SSH session setup failed"); + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "setup_failed", + peer = %peer_addr, + err = %e, + "sftp session state changed" + ); return; } Err(_elapsed) => { - tracing::warn!( + warn!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "handshake_timeout", peer = %peer_addr, deadline_secs = HANDSHAKE_DEADLINE_SECS, - "SSH handshake exceeded deadline; dropping connection", + "sftp session state changed", ); return; } }; - tracing::debug!(peer = %peer_addr, "SFTP session run_stream returned; awaiting session loop"); + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "handshake_completed", + peer = %peer_addr, + "sftp session state changed" + ); // Spawn the per-session watchdog. On Linux the wedge watchdog // observes the SFTP-handler activity stamp and the kernel TCP // state. On wedge detection it shuts the duplicated socket down @@ -722,16 +842,38 @@ async fn run_session( let session_result = match session_result { Some(r) => r, None => { - tracing::warn!(peer = %peer_addr, "SFTP session cancelled (watchdog or server shutdown)"); + warn!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "cancelled", + peer = %peer_addr, + "sftp session state changed" + ); return; } }; match session_result { Ok(()) => { - tracing::debug!(peer = %peer_addr, "SFTP session ended cleanly"); + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "ended_cleanly", + peer = %peer_addr, + "sftp session state changed" + ); } Err(e) => { - tracing::debug!(peer = %peer_addr, err = %e, "SSH session ended with error"); + debug!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "ended_with_error", + peer = %peer_addr, + err = %e, + "sftp session state changed" + ); } } } @@ -757,16 +899,33 @@ async fn drain_sessions(mut sessions: JoinSet<()>) { if let Err(e) = res && e.is_panic() { - tracing::error!(err = %e, "SFTP session task panicked during drain"); + error!( + event = EVENT_SFTP_SESSION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "drain_task_panicked", + err = %e, + "sftp session state changed" + ); } } }; match timeout(Duration::from_secs(SHUTDOWN_DRAIN_TIMEOUT_SECS), drain).await { - Ok(()) => tracing::info!("SFTP session drain complete"), - Err(_) => tracing::warn!( + Ok(()) => info!( + event = EVENT_SFTP_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "drain_completed", + "sftp server state changed" + ), + Err(_) => warn!( + event = EVENT_SFTP_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "drain_timeout", timeout_secs = SHUTDOWN_DRAIN_TIMEOUT_SECS, live = sessions.len(), - "SFTP session drain timed out, cancelling remaining sessions", + "sftp server state changed", ), } } @@ -872,6 +1031,7 @@ impl russh::server::Handler for SshSe ) -> impl std::future::Future> + Send { let user = user.to_owned(); let password = password.to_owned(); + let masked_user = MaskedAccessKey(&user).to_string(); let peer_addr = self.peer_addr; let session_diag = Arc::clone(&self.session_diag); session_diag.stamp(); @@ -880,7 +1040,15 @@ impl russh::server::Handler for SshSe let iam_sys = match rustfs_iam::get() { Ok(sys) => sys, Err(e) => { - tracing::error!(err = %e, "IAM system unavailable"); + error!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "iam_unavailable", + peer = %peer_addr, + err = %e, + "sftp auth state changed" + ); return Ok(Auth::reject()); } }; @@ -888,10 +1056,15 @@ impl russh::server::Handler for SshSe let (identity_opt, is_valid) = match iam_sys.check_key(&user).await { Ok(result) => result, Err(e) => { - tracing::error!( - user = %user, + error!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "check_key_failed", + user = %masked_user, + peer = %peer_addr, err = %e, - "IAM check_key error" + "sftp auth state changed" ); return Ok(Auth::reject()); } @@ -900,10 +1073,14 @@ impl russh::server::Handler for SshSe let identity = match identity_opt { Some(id) => id, None => { - tracing::warn!( - user = %user, + warn!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "unknown_access_key", + user = %masked_user, peer = %peer_addr, - "SFTP auth rejected: unknown access key" + "sftp auth state changed" ); return Ok(Auth::reject()); } @@ -912,10 +1089,14 @@ impl russh::server::Handler for SshSe // Reject disabled or expired accounts. FTPS checks this at // ftps/server.rs:286. SFTP must do the same. if !is_valid { - tracing::warn!( - user = %user, + warn!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "account_inactive", + user = %masked_user, peer = %peer_addr, - "SFTP auth rejected: account disabled or expired" + "sftp auth state changed" ); return Ok(Auth::reject()); } @@ -926,10 +1107,14 @@ impl russh::server::Handler for SshSe let secret_matches: bool = identity.credentials.secret_key.as_bytes().ct_eq(password.as_bytes()).into(); if !secret_matches { - tracing::warn!( - user = %user, + warn!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "invalid_secret_key", + user = %masked_user, peer = %peer_addr, - "SFTP auth rejected: invalid secret key" + "sftp auth state changed" ); return Ok(Auth::reject()); } @@ -937,10 +1122,14 @@ impl russh::server::Handler for SshSe let principal = ProtocolPrincipal::new(Arc::new(identity)); self.session_context = Some(SessionContext::new(principal, Protocol::Sftp, peer_addr.ip())); - tracing::info!( - user = %user, + debug!( + event = EVENT_SFTP_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_AUTH, + result = "authenticated", + user = %masked_user, peer = %peer_addr, - "SFTP auth accepted" + "sftp auth state changed" ); Ok(Auth::Accept) } @@ -992,10 +1181,14 @@ impl russh::server::Handler for SshSe let inputs: Result>, Self::Error> = (|| { if name != SFTP_SUBSYSTEM_NAME { - tracing::warn!( + warn!( + event = EVENT_SFTP_SUBSYSTEM_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "unsupported_subsystem", subsystem = %name, peer = %self.peer_addr, - "rejecting unsupported subsystem" + "sftp subsystem state changed" ); session.channel_failure(channel_id)?; return Ok(None); @@ -1004,9 +1197,14 @@ impl russh::server::Handler for SshSe let channel = match self.channels.remove(&channel_id) { Some(ch) => ch, None => { - tracing::error!( + error!( + event = EVENT_SFTP_SUBSYSTEM_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "channel_missing", channel = ?channel_id, - "subsystem_request: no channel found" + peer = %self.peer_addr, + "sftp subsystem state changed" ); session.channel_failure(channel_id)?; return Ok(None); @@ -1016,13 +1214,30 @@ impl russh::server::Handler for SshSe let session_context = match self.session_context.clone() { Some(ctx) => ctx, None => { - tracing::error!("subsystem_request before authentication"); + error!( + event = EVENT_SFTP_SUBSYSTEM_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + result = "unauthenticated_request", + channel = ?channel_id, + peer = %self.peer_addr, + "sftp subsystem state changed" + ); session.channel_failure(channel_id)?; return Ok(None); } }; session.channel_success(channel_id)?; + debug!( + event = EVENT_SFTP_SUBSYSTEM_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_SERVER, + state = "accepted", + channel = ?channel_id, + peer = %self.peer_addr, + "sftp subsystem state changed" + ); Ok(Some(RunInputs { stream: channel.into_stream(), diff --git a/crates/protocols/src/sftp/wedge_watchdog.rs b/crates/protocols/src/sftp/wedge_watchdog.rs index 3eec057ad..6997d0447 100644 --- a/crates/protocols/src/sftp/wedge_watchdog.rs +++ b/crates/protocols/src/sftp/wedge_watchdog.rs @@ -62,6 +62,10 @@ use std::time::{Duration, SystemTime, UNIX_EPOCH}; use tokio::net::TcpStream; use tokio_util::sync::CancellationToken; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_WATCHDOG: &str = "sftp_watchdog"; +const EVENT_SFTP_WATCHDOG_STATE: &str = "sftp_watchdog_state"; + /// Reason a watchdog cancelled its session. Included in the warn log /// the watchdog writes at cancel time so operators can correlate the /// cancel with the upstream client behaviour. @@ -140,12 +144,14 @@ pub(super) fn spawn_for_session(session_diag: Arc, socket: Socket, } Decision::Cancel(reason) => { tracing::warn!( - target: "rustfs_protocols::sftp::watchdog", + event = EVENT_SFTP_WATCHDOG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WATCHDOG, session_id, peer = %peer, silence_secs, reason = reason.as_str(), - "wedge watchdog cancelling session: russh select! parked outside its arms", + "sftp watchdog state changed", ); cancel_token.cancel(); break; diff --git a/crates/protocols/src/sftp/write.rs b/crates/protocols/src/sftp/write.rs index e3504d51a..e0072deca 100644 --- a/crates/protocols/src/sftp/write.rs +++ b/crates/protocols/src/sftp/write.rs @@ -32,11 +32,19 @@ use crate::common::gateway::S3Action; use bytes::Bytes; use futures_util::stream; use russh_sftp::protocol::{FileAttributes, Handle, OpenFlags, StatusCode}; +use rustfs_utils::MaskedAccessKey; use s3s::dto::{ AbortMultipartUploadInput, CompleteMultipartUploadInput, CompletedMultipartUpload, CompletedPart as S3CompletedPart, CopySource, CreateMultipartUploadInput, PutObjectInput, StreamingBlob, UploadPartCopyInput, UploadPartInput, }; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SFTP_WRITE: &str = "sftp_write"; +const EVENT_SFTP_WRITE_STATE: &str = "sftp_write_state"; +const EVENT_SFTP_MULTIPART_STATE: &str = "sftp_multipart_state"; +const EVENT_SFTP_ABORT_STATE: &str = "sftp_abort_state"; +const EVENT_SFTP_MULTIPART_COPY_STATE: &str = "sftp_multipart_copy_state"; + /// Running byte count for a write handle's current phase. Buffering is /// part_buffer.len(). Streaming is (parts_done * part_size) + /// part_buffer.len(). Failed is treated as zero in saturating mode and @@ -62,7 +70,13 @@ pub(super) fn write_dispatch_byte_count(phase: &WritePhase, part_size: u64, satu (Some(value), _) => Ok(value), (None, true) => Ok(u64::MAX), (None, false) => { - tracing::warn!("SFTP write running total overflowed u64"); + tracing::warn!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "byte_count_overflow", + "sftp write state changed" + ); Err(SftpError::code(StatusCode::Failure)) } } @@ -71,7 +85,13 @@ pub(super) fn write_dispatch_byte_count(phase: &WritePhase, part_size: u64, satu if saturating { Ok(0) } else { - tracing::warn!("SFTP write rejected: handle already poisoned by earlier upload failure"); + tracing::warn!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "handle_poisoned", + "sftp write state changed" + ); Err(SftpError::code(StatusCode::Failure)) } } @@ -90,7 +110,13 @@ pub(super) fn write_dispatch_append_bytes(phase: &mut WritePhase, data: &[u8]) - Ok(()) } WritePhase::Failed { .. } => { - tracing::error!("SFTP write_dispatch_append_bytes reached a Failed handle, internal invariant broken"); + tracing::error!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "append_on_failed_handle", + "sftp write state changed" + ); Err(SftpError::code(StatusCode::Failure)) } } @@ -335,10 +361,14 @@ impl SftpDriver { if attempt > 0 { tokio::time::sleep(std::time::Duration::from_millis(COMMIT_WRITE_BACKOFF_MS[attempt - 1])).await; tracing::warn!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %sanitise_control_bytes(bucket), key = %sanitise_control_bytes(key), attempt = attempt, - "retrying commit_write put_object after retryable backend error", + state = "retrying_put_object", + "sftp write state changed", ); } @@ -378,9 +408,13 @@ impl SftpDriver { // that proof, log and surface Failure rather than panicking // the session task. tracing::error!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %sanitise_control_bytes(bucket), key = %sanitise_control_bytes(key), - "commit_write retry loop fell through without returning", + result = "retry_loop_fell_through", + "sftp write state changed", ); Err(SftpError::code(StatusCode::Failure)) } @@ -418,7 +452,15 @@ impl SftpDriver { .await?; let e_tag = out.e_tag.ok_or_else(|| { - tracing::warn!(upload_id = %upload_id, part_number = part_number, "UploadPart returned no ETag"); + tracing::warn!( + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + upload_id = %upload_id, + part_number = part_number, + result = "etag_missing", + "sftp multipart state changed" + ); SftpError::code(StatusCode::Failure) })?; @@ -495,9 +537,13 @@ impl SftpDriver { let upload_id = out.upload_id.ok_or_else(|| { tracing::warn!( + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %sanitise_control_bytes(bucket), key = %sanitise_control_bytes(key), - "CreateMultipartUpload returned no upload_id" + result = "upload_id_missing", + "sftp multipart state changed" ); SftpError::code(StatusCode::Failure) })?; @@ -595,7 +641,15 @@ impl SftpDriver { let current_len = write_dispatch_byte_count(phase, part_size, false)?; if offset != current_len { - tracing::warn!(offset = offset, buffered = current_len, "SFTP write rejected: non-sequential offset"); + tracing::warn!( + event = EVENT_SFTP_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + offset, + buffered = current_len, + result = "non_sequential_offset", + "sftp write state changed" + ); return Err(SftpError::code(StatusCode::Failure)); } @@ -650,7 +704,11 @@ impl SftpDriver { WritePhase::Buffering { part_buffer } => std::mem::take(part_buffer), _ => { tracing::error!( - "SFTP write_dispatch_begin_streaming lost Buffering phase between check and extract, internal invariant broken" + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "buffering_phase_lost", + "sftp multipart state changed" ); return Err(SftpError::code(StatusCode::Failure)); } @@ -707,10 +765,14 @@ impl SftpDriver { } => { if *next_part_number > S3_MAX_MULTIPART_PARTS { tracing::warn!( + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %bucket, key = %key, limit = S3_MAX_MULTIPART_PARTS, - "SFTP write would exceed the S3 multipart parts limit", + result = "parts_limit_exceeded", + "sftp multipart state changed", ); let upload_id_for_fail = upload_id.clone(); let abort_authorized_for_fail = *abort_authorized; @@ -724,7 +786,13 @@ impl SftpDriver { (upload_id.clone(), *abort_authorized, *next_part_number, drained) } _ => { - tracing::error!("SFTP write_dispatch_flush_one_part called without Streaming phase, internal invariant broken"); + tracing::error!( + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "flush_without_streaming", + "sftp multipart state changed" + ); return Err(SftpError::code(StatusCode::Failure)); } }; @@ -745,7 +813,11 @@ impl SftpDriver { } _ => { tracing::error!( - "SFTP write_dispatch_flush_one_part post-upload arm without Streaming phase, internal invariant broken" + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, + result = "post_upload_phase_missing", + "sftp multipart state changed" ); Err(SftpError::code(StatusCode::Failure)) } @@ -806,22 +878,30 @@ impl SftpDriver { if abort_authorized { if let Err(abort_err) = self.abort_upload_with_auth(bucket, key, upload_id).await { tracing::warn!( + event = EVENT_SFTP_ABORT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %bucket, key = %key, upload_id = %upload_id, err = ?abort_err, - "abort after {context} also failed; S3 lifecycle must clean up", context = context, + result = "abort_failed", + "sftp abort state changed", ); } } else { tracing::warn!( + event = EVENT_SFTP_ABORT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %bucket, key = %key, upload_id = %upload_id, - access_key = %self.access_key(), - "skipped abort at close ({context}): principal lacks s3:AbortMultipartUpload, bucket lifecycle rules must reclaim parts", + access_key = %MaskedAccessKey(self.access_key()), context = context, + result = "abort_skipped_unauthorized", + "sftp abort state changed", ); } } @@ -871,11 +951,15 @@ impl SftpDriver { if !part_buffer.is_empty() { if next_part_number > S3_MAX_MULTIPART_PARTS { tracing::warn!( + event = EVENT_SFTP_MULTIPART_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %bucket, key = %key, upload_id = %upload_id, limit = S3_MAX_MULTIPART_PARTS, - "SFTP close rejected: trailing part would exceed S3 multipart parts limit", + result = "final_part_limit_exceeded", + "sftp multipart state changed", ); self.close_abort_or_skip(bucket, key, &upload_id, abort_authorized, "parts-limit breach") .await; @@ -932,11 +1016,15 @@ impl SftpDriver { let target = needed.max(configured).max(S3_MIN_PART_SIZE); if target > S3_MAX_PART_SIZE { tracing::warn!( + event = EVENT_SFTP_MULTIPART_COPY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, bucket = %dst_bucket, key = %sanitise_control_bytes(dst_key), content_length, target, - "multipart copy refused: per-part size exceeds S3_MAX_PART_SIZE" + result = "part_size_exceeded", + "sftp multipart copy state changed" ); return Err(SftpError::code(StatusCode::Failure)); } @@ -986,9 +1074,13 @@ impl SftpDriver { let e_tag = out.copy_part_result.and_then(|r| r.e_tag).ok_or_else(|| { tracing::warn!( + event = EVENT_SFTP_MULTIPART_COPY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SFTP_WRITE, upload_id = %mp.upload_id, part_number = part_number, - "UploadPartCopy returned no ETag" + result = "etag_missing", + "sftp multipart copy state changed" ); SftpError::code(StatusCode::Failure) })?; diff --git a/crates/protocols/src/swift/acl.rs b/crates/protocols/src/swift/acl.rs index b58ef0115..31f2ba27d 100644 --- a/crates/protocols/src/swift/acl.rs +++ b/crates/protocols/src/swift/acl.rs @@ -60,6 +60,10 @@ use super::{SwiftError, SwiftResult}; use std::fmt; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_ACL: &str = "swift_acl"; +const EVENT_SWIFT_ACL_DECISION: &str = "swift_acl_decision"; + /// Container ACL configuration #[derive(Debug, Clone, Default, PartialEq)] pub struct ContainerAcl { @@ -228,14 +232,22 @@ impl ContainerAcl { for grant in &self.read { match grant { AclGrant::PublicRead => { - debug!("Read access granted: public read enabled"); + debug!( + event = EVENT_SWIFT_ACL_DECISION, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ACL, + action = "read", + result = "granted", + reason = "public_read", + "swift acl decision" + ); return true; } AclGrant::PublicReadReferrer(pattern) => { if let Some(ref_header) = referrer && Self::matches_referrer_pattern(ref_header, pattern) { - debug!("Read access granted: referrer matches pattern {}", pattern); + debug!(event = EVENT_SWIFT_ACL_DECISION, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_ACL, action = "read", result = "granted", reason = "referrer_match", pattern = %pattern, "swift acl decision"); return true; } } @@ -243,7 +255,7 @@ impl ContainerAcl { if let Some(req_account) = request_account && req_account == account { - debug!("Read access granted: account {} matches", account); + debug!(event = EVENT_SWIFT_ACL_DECISION, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_ACL, action = "read", result = "granted", reason = "account_match", account = %account, "swift acl decision"); return true; } } @@ -255,14 +267,22 @@ impl ContainerAcl { && req_account == account && req_user == grant_user { - debug!("Read access granted: user {}:{} matches", account, grant_user); + debug!(event = EVENT_SWIFT_ACL_DECISION, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_ACL, action = "read", result = "granted", reason = "user_match", account = %account, user = %grant_user, "swift acl decision"); return true; } } } } - debug!("Read access denied: no matching ACL grant"); + debug!( + event = EVENT_SWIFT_ACL_DECISION, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ACL, + action = "read", + result = "denied", + reason = "no_matching_grant", + "swift acl decision" + ); false } @@ -288,7 +308,7 @@ impl ContainerAcl { } AclGrant::Account(account) => { if request_account == account { - debug!("Write access granted: account {} matches", account); + debug!(event = EVENT_SWIFT_ACL_DECISION, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_ACL, action = "write", result = "granted", reason = "account_match", account = %account, "swift acl decision"); return true; } } @@ -300,14 +320,22 @@ impl ContainerAcl { && request_account == account && req_user == grant_user { - debug!("Write access granted: user {}:{} matches", account, grant_user); + debug!(event = EVENT_SWIFT_ACL_DECISION, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_ACL, action = "write", result = "granted", reason = "user_match", account = %account, user = %grant_user, "swift acl decision"); return true; } } } } - debug!("Write access denied: no matching ACL grant"); + debug!( + event = EVENT_SWIFT_ACL_DECISION, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ACL, + action = "write", + result = "denied", + reason = "no_matching_grant", + "swift acl decision" + ); false } diff --git a/crates/protocols/src/swift/bulk.rs b/crates/protocols/src/swift/bulk.rs index 2d93a4d8f..adc3cbe8c 100644 --- a/crates/protocols/src/swift/bulk.rs +++ b/crates/protocols/src/swift/bulk.rs @@ -82,6 +82,11 @@ use s3s::Body; use serde::{Deserialize, Serialize}; use tracing::{debug, error}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_BULK: &str = "swift_bulk"; +const EVENT_SWIFT_BULK_DELETE_STATE: &str = "swift_bulk_delete_state"; +const EVENT_SWIFT_BULK_EXTRACT_STATE: &str = "swift_bulk_extract_state"; + /// Result of a single delete operation #[derive(Debug, Clone, Serialize, Deserialize)] pub struct DeleteResult { @@ -211,7 +216,14 @@ fn parse_object_path(path: &str) -> SwiftResult<(String, String)> { /// /// Deletes multiple objects specified in the request body pub async fn handle_bulk_delete(account: &str, body: String, credentials: &Credentials) -> SwiftResult> { - debug!("Bulk delete request for account: {}", account); + debug!( + event = EVENT_SWIFT_BULK_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + state = "started", + account = %account, + "swift bulk delete state changed" + ); let mut response = BulkDeleteResponse::default(); let mut delete_results = Vec::new(); @@ -223,7 +235,15 @@ pub async fn handle_bulk_delete(account: &str, body: String, credentials: &Crede return Err(SwiftError::BadRequest("No paths provided for bulk delete".to_string())); } - debug!("Processing {} delete requests", paths.len()); + debug!( + event = EVENT_SWIFT_BULK_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + state = "processing", + account = %account, + path_count = paths.len(), + "swift bulk delete state changed" + ); // Process each path for path in paths { @@ -248,7 +268,16 @@ pub async fn handle_bulk_delete(account: &str, body: String, credentials: &Crede } } Err(e) => { - error!("Error deleting {}: {}", path, e); + error!( + event = EVENT_SWIFT_BULK_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + result = "delete_failed", + account = %account, + path = %path, + error = %e, + "swift bulk delete state changed" + ); response.errors.push(vec![path.to_string(), e.to_string()]); DeleteResult { path: path.to_string(), @@ -259,7 +288,16 @@ pub async fn handle_bulk_delete(account: &str, body: String, credentials: &Crede } } Err(e) => { - error!("Invalid path {}: {}", path, e); + error!( + event = EVENT_SWIFT_BULK_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + result = "invalid_path", + account = %account, + path = %path, + error = %e, + "swift bulk delete state changed" + ); response.errors.push(vec![path.to_string(), e.to_string()]); DeleteResult { path: path.to_string(), @@ -328,7 +366,16 @@ pub async fn handle_bulk_extract( body: Vec, credentials: &Credentials, ) -> SwiftResult> { - debug!("Bulk extract request for container: {}, format: {:?}", container, format); + debug!( + event = EVENT_SWIFT_BULK_EXTRACT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + state = "started", + account = %account, + container = %container, + format = ?format, + "swift bulk extract state changed" + ); let mut response = BulkExtractResponse::default(); @@ -358,10 +405,27 @@ pub async fn handle_bulk_extract( { Ok(_) => { response.number_files_created += 1; - debug!("Extracted: {}", path_str); + debug!( + event = EVENT_SWIFT_BULK_EXTRACT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + state = "file_created", + container = %container, + object = %path_str, + "swift bulk extract state changed" + ); } Err(e) => { - error!("Failed to upload {}: {}", path_str, e); + error!( + event = EVENT_SWIFT_BULK_EXTRACT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + result = "upload_failed", + container = %container, + object = %path_str, + error = %e, + "swift bulk extract state changed" + ); response.errors.push(vec![path_str.clone(), e.to_string()]); } } @@ -430,14 +494,29 @@ async fn extract_tar_entries(format: ArchiveFormat, body: Vec) -> SwiftResul // Skip directories if entry.header().entry_type().is_dir() { - debug!("Skipping directory: {}", path_str); + debug!( + event = EVENT_SWIFT_BULK_EXTRACT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + state = "skipped_directory", + path = %path_str, + "swift bulk extract state changed" + ); continue; } // Read file contents let mut contents = Vec::new(); if let Err(e) = tokio::io::AsyncReadExt::read_to_end(&mut entry, &mut contents).await { - error!("Failed to read tar entry {}: {}", path_str, e); + error!( + event = EVENT_SWIFT_BULK_EXTRACT_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_BULK, + result = "tar_entry_read_failed", + path = %path_str, + error = %e, + "swift bulk extract state changed" + ); continue; } diff --git a/crates/protocols/src/swift/container.rs b/crates/protocols/src/swift/container.rs index 9a1047f69..df2d9d3db 100644 --- a/crates/protocols/src/swift/container.rs +++ b/crates/protocols/src/swift/container.rs @@ -27,13 +27,25 @@ use s3s::dto::{Tag, Tagging}; use sha2::{Digest, Sha256}; use tracing::{debug, error}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_CONTAINER: &str = "swift_container"; +const EVENT_SWIFT_CONTAINER_STORAGE_STATE: &str = "swift_container_storage_state"; + /// Sanitize storage layer errors for client responses /// /// Logs detailed error server-side while returning generic message to client. /// This prevents information disclosure vulnerabilities. fn sanitize_storage_error(operation: &str, error: E) -> SwiftError { // Log detailed error server-side - error!("Storage operation '{}' failed: {}", operation, error); + error!( + event = EVENT_SWIFT_CONTAINER_STORAGE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_CONTAINER, + operation = %operation, + error = %error, + result = "failed", + "swift container storage state changed" + ); // Return generic error to client SwiftError::InternalServerError(format!("{} operation failed", operation)) @@ -247,6 +259,17 @@ pub async fn list_containers(account: &str, credentials: &Credentials) -> SwiftR .filter_map(|info| bucket_info_to_container(info, &mapper, &project_id)) .collect(); + debug!( + event = EVENT_SWIFT_CONTAINER_STORAGE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_CONTAINER, + operation = "list_containers", + account = %account, + container_count = containers.len(), + result = "ok", + "swift container storage state changed" + ); + Ok(containers) } diff --git a/crates/protocols/src/swift/cors.rs b/crates/protocols/src/swift/cors.rs index 4e9e63a75..d9d59de08 100644 --- a/crates/protocols/src/swift/cors.rs +++ b/crates/protocols/src/swift/cors.rs @@ -56,6 +56,10 @@ use rustfs_credentials::Credentials; use s3s::Body; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_CORS: &str = "swift_cors"; +const EVENT_SWIFT_CORS_STATE: &str = "swift_cors_state"; + /// CORS configuration for a container #[derive(Debug, Clone, Default)] pub struct CorsConfig { @@ -164,7 +168,15 @@ pub async fn handle_preflight( credentials: &Credentials, request_headers: &HeaderMap, ) -> SwiftResult> { - debug!("CORS preflight request for container: {}", container_name); + debug!( + event = EVENT_SWIFT_CORS_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_CORS, + state = "preflight_requested", + account = %account, + container = %container_name, + "swift cors state changed" + ); // Load CORS configuration let config = CorsConfig::load(account, container_name, credentials).await?; diff --git a/crates/protocols/src/swift/encryption.rs b/crates/protocols/src/swift/encryption.rs index d3051db67..aef9354c6 100644 --- a/crates/protocols/src/swift/encryption.rs +++ b/crates/protocols/src/swift/encryption.rs @@ -63,6 +63,10 @@ use base64::{Engine as _, engine::general_purpose::STANDARD as BASE64}; use std::collections::HashMap; use tracing::{debug, warn}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_ENCRYPTION: &str = "swift_encryption"; +const EVENT_SWIFT_ENCRYPTION_STATE: &str = "swift_encryption_state"; + /// Encryption algorithm identifier #[derive(Debug, Clone, PartialEq)] pub enum EncryptionAlgorithm { @@ -270,7 +274,13 @@ pub fn should_encrypt(config: &EncryptionConfig, headers: &http::HeaderMap) -> b if let Some(disable) = headers.get("x-object-meta-crypto-disable") && disable.to_str().unwrap_or("") == "true" { - debug!("Client explicitly disabled encryption"); + debug!( + event = EVENT_SWIFT_ENCRYPTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ENCRYPTION, + state = "disabled_by_client", + "swift encryption state changed" + ); return false; } @@ -305,7 +315,15 @@ pub fn generate_iv(size: usize) -> Vec { /// In production, this would use a proper crypto library like `aes-gcm` or `ring`. /// This is a stub that demonstrates the API structure. pub fn encrypt_data(data: &[u8], config: &EncryptionConfig) -> SwiftResult<(Vec, EncryptionMetadata)> { - debug!("Encrypting {} bytes with {}", data.len(), config.algorithm.as_str()); + debug!( + event = EVENT_SWIFT_ENCRYPTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ENCRYPTION, + state = "encrypting", + input_bytes = data.len(), + algorithm = config.algorithm.as_str(), + "swift encryption state changed" + ); // Generate IV (12 bytes for GCM, 16 bytes for CBC) let iv_size = match config.algorithm { @@ -327,7 +345,14 @@ pub fn encrypt_data(data: &[u8], config: &EncryptionConfig) -> SwiftResult<(Vec< // let ciphertext = cipher.encrypt(nonce, data) // .map_err(|e| SwiftError::InternalServerError(format!("Encryption failed: {}", e)))?; - warn!("Encryption not yet implemented - returning plaintext with metadata"); + warn!( + event = EVENT_SWIFT_ENCRYPTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ENCRYPTION, + result = "not_implemented", + mode = "encrypt", + "swift encryption state changed" + ); let metadata = EncryptionMetadata::new(config.algorithm.clone(), config.key_id.clone(), iv); @@ -340,7 +365,15 @@ pub fn encrypt_data(data: &[u8], config: &EncryptionConfig) -> SwiftResult<(Vec< /// In production, this would use a proper crypto library like `aes-gcm` or `ring`. /// This is a stub that demonstrates the API structure. pub fn decrypt_data(encrypted_data: &[u8], metadata: &EncryptionMetadata, config: &EncryptionConfig) -> SwiftResult> { - debug!("Decrypting {} bytes with {}", encrypted_data.len(), metadata.algorithm.as_str()); + debug!( + event = EVENT_SWIFT_ENCRYPTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ENCRYPTION, + state = "decrypting", + input_bytes = encrypted_data.len(), + algorithm = metadata.algorithm.as_str(), + "swift encryption state changed" + ); // Verify key ID matches if metadata.key_id != config.key_id { @@ -361,7 +394,14 @@ pub fn decrypt_data(encrypted_data: &[u8], metadata: &EncryptionMetadata, config // let plaintext = cipher.decrypt(nonce, encrypted_data) // .map_err(|e| SwiftError::InternalServerError(format!("Decryption failed: {}", e)))?; - warn!("Decryption not yet implemented - returning data as-is"); + warn!( + event = EVENT_SWIFT_ENCRYPTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_ENCRYPTION, + result = "not_implemented", + mode = "decrypt", + "swift encryption state changed" + ); // In production, return plaintext Ok(encrypted_data.to_vec()) diff --git a/crates/protocols/src/swift/expiration.rs b/crates/protocols/src/swift/expiration.rs index d5a3d150f..f9d0ad3e9 100644 --- a/crates/protocols/src/swift/expiration.rs +++ b/crates/protocols/src/swift/expiration.rs @@ -57,6 +57,10 @@ use super::{SwiftError, SwiftResult}; use std::time::{SystemTime, UNIX_EPOCH}; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_EXPIRATION: &str = "swift_expiration"; +const EVENT_SWIFT_EXPIRATION_STATE: &str = "swift_expiration_state"; + /// Parse X-Delete-At header value /// /// Returns Unix timestamp in seconds @@ -92,7 +96,7 @@ pub fn extract_expiration(headers: &http::HeaderMap) -> SwiftResult> && let Ok(value_str) = delete_after.to_str() { let delete_at = parse_delete_after(value_str)?; - debug!("X-Delete-After: {} seconds -> X-Delete-At: {}", value_str, delete_at); + debug!(event = EVENT_SWIFT_EXPIRATION_STATE, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, state = "delete_after_parsed", delete_after = %value_str, delete_at, "swift expiration state changed"); return Ok(Some(delete_at)); } @@ -101,7 +105,14 @@ pub fn extract_expiration(headers: &http::HeaderMap) -> SwiftResult> && let Ok(value_str) = delete_at.to_str() { let timestamp = parse_delete_at(value_str)?; - debug!("X-Delete-At: {}", timestamp); + debug!( + event = EVENT_SWIFT_EXPIRATION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "delete_at_parsed", + delete_at = timestamp, + "swift expiration state changed" + ); return Ok(Some(timestamp)); } @@ -137,7 +148,14 @@ pub fn validate_expiration(delete_at: u64) -> SwiftResult<()> { // Warn if expiration is more than 10 years in the future let ten_years = 10 * 365 * 24 * 60 * 60; if delete_at > now + ten_years { - debug!("X-Delete-At timestamp is more than 10 years in the future: {}", delete_at); + debug!( + event = EVENT_SWIFT_EXPIRATION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "far_future_timestamp", + delete_at, + "swift expiration state changed" + ); } Ok(()) diff --git a/crates/protocols/src/swift/expiration_worker.rs b/crates/protocols/src/swift/expiration_worker.rs index c574ac27a..e97e26f58 100644 --- a/crates/protocols/src/swift/expiration_worker.rs +++ b/crates/protocols/src/swift/expiration_worker.rs @@ -57,6 +57,14 @@ use tokio::sync::RwLock; use tokio::time::interval; use tracing::{debug, error, info, warn}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_EXPIRATION: &str = "swift_expiration_worker"; +const EVENT_SWIFT_EXPIRATION_WORKER_STATE: &str = "swift_expiration_worker_state"; +const EVENT_SWIFT_EXPIRATION_OBJECT_TRACKING: &str = "swift_expiration_object_tracking"; +const EVENT_SWIFT_EXPIRATION_ITERATION_SUMMARY: &str = "swift_expiration_iteration_summary"; +const EVENT_SWIFT_EXPIRATION_DELETE_STATE: &str = "swift_expiration_delete_state"; +const EVENT_SWIFT_EXPIRATION_SCAN_STATE: &str = "swift_expiration_scan_state"; + /// Configuration for expiration worker #[derive(Debug, Clone)] pub struct ExpirationWorkerConfig { @@ -156,15 +164,29 @@ impl ExpirationWorker { pub async fn start(&self) { let mut running = self.running.write().await; if *running { - warn!("Expiration worker already running"); + warn!( + event = EVENT_SWIFT_EXPIRATION_WORKER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "already_running", + worker_id = self.config.worker_id, + max_workers = self.config.max_workers, + "swift expiration worker state changed" + ); return; } *running = true; drop(running); info!( - "Starting expiration worker (scan_interval={}s, worker_id={}/{})", - self.config.scan_interval_secs, self.config.worker_id, self.config.max_workers + event = EVENT_SWIFT_EXPIRATION_WORKER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "started", + scan_interval_secs = self.config.scan_interval_secs, + worker_id = self.config.worker_id, + max_workers = self.config.max_workers, + "swift expiration worker state changed" ); let config = self.config.clone(); @@ -180,13 +202,28 @@ impl ExpirationWorker { // Check if still running if !*running.read().await { - info!("Expiration worker stopped"); + info!( + event = EVENT_SWIFT_EXPIRATION_WORKER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "stopped", + worker_id = config.worker_id, + "swift expiration worker state changed" + ); break; } // Run cleanup iteration if let Err(e) = Self::cleanup_iteration(&config, &priority_queue, &metrics).await { - error!("Expiration cleanup iteration failed: {}", e); + error!( + event = EVENT_SWIFT_EXPIRATION_ITERATION_SUMMARY, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "error", + worker_id = config.worker_id, + error = %e, + "swift expiration iteration summary" + ); metrics.write().await.error_count += 1; } } @@ -197,7 +234,14 @@ impl ExpirationWorker { pub async fn stop(&self) { let mut running = self.running.write().await; *running = false; - info!("Stopping expiration worker"); + info!( + event = EVENT_SWIFT_EXPIRATION_WORKER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "stopping", + worker_id = self.config.worker_id, + "swift expiration worker state changed" + ); } /// Get current metrics @@ -213,7 +257,17 @@ impl ExpirationWorker { // Check if this worker should handle this object (distributed hashing) if !self.should_handle_object(&path) { - debug!("Skipping object {} (handled by different worker)", path); + debug!( + event = EVENT_SWIFT_EXPIRATION_OBJECT_TRACKING, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "skipped", + reason = "assigned_to_other_worker", + path = %path, + worker_id = self.config.worker_id, + max_workers = self.config.max_workers, + "swift expiration object tracking changed" + ); return; } @@ -225,7 +279,16 @@ impl ExpirationWorker { let mut queue = self.priority_queue.write().await; queue.push(Reverse(entry)); - debug!("Tracking object {} for expiration at {}", path, expires_at); + debug!( + event = EVENT_SWIFT_EXPIRATION_OBJECT_TRACKING, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "tracked", + path = %path, + expires_at, + worker_id = self.config.worker_id, + "swift expiration object tracking changed" + ); } /// Remove object from expiration tracking @@ -238,7 +301,15 @@ impl ExpirationWorker { // the cleanup iteration to skip objects that no longer exist. // This is acceptable because the queue size is bounded and cleanup is periodic. - debug!("Untracking object {} from expiration", path); + debug!( + event = EVENT_SWIFT_EXPIRATION_OBJECT_TRACKING, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "untracked", + path = %path, + worker_id = self.config.worker_id, + "swift expiration object tracking changed" + ); } /// Check if this worker should handle the given object (consistent hashing) @@ -273,7 +344,15 @@ impl ExpirationWorker { let start_time = SystemTime::now(); let now = start_time.duration_since(UNIX_EPOCH).unwrap().as_secs(); - info!("Starting expiration cleanup iteration (worker_id={})", config.worker_id); + debug!( + event = EVENT_SWIFT_EXPIRATION_ITERATION_SUMMARY, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "started", + worker_id = config.worker_id, + batch_size = config.batch_size, + "swift expiration iteration summary" + ); let mut deleted_count = 0; let mut scanned_count = 0; @@ -313,7 +392,15 @@ impl ExpirationWorker { // Parse path: "account/container/object" let parts: Vec<&str> = entry.path.splitn(3, '/').collect(); if parts.len() != 3 { - warn!("Invalid expiration entry path: {}", entry.path); + warn!( + event = EVENT_SWIFT_EXPIRATION_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "invalid_path", + path = %entry.path, + worker_id = config.worker_id, + "swift expiration delete state changed" + ); continue; } @@ -323,13 +410,42 @@ impl ExpirationWorker { match Self::delete_expired_object(account, container, object, entry.expires_at).await { Ok(true) => { deleted_count += 1; - info!("Deleted expired object: {}", entry.path); + debug!( + event = EVENT_SWIFT_EXPIRATION_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "deleted", + path = %entry.path, + expires_at = entry.expires_at, + worker_id = config.worker_id, + "swift expiration delete state changed" + ); } Ok(false) => { - debug!("Object {} no longer exists or expiration removed", entry.path); + debug!( + event = EVENT_SWIFT_EXPIRATION_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "not_deleted", + reason = "missing_or_expiration_removed", + path = %entry.path, + expires_at = entry.expires_at, + worker_id = config.worker_id, + "swift expiration delete state changed" + ); } Err(e) => { - error!("Failed to delete expired object {}: {}", entry.path, e); + error!( + event = EVENT_SWIFT_EXPIRATION_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "delete_failed", + path = %entry.path, + expires_at = entry.expires_at, + worker_id = config.worker_id, + error = %e, + "swift expiration delete state changed" + ); metrics.write().await.error_count += 1; } } @@ -345,8 +461,17 @@ impl ExpirationWorker { m.queue_size = priority_queue.read().await.len(); info!( - "Expiration cleanup iteration complete: scanned={}, deleted={}, duration={}ms, queue_size={}", - scanned_count, deleted_count, m.last_scan_duration_ms, m.queue_size + event = EVENT_SWIFT_EXPIRATION_ITERATION_SUMMARY, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "completed", + worker_id = config.worker_id, + scanned_count, + deleted_count, + duration_ms = m.last_scan_duration_ms, + queue_size = m.queue_size, + error_count = m.error_count, + "swift expiration iteration summary" ); Ok(()) @@ -368,8 +493,15 @@ impl ExpirationWorker { // For now, we'll log the deletion debug!( - "Would delete expired object: {}/{}/{} (expires_at={})", - account, container, object, expected_expires_at + event = EVENT_SWIFT_EXPIRATION_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "delete_candidate", + account = %account, + container = %container, + object = %object, + expires_at = expected_expires_at, + "swift expiration delete state changed" ); // TODO: Integrate with actual object storage @@ -390,13 +522,28 @@ impl ExpirationWorker { /// This is used for initial population or recovery after restart. /// In production, objects should be tracked incrementally via track_object(). pub async fn scan_all_objects(&self) -> SwiftResult<()> { - info!("Starting full scan of objects with expiration (worker_id={})", self.config.worker_id); + info!( + event = EVENT_SWIFT_EXPIRATION_SCAN_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + state = "started", + worker_id = self.config.worker_id, + max_workers = self.config.max_workers, + "swift expiration scan state changed" + ); // TODO: This would integrate with the storage layer to list all objects // For each object with X-Delete-At metadata, call track_object() // Placeholder implementation - warn!("Full object scan not yet implemented - requires storage layer integration"); + warn!( + event = EVENT_SWIFT_EXPIRATION_SCAN_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_EXPIRATION, + result = "unimplemented", + worker_id = self.config.worker_id, + "swift expiration scan state changed" + ); Ok(()) } diff --git a/crates/protocols/src/swift/formpost.rs b/crates/protocols/src/swift/formpost.rs index 9c2c48846..a49ebe95e 100644 --- a/crates/protocols/src/swift/formpost.rs +++ b/crates/protocols/src/swift/formpost.rs @@ -85,6 +85,10 @@ use sha1::Sha1; use std::time::{SystemTime, UNIX_EPOCH}; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_FORMPOST: &str = "swift_formpost"; +const EVENT_SWIFT_FORMPOST_STATE: &str = "swift_formpost_state"; + type HmacSha1 = Hmac; /// FormPost request parameters @@ -206,7 +210,13 @@ pub fn validate_formpost(path: &str, request: &FormPostRequest, key: &str) -> Sw )?; if request.signature != expected_sig { - debug!("FormPost signature mismatch: expected={}, got={}", expected_sig, request.signature); + debug!( + event = EVENT_SWIFT_FORMPOST_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_FORMPOST, + result = "signature_mismatch", + "swift formpost state changed" + ); return Err(SwiftError::Unauthorized("Invalid FormPost signature".to_string())); } @@ -433,7 +443,16 @@ pub async fn handle_formpost( match super::object::put_object(account, container, object_name, credentials, reader, &upload_headers).await { Ok(_) => { - debug!("FormPost uploaded: {}/{}/{}", account, container, object_name); + debug!( + event = EVENT_SWIFT_FORMPOST_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_FORMPOST, + state = "uploaded", + account = %account, + container = %container, + object = %object_name, + "swift formpost state changed" + ); } Err(e) => { upload_errors.push(format!("{}: {}", file.filename, e)); diff --git a/crates/protocols/src/swift/handler.rs b/crates/protocols/src/swift/handler.rs index 2fc7e1681..4ad9294de 100644 --- a/crates/protocols/src/swift/handler.rs +++ b/crates/protocols/src/swift/handler.rs @@ -35,6 +35,11 @@ use tokio_util::io::StreamReader; use tower::Service; use tracing::{debug, instrument}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_HANDLER: &str = "swift_handler"; +const EVENT_SWIFT_ROUTE_STATE: &str = "swift_route_state"; +const EVENT_SWIFT_TEMPURL_STATE: &str = "swift_tempurl_state"; + /// Swift-aware service that routes to Swift handlers or S3 service #[derive(Clone)] pub struct SwiftService { @@ -75,7 +80,14 @@ where let uri = req.uri(); if let Some(route) = self.router.route(uri, method.clone()) { - debug!("Swift route matched: {:?}", route); + debug!( + event = EVENT_SWIFT_ROUTE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_HANDLER, + state = "matched", + route = ?route, + "swift route state changed" + ); // Extract credentials from Keystone task-local storage (if available) // This is consistent with how S3 auth handler retrieves Keystone credentials @@ -98,7 +110,13 @@ where } // Not a Swift request, delegate to S3 service - debug!("No Swift route matched, delegating to S3 service"); + debug!( + event = EVENT_SWIFT_ROUTE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_HANDLER, + state = "delegated_to_s3", + "swift route state changed" + ); let mut s3_service = self.s3_service.clone(); Box::pin(async move { s3_service.call(req).await.map_err(Into::into) }) } @@ -127,7 +145,16 @@ async fn handle_swift_request( && let Some(tempurl_params) = tempurl::TempURLParams::from_query(query) { // TempURL detected - validate it - debug!("TempURL detected for {}/{}/{}", account, container, object); + debug!( + event = EVENT_SWIFT_TEMPURL_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_HANDLER, + state = "detected", + account = %account, + container = %container, + object = %object, + "swift tempurl state changed" + ); // Get account TempURL key let tempurl_key = super::account::get_tempurl_key(account, &credentials).await?; @@ -140,7 +167,16 @@ async fn handle_swift_request( tempurl.validate_request(method.as_str(), path, &tempurl_params)?; // TempURL is valid - proceed with request (no credentials needed) - debug!("TempURL validated successfully"); + debug!( + event = EVENT_SWIFT_TEMPURL_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_HANDLER, + result = "validated", + account = %account, + container = %container, + object = %object, + "swift tempurl state changed" + ); // Reconstruct request for object operation let req = Request::from_parts(parts, body); @@ -904,7 +940,14 @@ async fn handle_authenticated_request( .await .unwrap_or_else(|e| { // Log restore error but don't fail the DELETE - tracing::warn!("Failed to restore version after delete: {}", e); + tracing::warn!( + event = EVENT_SWIFT_TEMPURL_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_HANDLER, + result = "restore_after_delete_failed", + error = %e, + "swift tempurl state changed" + ); false }); diff --git a/crates/protocols/src/swift/object.rs b/crates/protocols/src/swift/object.rs index 4d4109015..5d9eb4f42 100644 --- a/crates/protocols/src/swift/object.rs +++ b/crates/protocols/src/swift/object.rs @@ -62,6 +62,10 @@ use std::collections::HashMap; use tracing::debug; use tracing::error; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_OBJECT: &str = "swift_object"; +const EVENT_SWIFT_OBJECT_STORAGE_STATE: &str = "swift_object_storage_state"; + /// Maximum number of metadata headers allowed per object (Swift standard) const MAX_METADATA_COUNT: usize = 90; @@ -258,7 +262,15 @@ fn validate_metadata(metadata: &HashMap) -> SwiftResult<()> { /// This prevents information disclosure vulnerabilities. fn sanitize_storage_error(operation: &str, error: E) -> SwiftError { // Log detailed error server-side - error!("Storage operation '{}' failed: {}", operation, error); + error!( + event = EVENT_SWIFT_OBJECT_STORAGE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_OBJECT, + operation = %operation, + error = %error, + result = "failed", + "swift object storage state changed" + ); // Return generic error to client SwiftError::InternalServerError(format!("{} operation failed", operation)) @@ -334,7 +346,14 @@ where // Store the fully qualified target (container/object) let target_value = symlink_target.to_header_value(container); user_metadata.insert("x-object-symlink-target".to_string(), target_value); - debug!("Creating symlink to target: {}", user_metadata.get("x-object-symlink-target").unwrap()); + debug!( + event = EVENT_SWIFT_OBJECT_STORAGE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_OBJECT, + state = "symlink_target_recorded", + target = %user_metadata.get("x-object-symlink-target").unwrap(), + "swift object storage state changed" + ); } // 9. Validate metadata limits diff --git a/crates/protocols/src/swift/quota.rs b/crates/protocols/src/swift/quota.rs index b75e4487c..9c79c3a9d 100644 --- a/crates/protocols/src/swift/quota.rs +++ b/crates/protocols/src/swift/quota.rs @@ -70,6 +70,10 @@ use super::{SwiftError, SwiftResult, container}; use rustfs_credentials::Credentials; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_QUOTA: &str = "swift_quota"; +const EVENT_SWIFT_QUOTA_STATE: &str = "swift_quota_state"; + /// Quota configuration for a container #[derive(Debug, Clone, Default)] pub struct QuotaConfig { @@ -161,8 +165,16 @@ pub async fn check_upload_quota( quota.check_quota(metadata.bytes_used, metadata.object_count, object_size)?; debug!( - "Quota check passed: {}/{:?} bytes, {}/{:?} objects", - metadata.bytes_used, quota.quota_bytes, metadata.object_count, quota.quota_count + event = EVENT_SWIFT_QUOTA_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_QUOTA, + state = "check_passed", + current_bytes = metadata.bytes_used, + quota_bytes = ?quota.quota_bytes, + current_count = metadata.object_count, + quota_count = ?quota.quota_count, + object_size, + "swift quota state changed" ); Ok(()) diff --git a/crates/protocols/src/swift/ratelimit.rs b/crates/protocols/src/swift/ratelimit.rs index 589cec6f5..e9a76a407 100644 --- a/crates/protocols/src/swift/ratelimit.rs +++ b/crates/protocols/src/swift/ratelimit.rs @@ -64,6 +64,10 @@ use std::sync::{Arc, Mutex}; use std::time::{SystemTime, UNIX_EPOCH}; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_RATELIMIT: &str = "swift_ratelimit"; +const EVENT_SWIFT_RATELIMIT_STATE: &str = "swift_ratelimit_state"; + /// Rate limit configuration #[derive(Debug, Clone, PartialEq)] pub struct RateLimit { @@ -221,11 +225,11 @@ impl RateLimiter { match bucket.try_consume() { Ok(remaining) => { - debug!("Rate limit OK for {}: {} remaining", key, remaining); + debug!(event = EVENT_SWIFT_RATELIMIT_STATE, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_RATELIMIT, key = %key, remaining, result = "allowed", "swift ratelimit state changed"); Ok((remaining, reset)) } Err(retry_after) => { - debug!("Rate limit exceeded for {}: retry after {} seconds", key, retry_after); + debug!(event = EVENT_SWIFT_RATELIMIT_STATE, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_RATELIMIT, key = %key, retry_after, result = "limited", "swift ratelimit state changed"); Err(SwiftError::TooManyRequests { retry_after, limit: rate_limit.limit, diff --git a/crates/protocols/src/swift/staticweb.rs b/crates/protocols/src/swift/staticweb.rs index aa849e892..9ee550a50 100644 --- a/crates/protocols/src/swift/staticweb.rs +++ b/crates/protocols/src/swift/staticweb.rs @@ -73,6 +73,10 @@ use rustfs_credentials::Credentials; use s3s::Body; use tracing::debug; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_STATICWEB: &str = "swift_staticweb"; +const EVENT_SWIFT_STATICWEB_STATE: &str = "swift_staticweb_state"; + /// Static website configuration for a container #[derive(Debug, Clone, Default)] pub struct StaticWebConfig { @@ -376,14 +380,33 @@ pub async fn handle_static_web_get( return Err(SwiftError::InternalServerError("Static web not enabled for this container".to_string())); } - debug!("Static web request: container={}, path={}, config={:?}", container, path, config); + debug!( + event = EVENT_SWIFT_STATICWEB_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_STATICWEB, + state = "requested", + container = %container, + path = %path, + listings_enabled = config.listings_enabled(), + index_document = config.index_document().unwrap_or_default(), + error_document = config.error_document().unwrap_or_default(), + "swift staticweb state changed" + ); // Resolve path let (object_path, _is_index, is_listing) = resolve_path(path, &config); if is_listing { // Generate directory listing - debug!("Generating directory listing for path: {}", object_path); + debug!( + event = EVENT_SWIFT_STATICWEB_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_STATICWEB, + state = "listing_generated", + container = %container, + path = %object_path, + "swift staticweb state changed" + ); // List objects with prefix let prefix = if object_path.is_empty() { @@ -419,7 +442,15 @@ pub async fn handle_static_web_get( } // Try to serve the object - debug!("Attempting to serve object: {}", object_path); + debug!( + event = EVENT_SWIFT_STATICWEB_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_STATICWEB, + state = "serving_object", + container = %container, + path = %object_path, + "swift staticweb state changed" + ); match object::get_object(account, container, &object_path, credentials, None).await { Ok(reader) => { @@ -446,7 +477,16 @@ pub async fn handle_static_web_get( Err(SwiftError::NotFound(_)) => { // Object not found - try to serve error document if let Some(error_doc) = config.error_document() { - debug!("Serving error document: {}", error_doc); + debug!( + event = EVENT_SWIFT_STATICWEB_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_STATICWEB, + state = "serving_error_document", + container = %container, + path = %object_path, + error_document = %error_doc, + "swift staticweb state changed" + ); match object::get_object(account, container, error_doc, credentials, None).await { Ok(reader) => { @@ -470,7 +510,15 @@ pub async fn handle_static_web_get( } Err(_) => { // Error document also not found - return standard 404 - debug!("Error document not found, returning standard 404"); + debug!( + event = EVENT_SWIFT_STATICWEB_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_STATICWEB, + result = "error_document_missing", + container = %container, + error_document = %error_doc, + "swift staticweb state changed" + ); } } } diff --git a/crates/protocols/src/swift/symlink.rs b/crates/protocols/src/swift/symlink.rs index d0400960d..94d8a6197 100644 --- a/crates/protocols/src/swift/symlink.rs +++ b/crates/protocols/src/swift/symlink.rs @@ -62,6 +62,10 @@ use super::{SwiftError, SwiftResult}; use std::collections::HashSet; use tracing::{debug, warn}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_SYMLINK: &str = "swift_symlink"; +const EVENT_SWIFT_SYMLINK_STATE: &str = "swift_symlink_state"; + /// Maximum symlink follow depth to prevent infinite loops const MAX_SYMLINK_DEPTH: u8 = 5; @@ -158,7 +162,15 @@ pub fn extract_symlink_target(headers: &http::HeaderMap) -> SwiftResult, account: &str, c if visited.contains(&path) { warn!( + event = EVENT_SWIFT_SYMLINK_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_SYMLINK, account = %account, container = %container, object = %object, - "Circular symlink reference detected" + result = "circular_reference_detected", + "swift symlink state changed" ); return Err(SwiftError::Conflict(format!( "Circular symlink reference detected: {}/{}/{}", diff --git a/crates/protocols/src/swift/sync.rs b/crates/protocols/src/swift/sync.rs index fdaa8e7e8..60a8749ec 100644 --- a/crates/protocols/src/swift/sync.rs +++ b/crates/protocols/src/swift/sync.rs @@ -53,6 +53,11 @@ use super::{SwiftError, SwiftResult}; use std::collections::HashMap; use tracing::{debug, warn}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_SYNC: &str = "swift_sync"; +const EVENT_SWIFT_SYNC_CONFIG_STATE: &str = "swift_sync_config_state"; +const EVENT_SWIFT_SYNC_RETRY_STATE: &str = "swift_sync_retry_state"; + /// Container sync configuration #[derive(Debug, Clone, PartialEq)] pub struct SyncConfig { @@ -109,12 +114,19 @@ impl SyncConfig { // Warn if using HTTP instead of HTTPS if self.sync_to.starts_with("http://") { - warn!("Container sync using unencrypted HTTP - consider using HTTPS"); + warn!(event = EVENT_SWIFT_SYNC_CONFIG_STATE, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_SYNC, result = "unencrypted_http", sync_to = %self.sync_to, "swift sync config state changed"); } // Validate key length (recommend at least 16 characters) if self.sync_key.len() < 16 { - warn!("Container sync key is short (<16 chars) - recommend longer key"); + warn!( + event = EVENT_SWIFT_SYNC_CONFIG_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_SYNC, + result = "short_key", + key_length = self.sync_key.len(), + "swift sync config state changed" + ); } Ok(()) @@ -211,7 +223,7 @@ impl SyncQueueEntry { let backoff_seconds = std::cmp::min(60 * (1 << (self.retry_count - 1)), 3600); self.next_retry = current_time + backoff_seconds; - debug!("Scheduled retry #{} for '{}' at +{}s", self.retry_count, self.object, backoff_seconds); + debug!(event = EVENT_SWIFT_SYNC_RETRY_STATE, component = LOG_COMPONENT_PROTOCOLS, subsystem = LOG_SUBSYSTEM_SWIFT_SYNC, state = "scheduled", retry_count = self.retry_count, object = %self.object, backoff_seconds, "swift sync retry state changed"); } /// Check if ready for retry diff --git a/crates/protocols/src/swift/versioning.rs b/crates/protocols/src/swift/versioning.rs index 615f5d9ef..84799b66d 100644 --- a/crates/protocols/src/swift/versioning.rs +++ b/crates/protocols/src/swift/versioning.rs @@ -61,6 +61,12 @@ use rustfs_ecstore::store_api::{ListOperations, ObjectOperations, ObjectOptions} use std::time::{SystemTime, UNIX_EPOCH}; use tracing::{debug, error}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_SWIFT_VERSIONING: &str = "swift_versioning"; +const EVENT_SWIFT_VERSIONING_ARCHIVE_STATE: &str = "swift_versioning_archive_state"; +const EVENT_SWIFT_VERSIONING_RESTORE_STATE: &str = "swift_versioning_restore_state"; +const EVENT_SWIFT_VERSIONING_LIST_STATE: &str = "swift_versioning_list_state"; + /// Generate a version name for an archived object /// /// Version names use inverted timestamps to sort newest-first: @@ -131,8 +137,15 @@ pub async fn archive_current_version( credentials: &Credentials, ) -> SwiftResult<()> { debug!( - "Archiving current version of {}/{}/{} to {}", - account, container, object, archive_container + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + state = "started", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + "swift versioning archive state changed" ); // Check if object exists @@ -140,7 +153,18 @@ pub async fn archive_current_version( Ok(info) => info, Err(SwiftError::NotFound(_)) => { // Object doesn't exist - nothing to archive - debug!("Object does not exist, nothing to archive"); + debug!( + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "skipped", + reason = "object_missing", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + "swift versioning archive state changed" + ); return Ok(()); } Err(e) => return Err(e), @@ -149,7 +173,16 @@ pub async fn archive_current_version( // Generate version name let version_name = generate_version_name(container, object); - debug!("Generated version name: {}", version_name); + debug!( + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + state = "version_name_generated", + container = %container, + object = %object, + version_name = %version_name, + "swift versioning archive state changed" + ); // Validate account and get project_id let project_id = validate_account_access(account, credentials)?; @@ -174,7 +207,18 @@ pub async fn archive_current_version( // Get source object info for copy operation let mut src_info = store.get_object_info(&source_bucket, &source_key, &opts).await.map_err(|e| { - error!("Failed to get source object info: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "source_info_failed", + source_bucket = %source_bucket, + source_key = %source_key, + archive_bucket = %archive_bucket, + version_key = %version_key, + error = %e, + "swift versioning archive state changed" + ); SwiftError::InternalServerError(format!("Failed to get object info for archiving: {}", e)) })?; @@ -182,11 +226,33 @@ pub async fn archive_current_version( .copy_object(&source_bucket, &source_key, &archive_bucket, &version_key, &mut src_info, &opts, &opts) .await .map_err(|e| { - error!("Failed to copy object to archive: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "copy_failed", + source_bucket = %source_bucket, + source_key = %source_key, + archive_bucket = %archive_bucket, + version_key = %version_key, + error = %e, + "swift versioning archive state changed" + ); SwiftError::InternalServerError(format!("Failed to archive version: {}", e)) })?; - debug!("Successfully archived version to {}/{}", archive_container, version_name); + debug!( + event = EVENT_SWIFT_VERSIONING_ARCHIVE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "archived", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + version_name = %version_name, + "swift versioning archive state changed" + ); Ok(()) } @@ -220,22 +286,46 @@ pub async fn restore_previous_version( credentials: &Credentials, ) -> SwiftResult { debug!( - "Restoring previous version of {}/{}/{} from {}", - account, container, object, archive_container + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + state = "started", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + "swift versioning restore state changed" ); // List versions for this object let versions = list_object_versions(account, container, object, archive_container, credentials).await?; if versions.is_empty() { - debug!("No versions found to restore"); + debug!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "not_found", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + "swift versioning restore state changed" + ); return Ok(false); } // Get newest version (first in list, since they're sorted newest-first) let newest_version = &versions[0]; - debug!("Restoring version: {}", newest_version); + debug!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + state = "selected", + version_name = %newest_version, + "swift versioning restore state changed" + ); // Validate account and get project_id let project_id = validate_account_access(account, credentials)?; @@ -261,7 +351,18 @@ pub async fn restore_previous_version( .get_object_info(&archive_bucket, &version_key, &opts) .await .map_err(|e| { - error!("Failed to get version object info: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "version_info_failed", + archive_bucket = %archive_bucket, + version_key = %version_key, + target_bucket = %target_bucket, + target_key = %target_key, + error = %e, + "swift versioning restore state changed" + ); SwiftError::InternalServerError(format!("Failed to get version info for restore: {}", e)) })?; @@ -278,18 +379,49 @@ pub async fn restore_previous_version( ) .await .map_err(|e| { - error!("Failed to restore version: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "copy_failed", + archive_bucket = %archive_bucket, + version_key = %version_key, + target_bucket = %target_bucket, + target_key = %target_key, + error = %e, + "swift versioning restore state changed" + ); SwiftError::InternalServerError(format!("Failed to restore version: {}", e)) })?; // Delete the version from archive after successful restore store.delete_object(&archive_bucket, &version_key, opts).await.map_err(|e| { - error!("Failed to delete archived version after restore: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "archive_cleanup_failed", + archive_bucket = %archive_bucket, + version_key = %version_key, + error = %e, + "swift versioning restore state changed" + ); // Don't fail the restore if deletion fails - object is restored SwiftError::InternalServerError(format!("Version restored but cleanup failed: {}", e)) })?; - debug!("Successfully restored version from {}", newest_version); + debug!( + event = EVENT_SWIFT_VERSIONING_RESTORE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "restored", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + version_name = %newest_version, + "swift versioning restore state changed" + ); Ok(true) } @@ -324,7 +456,17 @@ pub async fn list_object_versions( archive_container: &str, credentials: &Credentials, ) -> SwiftResult> { - debug!("Listing versions of {}/{}/{} in {}", account, container, object, archive_container); + debug!( + event = EVENT_SWIFT_VERSIONING_LIST_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + state = "started", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + "swift versioning list state changed" + ); // Validate account and get project_id let project_id = validate_account_access(account, credentials)?; @@ -359,7 +501,15 @@ pub async fn list_object_versions( ) .await .map_err(|e| { - error!("Failed to list archive container: {}", e); + error!( + event = EVENT_SWIFT_VERSIONING_LIST_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "archive_list_failed", + archive_bucket = %archive_bucket, + error = %e, + "swift versioning list state changed" + ); SwiftError::InternalServerError(format!("Failed to list versions: {}", e)) })?; @@ -382,7 +532,18 @@ pub async fn list_object_versions( // gives us newest first because smaller numbers sort first lexicographically versions.sort(); // Ascending sort for inverted timestamps - debug!("Found {} versions", versions.len()); + debug!( + event = EVENT_SWIFT_VERSIONING_LIST_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_SWIFT_VERSIONING, + result = "listed", + account = %account, + container = %container, + object = %object, + archive_container = %archive_container, + version_count = versions.len(), + "swift versioning list state changed" + ); Ok(versions) } diff --git a/crates/protocols/src/webdav/driver.rs b/crates/protocols/src/webdav/driver.rs index 14e9a3ad2..4c8707ebd 100644 --- a/crates/protocols/src/webdav/driver.rs +++ b/crates/protocols/src/webdav/driver.rs @@ -22,6 +22,7 @@ use dav_server::fs::{ }; use futures_util::{FutureExt, StreamExt, stream}; use percent_encoding::percent_decode_str; +use rustfs_utils::MaskedAccessKey; use rustfs_utils::path; use s3s::dto::*; use std::fmt::Debug; @@ -31,6 +32,22 @@ use std::time::SystemTime; use tokio::sync::RwLock; use tracing::{debug, error}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_WEBDAV_DRIVER: &str = "webdav_driver"; +const EVENT_WEBDAV_OBJECT_METADATA_FAILED: &str = "webdav_object_metadata_failed"; +const EVENT_WEBDAV_STREAM_READ_FAILED: &str = "webdav_stream_read_failed"; +const EVENT_WEBDAV_OBJECT_READ_FAILED: &str = "webdav_object_read_failed"; +const EVENT_WEBDAV_OBJECT_WRITE_STATE: &str = "webdav_object_write_state"; +const EVENT_WEBDAV_LIST_FAILED: &str = "webdav_list_failed"; +const EVENT_WEBDAV_COPY_FAILED: &str = "webdav_copy_failed"; +const EVENT_WEBDAV_DELETE_FAILED: &str = "webdav_delete_failed"; +const EVENT_WEBDAV_PROBE_FAILED: &str = "webdav_probe_failed"; +const EVENT_WEBDAV_BUCKET_LIST_FAILED: &str = "webdav_bucket_list_failed"; +const EVENT_WEBDAV_BUCKET_METADATA_STATE: &str = "webdav_bucket_metadata_state"; +const EVENT_WEBDAV_DIRECTORY_STATE: &str = "webdav_directory_state"; +const EVENT_WEBDAV_OBJECT_DELETE_STATE: &str = "webdav_object_delete_state"; +const EVENT_WEBDAV_RENAME_STATE: &str = "webdav_rename_state"; + /// Convert s3s ETag enum to string fn etag_to_string(etag: &ETag) -> String { match etag { @@ -209,7 +226,15 @@ where }) as Box) } Err(e) => { - error!("Failed to get file metadata for {}/{}: {}", bucket, key, e); + error!( + event = EVENT_WEBDAV_OBJECT_METADATA_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + object = %key, + error = %e, + "webdav object metadata failed" + ); Err(FsError::NotFound) } } @@ -280,7 +305,15 @@ where match chunk_result { Ok(bytes) => data.extend_from_slice(&bytes), Err(e) => { - error!("Error reading stream: {}", e); + error!( + event = EVENT_WEBDAV_STREAM_READ_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + object = %key, + error = %e, + "webdav stream read failed" + ); return Err(FsError::GeneralFailure); } } @@ -294,7 +327,17 @@ where } } Err(e) => { - error!("Failed to read bytes from {}/{}: {}", bucket, key, e); + error!( + event = EVENT_WEBDAV_OBJECT_READ_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + object = %key, + start_pos, + read_len = count, + error = %e, + "webdav object read failed" + ); Err(FsError::GeneralFailure) } } @@ -372,12 +415,31 @@ where .await { Ok(_) => { - debug!("Successfully flushed {} bytes to {}/{}", file_size, bucket, key); + debug!( + event = EVENT_WEBDAV_OBJECT_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "flushed", + bucket = %bucket, + object = %key, + file_size, + "webdav object write state changed" + ); // Buffer already cleared by std::mem::take above Ok(()) } Err(e) => { - error!("Failed to flush to {}/{}: {}", bucket, key, e); + error!( + event = EVENT_WEBDAV_OBJECT_WRITE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "flush_failed", + bucket = %bucket, + object = %key, + file_size, + error = %e, + "webdav object write state changed" + ); Err(FsError::GeneralFailure) } } @@ -473,7 +535,15 @@ where .list_objects_v2(list_input, access_key, secret_key) .await .map_err(|e| { - error!("Failed to list objects in {} with prefix '{}': {}", bucket, prefix, e); + error!( + event = EVENT_WEBDAV_LIST_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + prefix = %prefix, + error = %e, + "webdav list failed" + ); FsError::GeneralFailure })?; @@ -488,7 +558,18 @@ where .get_object(src_bucket, src_key, access_key, secret_key, None) .await .map_err(|e| { - error!("Failed to get source object '{}' in '{}': {}", src_key, src_bucket, e); + error!( + event = EVENT_WEBDAV_COPY_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "source_read_failed", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + error = %e, + "webdav copy failed" + ); FsError::GeneralFailure })?; @@ -499,7 +580,17 @@ where .. } = get_output; let body = body.ok_or_else(|| { - error!("GetObject for source object '{}/{}' returned no body stream", src_bucket, src_key); + error!( + event = EVENT_WEBDAV_COPY_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "source_body_missing", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + "webdav copy failed" + ); FsError::GeneralFailure })?; @@ -523,8 +614,16 @@ where .await .map_err(|e| { error!( - "Failed to copy object from '{}/{}' to '{}/{}': {}", - src_bucket, src_key, dst_bucket, dst_key, e + event = EVENT_WEBDAV_COPY_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "destination_write_failed", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + error = %e, + "webdav copy failed" ); FsError::GeneralFailure })?; @@ -550,7 +649,16 @@ where .delete_object(src_bucket, src_obj_key, access_key, secret_key) .await .map_err(|e| { - error!("Failed to delete source object '{}' after directory rename: {}", src_obj_key, e); + error!( + event = EVENT_WEBDAV_DELETE_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "rename_cleanup_failed", + bucket = %src_bucket, + object = %src_obj_key, + error = %e, + "webdav delete failed" + ); FsError::GeneralFailure })?; } @@ -575,7 +683,15 @@ where if Self::is_missing_head_object_error(&err_msg) { Ok(HeadObjectProbe::Missing) } else { - error!("Failed to probe object '{}/{}': {}", bucket, key, err_msg); + error!( + event = EVENT_WEBDAV_PROBE_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + object = %key, + error = %err_msg, + "webdav probe failed" + ); Err(FsError::GeneralFailure) } } @@ -718,7 +834,14 @@ where Ok(entries) } Err(e) => { - error!("Failed to list buckets: {}", e); + error!( + event = EVENT_WEBDAV_BUCKET_LIST_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + error = %e, + access_key = %MaskedAccessKey(&self.session_context.principal.user_identity.credentials.access_key), + "webdav bucket list failed" + ); Err(FsError::GeneralFailure) } } @@ -852,7 +975,15 @@ where Ok(entries) } Err(e) => { - error!("Failed to list objects in {}: {}", bucket, e); + error!( + event = EVENT_WEBDAV_LIST_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + bucket = %bucket, + prefix = %prefix_with_slash.unwrap_or_default(), + error = %e, + "webdav list failed" + ); Err(FsError::GeneralFailure) } } @@ -920,7 +1051,15 @@ where Ok(_) => Ok(()), Err(e) if e.to_string().contains("NoSuchBucket") => Ok(()), Err(e) => { - error!("Failed to delete bucket '{}': {}", bucket, e); + error!( + event = EVENT_WEBDAV_DELETE_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "bucket_delete_failed", + bucket = %bucket, + error = %e, + "webdav delete failed" + ); Err(FsError::GeneralFailure) } } @@ -1073,7 +1212,15 @@ where content_type: None, }) as Box), Err(e) => { - debug!("Bucket not found: {}: {}", bucket, e); + debug!( + event = EVENT_WEBDAV_BUCKET_METADATA_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + result = "not_found", + bucket = %bucket, + error = %e, + "webdav bucket metadata state changed" + ); Err(FsError::NotFound) } } @@ -1125,11 +1272,28 @@ where .await { Ok(_) => { - debug!("Successfully created directory '{}' in bucket '{}'", dir_key, bucket); + debug!( + event = EVENT_WEBDAV_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "created", + bucket = %bucket, + object = %dir_key, + "webdav directory state changed" + ); return Ok(()); } Err(e) => { - error!("Failed to create directory '{}' in bucket '{}': {}", dir_key, bucket, e); + error!( + event = EVENT_WEBDAV_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "create_failed", + bucket = %bucket, + object = %dir_key, + error = %e, + "webdav directory state changed" + ); return Err(FsError::GeneralFailure); } } @@ -1150,11 +1314,26 @@ where .await { Ok(_) => { - debug!("Successfully created bucket '{}'", bucket); + debug!( + event = EVENT_WEBDAV_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "bucket_created", + bucket = %bucket, + "webdav directory state changed" + ); Ok(()) } Err(e) => { - error!("Failed to create bucket '{}': {}", bucket, e); + error!( + event = EVENT_WEBDAV_DIRECTORY_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "bucket_create_failed", + bucket = %bucket, + error = %e, + "webdav directory state changed" + ); Err(FsError::GeneralFailure) } } @@ -1279,11 +1458,28 @@ where .await { Ok(_) => { - debug!("Successfully deleted object '{}/{}'", bucket, key); + debug!( + event = EVENT_WEBDAV_OBJECT_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "deleted", + bucket = %bucket, + object = %key, + "webdav object delete state changed" + ); Ok(()) } Err(e) => { - error!("Failed to delete object '{}/{}': {}", bucket, key, e); + error!( + event = EVENT_WEBDAV_OBJECT_DELETE_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "delete_failed", + bucket = %bucket, + object = %key, + error = %e, + "webdav object delete state changed" + ); Err(FsError::GeneralFailure) } } @@ -1323,11 +1519,32 @@ where .delete_object(&src_bucket, &src_key, access_key, secret_key) .await .map_err(|e| { - error!("Failed to delete source object after rename: {}", e); + error!( + event = EVENT_WEBDAV_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "source_delete_failed", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + error = %e, + "webdav rename state changed" + ); FsError::GeneralFailure })?; - debug!("Successfully renamed file '{}/{}' to '{}/{}'", src_bucket, src_key, dst_bucket, dst_key); + debug!( + event = EVENT_WEBDAV_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "file_renamed", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + "webdav rename state changed" + ); return Ok(()); } ResolvedPath::Directory { prefix, .. } => { @@ -1376,7 +1593,18 @@ where .list_objects_v2(list_input, access_key, secret_key) .await .map_err(|e| { - error!("Failed to list objects during directory rename: {}", e); + error!( + event = EVENT_WEBDAV_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "directory_list_failed", + src_bucket = %src_bucket, + src_prefix = %src_prefix, + dst_bucket = %dst_bucket, + dst_prefix = %dst_prefix, + error = %e, + "webdav rename state changed" + ); FsError::GeneralFailure })?; @@ -1415,13 +1643,30 @@ where } if !renamed_any { - debug!("Source not found: {}/{}", src_bucket, src_key); + debug!( + event = EVENT_WEBDAV_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + result = "source_not_found", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + "webdav rename state changed" + ); return Err(FsError::NotFound); } debug!( - "Successfully renamed directory '{}/{}' to '{}/{}'", - src_bucket, src_key, dst_bucket, dst_key + event = EVENT_WEBDAV_RENAME_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_DRIVER, + state = "directory_renamed", + src_bucket = %src_bucket, + src_object = %src_key, + dst_bucket = %dst_bucket, + dst_object = %dst_key, + "webdav rename state changed" ); Ok(()) } diff --git a/crates/protocols/src/webdav/server.rs b/crates/protocols/src/webdav/server.rs index cf0cb4d78..64bee71e6 100644 --- a/crates/protocols/src/webdav/server.rs +++ b/crates/protocols/src/webdav/server.rs @@ -26,6 +26,7 @@ use hyper::{Request, Response, StatusCode}; use hyper_util::rt::TokioIo; use rustfs_config::{DEFAULT_TLS_RELOAD_ENABLE, DEFAULT_TLS_RELOAD_INTERVAL, ENV_TLS_RELOAD_ENABLE, ENV_TLS_RELOAD_INTERVAL}; use rustfs_tls_runtime::{ReloadableServerCertResolver, TlsReloadOptions, spawn_server_cert_reload_loop}; +use rustfs_utils::MaskedAccessKey; use rustls::ServerConfig; use std::convert::Infallible; use std::net::IpAddr; @@ -36,6 +37,16 @@ use tokio::sync::{broadcast, watch}; use tokio_rustls::TlsAcceptor; use tracing::{debug, error, info, warn}; +const LOG_COMPONENT_PROTOCOLS: &str = "protocols"; +const LOG_SUBSYSTEM_WEBDAV_SERVER: &str = "webdav_server"; +const LOG_SUBSYSTEM_WEBDAV_AUTH: &str = "webdav_auth"; +const EVENT_WEBDAV_SERVER_STATE: &str = "webdav_server_state"; +const EVENT_WEBDAV_TLS_STATE: &str = "webdav_tls_state"; +const EVENT_WEBDAV_CONNECTION_STATE: &str = "webdav_connection_state"; +const EVENT_WEBDAV_REQUEST_VALIDATION_FAILED: &str = "webdav_request_validation_failed"; +const EVENT_WEBDAV_REQUEST_BODY_FAILED: &str = "webdav_request_body_failed"; +const EVENT_WEBDAV_AUTH_STATE: &str = "webdav_auth_state"; + /// WebDAV server implementation pub struct WebDavServer where @@ -67,16 +78,39 @@ where /// Start the WebDAV server pub async fn start(&self, mut shutdown_rx: broadcast::Receiver<()>) -> Result<(), WebDavInitError> { - info!("Initializing WebDAV server on {}", self.config.bind_addr); + info!( + event = EVENT_WEBDAV_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + state = "starting", + bind_addr = %self.config.bind_addr, + tls_enabled = self.config.tls_enabled, + max_body_size = self.config.max_body_size, + "webdav server state changed" + ); let listener = TcpListener::bind(self.config.bind_addr).await?; - info!("WebDAV server listening on {}", self.config.bind_addr); + info!( + event = EVENT_WEBDAV_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + state = "listening", + bind_addr = %self.config.bind_addr, + "webdav server state changed" + ); let (reload_shutdown_tx, reload_shutdown_rx) = watch::channel(false); // Setup TLS if enabled let tls_acceptor = if self.config.tls_enabled { if let Some(cert_dir) = &self.config.cert_dir { - debug!("Enabling WebDAV TLS with certificates from: {}", cert_dir); + debug!( + event = EVENT_WEBDAV_TLS_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + state = "enabled", + cert_dir = %cert_dir, + "webdav tls state changed" + ); let resolver = ReloadableServerCertResolver::load_from_directory(cert_dir) .map_err(|e| WebDavInitError::Tls(format!("Failed to create certificate resolver: {}", e)))?; @@ -118,28 +152,67 @@ where Ok(tls_stream) => { let io = TokioIo::new(tls_stream); if let Err(e) = Self::handle_connection_impl(io, storage, source_ip, max_body_size).await { - debug!("Connection error: {}", e); + debug!( + event = EVENT_WEBDAV_CONNECTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "error", + peer = %source_ip, + transport = "tls", + error = %e, + "webdav connection ended with error" + ); } } Err(e) => { - debug!("TLS handshake failed: {}", e); + debug!( + event = EVENT_WEBDAV_CONNECTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "tls_handshake_failed", + peer = %source_ip, + error = %e, + "webdav connection ended with error" + ); } } } else { let io = TokioIo::new(stream); if let Err(e) = Self::handle_connection_impl(io, storage, source_ip, max_body_size).await { - debug!("Connection error: {}", e); + debug!( + event = EVENT_WEBDAV_CONNECTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "error", + peer = %source_ip, + transport = "tcp", + error = %e, + "webdav connection ended with error" + ); } } }); } Err(e) => { - error!("Failed to accept connection: {}", e); + error!( + event = EVENT_WEBDAV_CONNECTION_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "accept_failed", + error = %e, + "webdav connection accept failed" + ); } } } _ = shutdown_rx.recv() => { - info!("WebDAV server received shutdown signal"); + info!( + event = EVENT_WEBDAV_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + state = "shutdown_requested", + "webdav server state changed" + ); let _ = reload_shutdown_tx.send(true); break; } @@ -147,7 +220,13 @@ where } let _ = reload_shutdown_tx.send(true); - info!("WebDAV server stopped"); + info!( + event = EVENT_WEBDAV_SERVER_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + state = "stopped", + "webdav server state changed" + ); Ok(()) } @@ -184,7 +263,16 @@ where && let Ok(length) = length_str.parse::() && length > max_body_size { - warn!("Request body too large: {} > {}", length, max_body_size); + warn!( + event = EVENT_WEBDAV_REQUEST_VALIDATION_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "payload_too_large", + content_length = length, + max_body_size, + source_ip = %source_ip, + "webdav request validation failed" + ); return Ok(error_response( StatusCode::PAYLOAD_TOO_LARGE, &format!("Request body too large. Maximum size is {} bytes", max_body_size), @@ -233,7 +321,15 @@ where let body_bytes = match body.collect().await { Ok(collected) => collected.to_bytes(), Err(e) => { - error!("Failed to read request body: {}", e); + error!( + event = EVENT_WEBDAV_REQUEST_BODY_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "request_body_read_failed", + source_ip = %source_ip, + error = %e, + "webdav request body failed" + ); return Ok(error_response(StatusCode::BAD_REQUEST, "Failed to read request body")); } }; @@ -249,7 +345,15 @@ where let body_bytes = match body.collect().await { Ok(collected) => collected.to_bytes(), Err(e) => { - error!("Failed to read response body: {}", e); + error!( + event = EVENT_WEBDAV_REQUEST_BODY_FAILED, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_SERVER, + result = "response_body_read_failed", + source_ip = %source_ip, + error = %e, + "webdav request body failed" + ); return Ok(error_response(StatusCode::INTERNAL_SERVER_ERROR, "Internal server error")); } }; @@ -261,10 +365,19 @@ where async fn authenticate(access_key: &str, secret_key: &str, source_ip: IpAddr) -> Result { use rustfs_credentials::Credentials as S3Credentials; use rustfs_iam::get; + let masked_access_key = MaskedAccessKey(access_key); // Access IAM system let iam_sys = get().map_err(|e| { - error!("IAM system unavailable during WebDAV auth: {}", e); + error!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "iam_unavailable", + source_ip = %source_ip, + error = %e, + "webdav auth state changed" + ); WebDavInitError::Server("Internal authentication service unavailable".to_string()) })?; @@ -282,26 +395,67 @@ where }; let (user_identity, is_valid) = iam_sys.check_key(&s3_creds.access_key).await.map_err(|e| { - error!("IAM check_key failed for {}: {}", access_key, e); + error!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "check_key_failed", + source_ip = %source_ip, + access_key = %masked_access_key, + error = %e, + "webdav auth state changed" + ); WebDavInitError::Server("Authentication verification failed".to_string()) })?; if !is_valid { - warn!("WebDAV login failed: Invalid access key '{}'", access_key); + warn!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "invalid_access_key", + source_ip = %source_ip, + access_key = %masked_access_key, + "webdav auth state changed" + ); return Err(WebDavInitError::Server("Invalid credentials".to_string())); } let identity = user_identity.ok_or_else(|| { - error!("User identity missing despite valid key for {}", access_key); + error!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "identity_missing", + source_ip = %source_ip, + access_key = %masked_access_key, + "webdav auth state changed" + ); WebDavInitError::Server("User not found".to_string()) })?; if !identity.credentials.secret_key.eq(&s3_creds.secret_key) { - warn!("WebDAV login failed: Invalid secret key for '{}'", access_key); + warn!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "invalid_secret_key", + source_ip = %source_ip, + access_key = %masked_access_key, + "webdav auth state changed" + ); return Err(WebDavInitError::Server("Invalid credentials".to_string())); } - info!("WebDAV user '{}' authenticated successfully", access_key); + debug!( + event = EVENT_WEBDAV_AUTH_STATE, + component = LOG_COMPONENT_PROTOCOLS, + subsystem = LOG_SUBSYSTEM_WEBDAV_AUTH, + result = "authenticated", + source_ip = %source_ip, + access_key = %masked_access_key, + "webdav auth state changed" + ); Ok(SessionContext::new( ProtocolPrincipal::new(Arc::new(identity)), diff --git a/crates/utils/src/lib.rs b/crates/utils/src/lib.rs index 70ee86461..88d138efa 100644 --- a/crates/utils/src/lib.rs +++ b/crates/utils/src/lib.rs @@ -47,6 +47,8 @@ pub mod crypto; #[cfg(feature = "compress")] pub mod compress; +pub mod logging; + #[cfg(feature = "path")] pub mod dirs; @@ -74,3 +76,4 @@ mod dunce; pub use dunce::*; mod envs; pub use envs::*; +pub use logging::*; diff --git a/crates/utils/src/logging.rs b/crates/utils/src/logging.rs new file mode 100644 index 000000000..5fadc9fb1 --- /dev/null +++ b/crates/utils/src/logging.rs @@ -0,0 +1,70 @@ +// Copyright 2024 RustFS Team +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use std::fmt; + +#[derive(Clone, Copy)] +pub struct MaskedAccessKey<'a>(pub &'a str); + +impl fmt::Display for MaskedAccessKey<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let value = self.0; + if value.is_empty() { + return Ok(()); + } + + let chars: Vec = value.chars().collect(); + match chars.len() { + 0 => Ok(()), + 1..=4 => f.write_str("***"), + 5..=8 => write!(f, "{}***{}", chars[0], chars[chars.len() - 1]), + len => { + for ch in &chars[..4] { + write!(f, "{ch}")?; + } + f.write_str("***")?; + for ch in &chars[len - 4..] { + write!(f, "{ch}")?; + } + Ok(()) + } + } + } +} + +impl fmt::Debug for MaskedAccessKey<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + fmt::Display::fmt(self, f) + } +} + +#[cfg(test)] +mod tests { + use super::MaskedAccessKey; + + #[test] + fn masks_short_values() { + assert_eq!(MaskedAccessKey("").to_string(), ""); + assert_eq!(MaskedAccessKey("a").to_string(), "***"); + assert_eq!(MaskedAccessKey("abcd").to_string(), "***"); + assert_eq!(MaskedAccessKey("abcde").to_string(), "a***e"); + assert_eq!(MaskedAccessKey("abcdefgh").to_string(), "a***h"); + } + + #[test] + fn masks_long_values() { + assert_eq!(MaskedAccessKey("AKIAIOSFODNN7EXAMPLE").to_string(), "AKIA***MPLE"); + assert_eq!(format!("{:?}", MaskedAccessKey("keystone:user-1234")), "keys***1234"); + } +} diff --git a/rustfs/src/auth.rs b/rustfs/src/auth.rs index c0a1317bd..dde215310 100644 --- a/rustfs/src/auth.rs +++ b/rustfs/src/auth.rs @@ -19,9 +19,9 @@ use rustfs_iam::error::Error as IamError; use rustfs_iam::sys::{ SESSION_POLICY_NAME, get_claims_from_token_with_secret, get_claims_from_token_with_secret_allow_missing_exp, }; -use rustfs_obs::MaskedAccessKey; use rustfs_policy::policy::{ClaimLookup, get_claim_case_insensitive}; use rustfs_trusted_proxies::ClientInfo; +use rustfs_utils::MaskedAccessKey; use rustfs_utils::http::{AMZ_OBJECT_LOCK_LEGAL_HOLD_LOWER, AMZ_OBJECT_LOCK_MODE_LOWER, AMZ_OBJECT_LOCK_RETAIN_UNTIL_DATE_LOWER}; use s3s::S3Error; use s3s::S3ErrorCode; diff --git a/rustfs/src/auth_keystone.rs b/rustfs/src/auth_keystone.rs index 04a0d11fa..812c3d061 100644 --- a/rustfs/src/auth_keystone.rs +++ b/rustfs/src/auth_keystone.rs @@ -17,7 +17,7 @@ use http::HeaderMap; use rustfs_credentials::Credentials; use rustfs_keystone::{KeystoneAuthProvider, KeystoneClient, KeystoneConfig, KeystoneIdentityMapper}; -use rustfs_obs::MaskedAccessKey; +use rustfs_utils::MaskedAccessKey; use s3s::{S3Result, s3_error}; use std::sync::{Arc, OnceLock}; use tracing::{error, info}; diff --git a/rustfs/src/protocols/client.rs b/rustfs/src/protocols/client.rs index 24a7f6f2e..3833288f2 100644 --- a/rustfs/src/protocols/client.rs +++ b/rustfs/src/protocols/client.rs @@ -16,7 +16,7 @@ use crate::storage::ecfs::FS; use http::{HeaderMap, Method}; use percent_encoding::{AsciiSet, CONTROLS, utf8_percent_encode}; use rustfs_credentials; -use rustfs_obs::MaskedAccessKey; +use rustfs_utils::MaskedAccessKey; use s3s::dto::*; use s3s::{S3, S3Request, S3Result}; use tokio_stream::Stream; diff --git a/scripts/check_logging_guardrails.sh b/scripts/check_logging_guardrails.sh index fb6f6f3e8..46439ed00 100755 --- a/scripts/check_logging_guardrails.sh +++ b/scripts/check_logging_guardrails.sh @@ -42,6 +42,45 @@ checked_files=( "crates/trusted-proxies/src/cloud/metadata/aws.rs" "crates/trusted-proxies/src/cloud/metadata/azure.rs" "crates/trusted-proxies/src/cloud/metadata/gcp.rs" + "crates/protocols/src/webdav/server.rs" + "crates/protocols/src/webdav/driver.rs" + "crates/protocols/src/ftps/server.rs" + "crates/protocols/src/ftps/driver.rs" + "crates/protocols/src/sftp/server.rs" + "crates/protocols/src/sftp/driver.rs" + "crates/protocols/src/sftp/write.rs" + "crates/protocols/src/sftp/config.rs" + "crates/protocols/src/sftp/errors.rs" + "crates/protocols/src/sftp/dir.rs" + "crates/protocols/src/sftp/fallback_watchdog.rs" + "crates/protocols/src/sftp/wedge_watchdog.rs" + "crates/protocols/src/swift/expiration_worker.rs" + "crates/protocols/src/swift/versioning.rs" + "crates/protocols/src/swift/bulk.rs" + "crates/protocols/src/swift/encryption.rs" + "crates/protocols/src/swift/handler.rs" + "crates/protocols/src/swift/staticweb.rs" + "crates/protocols/src/swift/acl.rs" + "crates/protocols/src/swift/sync.rs" + "crates/protocols/src/swift/container.rs" + "crates/protocols/src/swift/object.rs" + "crates/protocols/src/swift/formpost.rs" + "crates/protocols/src/swift/ratelimit.rs" + "crates/protocols/src/swift/expiration.rs" + "crates/protocols/src/swift/cors.rs" + "crates/protocols/src/swift/quota.rs" + "crates/protocols/src/swift/symlink.rs" + "crates/protocols/src/common/gateway.rs" + "crates/obs/src/telemetry/dial9.rs" + "crates/obs/src/telemetry/local.rs" + "crates/obs/src/metrics/scheduler.rs" + "crates/obs/src/cleaner/core.rs" + "crates/obs/src/cleaner/compress.rs" + "crates/obs/src/cleaner/scanner.rs" + "crates/obs/src/metrics/stats_collector.rs" + "crates/obs/src/global.rs" + "crates/obs/src/telemetry/recorder.rs" + "crates/obs/src/metrics/collectors/system_gpu.rs" ) forbidden_patterns=( @@ -249,6 +288,163 @@ forbidden_patterns=( 'debug!("Failed to fetch GCP IP ranges: {}", e)' 'debug!("Using default GCP public IP ranges")' 'debug!("Using default GCP VPC network ranges")' + 'info!("Initializing WebDAV server on {}"' + 'info!("WebDAV server listening on {}"' + 'debug!("Enabling WebDAV TLS with certificates from: {}"' + 'warn!("Request body too large: {} > {}"' + 'error!("IAM system unavailable during WebDAV auth: {}"' + 'error!("IAM check_key failed for {}: {}"' + 'warn!("WebDAV login failed: Invalid access key '\''{}'\''"' + 'warn!("WebDAV login failed: Invalid secret key for '\''{}'\''"' + 'info!("WebDAV user '\''{}'\'' authenticated successfully"' + 'info!("Initializing FTPS server on {}"' + 'info!("Configuring FTPS passive ports range: {:?} ({})"' + 'warn!("No passive ports configured, using system-assigned ports"' + 'info!("Configuring FTPS external IP for passive mode: {}"' + 'info!("FTPS server configured for both active and passive mode support"' + 'info!("FTPS is explicitly required for all connections"' + 'info!("TLS disabled, running in plain FTP mode"' + 'error!("IAM system unavailable during FTPS auth: {}"' + 'error!("IAM check_key failed for {}: {}"' + 'warn!("FTPS login failed: Invalid access key '\''{}'\''"' + 'warn!("FTPS login failed: Invalid secret key for '\''{}'\''"' + 'info!("FTPS user '\''{}'\'' authenticated successfully"' + 'warn!("Expiration worker already running"' + 'info!("Starting expiration worker (scan_interval={}s, worker_id={}/{})"' + 'info!("Expiration worker stopped"' + 'error!("Expiration cleanup iteration failed: {}"' + 'info!("Stopping expiration worker"' + 'debug!("Skipping object {} (handled by different worker)"' + 'debug!("Tracking object {} for expiration at {}"' + 'debug!("Untracking object {} from expiration"' + 'info!("Starting expiration cleanup iteration (worker_id={})"' + 'warn!("Invalid expiration entry path: {}"' + 'info!("Deleted expired object: {}"' + 'debug!("Object {} no longer exists or expiration removed"' + 'error!("Failed to delete expired object {}: {}"' + 'info!("Expiration cleanup iteration complete: scanned={}, deleted={}, duration={}ms, queue_size={}"' + 'debug!("Would delete expired object: {}/{}/{} (expires_at={})"' + 'info!("Starting full scan of objects with expiration (worker_id={})"' + 'warn!("Full object scan not yet implemented - requires storage layer integration"' + 'debug!("Bulk delete request for account: {}"' + 'debug!("Processing {} delete requests"' + 'error!("Error deleting {}: {}"' + 'error!("Invalid path {}: {}"' + 'debug!("Bulk extract request for container: {}, format: {:?}"' + 'debug!("Extracted: {}"' + 'error!("Failed to upload {}: {}"' + 'debug!("Skipping directory: {}"' + 'error!("Failed to read tar entry {}: {}"' + 'debug!("Client explicitly disabled encryption"' + 'debug!("Encrypting {} bytes with {}"' + 'warn!("Encryption not yet implemented - returning plaintext with metadata"' + 'debug!("Decrypting {} bytes with {}"' + 'warn!("Decryption not yet implemented - returning data as-is"' + 'debug!("Swift route matched: {:?}"' + 'debug!("No Swift route matched, delegating to S3 service"' + 'debug!("TempURL detected for {}/{}/{}"' + 'debug!("TempURL validated successfully"' + 'warn!("Failed to restore version after delete: {}"' + 'debug!("Static web request: container={}, path={}, config={:?}"' + 'debug!("Generating directory listing for path: {}"' + 'debug!("Attempting to serve object: {}"' + 'debug!("Serving error document: {}"' + 'debug!("Error document not found, returning standard 404"' + 'debug!("Read access granted: public read enabled"' + 'debug!("Read access granted: referrer matches pattern {}"' + 'debug!("Read access granted: account {} matches"' + 'debug!("Read access granted: user {}:{} matches"' + 'debug!("Read access denied: no matching ACL grant"' + 'debug!("Write access granted: account {} matches"' + 'debug!("Write access granted: user {}:{} matches"' + 'debug!("Write access denied: no matching ACL grant"' + 'warn!("Container sync using unencrypted HTTP - consider using HTTPS"' + 'warn!("Container sync key is short (<16 chars) - recommend longer key"' + 'debug!("Scheduled retry #{} for '\''{}'\'' at +{}s"' + 'error!("Storage operation '\''{}'\'' failed: {}"' + 'debug!("Creating symlink to target: {}"' + 'debug!("FormPost signature mismatch: expected={}, got={}"' + 'debug!("FormPost uploaded: {}/{}/{}"' + 'debug!("Rate limit OK for {}: {} remaining"' + 'debug!("Rate limit exceeded for {}: retry after {} seconds"' + 'debug!("X-Delete-After: {} seconds -> X-Delete-At: {}"' + 'debug!("X-Delete-At: {}"' + 'debug!("X-Delete-At timestamp is more than 10 years in the future: {}"' + 'debug!("Extracted symlink target: container={:?}, object={}"' + 'warn!("Circular symlink reference detected"' + 'debug!("CORS preflight request for container: {}"' + 'debug!("Quota check passed: {}/{:?} bytes, {}/{:?} objects"' + 'warn!("SFTP backend error"' + 'warn!("SFTP authorisation rejected because the IAM system was unreachable"' + 'warn!("fallback watchdog cancelling session: silence exceeded fallback threshold"' + 'warn!("wedge watchdog cancelling session: russh select! parked outside its arms"' + 'warn!("RUSTFS_SFTP_HANDLES_PER_SESSION out of range. Falling back to the default."' + 'warn!("RUSTFS_SFTP_BACKEND_OP_TIMEOUT_SECS out of range. Falling back to the default."' + 'warn!("RUSTFS_SFTP_READ_CACHE_WINDOW_BYTES out of range. Set to 0 to disable the cache, or to a value between the named bounds. Falling back to the default."' + 'warn!("RUSTFS_SFTP_READ_CACHE_TOTAL_MEM_BYTES below minimum. Falling back to the default."' + 'warn!("cannot stat file, skipping"' + 'debug!("skipping file: size outside valid key range"' + 'warn!("cannot read file, skipping"' + 'info!("loaded host key"' + 'warn!("file looks like a private key but failed to decode (passphrase-protected keys are not supported)"' + 'debug!("not a valid private key, skipping"' + 'info!("host key loading complete"' + 'warn!("SFTP host key file permission enforcement is not active on Windows.' + 'info!("Dial9 telemetry disabled"' + 'info!("Validating dial9 telemetry configuration"' + 'warn!("Failed to create dial9 output directory '\''{}'\'': {}"' + 'warn!("Continuing without dial9 telemetry"' + 'info!("Dial9 telemetry configuration validated successfully"' + 'info!("Dial9 telemetry data will be flushed on drop"' + 'info!("Dial9 telemetry guard dropped, data flushed"' + 'info!("Initialized local logging"' + 'info!("log cleaner compression profile configured"' + 'warn!("Log cleanup failed: {}"' + 'warn!("Log cleanup task panicked: {}"' + 'warn!("Metrics collection for cluster stats cancelled."' + 'warn!("Metrics collection for supplementary cluster stats cancelled."' + 'warn!("Metrics collection for bucket stats cancelled."' + 'warn!("Metrics collection for node/disk stats cancelled."' + 'warn!("Bucket monitor unavailable; skip replication bandwidth key-state transition this cycle."' + 'warn!("Metrics collection for bucket replication bandwidth stats cancelled."' + 'warn!("Metrics collection for audit target stats cancelled."' + 'warn!("Metrics collection for notification stats cancelled."' + 'warn!("Metrics collection for background workflow stats cancelled."' + 'warn!("Failed to get current PID for system monitoring: {}"' + 'warn!("GPU metrics collection failed: {}"' + 'warn!("GPU collector initialization failed: {}"' + 'warn!("Process metrics collection cancelled."' + 'warn!("Metrics collection for internode network stats cancelled."' + 'warn!("Failed to collect process attributes for metrics labels: {}"' + 'debug!("Log directory does not exist: {:?}"' + 'info!("Found {} regular log files, total size: {} bytes ({:.2} MB)"' + 'info!("Cleanup completed: deleted {} files, freed {} bytes ({:.2} MB)"' + 'warn!(file = ?file.path, error = %err, "parallel compression failed"' + 'warn!("parallel compression worker panicked, falling back to serial path"' + 'info!("parallel cleanup finished"' + 'warn!(file = ?file.path, error = %err, "serial compression failed, source kept"' + 'info!("[DRY RUN] Would delete: {:?} ({} bytes)"' + 'debug!("Deleted: {:?}"' + 'error!("Failed to delete {:?}: {}"' + 'warn!("zstd compression failed, fallback to gzip"' + 'debug!(file = ?archive_path, "compressed archive already exists, skipping"' + 'info!("[DRY RUN] Would compress file: {:?} -> {:?}"' + 'debug!("compression finished"' + 'debug!("Excluding file from cleanup: {:?}"' + 'tracing::warn!("Failed to delete empty file {:?}: {}"' + 'debug!("Deleted empty file: {:?}"' + 'tracing::info!("[DRY RUN] Would delete empty file: {:?}"' + 'warn!("Failed to load data usage from backend: {}"' + 'warn!("Failed to list buckets for cluster metrics: {}"' + 'warn!("Failed to load data usage for bucket metrics: {}"' + 'warn!("Failed to list buckets for bucket metrics: {}"' + 'warn!("Invalid bandwidth limit value for target {:?}: {}"' + 'warn!("OBSERVABILITY_METRIC_ENABLED was already initialized; keeping original value"' + 'info!("Initializing global guard"' + 'error!("{} cache read lock poisoned: {}"' + 'error!("{} cache write lock poisoned: {}"' + 'error!("metrics_metadata lock poisoned: {}"' + 'warn!("Could not get GPU stats, recording 0 for GPU memory usage"' ) for pattern in "${forbidden_patterns[@]}"; do