Added logging for GPIO

dreader/book_utils.py

@@ -2,6 +2,8 @@
 Utilities for managing book library, scanning EPUBs, and extracting metadata.
 """
 
+import logging
+import time
 from pathlib import Path
 from typing import List, Dict, Optional
 from dreader import create_ebook_reader
@@ -11,6 +13,8 @@ from PIL import Image
 import ebooklib
 from ebooklib import epub
 
+logger = logging.getLogger(__name__)
+
 
 def scan_book_directory(directory: Path) -> List[Dict[str, str]]:
     """
@@ -44,10 +48,15 @@ def extract_book_metadata(epub_path: Path, include_cover: bool = True) -> Option
     Returns:
         Dictionary with book metadata or None if extraction fails
     """
+    start_time = time.time()
     try:
         # Create temporary reader to extract metadata
+        reader_start = time.time()
         reader = create_ebook_reader(page_size=(400, 600))
         reader.load_epub(str(epub_path))
+        reader_elapsed = time.time() - reader_start
+
+        logger.debug(f"[METADATA] Loaded EPUB {epub_path.name} in {reader_elapsed:.2f}s")
 
         metadata = {
             'filename': epub_path.name,
@@ -58,12 +67,19 @@ def extract_book_metadata(epub_path: Path, include_cover: bool = True) -> Option
 
         # Extract cover image if requested - use direct EPUB extraction
         if include_cover:
+            cover_start = time.time()
             cover_data = extract_cover_from_epub(epub_path)
+            cover_elapsed = time.time() - cover_start
             metadata['cover_data'] = cover_data
+            logger.debug(f"[METADATA] Extracted cover from {epub_path.name} in {cover_elapsed:.2f}s")
+
+        total_elapsed = time.time() - start_time
+        logger.info(f"[METADATA] Extracted metadata from '{metadata['title']}' in {total_elapsed:.2f}s")
 
         return metadata
 
     except Exception as e:
+        logger.error(f"Error extracting metadata from {epub_path}: {e}")
         print(f"Error extracting metadata from {epub_path}: {e}")
         return {
             'filename': epub_path.name,
@@ -128,15 +144,20 @@ def extract_cover_from_epub(epub_path: Path, max_width: int = 300, max_height: i
     """
     try:
         # Read the EPUB
+        read_start = time.time()
         book = epub.read_epub(str(epub_path))
+        read_elapsed = time.time() - read_start
+        logger.debug(f"[COVER] Read EPUB {epub_path.name} in {read_elapsed:.2f}s")
 
         # Look for cover image
         cover_image = None
+        search_start = time.time()
 
         # First, try to find item marked as cover
         for item in book.get_items():
             if item.get_type() == ebooklib.ITEM_COVER:
                 cover_image = Image.open(BytesIO(item.get_content()))
+                logger.debug(f"[COVER] Found cover marked as ITEM_COVER in {epub_path.name}")
                 break
 
         # If not found, look for files with 'cover' in the name
@@ -146,6 +167,7 @@ def extract_cover_from_epub(epub_path: Path, max_width: int = 300, max_height: i
                     name = item.get_name().lower()
                     if 'cover' in name:
                         cover_image = Image.open(BytesIO(item.get_content()))
+                        logger.debug(f"[COVER] Found cover by filename in {epub_path.name}")
                         break
 
         # If still not found, get the first image
@@ -154,26 +176,36 @@ def extract_cover_from_epub(epub_path: Path, max_width: int = 300, max_height: i
                 if item.get_type() == ebooklib.ITEM_IMAGE:
                     try:
                         cover_image = Image.open(BytesIO(item.get_content()))
+                        logger.debug(f"[COVER] Using first image as cover in {epub_path.name}")
                         break
                     except:
                         continue
 
+        search_elapsed = time.time() - search_start
+
         if not cover_image:
+            logger.debug(f"[COVER] No cover image found in {epub_path.name}")
             return None
 
         # Resize if needed (maintain aspect ratio)
+        process_start = time.time()
         if cover_image.width > max_width or cover_image.height > max_height:
             cover_image.thumbnail((max_width, max_height), Image.Resampling.LANCZOS)
+            logger.debug(f"[COVER] Resized cover for {epub_path.name}")
 
         # Convert to base64
         buffer = BytesIO()
         cover_image.save(buffer, format='PNG')
         img_bytes = buffer.getvalue()
         img_base64 = base64.b64encode(img_bytes).decode('utf-8')
+        process_elapsed = time.time() - process_start
+
+        logger.debug(f"[COVER] Processed cover for {epub_path.name}: search={search_elapsed:.2f}s, encode={process_elapsed:.2f}s")
 
         return img_base64
 
     except Exception as e:
+        logger.error(f"Error extracting cover from EPUB {epub_path}: {e}")
         print(f"Error extracting cover from EPUB {epub_path}: {e}")
         return None