From 231b9d2cb13cec6886fa5a6e9353301b1bed5c6a Mon Sep 17 00:00:00 2001 From: Matthew Jackson Date: Sun, 10 May 2026 17:10:52 -0700 Subject: [PATCH] disc: structured timing + transition diagnostics for read errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 last_error_at: Option last_error_family: Option 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. --- src/disc/read_error.rs | 170 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 170 insertions(+) diff --git a/src/disc/read_error.rs b/src/disc/read_error.rs index ca5d8f7..179b387 100644 --- a/src/disc/read_error.rs +++ b/src/disc/read_error.rs @@ -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, + /// `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, + /// 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, + /// 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,