feat: add comprehensive logging throughout conversion pipeline

- voice_resolver: log spec resolution and cache hits
- conversion_executor: log chapter start/end, voice resolution, timing
- conversion_planner: log plan summary
- conversion_service: log entry point params and outcome
- conversion_runner: log job params and lifecycle
- form.py: log PendingJob creation
- synthesize.py: log pipeline creation and device selection
This commit is contained in:
Artem Akymenko
2026-07-29 11:05:52 +00:00
parent c706f7714a
commit d3ded8af0e
7 changed files with 57 additions and 0 deletions
+16
View File
@@ -8,6 +8,7 @@ This is Stage 6 of the conversion flow unification plan.
from __future__ import annotations from __future__ import annotations
import logging
import time import time
from contextlib import ExitStack from contextlib import ExitStack
from typing import Any, Callable, Dict, List, Optional, Set, Tuple from typing import Any, Callable, Dict, List, Optional, Set, Tuple
@@ -172,6 +173,14 @@ def execute_conversion(
result = ConversionResult(metadata=plan.metadata) result = ConversionResult(metadata=plan.metadata)
collector = MarkerCollector() collector = MarkerCollector()
logging.info(
"[executor] Starting: chapters=%d intro=%s outro=%s merge=%s",
len(plan.chapters),
bool(plan.intro and plan.intro.enabled),
bool(plan.outro and plan.outro.enabled),
request.save.merge_chapters_at_end,
)
# Determine cancellation checker # Determine cancellation checker
if check_cancelled is None: if check_cancelled is None:
check_cancelled = lambda: events.check_cancelled() check_cancelled = lambda: events.check_cancelled()
@@ -207,10 +216,12 @@ def execute_conversion(
# Resolve voices # Resolve voices
base_voice_spec = request.voice or "M1" base_voice_spec = request.voice or "M1"
logging.info("[executor] Resolving base voice: spec=%s", base_voice_spec)
base_provider, base_voice_choice, base_speed, base_steps = _resolve_voice( base_provider, base_voice_choice, base_speed, base_steps = _resolve_voice(
voice_resolver, base_voice_spec, request, voice_resolver, base_voice_spec, request,
log_callback=lambda msg: events.log(msg, level="warning"), log_callback=lambda msg: events.log(msg, level="warning"),
) )
logging.info("[executor] Base voice resolved: provider=%s voice=%s speed=%.2f", base_provider, base_voice_choice, base_speed)
# Use ExitStack for resource management # Use ExitStack for resource management
with ExitStack() as stack: with ExitStack() as stack:
@@ -290,12 +301,14 @@ def execute_conversion(
chapter_display = f"Chapter {chapter_idx}/{len(plan.chapters)}: {chapter.title}" chapter_display = f"Chapter {chapter_idx}/{len(plan.chapters)}: {chapter.title}"
events.log(f"Processing {chapter_display}") events.log(f"Processing {chapter_display}")
logging.info("[executor] Chapter %d/%d start: title=%s", chapter_idx, len(plan.chapters), chapter.title)
# Resolve chapter voice # Resolve chapter voice
chapter_provider, chapter_voice, chapter_speed, chapter_steps = _resolve_voice( chapter_provider, chapter_voice, chapter_speed, chapter_steps = _resolve_voice(
voice_resolver, chapter.voice_spec, request, voice_resolver, chapter.voice_spec, request,
log_callback=lambda msg: events.log(msg, level="warning"), log_callback=lambda msg: events.log(msg, level="warning"),
) )
logging.info("[executor] Chapter %d voice: provider=%s voice=%s speed=%.2f", chapter_idx, chapter_provider, chapter_voice, chapter_speed)
chapter_backend = pipeline_provider.get(chapter_provider, request.language, request.use_gpu) chapter_backend = pipeline_provider.get(chapter_provider, request.language, request.use_gpu)
# Record chapter start for markers # Record chapter start for markers
@@ -517,6 +530,9 @@ def execute_conversion(
# Record chapter end for markers # Record chapter end for markers
collector.on_chapter_end(stats.current_time) collector.on_chapter_end(stats.current_time)
logging.info("[executor] Chapter %d/%d done: time=%.1fs", chapter_idx, len(plan.chapters), stats.current_time)
logging.info("[executor] All chapters processed, total time=%.1fs", stats.current_time)
# Process outro # Process outro
if plan.outro and plan.outro.enabled and merge_chapters: if plan.outro and plan.outro.enabled and merge_chapters:
+8
View File
@@ -8,6 +8,7 @@ This is Stage 2 of the conversion flow unification plan.
from __future__ import annotations from __future__ import annotations
import logging
from typing import Any, Dict, List, Optional, Tuple from typing import Any, Dict, List, Optional, Tuple
from abogen.application.conversion_models import ( from abogen.application.conversion_models import (
@@ -65,6 +66,13 @@ def build_conversion_plan(request: ConversionRequest) -> ConversionPlan:
# 7. Resolve output layout # 7. Resolve output layout
output_layout = resolve_output_layout(request) output_layout = resolve_output_layout(request)
logging.info(
"[planner] Plan built: chapters=%d intro=%s outro=%s",
len(chapters),
bool(intro and intro.enabled),
bool(outro and outro.enabled),
)
return ConversionPlan( return ConversionPlan(
request=request, request=request,
metadata=metadata, metadata=metadata,
+7
View File
@@ -15,6 +15,7 @@ The service NEVER imports from PyQt or WebUI.
from __future__ import annotations from __future__ import annotations
import logging
from collections import defaultdict from collections import defaultdict
from typing import Any, Dict from typing import Any, Dict
@@ -61,6 +62,10 @@ def run_conversion(
try: try:
# Stage 0: Create voice resolver # Stage 0: Create voice resolver
events.log("Preparing conversion pipeline") events.log("Preparing conversion pipeline")
logging.info(
"[app] run_conversion: provider=%s language=%s voice=%s speed=%.2f",
request.tts_provider, request.language, request.voice, request.speed,
)
resolver = _create_voice_resolver(request, pool, voice_cache) resolver = _create_voice_resolver(request, pool, voice_cache)
# Stage 1: Prepare TTS context # Stage 1: Prepare TTS context
@@ -94,10 +99,12 @@ def run_conversion(
_finalize(request, result, plan, events) _finalize(request, result, plan, events)
events.log("Conversion complete") events.log("Conversion complete")
logging.info("[app] run_conversion completed successfully")
return result return result
except Exception as e: except Exception as e:
events.log(f"Conversion failed: {e}", level="error") events.log(f"Conversion failed: {e}", level="error")
logging.exception("[app] run_conversion failed: %s", e)
raise raise
finally: finally:
pool.dispose_all() pool.dispose_all()
+4
View File
@@ -7,6 +7,7 @@ PyQtVoiceResolver) with a single app-layer implementation.
from __future__ import annotations from __future__ import annotations
import logging
from typing import Any, Dict, Optional from typing import Any, Dict, Optional
from abogen.application.conversion_ports import ResolvedVoice, VoiceResolver from abogen.application.conversion_ports import ResolvedVoice, VoiceResolver
@@ -49,6 +50,7 @@ class AppVoiceResolver:
cache_key = f"{provider}:{resolved}" if resolved else provider cache_key = f"{provider}:{resolved}" if resolved else provider
cached = self._cache.get(cache_key) cached = self._cache.get(cache_key)
if cached is not None: if cached is not None:
logging.info("[resolver] Cache hit: spec=%s -> provider=%s resolved=%s", voice_spec, provider, resolved)
return ResolvedVoice( return ResolvedVoice(
provider=provider, provider=provider,
resolved_spec=resolved, resolved_spec=resolved,
@@ -68,6 +70,8 @@ class AppVoiceResolver:
loaded = resolved loaded = resolved
self._cache.set(cache_key, loaded) self._cache.set(cache_key, loaded)
logging.info("[resolver] Resolved: spec=%s -> provider=%s resolved=%s speed=%.2f steps=%s",
voice_spec, provider, resolved, speed, steps)
return ResolvedVoice( return ResolvedVoice(
provider=provider, provider=provider,
resolved_spec=resolved, resolved_spec=resolved,
+11
View File
@@ -15,6 +15,7 @@ Engine converts Language → its own format internally.
from __future__ import annotations from __future__ import annotations
import logging
from pathlib import Path from pathlib import Path
from typing import Any from typing import Any
@@ -48,6 +49,11 @@ def _build_request(job: Job) -> ConversionRequest:
"""Build a ConversionRequest from a WebUI Job.""" """Build a ConversionRequest from a WebUI Job."""
source_path = Path(job.stored_path) if job.stored_path else None source_path = Path(job.stored_path) if job.stored_path else None
logging.info(
"[runner] Building request: job=%s provider=%s language=%s voice=%s speed=%.2f gpu=%s",
job.id, job.tts_provider, job.language, job.voice, job.speed, job.use_gpu,
)
return ConversionRequest( return ConversionRequest(
# Source # Source
source_path=source_path, source_path=source_path,
@@ -186,6 +192,7 @@ def run_conversion_job(job: Job) -> None:
request = _build_request(job) request = _build_request(job)
events = WebUIEventsAdapter(job) events = WebUIEventsAdapter(job)
logging.info("[runner] Starting conversion: job=%s", job.id)
try: try:
result = run_conversion(request, events) result = run_conversion(request, events)
_apply_result(job, result) _apply_result(job, result)
@@ -193,10 +200,14 @@ def run_conversion_job(job: Job) -> None:
if job.status != JobStatus.CANCELLED: if job.status != JobStatus.CANCELLED:
job.progress = 1.0 job.progress = 1.0
logging.info("[runner] Conversion completed: job=%s", job.id)
except ConversionCancelled: except ConversionCancelled:
job.status = JobStatus.CANCELLED job.status = JobStatus.CANCELLED
job.add_log("Job cancelled", level="warning") job.add_log("Job cancelled", level="warning")
logging.info("[runner] Conversion cancelled: job=%s", job.id)
except Exception as exc: except Exception as exc:
job.error = str(exc) job.error = str(exc)
job.status = JobStatus.FAILED job.status = JobStatus.FAILED
job.add_log(f"Job failed: {exc}", level="error") job.add_log(f"Job failed: {exc}", level="error")
logging.exception("[runner] Conversion failed: job=%s error=%s", job.id, exc)
+6
View File
@@ -1,3 +1,4 @@
import logging
import time import time
import uuid import uuid
from typing import Any, Dict, Iterable, List, Mapping, Optional, Tuple, cast from typing import Any, Dict, Iterable, List, Mapping, Optional, Tuple, cast
@@ -794,6 +795,11 @@ def build_pending_job_from_extraction(
else: else:
normalization_overrides[key] = default_val normalization_overrides[key] = default_val
logging.info(
"[form] Creating PendingJob: language=%s voice=%s speed=%.2f provider=%s",
language, voice, speed, settings.get("tts_provider", "kokoro"),
)
pending = PendingJob( pending = PendingJob(
id=uuid.uuid4().hex, id=uuid.uuid4().hex,
original_filename=original_name, original_filename=original_name,
+5
View File
@@ -1,4 +1,5 @@
import io import io
import logging
import threading import threading
from typing import Any, Dict, Iterable, List, Mapping, Optional, Tuple from typing import Any, Dict, Iterable, List, Mapping, Optional, Tuple
import numpy as np import numpy as np
@@ -43,9 +44,11 @@ def _resolve_pipeline(language: Language, use_gpu: bool) -> Tuple[Any, bool]:
last_error: Optional[Exception] = None last_error: Optional[Exception] = None
for device in devices: for device in devices:
try: try:
logging.info("[preview] Trying device=%s for language=%s", device, language)
return get_preview_pipeline(language, device), device != "cpu" return get_preview_pipeline(language, device), device != "cpu"
except Exception as exc: except Exception as exc:
last_error = exc last_error = exc
logging.warning("[preview] Device %s failed: %s", device, exc)
raise RuntimeError("Preview pipeline is unavailable") from last_error raise RuntimeError("Preview pipeline is unavailable") from last_error
@@ -55,9 +58,11 @@ def get_preview_pipeline(language: Language, device: str) -> Any:
with _preview_pipeline_lock: with _preview_pipeline_lock:
pipeline = _preview_pipelines.get(key) pipeline = _preview_pipelines.get(key)
if pipeline is not None: if pipeline is not None:
logging.info("[preview] Using cached pipeline for %s/%s", language, device)
return pipeline return pipeline
from abogen.tts_plugin.utils import create_pipeline from abogen.tts_plugin.utils import create_pipeline
logging.info("[preview] Creating pipeline: provider=kokoro language=%s device=%s", language, device)
pipeline = create_pipeline("kokoro", language=language, device=device) pipeline = create_pipeline("kokoro", language=language, device=device)
_preview_pipelines[key] = pipeline _preview_pipelines[key] = pipeline
return pipeline return pipeline