diff --git a/CHANGELOG.md b/CHANGELOG.md index 83bb1cf..11d411e 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/Cargo.toml b/Cargo.toml index 9732e3e..b565b2d 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/disc/mod.rs b/src/disc/mod.rs index 5e85f31..4f9a52d 100644 --- a/src/disc/mod.rs +++ b/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, diff --git a/src/scsi/linux.rs b/src/scsi/linux.rs index 5137ced..011e8f9 100644 --- a/src/scsi/linux.rs +++ b/src/scsi/linux.rs @@ -260,6 +260,18 @@ impl ScsiTransport for SgIoTransport { data: &mut [u8], timeout_ms: u32, ) -> Result { + 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::(); + 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 { - source: std::io::Error::last_os_error(), - }); + let errno = 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 = - std::time::Instant::now() + std::time::Duration::from_millis(timeout_ms as u64); + let poll_t0 = std::time::Instant::now(); + 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,