From d487996281f71ccd3034dd708fa099057e528b42 Mon Sep 17 00:00:00 2001 From: historia Date: Fri, 28 Aug 2026 03:16:14 -0400 Subject: feat: unified logging with logging_kit.py --- app/backends/audiocpp/build.py | 12 ++-- app/backends/common.py | 7 ++- app/backends/servers.py | 4 +- app/converter/converter.py | 6 +- app/logging_kit.py | 131 ++++++++++++++++++++++++++++++++++++++ app/tests/test_hub.py | 7 ++- app/tests/test_logging_kit.py | 118 ++++++++++++++++++++++++++++++++++ app/tests/test_runview.py | 65 +++++++++++++++++++ app/tests/test_taskview.py | 140 ++++++++++++++++++++++++++++++++++++++++- app/ui/hub.py | 54 +++------------- app/ui/runview.py | 51 ++++++++++++++- app/ui/taskview.py | 124 +++++++++++++++++++++++++++++------- audiobook.py | 6 ++ 13 files changed, 637 insertions(+), 88 deletions(-) create mode 100644 app/logging_kit.py create mode 100644 app/tests/test_logging_kit.py diff --git a/app/backends/audiocpp/build.py b/app/backends/audiocpp/build.py index 9ffe429..1ad6018 100644 --- a/app/backends/audiocpp/build.py +++ b/app/backends/audiocpp/build.py @@ -6,10 +6,11 @@ import os import re import shlex import shutil -from datetime import datetime from pathlib import Path from typing import List, Optional +import logging_kit + from backends import common, servers from backends.common import APP_DIR from .catalog import _BACKEND_TOKEN_RE, detect_backend, load_server_config @@ -490,14 +491,11 @@ def _build_audiocpp_tui(emit, cancel, argv: List[str], command: str, cancelled build (CANCEL set) is not reported as a failure, but its partial output stays in the log file. """ - log_path = common.LOG_DIR / ( - f"audiocpp_build_{datetime.now():%Y%m%d_%H%M%S}.log") - log_path.parent.mkdir(parents=True, exist_ok=True) - log_handle = log_path.open("w", encoding="utf-8") + log_path, log_handle = logging_kit.run_artifact("audiocpp_build", + log_dir=common.LOG_DIR) def tee(line: str) -> None: - log_handle.write(line + "\n") - log_handle.flush() + logging_kit.write_line(log_handle, line) emit(line) class _TeeWriter(io.TextIOBase): diff --git a/app/backends/common.py b/app/backends/common.py index 4c768b8..d25a03e 100644 --- a/app/backends/common.py +++ b/app/backends/common.py @@ -17,6 +17,8 @@ import urllib.parse from pathlib import Path from typing import Dict, List, Optional, Set, Tuple +import logging_kit + # Messages queued while the TUI is on screen, printed to the real console # after the curses session ends (see ui.hub.run). Build/setup steps that # fail inside the TUI record here so the user gets a copy-pastable command @@ -32,8 +34,9 @@ TTS_ROOT = Path(__file__).resolve().parent.parent.parent # The single "everything else" directory under TTS_ROOT. APP_DIR = TTS_ROOT / "app" -# app/logs — build/server/conversion logs (already gitignored). -LOG_DIR = APP_DIR / "logs" +# app/logs — build/server/conversion logs (already gitignored). Naming and +# retention policy lives in logging_kit (streams vs. timestamped artifacts). +LOG_DIR = logging_kit.LOG_DIR # The project's sample-voice directory: .wav files dropped here are offered # as the default source when a setup/configure wizard asks for a wav diff --git a/app/backends/servers.py b/app/backends/servers.py index 986d82a..c258398 100644 --- a/app/backends/servers.py +++ b/app/backends/servers.py @@ -32,9 +32,7 @@ from pathlib import Path from typing import Callable, List, Optional from backends import common, probe -from backends.common import APP_DIR - -LOG_DIR = APP_DIR / "logs" +from backends.common import LOG_DIR # How long to wait for a server to accept connections on its URL. First-time # model loads (especially qwen-tts / faster-qwen3-tts pulling weights into diff --git a/app/converter/converter.py b/app/converter/converter.py index e1649c2..405073a 100644 --- a/app/converter/converter.py +++ b/app/converter/converter.py @@ -13,6 +13,8 @@ from datetime import datetime from pathlib import Path from typing import Callable, Dict, List, Optional, Tuple +import logging_kit + from . import audio, chunking, config, cover, extractors from .audio import TrackMeta from .clients import ( @@ -57,7 +59,9 @@ def resolve_dir(value, default: str) -> Path: BOOKS_FOLDER = resolve_dir(config.INPUT_DIR, "input") AUDIOBOOKS_FOLDER = resolve_dir(config.OUTPUT_DIR, "output") CHUNKS_FOLDER = APP_DIR / "chunks" # Per-chunk scratch audio, cleaned per book -LOGS_FOLDER = APP_DIR / "logs" +# The converter's log stream (audiobook_YYYYMMDD.log); naming/retention +# policy lives in logging_kit. +LOGS_FOLDER = logging_kit.LOG_DIR DEBUG_FOLDER = APP_DIR / "debug" # --debug dumps, kept across runs # Output containers and supported input formats. diff --git a/app/logging_kit.py b/app/logging_kit.py new file mode 100644 index 0000000..c16b7ed --- /dev/null +++ b/app/logging_kit.py @@ -0,0 +1,131 @@ +"""Ownership of app/logs: naming, handles, and retention. + +Every log file this app writes follows one of two conventions, and all of +them are created through this module so the policy lives in one place: + + * Streams — continuous app activity, appended to across runs: + ``_YYYYMMDD.log`` (e.g. audiobook_20260828.log, tui_20260828.log) + * Artifacts — one discrete operation, kept as its own file and referenced + by path afterwards (failure flashes, post-TUI notices): + ``_YYYYmmdd_HHMMSS.log`` (e.g. audiocpp_build_..., audiocpp_start_...) + +The one exception is ``-server.log``: managed-server processes +(backends.servers) spawn with their stdout/stderr attached to that file and +outlive this app's runs, so it stays a per-process append file — and +prune_logs never deletes it. + +Everything here is stdlib-only and best-effort: logging must never break +the app, so an unwritable directory or a failed write degrades to a no-op. +""" + +import time +from datetime import datetime +from pathlib import Path + +# The single log directory (app/logs, already gitignored). +LOG_DIR = Path(__file__).resolve().parent / "logs" + +# Stream/artifact files older than this are deleted by prune_logs (called +# once per app start). Server logs and pid files are never touched. +RETENTION_DAYS = 30 + + +def day_stream(prefix: str, log_dir: Path = None): + """Open today's ``_YYYYMMDD.log`` stream for appending. + + Returns the open text handle (write through write_line so lines are + flushed), or None when the directory/file cannot be opened. + """ + directory = log_dir if log_dir is not None else LOG_DIR + try: + directory.mkdir(parents=True, exist_ok=True) + return (directory / f"{prefix}_{datetime.now():%Y%m%d}.log" + ).open("a", encoding="utf-8") + except OSError: + return None + + +def run_artifact(name: str, log_dir: Path = None): + """Create ``_YYYYmmdd_HHMMSS.log``; return ``(path, handle)``. + + The path is always returned so callers can point the user at it even + when HANDLE is None (the directory/file could not be created). + """ + directory = log_dir if log_dir is not None else LOG_DIR + path = directory / f"{name}_{datetime.now():%Y%m%d_%H%M%S}.log" + try: + directory.mkdir(parents=True, exist_ok=True) + return path, path.open("w", encoding="utf-8") + except OSError: + return path, None + + +def write_line(handle, text: str) -> None: + """Append one line to HANDLE (None-safe), flushed; never raises.""" + if handle is None: + return + try: + handle.write(f"{text}\n") + handle.flush() + except (OSError, ValueError): + pass + + +class TeeWriter: + """A file-like that mirrors writes to a log file and an inner stream. + + Used with ``contextlib.redirect_stdout`` to tee plain-console output + into a persistent log without losing the original consumer (e.g. the + task view's line writer). Either side may be None, and write errors + are swallowed, so logging never breaks the caller. + """ + + def __init__(self, logf=None, inner=None): + self._logf = logf + self._inner = inner + + def write(self, text) -> int: + if not text: + return 0 + for stream in (self._logf, self._inner): + if stream is not None: + try: + stream.write(text) + except (OSError, ValueError): + pass + return len(text) + + def flush(self) -> None: + for stream in (self._logf, self._inner): + if stream is not None: + try: + stream.flush() + except (OSError, ValueError, AttributeError): + pass + + def isatty(self) -> bool: + return False + + +def prune_logs(days: int = RETENTION_DAYS, log_dir: Path = None) -> None: + """Delete stream/artifact log files older than DAYS (by mtime). + + ``-server.log`` files are skipped — a managed server may still + hold its log open, and its lifetime is not tied to this app's runs. + Non-log files (pid files, anything else) are never touched. + """ + directory = log_dir if log_dir is not None else LOG_DIR + try: + entries = list(directory.iterdir()) + except OSError: + return + cutoff = time.time() - days * 86400 + for entry in entries: + if not entry.name.endswith(".log") \ + or entry.name.endswith("-server.log"): + continue + try: + if entry.stat().st_mtime < cutoff: + entry.unlink() + except OSError: + pass diff --git a/app/tests/test_hub.py b/app/tests/test_hub.py index f0af74c..0bdf2d5 100644 --- a/app/tests/test_hub.py +++ b/app/tests/test_hub.py @@ -2535,10 +2535,11 @@ class SettingsTests(unittest.TestCase): # The ports section note hangs off the first port field, the remote # section note off the first remote URL field. notes = {f["key"]: f.get("note") for f in captured["fields"]} - self.assertTrue(notes["input_dir"]) - self.assertTrue(notes["output_dir"]) - self.assertTrue(notes["debug"]) + self.assertIsNone(notes["input_dir"]) + self.assertIsNone(notes["output_dir"]) + self.assertIsNone(notes["debug"]) self.assertTrue(notes["stop_and_exit"]) + self.assertTrue(notes["unload_models"]) self.assertTrue(notes["audiocpp_port"]) self.assertTrue(notes["audiocpp_remote_url"]) self.assertIsNone(notes["audio_format"]) diff --git a/app/tests/test_logging_kit.py b/app/tests/test_logging_kit.py new file mode 100644 index 0000000..1945e5e --- /dev/null +++ b/app/tests/test_logging_kit.py @@ -0,0 +1,118 @@ +"""Tests for app/logging_kit.py — log naming, teeing, and retention.""" + +import io +import os +import tempfile +import time +import unittest +from pathlib import Path + +import logging_kit + + +class _TempDir(unittest.TestCase): + def setUp(self): + self.tmp = tempfile.TemporaryDirectory() + self.addCleanup(self.tmp.cleanup) + self.dir = Path(self.tmp.name) + + +class DayStreamTests(_TempDir): + def test_creates_dated_stream_and_appends(self): + handle = logging_kit.day_stream("tui", log_dir=self.dir) + self.assertIsNotNone(handle) + logging_kit.write_line(handle, "first") + logging_kit.write_line(handle, "second") + handle.close() + files = list(self.dir.glob("tui_*.log")) + self.assertEqual(len(files), 1) + self.assertRegex(files[0].name, r"^tui_\d{8}\.log$") + self.assertEqual(files[0].read_text(encoding="utf-8"), + "first\nsecond\n") + + def test_unwritable_dir_returns_none(self): + blocker = self.dir / "file" # a file where the directory would be + blocker.write_text("x", encoding="utf-8") + self.assertIsNone( + logging_kit.day_stream("tui", log_dir=blocker)) + + +class RunArtifactTests(_TempDir): + def test_creates_timestamped_artifact(self): + path, handle = logging_kit.run_artifact("audiocpp_build", + log_dir=self.dir) + self.assertIsNotNone(handle) + self.assertRegex(path.name, r"^audiocpp_build_\d{8}_\d{6}\.log$") + logging_kit.write_line(handle, "out") + handle.close() + self.assertEqual(path.read_text(encoding="utf-8"), "out\n") + + def test_returns_path_even_when_unwritable(self): + blocker = self.dir / "file" + blocker.write_text("x", encoding="utf-8") + path, handle = logging_kit.run_artifact("x", log_dir=blocker) + self.assertIsNone(handle) + self.assertEqual(path.parent, blocker) + + +class WriteLineTests(unittest.TestCase): + def test_none_handle_is_a_noop(self): + logging_kit.write_line(None, "x") # must not raise + + def test_broken_handle_is_swallowed(self): + class Broken: + def write(self, _): + raise OSError("nope") + + def flush(self): + raise OSError("nope") + + logging_kit.write_line(Broken(), "x") # must not raise + + +class TeeWriterTests(unittest.TestCase): + def test_mirrors_to_both_sides(self): + logf, inner = io.StringIO(), io.StringIO() + writer = logging_kit.TeeWriter(logf, inner) + self.assertEqual(writer.write("hello"), 5) + writer.flush() + self.assertEqual(logf.getvalue(), "hello") + self.assertEqual(inner.getvalue(), "hello") + + def test_empty_write_returns_zero(self): + self.assertEqual(logging_kit.TeeWriter(io.StringIO()).write(""), 0) + + def test_none_sides_and_errors_are_swallowed(self): + writer = logging_kit.TeeWriter(None, None) + self.assertEqual(writer.write("x"), 1) # must not raise + writer.flush() + self.assertFalse(writer.isatty()) + + +class PruneTests(_TempDir): + def test_deletes_old_logs_keeps_new_server_logs_and_pid_files(self): + old = self.dir / "tui_20200101.log" + old.write_text("x", encoding="utf-8") + new = self.dir / "audiobook_20990101.log" + new.write_text("x", encoding="utf-8") + server = self.dir / "audiocpp-server.log" + server.write_text("x", encoding="utf-8") + pid = self.dir / "audiocpp-server.pid" + pid.write_text("1", encoding="utf-8") + ancient = time.time() - 100 * 86400 + os.utime(old, (ancient, ancient)) + os.utime(server, (ancient, ancient)) + + logging_kit.prune_logs(log_dir=self.dir) + + self.assertFalse(old.exists()) + self.assertTrue(new.exists()) + self.assertTrue(server.exists()) # owned by a server process + self.assertTrue(pid.exists()) # not a log + + def test_missing_dir_is_a_noop(self): + logging_kit.prune_logs(log_dir=self.dir / "nope") # must not raise + + +if __name__ == "__main__": + unittest.main() diff --git a/app/tests/test_runview.py b/app/tests/test_runview.py index f2d5180..8feeee1 100644 --- a/app/tests/test_runview.py +++ b/app/tests/test_runview.py @@ -10,6 +10,7 @@ cancel → stop-server flow. import os import sys import tempfile +import types import unittest from queue import Empty from unittest.mock import patch @@ -129,6 +130,70 @@ class StateTransitionTests(_FakeTui, unittest.TestCase): self.assertEqual(view.server, "stopped") +class LogAppenderTests(_FakeTui, unittest.TestCase): + """_LogAppender: stray console output survives in the run's log file.""" + + def _appender(self): + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + path = os.path.join(tmp.name, "audiobook_20260828.log") + return path, runview._LogAppender(path) + + def test_write_splits_lines_into_the_file(self): + path, appender = self._appender() + appender.write("one\ntwo\n") + appender.write("three") + appender.flush() + with open(path, encoding="utf-8") as handle: + lines = handle.read().splitlines() + self.assertEqual(len(lines), 3) + self.assertTrue(lines[0].endswith(" - one")) + self.assertTrue(lines[2].endswith(" - three")) + + def test_blank_lines_and_empty_path_are_skipped(self): + path, appender = self._appender() + appender.write("\n\n") + appender.flush() + appender.write("x") + appender.flush() + empty = runview._LogAppender("") + empty.write("ignored\n") # must not raise + with open(path, encoding="utf-8") as handle: + self.assertEqual(len(handle.read().splitlines()), 1) + + def test_unwritable_path_never_raises(self): + appender = runview._LogAppender("/nonexistent-dir-zz/log.log") + appender.write("boom\n") # must not raise + appender.flush() + + def test_worker_stdout_is_mirrored_to_the_run_log(self): + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + log_path = os.path.join(tmp.name, "audiobook_20260828.log") + view, _ = self.make_view(log_path=log_path) + + fake = types.ModuleType("audiobook") + + def convert(**_kwargs): + print("[INFO] stray console output") + + fake.convert = convert + with patch.dict(sys.modules, {"audiobook": fake}): + view._worker_main() + + with open(log_path, encoding="utf-8") as handle: + text = handle.read() + self.assertIn("[INFO] stray console output", text) + # The worker signed off normally through the event queue. + kinds = [] + while True: + try: + kinds.append(view._queue.get_nowait()["kind"]) + except Empty: + break + self.assertEqual(kinds, ["worker_exit"]) + + class RenderTests(_FakeTui, unittest.TestCase): def _strings(self, screen): return " ".join(text for _, _, text, _ in screen.strings) diff --git a/app/tests/test_taskview.py b/app/tests/test_taskview.py index 646fccb..1db708d 100644 --- a/app/tests/test_taskview.py +++ b/app/tests/test_taskview.py @@ -9,8 +9,10 @@ transitions through ``handle_event`` + ``_step_mark`` + ``_result_rc``. import io import sys +import tempfile import threading import unittest +from pathlib import Path from queue import Empty from unittest.mock import patch @@ -30,6 +32,12 @@ class _FakeTui: patcher = patch.dict(sys.modules, {"curses": self.curses}) patcher.start() self.addCleanup(patcher.stop) + # Console mirroring is disabled by default so tests stay hermetic; + # the console-log tests patch day_stream with a real temp file. + log_patcher = patch.object(taskview.logging_kit, "day_stream", + return_value=None) + log_patcher.start() + self.addCleanup(log_patcher.stop) taskview.tui._THEME.clear() self.addCleanup(taskview.tui._THEME.clear) @@ -41,6 +49,18 @@ class _FakeTui: return view, screen +class _TempLog: + """A temp target for the tui_ day stream (patched over day_stream).""" + + def _log_target(self): + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + path = Path(tmp.name) / "tui_20260828.log" + handle = path.open("w", encoding="utf-8") + self.addCleanup(handle.close) + return path, handle + + class RunStepsInlineTests(unittest.TestCase): def test_runs_steps_in_order_and_returns_zero(self): order = [] @@ -128,10 +148,100 @@ class ProgressParsingTests(_FakeTui, unittest.TestCase): def test_log_tail_is_capped(self): view, _ = self.make_view(steps=[_step("a")]) - for i in range(taskview._LOG_TAIL + 5): + for i in range(taskview._LOG_KEEP + 5): view._ingest_line(f"line {i}") - self.assertEqual(len(view.log_tail), taskview._LOG_TAIL) - self.assertEqual(view.log_tail[-1], f"line {taskview._LOG_TAIL + 4}") + self.assertEqual(len(view.log_tail), taskview._LOG_KEEP) + self.assertEqual(view.log_tail[-1], f"line {taskview._LOG_KEEP + 4}") + + +class ConsoleLogTests(_TempLog, _FakeTui, unittest.TestCase): + """The tui_ day-stream mirror: header, lines, markers, exclusions.""" + + def test_run_header_lines_and_step_markers_are_written(self): + path, handle = self._log_target() + with patch.object(taskview.logging_kit, "day_stream", + return_value=handle): + view, _ = self.make_view(steps=[_step("one")]) + view.handle_event({"kind": "step_start", "index": 0, + "title": "one"}) + view._ingest_line("cloning into 'audio.cpp'...") + view.handle_event({"kind": "step_done", "index": 0, "rc": 0}) + view.handle_event({"kind": "finish", "phase": "done", "rc": 0}) + view._on_stop() + text = path.read_text(encoding="utf-8") + self.assertIn("=== Setup —", text) + self.assertIn("--- one ---", text) + self.assertIn("cloning into 'audio.cpp'...", text) + self.assertIn("[OK] one (exit 0)", text) + self.assertIn("=== done (exit 0) ===", text) + + def test_machine_progress_lines_are_not_logged(self): + path, handle = self._log_target() + with patch.object(taskview.logging_kit, "day_stream", + return_value=handle): + view, _ = self.make_view(steps=[_step("a")]) + view._ingest_line("AUDIOCPP_PROGRESS downloaded=1 total=2") + view._ingest_line("[ 45%] building") + view._on_stop() + text = path.read_text(encoding="utf-8") + self.assertNotIn("AUDIOCPP_PROGRESS", text) + self.assertIn("[ 45%] building", text) + + def test_failed_step_is_marked_in_the_log(self): + path, handle = self._log_target() + with patch.object(taskview.logging_kit, "day_stream", + return_value=handle): + view, _ = self.make_view(steps=[_step("one")]) + view.handle_event({"kind": "step_start", "index": 0, + "title": "one"}) + view.handle_event({"kind": "step_done", "index": 0, "rc": 7}) + view._on_stop() + text = path.read_text(encoding="utf-8") + self.assertIn("[FAIL] one (exit 7)", text) + + def test_cancelled_step_is_marked_in_the_log(self): + path, handle = self._log_target() + with patch.object(taskview.logging_kit, "day_stream", + return_value=handle): + view, _ = self.make_view(steps=[_step("one")]) + view.handle_event({"kind": "step_start", "index": 0, + "title": "one"}) + view.handle_event({"kind": "step_cancelled", "index": 0}) + view.handle_event({"kind": "finish", "phase": "cancelled", + "rc": 1}) + view._on_stop() + text = path.read_text(encoding="utf-8") + self.assertIn("[x] one (cancelled)", text) + self.assertIn("=== cancelled (exit 1) ===", text) + + def test_unwritable_log_disables_the_mirror(self): + with patch.object(taskview.logging_kit, "day_stream", + return_value=None): + view, _ = self.make_view(steps=[_step("a")]) + view._ingest_line("hello") # must not raise + view._on_stop() + self.assertEqual(view.log_tail, ["hello"]) + + def test_lane_output_is_mirrored_with_lane_markers(self): + path, handle = self._log_target() + with patch.object(taskview.logging_kit, "day_stream", + return_value=handle): + screen = FakeScreen(width=80, height=24) + view = taskview.LanesView( + screen, "Setup", + [taskview.TaskLane("Build", [_step("one")])], + clock=lambda: 1000.0) + lane = view._lanes[0] + view._handle_lane_event(lane, {"kind": "step_start", + "index": 0, "title": "one"}) + view._ingest_lane_line(lane, "compiling foo.o") + view._handle_lane_event(lane, {"kind": "lane_finish", "rc": 0}) + view._console_log.close() + text = path.read_text(encoding="utf-8") + self.assertIn("=== Setup —", text) + self.assertIn("--- [Build] one ---", text) + self.assertIn("compiling foo.o", text) + self.assertIn("=== [Build] finished (exit 0) ===", text) class StateTransitionTests(_FakeTui, unittest.TestCase): @@ -193,6 +303,30 @@ class RenderTests(_FakeTui, unittest.TestCase): self.assertIn("two", text) self.assertIn("Esc or q: cancel", text) + def test_log_tail_fills_the_available_height(self): + # A tall terminal shows all 20 lines (the old 10-line cap would + # have left the bottom blank). + view, screen = self.make_view(steps=[_step("one")], height=30) + for i in range(20): + view._ingest_line(f"line {i}") + view.render() + shown = [t for _, _, t, _ in screen.strings if t.startswith("line ")] + self.assertEqual(len(shown), 20) + self.assertEqual(shown[0], "line 0") + self.assertEqual(shown[-1], "line 19") + + def test_log_tail_shows_the_most_recent_lines_that_fit(self): + # The tail is anchored to the latest output: on a small screen the + # earliest lines scroll off while the newest stay visible. + view, screen = self.make_view(steps=[_step("one")], height=24) + for i in range(20): + view._ingest_line(f"line {i}") + view.render() + shown = [t for _, _, t, _ in screen.strings if t.startswith("line ")] + self.assertGreater(len(shown), 10) # more than the old fixed cap + self.assertEqual(shown[-1], "line 19") + self.assertNotIn("line 0", shown) + def test_done_screen_shows_the_completion_footer(self): view, screen = self.make_view(steps=[_step("one")]) view.handle_event({"kind": "step_start", "index": 0, "title": "one"}) diff --git a/app/ui/hub.py b/app/ui/hub.py index a5c3dc4..e17e862 100644 --- a/app/ui/hub.py +++ b/app/ui/hub.py @@ -30,6 +30,8 @@ from datetime import datetime from pathlib import Path from typing import Callable, Optional, Tuple +import logging_kit + from backends import ( REGISTRY, BackendStatus, @@ -561,60 +563,24 @@ class _Hub: return tui.Wizard.BACK -class _TeeWriter: - """A file-like that mirrors writes to a log file and an inner stream. - - Used to capture the server module's plain-console output (the task view - already redirects stdout to its line-writer) into a persistent log file - under ``servers.LOG_DIR`` without losing the on-screen log tail. - """ - - def __init__(self, logf, inner): - self._logf = logf - self._inner = inner - - def write(self, text): - if not text: - return 0 - try: - self._logf.write(text) - except OSError: - pass - try: - self._inner.write(text) - except OSError: - pass - return len(text) - - def flush(self): - try: - self._logf.flush() - except OSError: - pass - try: - self._inner.flush() - except OSError: - pass - - def _server_action_step(spec, action: str): """Build a task step that starts/stops SPEC's server, logged to a file. ACTION is "start" or "stop". The step runs inside the task view (no - console drop): the server module's output is tee'd to - ``/-.log`` and to the view's log tail. - Returns ``(TaskStep, log_path)`` so the caller can point the user at the - file on failure. + console drop): the server module's output is tee'd to a timestamped + ``__*.log`` artifact under ``servers.LOG_DIR`` (see + ``logging_kit.run_artifact``) and to the view's log tail. Returns + ``(TaskStep, log_path)`` so the caller can point the user at the file + on failure. """ - log_path = servers.LOG_DIR / f"{spec.name}-{action}.log" title = (f"Start {spec.name} server" if action == "start" else f"Stop {spec.name} server") + log_path, logf = logging_kit.run_artifact(f"{spec.name}_{action}", + log_dir=servers.LOG_DIR) def work(emit, cancel): - servers.LOG_DIR.mkdir(parents=True, exist_ok=True) inner = sys.stdout # the task view's line-writer, when run in TUI - with log_path.open("w", encoding="utf-8") as logf, \ - contextlib.redirect_stdout(_TeeWriter(logf, inner)): + with contextlib.redirect_stdout(logging_kit.TeeWriter(logf, inner)): if action == "start": ok = servers.start(spec, cancel=cancel) else: diff --git a/app/ui/runview.py b/app/ui/runview.py index 9448c06..b3a1ab0 100644 --- a/app/ui/runview.py +++ b/app/ui/runview.py @@ -29,7 +29,6 @@ so the failure is never scrolled away. """ import contextlib -import io import threading import time from dataclasses import dataclass @@ -59,6 +58,51 @@ _SERVER_STATES = { _MONITOR_INTERVAL = 2.0 +class _LogAppender: + """A file-like that appends redirected console output to the run's log. + + The run view owns the screen, so anything a conversion prints to + stdout/stderr outside the progress events would otherwise be swallowed + silently; this mirrors it line by line into the run's dated log file + (RunConfig.log_path, the audiobook_ day stream), prefixed with the same + timestamp format the converter's log records use. Best-effort: write + errors are swallowed, and an empty path disables logging. + """ + + def __init__(self, path: str): + self._path = path + self._buffer = "" + + def write(self, text: str) -> int: + if not text: + return 0 + self._buffer += text + while True: + cut = self._buffer.find("\n") + if cut < 0: + break + line, self._buffer = self._buffer[:cut], self._buffer[cut + 1:] + self._append(line) + return len(text) + + def flush(self) -> None: + if self._buffer: + self._append(self._buffer) + self._buffer = "" + + def isatty(self) -> bool: + return False + + def _append(self, line: str) -> None: + if not self._path or not line.strip(): + return + try: + with open(self._path, "a", encoding="utf-8") as logf: + logf.write(f"{datetime.now():%Y-%m-%d %H:%M:%S} - {line}\n") + except OSError: + pass + + @dataclass class RunConfig: """Everything the run view needs to execute one conversion. @@ -232,7 +276,7 @@ class RunView(ScreenView): import audiobook config = self.config try: - with contextlib.redirect_stdout(io.StringIO()): + with contextlib.redirect_stdout(_LogAppender(config.log_path)): if config.autostart_spec is not None: if config.restart_first: # The managed qwen server hosts another model than @@ -401,7 +445,8 @@ class RunView(ScreenView): def _stop() -> None: try: - with contextlib.redirect_stdout(io.StringIO()): + with contextlib.redirect_stdout( + _LogAppender(self.config.log_path)): servers.stop(name) finally: self._queue.put({"kind": "server_stopped"}) diff --git a/app/ui/taskview.py b/app/ui/taskview.py index d7aed96..3831ceb 100644 --- a/app/ui/taskview.py +++ b/app/ui/taskview.py @@ -7,8 +7,11 @@ dumped the user into plain console output. This widget keeps them inside the hub's curses session: a worker thread runs an ordered list of ``TaskStep``s while the main thread redraws a DOS-style frame showing each step's state (pending / running with a spinner and elapsed clock / [OK] / [FAIL]), an -optional progress bar for the current step, and a dim scrolling log tail of -the step's output. +optional progress bar for the current step, and a dim log tail of the step's +output filling the remaining screen height. Every line the view shows is also +mirrored to the ``tui_YYYYMMDD.log`` day stream under app/logs (see +``_ConsoleLog``), so console output survives the curses session even when the +step itself keeps no log. Steps stream their output by calling ``emit(line)`` (or simply printing to stdout/stderr, which the view captures). The view turns output into progress @@ -43,17 +46,22 @@ import sys import threading import time from dataclasses import dataclass +from datetime import datetime from queue import Empty, Queue from typing import Callable, List, Optional, Tuple +import logging_kit + from ui import tui from ui.viewkit import (TERMINAL_PHASES as _TERMINAL, - DRAW_TIMEOUT_MS as _DRAW_TIMEOUT_MS, - ScreenView, _box, _fit, _format_elapsed, _sep, - _text) + DRAW_TIMEOUT_MS as _DRAW_TIMEOUT_MS, + ScreenView, _box, _fit, _format_elapsed, _sep, + _text) -# How many recent output lines the log tail keeps. -_LOG_TAIL = 10 +# How many recent output lines the tail keeps in memory. The on-screen tail +# draws as many as fit (see render); the full run is also mirrored to the +# ``tui_`` day stream under app/logs (see _ConsoleLog). +_LOG_KEEP = 1000 # Progress-line matchers, in order of precedence. _PROGRESS_BYTES = re.compile(r"AUDIOCPP_PROGRESS downloaded=(\d+) total=(\d+)") @@ -143,6 +151,43 @@ def _silence_cue_text(silent: float) -> str: return f"(no output {int(silent // 60)}m)" +class _ConsoleLog: + """Mirrors a task view's console output into the ``tui_`` day stream. + + Every line the view shows (minus machine-readable progress lines) is + appended to ``app/logs/tui_YYYYMMDD.log``, with a separator header per + run and step start/finish markers, so no in-TUI console output is lost. + The file is opened lazily on the first line — a run with no output + creates nothing — and every write is best-effort: an unwritable + app/logs simply disables the mirror. One instance per view run; both + lanes of a LanesView share theirs (ingestion runs on the main thread). + """ + + def __init__(self, title: str): + self._title = title + self._handle = None + self._started = False + + def line(self, text: str) -> None: + """Append TEXT (and, once, the run's separator header).""" + if not self._started: + self._started = True + self._handle = logging_kit.day_stream("tui") + logging_kit.write_line(self._handle, "") + logging_kit.write_line( + self._handle, f"=== {self._title} — " + f"{datetime.now():%Y-%m-%d %H:%M:%S} ===") + logging_kit.write_line(self._handle, text) + + def close(self) -> None: + if self._handle is not None: + try: + self._handle.close() + except OSError: + pass + self._handle = None + + def _lane_step_mark(current: Optional[int], results: List[Optional[int]], cancelled_step: Optional[int], @@ -238,6 +283,8 @@ class TaskView(ScreenView): self.finished_at: Optional[float] = None self.cancelled = False self.cancelling = False + # -- console mirror (app/logs/tui_YYYYMMDD.log) ---------------- + self._console_log = _ConsoleLog(title) # -- threads --------------------------------------------------- self._queue: Queue = Queue() self._cancel = threading.Event() @@ -295,27 +342,37 @@ class TaskView(ScreenView): self.last_line_at = self._now() self._progress = None self._progress_kind = "" + self._console_log.line(f"--- {event.get('title') or ''} ---") elif kind == "line": text = event.get("text") or "" self._ingest_line(text) elif kind == "step_done": index = event["index"] - self.results[index] = event.get("rc") or 0 + rc = event.get("rc") or 0 + self.results[index] = rc self.current = None self.last_line_at = None self._progress = None self._progress_kind = "" + self._console_log.line( + f"[{'OK' if rc == 0 else 'FAIL'}] " + f"{self.steps[index].title} (exit {rc})") elif kind == "step_cancelled": - self.cancelled_step = event["index"] + index = event["index"] + self.cancelled_step = index self.current = None self.last_line_at = None self._progress = None self._progress_kind = "" + self._console_log.line( + f"[x] {self.steps[index].title} (cancelled)") elif kind == "finish": self.phase = event.get("phase") or "done" self.cancelled = self.phase == "cancelled" self.finished_at = self._now() self.current = None + self._console_log.line( + f"=== {self.phase} (exit {event.get('rc') or 0}) ===") def _ingest_line(self, text: str) -> None: """Fold one output line into the log tail and progress bar.""" @@ -333,8 +390,9 @@ class TaskView(ScreenView): # Percent/count lines stay in the log (the tail already # collapses rapid \r updates to the last full line). self.log_tail.append(line) - if len(self.log_tail) > _LOG_TAIL: - del self.log_tail[: len(self.log_tail) - _LOG_TAIL] + if len(self.log_tail) > _LOG_KEEP: + del self.log_tail[: len(self.log_tail) - _LOG_KEEP] + self._console_log.line(line) # ScreenView hooks ------------------------------------------------ @@ -358,6 +416,10 @@ class TaskView(ScreenView): return 1 return next((rc for rc in self.results if rc), 0) + def _on_stop(self) -> None: + self._console_log.close() + super()._on_stop() + def _prompt_cancel(self) -> bool: """Esc/q: confirm cancel, then wait for the worker to wind down.""" self._blocking() @@ -439,12 +501,14 @@ class TaskView(ScreenView): y += 1 # -- log tail -------------------------------------------------- - for line in self.log_tail[-_LOG_TAIL:]: - _text(scr, theme, y, inner_x, _fit(line, width - inner_x - 2), - theme["dim"]) - y += 1 - if y >= height - 3: - break + # Every recent line that fits between here and the footer; the + # full run lives in the tui_ day stream (see _ConsoleLog). + room = (height - 3) - y + if room > 0: + for line in self.log_tail[-room:]: + _text(scr, theme, y, inner_x, _fit(line, width - inner_x - 2), + theme["dim"]) + y += 1 # -- footer ---------------------------------------------------- suffix = "" if not self.wait_on_finish else " — press any key to return" @@ -659,6 +723,7 @@ class LanesView(_GetchModes): self.theme = tui._ensure_theme(curses) self._clock = clock self._lanes = [_LaneState(lane.title, lane.steps) for lane in lanes] + self._console_log = _ConsoleLog(title) # shared by both lanes self.phase = "running" # running | done | error | cancelled self.cancelled = False self.cancelling = False @@ -704,23 +769,35 @@ class LanesView(_GetchModes): lane.last_line_at = self._now() lane.progress = None lane.progress_kind = "" + self._console_log.line( + f"--- [{lane.title}] {event.get('title') or ''} ---") elif kind == "line": self._ingest_lane_line(lane, event.get("text") or "") elif kind == "step_done": - lane.results[event["index"]] = event.get("rc") or 0 + index = event["index"] + rc = event.get("rc") or 0 + lane.results[index] = rc lane.current = None lane.last_line_at = None lane.progress = None lane.progress_kind = "" + self._console_log.line( + f"[{'OK' if rc == 0 else 'FAIL'}] [{lane.title}] " + f"{lane.steps[index].title} (exit {rc})") elif kind == "step_cancelled": - lane.cancelled_step = event["index"] + index = event["index"] + lane.cancelled_step = index lane.current = None lane.last_line_at = None lane.progress = None lane.progress_kind = "" + self._console_log.line( + f"[x] [{lane.title}] {lane.steps[index].title} (cancelled)") elif kind == "lane_finish": lane.rc = event.get("rc") or 0 lane.finished = True + self._console_log.line( + f"=== [{lane.title}] finished (exit {lane.rc}) ===") def _ingest_lane_line(self, lane: _LaneState, text: str) -> None: """Fold one output line into LANE's log tail and progress bar.""" @@ -736,8 +813,9 @@ class LanesView(_GetchModes): if kind == "bytes": return lane.log_tail.append(line) - if len(lane.log_tail) > _LOG_TAIL: - del lane.log_tail[: len(lane.log_tail) - _LOG_TAIL] + if len(lane.log_tail) > _LOG_KEEP: + del lane.log_tail[: len(lane.log_tail) - _LOG_KEEP] + self._console_log.line(line) def _drain(self) -> None: for lane in self._lanes: @@ -762,6 +840,7 @@ class LanesView(_GetchModes): self.phase = "error" break self.finished_at = self._now() + self._console_log.line(f"=== {self.phase} ===") def _now(self) -> float: return self._clock() @@ -814,6 +893,7 @@ class LanesView(_GetchModes): # must not make later hub dialogs dismiss themselves. self._blocking() finally: + self._console_log.close() sys.stdout, sys.stderr = saved_out, saved_err def _get_key(self) -> Optional[int]: @@ -935,7 +1015,7 @@ class LanesView(_GetchModes): theme["accent"]) row += 1 - for line in lane.log_tail[-_LOG_TAIL:]: + for line in lane.log_tail: if row >= y + h - 1: break _text(scr, theme, row, x + 1, _fit(line, w - 3), theme["dim"]) diff --git a/audiobook.py b/audiobook.py index 7bdd989..0d0f5d7 100755 --- a/audiobook.py +++ b/audiobook.py @@ -36,6 +36,9 @@ sys.path.insert(0, str(APP_DIR)) # runs only when audiobook.py is executed as a script, from main() below. from backends import envs as _envs # noqa: I001 +# app/logs owner: naming conventions and startup pruning (stdlib-only). +import logging_kit # noqa: I001 + from converter import config from converter import converter as _converter_mod from converter.clients import ( @@ -198,6 +201,9 @@ def main() -> None: # requirements.txt) first if needed. A no-op when already there. Done # here rather than at import time so importing this module is light. _envs.bootstrap(__file__) + # Trim stale stream/artifact logs once per app start (server logs are + # never touched); see app/logging_kit.py. + logging_kit.prune_logs() # No arguments + interactive terminal -> the TUI hub (set up backends # and process the input directory end-to-end). Anything else is the # scriptable argparse CLI. -- cgit v1.2.3