fix(heal): demote per-object heal logs and cap erasure-set failure warns (#5727)

fix(heal): demote per-object logs and cap erasure-set failure warns

Follow-up to rustfs/rustfs#5716. Per-object heal task kinds (Object/Metadata/MRF/ECDecode) queued by MRF/autoheal/scanner loops emitted info!/warn!/error! lines per object: task lifecycle (started/completed/timed_out/failed), the missing-object warn, queue admission full/drop/displacement warns, retry-admission decisions, and uncapped per-object warns in erasure-set sweeps.

Add a shared demote_to_debug_when! macro that keeps aggregate task kinds and admin/internal requests at operator-visible levels while demoting per-object occurrences to debug!, sample-cap the erasure-set transient_skip/failed warns per bucket via take_failure_log_sample (reusing the heal_bucket_objects precedent), demote the per-retry admission decision logs to debug! (covered by rustfs_heal_admission_total and the scheduler task_retrying/task_failed events), and record the previously unmetered duplicate-admission outcome.

Extend scripts/check_logging_guardrails.sh with injection-verified regression guards and run it in both quick-checks jobs (ci.yml and its ci-docs-only.yml mirror).
This commit is contained in:
Zhengchao An
2026-08-05 10:43:57 +08:00
committed by GitHub
parent 204068e07e
commit d2e5346044
6 changed files with 207 additions and 48 deletions
+3
View File
@@ -102,6 +102,9 @@ jobs:
- name: Check architecture migration rules
run: ./scripts/check_architecture_migration_rules.sh
- name: Check logging guardrails
run: ./scripts/check_logging_guardrails.sh
- name: Check tokio io-uring feature guard
run: ./scripts/check_no_tokio_io_uring.sh
+3
View File
@@ -137,6 +137,9 @@ jobs:
- name: Check architecture migration rules
run: ./scripts/check_architecture_migration_rules.sh
- name: Check logging guardrails
run: ./scripts/check_logging_guardrails.sh
- name: Check tokio io-uring feature guard
run: ./scripts/check_no_tokio_io_uring.sh
+11 -7
View File
@@ -16,7 +16,7 @@ use crate::heal::{
progress::HealProgress,
resume::{CheckpointManager, ResumeManager, ResumeUtils, compose_key},
storage::{HealStorageAPI, next_heal_listing_token},
task::is_missing_object_dir_heal_result,
task::{demote_to_debug_when, is_missing_object_dir_heal_result, take_failure_log_sample},
};
use crate::{Error, Result};
use futures::{StreamExt, stream::FuturesUnordered};
@@ -612,6 +612,12 @@ impl ErasureSetHealer {
let page_concurrency_limit =
Self::effective_heal_page_object_concurrency_for_source(self.source, self.heal_opts.scan_mode);
let in_flight = Arc::new(AtomicUsize::new(0));
// Per-bucket sample caps for per-object warn! lines: a flapping rebuild
// disk can fail/skip hundreds of thousands of versions in one sweep, so
// only the first few occurrences warn and the rest demote to debug!.
// The end-of-pass summary reports the full failed/skipped counts.
let mut transient_skip_samples_logged = 0_u64;
let mut failure_samples_logged = 0_u64;
// backlog#920: select the per-erasure-set DISK-WALK union enumerator when
// the scan is Deep OR the request came from AutoHeal — these are the paths
@@ -748,8 +754,7 @@ impl ErasureSetHealer {
Err(Error::TransientSkip { message }) => {
*skipped_objects += 1;
checkpoint_manager.add_skipped_object(key).await?;
warn!(
target: "rustfs::heal::erasure_healer",
demote_to_debug_when!(!take_failure_log_sample(&mut transient_skip_samples_logged), warn, target: "rustfs::heal::erasure_healer", {
event = EVENT_HEAL_ERASURE_OBJECT_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_ERASURE_HEALER,
@@ -760,13 +765,12 @@ impl ErasureSetHealer {
state = "transient_skip",
error = %message,
"Erasure set object heal skipped due to transient error"
);
});
}
Err(err) => {
*failed_objects += 1;
checkpoint_manager.add_failed_object(key).await?;
warn!(
target: "rustfs::heal::erasure_healer",
demote_to_debug_when!(!take_failure_log_sample(&mut failure_samples_logged), warn, target: "rustfs::heal::erasure_healer", {
event = EVENT_HEAL_ERASURE_OBJECT_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_ERASURE_HEALER,
@@ -777,7 +781,7 @@ impl ErasureSetHealer {
state = "failed",
error = %err,
"Erasure set object heal failed"
);
});
}
}
+31 -24
View File
@@ -15,7 +15,7 @@
use crate::heal::{
progress::{HealProgress, HealStatistics},
storage::HealStorageAPI,
task::{HealOptions, HealPriority, HealRequest, HealTask, HealTaskStatus, HealType},
task::{HealOptions, HealPriority, HealRequest, HealTask, HealTaskStatus, HealType, demote_to_debug_when},
};
use crate::{Error, Result};
use metrics::{counter, gauge};
@@ -54,6 +54,13 @@ const EVENT_HEAL_UNCLEAN_SHUTDOWN: &str = "heal_unclean_shutdown";
const MAX_RECOVERABLE_HEAL_RETRIES: u32 = 3;
const MAX_RECOVERABLE_HEAL_RETRY_DELAY: Duration = Duration::from_secs(30);
// Admission/scheduler outcomes for per-object requests (Object/Metadata/MRF/
// ECDecode) log via demote_to_debug_when! — MRF, autoheal, and scanner
// recovery loops submit those per object, so a full queue or a retry storm
// would otherwise emit one warn! per object (rustfs/rustfs#5716). The
// `rustfs_heal_admission_total` metric and the `heal_queue_state` backlog
// event keep the aggregate signal at operator-visible levels.
#[cfg(test)]
struct RetryOwnershipTestHook {
task_id: String,
@@ -976,6 +983,7 @@ impl HealManager {
let queue_len = queue.len();
publish_heal_queue_length(queue);
let queue_capacity = config.queue_size;
let per_object_request = request.heal_type.is_per_object();
if queue_len >= queue_capacity && !request.force_start {
if Self::can_displace_queued_work(&request) && queue.can_displace_lower_priority(request.priority) {
@@ -985,8 +993,7 @@ impl HealManager {
if let Some(displaced) = queue.push_displacing_lower_priority(request) {
publish_heal_queue_length(queue);
Self::record_admission_metric(source, HealAdmissionResult::Accepted, context);
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(per_object_request, warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -1000,12 +1007,11 @@ impl HealManager {
queue_capacity,
result = "accepted_by_displacement",
"Heal queue request accepted by displacement"
);
});
return HealAdmissionResult::Accepted;
}
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(per_object_request, warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -1017,7 +1023,7 @@ impl HealManager {
queue_capacity,
result = "full_no_displacement_candidate",
"Heal queue request rejected without displacement"
);
});
Self::record_admission_metric(source, HealAdmissionResult::Full, context);
return HealAdmissionResult::Full;
}
@@ -1026,8 +1032,7 @@ impl HealManager {
Self::record_admission_metric(request.source, admission, context);
match admission {
HealAdmissionResult::Dropped(reason) => {
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(per_object_request, warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -1040,11 +1045,10 @@ impl HealManager {
reason = reason.as_str(),
result = "dropped_full",
"Heal queue request dropped"
);
});
}
HealAdmissionResult::Full => {
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(per_object_request, warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -1056,7 +1060,7 @@ impl HealManager {
queue_capacity,
result = "rejected_full",
"Heal queue request rejected"
);
});
}
HealAdmissionResult::Accepted | HealAdmissionResult::Merged => {}
}
@@ -1481,6 +1485,7 @@ impl HealManager {
drop(retrying_heals);
drop(queue);
drop(active_heals);
Self::record_admission_metric(request.source, admission, "duplicate");
match admission {
HealAdmissionResult::Merged => {
@@ -1501,8 +1506,7 @@ impl HealManager {
);
}
HealAdmissionResult::Dropped(reason) => {
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(request.heal_type.is_per_object(), warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -1512,7 +1516,7 @@ impl HealManager {
duplicate_state,
result = "dropped_duplicate",
"Heal queue admission decided"
);
});
}
HealAdmissionResult::Accepted | HealAdmissionResult::Full => {}
}
@@ -2554,8 +2558,7 @@ impl HealManager {
Err(e) => {
let will_retry = retry_request.is_some();
if will_retry {
warn!(
target: "rustfs::heal::manager",
demote_to_debug_when!(task.heal_type.is_per_object(), warn, target: "rustfs::heal::manager", {
event = EVENT_HEAL_SCHEDULER_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_MANAGER,
@@ -2566,7 +2569,7 @@ impl HealManager {
retry_attempt = task.retry_attempts.saturating_add(1),
error = %e,
"Heal scheduler task retrying"
);
});
} else {
error!(
target: "rustfs::heal::manager",
@@ -2669,7 +2672,7 @@ impl HealManager {
loop {
tokio::select! {
_ = retry_cancel_token.cancelled() => {
info!(
debug!(
target: "rustfs::heal::manager",
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
@@ -2702,7 +2705,7 @@ impl HealManager {
};
if active_duplicate {
retrying_heals_for_spawn.lock().await.remove(&retry_request_id);
info!(
debug!(
target: "rustfs::heal::manager",
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
@@ -2730,7 +2733,7 @@ impl HealManager {
retrying_heals_for_spawn.lock().await.remove(&retry_request_id);
drop(queue);
retry_completed_heals.lock().await.remove(&retry_request_id);
info!(
debug!(
target: "rustfs::heal::manager",
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
@@ -2751,7 +2754,7 @@ impl HealManager {
HealAdmissionResult::Merged => {
retrying_heals_for_spawn.lock().await.remove(&retry_request_id);
drop(queue);
info!(
debug!(
target: "rustfs::heal::manager",
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
@@ -2765,7 +2768,11 @@ impl HealManager {
return;
}
HealAdmissionResult::Full => {
warn!(
// admit_request_to_queue already logged the
// rejection (context = "retry"); this repeats
// every backoff cycle while the queue stays
// full, so keep it at debug!.
debug!(
target: "rustfs::heal::manager",
event = EVENT_HEAL_QUEUE_ADMISSION,
component = LOG_COMPONENT_HEAL,
+125 -17
View File
@@ -47,6 +47,25 @@ const MAX_RETAINED_HEAL_RESULT_ITEMS: usize = 1024;
const EVENT_HEAL_OBJECT_RESULT: &str = "heal_object_result";
const MAX_BUCKET_OBJECT_HEAL_RETRIES: u32 = 3;
const MAX_BUCKET_FAILURE_LOG_SAMPLES: u64 = 5;
/// Emits at `$level`, demoted to `debug!` when `$demote` is true. Keeps
/// per-object heal work — Object/Metadata/MRF/ECDecode tasks queued per
/// object by MRF/autoheal/scanner loops, and per-object sweep failures past
/// a sample cap — from amplifying into one info!/warn!/error! line per
/// object during mass recovery (rustfs/rustfs#5716). Aggregate task kinds
/// and foreground (admin/internal) requests keep operator-visible levels;
/// metrics and end-of-sweep summaries carry the aggregate signal for the
/// demoted paths.
macro_rules! demote_to_debug_when {
($demote:expr, $level:ident, target: $target:expr, { $($fields:tt)* }) => {
if $demote {
tracing::debug!(target: $target, $($fields)*);
} else {
tracing::$level!(target: $target, $($fields)*);
}
};
}
pub(crate) use demote_to_debug_when;
const EVENT_HEAL_BUCKET_STAGE: &str = "heal_bucket_stage";
const EVENT_HEAL_BUCKET_RESULT: &str = "heal_bucket_result";
const EVENT_HEAL_METADATA_STAGE: &str = "heal_metadata_stage";
@@ -100,6 +119,18 @@ impl HealType {
Self::ECDecode { .. } => "ec_decode",
}
}
/// Task kinds enqueued at per-object granularity (MRF, autoheal, scanner,
/// read-repair loops). Their lifecycle and admission logs stay at `debug!`
/// so a recovery loop queuing hundreds of thousands of object heal tasks
/// cannot amplify into per-object `info!`/`warn!` lines; aggregate kinds
/// (cluster/bucket/prefix/erasure-set) keep operator-visible levels.
pub(crate) fn is_per_object(&self) -> bool {
matches!(
self,
Self::Object { .. } | Self::Metadata { .. } | Self::MRF { .. } | Self::ECDecode { .. }
)
}
}
fn is_object_level_not_found_error(err: &Error) -> bool {
@@ -115,6 +146,20 @@ pub(crate) fn is_missing_object_dir_heal_result(object: &str, err: &Error) -> bo
object.ends_with(SLASH_SEPARATOR) && is_object_level_not_found_error(err)
}
/// Sample cap for per-object failure logs during a sweep: returns true (and
/// consumes a sample slot) for the first [`MAX_BUCKET_FAILURE_LOG_SAMPLES`]
/// calls, false afterwards so callers demote the remaining occurrences to
/// `debug!`. Aggregate failed/skipped counts still surface in end-of-sweep
/// summaries.
pub(crate) fn take_failure_log_sample(samples_logged: &mut u64) -> bool {
if *samples_logged < MAX_BUCKET_FAILURE_LOG_SAMPLES {
*samples_logged = samples_logged.saturating_add(1);
true
} else {
false
}
}
/// Heal priority
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)]
pub enum HealPriority {
@@ -618,8 +663,7 @@ impl HealTask {
)
.increment(1);
info!(
target: "rustfs::heal::task",
demote_to_debug_when!(self.heal_type.is_per_object(), info, target: "rustfs::heal::task", {
event = EVENT_HEAL_TASK_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_TASK,
@@ -628,7 +672,7 @@ impl HealTask {
state = "started",
queue_delay = ?queue_delay,
"Heal task started"
);
});
let result = match &self.heal_type {
HealType::Cluster => self.heal_cluster().await,
@@ -660,8 +704,7 @@ impl HealTask {
Ok(_) => {
let mut status = self.status.write().await;
*status = HealTaskStatus::Completed;
info!(
target: "rustfs::heal::task",
demote_to_debug_when!(self.heal_type.is_per_object(), info, target: "rustfs::heal::task", {
event = EVENT_HEAL_TASK_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_TASK,
@@ -669,7 +712,7 @@ impl HealTask {
heal_type = self.heal_type.log_kind(),
state = "completed",
"Heal task completed"
);
});
}
Err(Error::TaskCancelled) => {
let mut status = self.status.write().await;
@@ -688,8 +731,7 @@ impl HealTask {
Err(Error::TaskTimeout) => {
let mut status = self.status.write().await;
*status = HealTaskStatus::Timeout;
warn!(
target: "rustfs::heal::task",
demote_to_debug_when!(self.heal_type.is_per_object(), warn, target: "rustfs::heal::task", {
event = EVENT_HEAL_TASK_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_TASK,
@@ -697,13 +739,16 @@ impl HealTask {
heal_type = self.heal_type.log_kind(),
state = "timed_out",
"Heal task timed out"
);
});
}
Err(e) => {
let mut status = self.status.write().await;
*status = HealTaskStatus::Failed { error: e.to_string() };
error!(
target: "rustfs::heal::task",
// Per-object failures are already logged with full object
// context by the heal_* implementations and terminally by the
// scheduler's task_failed error!; this generic duplicate would
// multiply every failed object by the retry count.
demote_to_debug_when!(self.heal_type.is_per_object(), error, target: "rustfs::heal::task", {
event = EVENT_HEAL_TASK_STATE,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_TASK,
@@ -712,7 +757,7 @@ impl HealTask {
state = "failed",
error = %e,
"Heal task failed"
);
});
}
}
@@ -830,17 +875,21 @@ impl HealTask {
};
if !object_exists {
warn!(
target: "rustfs::heal::task",
// Background loops (scanner/MRF/autoheal/read-repair) routinely
// race object deletion, so a missing target is per-object noise
// for them; only foreground admin/internal requests keep the warn.
let background_source = !matches!(self.source, HealRequestSource::Admin | HealRequestSource::Internal);
demote_to_debug_when!(background_source, warn, target: "rustfs::heal::task", {
event = EVENT_HEAL_OBJECT_MISSING,
component = LOG_COMPONENT_HEAL,
subsystem = LOG_SUBSYSTEM_OBJECT,
task_id = %self.id,
bucket,
object,
source = self.source.as_str(),
recreate_missing = self.options.recreate_missing,
"Heal target object is missing"
);
});
if self.options.recreate_missing {
debug!(
target: "rustfs::heal::task",
@@ -1536,8 +1585,7 @@ impl HealTask {
}
first_failed_object.get_or_insert_with(|| object.to_string());
first_error.get_or_insert_with(|| err.to_string());
if failure_samples_logged < MAX_BUCKET_FAILURE_LOG_SAMPLES {
failure_samples_logged = failure_samples_logged.saturating_add(1);
if take_failure_log_sample(&mut failure_samples_logged) {
warn!(
target: "rustfs::heal::task",
event = EVENT_HEAL_BUCKET_RESULT,
@@ -2396,6 +2444,66 @@ mod tests {
resume_disk: Mutex<Option<DiskStore>>,
}
#[test]
fn per_object_heal_types_are_classified_for_log_demotion() {
assert!(
HealType::Object {
bucket: "b".to_string(),
object: "o".to_string(),
version_id: None,
}
.is_per_object()
);
assert!(
HealType::Metadata {
bucket: "b".to_string(),
object: "o".to_string(),
}
.is_per_object()
);
assert!(
HealType::MRF {
meta_path: "p".to_string(),
}
.is_per_object()
);
assert!(
HealType::ECDecode {
bucket: "b".to_string(),
object: "o".to_string(),
version_id: None,
}
.is_per_object()
);
assert!(!HealType::Cluster.is_per_object());
assert!(!HealType::Bucket { bucket: "b".to_string() }.is_per_object());
assert!(
!HealType::Prefix {
bucket: "b".to_string(),
prefix: "p".to_string(),
}
.is_per_object()
);
assert!(
!HealType::ErasureSet {
buckets: Vec::new(),
set_disk_id: "s".to_string(),
}
.is_per_object()
);
}
#[test]
fn failure_log_sampling_caps_at_max_samples() {
let mut samples_logged = 0_u64;
for _ in 0..MAX_BUCKET_FAILURE_LOG_SAMPLES {
assert!(take_failure_log_sample(&mut samples_logged));
}
assert!(!take_failure_log_sample(&mut samples_logged));
assert!(!take_failure_log_sample(&mut samples_logged));
assert_eq!(samples_logged, MAX_BUCKET_FAILURE_LOG_SAMPLES);
}
/// Build a latest, non-delete-marker heal list item with no version id.
fn heal_item(name: &str) -> HealListItem {
HealListItem {
+34
View File
@@ -848,4 +848,38 @@ if [[ "$stdout_sink_calls" != "2" ]]; then
exit 1
fi
# Heal log amplification guards (rustfs/rustfs#5716 follow-up): per-object heal
# work (Object/Metadata/MRF/ECDecode tasks queued by MRF/autoheal/scanner loops)
# must not emit info!/warn!/error! lines per object during mass recovery.
# The 1000-char window covers the measured 541-710 chars of structured fields
# between the macro open and the message at every retry-admission site.
if rg -n -U '(info|warn)!\(\s*target: "rustfs::heal::manager",[\s\S]{0,1000}"Heal retry admission decided"' crates/heal/src/heal/manager.rs >/dev/null; then
echo "❌ logging guardrail violation: heal retry admission decisions repeat per retrying task (per-object under MRF retry storms) and must stay at DEBUG" >&2
exit 1
fi
demoted_task_sites="$(rg -c -F 'demote_to_debug_when!(self.heal_type.is_per_object()' crates/heal/src/heal/task.rs || echo 0)"
if [[ "$demoted_task_sites" -lt 4 ]]; then
echo "❌ logging guardrail violation: per-object heal task lifecycle/failure logs must stay demoted to DEBUG via demote_to_debug_when! (expected >= 4 sites in crates/heal/src/heal/task.rs, found $demoted_task_sites)" >&2
exit 1
fi
demoted_task_total_sites="$(rg -c -F 'demote_to_debug_when!(' crates/heal/src/heal/task.rs || echo 0)"
if [[ "$demoted_task_total_sites" -lt 5 ]]; then
echo "❌ logging guardrail violation: the background-source missing-object warn in crates/heal/src/heal/task.rs must stay level-split via demote_to_debug_when! (expected >= 5 total sites, found $demoted_task_total_sites)" >&2
exit 1
fi
erasure_sampled_sites="$(rg -c -F 'take_failure_log_sample(' crates/heal/src/heal/erasure_healer.rs || echo 0)"
if [[ "$erasure_sampled_sites" -lt 2 ]]; then
echo "❌ logging guardrail violation: erasure-set per-object failure/skip warns must stay sample-capped via take_failure_log_sample (expected >= 2 sites in crates/heal/src/heal/erasure_healer.rs, found $erasure_sampled_sites)" >&2
exit 1
fi
demoted_admission_sites="$(rg -c -F 'demote_to_debug_when!(' crates/heal/src/heal/manager.rs || echo 0)"
if [[ "$demoted_admission_sites" -lt 6 ]]; then
echo "❌ logging guardrail violation: heal queue admission/scheduler warns for per-object requests must stay level-split via demote_to_debug_when! (expected >= 6 sites in crates/heal/src/heal/manager.rs, found $demoted_admission_sites)" >&2
exit 1
fi
echo "✅ Logging guardrails check passed"