Commit Graph
6 Commits
Author SHA1 Message Date
matthew 231b9d2cb1 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.
2026-05-10 17:10:52 -07:00
matthew 445a15fa25 disc: wedge AVOIDANCE on Pass 1 — inter-error pause + larger jumps
Complements the wedge-skip backstop (d7f1862) with proactive
avoidance so we don't HIT the wedge in the first place. User's
take after seeing the Dune Pt 2 rip wedge at 48%: 'we shouldn't be
wedging.'

Empirical observations from the 23:09:12-23:09:55 wedge timeline:

  5 read errors over 43 s, ~8 s apart (drive's own ECC recovery
  takes 5-10 s per failure). Not 'hammering' in any usual sense,
  but cumulative firmware-state buildup over 5 in-cluster errors
  was enough to tip the BU40N into wedge mode at the 5th error.

  Damage cluster spanned ~140 MB (LBAs 19.898M-19.965M). Current
  damage-jump base of 256 sectors × batch=32 = 16 MB first jump,
  doubling to 32 MB, 64 MB... Each jump landed BACK INSIDE the
  140 MB cluster, exposing the drive to MORE in-cluster errors.

Two avoidance levers:

1. Inter-error pause on Pass 1 (PASS_1_FAIL_PAUSE_SECS = 5 s):
   pre-fix Pass 1 ran pause_secs=0 on all errors to 'zoom past'
   damage zones. Successful reads still zoom at zero pause — the
   pause applies only to FAILED reads, giving the drive's firmware
   cool-down between cluster exposures. Cost: ~5 s per scattered
   failure (~30-60 s total on a damage cluster); trivial vs.
   crashing the rip at 48%.

2. Larger damage-jump base (JUMP_BASE_SECTORS = 1024, up from
   256): first jump at batch=32 now covers 64 MB instead of 16 MB,
   second jump 128 MB instead of 32 MB. Two jumps clear 192 MB —
   well past most single-cluster damage patterns. Smaller jumps
   were landing inside the cluster and adding to the wedge counter.

Plus a halt-aware sleep helper (sleep_secs_or_halt) so the new
inter-error pause doesn't degrade halt response time. Halt poll
granularity 100 ms — halt fires within ~100 ms regardless of
remaining pause time. Updated three sleep call sites in disc/mod.rs
(SkipBlock pause, JumpAhead post-pause, Retry pause).

The wedge-SKIP backstop (d7f1862) stays — combined with this
avoidance work, the flow becomes:
  damage cluster encountered →
    pause 5 s, mark NonTrimmed →
    second failure →
    pause 5 s, mark NonTrimmed →
    ...
    threshold hit →
    damage-jump 64 MB (clears 95% of clusters) →
    if jump lands in another cluster: 128 MB next jump →
    only if drive STILL wedges after all this:
      wedge-skip kicks in (1 GB jump + 30 s cooldown × 16 budget)

Tests:
  pass_1_pauses_briefly_on_skip_for_wedge_avoidance — locks the
    new 5 s pause behavior in place (replaces the old pause=0 test).
  integration test threshold bumped from 5 s to 60 s with comment
    explaining the new bound is 'not infinite' rather than
    'milliseconds-fast'.
  All 433+ tests green on cargo +1.86 fmt + clippy + test.

Precommit green.
2026-05-10 16:55:02 -07:00
matthew d7f186283e disc: Pass 1 wedge-skip instead of abort-on-first-wedge
Pre-fix: when the drive returned HARDWARE_ERROR or ILLEGAL_REQUEST
during Pass 1 sweep, libfreemkv immediately returned ReadAction::
AbortPass. Autorip surfaced this as a fatal error and stopped the
rip at whatever progress percentage Pass 1 had reached — typically
40-50%. On a disc with one physical-damage cluster, the user would
see Pass 1 die at ~48% with the cryptic message 'E6000: <lba>
0x02/0x04/0x3e' and have no rip output to work with.

Root cause analysis: BU40N firmware transitions into a fast-fail
state when it hits cumulative read failures in a small LBA range —
returns HARDWARE_ERROR for every subsequent read near that LBA, even
sectors that aren't physically damaged. Per CLAUDE.md 'Bad-sector
handling' rule #2, 'Recovery requires eject+reload OR significant
cool-down.' Aborting on first wedge throws away the rest of the
disc; the right response is to SKIP the wedged region (mark as
NonTrimmed for Pass N), pause for drive cooldown, and continue.

Fix: in handle_read_error, the HARDWARE_ERROR / ILLEGAL_REQUEST arm
now branches on bisect_on_marginal:

  Pass 1 (bisect_on_marginal=false): JumpAhead with WEDGE_JUMP_SECTORS
    (1 GB at 2048 bytes/sector) and WEDGE_PAUSE_SECS (30 s cooldown).
    Tracks wedge_count in ReadCtx; resets on any successful read.
    Truly aborts only after WEDGE_ABORT_THRESHOLD (16) consecutive
    wedges with no good read in between — generous enough to clear
    most physical-damage clusters, bounded enough to not loop forever
    on a permanently bricked drive.

  Pass N (bisect_on_marginal=true): unchanged AbortPass. Pass N's
    job is single-sector recovery; if the drive won't talk near a
    specific LBA, skipping doesn't help. Pass N exits and lets the
    outer layer decide retry/eject/surface.

5 unit tests cover the new policy:
  pass_1_hardware_error_jumps_ahead_not_aborts — JumpAhead emitted
    with correct sectors+pause, wedge_count incremented.
  pass_1_hardware_error_aborts_after_threshold — AbortPass kicks in
    on the WEDGE_ABORT_THRESHOLD-th consecutive wedge.
  pass_1_good_read_resets_wedge_count — on_success clears
    wedge_count; subsequent wedge gets fresh skip budget.
  pass_n_hardware_error_still_aborts — Pass N's AbortPass behavior
    intact.
  pass_1_illegal_request_also_routes_to_wedge_skip — both wedge
    sense families get the skip treatment.

Impact: on the Dune Pt 2 disc that consistently wedged at 48%
(physical damage at LBA ~19.9M), Pass 1 will now jump ahead 1 GB
on the wedge, give the drive 30 s cooldown, and continue scanning
the rest of the disc. The damaged region becomes Pass N's job to
revisit. Worst case if the drive stays wedged: 16 GB of NonTrimmed
disc area before honest AbortPass.

Precommit (cargo +1.86 fmt + clippy + test) green; 430 passing.
2026-05-10 16:37:59 -07:00
matthew f755ca9ea4 v0.18.7: Pass 1 fast-skip, defer recovery to Pass N
Pass 1 sweep was grinding through damage zones because the marginal-
media handler returned `Bisect` for every failed 32-sector batch —
forcing 32 single-sector reads per bad block at ~5s each on a real
BU40N-vs-Dune-Pt-2 trace. AND the JumpAhead trigger required a 16-
block damage window to fill before firing, so entry into a
contiguous damage zone took ~40 minutes of grinding before the
first jump fired. Architecturally wrong: Pass 1's job is "fast and
accurate, get the most data in the shortest time." Bisection +
recovery is Pass N's purpose-built role.

ReadCtx now carries two new fields:
  - `consecutive_outer_failures: u64` — outer-batch failures since
    last outer success. Bisect inner failures don't count.
  - `bisect_on_marginal: bool` — whether to return Bisect on a
    marginal-media batch failure.
  - `fast_jump_threshold: u64` — outer-failures count that triggers
    JumpAhead before the damage window has filled.

`for_sweep` (Pass 1) sets `bisect_on_marginal=false`,
`fast_jump_threshold=4`, and zeroes the post-failure pause. Failed
batches become SkipBlock → whole block NonTrimmed → advance, no
sleep. After 4 consecutive outer failures: JumpAhead with the
existing escalating multiplier.

`for_patch` (Pass N) sets `bisect_on_marginal=true`,
`fast_jump_threshold=u64::MAX`, keeps the original cooldown pauses.
Pass N's whole reason to exist is to grind on bad ranges with
proper recovery semantics — single-sector reads, 60s recovery
timeout, retry budget, escalating skip — and that's unchanged.

`on_success` resets `consecutive_outer_failures` only when not
bisecting, so a good single-sector read inside Pass N's bisect
doesn't pretend we've escaped the damaged batch.

Tests:
  - `pass_n_marginal_with_batch_gt_1_bisects` — Pass N still bisects.
  - `pass_1_marginal_skips_instead_of_bisecting` — Pass 1 doesn't.
  - `pass_1_jumps_after_4_consecutive_outer_failures` — fast-entry.
  - `pass_n_does_not_fast_jump` — fast-entry is Pass-1-only.
  - `outer_success_resets_consecutive_outer_failures` — counter reset.
  - `bisect_inner_success_does_not_reset_outer_counter` — semantics.
  - `pass_1_does_not_pause_on_skip` — explicit zero-pause contract.
  - `long_failure_streak_extends_pause_on_pass_n` — Pass N still
    extends pauses on long failure streaks (renamed from the old
    sweep-based test).

Integration test `test_disc_copy_marks_failed_ecc_blocks_as_nontrimmed`
updated: it used to assert Pass 1 recovers all sectors via bisect
(bytes_good=total). New contract: Pass 1 marks NonTrimmed; Pass N
recovers. Test now asserts Pass-1-only outcome (bytes_pending=total,
complete=false) consistent with the redesign.

Real-world impact on the user's BU40N + Dune Pt 2 trace from this
session: a damage zone that was on track to take ~40 minutes of
Pass-1 grinding will now jump in ~20 seconds. Pass N still has the
full 7-pass recovery budget to revisit those NonTrimmed ranges.
2026-05-10 12:50:12 -07:00
matthew 0cd7314831 0.18 round 1+2 integration fixes
Two clippy issues surfaced when round 1 polish + round 2 FrameSink
migrations both landed on libfreemkv main:

- src/halt.rs: clippy::new_without_default fires when a public new()
  exists without Default. The polish pass dropped the derive thinking
  it was redundant — clippy disagrees, so add a manual impl that
  forwards to new(). Doc-comment notes why both exist.

- src/disc/read_error.rs:372: pre-existing
  assert_eq!(.., true) trips clippy::bool_assert_comparison. Pre-0.18
  precommits passed because that lint sat outside the gate; the
  round-2 commits brought enough new clippy surface that it now
  shows up. Trivial cleanup: assert!(...) instead of assert_eq!.

Single contributor: MattJackson.
2026-05-09 10:00:06 -07:00
matthew 8c8c4724f3 unified read-error handler + pass N size-aware skip
New disc/read_error.rs as the single entry point all read failures flow
through. Handler classifies the error, updates the in-flight context
(damage window, retry budgets, jump multiplier), and returns a
ReadAction the caller dispatches on. Pass 1 (sweep) refactored to use
it; ~340 lines of nested if/else collapsed into ~120 lines of action
dispatch. Adding a new error class = one match arm. Logging is in one
place. Bisect inner failures don't poison the damage window. Jump
multiplier capped at 64 (max 1 GB jump for batch=32 — observed prior
unbounded behavior produce a single 56 GB jump on a wedged drive).

Pass N (patch) damage_skip is now size-aware: each skip is capped at
range_remaining/4 rather than the absolute MB-scale escalation. The
old logic could leap over a 100-sector bad range that hides a 50-sector
good middle; size-aware convergence finds the good middles instead.

Tests in tests/pass_n_size_aware_skip.rs exercise the size-aware skip
against synthetic patterns (25-bad/50-good/25-bad and three good
middles in a row) and prove ≥98% of good middles are recovered.
Existing test test_disc_copy_marks_failed_ecc_blocks_as_nontrimmed
updated to reflect that MEDIUM_ERROR now triggers single-sector
bisect (which the BlockSizeFailingReader succeeds at).
2026-05-07 09:08:43 -07:00