Update app.py

app.py

@@ -1,38 +1,90 @@
+print("DEBUG: app.py script execution starting...")
+
 import os
 import asyncio
 import json
+import logging
+import sys # For stdout logging and sys.exit
+
+# --- Detailed Logging Setup ---
+print("DEBUG: Setting up logging...")
+logging.basicConfig(
+    level=logging.DEBUG, # Capture all DEBUG, INFO, WARNING, ERROR, CRITICAL
+    format='%(asctime)s - %(name)s - %(levelname)s - %(module)s:%(lineno)d - %(message)s',
+    stream=sys.stdout, # Ensure logs go to standard output for Hugging Face
+    force=True # In case logging was already configured by another lib (unlikely here)
+)
+logger = logging.getLogger(__name__) # Get a logger for this module
+logging.getLogger('telethon').setLevel(logging.DEBUG) # Max verbosity for Telethon
+# logging.getLogger('PIL').setLevel(logging.DEBUG) # If Pillow issues arise
+print("DEBUG: Logging setup complete.")
+
+logger.debug("DEBUG: Importing Telethon...")
 from telethon import TelegramClient, events
 from telethon.tl import types # For DocumentAttributeFilename
+logger.debug("DEBUG: Telethon imported.")
+
+logger.debug("DEBUG: Importing Pillow...")
 from PIL import Image, ImageDraw, ImageFont
+logger.debug("DEBUG: Pillow imported.")
 
-# --- Configuration ---
+
+# --- Configuration Loading and Environment Variable Check ---
+logger.info("DEBUG: Loading environment variables...")
 try:
+    logger.debug("DEBUG: Attempting to import dotenv...")
     from dotenv import load_dotenv
-    load_dotenv()
+    logger.debug("DEBUG: dotenv imported. Attempting to load .env file...")
+    if load_dotenv():
+        logger.info("DEBUG: .env file loaded successfully.")
+    else:
+        logger.info("DEBUG: No .env file found or it's empty, relying on pre-set environment variables.")
 except ImportError:
-    pass
+    logger.info("DEBUG: python-dotenv not installed, relying on pre-set environment variables.")
+except Exception as e:
+    logger.error(f"DEBUG: Error loading .env using dotenv: {e}")
+
 
 API_ID = os.environ.get('API_ID')
 API_HASH = os.environ.get('API_HASH')
 BOT_TOKEN = os.environ.get('BOT_TOKEN')
 
+logger.info(f"DEBUG: API_ID loaded: {'Set' if API_ID else 'NOT SET'}")
+logger.info(f"DEBUG: API_HASH loaded: {'Set' if API_HASH else 'NOT SET'}")
+logger.info(f"DEBUG: BOT_TOKEN loaded: {'Set' if BOT_TOKEN else 'NOT SET'}")
+
 if not all([API_ID, API_HASH, BOT_TOKEN]):
-    print("CRITICAL: API_ID, API_HASH, and BOT_TOKEN environment variables must be set.")
-    exit(1)
+    logger.critical("CRITICAL ERROR: API_ID, API_HASH, and BOT_TOKEN environment variables must be set in Hugging Face Secrets.")
+    logger.critical("Bot cannot start. Please set these secrets in your Space settings.")
+    sys.exit(1) # Exit script if critical env vars are missing
+
 try:
     API_ID = int(API_ID)
+    logger.info(f"DEBUG: API_ID successfully converted to int: {str(API_ID)[:4]}... (masked for log)")
 except ValueError:
-    print("CRITICAL: API_ID must be an integer.")
-    exit(1)
+    logger.critical(f"CRITICAL ERROR: API_ID ('{os.environ.get('API_ID')}') must be an integer.")
+    sys.exit(1)
 
-# Adjusted session path
-SESSION_NAME = 'session/image_bot_session' # Store session file in 'session' subdirectory
-bot = TelegramClient(SESSION_NAME, API_ID, API_HASH)
+# --- Session Name (Change this to force a new session if connection hangs) ---
+SESSION_VERSION = "v1" # Increment this (e.g., "v2", "v3") if you suspect session file issues
+SESSION_NAME = f'session/image_bot_session_{SESSION_VERSION}'
+logger.info(f"DEBUG: Using session name: {SESSION_NAME}")
+
+logger.debug("DEBUG: Initializing TelegramClient (bot variable)...")
+try:
+    bot = TelegramClient(SESSION_NAME, API_ID, API_HASH)
+    logger.info(f"DEBUG: TelegramClient initialized successfully with session '{SESSION_NAME}'.")
+except Exception as e:
+    logger.critical(f"CRITICAL ERROR: Failed to initialize TelegramClient: {e}", exc_info=True)
+    sys.exit(1)
 
 
-# --- Paths and Constants ---
+# --- Paths and Directory Setup ---
+logger.info("DEBUG: Defining paths and ensuring directories...")
 DATA_DIR = "data"
-DOWNLOADS_DIR = "downloads" # Changed from TEMP_DIR
+DOWNLOADS_DIR = "downloads" # Changed from TEMP_DIR to match Dockerfile
+SESSION_DIR = "session"     # Directory for Telethon session specified in Dockerfile
+
 CONFIG_FILENAME = "config.json"
 TEMPLATE_FILENAME = "user_template.png"
 USER_FONT_FILENAME = "user_font.ttf"
@@ -41,13 +93,21 @@ CONFIG_PATH = os.path.join(DATA_DIR, CONFIG_FILENAME)
 TEMPLATE_PATH = os.path.join(DATA_DIR, TEMPLATE_FILENAME)
 USER_FONT_PATH = os.path.join(DATA_DIR, USER_FONT_FILENAME)
 
-# Ensure base directories exist (Dockerfile should create them, but this is a good fallback)
-# The Dockerfile now creates these, but os.makedirs with exist_ok=True is safe.
-os.makedirs(DATA_DIR, exist_ok=True)
-os.makedirs(DOWNLOADS_DIR, exist_ok=True)
-os.makedirs("session", exist_ok=True) # Ensure the 'session' directory for Telethon exists
+# Dockerfile should create these, but Python checks are good for robustness
+for dir_path in [DATA_DIR, DOWNLOADS_DIR, SESSION_DIR]:
+    logger.debug(f"DEBUG: Ensuring directory exists: {dir_path}")
+    try:
+        os.makedirs(dir_path, exist_ok=True)
+        logger.info(f"DEBUG: Directory '{dir_path}' ensured (created if didn't exist).")
+        # Optional: Check writability, though chmod 777 in Dockerfile should cover this
+        if not os.access(dir_path, os.W_OK):
+             logger.warning(f"DEBUG: Directory '{dir_path}' might not be writable despite creation!")
+    except Exception as e:
+        logger.error(f"DEBUG: Error ensuring directory '{dir_path}': {e}", exc_info=True)
+logger.info("DEBUG: Paths defined and directories ensured.")
+
 
-# --- Default Configuration (if config.json is missing/invalid) ---
+# --- Default Configuration ---
 DEFAULT_CONFIG = {
     "raw_image_box": {"x": 40, "y": 40, "width": 1000, "height": 780},
     "caption_area": {"x": 60, "y": 870},
@@ -56,104 +116,134 @@ DEFAULT_CONFIG = {
     "line_spacing": 10
 }
 bot_config = {}
+logger.debug(f"DEBUG: Default config: {DEFAULT_CONFIG}")
 
 # --- Config Management ---
 def load_bot_config():
     global bot_config
+    logger.info(f"DEBUG: Attempting to load bot configuration from {CONFIG_PATH}...")
     try:
         if os.path.exists(CONFIG_PATH):
             with open(CONFIG_PATH, 'r') as f:
                 loaded_values = json.load(f)
-            bot_config = DEFAULT_CONFIG.copy()
-            bot_config.update(loaded_values)
+            logger.info(f"DEBUG: Successfully read from {CONFIG_PATH}.")
+            bot_config = DEFAULT_CONFIG.copy() # Start with defaults
+            bot_config.update(loaded_values) # Override with loaded values
+            logger.info("DEBUG: Merged loaded config with defaults.")
         else:
+            logger.info(f"DEBUG: Config file {CONFIG_PATH} not found. Using defaults.")
             bot_config = DEFAULT_CONFIG.copy()
-        save_bot_config() # Ensure file exists with all keys
-        print(f"Configuration loaded/initialized: {bot_config}")
+        # Always save after loading/initializing to ensure file exists with all keys and consistent format
+        save_bot_config(initial_load=True)
+        logger.info(f"DEBUG: Final configuration after load/init: {bot_config}")
+    except json.JSONDecodeError as e:
+        logger.error(f"DEBUG: Error decoding JSON from {CONFIG_PATH}. Using defaults and overwriting. Error: {e}", exc_info=True)
+        bot_config = DEFAULT_CONFIG.copy()
+        save_bot_config(initial_load=True) # Attempt to save a clean default config
     except Exception as e:
-        print(f"Error loading config, using defaults: {e}")
+        logger.error(f"DEBUG: Critical error loading config, using defaults: {e}", exc_info=True)
         bot_config = DEFAULT_CONFIG.copy()
-        save_bot_config()
+        # Avoid saving if a critical non-JSON error occurred during load, to prevent infinite loops if save also fails
+        if not os.path.exists(CONFIG_PATH): # Save only if file didn't exist
+            save_bot_config(initial_load=True)
+
 
-def save_bot_config():
+def save_bot_config(initial_load=False):
     global bot_config
+    if not initial_load: # Only log intent if it's a user-triggered save
+        logger.info(f"DEBUG: Attempting to save bot configuration to {CONFIG_PATH}...")
     try:
         with open(CONFIG_PATH, 'w') as f:
             json.dump(bot_config, f, indent=4)
+        if not initial_load:
+            logger.info(f"DEBUG: Configuration saved successfully: {bot_config}")
     except Exception as e:
-        print(f"Error saving config: {e}")
+        logger.error(f"DEBUG: Error saving config to {CONFIG_PATH}: {e}", exc_info=True)
 
 # --- User State Management ---
 user_sessions = {}
+logger.debug("DEBUG: User sessions initialized as empty dict.")
 
 # --- Helper Functions (Image Processing) ---
 async def generate_image_with_frame(raw_image_path, frame_template_path, caption_text, chat_id):
-    output_filename = f"final_image_{chat_id}.png"
-    # Save final output to DOWNLOADS_DIR before sending, then clean up
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Starting image generation. Raw: '{raw_image_path}', Template: '{frame_template_path}', Caption: '{caption_text[:30]}...'")
+    output_filename = f"final_image_{chat_id}_{SESSION_VERSION}.png" # Add session version for uniqueness
     output_path = os.path.join(DOWNLOADS_DIR, output_filename)
+    logger.debug(f"DEBUG: [ChatID: {chat_id}] Output path will be: {output_path}")
 
-
+    # Use loaded configuration
     cfg_raw_box = bot_config.get("raw_image_box", DEFAULT_CONFIG["raw_image_box"])
     cfg_caption_area = bot_config.get("caption_area", DEFAULT_CONFIG["caption_area"])
     cfg_font_size = bot_config.get("caption_font_size", DEFAULT_CONFIG["caption_font_size"])
     cfg_caption_color = bot_config.get("caption_color", DEFAULT_CONFIG["caption_color"])
     cfg_line_spacing = bot_config.get("line_spacing", DEFAULT_CONFIG["line_spacing"])
+    logger.debug(f"DEBUG: [ChatID: {chat_id}] Using image processing config: raw_box={cfg_raw_box}, caption_area={cfg_caption_area}, font_size={cfg_font_size}")
 
     try:
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Opening raw image: {raw_image_path}")
         raw_img = Image.open(raw_image_path).convert("RGBA")
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Opening frame template image: {frame_template_path}")
         frame_template_img = Image.open(frame_template_path).convert("RGBA")
 
         raw_img_copy = raw_img.copy()
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Resizing raw image to fit box: {cfg_raw_box['width']}x{cfg_raw_box['height']}")
         raw_img_copy.thumbnail((cfg_raw_box['width'], cfg_raw_box['height']), Image.LANCZOS)
 
         final_img = frame_template_img.copy()
         paste_x = cfg_raw_box['x'] + (cfg_raw_box['width'] - raw_img_copy.width) // 2
         paste_y = cfg_raw_box['y'] + (cfg_raw_box['height'] - raw_img_copy.height) // 2
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Pasting raw image at ({paste_x}, {paste_y}) on template.")
         final_img.paste(raw_img_copy, (paste_x, paste_y), raw_img_copy if raw_img_copy.mode == 'RGBA' else None)
 
         draw = ImageDraw.Draw(final_img)
         font_to_use = None
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Attempting to load user font: {USER_FONT_PATH} with size {cfg_font_size}")
         if os.path.exists(USER_FONT_PATH):
             try:
                 font_to_use = ImageFont.truetype(USER_FONT_PATH, cfg_font_size)
-            except IOError:
-                print(f"User font at '{USER_FONT_PATH}' found but couldn't be loaded. Using fallback.")
+                logger.info(f"DEBUG: [ChatID: {chat_id}] User font loaded successfully.")
+            except IOError as e:
+                logger.warning(f"DEBUG: [ChatID: {chat_id}] User font at '{USER_FONT_PATH}' found but couldn't be loaded: {e}. Using fallback.")
         if not font_to_use:
             try:
+                logger.debug(f"DEBUG: [ChatID: {chat_id}] Attempting to load 'arial.ttf' as fallback.")
                 font_to_use = ImageFont.truetype("arial.ttf", cfg_font_size)
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Fallback font 'arial.ttf' loaded.")
             except IOError:
-                print("Arial.ttf not found, using Pillow's load_default(). This may look very basic.")
-                font_to_use = ImageFont.load_default().font_variant(size=cfg_font_size)
+                logger.warning(f"DEBUG: [ChatID: {chat_id}] Arial.ttf not found, using Pillow's load_default(). This may look very basic.")
+                font_to_use = ImageFont.load_default().font_variant(size=cfg_font_size) #Pillow 10+
 
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Drawing caption text...")
         lines = caption_text.split('\n')
         current_y = cfg_caption_area['y']
-        for line in lines:
-            try:
+        for i, line in enumerate(lines):
+            try: # Pillow 9.2.0+ textbbox
                 line_bbox = draw.textbbox((0, 0), line, font=font_to_use)
                 line_height = line_bbox[3] - line_bbox[1]
-            except AttributeError:
+            except AttributeError: # Fallback for older Pillow versions or basic font
                 (text_width, text_height) = draw.textsize(line, font=font_to_use)
                 line_height = text_height
-            
+            logger.debug(f"DEBUG: [ChatID: {chat_id}] Drawing line {i+1}/{len(lines)}: '{line[:20]}...' at y={current_y}, height={line_height}")
             draw.text((cfg_caption_area['x'], current_y), line, font=font_to_use, fill=cfg_caption_color)
             current_y += line_height + cfg_line_spacing
 
-        final_img.convert("RGB").save(output_path, "PNG")
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Saving final image to {output_path}")
+        final_img.convert("RGB").save(output_path, "PNG") # Consider JPEG for smaller size if transparency not needed
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Image generation complete: {output_path}")
         return output_path
 
     except FileNotFoundError as fnf_err:
-        print(f"Error: Image file not found during processing. Template: {frame_template_path}, Raw: {raw_image_path}. Error: {fnf_err}")
+        logger.error(f"DEBUG: [ChatID: {chat_id}] File not found during image processing. Template: {frame_template_path}, Raw: {raw_image_path}. Error: {fnf_err}", exc_info=True)
         return None
     except Exception as e:
-        print(f"Error during image processing: {e}")
-        import traceback
-        traceback.print_exc()
+        logger.error(f"DEBUG: [ChatID: {chat_id}] Critical error during image processing: {e}", exc_info=True)
         return None
 
-# --- Bot Event Handlers --- (Mostly same as before, checking paths for DOWNLOADS_DIR)
+# --- Bot Event Handlers ---
 @bot.on(events.NewMessage(pattern='/start'))
 async def start_handler(event):
     chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /start command from user {event.sender_id}")
     user_sessions[chat_id] = {'state': 'idle', 'data': {}}
     start_message = (
         "Welcome! This bot helps you create images with a template.\n\n"
@@ -170,22 +260,30 @@ async def start_handler(event):
         "If using ephemeral storage (common on free tiers), your uploaded template, font, config, and session might be lost on restarts, requiring setup again."
     )
     await event.reply(start_message)
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Sent welcome message for /start.")
+
+# ... (Other command handlers: /settemplate, /setfont, /viewconfig, /help_config, /setconfig, /create, /cancel)
+# Add logger.info(f"DEBUG: [ChatID: {chat_id}] Received {command_name} command...") to each
 
 @bot.on(events.NewMessage(pattern='/settemplate'))
 async def set_template_handler(event):
     chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /settemplate command.")
     user_sessions[chat_id] = {'state': 'awaiting_template_image', 'data': {}}
     await event.reply("Please send your frame template image (e.g., a PNG or JPG).")
 
 @bot.on(events.NewMessage(pattern='/setfont'))
 async def set_font_handler(event):
     chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /setfont command.")
     user_sessions[chat_id] = {'state': 'awaiting_font_file', 'data': {}}
     await event.reply("Please send your `.ttf` font file as a document/file.")
 
 @bot.on(events.NewMessage(pattern='/viewconfig'))
 async def view_config_handler(event):
-    load_bot_config()
+    chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /viewconfig command.")
+    load_bot_config() # Ensure config is fresh
     config_str = "Current Bot Configuration:\n"
     config_str += f"- Font: {'User font set (' + USER_FONT_FILENAME + ')' if os.path.exists(USER_FONT_PATH) else 'Using fallback font (Arial or Pillow default)'}\n"
     for key, value in bot_config.items():
@@ -194,6 +292,8 @@ async def view_config_handler(event):
 
 @bot.on(events.NewMessage(pattern='/help_config'))
 async def help_config_handler(event):
+    chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /help_config command.")
     await event.reply(
         "**Configuration Commands (`/setconfig <key> <value>`):**\n"
         "`raw_image_box_x <num>` (e.g., 40)\n"
@@ -212,13 +312,15 @@ async def help_config_handler(event):
 
 @bot.on(events.NewMessage(pattern=r'/setconfig (\w+) (.+)'))
 async def set_config_handler(event):
+    chat_id = event.chat_id
     key_to_set = event.pattern_match.group(1).strip()
     value_str = event.pattern_match.group(2).strip()
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /setconfig command. Key: '{key_to_set}', Value: '{value_str}'")
     
     load_bot_config()
-    original_config_copy = json.dumps(bot_config)
+    original_config_copy = json.dumps(bot_config) # For checking if value actually changed
     updated = False
-    sub_key = None # Initialize sub_key
+    sub_key = None
 
     try:
         if key_to_set.startswith("raw_image_box_"):
@@ -235,7 +337,7 @@ async def set_config_handler(event):
             bot_config[key_to_set] = int(value_str)
             updated = True
         elif key_to_set == "caption_color":
-            bot_config[key_to_set] = value_str
+            bot_config[key_to_set] = value_str # No specific validation, user responsible
             updated = True
         
         if updated:
@@ -251,156 +353,259 @@ async def set_config_handler(event):
                  else:
                      reply_value = bot_config.get(key_to_set, value_str)
                  await event.reply(f"Configuration updated: {key_to_set} = {reply_value}")
+                 logger.info(f"DEBUG: [ChatID: {chat_id}] Config '{key_to_set}' updated to '{reply_value}'.")
             else:
                  await event.reply(f"Value for {key_to_set} is already {value_str}. No change made.")
+                 logger.info(f"DEBUG: [ChatID: {chat_id}] Config '{key_to_set}' already '{value_str}'. No change.")
         else:
             await event.reply(f"Unknown or non-configurable key: '{key_to_set}'. See `/help_config`.")
+            logger.warning(f"DEBUG: [ChatID: {chat_id}] Unknown config key attempted: '{key_to_set}'.")
     except ValueError:
         await event.reply(f"Invalid value for '{key_to_set}'. Please provide a number where expected (e.g., for sizes, coordinates).")
+        logger.warning(f"DEBUG: [ChatID: {chat_id}] Invalid value for config key '{key_to_set}': '{value_str}'.")
     except Exception as e:
         await event.reply(f"Error setting config: {e}")
+        logger.error(f"DEBUG: [ChatID: {chat_id}] Error setting config '{key_to_set}': {e}", exc_info=True)
+
 
 @bot.on(events.NewMessage(pattern='/create'))
 async def create_post_handler(event):
     chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /create command.")
     if not os.path.exists(TEMPLATE_PATH):
+        logger.warning(f"DEBUG: [ChatID: {chat_id}] /create failed: Template not found at {TEMPLATE_PATH}.")
         await event.reply("No template found. Please set one using `/settemplate` first.")
         return
     if not os.path.exists(USER_FONT_PATH):
+        logger.warning(f"DEBUG: [ChatID: {chat_id}] /create warning: User font not found at {USER_FONT_PATH}. Fallback will be used.")
         await event.reply("Warning: No user font found (use `/setfont`). A fallback font will be attempted, but results may vary.")
 
     user_sessions[chat_id] = {'state': 'awaiting_raw_image_for_create', 'data': {}}
     await event.reply("Please send the raw image you want to use.")
+    logger.debug(f"DEBUG: [ChatID: {chat_id}] State set to 'awaiting_raw_image_for_create'.")
+
 
 @bot.on(events.NewMessage(pattern='/cancel'))
 async def cancel_handler(event):
     chat_id = event.chat_id
+    logger.info(f"DEBUG: [ChatID: {chat_id}] Received /cancel command.")
     if chat_id in user_sessions and user_sessions[chat_id]['state'] != 'idle':
         temp_raw_path = user_sessions[chat_id].get('data', {}).get('raw_image_path')
         if temp_raw_path and os.path.exists(temp_raw_path):
-            try: os.remove(temp_raw_path)
-            except OSError as e: print(f"Error deleting temp file {temp_raw_path}: {e}")
+            try:
+                os.remove(temp_raw_path)
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Deleted temp raw image: {temp_raw_path}")
+            except OSError as e:
+                logger.error(f"DEBUG: [ChatID: {chat_id}] Error deleting temp file {temp_raw_path}: {e}")
         user_sessions[chat_id] = {'state': 'idle', 'data': {}}
         await event.reply("Operation cancelled.")
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Operation cancelled, state reset to 'idle'.")
     else:
         await event.reply("Nothing to cancel.")
+        logger.info(f"DEBUG: [ChatID: {chat_id}] /cancel received but nothing to cancel (state was 'idle' or no session).")
 
 @bot.on(events.NewMessage)
-async def message_handler(event): # pylint: disable=too-many-branches
+async def message_handler(event): # pylint: disable=too-many-branches, too-many-statements
     chat_id = event.chat_id
-    if chat_id not in user_sessions:
+    if chat_id not in user_sessions: # Initialize session if it doesn't exist
         user_sessions[chat_id] = {'state': 'idle', 'data': {}}
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] New user or session cleared, initialized session.")
+
+    # Let specific command handlers (defined with patterns) take precedence
+    # This generic handler processes messages based on user state.
+    if event.text and event.text.startswith(('/', '#', '.')): # Common command prefixes
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Message looks like a command ('{event.text[:20]}...'), letting patterned handlers manage it.")
+        return
 
-    if event.text and event.text.startswith(('/', '#', '.')):
-        return # Let specific command handlers take precedence
 
     current_state = user_sessions.get(chat_id, {}).get('state', 'idle')
     session_data = user_sessions.get(chat_id, {}).get('data', {})
+    logger.debug(f"DEBUG: [ChatID: {chat_id}] Message received. Current state: '{current_state}'. Message text (first 30 chars): '{str(event.raw_text)[:30]}...' Is photo: {event.photo is not None}. Is document: {event.document is not None}.")
+
 
+    # Handle font upload (as document)
     if event.document and current_state == 'awaiting_font_file':
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Document received in 'awaiting_font_file' state.")
+        doc_attrs = event.document.attributes
+        filename = "unknown_document"
+        for attr in doc_attrs:
+            if isinstance(attr, types.DocumentAttributeFilename):
+                filename = attr.file_name
+                break
+        logger.debug(f"DEBUG: [ChatID: {chat_id}] Document filename: '{filename}', MIME type: '{event.document.mime_type}'")
+
         is_ttf = False
-        if hasattr(event.document, 'mime_type') and \
+        if filename.lower().endswith('.ttf'):
+            is_ttf = True
+        elif hasattr(event.document, 'mime_type') and \
            ('font' in event.document.mime_type or 'ttf' in event.document.mime_type or 'opentype' in event.document.mime_type):
             is_ttf = True
-        if not is_ttf and hasattr(event.document, 'attributes'):
-            for attr in event.document.attributes:
-                if isinstance(attr, types.DocumentAttributeFilename) and attr.file_name.lower().endswith('.ttf'):
-                    is_ttf = True
-                    break
+        
         if is_ttf:
             await event.reply("Downloading font file...")
+            logger.info(f"DEBUG: [ChatID: {chat_id}] Downloading TTF font: {filename}")
             try:
                 await bot.download_media(event.message.document, USER_FONT_PATH)
                 user_sessions[chat_id]['state'] = 'idle'
-                await event.reply(f"Font saved as '{USER_FONT_FILENAME}' in `data/` directory!")
+                await event.reply(f"Font saved as '{USER_FONT_FILENAME}' in `data/` directory! It will be used for new images.")
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Font saved successfully. State set to 'idle'.")
             except Exception as e:
                 await event.reply(f"Sorry, I couldn't save the font. Error: {e}")
+                logger.error(f"DEBUG: [ChatID: {chat_id}] Error saving font: {e}", exc_info=True)
                 user_sessions[chat_id]['state'] = 'idle'
         else:
-            await event.reply("That doesn't look like a .ttf font file. Please send a valid .ttf font file, or use /cancel.")
+            await event.reply("That doesn't look like a .ttf font file based on its name or type. Please send a valid .ttf font file, or use /cancel.")
+            logger.warning(f"DEBUG: [ChatID: {chat_id}] Received document is not a TTF: {filename}")
         return
 
+    # Handle image uploads for template or raw image
     if event.photo:
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Photo received in state '{current_state}'.")
         if current_state == 'awaiting_template_image':
             await event.reply("Downloading template image...")
+            logger.info(f"DEBUG: [ChatID: {chat_id}] Downloading template image.")
             try:
                 await bot.download_media(event.message.photo, TEMPLATE_PATH)
                 user_sessions[chat_id]['state'] = 'idle'
-                await event.reply(f"Template saved as '{TEMPLATE_FILENAME}' in `data/` directory!")
+                await event.reply(f"Template saved as '{TEMPLATE_FILENAME}' in `data/` directory! Remember to `/setfont` and use `/setconfig` if needed.")
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Template saved. State set to 'idle'.")
             except Exception as e:
                 await event.reply(f"Couldn't save template image. Error: {e}")
+                logger.error(f"DEBUG: [ChatID: {chat_id}] Error saving template: {e}", exc_info=True)
                 user_sessions[chat_id]['state'] = 'idle'
             return
+
         elif current_state == 'awaiting_raw_image_for_create':
-            raw_img_filename = f"raw_{chat_id}_{event.message.id}.jpg"
-            # Save raw images to DOWNLOADS_DIR
+            raw_img_filename = f"raw_{chat_id}_{event.message.id}_{SESSION_VERSION}.jpg"
             raw_img_temp_path = os.path.join(DOWNLOADS_DIR, raw_img_filename)
             await event.reply("Downloading raw image...")
+            logger.info(f"DEBUG: [ChatID: {chat_id}] Downloading raw image to {raw_img_temp_path}.")
             try:
                 await bot.download_media(event.message.photo, raw_img_temp_path)
                 session_data['raw_image_path'] = raw_img_temp_path
                 user_sessions[chat_id]['state'] = 'awaiting_caption_for_create'
-                await event.reply("Raw image received. Now, please send the caption text.")
+                await event.reply("Raw image received. Now, please send the caption text for the image.")
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Raw image saved. State set to 'awaiting_caption_for_create'.")
             except Exception as e:
                 await event.reply(f"Couldn't save raw image. Error: {e}")
+                logger.error(f"DEBUG: [ChatID: {chat_id}] Error saving raw image: {e}", exc_info=True)
                 user_sessions[chat_id]['state'] = 'idle'
             return
 
+    # Handle text input for caption
     if event.text and not event.text.startswith('/') and current_state == 'awaiting_caption_for_create':
         caption_text = event.text
         raw_image_path = session_data.get('raw_image_path')
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Caption text received: '{caption_text[:30]}...'. Raw image path: {raw_image_path}")
 
         if not raw_image_path or not os.path.exists(raw_image_path):
-            await event.reply("Error: Raw image data not found. Try `/create` again.")
+            logger.error(f"DEBUG: [ChatID: {chat_id}] Raw image path not found or file missing: {raw_image_path}. State reset.")
+            await event.reply("Error: Raw image data not found. Please try the `/create` command again.")
             user_sessions[chat_id]['state'] = 'idle'
             return
 
         processing_msg = await event.reply("⏳ Processing your image, please wait...")
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Starting image processing with caption.")
         final_image_path = await generate_image_with_frame(raw_image_path, TEMPLATE_PATH, caption_text, chat_id)
         
-        try: await bot.delete_messages(chat_id, processing_msg)
-        except Exception: pass # noqa
+        try: # Try to delete "Processing..." message
+            logger.debug(f"DEBUG: [ChatID: {chat_id}] Attempting to delete 'Processing...' message.")
+            await bot.delete_messages(chat_id, processing_msg)
+        except Exception as e:
+            logger.warning(f"DEBUG: [ChatID: {chat_id}] Could not delete 'Processing...' message: {e}")
+
 
         if final_image_path and os.path.exists(final_image_path):
+            logger.info(f"DEBUG: [ChatID: {chat_id}] Final image created: {final_image_path}. Sending to user.")
             try:
                 await bot.send_file(chat_id, final_image_path, caption="🖼️ Here's your generated image!")
+                logger.info(f"DEBUG: [ChatID: {chat_id}] Final image sent successfully.")
             except Exception as e:
                 await event.reply(f"Sorry, couldn't send the final image. Error: {e}")
+                logger.error(f"DEBUG: [ChatID: {chat_id}] Error sending final image: {e}", exc_info=True)
             finally:
-                if os.path.exists(final_image_path): os.remove(final_image_path)
+                if os.path.exists(final_image_path):
+                    logger.debug(f"DEBUG: [ChatID: {chat_id}] Deleting final image from server: {final_image_path}")
+                    os.remove(final_image_path)
         else:
-            await event.reply("❌ Sorry, something went wrong while creating the image.")
+            await event.reply("❌ Sorry, something went wrong while creating the image. Please check if the template and font are set correctly, and if the raw image is valid.")
+            logger.error(f"DEBUG: [ChatID: {chat_id}] Image generation failed or final_image_path is invalid.")
 
-        if os.path.exists(raw_image_path): os.remove(raw_image_path)
+        # Cleanup raw image and reset state
+        if os.path.exists(raw_image_path):
+            logger.debug(f"DEBUG: [ChatID: {chat_id}] Deleting temporary raw image: {raw_image_path}")
+            os.remove(raw_image_path)
         user_sessions[chat_id]['state'] = 'idle'
-        user_sessions[chat_id]['data'] = {}
+        user_sessions[chat_id]['data'] = {} # Clear session data for this user
+        logger.info(f"DEBUG: [ChatID: {chat_id}] Post creation process complete. State set to 'idle'.")
         return
     
-    if event.text and not event.text.startswith('/') and current_state != 'idle':
+    # If message wasn't handled by specific states above and is not a command
+    if current_state != 'idle': # Only reply if in an active state and message wasn't processed
+         logger.debug(f"DEBUG: [ChatID: {chat_id}] Unhandled message in state '{current_state}'. Text: '{str(event.raw_text)[:30]}...'")
          await event.reply(f"I'm currently waiting for: `{current_state}`. If you're stuck, try `/cancel`.")
 
+
 # --- Main Bot Execution ---
 async def main():
-    print("Bot starting...")
-    load_bot_config()
+    logger.info("===== Bot main() function starting =====")
+    load_bot_config() # Load or create initial config on startup
 
+    # --- Network Test (Optional but recommended for debugging connection hangs) ---
+    logger.info("DEBUG: Performing a simple network test to google.com...")
     try:
-        print(f"Connecting to Telegram with API_ID: {str(API_ID)[:4]}... (masked)")
+        import socket # Standard library, should be available
+        host_to_test = "google.com"
+        port_to_test = 80 # HTTP port
+        socket.create_connection((host_to_test, port_to_test), timeout=10)
+        logger.info(f"DEBUG: Network test to {host_to_test}:{port_to_test} was SUCCESSFUL.")
+    except OSError as e:
+        logger.warning(f"DEBUG: Network test to {host_to_test}:{port_to_test} FAILED - OSError: {e}. This might indicate broader network issues in the container.")
+    except Exception as ex:
+        logger.warning(f"DEBUG: Network test to {host_to_test}:{port_to_test} FAILED with other exception: {ex}. This might indicate broader network issues.")
+    logger.info("DEBUG: Network test completed.")
+    # --- End Network Test ---
+
+    try:
+        logger.info(f"DEBUG: Attempting to connect to Telegram with bot token...")
+        logger.info(f"DEBUG: Using API_ID: {str(API_ID)[:4]}... (masked), Session: {SESSION_NAME}")
+        
+        # The actual connection happens here
         await bot.start(bot_token=BOT_TOKEN)
-        print("Bot is connected and running!")
+        logger.info("SUCCESS: Bot connected to Telegram successfully!")
+        
         me = await bot.get_me()
-        print(f"Logged in as: {me.username} (ID: {me.id})")
+        logger.info(f"Bot User Info: Logged in as: @{me.username} (ID: {me.id})")
+        
+        logger.info("Bot is now running and listening for messages...")
         await bot.run_until_disconnected()
+
+    except OSError as e: # Specific catch for network related OS errors during start
+        logger.critical(f"CRITICAL ERROR: OSError during bot.start() or connection phase: {e}. This often indicates network connectivity problems from the container to Telegram servers.", exc_info=True)
     except Exception as e:
-        print(f"CRITICAL: An error occurred while running the bot: {e}")
-        import traceback
-        traceback.print_exc()
+        logger.critical(f"CRITICAL ERROR: An unhandled exception occurred while starting or running the bot: {e}", exc_info=True)
     finally:
-        print("Bot is stopping...")
+        logger.info("===== Bot main() function ending (or ended due to error) =====")
         if bot.is_connected():
-            await bot.disconnect()
-        print("Bot has disconnected.")
+            logger.info("DEBUG: Bot is connected, attempting to disconnect...")
+            try:
+                await bot.disconnect()
+                logger.info("DEBUG: Bot disconnected successfully.")
+            except Exception as e:
+                logger.error(f"DEBUG: Error during bot disconnect: {e}", exc_info=True)
+        else:
+            logger.info("DEBUG: Bot was not connected (or already disconnected).")
+        logger.info("Bot has stopped.")
 
 if __name__ == '__main__':
-    asyncio.run(main())
+    logger.info("DEBUG: Script is being run directly (__name__ == '__main__').")
+    print("DEBUG: Starting asyncio event loop...") # Ensure this prints before loop starts
+    try:
+        asyncio.run(main())
+    except KeyboardInterrupt:
+        logger.info("DEBUG: Bot stopped by KeyboardInterrupt (Ctrl+C).")
+    except Exception as e:
+        logger.critical(f"DEBUG: Critical error running asyncio event loop: {e}", exc_info=True)
+    finally:
+        print("DEBUG: Asyncio event loop finished.")