mirror of
https://github.com/rustfs/rustfs.git
synced 2026-08-08 22:33:22 +00:00
docs(agents): make the structured-logging rule reachable and enforceable (#5828)
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`
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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<Error>) -> 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
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user