From f1f8e899c46de80d7f9fbb8f0b53983e18167bd2 Mon Sep 17 00:00:00 2001 From: historia Date: Wed, 19 Aug 2026 03:32:06 -0400 Subject: fix: reduce excessive logging --- converter/audio.py | 3 -- converter/converter.py | 42 ++++++++++++++--------- converter/tts.py | 26 +++++++++----- tests/test_converter.py | 90 ++++++++++++++++++++++++++++++++++++++++++++++++- 4 files changed, 133 insertions(+), 28 deletions(-) diff --git a/converter/audio.py b/converter/audio.py index 4fd1721..c9feeb8 100644 --- a/converter/audio.py +++ b/converter/audio.py @@ -359,9 +359,6 @@ def combine_chunks(total_chunks: int, output_path: Path, logger.info("Saved speed-adjusted audiobook (%gx): %s", speed, speed_path) print(f"[INFO] Saved speed-adjusted audiobook: {speed_path.name} ({speed:g}x)") - if missing_chunks: - print(f"[WARNING] Missing chunks: {missing_chunks}") - return True except FileNotFoundError: diff --git a/converter/converter.py b/converter/converter.py index 3e5d628..30418e5 100644 --- a/converter/converter.py +++ b/converter/converter.py @@ -19,19 +19,32 @@ from .tts import FasterTTSClient, QwenTTSClient, normalize_language, speaker_dis logger = logging.getLogger(__name__) +def _console_log_filter(record: logging.LogRecord) -> bool: + """Keep httpx/httpcore request logs out of the console (file only).""" + return not record.name.startswith(("httpx", "httpcore")) + + def setup_logging(debug: bool = False) -> None: - """Configure logging to both a dated file and the console.""" + """Configure logging to a dated file and the console. + + The file keeps the full record (DEBUG with --debug), including httpx + request logs. The console handler only surfaces warnings and errors + (DEBUG with --debug) so progress prints are never mirrored as + timestamped log lines; httpx/httpcore request logs stay file-only. + """ config.LOGS_FOLDER.mkdir(parents=True, exist_ok=True) + file_handler = logging.FileHandler( + config.LOGS_FOLDER / f"audiobook_{datetime.now():%Y%m%d}.log", + encoding="utf-8", + ) + file_handler.setLevel(logging.DEBUG if debug else logging.INFO) + console_handler = logging.StreamHandler(sys.stdout) + console_handler.setLevel(logging.DEBUG if debug else logging.WARNING) + console_handler.addFilter(_console_log_filter) logging.basicConfig( level=logging.INFO, format="%(asctime)s - %(levelname)s - %(message)s", - handlers=[ - logging.FileHandler( - config.LOGS_FOLDER / f"audiobook_{datetime.now():%Y%m%d}.log", - encoding="utf-8", - ), - logging.StreamHandler(sys.stdout), - ], + handlers=[file_handler, console_handler], ) if debug: logging.getLogger("converter").setLevel(logging.DEBUG) @@ -323,7 +336,6 @@ class AudiobookConverter: duration = time.time() - start_time logger.info("Conversion completed in %dm %ds: %s", int(duration // 60), int(duration % 60), output_path) - print(f"[SUCCESS] Conversion completed in {int(duration // 60)}m {int(duration % 60)}s") return True def _synthesize_chunks(self, chunks: List[str], @@ -362,20 +374,18 @@ class AudiobookConverter: print(f"[OK] Chunk {chunk_num:3d}/{total_chunks} completed") logger.info("+ Chunk %d/%d completed", chunk_num, total_chunks) else: - print(f"[FAIL] Chunk {chunk_num:3d}/{total_chunks} FAILED") - logger.error("- Chunk %d/%d failed", chunk_num, total_chunks) + logger.error("Chunk %d/%d failed", chunk_num, total_chunks) except Exception as exc: results[chunk_num] = None - print(f"[ERROR] Chunk {chunk_num:3d}/{total_chunks} ERROR: {exc}") - logger.error("- Chunk %d/%d error: %s", chunk_num, total_chunks, exc) + logger.error("Chunk %d/%d error: %s", chunk_num, total_chunks, exc) successful_chunks = sum(1 for path in results.values() if path) print(f"\n{'=' * 50}") print("CHUNK PROCESSING COMPLETE") print(f"Successful: {successful_chunks}/{total_chunks}") print(f"{'=' * 50}") - logger.info("Qwen processing completed: %d/%d chunks", successful_chunks, total_chunks) + logger.info("Chunk processing completed: %d/%d chunks", successful_chunks, total_chunks) return results def _convert_text(self, text: str, output_path: Path, start_time: float, @@ -415,7 +425,8 @@ class AudiobookConverter: chunk_sizes = [len(chunk.split()) for chunk in chunks] avg_chunk_size = sum(chunk_sizes) / len(chunk_sizes) logger.info("Split into %d chunks (avg %.0f words per chunk)", total_chunks, avg_chunk_size) - print(f"[INFO] Processing {total_chunks} chunks via Qwen API...") + backend = "faster TTS API" if self.faster else "Qwen API" + print(f"[INFO] Processing {total_chunks} chunks via {backend}...") results = self._synthesize_chunks(chunks, debug_dir=debug_dir) successful_chunks = sum(1 for path in results.values() if path) @@ -446,7 +457,6 @@ class AudiobookConverter: f"({successful_chunks}/{total_chunks} chunks)") else: logger.info("Conversion completed in %dm %ds: %s", minutes, seconds, output_path) - print(f"[SUCCESS] Conversion completed in {minutes}m {seconds}s") else: logger.error("Failed to combine chunks into final audiobook") diff --git a/converter/tts.py b/converter/tts.py index 1f5606f..07cfa65 100644 --- a/converter/tts.py +++ b/converter/tts.py @@ -222,26 +222,36 @@ class QwenTTSClient(_BaseTTSClient): print(f"[OK] Reference text:\n{self.voice_clone_ref_text}") def _init_client(self, url: str, clone: bool = False) -> None: - """Initialize a Gradio client and store its API metadata.""" + """Initialize a Gradio client and store its API metadata. + + gradio_client prints its usage info directly to stdout while the + client is created and its API metadata loaded, so stdout is swapped + for a buffer for the whole process; the captured text is re-emitted + at DEBUG level for troubleshooting. + """ from gradio_client import Client logger.info("Connecting to Qwen API at %s...", url) old_stdout = sys.stdout - sys.stdout = io.TextIOWrapper(io.BytesIO(), encoding="utf-8", errors="replace") + captured = io.StringIO() + sys.stdout = captured try: try: client = Client(url, httpx_kwargs={"timeout": config.API_TIMEOUT}) except TypeError: # Older gradio_client versions don't support httpx_kwargs. client = Client(url) + if clone: + self.clone_client = client + self.clone_api_info = self._load_api_info(client) + else: + self.client = client + self.api_info = self._load_api_info(client) finally: sys.stdout = old_stdout - if clone: - self.clone_client = client - self.clone_api_info = self._load_api_info(client) - else: - self.client = client - self.api_info = self._load_api_info(client) + usage_info = captured.getvalue().strip() + if usage_info: + logger.debug("Gradio client output for %s:\n%s", url, usage_info) logger.info("Connected to Qwen API") @staticmethod diff --git a/tests/test_converter.py b/tests/test_converter.py index 707688e..a79ae58 100644 --- a/tests/test_converter.py +++ b/tests/test_converter.py @@ -1,12 +1,18 @@ """Tests for the audiobook converter orchestration helpers.""" +import logging import tempfile import unittest from pathlib import Path from unittest.mock import MagicMock, patch from converter import config -from converter.converter import AudiobookConverter, find_existing_outputs, prompt_overwrite +from converter.converter import ( + AudiobookConverter, + find_existing_outputs, + prompt_overwrite, + setup_logging, +) class SanitizeFilenameTests(unittest.TestCase): @@ -248,6 +254,88 @@ class DebugDumpTests(unittest.TestCase): self.assertTrue(AudiobookConverter(debug=True).debug) +class SetupLoggingTests(unittest.TestCase): + """Console handler stays quiet; the log file keeps the full record.""" + + def setUp(self): + self._tmp = tempfile.TemporaryDirectory() + self._logs_folder = patch.object(config, "LOGS_FOLDER", Path(self._tmp.name)) + self._logs_folder.start() + self._root = logging.getLogger() + self._saved_handlers = self._root.handlers[:] + self._saved_level = self._root.level + self._saved_converter_level = logging.getLogger("converter").level + self._root.handlers.clear() + + def tearDown(self): + for handler in self._root.handlers: + if handler not in self._saved_handlers: + handler.close() + self._root.handlers[:] = self._saved_handlers + self._root.setLevel(self._saved_level) + logging.getLogger("converter").setLevel(self._saved_converter_level) + self._logs_folder.stop() + self._tmp.cleanup() + + def _console_handler(self): + matches = [h for h in logging.getLogger().handlers + if isinstance(h, logging.StreamHandler) + and not isinstance(h, logging.FileHandler)] + self.assertEqual(len(matches), 1) + return matches[0] + + def _file_handler(self): + matches = [h for h in logging.getLogger().handlers + if isinstance(h, logging.FileHandler)] + self.assertEqual(len(matches), 1) + return matches[0] + + def test_console_quiet_and_file_verbose_by_default(self): + setup_logging() + self.assertEqual(self._console_handler().level, logging.WARNING) + self.assertEqual(self._file_handler().level, logging.INFO) + + def test_debug_flag_lowers_both_handlers(self): + setup_logging(debug=True) + self.assertEqual(self._console_handler().level, logging.DEBUG) + self.assertEqual(self._file_handler().level, logging.DEBUG) + + def test_http_logs_filtered_from_console_only(self): + setup_logging(debug=True) + console = self._console_handler() + http_record = logging.LogRecord("httpx", logging.INFO, "httpx", 1, + "HTTP Request: GET ...", None, None) + self.assertFalse(console.filter(http_record)) + chunk_record = logging.LogRecord("converter.converter", logging.DEBUG, + "converter", 1, + "Chunk 1/1 request text", None, None) + self.assertTrue(console.filter(chunk_record)) + + +class SynthesizeChunkLoggingTests(unittest.TestCase): + """Chunk failures surface as a single ERROR record (no print echo).""" + + def setUp(self): + self.converter = AudiobookConverter.__new__(AudiobookConverter) + self.converter.tts = MagicMock() + + def test_failed_chunk_logs_single_error(self): + self.converter.tts.process_chunk_with_retry.return_value = None + with self.assertLogs("converter.converter", level="ERROR") as logs: + results = self.converter._synthesize_chunks(["Hello."]) + self.assertEqual(results, {1: None}) + self.assertEqual(len(logs.output), 1) + self.assertIn("Chunk 1/1 failed", logs.output[0]) + + def test_raising_chunk_logs_single_error(self): + self.converter.tts.process_chunk_with_retry.side_effect = RuntimeError("boom") + with self.assertLogs("converter.converter", level="ERROR") as logs: + results = self.converter._synthesize_chunks(["Hello."]) + self.assertEqual(results, {1: None}) + self.assertEqual(len(logs.output), 1) + self.assertIn("Chunk 1/1 error: boom", logs.output[0]) + + class PromptOverwriteTests(unittest.TestCase): def test_single_file_yes(self): with patch("builtins.input", return_value="y"): -- cgit v1.2.3