From 5428c42ffdba8f833e8528b0c84ad545f5e6e2ef Mon Sep 17 00:00:00 2001 From: Shuming Liu Date: Sun, 25 Oct 2026 11:31:32 +0800 Subject: [PATCH] add debug info --- sentence_api/.env.example | 1 + sentence_api/config.py | 2 + sentence_api/main.py | 4 ++ sentence_api/processing.py | 107 +++++++++++++++++++++++++++++++++- sentence_api/transcription.py | 99 +++++++++++++++++++++++++++++++ 5 files changed, 212 insertions(+), 1 deletion(-) diff --git a/sentence_api/.env.example b/sentence_api/.env.example index bec45eb..612dc25 100644 --- a/sentence_api/.env.example +++ b/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 diff --git a/sentence_api/config.py b/sentence_api/config.py index 0a7b5fe..73ffc65 100644 --- a/sentence_api/config.py +++ b/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"), diff --git a/sentence_api/main.py b/sentence_api/main.py index b6bec6f..42c476d 100644 --- a/sentence_api/main.py +++ b/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) diff --git a/sentence_api/processing.py b/sentence_api/processing.py index a70a58a..4a6fb0e 100644 --- a/sentence_api/processing.py +++ b/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), diff --git a/sentence_api/transcription.py b/sentence_api/transcription.py index ef95a57..bda7027 100644 --- a/sentence_api/transcription.py +++ b/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("