disc: structured timing + transition diagnostics for read errors

Adds the observability we need to debug wedge incidents from logs
alone — without needing to enable verbose TRACE-level SCSI tracing.
Goal stated by user: "when error occurs we can debug and code
correctly."

Pre-fix the WARN log on each read error showed only sense codes
and consecutive_failures. Missing: timing context (was the failed
read fast or slow?), gap to previous events (cumulative vs.
immediate failure?), and family transitions (did the drive just
flip into wedge mode, or has it been there?).

New fields on ReadCtx (no caller signature change):

  last_success_at: Option<Instant>
  last_error_at: Option<Instant>
  last_error_family: Option<SenseFamily>
  total_errors: u64
  total_reads_ok: u64
  zones_entered: u64
  jumps_taken: u64
  in_damage_zone: bool

New SenseFamily enum (NotReady / Medium / Hardware / IllegalRequest
/ Other) with is_wedge_family predicate.

handle_read_error WARN log now carries:
  consecutive_failures
  consecutive_outer_failures
  ms_since_last_error    NEW gap between this and previous error
  ms_since_last_success  NEW gap to last good read
  total_errors           NEW aggregate this pass
  total_reads_ok         NEW
  wedge_count
  sense_family           NEW typed category, easier to filter
  sense_key / asc / ascq (existing)

NEW WARN log "wedge_transition" fires once when the sense family
changes from non-wedge to wedge (Medium to Hardware/IllegalRequest).
That's the moment the drive's firmware flipped into fast-fail
mode. Single timestamped event in the log so post-mortems can
pinpoint the transition without scanning thousands of TRACE lines.

Worked example: if the next wedge incident shows

  read_error  ms_since_last_success=18234  ms_since_last_error=null
  read_error  ms_since_last_success=28000  ms_since_last_error=10000
  read_error  ms_since_last_success=43000  ms_since_last_error=68
                                          (drive returned <100ms = wedge symptom)
  wedge_transition  errors_in_zone=5  ms_since_last_success=43000

we can immediately tell cumulative damage, 5 errors over 43 s,
drive went into fast-fail mode at the 5th. If instead we see

  read_error  ms_since_last_success=200  ms_since_last_error=null  sense_family=Hardware
  wedge_transition  errors_in_zone=1

the wedge was triggered by ONE read at a physically-bricked LBA
(immediate fast-fail, no warm-up).

These two patterns demand different tuning responses (longer
pause vs. larger initial jump), and now we can distinguish them
from a single WARN log line each instead of needing TRACE
verbose for the whole rip.

Plus jumps_taken / zones_entered counters that feed an end-of-pass
INFO summary (PassSummary). Caller invokes pass_summary at sweep
end and logs structured stats: "Pass 1 saw N errors / M ok reads
/ K zones / J jumps". Single-line post-mortem for any rip.

No caller signature change (timing is internal to the handler;
end-of-pass summary is a new method callers opt into). Precommit
green; 433+ tests pass. Staged for the 0.18.10 release once we
have user-validation data on 0.18.9's avoidance tuning.
This commit is contained in:
MattJackson
2026-05-10 17:10:52 -07:00
parent 26e2d847d5
commit a832bad697
+170
View File
@@ -72,6 +72,73 @@ pub struct ReadCtx {
/// `WEDGE_ABORT_THRESHOLD` consecutive wedges with no good read
/// in between → real AbortPass.
pub wedge_count: u64,
// ── Diagnostic counters (added 2026-05-10) ──
//
// Aggregate state for post-mortem analysis of wedge incidents.
// Every Pass 1 / Pass N sweep now produces a structured summary
// at the WARN log on each error AND an end-of-pass INFO summary.
// Goal: when a wedge happens, the operator should be able to tell
// from the logs whether it was triggered by ONE read at a
// physically-damaged sector (immediate failure) or by accumulated
// exposure across MANY reads (firmware-state buildup), and what
// the timing pattern looked like.
/// `Instant` of the most recent successful read. Used to compute
/// "time since last good" for the WARN log on each error. None
/// before the first successful read.
pub last_success_at: Option<std::time::Instant>,
/// `Instant` of the most recent failed read. Used to compute
/// "time since last error" for the WARN log. None before the
/// first error.
pub last_error_at: Option<std::time::Instant>,
/// Last error's sense-key "family" (Medium / Hardware / IllegalRequest
/// / NotReady / Other). Used to detect WEDGE TRANSITIONS — when
/// the family changes from Medium → Hardware/IllegalRequest, the
/// drive almost certainly just entered fast-fail mode. That
/// transition gets its own WARN log so the trace is unambiguous.
pub last_error_family: Option<SenseFamily>,
/// Sum of all errors observed during this sweep. Reported in the
/// end-of-pass summary.
pub total_errors: u64,
/// Sum of all successful reads during this sweep.
pub total_reads_ok: u64,
/// Count of damage zones entered (transitions from clean → in-damage).
pub zones_entered: u64,
/// Count of damage-jumps executed during this sweep.
pub jumps_taken: u64,
/// True between "first error after a clean period" and "16 consecutive
/// good reads after the last error in the cluster." Used to count
/// zone entries and to bound zone_reads accurately.
pub in_damage_zone: bool,
}
/// Coarse classification of a SCSI sense key for diagnostic logging.
/// Wedge-family events (Hardware + IllegalRequest) get their own
/// transition log when the sense family changes.
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum SenseFamily {
NotReady,
Medium,
Hardware,
IllegalRequest,
Other,
}
impl SenseFamily {
pub fn from_sense_key(sense_key: u8) -> Self {
match sense_key {
scsi::SENSE_KEY_NOT_READY => SenseFamily::NotReady,
scsi::SENSE_KEY_MEDIUM_ERROR => SenseFamily::Medium,
scsi::SENSE_KEY_HARDWARE_ERROR => SenseFamily::Hardware,
scsi::SENSE_KEY_ILLEGAL_REQUEST => SenseFamily::IllegalRequest,
_ => SenseFamily::Other,
}
}
/// True for the "wedge family" — Hardware + IllegalRequest are
/// the senses the BU40N firmware returns in its fast-fail state.
pub fn is_wedge_family(self) -> bool {
matches!(self, SenseFamily::Hardware | SenseFamily::IllegalRequest)
}
}
impl ReadCtx {
@@ -98,6 +165,14 @@ impl ReadCtx {
bisecting: false,
bisect_on_marginal: false,
wedge_count: 0,
last_success_at: None,
last_error_at: None,
last_error_family: None,
total_errors: 0,
total_reads_ok: 0,
zones_entered: 0,
jumps_taken: 0,
in_damage_zone: false,
}
}
@@ -124,6 +199,14 @@ impl ReadCtx {
bisecting: false,
bisect_on_marginal: true,
wedge_count: 0,
last_success_at: None,
last_error_at: None,
last_error_family: None,
total_errors: 0,
total_reads_ok: 0,
zones_entered: 0,
jumps_taken: 0,
in_damage_zone: false,
}
}
@@ -146,7 +229,40 @@ impl ReadCtx {
if self.damage_window.len() > self.damage_window_max {
self.damage_window.remove(0);
}
// Diagnostic state.
self.total_reads_ok += 1;
self.last_success_at = Some(std::time::Instant::now());
// If we were in a damage zone and accumulated enough good
// reads to exit (damage_window now all-good), the zone is
// over. Don't reset zones_entered — that's a sweep total.
if self.in_damage_zone && self.consecutive_good >= self.damage_window_max as u64 {
self.in_damage_zone = false;
self.last_error_family = None;
}
}
/// Final per-pass summary suitable for an INFO log at the end of
/// `sweep` / `patch`. Caller renders this to a single structured
/// log line.
pub fn pass_summary(&self) -> PassSummary {
PassSummary {
total_reads_ok: self.total_reads_ok,
total_errors: self.total_errors,
zones_entered: self.zones_entered,
jumps_taken: self.jumps_taken,
}
}
}
/// End-of-pass stats logged at INFO for post-mortem analysis. Lets
/// an operator answer "how damaged is this disc?" from a single log
/// line per pass.
#[derive(Debug, Clone, Copy)]
pub struct PassSummary {
pub total_reads_ok: u64,
pub total_errors: u64,
pub zones_entered: u64,
pub jumps_taken: u64,
}
/// What the caller should do after a read failure. The caller owns the
@@ -261,12 +377,53 @@ pub fn handle_read_error(err: &Error, ctx: &mut ReadCtx) -> ReadAction {
ctx.consecutive_outer_failures += 1;
}
// Diagnostic instrumentation — compute timing context BEFORE
// mutating the timestamps so the log reflects the gap to the
// PREVIOUS error / success, not zero.
let now = std::time::Instant::now();
let ms_since_last_error = ctx
.last_error_at
.map(|t| now.duration_since(t).as_millis() as u64);
let ms_since_last_success = ctx
.last_success_at
.map(|t| now.duration_since(t).as_millis() as u64);
let current_family = err
.scsi_sense()
.map(|s| SenseFamily::from_sense_key(s.sense_key))
.unwrap_or(SenseFamily::Other);
// Zone-entry tracking: this is the first error after a clean run
// (or the first error of the sweep).
if !ctx.in_damage_zone && !ctx.bisecting {
ctx.in_damage_zone = true;
ctx.zones_entered += 1;
}
ctx.total_errors += 1;
ctx.last_error_at = Some(now);
// Wedge transition: previous error was MEDIUM, this one is
// HARDWARE or ILLEGAL_REQUEST. That's the moment the drive's
// firmware flipped into fast-fail mode. Distinct WARN so logs
// make it unambiguous when the wedge "started."
let is_wedge_transition = matches!(ctx.last_error_family, Some(prev) if !prev.is_wedge_family())
&& current_family.is_wedge_family();
ctx.last_error_family = Some(current_family);
tracing::warn!(
target: "freemkv::disc",
phase = "read_error",
consecutive_failures = ctx.consecutive_failures,
consecutive_outer_failures = ctx.consecutive_outer_failures,
ms_since_last_error,
ms_since_last_success,
total_errors = ctx.total_errors,
total_reads_ok = ctx.total_reads_ok,
batch = ctx.batch,
bisecting = ctx.bisecting,
wedge_count = ctx.wedge_count,
sense_family = ?current_family,
sense_key = err.scsi_sense().map(|s| s.sense_key),
asc = err.scsi_sense().map(|s| s.asc),
ascq = err.scsi_sense().map(|s| s.ascq),
@@ -274,6 +431,17 @@ pub fn handle_read_error(err: &Error, ctx: &mut ReadCtx) -> ReadAction {
"read failed; classifying"
);
if is_wedge_transition {
tracing::warn!(
target: "freemkv::disc",
phase = "wedge_transition",
errors_in_zone = ctx.total_errors,
ms_since_last_success,
new_family = ?current_family,
"drive entered wedge / fast-fail family (was returning recoverable medium errors before this)"
);
}
// 1. Transport failure: bridge crash / USB disconnect. The outer
// pass loop knows how to handle this (rediscover sg path,
// re-open drive). Inline single-sector retry here was tried in
@@ -353,6 +521,7 @@ pub fn handle_read_error(err: &Error, ctx: &mut ReadCtx) -> ReadAction {
pause_secs = WEDGE_PAUSE_SECS,
"Pass 1 wedge detected — jumping ahead and pausing for drive cooldown"
);
ctx.jumps_taken += 1;
return ReadAction::JumpAhead {
sectors: WEDGE_JUMP_SECTORS,
pause_secs: WEDGE_PAUSE_SECS,
@@ -474,6 +643,7 @@ pub fn handle_read_error(err: &Error, ctx: &mut ReadCtx) -> ReadAction {
// doesn't keep firing fast-jump every read after the initial
// jump fired. The window-based trigger handles further jumps.
ctx.consecutive_outer_failures = 0;
ctx.jumps_taken += 1;
return ReadAction::JumpAhead {
sectors,
pause_secs: pause_secs + POST_JUMP_EXTRA_PAUSE_SECS,