feat: enhance logging for AI service error diagnosis

Added comprehensive logging to diagnose 'Expecting value: line 1 column 1 (char 0)' errors in AI service responses. The changes include detailed logging of AI requests/responses, cache operations, and article processing steps to better identify when the AI service returns empty or invalid responses.

ai_processor/article_processor.py

@@ -60,6 +60,7 @@ class ArticleProcessor:
                         scraper_dir = alt_path
                         break
                 else:
+                    logger.error(f"No valid articles directory found")
                     return []
 
             # Log cache state before scanning
@@ -113,10 +114,12 @@ class ArticleProcessor:
                     f"If cache should be empty, check cache file: {self.cache_manager.cache_file}"
                 )
 
+            logger.info(f"Found {len(unprocessed_articles)} unprocessed articles to process")
             return unprocessed_articles
 
         except Exception as e:
             logger.error(f"Error finding unprocessed articles: {e}")
+            logger.error(f"Error type: {type(e).__name__}")
             return []
 
     def process_article_file(self, file_path: str, filename: str) -> dict:
@@ -131,9 +134,16 @@ class ArticleProcessor:
             Dictionary containing the extracted facts or None if failed
         """
         try:
+            logger.debug(f"Processing article file: {filename}")
+            logger.debug(f"File path: {file_path}")
+            
             with open(file_path, "r", encoding="utf-8") as f:
                 article_data = json.load(f)
 
+            logger.debug(f"Loaded article data for: {filename}")
+            logger.debug(f"Article title: {article_data.get('title', 'No title')}")
+            logger.debug(f"Article content length: {len(article_data.get('original_content', ''))}")
+
             # Extract facts from the article
             facts = self.fact_extractor.extract_facts_from_article(
                 article_data.get("original_content", ""),
@@ -152,8 +162,15 @@ class ArticleProcessor:
             logger.info(f"Successfully processed article: {filename}")
             return facts
 
+        except json.JSONDecodeError as e:
+            logger.error(f"JSON decode error processing article {filename}: {e}")
+            logger.error(f"File path: {file_path}")
+            metrics_collector.increment_articles_failed()
+            return None
         except Exception as e:
             logger.error(f"Error processing article {filename}: {e}")
+            logger.error(f"Error type: {type(e).__name__}")
+            logger.error(f"File path: {file_path}")
             metrics_collector.increment_articles_failed()
             return None
 
@@ -171,18 +188,23 @@ class ArticleProcessor:
         failed = 0
 
         logger.info(f"Processing batch of {len(articles_batch)} articles")
+        logger.debug(f"Batch contents: {[filename for _, filename in articles_batch]}")
 
         for file_path, filename in articles_batch:
             try:
+                logger.debug(f"Processing individual article: {filename}")
                 facts = self.process_article_file(file_path, filename)
                 if facts:
                     successful += 1
                     metrics_collector.increment_articles_processed()
+                    logger.debug(f"Successfully processed: {filename}")
                 else:
                     failed += 1
                     metrics_collector.increment_articles_failed()
+                    logger.warning(f"Failed to process: {filename}")
             except Exception as e:
                 logger.error(f"Error processing batch item {filename}: {e}")
+                logger.error(f"Error type: {type(e).__name__}")
                 failed += 1
                 metrics_collector.increment_articles_failed()
 
@@ -226,6 +248,7 @@ class ArticleProcessor:
         # Process articles in batches
         for i in range(0, len(unprocessed_articles), self.batch_size):
             batch = unprocessed_articles[i : i + self.batch_size]
+            logger.info(f"Processing batch {i//self.batch_size + 1} with {len(batch)} articles")
             successful, failed = self.process_batch(batch)
             total_processed += successful
             total_failed += failed
@@ -251,6 +274,7 @@ class ArticleProcessor:
 
         logger.info(f"Processing completed in {duration:.2f} seconds")
         logger.info(f"Total processed: {total_processed}, Total failed: {total_failed}")
+        logger.info(f"Processing stats: {stats}")
 
         return stats
 
@@ -265,4 +289,5 @@ class ArticleProcessor:
         Returns:
             Dictionary with processing statistics
         """
+        logger.info("Starting real-time processing of new articles")
         return self.process_all_articles(scraper_dir)

ai_processor/cache_manager.py

@@ -19,6 +19,7 @@ class CacheManager:
     def __init__(self, cache_file: str = CACHE_FILE):
         self.cache_file = cache_file
         self.cache = self._load_cache()
+        logger.info(f"Cache manager initialized with cache file: {self.cache_file}")
 
     def _load_cache(self) -> Dict:
         """Load cache from file."""
@@ -29,6 +30,8 @@ class CacheManager:
         }
 
         try:
+            logger.debug(f"Attempting to load cache from: {self.cache_file}")
+            
             if not os.path.exists(self.cache_file):
                 logger.info(
                     f"Cache file does not exist: {self.cache_file}. Creating new empty cache."
@@ -77,13 +80,14 @@ class CacheManager:
                 cache_data["processed_files"] = {}
 
             logger.info(
-                f"Loaded cache with {len(cache_data['processed_files'])} processed files"
+                f"Loaded cache with {len(cache_data['processed_files'])} processed files from {self.cache_file}"
             )
+            logger.debug(f"Cache file size: {file_size} bytes")
             return cache_data
 
         except json.JSONDecodeError as e:
-            logger.warning(
+            logger.error(
-                f"Cache file contains invalid JSON: {e}. Treating as fresh cache."
+                f"Cache file contains invalid JSON: {e}. Creating fresh cache."
             )
             return empty_cache
         except Exception as e:
@@ -94,16 +98,20 @@ class CacheManager:
     def _save_cache(self) -> None:
         """Save cache to file."""
         try:
+            logger.debug(f"Saving cache to file: {self.cache_file}")
             # Create directory if it doesn't exist
             os.makedirs(os.path.dirname(self.cache_file), exist_ok=True)
 
             with open(self.cache_file, "w", encoding="utf-8") as f:
                 json.dump(self.cache, f, indent=2, ensure_ascii=False)
+            
+            logger.debug(f"Successfully saved cache to {self.cache_file}")
         except Exception as e:
             logger.error(f"Error saving cache file {self.cache_file}: {e}")
 
     def is_processed(self, file_path: str) -> bool:
         """Check if a file has been processed."""
+        logger.debug(f"Checking if file is processed: {file_path}")
         processed_files = self.cache.get("processed_files")
 
         # Handle case where processed_files is None or not a dict
@@ -113,10 +121,13 @@ class CacheManager:
             )
             return False
 
-        return file_path in processed_files
+        result = file_path in processed_files
+        logger.debug(f"File {file_path} processed status: {result}")
+        return result
 
     def mark_processed(self, file_path: str, status: str = "processed") -> None:
         """Mark a file as processed."""
+        logger.debug(f"Marking file as processed: {file_path}")
         # Ensure we're using the correct cache structure
         if "processed_files" not in self.cache:
             self.cache["processed_files"] = {}
@@ -126,21 +137,27 @@ class CacheManager:
             "last_updated": datetime.now().isoformat(),
         }
         self._save_cache()
+        logger.info(f"Successfully marked file as processed: {file_path}")
 
     def get_processed_files(self) -> List[str]:
         """Get list of all processed files."""
-        return list(self.cache.get("processed_files", {}).keys())
+        files = list(self.cache.get("processed_files", {}).keys())
+        logger.debug(f"Retrieved {len(files)} processed files from cache")
+        return files
 
     def get_cache_stats(self) -> Dict:
         """Get cache statistics."""
-        return {
+        stats = {
             "total_files": len(self.cache.get("processed_files", {})),
             "processed_files": len(self.cache.get("processed_files", {})),
             "cache_file": self.cache_file,
         }
+        logger.debug(f"Cache stats: {stats}")
+        return stats
 
     def clear_cache(self) -> None:
         """Clear the entire cache."""
+        logger.info("Clearing entire cache")
         self.cache = {}
         self._save_cache()
-        logger.info("Cache cleared")
+        logger.info("Cache cleared successfully")

ai_processor/fact_extractor.py

@@ -71,6 +71,11 @@ class FactExtractor:
             }}
             """
             
+            # Log the request details for debugging
+            logger.debug(f"Preparing AI request for article: {title}")
+            logger.debug(f"AI Server URL: {extraction_url}")
+            logger.debug(f"Request payload preview: {str({'model': self.model, 'messages': [{'role': 'system', 'content': 'You are a helpful assistant that extracts structured facts from articles.'}, {'role': 'user', 'content': prompt[:200]}]}[:300])}...")
+            
             # Call the AI service with gpt-oss model for fact extraction
             try:
                 response = requests.post(
@@ -87,10 +92,18 @@ class FactExtractor:
                     headers=self._get_headers(),
                     timeout=60
                 )
+                
+                # Log response details for debugging
+                logger.debug(f"AI service response status: {response.status_code}")
+                logger.debug(f"AI service response headers: {dict(response.headers)}")
+                logger.debug(f"AI service response text preview: {response.text[:500]}...")
+                
                 response.raise_for_status()
             except requests.exceptions.RequestException as e:
-                logger.error(f"REQUEST FAILED for article '{title}' - URL: {extraction_url}, Error: {e}")
+                logger.error(f"REQUEST FAILED for article '{title}' - URL: {extraction_url}")
+                logger.error(f"Request error details: {e}")
                 logger.error(f"Article content preview: {article_content[:200]}...")
+                logger.error(f"Response text (if available): {response.text[:500] if 'response' in locals() else 'No response available'}")
                 # Return basic structure if request fails
                 return self._create_basic_fact_structure(article_content, title)
             
@@ -98,23 +111,35 @@ class FactExtractor:
             try:
                 result = response.json()
                 extracted_text = result['choices'][0]['message']['content'].strip()
+                logger.debug(f"Successfully parsed JSON response for article '{title}'")
+                logger.debug(f"Extracted text preview: {extracted_text[:300]}...")
             except json.JSONDecodeError as e:
-                logger.error(f"JSON PARSING FAILED for article '{title}' - Response status: {response.status_code}, Response text: {response.text[:200]}...")
+                logger.error(f"JSON PARSING FAILED for article '{title}'")
+                logger.error(f"Response status: {response.status_code}")
+                logger.error(f"Response text (full): {response.text}")
+                logger.error(f"JSON parsing error: {e}")
                 logger.error(f"Article content preview: {article_content[:200]}...")
                 # Return basic structure if response parsing fails
                 return self._create_basic_fact_structure(article_content, title)
             
             # Check if the response is empty or invalid
             if not extracted_text or extracted_text.strip() == "":
-                logger.warning(f"Empty response from AI service for article '{title}'. Creating basic structure.")
+                logger.warning(f"Empty response from AI service for article '{title}'")
+                logger.warning(f"Response status: {response.status_code}")
+                logger.warning(f"Response text preview: {response.text[:300]}...")
+                logger.warning(f"Article content preview: {article_content[:200]}...")
                 facts = self._create_basic_fact_structure(article_content, title)
             else:
                 # Try to parse the JSON from the response
                 try:
                     facts = json.loads(extracted_text)
+                    logger.debug(f"Successfully parsed extracted JSON for article '{title}'")
                 except json.JSONDecodeError as e:
                     # If JSON parsing fails, create a basic structure
-                    logger.warning(f"Failed to parse JSON from AI response for article '{title}': {e}. Creating basic structure.")
+                    logger.error(f"Failed to parse JSON from AI response for article '{title}': {e}")
+                    logger.error(f"Extracted text that failed to parse: {extracted_text[:500]}...")
+                    logger.error(f"Response status: {response.status_code}")
+                    logger.error(f"Response text (full): {response.text}")
                     facts = self._create_basic_fact_structure(article_content, title)
             
             # Ensure all required fields are present
@@ -125,7 +150,9 @@ class FactExtractor:
             return facts
             
         except Exception as e:
-            logger.error(f"Error extracting facts from article '{title}': {e}")
+            logger.error(f"UNEXPECTED ERROR extracting facts from article '{title}': {e}")
+            logger.error(f"Error type: {type(e).__name__}")
+            logger.error(f"Article content preview: {article_content[:200]}...")
             # Return basic structure if extraction fails
             return self._create_basic_fact_structure(article_content, title)
     

ai_processor/main.py

@@ -8,29 +8,20 @@ import sys
 import os
 from datetime import datetime
 
-# Setup logging
-logging.basicConfig(
-    level=logging.INFO,
-    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
-    handlers=[
-        logging.FileHandler('ai_processor.log'),
-        logging.StreamHandler()
-    ]
-)
-
-logger = logging.getLogger(__name__)
-
-def setup_logging():
-    """Setup logging configuration."""
-    # Ensure log directory exists
-    log_dir = os.path.dirname('ai_processor.log')
-    if log_dir:
-        os.makedirs(log_dir, exist_ok=True)
-
 from article_processor import ArticleProcessor
 from metrics_collector import metrics_collector
 from cache_manager import CacheManager
-from config import CACHE_FILE, LOG_FILE
+from config import CACHE_FILE, LOG_FILE, LOG_LEVEL
+
+# Setup logging
+logging.basicConfig(
+    level=getattr(logging, LOG_LEVEL.upper(), logging.INFO),
+    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
+    handlers=[
+        logging.FileHandler(LOG_FILE),
+        logging.StreamHandler()
+    ]
+)
 
 logger = logging.getLogger(__name__)
 
@@ -102,4 +93,4 @@ if __name__ == "__main__":
     if len(sys.argv) > 1 and sys.argv[1] == "new":
         process_new_articles()
     else:
-        main()
+        main()