Add session logging and tuned runtime preset

history.md

@@ -203,3 +203,14 @@ The project now features a high-performance, Apple Silicon-optimized pipeline th
     - Routed post-correct and merge-decider requests through a shared Ollama caller with keep-alive support.
     - Added flags for warmup timeout and optional warmup skip for troubleshooting.
 - **Outcome:** Lower first-request latency and fewer fallback-to-rules events due to local model cold starts.
+
+## Phase 25: Session Logging + Tuned Live Preset
+- **Goal:** Preserve reliable debugging context while locking in the best-performing live settings discovered through manual testing.
+- **Approach:**
+    - Added session file logging hooks so finalized captions, revisions, startup state, and runtime errors can be written to a dedicated log via `--session-log-file`.
+    - Improved interactive terminal behavior by clearing stale draft lines cleanly and right-aligning Arabic output more consistently against terminal width.
+    - Recorded the current preferred live preset for English-first filtered transcription with multilingual output and local LLM post-correction:
+    ```bash
+    python3 transcribe.py --silence 100 -q -s -c -es -en -fr -ar --lang en --filter-lang --mt-max-chars 450 --mt-max-new-tokens 220 --smart-correct --post-correct --post-correct-llm --post-correct-model qwen2.5:3b-instruct --session-log-file debug_session_1.log
+    ```
+- **Outcome:** The project now has a repeatable "known good" runtime profile plus persistent session diagnostics for reviewing caption issues after a run.

transcribe.py

@@ -2,6 +2,8 @@ import sys
 import time
 import re
 import os
+import shutil
+from datetime import datetime
 import requests
 import threading
 import json
@@ -33,7 +35,7 @@ from silero_vad import load_silero_vad, get_speech_timestamps
 from transformers import MarianMTModel, MarianTokenizer
 
 # Parameters
-WHISPER_MODEL = "mlx-community/whisper-small-mlx" 
+WHISPER_MODEL = "mlx-community/whisper-base-mlx" 
 INGEST_URL = "https://emiapi.reynafamily.com/live-captions/ingest"
 
 # Translation models (English -> Target)
@@ -50,6 +52,16 @@ VAD_THRESHOLD = 0.5
 
 audio_queue = queue.Queue()
 ingest_queue = queue.Queue()
+session_log_handle = None
+
+def log_session(message):
+    """Write a timestamped line to the session debug log if enabled."""
+    global session_log_handle
+    if session_log_handle is None:
+        return
+    ts = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
+    session_log_handle.write(f"{ts} {message}\n")
+    session_log_handle.flush()
 
 def parse_temperature_fallback(value):
     """Parse comma-separated temperatures into a tuple of floats."""
@@ -299,16 +311,21 @@ def call_ollama_generate(args, prompt, timeout, temperature=0.1):
 
 def post_correct_with_local_llm(text, args, llm_state, context_lines=None):
     """Optionally rewrite finalized English caption via a local Ollama model."""
-    if not args.post_correct_llm or not llm_state.get("available", True):
+    if args.post_correct_debug:
+        print(f"[POST-LLM][PRE]: {text}", flush=True)
+    if not args.post_correct_llm:
+        if args.post_correct_debug:
+            print("[POST-LLM][SKIP]: --post-correct-llm not enabled; using rules-only.", flush=True)
+        return text
+    if not llm_state.get("available", True):
+        if args.post_correct_debug:
+            print("[POST-LLM][SKIP]: LLM marked unavailable after prior failure; using rules-only.", flush=True)
         return text
 
     context_lines = context_lines or []
     prev2 = context_lines[-2] if len(context_lines) >= 2 else ""
     prev1 = context_lines[-1] if len(context_lines) >= 1 else ""
 
-    if args.post_correct_debug:
-        print(f"[POST-LLM][PRE]: {text}")
-
     prompt = (
         "You are a real-time English caption corrector for live speech.\n"
         "Task:\n"
@@ -333,27 +350,27 @@ def post_correct_with_local_llm(text, args, llm_state, context_lines=None):
         raw = response.json().get("response", "").strip()
         cleaned = normalize_english_caption(raw)
         if args.post_correct_debug:
-            print(f"[POST-LLM][RAW]: {raw}")
+            print(f"[POST-LLM][RAW]: {raw}", flush=True)
         if cleaned:
             overlap = word_overlap_ratio(text, cleaned)
             if overlap < args.post_correct_min_overlap:
                 if args.post_correct_debug:
                     print(
                         f"[POST-LLM][REJECT]: low overlap ({overlap:.2f} < {args.post_correct_min_overlap:.2f}); keeping pre text"
-                    )
+                    , flush=True)
                 return text
             if args.post_correct_debug:
-                print(f"[POST-LLM][POST]: {cleaned}")
+                print(f"[POST-LLM][POST]: {cleaned}", flush=True)
             return cleaned
         if args.post_correct_debug:
-            print("[POST-LLM][POST]: <empty response, keeping pre text>")
+            print("[POST-LLM][POST]: <empty response, keeping pre text>", flush=True)
     except Exception as exc:
         if not llm_state.get("warned", False):
             print(f"\n[SYSTEM]: Local post-correct LLM unavailable ({exc}). Falling back to rules-only.")
             llm_state["warned"] = True
         llm_state["available"] = False
         if args.post_correct_debug:
-            print(f"[POST-LLM][ERROR]: {exc}")
+            print(f"[POST-LLM][ERROR]: {exc}", flush=True)
     return text
 
 def maybe_merge_recent_caption(recent_en_lines, current_text, now_ts, window_sec):
@@ -447,8 +464,11 @@ def format_caption_lines(lang_key, text):
     key = lang_key.lower()
     if key == "ar":
         cleaned = normalize_arabic_punctuation(text)
-        # Put label on separate line and force RTL embedding for the content line.
-        return ["[AR]:", f"\u202B{cleaned}\u202C"]
+        # Put label on separate line, right-align content, and force RTL embedding.
+        term_width = shutil.get_terminal_size(fallback=(100, 20)).columns
+        visible_len = len(cleaned)
+        left_pad = max(0, term_width - visible_len)
+        return ["[AR]:", f"{' ' * left_pad}\u202B{cleaned}\u202C"]
     return [f"[{lang_key.upper()}]: {text}"]
 
 def print_caption(lang_key, text, leading_newline=False):
@@ -457,6 +477,7 @@ def print_caption(lang_key, text, leading_newline=False):
         lines[0] = "\n" + lines[0]
     for line in lines:
         print(line)
+        log_session(line.strip())
 
 def is_hallucination(text):
     """Detect common Whisper hallucinations or high repetition."""
@@ -534,7 +555,7 @@ def warmup_ollama_model(args):
         print(f"[SYSTEM]: Ollama warmup failed ({exc}). Continuing; runtime fallback will apply.")
 
 def main():
-    global WHISPER_MODEL
+    global WHISPER_MODEL, session_log_handle
     parser = argparse.ArgumentParser(description="Live transcription and translation with Whisper.")
     parser.add_argument("-es", action="store_true", help="Enable Spanish translation")
     parser.add_argument("-en", action="store_true", help="Enable English (detected or bridged)")
@@ -587,35 +608,57 @@ def main():
     parser.add_argument("--speaker-sim-threshold", type=float, default=0.72, help="Cosine similarity threshold below which a speaker change is assumed (default: 0.72)")
     parser.add_argument("--speaker-min-buffer", type=float, default=1.6, help="Minimum buffered speech seconds before speaker-change checks (default: 1.6)")
     parser.add_argument("--speaker-check-interval", type=float, default=0.6, help="Seconds between speaker-change checks while buffering (default: 0.6)")
+    parser.add_argument("--session-log-file", type=str, default="transcribe_session.log", help="Path to session debug log file (default: transcribe_session.log)")
+    parser.add_argument("--disable-session-log", action="store_true", help="Disable writing session debug logs to file")
     
     args = parser.parse_args()
+    if not args.disable_session_log:
+        session_log_handle = open(args.session_log_file, "a", encoding="utf-8")
+        log_session("=" * 72)
+        log_session("SESSION_START")
+        log_session(f"ARGS {json.dumps(vars(args), sort_keys=True)}")
+        print(f"Session logging to: {args.session_log_file}")
     if args.post_correct_llm and not args.post_correct:
         args.post_correct = True
         print("[SYSTEM]: Enabling --post-correct because --post-correct-llm was requested.")
+        log_session("[SYSTEM]: Enabling --post-correct because --post-correct-llm was requested.")
     file_glossary_pairs = load_glossary_file(args.glossary_file)
     merged_glossary_pairs = file_glossary_pairs + args.glossary_pair
     if file_glossary_pairs:
         print(f"Loaded {len(file_glossary_pairs)} glossary terms from {args.glossary_file}")
+        log_session(f"Loaded {len(file_glossary_pairs)} glossary terms from {args.glossary_file}")
     if args.post_correct:
         print("Post-correct mode: rules enabled.")
+        log_session("Post-correct mode: rules enabled.")
     if args.post_correct_llm:
         print(
             f"Post-correct LLM: {args.post_correct_model} via {args.post_correct_ollama_url} "
             f"(keep_alive={args.post_correct_keep_alive})"
         )
+        log_session(
+            f"Post-correct LLM: {args.post_correct_model} via {args.post_correct_ollama_url} "
+            f"(keep_alive={args.post_correct_keep_alive})"
+        )
     if args.post_correct_debug:
         print("Post-correct debug logging enabled.")
+        log_session("Post-correct debug logging enabled.")
     if args.llm_merge_decider and not args.post_correct_llm:
         print("[SYSTEM]: --llm-merge-decider requires --post-correct-llm. Falling back to heuristic merge.")
         args.llm_merge_decider = False
+        log_session("[SYSTEM]: --llm-merge-decider requires --post-correct-llm. Falling back to heuristic merge.")
     if args.speaker_change_detect:
         print(
             "Speaker-change detection enabled "
             f"(threshold={args.speaker_sim_threshold}, min_buffer={args.speaker_min_buffer}s)."
         )
+        log_session(
+            "Speaker-change detection enabled "
+            f"(threshold={args.speaker_sim_threshold}, min_buffer={args.speaker_min_buffer}s)."
+        )
 
     if args.quantize:
         WHISPER_MODEL = "mlx-community/whisper-small-mlx-4bit"
+        log_session("Using quantized Whisper model variant.")
 
     if args.list_devices:
         print("\nAvailable Audio Devices:")
@@ -625,6 +668,7 @@ def main():
     buffer_limit = SAMPLERATE * args.max_buffer
     device = "mps" if torch.backends.mps.is_available() else "cpu"
     print(f"Using device: {device}")
+    log_session(f"Using device: {device}")
 
     # Only start ingest thread if enabled
     if args.ingest:
@@ -688,6 +732,7 @@ def main():
         print("Using system default input device.")
 
     print(f"\nStarting live transcription{' & server ingest' if args.ingest else ''}... (Press Ctrl+C to stop)")
+    log_session(f"Starting live transcription (ingest={args.ingest}).")
     
     audio_buffer = []
     speech_started = False
@@ -696,6 +741,7 @@ def main():
     rolling_context = ""
     rolling_context_en = ""
     last_draft_text = ""
+    draft_line_active = False
     recent_en_lines = deque(maxlen=2)
     llm_post_correct_state = {"available": True, "warned": False, "merge_warned": False}
     speaker_reference_signature = None
@@ -781,6 +827,7 @@ def main():
                             if args.stream:
                                 sys.stdout.write("\r\033[K")
                                 sys.stdout.flush()
+                                draft_line_active = False
 
                             # Prepare transcription kwargs
                             transcribe_kwargs = {"path_or_hf_repo": WHISPER_MODEL}
@@ -901,6 +948,7 @@ def main():
                                         if merge_ok:
                                             english_for_caption = merge_text
                                             print(f"[EN-REV]: {old_line} -> {english_for_caption}")
+                                            log_session(f"[EN-REV]: {old_line} -> {english_for_caption}")
                                         else:
                                             if recent_en_lines:
                                                 recent_en_lines[-1]["text"] = old_line
@@ -912,6 +960,7 @@ def main():
                                 if args.en and english_for_caption:
                                     payload["en"] = english_for_caption
                                     print(f"[EN]: {english_for_caption}")
+                                    log_session(f"[EN]: {english_for_caption}")
 
                                 # Update rolling context for next segment
                                 if args.context:
@@ -959,6 +1008,7 @@ def main():
                             stuck_draft_count = 0
                             last_draft_text = ""
                             speaker_reference_signature = None
+                            draft_line_active = False
 
                         elif args.stream and (time.time() - last_stream_time) > 1.0:
                             # Draft transcription
@@ -981,13 +1031,17 @@ def main():
                                 if draft_text != last_draft_text:
                                     last_change_time = time.time()
                                     last_draft_text = draft_text
-
-                                sys.stdout.write(f"\r\033[K[DRAFT]: {draft_text}")
-                                sys.stdout.flush()
+                                    if not draft_line_active:
+                                        # Reserve one blank line before the rolling draft line.
+                                        sys.stdout.write("\n")
+                                        draft_line_active = True
+                                    sys.stdout.write(f"\r\033[K[DRAFT]: {draft_text}")
+                                    sys.stdout.flush()
                                 
                                 # Send draft to ingest if enabled
                                 if args.ingest:
                                     ingest_queue.put({"draft": draft_text})
+                                    log_session("[DRAFT]: queued draft ingest payload")
                             else:
                                 # If Whisper returns empty, check if we've been silent for too long
                                 # even though VAD says there is speech.
@@ -1003,6 +1057,7 @@ def main():
                                     last_draft_text = ""
                                     sys.stdout.write("\r\033[K")
                                     sys.stdout.flush()
+                                    draft_line_active = False
                                     continue
                                     
                             last_stream_time = time.time()
@@ -1013,8 +1068,15 @@ def main():
 
     except KeyboardInterrupt:
         print("\nStopped by user.")
+        log_session("Stopped by user.")
     except Exception as e:
         print(f"\nError: {e}")
+        log_session(f"Error: {e}")
+    finally:
+        if session_log_handle is not None:
+            log_session("SESSION_END")
+            session_log_handle.close()
+            session_log_handle = None
 
 if __name__ == "__main__":
     import multiprocessing