add debug info

sentence_api/.env.example

@@ -9,6 +9,7 @@ MAX_VIDEO_UPLOAD_BYTES=12884901888
 MAX_ATTEMPT_UPLOAD_BYTES=52428800
 KEEP_ATTEMPT_AUDIO=false
 ASSESSMENT_PASS_SCORE=70
+LOG_LEVEL=INFO
 
 MOSS_TRANSCRIBE_URL=http://127.0.0.1:8001/v1/audio/transcriptions
 MOSS_MODEL=OpenMOSS-Team/MOSS-Transcribe-Diarize

sentence_api/config.py

@@ -26,6 +26,7 @@ class Settings:
     moss_timeout_seconds: float
     moss_max_new_tokens: int
     moss_end_padding_ms: int
+    log_level: str
     ai_api_url: str
     ai_api_key: str
     ai_model: str
@@ -65,6 +66,7 @@ class Settings:
             moss_timeout_seconds=float(os.getenv("MOSS_TIMEOUT_SECONDS", "1800")),
             moss_max_new_tokens=int(os.getenv("MOSS_MAX_NEW_TOKENS", "65536")),
             moss_end_padding_ms=int(os.getenv("MOSS_END_PADDING_MS", "300")),
+            log_level=os.getenv("LOG_LEVEL", "INFO").strip().upper() or "INFO",
             ai_api_url=os.getenv("AI_API_URL", "").strip().rstrip("/"),
             ai_api_key=os.getenv("AI_API_KEY", "").strip(),
             ai_model=os.getenv("AI_MODEL", "gpt-4o-mini"),

sentence_api/main.py

@@ -99,6 +99,10 @@ def create_app(
     oss_uploader: Optional[VolcanoOSSUploader] = None,
 ) -> FastAPI:
     service_settings = settings or Settings.from_env()
+    logging.basicConfig(
+        level=getattr(logging, service_settings.log_level, logging.INFO),
+        format="%(asctime)s %(levelname)s %(name)s %(message)s",
+    )
     service_settings.ensure_directories()
     video_repository = repository or VideoRepository(service_settings.database_path)
     legacy_store = store or BoundaryStore(service_settings.legacy_boundaries_file)

sentence_api/processing.py

@@ -200,15 +200,50 @@ class VideoProcessor:
         gaps = find_sentence_gaps(document, min_gap_ms)
         inserted: List[SentenceBoundary] = []
         transcribed_gaps = 0
+        logger.info(
+            "Gap repair started: video=%s min_gap_ms=%d language=%s gaps=%d "
+            "sentences=%d duration_ms=%d transcriber=%s",
+            video_hash,
+            min_gap_ms,
+            video.get("language") or "auto",
+            len(gaps),
+            len(document.sentences),
+            document.duration_ms,
+            type(self.transcriber).__name__,
+        )
         if gaps:
             language = video.get("language")
             with tempfile.TemporaryDirectory(prefix="gap-repair-") as temp_dir:
                 for gap_index, (raw_start, raw_end) in enumerate(gaps):
+                    logger.info(
+                        "Gap %d/%d: raw=%d-%dms duration=%dms",
+                        gap_index + 1,
+                        len(gaps),
+                        raw_start,
+                        raw_end,
+                        raw_end - raw_start,
+                    )
                     clipped = _inset_gap(raw_start, raw_end, document.duration_ms)
                     if clipped is None:
+                        logger.warning(
+                            "Gap %d/%d skipped after inset: raw=%d-%dms",
+                            gap_index + 1,
+                            len(gaps),
+                            raw_start,
+                            raw_end,
+                        )
                         continue
                     start_ms, end_ms = clipped
                     chunk_path = Path(temp_dir) / f"gap-{gap_index}.wav"
+                    logger.info(
+                        "Gap %d/%d extracted range=%d-%dms duration=%dms file=%s",
+                        gap_index + 1,
+                        len(gaps),
+                        start_ms,
+                        end_ms,
+                        end_ms - start_ms,
+                        chunk_path,
+                    )
                     try:
                         extract_audio_segment(
                             media_path,
@@ -219,14 +254,33 @@ class VideoProcessor:
                         samples, sample_rate = decode_audio_mono(chunk_path)
                         metrics = analyze_samples(samples, sample_rate)
                     except (AudioAnalysisError, RuntimeError) as exc:
-                        logger.info(
+                        logger.warning(
                             "Skipping sentence gap %s-%sms: %s",
                             start_ms,
                             end_ms,
                             exc,
+                            exc_info=True,
                         )
                         continue
+                    logger.info(
+                        "Gap %d/%d audio metrics: duration_ms=%d speech_duration_ms=%d "
+                        "internal_silence_ms=%d pause_ratio=%.3f threshold_ms=%d",
+                        gap_index + 1,
+                        len(gaps),
+                        metrics.recording_duration_ms,
+                        metrics.speech_duration_ms,
+                        metrics.internal_silence_ms,
+                        metrics.internal_pause_ratio,
+                        GAP_REPAIR_MIN_SPEECH_MS,
+                    )
                     if metrics.speech_duration_ms < GAP_REPAIR_MIN_SPEECH_MS:
+                        logger.warning(
+                            "Gap %d/%d skipped as silence: speech_duration_ms=%d < %d",
+                            gap_index + 1,
+                            len(gaps),
+                            metrics.speech_duration_ms,
+                            GAP_REPAIR_MIN_SPEECH_MS,
+                        )
                         continue
                     try:
                         transcript = self.transcriber.transcribe(chunk_path, language)
@@ -237,8 +291,16 @@ class VideoProcessor:
                             start_ms,
                             end_ms,
                             exc,
+                            exc_info=True,
                         )
                         continue
+                    logger.info(
+                        "Gap %d/%d transcript returned: segments=%d text=%r",
+                        gap_index + 1,
+                        len(gaps),
+                        len(transcript.segments),
+                        transcript.text,
+                    )
                     gap_document = document_from_transcript(
                         video_hash=video_hash,
                         duration_ms=end_ms - start_ms,
@@ -252,12 +314,45 @@ class VideoProcessor:
                         offset_ms=start_ms,
                         limit_end_ms=end_ms,
                     )
+                    if not shifted:
+                        logger.warning(
+                            "Gap %d/%d produced no insertable sentences: "
+                            "transcript_segments=%d boundary_sentences=%d range=%d-%dms",
+                            gap_index + 1,
+                            len(gaps),
+                            len(transcript.segments),
+                            len(gap_document.sentences),
+                            start_ms,
+                            end_ms,
+                        )
+                        for boundary in gap_document.sentences:
+                            logger.warning(
+                                "Candidate boundary before shift: start=%d end=%d text=%r",
+                                boundary.start_ms,
+                                boundary.end_ms,
+                                boundary.text,
+                            )
                     if not shifted:
                         continue
                     transcribed_gaps += 1
                     inserted.extend(shifted)
+                    logger.info(
+                        "Gap %d/%d produced %d insertable sentences: range=%d-%dms",
+                        gap_index + 1,
+                        len(gaps),
+                        len(shifted),
+                        start_ms,
+                        end_ms,
+                    )
 
         if not inserted:
+            logger.warning(
+                "Gap repair finished without inserts: video=%s gaps=%d "
+                "transcribed_gaps=%d inserted=0",
+                video_hash,
+                len(gaps),
+                transcribed_gaps,
+            )
             return {
                 "min_gap_ms": min_gap_ms,
                 "gap_count": len(gaps),
@@ -269,6 +364,16 @@ class VideoProcessor:
         merged = _merge_sentence_lists(document.sentences, inserted)
         updated = document.model_copy(update={"sentences": merged})
         saved = self.repository.replace_sentences(updated)
+        logger.info(
+            "Gap repair finished: video=%s gaps=%d transcribed_gaps=%d inserted=%d "
+            "sentences=%d->%d",
+            video_hash,
+            len(gaps),
+            transcribed_gaps,
+            len(saved.sentences) - len(document.sentences),
+            len(document.sentences),
+            len(saved.sentences),
+        )
         return {
             "min_gap_ms": min_gap_ms,
             "gap_count": len(gaps),

sentence_api/transcription.py

@@ -1,4 +1,5 @@
 import io
+import logging
 import mimetypes
 import re
 import wave
@@ -12,6 +13,9 @@ import numpy as np
 from .audio_metrics import AudioAnalysisError, decode_audio_mono, speech_frame_mask
 
 
+logger = logging.getLogger(__name__)
+
+
 # Whisper was trained on 30-second clips. Sending longer audio in a single request
 # makes the model enter a repetition loop (every later segment becomes the same
 # sentence while timestamps keep advancing), so long audio is split into short
@@ -93,12 +97,44 @@ class MossTranscriber:
         self, audio_path: Path, language: Optional[str]
     ) -> Transcript:
         content_type = mimetypes.guess_type(audio_path.name)[0] or "application/octet-stream"
+        logger.info(
+            "Transcription request: endpoint=%s model=%s audio=%s language=%s",
+            self.endpoint,
+            self.model,
+            audio_path.name,
+            language or "auto",
+        )
         with audio_path.open("rb") as audio_file:
             payload = self._post_audio(audio_file, audio_path.name, content_type, language)
         raw_text = str(payload.get("text") or "").strip()
+        raw_segments = payload.get("segments")
         segments = _parse_json_segments(payload.get("segments"))
+        logger.info(
+            "Transcription response: audio=%s raw_text_chars=%d raw_segments=%s "
+            "parsed_segments=%d text=%r",
+            audio_path.name,
+            len(raw_text),
+            len(raw_segments) if isinstance(raw_segments, list) else "missing",
+            len(segments),
+            _log_text_preview(raw_text),
+        )
         if not segments:
             segments = _parse_compact_segments(raw_text)
+            if segments:
+                logger.info(
+                    "Recovered %d compact-format segments from response text: audio=%s",
+                    len(segments),
+                    audio_path.name,
+                )
+        if not segments:
+            logger.warning(
+                "Transcription returned no usable timestamped segments: audio=%s "
+                "payload_keys=%s raw_segments=%s text=%r",
+                audio_path.name,
+                sorted(payload.keys()),
+                _log_segments_preview(raw_segments),
+                _log_text_preview(raw_text, 500),
+            )
         plain_text = " ".join(segment.text for segment in segments).strip()
         plain_text = _strip_speaker_tags(plain_text) or _strip_speaker_tags(raw_text)
         return Transcript(text=plain_text, segments=segments)
@@ -117,11 +153,38 @@ class MossTranscriber:
                 "audio/wav",
                 language,
             )
+            raw_chunk_segments = payload.get("segments")
             chunk_segments = _parse_json_segments(
                 payload.get("segments"), compression_limit=COMPRESSION_RATIO_LIMIT
             )
+            logger.info(
+                "Chunk transcription response: range=%.3f-%.3fs raw_segments=%s "
+                "parsed_segments=%d text=%r",
+                start_seconds,
+                end_seconds,
+                len(raw_chunk_segments) if isinstance(raw_chunk_segments, list) else "missing",
+                len(chunk_segments),
+                _log_text_preview(str(payload.get("text") or "")),
+            )
             if not chunk_segments:
                 chunk_segments = _parse_compact_segments(str(payload.get("text") or "").strip())
+                if chunk_segments:
+                    logger.info(
+                        "Recovered %d compact-format segments from chunk text: range=%.3f-%.3fs",
+                        len(chunk_segments),
+                        start_seconds,
+                        end_seconds,
+                    )
+            if not chunk_segments:
+                logger.warning(
+                    "Chunk returned no usable timestamped segments: range=%.3f-%.3fs "
+                    "payload_keys=%s raw_segments=%s text=%r",
+                    start_seconds,
+                    end_seconds,
+                    sorted(payload.keys()),
+                    _log_segments_preview(raw_chunk_segments),
+                    _log_text_preview(str(payload.get("text") or ""), 500),
+                )
             for segment in chunk_segments:
                 words = None
                 if segment.words:
@@ -172,8 +235,20 @@ class MossTranscriber:
                 word_payload, audio_file, filename, content_type
             )
             if response.status_code in (400, 422):
+                logger.warning(
+                    "Transcription endpoint rejected word timestamps; retrying without them: "
+                    "status=%d body=%s",
+                    response.status_code,
+                    _log_text_preview(getattr(response, "text", ""), 1000),
+                )
                 audio_file.seek(0)
                 response = self._post_once(data, audio_file, filename, content_type)
+            if response.status_code >= 400:
+                logger.warning(
+                    "Transcription endpoint returned HTTP %d: body=%s",
+                    response.status_code,
+                    _log_text_preview(getattr(response, "text", ""), 2000),
+                )
             response.raise_for_status()
             return response.json()
         except (httpx.HTTPError, ValueError) as exc:
@@ -556,6 +631,30 @@ def _wav_duration_seconds(path: Path) -> Optional[float]:
     return None
 
 
+def _log_text_preview(text: str, limit: int = 240) -> str:
+    text = " ".join(text.split())
+    return text if len(text) <= limit else f"{text[:limit]}... [{len(text)} chars]"
+
+
+def _log_segments_preview(raw_segments, limit: int = 5):
+    if not isinstance(raw_segments, list):
+        return raw_segments
+    preview = []
+    for item in raw_segments[:limit]:
+        if not isinstance(item, dict):
+            preview.append(item)
+            continue
+        preview.append(
+            {
+                "start": item.get("start"),
+                "end": item.get("end"),
+                "compression_ratio": item.get("compression_ratio"),
+                "text": _log_text_preview(str(item.get("text") or "")),
+            }
+        )
+    return {"count": len(raw_segments), "items": preview}
+
+
 def _wav_bytes(samples: np.ndarray, sample_rate: int) -> bytes:
     pcm = np.clip(np.round(samples * 32767), -32768, 32767).astype("<i2")
     buffer = io.BytesIO()