From 96d24bc006699681248f76341c528272334faca9 Mon Sep 17 00:00:00 2001 From: Zhengchao An Date: Sat, 8 Aug 2026 07:05:57 +0800 Subject: [PATCH] docs(agents): make the structured-logging rule reachable and enforceable (#5828) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The RustFS event shape (`event`/`component`/`subsystem`/`result` + context, message last) is specified only in `.agents/skills/rustfs-logging-governance/SKILL.md`, and nothing routes a change to it: - `AGENTS.md`, which is what an agent actually loads by default, never mentions logging. Its only related line is "log unknown fields at `warn`" under Serde Safety, which is about level, not shape. - The skill's `description` says "use when editing or reviewing RustFS logs", so a bugfix that adds one log line in passing — how most new log sites enter this repo — never matches it. - `scripts/check_logging_guardrails.sh` is a blocklist: 500+ `rg -F` literals that retire log lines which already shipped. It cannot see a newly written one. For `crates/ecstore/src/disk/local.rs` the only check is that `#[tracing::instrument]` is TRACE-only; `warn!`/`info!` shape is unchecked. PR #5822 landed `warn!("heal rename_data: purging ... {:?} failed: {}", ...)` in `disk/local.rs` — sentence-style, no fields, directly beside `info!(event = EVENT_DISK_LOCAL_RENAME_REJECTED, component = ..., subsystem = ...)` — with every check green. That is the gap, not an authoring mistake. Close all three: - `AGENTS.md`: a Logging section stating the field shape, the level policy, the reuse-the-file's-constants rule, and that it applies to any `tracing` macro added in passing, not only to log-focused changes. - Skill `description`: trigger on adding or editing any `tracing` macro, naming the single-line-added-in-passing case explicitly. - Guardrail: assert the event shape positively on the already-governed disk files — `error!`/`warn!`/`info!` must open with fields or a `target:`, never a bare string. Commented-out macros are excluded; `debug!`/`trace!` stay out of scope as targeted diagnostics. Self-test fixtures cover both directions. `crates/ecstore/src/disk/mod.rs` carried the one live violation in that file set (`conv_part_err_to_int`), so it is converted here; the guardrail would otherwise fail on an untouched file. Verification: - `./scripts/check_logging_guardrails.sh` — passes - Negative control: re-inserting PR #5822's exact `warn!` line into `disk/local.rs` makes it exit 1 pointing at that line - `cargo fmt -p rustfs-ecstore -- --check`, `cargo check -p rustfs-ecstore` --- .../skills/rustfs-logging-governance/SKILL.md | 2 +- AGENTS.md | 22 ++++++++ crates/ecstore/src/disk/mod.rs | 12 ++++- scripts/check_logging_guardrails.sh | 54 +++++++++++++++++++ 4 files changed, 88 insertions(+), 2 deletions(-) diff --git a/.agents/skills/rustfs-logging-governance/SKILL.md b/.agents/skills/rustfs-logging-governance/SKILL.md index 62a4fc7f0..ec716fca6 100644 --- a/.agents/skills/rustfs-logging-governance/SKILL.md +++ b/.agents/skills/rustfs-logging-governance/SKILL.md @@ -1,6 +1,6 @@ --- 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`. +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 whenever a change adds or edits any `tracing` macro call (`error!`/`warn!`/`info!`/`debug!`/`trace!`/`#[instrument]`) — including a single log line added in passing while fixing unrelated logic, which is how most new log sites enter the repo — and when reviewing RustFS logs, startup/config diagnostics, cloud metadata logs, request validation logs, or `scripts/check_logging_guardrails.sh`. --- # RustFS Logging Governance diff --git a/AGENTS.md b/AGENTS.md index 8f3672e1f..146c5f9ee 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -322,6 +322,28 @@ High risk: all seven roles. - Use environment variables or vault tooling for sensitive configuration. - For localhost-sensitive tests, verify proxy settings to avoid traffic leakage. +## Logging + +Applies to **every** `tracing` macro you add or edit, including a single line +added in passing while fixing something else — not only to log-focused changes. + +- Fields first, message second: `event`, `component`, `subsystem`, + `result`/`state`, then key context. The message is a short label, not a + sentence with values interpolated into it. +- Reuse the existing `EVENT_*` / `LOG_COMPONENT_*` / `LOG_SUBSYSTEM_*` + constants of the module you are editing; match the shape of the log sites + already in that file rather than introducing a second style next to them. +- Level policy: `error` for behavior/security-affecting failures, `warn` for + degraded or fallback paths, `info` for low-frequency lifecycle, `debug` for + targeted diagnostics, `trace` for hot paths. Per-object and per-request + success paths are `trace`. +- Never log secrets, tokens, credential payloads, or merged config dumps. +- `scripts/check_logging_guardrails.sh` enforces a subset of this on the files + it lists; passing it is a floor, not evidence the log matches the house style. + +See `.agents/skills/rustfs-logging-governance/SKILL.md` for the full event +model, level policy, and guardrail-update checklist. + ## Tools ### xl.meta decode tool Quick Use diff --git a/crates/ecstore/src/disk/mod.rs b/crates/ecstore/src/disk/mod.rs index 233f2909f..d916522a7 100644 --- a/crates/ecstore/src/disk/mod.rs +++ b/crates/ecstore/src/disk/mod.rs @@ -42,6 +42,10 @@ pub const PART_TRANSACTION_NEW_META: &str = "new.meta"; pub const PART_TRANSACTION_OLD_META: &str = "old.meta"; pub const PART_TRANSACTION_ROLLBACK: &str = "rollback"; +const LOG_COMPONENT_ECSTORE: &str = "ecstore"; +const LOG_SUBSYSTEM_DISK: &str = "disk"; +const EVENT_DISK_PART_ERR_UNCLASSIFIED: &str = "disk_part_err_unclassified"; + pub fn part_transaction_path(part_path: &str) -> String { match part_path.rsplit_once('/') { Some((parent, name)) => format!("{parent}/.{name}.rustfs-txn"), @@ -1196,7 +1200,13 @@ pub fn conv_part_err_to_int(err: &Option) -> usize { Some(DiskError::DiskNotFound) => CHECK_PART_DISK_NOT_FOUND, None => CHECK_PART_SUCCESS, _ => { - tracing::warn!("conv_part_err_to_int: unknown error: {err:?}"); + tracing::warn!( + event = EVENT_DISK_PART_ERR_UNCLASSIFIED, + component = LOG_COMPONENT_ECSTORE, + subsystem = LOG_SUBSYSTEM_DISK, + error = ?err, + "Part error has no check-part code and degrades to unknown" + ); CHECK_PART_UNKNOWN } } diff --git a/scripts/check_logging_guardrails.sh b/scripts/check_logging_guardrails.sh index 42fc3e271..d1bb4da6e 100755 --- a/scripts/check_logging_guardrails.sh +++ b/scripts/check_logging_guardrails.sh @@ -842,6 +842,60 @@ for file in "${disk_logging_files[@]}"; do fi done +# `forbidden_patterns` above only retires log lines that already shipped, so a +# newly written sentence-style log passes every check in this script — which is +# how one reaches review in the first place (PR #5822 added +# `warn!("heal rename_data: purging ... {:?} failed: {}", ...)` to +# disk/local.rs with CI green). Assert the RustFS event shape positively on the +# file sets already governed here: error!/warn!/info! must open with fields +# (`event = ...`) or a `target:`, never with a bare message string. debug! and +# trace! stay out of scope — they are targeted diagnostics, not operator +# events. Extend this list as more files are converted; it is deliberately +# narrower than `checked_files`, which is only a blocklist surface. +structured_event_files=( + "crates/ecstore/src/disk/mod.rs" + "crates/ecstore/src/disk/local.rs" + "crates/ecstore/src/cluster/rpc/remote_disk.rs" +) + +# The leading class rejects `my_info!(` while still matching `tracing::warn!(`. +sentence_style_log_pattern='(?:^|[^A-Za-z0-9_])(?:error|warn|info)!\(\s*"' + +for file in "${structured_event_files[@]}"; do + # Commented-out macros are dead code, not emitted events. + sentence_style_logs="$(rg -n -U "$sentence_style_log_pattern" "$file" | rg -v '^[0-9]+:\s*//' || true)" + if [[ -n "$sentence_style_logs" ]]; then + echo "❌ logging guardrail violation: error!/warn!/info! must lead with structured fields (event/component/subsystem) in $file" >&2 + echo "$sentence_style_logs" >&2 + exit 1 + fi +done + +# Keep the matcher honest in both directions. +for fixture in \ + 'warn!("heal rename_data: purging stale destination data dir {:?} failed: {}", dst_data_path, err);' \ + $'warn!(\n "rename_data commit failed: {}",\n err\n);' \ + 'tracing::warn!("conv_part_err_to_int: unknown error: {err:?}");' \ + 'info!("disk scan finished");'; do + if ! printf '%s\n' "$fixture" | rg -U "$sentence_style_log_pattern" >/dev/null; then + echo "❌ logging guardrail self-test failed: sentence-style log was accepted" >&2 + echo "$fixture" >&2 + exit 1 + fi +done + +for fixture in \ + $'info!(\n event = EVENT_DISK_LOCAL_RENAME_REJECTED,\n component = LOG_COMPONENT_ECSTORE,\n reason = "rename_all_data_path_failed",\n "Disk local rename flow failed"\n);' \ + 'warn!(target: "rustfs::heal::manager", event = EVENT_HEAL_RETRY, "Heal retry admission decided");' \ + 'my_info!("not a tracing macro");' \ + 'debug!("list_dir raw {:?}", entries);'; do + if printf '%s\n' "$fixture" | rg -U "$sentence_style_log_pattern" >/dev/null; then + echo "❌ logging guardrail self-test failed: structured event was rejected" >&2 + echo "$fixture" >&2 + exit 1 + fi +done + if rg -n -U 'debug!\([\s\S]{0,600}"Remote disk RPC started"' crates/ecstore/src/cluster/rpc/remote_disk.rs >/dev/null; then echo "❌ logging guardrail violation: successful remote disk RPC events must not be emitted at DEBUG" >&2 exit 1