Log plain progress lines when stderr is not a terminal

CHANGELOG.md

@@ -22,6 +22,15 @@ project uses [semantic versioning][semver].
   and is selectable in the desktop app's Simple mode and preset editor. This is
   a one-way verified transfer, not two-way sync — see `ROADMAP.md`.
 
+- **Progress lines when stderr is not a terminal.** A background job, CI run
+  or redirected log used to print nothing until the final summary, so a
+  six-hour `offloader report` was indistinguishable from a hung one. Off a TTY,
+  `offload`, `report` and `verify` now write plain newline-terminated lines
+  (percent of job bytes, files done/total, file name, throughput and ETA): one
+  when a file starts, one every 30 s (including partway through a single large
+  file, via a new `on_bytes` callback on `hash_file`), and one on completion. The single-line
+  bar on a terminal is unchanged and `--quiet` still silences both.
+
 ### Fixed
 
 Found by adding CI on Linux and macOS — the suite had only ever run on Windows.

README.md

@@ -356,13 +356,13 @@ what makes the report layer testable without moving bytes.
 
 ```sh
 pip install -e ".[dev]"
-pytest                      # 409 tests, ~33s
+pytest                      # 413 tests, ~33s
 pytest --fuzz               # same suite, 3000 examples per property (~2 min)
 ruff check src tests
 pytest --cov=offloader --cov-report=term-missing
 ```
 
-409 tests at 82% line coverage. They cover formatting against the reference's
+413 tests at 82% line coverage. They cover formatting against the reference's
 exact strings, checksum vectors and streaming equivalence, copy/verify
 behaviour including simulated destination corruption, pause/resume/cancel
 concurrency, retry discrimination, BRAW container parsing, ffprobe parsing,

src/offloader/cli.py

@@ -24,25 +24,46 @@
 DEFAULT_REPORTS = "pdf"
 
 
+#: Seconds between periodic progress lines when stderr is not a terminal.
+LOG_INTERVAL = 30.0
+#: Minimum seconds between "file started" lines, so a card of thousands of
+#: small clips cannot flood a log.
+LOG_START_GAP = 1.0
+
+
 class _Progress:
-    """Single-line progress on stderr; silent when not a TTY."""
+    """Progress on stderr: a single redrawn line on a TTY, plain lines otherwise.
+
+    A background job or CI run has no terminal to redraw, and a six-hour run
+    that logs nothing until its summary is indistinguishable from a hung one.
+    So off a TTY it writes newline-terminated lines, throttled to stay readable.
+    `--quiet` silences both.
+    """
 
     def __init__(self, enabled: bool) -> None:
-        self.enabled = enabled and sys.stderr.isatty()
+        self.enabled = enabled
+        self.tty = sys.stderr.isatty()
         self._last = 0.0
         self._width = 0
+        self._started = time.monotonic()
+        self._last_start = -LOG_START_GAP
+        self._last_log = self._started
+        self._key: tuple[int, str] | None = None
+        self._logged_final = False
 
     def __call__(self, event: engine.ProgressEvent) -> None:
         if not self.enabled:
             return
         now = time.monotonic()
         final = event.job_bytes_done >= event.job_bytes_total
+        if not self.tty:
+            self._log(event, now, final)
+            return
         if now - self._last < 0.1 and not final:
             return
         self._last = now
 
-        pct = (event.job_bytes_done / event.job_bytes_total * 100
-               if event.job_bytes_total else 100.0)
+        pct = self._percent(event)
         line = (f"  [{pct:5.1f}%] {event.stage:<6} "
                 f"{event.file_index + 1}/{event.file_total}  {event.file_name}")
         line = line[:110]
@@ -51,8 +72,40 @@ def __call__(self, event: engine.ProgressEvent) -> None:
         sys.stderr.write("\r" + line + " " * pad)
         sys.stderr.flush()
 
+    @staticmethod
+    def _percent(event: engine.ProgressEvent) -> float:
+        return (event.job_bytes_done / event.job_bytes_total * 100
+                if event.job_bytes_total else 100.0)
+
+    def _log(self, event: engine.ProgressEvent, now: float, final: bool) -> None:
+        key = (event.file_index, event.stage)
+        new_file = key != self._key
+        self._key = key
+        due = now - self._last_log >= LOG_INTERVAL
+        started = new_file and now - self._last_start >= LOG_START_GAP
+        finished = final and not self._logged_final
+        if not (due or started or finished):
+            return
+        if new_file:
+            self._last_start = now
+        self._last_log = now
+        self._logged_final = self._logged_final or final
+
+        pct = self._percent(event)
+        parts = [f"[{pct:5.1f}%] {event.stage} "
+                 f"{event.file_index + 1}/{event.file_total} {event.file_name}"]
+        elapsed = now - self._started
+        if event.job_bytes_done and elapsed > 0:
+            rate = event.job_bytes_done / elapsed
+            parts.append(f"{format_size(int(rate))}/s")
+            remaining = event.job_bytes_total - event.job_bytes_done
+            if remaining > 0:
+                parts.append(f"ETA {format_elapsed(remaining / rate)}")
+        sys.stderr.write("  ".join(parts) + "\n")
+        sys.stderr.flush()
+
     def done(self) -> None:
-        if self.enabled and self._width:
+        if self.enabled and self.tty and self._width:
             sys.stderr.write("\r" + " " * self._width + "\r")
             sys.stderr.flush()
             self._width = 0
@@ -312,24 +365,57 @@ def cmd_verify(args: argparse.Namespace) -> int:
         print(f"error: no .mhl manifest found under {target}", file=sys.stderr)
         return 2
 
-    show = not args.quiet and sys.stderr.isatty()
+    show = not args.quiet
+    tty = sys.stderr.isatty()
+    last_log = time.monotonic()
+    last_start = -LOG_START_GAP
+    started_index = -1
 
     def progress(index: int, total: int, path: Path) -> None:
-        if show:
+        if show and tty:
             sys.stderr.write('\r' + f"  [{index + 1}/{total}] {path.name[:70]:<70}")
             sys.stderr.flush()
 
+    def log_bytes(index: int, total: int, path: Path, done: int, size: int) -> None:
+        """Off a TTY: a line as each file starts and one per LOG_INTERVAL after.
+
+        Percent counts files completed plus the share of this one read so far,
+        and stops short of 100 until the last hash has returned (the manifest's
+        own completion line below says so).
+        """
+        nonlocal last_log, last_start, started_index
+        if not show or tty:
+            return
+        now = time.monotonic()
+        new_file = index != started_index
+        started_index = index
+        due = now - last_log >= LOG_INTERVAL
+        if not (due or (new_file and now - last_start >= LOG_START_GAP)):
+            return
+        if new_file:
+            last_start = now
+        last_log = now
+        share = done / size if size else 0.0
+        pct = min((index + share) / total * 100, 99.9) if total else 0.0
+        sys.stderr.write(f"[{pct:5.1f}%] verify {index + 1}/{total} {path.name}\n")
+        sys.stderr.flush()
+
     worst = 0
     for manifest in manifests:
         try:
             report = verify_mod.verify_manifest(
-                manifest, progress=progress, bypass_cache=not args.allow_cache)
+                manifest, progress=progress, bytes_progress=log_bytes,
+                bypass_cache=not args.allow_cache)
         except Exception as exc:
             print(f"error: could not read {manifest}: {exc}", file=sys.stderr)
             worst = max(worst, 2)
             continue
-        if show:
+        if show and tty:
             sys.stderr.write('\r' + " " * 90 + '\r')
+        elif show and report.verdicts:
+            sys.stderr.write(f"[100.0%] verify {len(report.verdicts)}/"
+                             f"{len(report.verdicts)} {manifest.name} done\n")
+            sys.stderr.flush()
 
         print('\n' + str(manifest))
         print(f"  {report.summary()}")

src/offloader/engine.py

@@ -533,7 +533,14 @@ def note_retry(attempt: int, exc: BaseException, pause: float,
                         )
                     try:
                         dst_sum, verify_attempts = retry_mod.call(
-                            lambda p=partial: hash_file(p, options.algorithm),
+                            lambda p=partial, _i=index, _s=source, _z=stat.st_size:
+                            hash_file(
+                                p, options.algorithm,
+                                on_bytes=lambda n: emit(ProgressEvent(
+                                    _i, len(files), _s.name, "verify",
+                                    n, _z,
+                                    counters.job_bytes_done,
+                                    counters.job_bytes_total))),
                             options.retry,
                         )
                         if verify_attempts > 1:
@@ -680,7 +687,12 @@ def rescan(source_root: Path, destination_roots: Sequence[Path],
                                    0, stat.st_size, done, total))
         if algorithm.factory is not None:
             try:
-                entry.checksum = hash_file(source, options.algorithm)
+                entry.checksum = hash_file(
+                    source, options.algorithm,
+                    on_bytes=lambda n, _i=index, _s=source, _z=stat.st_size, _d=done:
+                        progress(ProgressEvent(_i, len(files), _s.name, "verify",
+                                               n, _z, _d + n, total))
+                        if progress else None)
             except OSError:
                 entry.checksum = None
         done += stat.st_size
@@ -707,5 +719,11 @@ def rescan(source_root: Path, destination_roots: Sequence[Path],
                 )
         job.files.append(entry)
 
+    if progress and files:
+        # The last per-file event fires before that file is hashed, so say
+        # outright that the job is complete.
+        progress(ProgressEvent(len(files) - 1, len(files), files[-1].name, "verify",
+                               stat.st_size, stat.st_size, total, total))
+
     job.finished = _dt.datetime.now()
     return job

src/offloader/hashers.py

@@ -102,16 +102,24 @@ def new_hasher(key: str) -> Hasher:
     return get_algorithm(key).new() or _NullHasher()
 
 
-def hash_file(path: Path, key: str, chunk_size: int = 8 << 20) -> str:
+def hash_file(path: Path, key: str, chunk_size: int = 8 << 20,
+              on_bytes: Callable[[int], None] | None = None) -> str:
     """Hash a file off disk. Used by full verification to re-read a
     destination, and by the `report` and `verify` commands to reconstruct or
-    re-check checksums without copying."""
+    re-check checksums without copying.
+
+    `on_bytes`, if given, is called with the running byte count after each
+    chunk, so a caller can show progress inside one very large file."""
     from .longpath import open_binary
 
     hasher = new_hasher(key)
+    read = 0
     with open_binary(path, "rb") as handle:
         for chunk in iter(lambda: handle.read(chunk_size), b""):
             hasher.update(chunk)
+            read += len(chunk)
+            if on_bytes:
+                on_bytes(read)
     return hasher.hexdigest()
 
 

src/offloader/verify.py

@@ -161,13 +161,17 @@ def verify_manifest(
     manifest: Path,
     *,
     progress: Callable[[int, int, Path], None] | None = None,
+    bytes_progress: Callable[[int, int, Path, int, int], None] | None = None,
     bypass_cache: bool = True,
     find_unlisted: bool = True,
 ) -> VerifyReport:
     """Re-hash everything an MHL describes and compare.
 
     `bypass_cache` evicts each file before reading it, so a freshly written tree
     is read off the device rather than out of memory.
+
+    `progress` fires as each entry starts; `bytes_progress` (index, total, path,
+    bytes read, file size) fires after each chunk read within the entry.
     """
     manifest = Path(manifest)
     entries = list(_entries(manifest))
@@ -191,7 +195,11 @@ def verify_manifest(
             actual_size = path.stat().st_size
             if bypass_cache:
                 evict_from_cache(path)
-            actual = hash_file(path, algorithm_key)
+            actual = hash_file(
+                path, algorithm_key,
+                on_bytes=(lambda n, _i=index, _p=path, _z=actual_size:
+                          bytes_progress(_i, len(entries), _p, n, _z))
+                if bytes_progress else None)
         except OSError as exc:
             report.verdicts.append(
                 FileVerdict(path, EntryResult.UNREADABLE, expected=expected,