From b1279b3b6f214534fb4a03b3dbd901fcb486dd73 Mon Sep 17 00:00:00 2001 From: owenpkent <20529132+owenpkent@users.noreply.github.com> Date: Mon, 26 Oct 2026 18:28:57 -0600 Subject: [PATCH 1/2] Log plain progress lines when stderr is not a terminal A background or redirected run printed nothing until the final summary, so a six-hour report looked hung. Off a TTY, offload, report and verify now write newline-terminated lines (percent, files, name, throughput, ETA): one per file start (at most one a second), one every 30 s, and one on completion. The single-line bar on a TTY and --quiet behave as before. --- CHANGELOG.md | 8 ++++ README.md | 4 +- src/offloader/cli.py | 83 ++++++++++++++++++++++++++++---- tests/test_cli.py | 110 +++++++++++++++++++++++++++++++++++++++++-- 4 files changed, 190 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0ee5eea..71a2ff1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,14 @@ 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, 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. diff --git a/README.md b/README.md index 277cb75..5de645c 100644 --- a/README.md +++ b/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 # 410 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 +410 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, diff --git a/src/offloader/cli.py b/src/offloader/cli.py index 6773f22..73eba51 100644 --- a/src/offloader/cli.py +++ b/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,12 +365,26 @@ 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() def progress(index: int, total: int, path: Path) -> None: - if show: + nonlocal last_log + if not show: + return + if tty: sys.stderr.write('\r' + f" [{index + 1}/{total}] {path.name[:70]:<70}") sys.stderr.flush() + return + # Off a TTY: the first and last file of each manifest, and one line per + # LOG_INTERVAL in between, so a long verify leaves a trail in the log. + now = time.monotonic() + if index == 0 or index + 1 == total or now - last_log >= LOG_INTERVAL: + last_log = now + pct = (index + 1) / total * 100 if total else 100.0 + sys.stderr.write(f"[{pct:5.1f}%] verify {index + 1}/{total} {path.name}\n") + sys.stderr.flush() worst = 0 for manifest in manifests: @@ -328,7 +395,7 @@ def progress(index: int, total: int, path: Path) -> None: 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') print('\n' + str(manifest)) diff --git a/tests/test_cli.py b/tests/test_cli.py index 119bd3e..d7fdc20 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -100,13 +100,97 @@ def test_multiple_destinations(source_tree: Path, tmp_path: Path): # ------------------------------------------------------------------ progress -def test_progress_is_silent_when_stderr_is_not_a_tty(capsys): - """Piped output must stay clean for logs and CI.""" +class _PipedStderr: + """A stderr that is not a terminal, capturing what is written.""" + + def __init__(self) -> None: + self.written: list[str] = [] + + @staticmethod + def isatty(): + return False + + def write(self, text): + self.written.append(text) + + @staticmethod + def flush(): + pass + + @property + def text(self) -> str: + return "".join(self.written) + + +def _event(index=0, total=3, name="clip.mov", stage="copy", done=5, size=10): + return cli.engine.ProgressEvent(index, total, name, stage, 0, 10, done, size) + + +def test_progress_writes_plain_lines_when_stderr_is_not_a_tty(monkeypatch): + """A background job must leave a trail in its log, never a redrawn line.""" + err = _PipedStderr() + monkeypatch.setattr(cli.sys, "stderr", err) + clock = iter([100.0, 105.0]) + monkeypatch.setattr(cli.time, "monotonic", lambda: next(clock)) progress = cli._Progress(enabled=True) - assert not progress.enabled - progress(cli.engine.ProgressEvent(0, 1, "clip.mov", "copy", 0, 10, 5, 10)) + progress(_event(0, done=5, size=20)) + progress.done() + assert err.text.endswith("\n") + assert "\r" not in err.text + line = err.text.splitlines()[0] + assert "25.0%" in line and "1/3" in line and "clip.mov" in line + assert "/s" in line and "ETA" in line + + +def test_progress_lines_are_throttled_off_a_tty(monkeypatch): + err = _PipedStderr() + monkeypatch.setattr(cli.sys, "stderr", err) + now = [1000.0] + monkeypatch.setattr(cli.time, "monotonic", lambda: now[0]) + progress = cli._Progress(enabled=True) + + progress(_event(0, done=1, size=100)) # file start: logged + progress(_event(0, done=2, size=100)) # same file, too soon: dropped + now[0] += 0.2 + progress(_event(1, done=3, size=100)) # new file inside the gap: dropped + assert len(err.text.splitlines()) == 1 + + now[0] += cli.LOG_INTERVAL + progress(_event(1, done=4, size=100)) # periodic line + assert len(err.text.splitlines()) == 2 + + now[0] += 2 + progress(_event(2, done=5, size=100)) # next file start + assert len(err.text.splitlines()) == 3 + + progress(_event(2, done=100, size=100)) # completion, once + progress(_event(2, done=100, size=100)) + assert len(err.text.splitlines()) == 4 + assert "100.0%" in err.text.splitlines()[-1] + + +def test_quiet_progress_is_silent_off_a_tty(monkeypatch): + err = _PipedStderr() + monkeypatch.setattr(cli.sys, "stderr", err) + progress = cli._Progress(enabled=False) + progress(_event(done=10, size=10)) progress.done() - assert capsys.readouterr().err == "" + assert err.text == "" + + +def test_report_command_logs_progress_off_a_tty_and_quiet_silences_it( + source_tree: Path, tmp_path: Path, monkeypatch, capsys): + # capsys replaces stderr with a non-TTY object, the case under test. + code = cli.main(["report", "--source", str(source_tree), + "--name", "A001", "--no-probe"]) + assert code == 0 + err = capsys.readouterr().err + assert "%]" in err and err.endswith("\n") and "\r" not in err + + code = cli.main(["report", "--source", str(source_tree), + "--name", "A001", "--no-probe", "--quiet"]) + assert code == 0 + assert "%]" not in capsys.readouterr().err def test_progress_renders_a_throttled_single_line(monkeypatch): @@ -210,6 +294,22 @@ def test_verify_passes_on_a_clean_tree(source_tree: Path, tmp_path: Path, capsys assert "safe to erase" in out +def test_verify_logs_plain_lines_off_a_tty_and_quiet_silences_them( + source_tree: Path, tmp_path: Path, capsys): + destination = tmp_path / "d1" + cli.main(["offload", "--source", str(source_tree), "--dest", str(destination), + "--name", "A001", "--verify", "full", "--report", "mhl", + "--no-probe", "--quiet"]) + capsys.readouterr() + + assert cli.main(["verify", str(destination)]) == 0 + err = capsys.readouterr().err + assert "verify 1/" in err and err.endswith("\n") and "\r" not in err + + assert cli.main(["verify", str(destination), "--quiet"]) == 0 + assert "verify 1/" not in capsys.readouterr().err + + def test_verify_fails_on_a_flipped_bit(source_tree: Path, tmp_path: Path, capsys): destination = tmp_path / "d1" cli.main(["offload", "--source", str(source_tree), "--dest", str(destination), From 6d3736993092781e02730ff167d307e0dc57b5aa Mon Sep 17 00:00:00 2001 From: owenpkent <20529132+owenpkent@users.noreply.github.com> Date: Mon, 26 Oct 2026 19:31:46 -0600 Subject: [PATCH 2/2] Report progress inside a file while hashing; keep verify below 100% until done hash_file takes an optional on_bytes callback, called per chunk, which rescan, the full-verification read in run() and verify_manifest use so the periodic log line fires during one very large file. rescan now emits its final byte count, and verify computes percent from completed work and logs 100% only after the last hash returns. --- CHANGELOG.md | 3 +- README.md | 4 +- src/offloader/cli.py | 43 ++++++++++++++++------ src/offloader/engine.py | 22 ++++++++++- src/offloader/hashers.py | 12 +++++- src/offloader/verify.py | 10 ++++- tests/test_cli.py | 79 ++++++++++++++++++++++++++++++++++++++++ 7 files changed, 153 insertions(+), 20 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 71a2ff1..b00be25 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,7 +27,8 @@ project uses [semantic versioning][semver]. 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, and one on completion. The single-line + 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 diff --git a/README.md b/README.md index 5de645c..49d190c 100644 --- a/README.md +++ b/README.md @@ -356,13 +356,13 @@ what makes the report layer testable without moving bytes. ```sh pip install -e ".[dev]" -pytest # 410 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 ``` -410 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, diff --git a/src/offloader/cli.py b/src/offloader/cli.py index 73eba51..41cb90f 100644 --- a/src/offloader/cli.py +++ b/src/offloader/cli.py @@ -368,35 +368,54 @@ def cmd_verify(args: argparse.Namespace) -> int: 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: - nonlocal last_log - if not show: - return - if tty: + 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 - # Off a TTY: the first and last file of each manifest, and one line per - # LOG_INTERVAL in between, so a long verify leaves a trail in the log. now = time.monotonic() - if index == 0 or index + 1 == total or now - last_log >= LOG_INTERVAL: - last_log = now - pct = (index + 1) / total * 100 if total else 100.0 - sys.stderr.write(f"[{pct:5.1f}%] verify {index + 1}/{total} {path.name}\n") - sys.stderr.flush() + 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 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()}") diff --git a/src/offloader/engine.py b/src/offloader/engine.py index 6660ceb..4377da5 100644 --- a/src/offloader/engine.py +++ b/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 diff --git a/src/offloader/hashers.py b/src/offloader/hashers.py index c9a5290..2a66177 100644 --- a/src/offloader/hashers.py +++ b/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() diff --git a/src/offloader/verify.py b/src/offloader/verify.py index 3975139..be8dbc7 100644 --- a/src/offloader/verify.py +++ b/src/offloader/verify.py @@ -161,6 +161,7 @@ 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: @@ -168,6 +169,9 @@ def verify_manifest( `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, diff --git a/tests/test_cli.py b/tests/test_cli.py index d7fdc20..e460b4f 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -178,6 +178,85 @@ def test_quiet_progress_is_silent_off_a_tty(monkeypatch): assert err.text == "" +class _SlowHandle: + """Four 10-byte reads, each costing 20 s on the fake clock, and a hook that + sees whatever has been logged so far at the moment each read happens.""" + + def __init__(self, clock, on_read): + self._clock, self._on_read, self._left = clock, on_read, 4 + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def read(self, _n): + self._on_read() + self._clock[0] += 20.0 + if self._left: + self._left -= 1 + return b"x" * 10 + return b"" + + +def _slow_reads(monkeypatch, err, on_read=lambda: None): + clock = [1000.0] + monkeypatch.setattr(cli.sys, "stderr", err) + monkeypatch.setattr(cli.time, "monotonic", lambda: clock[0]) + monkeypatch.setattr(cli.longpath, "open_binary", + lambda *a, **k: _SlowHandle(clock, on_read)) + + +def test_report_logs_a_periodic_line_while_one_file_is_still_hashing( + tmp_path: Path, monkeypatch): + """A 37 GB clip must not leave the log silent for the whole read.""" + source = tmp_path / "card" + source.mkdir() + (source / "only.mov").write_bytes(b"x" * 40) + err = _PipedStderr() + _slow_reads(monkeypatch, err) + seen_mid_file: list[str] = [] + + real = cli.engine.hash_file + + def spy(path, key, *a, **k): + digest = real(path, key, *a, **k) + seen_mid_file.append(err.text) # before rescan returns + return digest + + monkeypatch.setattr(cli.engine, "hash_file", spy) + assert cli.main(["report", "--source", str(source), "--name", "A001", + "--no-probe", "--report", "csv"]) == 0 + mid = seen_mid_file[0].splitlines() + # One line when the file starts, then at least one periodic line before + # the hash finished, each showing progress within the file. + assert len(mid) >= 2 + assert any("%" in line and "ETA" in line for line in mid[1:]) + + +def test_report_logs_a_completion_line(source_tree: Path, capsys): + cli.main(["report", "--source", str(source_tree), "--name", "A001", + "--no-probe", "--report", "csv"]) + lines = capsys.readouterr().err.splitlines() + assert lines and lines[-1].startswith("[100.0%]") + + +def test_verify_does_not_claim_100_percent_before_the_last_hash_returns( + source_tree: Path, tmp_path: Path, monkeypatch, capsys): + destination = tmp_path / "d1" + cli.main(["offload", "--source", str(source_tree), "--dest", str(destination), + "--name", "A001", "--verify", "full", "--report", "mhl", + "--no-probe", "--quiet"]) + capsys.readouterr() + err = _PipedStderr() + snapshots: list[str] = [] + _slow_reads(monkeypatch, err, on_read=lambda: snapshots.append(err.text)) + cli.main(["verify", str(destination)]) + assert snapshots and all("100.0%" not in text for text in snapshots) + assert "[100.0%]" in err.text + + def test_report_command_logs_progress_off_a_tty_and_quiet_silences_it( source_tree: Path, tmp_path: Path, monkeypatch, capsys): # capsys replaces stderr with a non-TTY object, the case under test.