v0.13.13 — telemetry: tracing instrumentation in SgIoTransport + Disc::copy

v0.13.12 shipped the async fd_recovery design but a live test on Dune 2
showed Pass 1 sat for 14 minutes with bytes_good=0 — the inner loop iterates
(throttled on_progress log fires every 78s) but each iteration evidently
takes ~60s instead of the microseconds the design promises on fast-fail.
Without trace-level telemetry at the SCSI + Disc::copy boundaries we
can't tell where the time goes.

This release is instrumentation only — no behavior change.

- New dep: tracing 0.1. Per project docs, debug/trace logging is allowed in
  libfreemkv (the no-English rule applies to errors). Consumers wire a
  tracing subscriber.
- SgIoTransport::execute (Linux): trace at every state transition (entry,
  recovery_swap_ok, recovery_pending, write_ok / write_err, poll_done,
  timeout_spawn_recovery, scsi_err, read_err, ok). Each event includes
  opcode + elapsed timing. The bg recovery thread also traces close_ms +
  open_ms so we can see if the kernel really takes 60s to close+open on a
  wedged Initio bridge.
- Disc::copy: trace at copy_start, outer_loop, region_enter, every 100
  inner-loop iterations (iter_progress with pos/region_end/skip_size/
  bytes_good/read_ok_count/read_err_count/last_read_ms/copy_elapsed_ms),
  copy_done.
- All trace events use targets `freemkv::scsi` and `freemkv::disc` so
  consumers can filter by subsystem (e.g. autorip /api/debug?q=freemkv::scsi).

Next: run the live test on Dune 2 again, read the autorip JSONL log,
diagnose why each iter is slow, fix the actual bug.

CHANGELOG.md

@@ -1,5 +1,45 @@
 # Changelog
 
+## 0.13.13 (2026-04-25)
+
+### Telemetry: instrument the rip pipeline for in-flight diagnosis
+
+v0.13.12 shipped Fix 1+2+4 + cross-platform parity but a live test on Dune 2
+showed Pass 1 sat for 14 minutes with `bytes_good=0` while the inner loop
+appeared to iterate (the throttled `on_progress` log fired every 78s). The
+async fd_recovery design at §7 said each `execute()` call should bound at
+~1.5 s on poll timeout, with subsequent calls returning `DeviceNotFound` in
+microseconds until recovery completes. Observed reality contradicts that:
+each iteration takes ~60 s, not microseconds. Without trace-level telemetry
+at the SCSI + Disc::copy boundaries we can't diagnose where the time goes.
+
+This release adds the telemetry. No behavior change; instrumentation only.
+
+- New dep: `tracing = "0.1"`. Per project docs, debug/trace logging is permitted
+  in libfreemkv (the no-English rule applies to errors, not telemetry).
+  Consumers (autorip) wire a tracing subscriber and pipe events into the
+  JSONL debug log automatically.
+- `SgIoTransport::execute` (Linux): trace events at every state transition
+  (entry, recovery_swap_ok, recovery_pending, write_ok / write_err, poll_done,
+  timeout_spawn_recovery, scsi_err, read_err, ok). Each event includes the
+  opcode and elapsed timing. The bg recovery thread also traces close_ms +
+  open_ms so we can see if the kernel is hanging close+open.
+- `Disc::copy`: trace events at copy_start, outer_loop, region_enter, every
+  100 inner-loop iterations (iter_progress with pos / region_end / skip_size /
+  bytes_good / read_ok_count / read_err_count / last_read_ms /
+  copy_elapsed_ms), and copy_done.
+- All trace events use `target` strings `freemkv::scsi` and `freemkv::disc`
+  so consumers can filter by subsystem.
+
+### What this enables
+
+- A live rip will now produce a SCSI event stream visible at
+  `/api/debug?n=N&q=freemkv::scsi`. We can finally answer: "is the inner
+  loop iterating slowly because each call is slow, or fast with the bg
+  thread blocked?"
+- `bg_recovery_done` events with `close_ms` / `open_ms` reveal whether the
+  kernel really takes 60 s for close+open on a wedged Initio bridge.
+
 ## 0.13.12 (2026-04-25)
 
 ### Fix: delete stall guard from `Disc::copy` (RIP_DESIGN.md §6 Fix 1)

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "libfreemkv"
-version = "0.13.12"
+version = "0.13.13"
 edition = "2024"
 rust-version = "1.86"
 license = "AGPL-3.0-only"
@@ -24,6 +24,10 @@ rand = "0.8"
 cmac = "0.7"
 zip = { version = "2", default-features = false, features = ["deflate"] }
 base64 = "0.22.1"
+# Trace-level instrumentation for Disc::copy + SgIoTransport::execute. Permitted
+# under project docs ("Acceptable strings: debug/trace logging"). Consumers (autorip)
+# wire a tracing subscriber and pipe events into the JSONL debug log.
+tracing = "0.1"
 
 [target.'cfg(target_os = "linux")'.dependencies]
 libc = "0.2"

src/disc/mod.rs

@@ -1286,6 +1286,20 @@ impl Disc {
         let mut buf = vec![0u8; batch as usize * 2048];
         let mut bytes_done = 0u64;
         let mut halt_requested = false;
+        let copy_t0 = std::time::Instant::now();
+        let mut iter_count: u64 = 0;
+        let mut read_ok_count: u64 = 0;
+        let mut read_err_count: u64 = 0;
+        let mut last_log_iter: u64 = 0;
+        tracing::trace!(
+            target: "freemkv::disc",
+            phase = "copy_start",
+            total_bytes,
+            batch,
+            skip_init,
+            skip_max,
+            "Disc::copy entered"
+        );
 
         // Iterate over not-yet-finished regions from the mapfile. We re-read the
         // mapfile after each block because record() mutates the region list.
@@ -1295,6 +1309,12 @@ impl Disc {
                 mapfile::SectorStatus::NonTrimmed,
                 mapfile::SectorStatus::NonScraped,
             ]);
+            tracing::trace!(
+                target: "freemkv::disc",
+                phase = "outer_loop",
+                regions_remaining = regions_to_do.len(),
+                "Disc::copy outer iter"
+            );
             if regions_to_do.is_empty() {
                 break;
             }
@@ -1307,6 +1327,14 @@ impl Disc {
             };
             let region_end = region_pos + region_size;
             let mut pos = region_pos;
+            tracing::trace!(
+                target: "freemkv::disc",
+                phase = "region_enter",
+                region_pos,
+                region_size,
+                region_end,
+                "entering NonTried region"
+            );
 
             while pos < region_end {
                 if let Some(ref h) = opts.halt {
@@ -1321,11 +1349,15 @@ impl Disc {
                 let bytes = count as usize * 2048;
 
                 let recovery = !opts.skip_on_error; // fast reads when skipping
+                iter_count += 1;
+                let read_t0 = std::time::Instant::now();
                 let read_ok = reader
                     .read_sectors(lba, count, &mut buf[..bytes], recovery)
                     .is_ok();
+                let read_elapsed_ms = read_t0.elapsed().as_millis() as u64;
 
                 if read_ok {
+                    read_ok_count += 1;
                     if opts.decrypt {
                         crate::decrypt::decrypt_sectors(&mut buf[..bytes], &keys, 0)?;
                     }
@@ -1339,6 +1371,7 @@ impl Disc {
                     skip_size = skip_init; // reset after success
                     pos += block_bytes;
                 } else if opts.skip_on_error {
+                    read_err_count += 1;
                     // Zero-fill this block, mark non-trimmed for later patch trim.
                     buf[..bytes].fill(0);
                     file.seek(SeekFrom::Start(pos))
@@ -1364,6 +1397,27 @@ impl Disc {
                     return Err(Error::DiscRead { sector: lba as u64 });
                 }
 
+                // Throttled iter telemetry — every 100 inner iterations.
+                if iter_count - last_log_iter >= 100 {
+                    last_log_iter = iter_count;
+                    let stats = map.stats();
+                    tracing::trace!(
+                        target: "freemkv::disc",
+                        phase = "iter_progress",
+                        iter_count,
+                        read_ok_count,
+                        read_err_count,
+                        last_read_ms = read_elapsed_ms,
+                        pos,
+                        region_end,
+                        skip_size,
+                        bytes_good = stats.bytes_good,
+                        bytes_pending = stats.bytes_pending,
+                        copy_elapsed_ms = copy_t0.elapsed().as_millis() as u64,
+                        "Disc::copy inner iter"
+                    );
+                }
+
                 if let Some(cb) = opts.on_progress {
                     let stats = map.stats();
                     cb(stats.bytes_good, total_bytes);
@@ -1373,6 +1427,18 @@ impl Disc {
 
         file.sync_all().map_err(|e| Error::IoError { source: e })?;
         let stats = map.stats();
+        tracing::trace!(
+            target: "freemkv::disc",
+            phase = "copy_done",
+            iter_count,
+            read_ok_count,
+            read_err_count,
+            bytes_good = stats.bytes_good,
+            bytes_pending = stats.bytes_pending,
+            halted = halt_requested,
+            copy_elapsed_ms = copy_t0.elapsed().as_millis() as u64,
+            "Disc::copy returning"
+        );
         Ok(CopyResult {
             bytes_total: total_bytes,
             bytes_good: stats.bytes_good,

src/scsi/linux.rs

@@ -260,6 +260,18 @@ impl ScsiTransport for SgIoTransport {
         data: &mut [u8],
         timeout_ms: u32,
     ) -> Result<ScsiResult> {
+        let exec_t0 = std::time::Instant::now();
+        let opcode = cdb[0];
+        tracing::trace!(
+            target: "freemkv::scsi",
+            phase = "enter",
+            opcode = opcode,
+            timeout_ms,
+            data_len = data.len(),
+            fd = self.fd,
+            "SgIoTransport::execute"
+        );
+
         // Recover from a prior timeout: if a background reopen produced a
         // fresh fd, swap it in. If recovery is still pending (-1), the
         // background thread hasn't finished — return DeviceNotFound and let
@@ -269,8 +281,20 @@ impl ScsiTransport for SgIoTransport {
                 .fd_recovery
                 .swap(-1, std::sync::atomic::Ordering::Acquire);
             if recovered >= 0 {
+                tracing::trace!(
+                    target: "freemkv::scsi",
+                    phase = "recovery_swap_ok",
+                    new_fd = recovered,
+                    "fd_recovery delivered fresh fd"
+                );
                 self.fd = recovered;
             } else {
+                tracing::trace!(
+                    target: "freemkv::scsi",
+                    phase = "recovery_pending",
+                    elapsed_us = exec_t0.elapsed().as_micros() as u64,
+                    "fd_recovery still pending → DeviceNotFound"
+                );
                 return Err(Error::DeviceNotFound {
                     path: self.device_path.display().to_string(),
                 });
@@ -309,6 +333,7 @@ impl ScsiTransport for SgIoTransport {
 
         // Submit command asynchronously via write()
         let hdr_size = std::mem::size_of::<sg_io_hdr>();
+        let write_t0 = std::time::Instant::now();
         let wr = unsafe {
             libc::write(
                 self.fd,
@@ -316,16 +341,32 @@ impl ScsiTransport for SgIoTransport {
                 hdr_size,
             )
         };
+        let write_elapsed_us = write_t0.elapsed().as_micros() as u64;
         if wr < 0 {
-            return Err(Error::IoError {
+            let errno = std::io::Error::last_os_error();
-                source: std::io::Error::last_os_error(),
+            tracing::trace!(
-            });
+                target: "freemkv::scsi",
+                phase = "write_err",
+                opcode = opcode,
+                errno = errno.raw_os_error().unwrap_or(0),
+                write_elapsed_us,
+                "sg write() returned <0"
+            );
+            return Err(Error::IoError { source: errno });
         }
+        tracing::trace!(
+            target: "freemkv::scsi",
+            phase = "write_ok",
+            opcode = opcode,
+            wr,
+            write_elapsed_us,
+            "sg write() submitted"
+        );
 
         // Wait for completion with enforceable timeout.
         // Retry on EINTR (signal interrupted poll) with remaining time.
-        let deadline =
+        let poll_t0 = std::time::Instant::now();
-            std::time::Instant::now() + std::time::Duration::from_millis(timeout_ms as u64);
+        let deadline = poll_t0 + std::time::Duration::from_millis(timeout_ms as u64);
         let pr = loop {
             let remaining = deadline
                 .saturating_duration_since(std::time::Instant::now())
@@ -344,6 +385,16 @@ impl ScsiTransport for SgIoTransport {
                 break ret;
             }
         };
+        let poll_elapsed_ms = poll_t0.elapsed().as_millis() as u64;
+        tracing::trace!(
+            target: "freemkv::scsi",
+            phase = "poll_done",
+            opcode = opcode,
+            pr,
+            poll_elapsed_ms,
+            timeout_ms,
+            "poll() returned"
+        );
 
         if pr <= 0 {
             // Timeout (0) or fatal poll error (-1). Command is still pending
@@ -355,17 +406,38 @@ impl ScsiTransport for SgIoTransport {
             self.fd = -1;
             let c_path = Self::to_c_path(&self.device_path);
             let recovery = self.fd_recovery.clone();
+            tracing::trace!(
+                target: "freemkv::scsi",
+                phase = "timeout_spawn_recovery",
+                opcode = opcode,
+                old_fd,
+                exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
+                "poll timeout — spawning bg close+open"
+            );
             std::thread::spawn(move || {
                 // Close blocks until the kernel finishes/aborts the
                 // abandoned command. Then we open a fresh fd. Both happen
                 // off the main thread.
+                let close_t0 = std::time::Instant::now();
                 unsafe { libc::close(old_fd) };
+                let close_ms = close_t0.elapsed().as_millis() as u64;
+                let open_t0 = std::time::Instant::now();
                 let new_fd = unsafe {
                     libc::open(
                         c_path.as_ptr() as *const libc::c_char,
                         libc::O_RDWR | libc::O_NONBLOCK | libc::O_CLOEXEC,
                     )
                 };
+                let open_ms = open_t0.elapsed().as_millis() as u64;
+                tracing::trace!(
+                    target: "freemkv::scsi",
+                    phase = "bg_recovery_done",
+                    old_fd,
+                    new_fd,
+                    close_ms,
+                    open_ms,
+                    "bg recovery thread completed close+open"
+                );
                 if new_fd >= 0 {
                     let prev = recovery.swap(new_fd, std::sync::atomic::Ordering::Release);
                     if prev >= 0 {
@@ -386,6 +458,7 @@ impl ScsiTransport for SgIoTransport {
         }
 
         // Read response — copies data from kernel buffer to caller's buffer
+        let read_t0 = std::time::Instant::now();
         let rd = unsafe {
             libc::read(
                 self.fd,
@@ -393,7 +466,16 @@ impl ScsiTransport for SgIoTransport {
                 hdr_size,
             )
         };
+        let read_elapsed_us = read_t0.elapsed().as_micros() as u64;
         if rd < 0 {
+            tracing::trace!(
+                target: "freemkv::scsi",
+                phase = "read_err",
+                opcode = opcode,
+                read_elapsed_us,
+                exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
+                "sg read() returned <0"
+            );
             return Err(Error::IoError {
                 source: std::io::Error::last_os_error(),
             });
@@ -414,6 +496,15 @@ impl ScsiTransport for SgIoTransport {
             } else {
                 0
             };
+            tracing::trace!(
+                target: "freemkv::scsi",
+                phase = "scsi_err",
+                opcode = opcode,
+                status = hdr.status,
+                sense_key,
+                exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
+                "SCSI status non-zero"
+            );
             return Err(Error::ScsiError {
                 opcode: cdb[0],
                 status: hdr.status,
@@ -421,6 +512,14 @@ impl ScsiTransport for SgIoTransport {
             });
         }
 
+        tracing::trace!(
+            target: "freemkv::scsi",
+            phase = "ok",
+            opcode = opcode,
+            bytes_transferred,
+            exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
+            "execute() success"
+        );
         Ok(ScsiResult {
             status: hdr.status,
             bytes_transferred,