From 6ba720969ef44aa2e204e15d131a491ffd21503d Mon Sep 17 00:00:00 2001
From: JayZed <jzarycky@sympatico.ca>
Date: Mon, 26 Feb 2024 06:25:10 -0500
Subject: [PATCH] Improved debug logging for whisperai

---
 bazarr/app/logger.py                         | 10 +++++-----
 libs/subliminal_patch/providers/whisperai.py | 12 +++++++++++-
 2 files changed, 16 insertions(+), 6 deletions(-)

diff --git a/bazarr/app/logger.py b/bazarr/app/logger.py
index c9a1282bb..543939fa2 100644
--- a/bazarr/app/logger.py
+++ b/bazarr/app/logger.py
@@ -91,10 +91,10 @@ def configure_logging(debug=False):
     warnings.simplefilter('ignore', category=PytzUsageWarning)
     # warnings.simplefilter('ignore', category=SAWarning)
 
-    if not debug:
-        log_level = "INFO"
+    if debug:
+        log_level = logging.DEBUG
     else:
-        log_level = "DEBUG"
+        log_level = logging.INFO
 
     logger.handlers = []
 
@@ -106,7 +106,7 @@ def configure_logging(debug=False):
         '%(asctime)-15s - %(name)-32s (%(thread)x) :  %(levelname)s (%(module)s:%(lineno)d) - %(message)s')
     ch.setFormatter(cf)
 
-    ch.setLevel(log_level)
+    ch.setLevel(logging.DEBUG)
     logger.addHandler(ch)
 
     # File Logging
@@ -120,7 +120,7 @@ def configure_logging(debug=False):
     f = FileHandlerFormatter('%(asctime)s|%(levelname)-8s|%(name)-32s|%(message)s|',
                              '%Y-%m-%d %H:%M:%S')
     fh.setFormatter(f)
-    fh.setLevel(log_level)
+    fh.setLevel(logging.DEBUG)
     logger.addHandler(fh)
 
     if debug:
diff --git a/libs/subliminal_patch/providers/whisperai.py b/libs/subliminal_patch/providers/whisperai.py
index 33421f201..1d47057e6 100644
--- a/libs/subliminal_patch/providers/whisperai.py
+++ b/libs/subliminal_patch/providers/whisperai.py
@@ -299,7 +299,7 @@ class WhisperAIProvider(Provider):
             
         # tell the user what we are about to do
         sub.release_info = f"{sub.task} {language_from_alpha3(sub.audio_language)} audio -> {language_from_alpha3(language.alpha3)} SRT"
-        logger.debug(f"Whisper ({video.original_path}): {sub.audio_language} -> {language.alpha3} [TASK: {sub.task}]")
+        logger.debug(f"Whisper query: ({video.original_path}): {sub.audio_language} -> {language.alpha3} [TASK: {sub.task}]")
 
         return sub
 
@@ -319,6 +319,8 @@ class WhisperAIProvider(Provider):
             subtitle.content = None
             return         
 
+        logger.debug(f'Audio stream length (in WAV format) is {len(out):,} bytes')
+
         if subtitle.task == "transcribe":
             output_language = subtitle.audio_language
         else:
@@ -334,6 +336,14 @@ class WhisperAIProvider(Provider):
                               
         endTime = time.time()
         elapsedTime = timedelta(seconds=round(endTime - startTime))
+
+        # for debugging, log if anything got returned
+        subtitle_length = len(r.content)
+        logger.debug(f'Returned subtitle length is {subtitle_length:,} bytes')
+        subtitle_length = min(subtitle_length, 1000)
+        if subtitle_length > 0:
+            logger.debug(f'First {subtitle_length} bytes of subtitle: {r.content[0:subtitle_length]}')
+
         logger.info(f'Completed WhisperAI {subtitle.task} to {language_from_alpha3(output_language)} in {elapsedTime} for {subtitle.video.original_path}')
 
         subtitle.content = r.content