From 9059a9c68dfa335a07118c15f25b596163bc7529 Mon Sep 17 00:00:00 2001 From: houseme Date: Sun, 14 Jun 2026 01:00:26 +0800 Subject: [PATCH] refactor(logging): standardize concurrency and trusted proxy events (#3417) * refactor(logging): standardize concurrency and proxy events * chore(logging): extend guardrails for concurrency and proxies * feat(skill): add rustfs logging governance skill --- .../skills/rustfs-logging-governance/SKILL.md | 107 +++++++ .../agents/openai.yaml | 4 + .../references/logging-governance.md | 285 ++++++++++++++++++ crates/concurrency/src/deadlock.rs | 20 +- crates/concurrency/src/lock.rs | 12 +- crates/concurrency/src/manager.rs | 24 +- crates/concurrency/src/workers.rs | 54 +++- crates/trusted-proxies/src/cloud/detector.rs | 124 +++++++- .../trusted-proxies/src/cloud/metadata/aws.rs | 68 ++++- .../src/cloud/metadata/azure.rs | 140 ++++++++- .../trusted-proxies/src/cloud/metadata/gcp.rs | 164 +++++++++- crates/trusted-proxies/src/cloud/ranges.rs | 110 ++++++- crates/trusted-proxies/src/config/loader.rs | 61 +++- crates/trusted-proxies/src/global.rs | 21 +- .../trusted-proxies/src/middleware/service.rs | 63 +++- crates/trusted-proxies/src/proxy/chain.rs | 10 +- crates/trusted-proxies/src/proxy/metrics.rs | 29 +- crates/trusted-proxies/src/proxy/validator.rs | 83 ++++- scripts/check_logging_guardrails.sh | 104 +++++++ 19 files changed, 1363 insertions(+), 120 deletions(-) create mode 100644 .agents/skills/rustfs-logging-governance/SKILL.md create mode 100644 .agents/skills/rustfs-logging-governance/agents/openai.yaml create mode 100644 .agents/skills/rustfs-logging-governance/references/logging-governance.md diff --git a/.agents/skills/rustfs-logging-governance/SKILL.md b/.agents/skills/rustfs-logging-governance/SKILL.md new file mode 100644 index 000000000..62a4fc7f0 --- /dev/null +++ b/.agents/skills/rustfs-logging-governance/SKILL.md @@ -0,0 +1,107 @@ +--- +name: rustfs-logging-governance +description: Standardize and review RustFS logging with structured `tracing` events, lower noise on hot paths, preserve security-sensitive diagnostics, and extend guardrails to prevent legacy logging patterns from returning. Use when editing or reviewing RustFS logs, startup/config diagnostics, cloud metadata logs, request validation logs, or `scripts/check_logging_guardrails.sh`. +--- + +# RustFS Logging Governance + +Use this skill when RustFS logging needs to be added, cleaned up, reviewed, or protected against regressions. + +## Quick Start + +1. Identify the files whose logs are changing. +2. Scan current `tracing` or `log` macros before editing. +3. Convert sentence-style logs to short event-style logs. +4. Demote hot-path success logs unless operators truly need them at `info`. +5. Preserve failure, fallback, and security-relevant diagnostics. +6. Update `scripts/check_logging_guardrails.sh` when a broad cleanup removes a legacy pattern class. +7. Validate with formatting, targeted checks/tests, and the logging guardrail script. + +## Core Workflow + +### 1. Scope the logging surface + +- Read the changed module in full before touching log lines. +- Classify the log site: + - lifecycle/startup + - request or validation path + - background loop or hot path + - fallback/degraded behavior + - cloud metadata or external fetch path + - metrics/config summary +- Do not rewrite business logic to make logging easier. + +### 2. Use the RustFS event shape + +- Prefer fields first, message second. +- Use short labels, not prose paragraphs. +- Default field shape: + - `event` + - `component` + - `subsystem` + - `state` or `result` + - key context fields +- Reuse stable field names and avoid inventing near-duplicates. + +See `references/logging-governance.md` for the event model, level policy, and anti-pattern list. + +### 3. Choose the right level + +- `error`: operation failure that affects behavior or security guarantees. +- `warn`: degraded path, fallback, suspicious input, or operator-actionable misconfiguration. +- `info`: low-frequency lifecycle or mode selection. +- `debug`: targeted diagnostics and low-volume detail. +- `trace`: hot-path and repetitive success-path events. + +When in doubt, lower the verbosity of normal success paths and keep structured detail in fields. + +### 4. Preserve security and privacy boundaries + +- Do not log secrets, tokens, auth headers, raw credential payloads, or merged config dumps. +- Avoid logging raw forwarded headers or full trusted network inventories above `debug`. +- Keep warning/error logs useful without echoing attacker-controlled payloads unnecessarily. + +### 5. Keep summaries aggregated + +- Replace multi-line startup banners or checklist logs with one structured event. +- If metrics already express a concept, avoid duplicating it with many `info!` lines. +- Prefer counts, modes, and sources over inventories unless debug detail is truly needed. + +### 6. Update guardrails when needed + +- Broad logging cleanup should usually extend `scripts/check_logging_guardrails.sh`. +- Add forbidden patterns only for styles the repo has intentionally retired: + - sentence-style lifecycle logs + - noisy hot-path `info!` + - checklist-style summary logs + - legacy fallback wording that has been replaced by structured fields +- Keep guardrails concrete and grep-friendly. + +### 7. Validate manually + +Use the smallest relevant set: + +```bash +cargo fmt --all --check +./scripts/check_logging_guardrails.sh +cargo check -p +cargo test -p +``` + +For broader Rust changes, add: + +```bash +./scripts/check_unsafe_code_allowances.sh +./scripts/check_architecture_migration_rules.sh +cargo clippy -p --all-targets -- -D warnings +``` + +## RustFS-Specific Notes + +- The durable RustFS logging direction is `event + component + subsystem + state/result + key context fields`. +- `crates/concurrency` and `crates/trusted-proxies` are examples of this style for lifecycle, fallback, and cloud metadata logs. +- `scripts/check_logging_guardrails.sh` is the enforcement point for preventing removed log styles from returning. + +## References + +- Read `references/logging-governance.md` when you need the detailed field set, anti-pattern examples, or guardrail update checklist. diff --git a/.agents/skills/rustfs-logging-governance/agents/openai.yaml b/.agents/skills/rustfs-logging-governance/agents/openai.yaml new file mode 100644 index 000000000..fce6821a0 --- /dev/null +++ b/.agents/skills/rustfs-logging-governance/agents/openai.yaml @@ -0,0 +1,4 @@ +interface: + display_name: "RustFS Logging Governance" + short_description: "Standardize RustFS logs with structured events and guardrails." + default_prompt: "Use $rustfs-logging-governance to standardize or review RustFS logging, reduce noise, and update guardrails." diff --git a/.agents/skills/rustfs-logging-governance/references/logging-governance.md b/.agents/skills/rustfs-logging-governance/references/logging-governance.md new file mode 100644 index 000000000..7d4b23893 --- /dev/null +++ b/.agents/skills/rustfs-logging-governance/references/logging-governance.md @@ -0,0 +1,285 @@ +# RustFS Logging Governance Reference + +## Workspace Scope Map + +Use `Cargo.toml` `[workspace].members` as the source of truth for crate membership. When doing a broad logging sweep, classify crates by operational role so logs stay consistent within each role. + +### Core Server And Request Handling + +- `rustfs` + - Role: top-level server, startup, auth, admin wiring, S3 request handling. + - Logging focus: startup lifecycle, config summaries, authn/authz failures, protocol entrypoints, degraded subsystems. +- `crates/protocols` + - Role: protocol integrations such as FTP, SFTP, WebDAV, and related server-side protocol layers. + - Logging focus: listener lifecycle, per-protocol enablement/disablement, request bridge failures. +- `crates/madmin` + - Role: admin API contracts and management interfaces. + - Logging focus: admin action boundaries, validation failures, compatibility warnings. +- `crates/trusted-proxies` + - Role: forwarded IP trust, proxy chain validation, cloud metadata sources. + - Logging focus: direct/trusted/fallback decisions, degraded metadata fetches, aggregated config summaries. +- `crates/keystone` + - Role: Keystone auth integration. + - Logging focus: integration enablement, upstream auth failures, config safety without credential leakage. + +### Storage, Healing, And Data Plane + +- `crates/ecstore` + - Role: erasure-coded storage implementation and peer/store initialization. + - Logging focus: disk/peer lifecycle, storage fallback, object I/O failures, avoid per-object noise. +- `crates/heal` + - Role: healing orchestration and repair workflows. + - Logging focus: scheduler lifecycle, repair decisions, backlog or skipped work summaries, avoid repetitive task spam at `info`. +- `crates/scanner` + - Role: data integrity scanning and health monitoring. + - Logging focus: scan lifecycle, compaction/deep-heal transitions, lag/backlog, noisy folder iteration should stay at `debug/trace`. +- `crates/object-capacity` + - Role: capacity scan and refresh core. + - Logging focus: refresh lifecycle, degraded capacity sources, aggregate stats rather than per-object chatter. +- `crates/filemeta` + - Role: file metadata parsing and helpers. + - Logging focus: parse failures, schema/format mismatch, avoid dumping raw metadata payloads. +- `crates/storage-api` + - Role: storage contracts and shared data plane interfaces. + - Logging focus: contract mismatch and boundary diagnostics, usually low-volume. +- `crates/checksums` + - Role: checksum helpers and validation. + - Logging focus: integrity failures and compatibility mismatches, not per-chunk success logs. +- `crates/zip` + - Role: ZIP handling and compression helpers. + - Logging focus: parse/extract failures, archive path safety issues, avoid verbose file-by-file success logs. + +### Security, Identity, And Policy + +- `crates/iam` + - Role: identity and access management. + - Logging focus: authz decision boundaries, imported payload safety, do not leak principals, secrets, or claims. +- `crates/policy` + - Role: policy modeling and evaluation. + - Logging focus: deny/allow decision context, parser/validation failures, no raw secret-bearing request dumps. +- `crates/credentials` + - Role: credential handling. + - Logging focus: never log secrets or tokens; only safe identifiers and redacted states. +- `crates/kms` + - Role: key management service integration. + - Logging focus: init/health/fallback, key-source availability, never log key material. +- `crates/crypto` + - Role: cryptographic helpers and security primitives. + - Logging focus: only algorithm or mode state, not plaintext, ciphertext, or secret-derived material. +- `crates/security-governance` + - Role: security governance contracts. + - Logging focus: policy/state transitions and enforcement diagnostics. +- `crates/signer` + - Role: request signing helpers. + - Logging focus: signature validation failures without expected-signature leakage. + +### Notifications, Audit, And Targets + +- `crates/notify` + - Role: notification dispatch, runtime facade, notifier implementations. + - Logging focus: target lifecycle, dispatch summaries, stream lag/backpressure, avoid per-event success spam. +- `crates/audit` + - Role: audit target fan-out and audit pipeline management. + - Logging focus: pipeline lifecycle, target availability, batch dispatch summaries, avoid noisy "started successfully" prose. +- `crates/targets` + - Role: target-specific configuration and utilities used by fan-out style systems. + - Logging focus: target selection, config validation, per-target degraded state. +- `crates/s3-types` + - Role: S3 event and type definitions. + - Logging focus: usually minimal; keep logging at integration boundaries rather than low-level type crates. +- `crates/s3-ops` + - Role: S3 operation definitions and mapping. + - Logging focus: mapping/contract failures, unsupported combinations, not normal-path request spam. + +### Concurrency, Locking, And Runtime Foundations + +- `crates/concurrency` + - Role: timeout, locking, backpressure, and I/O scheduling facade. + - Logging focus: lifecycle transitions and degraded states, not high-frequency worker/permit churn at `info`. +- `crates/lock` + - Role: distributed locking implementation. + - Logging focus: lock lifecycle, contention anomalies, lock ordering or timeout diagnostics. +- `crates/tls-runtime` + - Role: shared TLS runtime foundation. + - Logging focus: certificate lifecycle, reload/fallback, validation failures without sensitive dumps. +- `crates/obs` + - Role: observability helpers. + - Logging focus: this crate shapes other crates' telemetry conventions; avoid recursive or redundant summaries. +- `crates/io-core` + - Role: zero-copy I/O core primitives. + - Logging focus: keep very sparse; prefer metrics unless failures are actionable. +- `crates/io-metrics` + - Role: I/O metrics collection. + - Logging focus: typically minimal; metrics should carry the hot-path signal. +- `crates/rio` + - Role: Rust I/O utility layer. + - Logging focus: compatibility or runtime boundary failures, not fast-path internals. +- `crates/rio-v2` + - Role: next-generation I/O compatibility layer. + - Logging focus: migration/feature-mode differences and degraded fallback between I/O paths. +- `crates/utils` + - Role: shared helpers. + - Logging focus: usually avoid direct logging in generic helpers unless the helper is itself an operational boundary. +- `crates/common` + - Role: shared data structures and helpers. + - Logging focus: same principle as `utils`; prefer callers to log context-rich events. +- `crates/config` + - Role: configuration management. + - Logging focus: config source, fallback, validation, and summary aggregation; avoid dumping merged configs. +- `crates/data-usage` + - Role: shared data usage models and algorithms. + - Logging focus: refresh lifecycle, summary stats, and degraded reads. + +### Schema, Contracts, And API Support + +- `crates/protos` + - Role: protobuf definitions. + - Logging focus: usually none inside the crate; emit logs at decode/use boundaries. +- `crates/extension-schema` + - Role: extension schema contracts. + - Logging focus: schema validation and compatibility mismatches. +- `crates/s3select-api` + - Role: S3 Select API interfaces. + - Logging focus: request validation and unsupported feature boundaries. +- `crates/s3select-query` + - Role: S3 Select query engine. + - Logging focus: query parse/planning/execution failures, avoid row-level spam. +- `crates/protocols` + - Role: non-S3 protocol support. + - Logging focus: see core server section; keep per-request verbosity below `info`. + +### Testing And Non-Production Crates + +- `crates/e2e_test` + - Role: end-to-end tests. + - Logging focus: test clarity matters more than production governance, but avoid copying test-only logging style into production crates. + +## Current Guardrail Coverage Map + +`scripts/check_logging_guardrails.sh` currently enforces retired patterns in these high-signal areas: + +- `rustfs/src/main.rs` +- `rustfs/src/startup_iam.rs` +- `rustfs/src/auth.rs` +- `rustfs/src/protocols/client.rs` +- `crates/audit/src/pipeline.rs` +- `crates/audit/src/system.rs` +- `crates/audit/src/global.rs` +- `crates/notify/src/config_manager.rs` +- `crates/notify/src/runtime_facade.rs` +- `crates/notify/src/notifier.rs` +- `crates/ecstore/src/store/peer.rs` +- `crates/ecstore/src/store/init.rs` +- `crates/ecstore/src/tier/tier.rs` +- `crates/concurrency/src/workers.rs` +- `crates/concurrency/src/manager.rs` +- `crates/concurrency/src/lock.rs` +- `crates/concurrency/src/deadlock.rs` +- `crates/trusted-proxies/src/global.rs` +- `crates/trusted-proxies/src/config/loader.rs` +- `crates/trusted-proxies/src/proxy/metrics.rs` +- `crates/trusted-proxies/src/proxy/validator.rs` +- `crates/trusted-proxies/src/proxy/chain.rs` +- `crates/trusted-proxies/src/middleware/service.rs` +- `crates/trusted-proxies/src/cloud/detector.rs` +- `crates/trusted-proxies/src/cloud/ranges.rs` +- `crates/trusted-proxies/src/cloud/metadata/aws.rs` +- `crates/trusted-proxies/src/cloud/metadata/azure.rs` +- `crates/trusted-proxies/src/cloud/metadata/gcp.rs` + +When expanding coverage, prefer crates with: + +- repeated sentence-style lifecycle logs +- high-frequency success-path `info!` +- startup/config checklist banners +- security-sensitive fallback wording +- external fetch/retry/fallback flows + +That typically means the next broad candidates are `rustfs`, `crates/notify`, `crates/audit`, `crates/targets`, `crates/heal`, and `crates/scanner`. + +## Event Model + +Prefer this structure when the fields are available: + +- `event` +- `component` +- `subsystem` +- `state` or `result` +- stable context fields such as: + - `enabled` + - `implementation` + - `validation_mode` + - `peer_ip` + - `client_ip` + - `proxy_hops` + - `duration_ms` + - `fallback` + - `reason` + - `range_count` + - `hold_time_ms` + - `available_slots` + - `total_slots` + - `permits_in_use` + +## Level Policy + +- `error`: the operation fails and callers or security guarantees are affected. +- `warn`: a degraded path, fallback, suspicious request, or operator-actionable config issue occurs. +- `info`: a low-frequency lifecycle or mode transition occurs. +- `debug`: useful diagnostics exist but normal operators do not need them all the time. +- `trace`: hot-path and repetitive success-path details occur. + +## Preferred Patterns + +- Use a short message label: + - `"trusted proxy validation failed"` + - `"concurrency manager state changed"` + - `"trusted proxy cloud metadata loaded"` +- Put key meaning into fields, not only the message text. +- Aggregate config or metrics summaries into one log event. + +## Retired Patterns + +These should usually be removed or replaced: + +- Sentence-style lifecycle logs: + - `info!("Concurrency manager stopped")` + - `info!("Trusted Proxies module initialized")` +- Checklist or banner logs: + - `info!("=== Application Configuration ===")` + - `info!("Available metrics:")` +- Hot-path noise: + - `info!("worker take, {}", *available)` + - `debug!("Proxy validation successful in {:?}", duration)` +- Legacy fallback prose: + - `"Request from private network but not trusted: ..."` + - `"Cloud metadata fetching is disabled"` + +## Guardrail Update Checklist + +When extending `scripts/check_logging_guardrails.sh`: + +1. Add the touched files to `checked_files`. +2. Add only legacy patterns that have been intentionally retired. +3. Keep patterns literal and grep-friendly. +4. Run the guardrail script after changes. +5. Avoid adding patterns for logs that are still valid elsewhere in the repo. + +## Validation Checklist + +For logging-only changes: + +```bash +cargo fmt --all --check +./scripts/check_logging_guardrails.sh +cargo check -p +cargo test -p +``` + +For broader Rust changes: + +```bash +./scripts/check_unsafe_code_allowances.sh +./scripts/check_architecture_migration_rules.sh +cargo clippy -p --all-targets -- -D warnings +``` diff --git a/crates/concurrency/src/deadlock.rs b/crates/concurrency/src/deadlock.rs index e291ec352..f55b4990e 100644 --- a/crates/concurrency/src/deadlock.rs +++ b/crates/concurrency/src/deadlock.rs @@ -102,7 +102,15 @@ impl DeadlockManager { *running = true; drop(running); - tracing::info!("Deadlock detection started"); + tracing::info!( + event = "deadlock_monitor.lifecycle", + component = "concurrency", + subsystem = "deadlock", + state = "started", + check_interval_ms = self.config.check_interval.as_millis(), + hang_threshold_ms = self.config.hang_threshold.as_millis(), + "deadlock monitor state changed" + ); } /// Stop the deadlock detection @@ -110,7 +118,15 @@ impl DeadlockManager { let mut running = self.running.lock().await; *running = false; - tracing::info!("Deadlock detection stopped"); + tracing::info!( + event = "deadlock_monitor.lifecycle", + component = "concurrency", + subsystem = "deadlock", + state = "stopped", + check_interval_ms = self.config.check_interval.as_millis(), + hang_threshold_ms = self.config.hang_threshold.as_millis(), + "deadlock monitor state changed" + ); } /// Create a request tracker diff --git a/crates/concurrency/src/lock.rs b/crates/concurrency/src/lock.rs index 41cd25bb1..25a02aa24 100644 --- a/crates/concurrency/src/lock.rs +++ b/crates/concurrency/src/lock.rs @@ -138,9 +138,13 @@ impl OptimizedLockGuard { lock_metrics::record_lock_hold_time(hold_time); tracing::debug!( + event = "lock_guard.release", + component = "concurrency", + subsystem = "lock", + release_mode = "early", resource = %self.resource, hold_time_ms = hold_time.as_millis(), - "Lock released early (optimization active)" + "lock guard released" ); } @@ -161,9 +165,13 @@ impl Drop for OptimizedLockGuard { lock_metrics::record_lock_hold_time(hold_time); tracing::debug!( + event = "lock_guard.release", + component = "concurrency", + subsystem = "lock", + release_mode = "drop", resource = %self.resource, hold_time_ms = hold_time.as_millis(), - "Lock released on drop (normal release)" + "lock guard released" ); } } diff --git a/crates/concurrency/src/manager.rs b/crates/concurrency/src/manager.rs index 6259a7ff6..423f6686a 100644 --- a/crates/concurrency/src/manager.rs +++ b/crates/concurrency/src/manager.rs @@ -233,12 +233,16 @@ impl ConcurrencyManager { } tracing::info!( - "Concurrency manager started (timeout={}, lock={}, deadlock={}, backpressure={}, scheduler={})", - self.is_timeout_enabled(), - self.is_lock_enabled(), - self.is_deadlock_enabled(), - self.is_backpressure_enabled(), - self.is_scheduler_enabled() + event = "concurrency_manager.lifecycle", + component = "concurrency", + subsystem = "manager", + state = "started", + timeout_enabled = self.is_timeout_enabled(), + lock_enabled = self.is_lock_enabled(), + deadlock_enabled = self.is_deadlock_enabled(), + backpressure_enabled = self.is_backpressure_enabled(), + scheduler_enabled = self.is_scheduler_enabled(), + "concurrency manager state changed" ); } @@ -249,7 +253,13 @@ impl ConcurrencyManager { self.deadlock.stop().await; } - tracing::info!("Concurrency manager stopped"); + tracing::info!( + event = "concurrency_manager.lifecycle", + component = "concurrency", + subsystem = "manager", + state = "stopped", + "concurrency manager state changed" + ); } } diff --git a/crates/concurrency/src/workers.rs b/crates/concurrency/src/workers.rs index 0c116a9bd..e0eb47913 100644 --- a/crates/concurrency/src/workers.rs +++ b/crates/concurrency/src/workers.rs @@ -16,7 +16,7 @@ use std::sync::Arc; use tokio::sync::{Mutex, Notify}; -use tracing::info; +use tracing::{debug, trace}; /// Cooperative worker-slot controller for async tasks. pub struct Workers { @@ -43,12 +43,30 @@ impl Workers { pub async fn take(&self) { loop { let mut available = self.available.lock().await; - info!("worker take, {}", *available); if *available == 0 { + trace!( + event = "worker_slot.acquire", + component = "concurrency", + subsystem = "workers", + state = "waiting", + available_slots = *available, + total_slots = self.limit, + "worker slot pending" + ); drop(available); self.notify.notified().await; } else { *available -= 1; + trace!( + event = "worker_slot.acquire", + component = "concurrency", + subsystem = "workers", + state = "granted", + available_slots = *available, + total_slots = self.limit, + permits_in_use = self.limit.saturating_sub(*available), + "worker slot updated" + ); break; } } @@ -57,8 +75,17 @@ impl Workers { /// Release a worker slot. pub async fn give(&self) { let mut available = self.available.lock().await; - info!("worker give, {}", *available); *available = (*available).saturating_add(1).min(self.limit); // avoid over-release beyond limit + trace!( + event = "worker_slot.release", + component = "concurrency", + subsystem = "workers", + state = "released", + available_slots = *available, + total_slots = self.limit, + permits_in_use = self.limit.saturating_sub(*available), + "worker slot updated" + ); self.notify.notify_one(); // Notify a waiting task } @@ -70,11 +97,30 @@ impl Workers { if *available == self.limit { break; } + trace!( + event = "worker_slot.wait", + component = "concurrency", + subsystem = "workers", + state = "waiting", + available_slots = *available, + total_slots = self.limit, + permits_in_use = self.limit.saturating_sub(*available), + "worker drain pending" + ); } // Wait until all slots are freed self.notify.notified().await; } - info!("worker wait end"); + debug!( + event = "worker_slot.wait", + component = "concurrency", + subsystem = "workers", + state = "drained", + available_slots = self.limit, + total_slots = self.limit, + permits_in_use = 0, + "worker drain complete" + ); } /// Return the current number of available worker slots. diff --git a/crates/trusted-proxies/src/cloud/detector.rs b/crates/trusted-proxies/src/cloud/detector.rs index b6a3dbb8a..0d641585c 100644 --- a/crates/trusted-proxies/src/cloud/detector.rs +++ b/crates/trusted-proxies/src/cloud/detector.rs @@ -157,12 +157,30 @@ pub trait CloudMetadataFetcher: Send + Sync { match self.fetch_network_cidrs().await { Ok(cidrs) => ranges.extend(cidrs), - Err(e) => warn!("Failed to fetch network CIDRs from {}: {}", self.provider_name(), e), + Err(e) => warn!( + event = "trusted_proxies.cloud_fetch", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = self.provider_name(), + dataset = "network_cidrs", + result = "degraded", + error = %e, + "trusted proxy cloud metadata fetch degraded" + ), } match self.fetch_public_ip_ranges().await { Ok(public_ranges) => ranges.extend(public_ranges), - Err(e) => warn!("Failed to fetch public IP ranges from {}: {}", self.provider_name(), e), + Err(e) => warn!( + event = "trusted_proxies.cloud_fetch", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = self.provider_name(), + dataset = "public_ip_ranges", + result = "degraded", + error = %e, + "trusted proxy cloud metadata fetch degraded" + ), } Ok(ranges) @@ -208,7 +226,13 @@ impl CloudDetector { /// Fetches trusted IP ranges for the detected cloud provider. pub async fn fetch_trusted_ranges(&self) -> Result, AppError> { if !self.enabled { - debug!("Cloud metadata fetching is disabled"); + debug!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + state = "disabled", + "trusted proxy cloud detection skipped" + ); return Ok(Vec::new()); } @@ -216,36 +240,87 @@ impl CloudDetector { match provider { Some(CloudProvider::Aws) => { - info!("Detected AWS environment, fetching metadata"); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = "aws", + result = "detected", + timeout_ms = self.timeout.as_millis(), + "trusted proxy cloud provider detected" + ); let fetcher = crate::AwsMetadataFetcher::new(self.timeout); fetcher.fetch_trusted_proxy_ranges().await } Some(CloudProvider::Azure) => { - info!("Detected Azure environment, fetching metadata"); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = "azure", + result = "detected", + timeout_ms = self.timeout.as_millis(), + "trusted proxy cloud provider detected" + ); let fetcher = crate::AzureMetadataFetcher::new(self.timeout); fetcher.fetch_trusted_proxy_ranges().await } Some(CloudProvider::Gcp) => { - info!("Detected GCP environment, fetching metadata"); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = "gcp", + result = "detected", + timeout_ms = self.timeout.as_millis(), + "trusted proxy cloud provider detected" + ); let fetcher = crate::GcpMetadataFetcher::new(self.timeout); fetcher.fetch_trusted_proxy_ranges().await } Some(CloudProvider::Cloudflare) => { - info!("Detected Cloudflare environment"); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = "cloudflare", + result = "detected", + "trusted proxy cloud provider detected" + ); let ranges = crate::CloudflareIpRanges::fetch().await?; Ok(ranges) } Some(CloudProvider::DigitalOcean) => { - info!("Detected DigitalOcean environment"); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = "digitalocean", + result = "detected", + "trusted proxy cloud provider detected" + ); let ranges = crate::DigitalOceanIpRanges::fetch().await?; Ok(ranges) } Some(CloudProvider::Unknown(name)) => { - warn!("Unknown cloud provider detected: {}", name); + warn!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = %name, + result = "unknown", + "trusted proxy cloud provider unresolved" + ); Ok(Vec::new()) } None => { - debug!("No cloud provider detected"); + debug!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + result = "none", + "trusted proxy cloud provider not detected" + ); Ok(Vec::new()) } } @@ -265,17 +340,40 @@ impl CloudDetector { for provider in providers { let provider_name = provider.provider_name(); - debug!("Trying to fetch metadata from {}", provider_name); + debug!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = provider_name, + result = "attempt", + "trusted proxy cloud provider fetch attempted" + ); match provider.fetch_trusted_proxy_ranges().await { Ok(ranges) => { if !ranges.is_empty() { - info!("Fetched {} IP ranges from {}", ranges.len(), provider_name); + info!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = provider_name, + result = "loaded", + range_count = ranges.len(), + "trusted proxy cloud provider ranges loaded" + ); return Ok(ranges); } } Err(e) => { - debug!("Failed to fetch metadata from {}: {}", provider_name, e); + debug!( + event = "trusted_proxies.cloud_detect", + component = "trusted_proxies", + subsystem = "cloud_detector", + provider = provider_name, + result = "failed", + error = %e, + "trusted proxy cloud provider fetch failed" + ); } } } diff --git a/crates/trusted-proxies/src/cloud/metadata/aws.rs b/crates/trusted-proxies/src/cloud/metadata/aws.rs index c5b889208..506eca925 100644 --- a/crates/trusted-proxies/src/cloud/metadata/aws.rs +++ b/crates/trusted-proxies/src/cloud/metadata/aws.rs @@ -67,12 +67,30 @@ impl AwsMetadataFetcher { .map_err(|e| AppError::cloud(format!("Failed to read IMDSv2 token: {}", e)))?; Ok(token) } else { - debug!("IMDSv2 token request failed with status: {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "imdsv2_token", + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud("Failed to obtain IMDSv2 token")) } } Err(e) => { - debug!("IMDSv2 token request failed: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "imdsv2_token", + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud(format!("IMDSv2 request failed: {}", e))) } } @@ -97,7 +115,17 @@ impl CloudMetadataFetcher for AwsMetadataFetcher { match networks { Ok(networks) => { - debug!("Using default AWS VPC network ranges"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "network_cidrs", + result = "fallback", + source = "default_ranges", + range_count = networks.len(), + "trusted proxy cloud metadata fallback applied" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse default AWS ranges: {}", e))), @@ -137,15 +165,43 @@ impl CloudMetadataFetcher for AwsMetadataFetcher { } } - info!("Successfully fetched {} AWS public IP ranges", networks.len()); + info!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "public_ip_ranges", + result = "loaded", + source = "api", + range_count = networks.len(), + "trusted proxy cloud metadata loaded" + ); Ok(networks) } else { - debug!("Failed to fetch AWS IP ranges: HTTP {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "public_ip_ranges", + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Ok(Vec::new()) } } Err(e) => { - debug!("Failed to fetch AWS IP ranges: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "aws_metadata", + provider = "aws", + operation = "public_ip_ranges", + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); Ok(Vec::new()) } } diff --git a/crates/trusted-proxies/src/cloud/metadata/azure.rs b/crates/trusted-proxies/src/cloud/metadata/azure.rs index e8ce7e912..2095249d9 100644 --- a/crates/trusted-proxies/src/cloud/metadata/azure.rs +++ b/crates/trusted-proxies/src/cloud/metadata/azure.rs @@ -46,7 +46,15 @@ impl AzureMetadataFetcher { async fn get_metadata(&self, path: &str) -> Result { let url = format!("{}/metadata/{}?api-version=2021-05-01", self.metadata_endpoint, path); - debug!("Fetching Azure metadata from: {}", url); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "metadata_request", + path = %path, + "trusted proxy cloud metadata request started" + ); match self.client.get(&url).header("Metadata", "true").send().await { Ok(response) => { @@ -57,12 +65,32 @@ impl AzureMetadataFetcher { .map_err(|e| AppError::cloud(format!("Failed to read Azure metadata response: {}", e)))?; Ok(text) } else { - debug!("Azure metadata request failed with status: {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "metadata_request", + path = %path, + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud(format!("Azure metadata API returned status: {}", response.status()))) } } Err(e) => { - debug!("Azure metadata request failed: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "metadata_request", + path = %path, + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud(format!("Azure metadata request failed: {}", e))) } } @@ -91,7 +119,15 @@ impl AzureMetadataFetcher { address_prefixes: Vec, } - debug!("Fetching Azure IP ranges from: {}", url); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "public_ip_ranges", + source = %url, + "trusted proxy cloud metadata request started" + ); match self.client.get(url).timeout(Duration::from_secs(10)).send().await { Ok(response) => { @@ -114,15 +150,45 @@ impl AzureMetadataFetcher { } } - info!("Successfully fetched {} Azure public IP ranges", networks.len()); + info!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "public_ip_ranges", + source = "api", + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud metadata loaded" + ); Ok(networks) } else { - debug!("Failed to fetch Azure IP ranges: HTTP {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "public_ip_ranges", + source = %url, + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Ok(Vec::new()) } } Err(e) => { - debug!("Failed to fetch Azure IP ranges: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "public_ip_ranges", + source = %url, + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); // Fallback to hardcoded ranges if the download fails. Self::default_azure_ranges() } @@ -217,7 +283,17 @@ impl AzureMetadataFetcher { match networks { Ok(networks) => { - debug!("Using default Azure public IP ranges"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "public_ip_ranges", + result = "fallback", + source = "default_ranges", + range_count = networks.len(), + "trusted proxy cloud metadata fallback applied" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse default Azure ranges: {}", e))), @@ -265,15 +341,45 @@ impl CloudMetadataFetcher for AzureMetadataFetcher { } if !cidrs.is_empty() { - info!("Successfully fetched {} network CIDRs from Azure metadata", cidrs.len()); + info!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "network_cidrs", + source = "metadata", + result = "loaded", + range_count = cidrs.len(), + "trusted proxy cloud metadata loaded" + ); Ok(cidrs) } else { - debug!("No network CIDRs found in Azure metadata, falling back to defaults"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "network_cidrs", + source = "metadata", + result = "fallback", + reason = "empty_metadata", + "trusted proxy cloud metadata fallback applied" + ); Self::default_azure_network_ranges() } } Err(e) => { - warn!("Failed to fetch Azure network metadata: {}", e); + warn!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "network_cidrs", + source = "metadata", + result = "fallback", + error = %e, + "trusted proxy cloud metadata fallback applied" + ); Self::default_azure_network_ranges() } } @@ -299,7 +405,17 @@ impl AzureMetadataFetcher { match networks { Ok(networks) => { - debug!("Using default Azure VNet network ranges"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "azure_metadata", + provider = "azure", + operation = "network_cidrs", + result = "fallback", + source = "default_ranges", + range_count = networks.len(), + "trusted proxy cloud metadata fallback applied" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse default Azure network ranges: {}", e))), diff --git a/crates/trusted-proxies/src/cloud/metadata/gcp.rs b/crates/trusted-proxies/src/cloud/metadata/gcp.rs index ad4f90dd4..6872a293c 100644 --- a/crates/trusted-proxies/src/cloud/metadata/gcp.rs +++ b/crates/trusted-proxies/src/cloud/metadata/gcp.rs @@ -46,7 +46,15 @@ impl GcpMetadataFetcher { async fn get_metadata(&self, path: &str) -> Result { let url = format!("{}/computeMetadata/v1/{}", self.metadata_endpoint, path); - debug!("Fetching GCP metadata from: {}", url); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "metadata_request", + path = %path, + "trusted proxy cloud metadata request started" + ); match self.client.get(&url).header("Metadata-Flavor", "Google").send().await { Ok(response) => { @@ -57,12 +65,32 @@ impl GcpMetadataFetcher { .map_err(|e| AppError::cloud(format!("Failed to read GCP metadata response: {}", e)))?; Ok(text) } else { - debug!("GCP metadata request failed with status: {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "metadata_request", + path = %path, + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud(format!("GCP metadata API returned status: {}", response.status()))) } } Err(e) => { - debug!("GCP metadata request failed: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "metadata_request", + path = %path, + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); Err(AppError::cloud(format!("GCP metadata request failed: {}", e))) } } @@ -123,7 +151,17 @@ impl CloudMetadataFetcher for GcpMetadataFetcher { .collect(); if interface_indices.is_empty() { - warn!("No network interfaces found in GCP metadata"); + warn!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_cidrs", + source = "metadata", + result = "fallback", + reason = "no_interfaces", + "trusted proxy cloud metadata fallback applied" + ); return Self::default_gcp_network_ranges(); } @@ -149,21 +187,61 @@ impl CloudMetadataFetcher for GcpMetadataFetcher { } } Err(e) => { - debug!("Failed to get IP/mask for GCP interface {}: {}", index, e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_interface", + interface_index = index, + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); } } } if cidrs.is_empty() { - warn!("Could not determine network CIDRs from GCP metadata, falling back to defaults"); + warn!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_cidrs", + source = "metadata", + result = "fallback", + reason = "empty_metadata", + "trusted proxy cloud metadata fallback applied" + ); Self::default_gcp_network_ranges() } else { - info!("Successfully fetched {} network CIDRs from GCP metadata", cidrs.len()); + info!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_cidrs", + source = "metadata", + result = "loaded", + range_count = cidrs.len(), + "trusted proxy cloud metadata loaded" + ); Ok(cidrs) } } Err(e) => { - warn!("Failed to fetch GCP network metadata: {}", e); + warn!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_cidrs", + source = "metadata", + result = "fallback", + error = %e, + "trusted proxy cloud metadata fallback applied" + ); Self::default_gcp_network_ranges() } } @@ -189,7 +267,15 @@ impl GcpMetadataFetcher { ipv4_prefix: Option, } - debug!("Fetching GCP IP ranges from: {}", url); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "public_ip_ranges", + source = %url, + "trusted proxy cloud metadata request started" + ); match self.client.get(url).timeout(Duration::from_secs(10)).send().await { Ok(response) => { @@ -209,15 +295,45 @@ impl GcpMetadataFetcher { } } - info!("Successfully fetched {} GCP public IP ranges", networks.len()); + info!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "public_ip_ranges", + source = "api", + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud metadata loaded" + ); Ok(networks) } else { - debug!("Failed to fetch GCP IP ranges: HTTP {}", response.status()); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "public_ip_ranges", + source = %url, + result = "http_error", + status = %response.status(), + "trusted proxy cloud metadata request failed" + ); Self::default_gcp_ip_ranges() } } Err(e) => { - debug!("Failed to fetch GCP IP ranges: {}", e); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "public_ip_ranges", + source = %url, + result = "request_failed", + error = %e, + "trusted proxy cloud metadata request failed" + ); Self::default_gcp_ip_ranges() } } @@ -280,7 +396,17 @@ impl GcpMetadataFetcher { match networks { Ok(networks) => { - debug!("Using default GCP public IP ranges"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "public_ip_ranges", + result = "fallback", + source = "default_ranges", + range_count = networks.len(), + "trusted proxy cloud metadata fallback applied" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse default GCP ranges: {}", e))), @@ -300,7 +426,17 @@ impl GcpMetadataFetcher { match networks { Ok(networks) => { - debug!("Using default GCP VPC network ranges"); + debug!( + event = "trusted_proxies.cloud_metadata", + component = "trusted_proxies", + subsystem = "gcp_metadata", + provider = "gcp", + operation = "network_cidrs", + result = "fallback", + source = "default_ranges", + range_count = networks.len(), + "trusted proxy cloud metadata fallback applied" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse default GCP network ranges: {}", e))), diff --git a/crates/trusted-proxies/src/cloud/ranges.rs b/crates/trusted-proxies/src/cloud/ranges.rs index b7b81a7f7..cd3b8e4e0 100644 --- a/crates/trusted-proxies/src/cloud/ranges.rs +++ b/crates/trusted-proxies/src/cloud/ranges.rs @@ -60,7 +60,16 @@ impl CloudflareIpRanges { match networks { Ok(networks) => { - info!("Loaded {} static Cloudflare IP ranges", networks.len()); + info!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = "static", + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud ranges loaded" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse static Cloudflare IP ranges: {}", e))), @@ -96,19 +105,55 @@ impl CloudflareIpRanges { match ranges { Ok(mut networks) => { - debug!("Fetched {} IP ranges from {}", networks.len(), url); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = %url, + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud ranges fetched" + ); all_ranges.append(&mut networks); } Err(e) => { - debug!("Failed to parse IP ranges from {}: {}", url, e); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = %url, + result = "parse_failed", + error = %e, + "trusted proxy cloud ranges parse failed" + ); } } } else { - debug!("Failed to fetch IP ranges from {}: HTTP {}", url, response.status()); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = %url, + result = "http_error", + status = %response.status(), + "trusted proxy cloud ranges fetch failed" + ); } } Err(e) => { - debug!("Failed to fetch from {}: {}", url, e); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = %url, + result = "request_failed", + error = %e, + "trusted proxy cloud ranges fetch failed" + ); } } } @@ -117,7 +162,16 @@ impl CloudflareIpRanges { // Fallback to static list if API requests fail. Self::fetch().await } else { - info!("Successfully fetched {} Cloudflare IP ranges from API", all_ranges.len()); + info!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "cloudflare", + source = "api", + result = "loaded", + range_count = all_ranges.len(), + "trusted proxy cloud ranges loaded" + ); Ok(all_ranges) } } @@ -151,7 +205,16 @@ impl DigitalOceanIpRanges { match networks { Ok(networks) => { - info!("Loaded {} static DigitalOcean IP ranges", networks.len()); + info!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "digitalocean", + source = "static", + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud ranges loaded" + ); Ok(networks) } Err(e) => Err(AppError::cloud(format!("Failed to parse static DigitalOcean IP ranges: {}", e))), @@ -200,15 +263,42 @@ impl GoogleCloudIpRanges { } } - info!("Successfully fetched {} Google Cloud IP ranges from API", networks.len()); + info!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "gcp", + source = "api", + result = "loaded", + range_count = networks.len(), + "trusted proxy cloud ranges loaded" + ); Ok(networks) } else { - debug!("Failed to fetch Google IP ranges: HTTP {}", response.status()); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "gcp", + source = %url, + result = "http_error", + status = %response.status(), + "trusted proxy cloud ranges fetch failed" + ); Ok(Vec::new()) } } Err(e) => { - debug!("Failed to fetch Google IP ranges: {}", e); + debug!( + event = "trusted_proxies.cloud_ranges", + component = "trusted_proxies", + subsystem = "cloud_ranges", + provider = "gcp", + source = %url, + result = "request_failed", + error = %e, + "trusted proxy cloud ranges fetch failed" + ); Ok(Vec::new()) } } diff --git a/crates/trusted-proxies/src/config/loader.rs b/crates/trusted-proxies/src/config/loader.rs index 9cb43911c..21cc97e02 100644 --- a/crates/trusted-proxies/src/config/loader.rs +++ b/crates/trusted-proxies/src/config/loader.rs @@ -176,11 +176,26 @@ impl ConfigLoader { pub fn from_env_or_default() -> AppConfig { match Self::from_env() { Ok(config) => { - info!("Configuration loaded successfully from environment variables"); + info!( + event = "trusted_proxies.config", + component = "trusted_proxies", + subsystem = "config_loader", + result = "loaded", + source = "environment", + "trusted proxies configuration loaded" + ); config } Err(e) => { - tracing::warn!("Failed to load configuration from environment: {}. Using defaults", e); + tracing::warn!( + event = "trusted_proxies.config", + component = "trusted_proxies", + subsystem = "config_loader", + result = "fallback", + source = "defaults", + error = %e, + "trusted proxies configuration fell back to defaults" + ); Self::default_config() } } @@ -214,20 +229,38 @@ impl ConfigLoader { /// Prints a summary of the configuration to the log. pub fn print_summary(config: &AppConfig) { - info!("=== Application Configuration ==="); - info!("Server: {}", config.server_addr); - info!("Trusted Proxies: {}", config.proxy.proxies.len()); - info!("Validation Mode: {:?}", config.proxy.validation_mode); - info!("Cache Capacity: {}", config.cache.capacity); - info!("Metrics Enabled: {}", config.monitoring.metrics_enabled); - info!("Cloud Metadata: {}", config.cloud.metadata_enabled); - - if config.monitoring.log_failed_validations { - info!("Failed validations will be logged"); - } + info!( + event = "trusted_proxies.config", + component = "trusted_proxies", + subsystem = "config_loader", + result = "summary", + server_addr = %config.server_addr, + trusted_proxy_count = config.proxy.proxies.len(), + validation_mode = config.proxy.validation_mode.as_str(), + cache_capacity = config.cache.capacity, + cache_ttl_seconds = config.cache.ttl_seconds, + cache_cleanup_interval_seconds = config.cache.cleanup_interval_seconds, + metrics_enabled = config.monitoring.metrics_enabled, + structured_logging = config.monitoring.structured_logging, + tracing_enabled = config.monitoring.tracing_enabled, + log_failed_validations = config.monitoring.log_failed_validations, + cloud_metadata_enabled = config.cloud.metadata_enabled, + cloud_metadata_timeout_seconds = config.cloud.metadata_timeout_seconds, + cloudflare_ips_enabled = config.cloud.cloudflare_ips_enabled, + forced_provider = config.cloud.forced_provider.as_deref().unwrap_or("none"), + "trusted proxies configuration summarized" + ); if !config.proxy.proxies.is_empty() { - tracing::debug!("Trusted networks: {:?}", config.proxy.get_network_strings()); + tracing::debug!( + event = "trusted_proxies.config", + component = "trusted_proxies", + subsystem = "config_loader", + result = "trusted_networks", + trusted_proxy_count = config.proxy.proxies.len(), + trusted_networks = ?config.proxy.get_network_strings(), + "trusted proxies networks enumerated" + ); } } } diff --git a/crates/trusted-proxies/src/global.rs b/crates/trusted-proxies/src/global.rs index 162d1cb2e..7d0e7033e 100644 --- a/crates/trusted-proxies/src/global.rs +++ b/crates/trusted-proxies/src/global.rs @@ -43,7 +43,14 @@ pub fn init() { ENABLED.get_or_init(|| enabled); if !enabled { - tracing::info!("Trusted Proxies module is disabled via configuration"); + tracing::info!( + event = "trusted_proxies.lifecycle", + component = "trusted_proxies", + subsystem = "global", + state = "disabled", + enabled, + "trusted proxies state changed" + ); return; } @@ -66,7 +73,17 @@ pub fn init() { ) }); - tracing::info!("Trusted Proxies module initialized"); + tracing::info!( + event = "trusted_proxies.lifecycle", + component = "trusted_proxies", + subsystem = "global", + state = "initialized", + enabled, + metrics_enabled = config.monitoring.metrics_enabled, + trusted_proxy_count = config.proxy.proxies.len(), + validation_mode = config.proxy.validation_mode.as_str(), + "trusted proxies state changed" + ); ConfigLoader::print_summary(&config); } diff --git a/crates/trusted-proxies/src/middleware/service.rs b/crates/trusted-proxies/src/middleware/service.rs index 0e0c69b9a..fdfac736c 100644 --- a/crates/trusted-proxies/src/middleware/service.rs +++ b/crates/trusted-proxies/src/middleware/service.rs @@ -19,7 +19,7 @@ use http::Request; use std::sync::Arc; use std::task::{Context, Poll}; use tower::Service; -use tracing::debug; +use tracing::{debug, trace, warn}; /// Tower Service for the trusted proxy middleware. #[derive(Clone)] @@ -64,7 +64,13 @@ where fn call(&mut self, mut req: Request) -> Self::Future { // If the middleware is disabled, pass the request through immediately. if !self.enabled { - debug!("Trusted proxy middleware is disabled"); + debug!( + event = "proxy_validation.middleware", + component = "trusted_proxies", + subsystem = "middleware", + state = "disabled", + "trusted proxy middleware bypassed" + ); return self.inner.call(req); } @@ -77,20 +83,65 @@ where match self.validator.validate_request(peer_addr, req.headers()) { Ok(client_info) => { // Insert the verified client info into the request extensions. - req.extensions_mut().insert(client_info); - let duration = start_time.elapsed(); - debug!("Proxy validation successful in {:?}", duration); + trace!( + event = "proxy_validation.middleware", + component = "trusted_proxies", + subsystem = "middleware", + result = if client_info.is_from_trusted_proxy { + "trusted_proxy" + } else { + "direct" + }, + peer_ip = peer_addr + .map(|addr| addr.ip().to_string()) + .unwrap_or_else(|| "0.0.0.0".to_string()), + client_ip = %client_info.real_ip, + proxy_hops = client_info.proxy_hops, + warning_count = client_info.warnings.len(), + validation_mode = client_info.validation_mode.as_str(), + duration_ms = duration.as_millis(), + "trusted proxy evaluation completed" + ); + + req.extensions_mut().insert(client_info); } Err(err) => { // If the error is recoverable, fallback to a direct connection info. if err.is_recoverable() { + let duration = start_time.elapsed(); + warn!( + event = "proxy_validation.middleware", + component = "trusted_proxies", + subsystem = "middleware", + result = "fallback", + fallback = "socket_peer", + peer_ip = peer_addr + .map(|addr| addr.ip().to_string()) + .unwrap_or_else(|| "0.0.0.0".to_string()), + error = %err, + duration_ms = duration.as_millis(), + "trusted proxy validation fell back to direct peer" + ); let client_info = ClientInfo::direct( peer_addr.unwrap_or_else(|| std::net::SocketAddr::new(std::net::IpAddr::from([0, 0, 0, 0]), 0)), ); req.extensions_mut().insert(client_info); } else { - debug!("Unrecoverable proxy validation error: {}", err); + let duration = start_time.elapsed(); + warn!( + event = "proxy_validation.middleware", + component = "trusted_proxies", + subsystem = "middleware", + result = "error", + fallback = "none", + peer_ip = peer_addr + .map(|addr| addr.ip().to_string()) + .unwrap_or_else(|| "0.0.0.0".to_string()), + error = %err, + duration_ms = duration.as_millis(), + "trusted proxy validation failed" + ); } } } diff --git a/crates/trusted-proxies/src/proxy/chain.rs b/crates/trusted-proxies/src/proxy/chain.rs index 629147cf7..ac2a15cab 100644 --- a/crates/trusted-proxies/src/proxy/chain.rs +++ b/crates/trusted-proxies/src/proxy/chain.rs @@ -81,7 +81,15 @@ impl ProxyChainAnalyzer { current_proxy_ip: IpAddr, headers: &HeaderMap, ) -> Result { - trace!("Analyzing proxy chain: {:?} with current proxy: {}", proxy_chain, current_proxy_ip); + trace!( + event = "proxy_chain.analyze", + component = "trusted_proxies", + subsystem = "chain", + validation_mode = self.config.validation_mode.as_str(), + proxy_chain_len = proxy_chain.len(), + current_proxy_ip = %current_proxy_ip, + "proxy chain analysis started" + ); // Validate all IP addresses in the chain. self.validate_ip_addresses(proxy_chain)?; diff --git a/crates/trusted-proxies/src/proxy/metrics.rs b/crates/trusted-proxies/src/proxy/metrics.rs index 7ae8afc3a..2b5c4d629 100644 --- a/crates/trusted-proxies/src/proxy/metrics.rs +++ b/crates/trusted-proxies/src/proxy/metrics.rs @@ -219,21 +219,26 @@ impl ProxyMetrics { /// Prints a summary of enabled metrics to the log. pub fn print_summary(&self) { if !self.enabled { - info!("Metrics collection is disabled"); + info!( + event = "trusted_proxies.metrics", + component = "trusted_proxies", + subsystem = "metrics", + state = "disabled", + app = %self.app_name, + "trusted proxies metrics state changed" + ); return; } - info!("Proxy metrics enabled for application: {}", self.app_name); - info!("Available metrics:"); - info!(" - rustfs_trusted_proxy_validation_attempts_total"); - info!(" - rustfs_trusted_proxy_validation_success_total"); - info!(" - rustfs_trusted_proxy_validation_failure_total"); - info!(" - rustfs_trusted_proxy_validation_failure_by_type_total"); - info!(" - rustfs_trusted_proxy_chain_length"); - info!(" - rustfs_trusted_proxy_validation_duration_seconds"); - info!(" - rustfs_trusted_proxy_cache_size"); - info!(" - rustfs_trusted_proxy_cache_hits_total"); - info!(" - rustfs_trusted_proxy_cache_misses_total"); + info!( + event = "trusted_proxies.metrics", + component = "trusted_proxies", + subsystem = "metrics", + state = "enabled", + app = %self.app_name, + metric_count = 9, + "trusted proxies metrics state changed" + ); } } diff --git a/crates/trusted-proxies/src/proxy/validator.rs b/crates/trusted-proxies/src/proxy/validator.rs index 993f1890f..5a37d1a9f 100644 --- a/crates/trusted-proxies/src/proxy/validator.rs +++ b/crates/trusted-proxies/src/proxy/validator.rs @@ -18,7 +18,7 @@ use axum::http::HeaderMap; use std::net::{IpAddr, SocketAddr}; use std::sync::Arc; use std::time::{Duration, Instant}; -use tracing::{debug, warn}; +use tracing::{debug, trace, warn}; use crate::{ CacheConfig, CacheStats, IpValidationCache, ProxyChainAnalyzer, ProxyError, ProxyMetrics, TrustedProxyConfig, ValidationMode, @@ -81,14 +81,6 @@ impl ClientInfo { warnings, } } - - /// Returns a string representation of the client info for logging. - pub fn to_log_string(&self) -> String { - format!( - "client_ip={}, proxy={:?}, hops={}, trusted={}, mode={:?}", - self.real_ip, self.proxy_ip, self.proxy_hops, self.is_from_trusted_proxy, self.validation_mode - ) - } } /// Core validator that processes incoming requests to verify proxy chains. @@ -149,13 +141,28 @@ impl ProxyValidator { /// Internal logic for request validation. fn validate_request_internal(&self, peer_addr: Option, headers: &HeaderMap) -> Result { let Some(peer_addr) = peer_addr else { - debug!("SocketAddr extension is missing; skipping trusted proxy evaluation"); + debug!( + event = "proxy_validation.evaluate", + component = "trusted_proxies", + subsystem = "validator", + result = "direct", + reason = "missing_peer_addr", + "trusted proxy evaluation skipped" + ); return Ok(ClientInfo::direct(SocketAddr::new(IpAddr::from([0, 0, 0, 0]), 0))); }; let peer_ip = peer_addr.ip(); if peer_ip.is_unspecified() { - debug!("Peer address is unspecified; skipping trusted proxy evaluation"); + debug!( + event = "proxy_validation.evaluate", + component = "trusted_proxies", + subsystem = "validator", + result = "direct", + reason = "unspecified_peer_addr", + peer_ip = %peer_ip, + "trusted proxy evaluation skipped" + ); return Ok(ClientInfo::direct(peer_addr)); } @@ -165,7 +172,15 @@ impl ProxyValidator { // Check if the direct peer is a trusted proxy. if is_trusted_proxy { - debug!("Request received from trusted proxy: {}", peer_ip); + trace!( + event = "proxy_validation.peer", + component = "trusted_proxies", + subsystem = "validator", + result = "trusted_proxy", + peer_ip = %peer_ip, + validation_mode = self.config.validation_mode.as_str(), + "trusted proxy peer accepted" + ); // Parse and validate headers from the trusted proxy. self.validate_trusted_proxy_request(&peer_addr, headers) @@ -173,8 +188,25 @@ impl ProxyValidator { // Log a warning if the request is from a private network but not trusted. if self.config.is_private_network(&peer_ip) { warn!( - "Request from private network but not trusted: {}. This might indicate a configuration issue.", - peer_ip + event = "proxy_validation.peer", + component = "trusted_proxies", + subsystem = "validator", + result = "direct", + fallback = "socket_peer", + reason = "private_network_untrusted", + peer_ip = %peer_ip, + "trusted proxy validation downgraded to direct peer" + ); + } else { + trace!( + event = "proxy_validation.peer", + component = "trusted_proxies", + subsystem = "validator", + result = "direct", + fallback = "socket_peer", + reason = "peer_not_trusted", + peer_ip = %peer_ip, + "trusted proxy validation resolved direct peer" ); } @@ -194,7 +226,14 @@ impl ProxyValidator { } let Ok(handle) = tokio::runtime::Handle::try_current() else { - tracing::debug!("No Tokio runtime available; trusted proxy cache maintenance is disabled"); + tracing::debug!( + event = "proxy_validation.cache_maintenance", + component = "trusted_proxies", + subsystem = "validator", + state = "disabled", + reason = "missing_tokio_runtime", + "trusted proxy cache maintenance unavailable" + ); return; }; @@ -235,6 +274,20 @@ impl ProxyValidator { return Err(ProxyError::ChainNotContinuous); } + trace!( + event = "proxy_validation.chain", + component = "trusted_proxies", + subsystem = "validator", + result = "accepted", + proxy_ip = %proxy_ip, + client_ip = %chain_analysis.client_ip, + proxy_hops = chain_analysis.hops, + warning_count = chain_analysis.warnings.len(), + validation_mode = chain_analysis.validation_mode.as_str(), + trusted_proxy_count = chain_analysis.trusted_chain.len(), + "trusted proxy chain accepted" + ); + Ok(ClientInfo::from_trusted_proxy( chain_analysis.client_ip, client_info.forwarded_host, diff --git a/scripts/check_logging_guardrails.sh b/scripts/check_logging_guardrails.sh index 1261b3b34..8d2c82f01 100755 --- a/scripts/check_logging_guardrails.sh +++ b/scripts/check_logging_guardrails.sh @@ -18,6 +18,21 @@ checked_files=( "crates/ecstore/src/store/peer.rs" "crates/ecstore/src/store/init.rs" "crates/ecstore/src/tier/tier.rs" + "crates/concurrency/src/workers.rs" + "crates/concurrency/src/manager.rs" + "crates/concurrency/src/lock.rs" + "crates/concurrency/src/deadlock.rs" + "crates/trusted-proxies/src/global.rs" + "crates/trusted-proxies/src/config/loader.rs" + "crates/trusted-proxies/src/proxy/metrics.rs" + "crates/trusted-proxies/src/proxy/validator.rs" + "crates/trusted-proxies/src/proxy/chain.rs" + "crates/trusted-proxies/src/middleware/service.rs" + "crates/trusted-proxies/src/cloud/detector.rs" + "crates/trusted-proxies/src/cloud/ranges.rs" + "crates/trusted-proxies/src/cloud/metadata/aws.rs" + "crates/trusted-proxies/src/cloud/metadata/azure.rs" + "crates/trusted-proxies/src/cloud/metadata/gcp.rs" ) forbidden_patterns=( @@ -111,6 +126,95 @@ forbidden_patterns=( 'warn!("KMS initialization skipped: {e}")' 'warn!("Audit system: {e}")' 'warn!("notification system: {e}")' + 'info!("worker take, {}", *available)' + 'info!("worker give, {}", *available)' + 'info!("worker wait end")' + '"Concurrency manager started (timeout={}, lock={}, deadlock={}, backpressure={}, scheduler={})"' + 'info!("Concurrency manager stopped")' + 'info!("Deadlock detection started")' + 'info!("Deadlock detection stopped")' + '"Lock released early (optimization active)"' + '"Lock released on drop (normal release)"' + 'info!("Trusted Proxies module is disabled via configuration")' + 'info!("Trusted Proxies module initialized")' + 'info!("Configuration loaded successfully from environment variables")' + 'warn!("Failed to load configuration from environment: {}. Using defaults", e)' + 'info!("=== Application Configuration ===")' + 'info!("Server: {}", config.server_addr)' + 'info!("Trusted Proxies: {}", config.proxy.proxies.len())' + 'info!("Validation Mode: {:?}", config.proxy.validation_mode)' + 'info!("Cache Capacity: {}", config.cache.capacity)' + 'info!("Metrics Enabled: {}", config.monitoring.metrics_enabled)' + 'info!("Cloud Metadata: {}", config.cloud.metadata_enabled)' + 'info!("Failed validations will be logged")' + 'debug!("Trusted networks: {:?}", config.proxy.get_network_strings())' + 'info!("Metrics collection is disabled")' + 'info!("Proxy metrics enabled for application: {}", self.app_name)' + 'info!("Available metrics:")' + 'debug!("SocketAddr extension is missing; skipping trusted proxy evaluation")' + 'debug!("Peer address is unspecified; skipping trusted proxy evaluation")' + 'debug!("Request received from trusted proxy: {}", peer_ip)' + '"Request from private network but not trusted: {}. This might indicate a configuration issue."' + 'debug!("No Tokio runtime available; trusted proxy cache maintenance is disabled")' + 'trace!("Analyzing proxy chain: {:?} with current proxy: {}", proxy_chain, current_proxy_ip)' + 'debug!("Trusted proxy middleware is disabled")' + 'debug!("Proxy validation successful in {:?}", duration)' + 'debug!("Unrecoverable proxy validation error: {}", err)' + 'debug!("Cloud metadata fetching is disabled")' + 'info!("Detected AWS environment, fetching metadata")' + 'info!("Detected Azure environment, fetching metadata")' + 'info!("Detected GCP environment, fetching metadata")' + 'info!("Detected Cloudflare environment")' + 'info!("Detected DigitalOcean environment")' + 'warn!("Unknown cloud provider detected: {}", name)' + 'debug!("No cloud provider detected")' + 'debug!("Trying to fetch metadata from {}", provider_name)' + 'info!("Fetched {} IP ranges from {}", ranges.len(), provider_name)' + 'debug!("Failed to fetch metadata from {}: {}", provider_name, e)' + 'warn!("Failed to fetch network CIDRs from {}: {}", self.provider_name(), e)' + 'warn!("Failed to fetch public IP ranges from {}: {}", self.provider_name(), e)' + 'info!("Loaded {} static Cloudflare IP ranges", networks.len())' + 'debug!("Fetched {} IP ranges from {}", networks.len(), url)' + 'debug!("Failed to parse IP ranges from {}: {}", url, e)' + 'debug!("Failed to fetch IP ranges from {}: HTTP {}", url, response.status())' + 'debug!("Failed to fetch from {}: {}", url, e)' + 'info!("Successfully fetched {} Cloudflare IP ranges from API", all_ranges.len())' + 'info!("Loaded {} static DigitalOcean IP ranges", networks.len())' + 'info!("Successfully fetched {} Google Cloud IP ranges from API", networks.len())' + 'debug!("Failed to fetch Google IP ranges: HTTP {}", response.status())' + 'debug!("Failed to fetch Google IP ranges: {}", e)' + 'debug!("IMDSv2 token request failed with status: {}", response.status())' + 'debug!("IMDSv2 token request failed: {}", e)' + 'debug!("Using default AWS VPC network ranges")' + 'info!("Successfully fetched {} AWS public IP ranges", networks.len())' + 'debug!("Failed to fetch AWS IP ranges: HTTP {}", response.status())' + 'debug!("Failed to fetch AWS IP ranges: {}", e)' + 'debug!("Fetching Azure metadata from: {}", url)' + 'debug!("Azure metadata request failed with status: {}", response.status())' + 'debug!("Azure metadata request failed: {}", e)' + 'debug!("Fetching Azure IP ranges from: {}", url)' + 'info!("Successfully fetched {} Azure public IP ranges", networks.len())' + 'debug!("Failed to fetch Azure IP ranges: HTTP {}", response.status())' + 'debug!("Failed to fetch Azure IP ranges: {}", e)' + 'debug!("Using default Azure public IP ranges")' + 'info!("Successfully fetched {} network CIDRs from Azure metadata", cidrs.len())' + 'debug!("No network CIDRs found in Azure metadata, falling back to defaults")' + 'warn!("Failed to fetch Azure network metadata: {}", e)' + 'debug!("Using default Azure VNet network ranges")' + 'debug!("Fetching GCP metadata from: {}", url)' + 'debug!("GCP metadata request failed with status: {}", response.status())' + 'debug!("GCP metadata request failed: {}", e)' + 'warn!("No network interfaces found in GCP metadata")' + 'debug!("Failed to get IP/mask for GCP interface {}: {}", index, e)' + 'warn!("Could not determine network CIDRs from GCP metadata, falling back to defaults")' + 'info!("Successfully fetched {} network CIDRs from GCP metadata", cidrs.len())' + 'warn!("Failed to fetch GCP network metadata: {}", e)' + 'debug!("Fetching GCP IP ranges from: {}", url)' + 'info!("Successfully fetched {} GCP public IP ranges", networks.len())' + 'debug!("Failed to fetch GCP IP ranges: HTTP {}", response.status())' + 'debug!("Failed to fetch GCP IP ranges: {}", e)' + 'debug!("Using default GCP public IP ranges")' + 'debug!("Using default GCP VPC network ranges")' ) for pattern in "${forbidden_patterns[@]}"; do