From 18bd4d169da01949c944b527f4908d4c45979983 Mon Sep 17 00:00:00 2001 From: Bill Date: Sun, 2 Nov 2025 15:41:47 -0500 Subject: [PATCH] debug: add comprehensive diagnostic logging for database initialization Following systematic debugging methodology after 5 failed fix attempts. Adding extensive print-based diagnostics to trace execution flow in Docker. Instrumentation added to: - api/main.py: Module import, app creation, lifespan function, module-level init - api/database.py: initialize_dev_database() entry/exit and decision points This diagnostic version will help identify: 1. Whether module-level code executes in Docker 2. Which initialization layer is failing 3. Database paths being resolved 4. Environment variable values Tests confirmed passing with diagnostic logging. --- api/database.py | 17 ++++++++++++++--- api/main.py | 44 ++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 56 insertions(+), 5 deletions(-) diff --git a/api/database.py b/api/database.py index b004a8b..3ebb257 100644 --- a/api/database.py +++ b/api/database.py @@ -244,24 +244,35 @@ def initialize_dev_database(db_path: str = "data/trading_dev.db") -> None: Args: db_path: Path to dev database file """ + print(f"🔍 DIAGNOSTIC: initialize_dev_database() CALLED with db_path={db_path}") from tools.deployment_config import should_preserve_dev_data - if should_preserve_dev_data(): + preserve = should_preserve_dev_data() + print(f"🔍 DIAGNOSTIC: should_preserve_dev_data() returned: {preserve}") + + if preserve: print(f"ℹī¸ PRESERVE_DEV_DATA=true, keeping existing dev database: {db_path}") # Ensure schema exists even if preserving data - if not Path(db_path).exists(): + db_exists = Path(db_path).exists() + print(f"🔍 DIAGNOSTIC: Database exists check: {db_exists}") + if not db_exists: print(f"📁 Dev database doesn't exist, creating: {db_path}") initialize_database(db_path) + print(f"🔍 DIAGNOSTIC: initialize_dev_database() RETURNING (preserve mode)") return # Delete existing dev database - if Path(db_path).exists(): + db_exists = Path(db_path).exists() + print(f"🔍 DIAGNOSTIC: Database exists (before deletion): {db_exists}") + if db_exists: print(f"🗑ī¸ Removing existing dev database: {db_path}") Path(db_path).unlink() + print(f"🔍 DIAGNOSTIC: Database deleted successfully") # Create fresh dev database print(f"📁 Creating fresh dev database: {db_path}") initialize_database(db_path) + print(f"🔍 DIAGNOSTIC: initialize_dev_database() COMPLETED successfully") def cleanup_dev_database(db_path: str = "data/trading_dev.db", data_path: str = "./data/dev_agent_data") -> None: diff --git a/api/main.py b/api/main.py index f4f73d5..12a98e0 100644 --- a/api/main.py +++ b/api/main.py @@ -131,31 +131,49 @@ def create_app( @asynccontextmanager async def lifespan(app: FastAPI): """Initialize database on startup, cleanup on shutdown if needed""" + print("=" * 80) + print("🔍 DIAGNOSTIC: LIFESPAN FUNCTION CALLED!") + print("=" * 80) + from tools.deployment_config import is_dev_mode, get_db_path from api.database import initialize_dev_database, initialize_database # Startup - use closure to access db_path from create_app scope logger.info("🚀 FastAPI application starting...") logger.info("📊 Initializing database...") + print(f"🔍 DIAGNOSTIC: Lifespan - db_path from closure: {db_path}") - if is_dev_mode(): + deployment_mode = is_dev_mode() + print(f"🔍 DIAGNOSTIC: Lifespan - is_dev_mode() returned: {deployment_mode}") + + if deployment_mode: # Initialize dev database (reset unless PRESERVE_DEV_DATA=true) logger.info(" 🔧 DEV mode detected - initializing dev database") + print("🔍 DIAGNOSTIC: Lifespan - DEV mode detected") dev_db_path = get_db_path(db_path) + print(f"🔍 DIAGNOSTIC: Lifespan - Resolved dev database path: {dev_db_path}") + print(f"🔍 DIAGNOSTIC: Lifespan - About to call initialize_dev_database({dev_db_path})") initialize_dev_database(dev_db_path) + print(f"🔍 DIAGNOSTIC: Lifespan - initialize_dev_database() completed") log_dev_mode_startup_warning() else: # Ensure production database schema exists logger.info(" 🏭 PROD mode - ensuring database schema exists") + print("🔍 DIAGNOSTIC: Lifespan - PROD mode detected") + print(f"🔍 DIAGNOSTIC: Lifespan - About to call initialize_database({db_path})") initialize_database(db_path) + print(f"🔍 DIAGNOSTIC: Lifespan - initialize_database() completed") logger.info("✅ Database initialized") logger.info("🌐 API server ready to accept requests") + print("🔍 DIAGNOSTIC: Lifespan - Startup complete, yielding control") + print("=" * 80) yield # Shutdown (if needed in future) logger.info("🛑 FastAPI application shutting down...") + print("🔍 DIAGNOSTIC: LIFESPAN SHUTDOWN CALLED") app = FastAPI( title="AI-Trader Simulation API", @@ -520,23 +538,45 @@ def create_app( # Create default app instance +print("=" * 80) +print("🔍 DIAGNOSTIC: Module api.main is being imported/executed") +print("=" * 80) + app = create_app() +print(f"🔍 DIAGNOSTIC: create_app() completed, app object created: {app}") # Ensure database is initialized when module is loaded # This handles cases where lifespan might not be triggered properly +print("🔍 DIAGNOSTIC: Starting module-level database initialization check...") logger.info("🔧 Module-level database initialization check...") + from tools.deployment_config import is_dev_mode, get_db_path from api.database import initialize_dev_database, initialize_database _db_path = app.state.db_path -if is_dev_mode(): +print(f"🔍 DIAGNOSTIC: app.state.db_path = {_db_path}") + +deployment_mode = is_dev_mode() +print(f"🔍 DIAGNOSTIC: is_dev_mode() returned: {deployment_mode}") + +if deployment_mode: + print("🔍 DIAGNOSTIC: DEV mode detected - initializing dev database at module load") logger.info(" 🔧 DEV mode - initializing dev database at module load") _dev_db_path = get_db_path(_db_path) + print(f"🔍 DIAGNOSTIC: Resolved dev database path: {_dev_db_path}") + print(f"🔍 DIAGNOSTIC: About to call initialize_dev_database({_dev_db_path})") initialize_dev_database(_dev_db_path) + print(f"🔍 DIAGNOSTIC: initialize_dev_database() completed successfully") else: + print("🔍 DIAGNOSTIC: PROD mode - ensuring database exists at module load") logger.info(" 🏭 PROD mode - ensuring database exists at module load") + print(f"🔍 DIAGNOSTIC: About to call initialize_database({_db_path})") initialize_database(_db_path) + print(f"🔍 DIAGNOSTIC: initialize_database() completed successfully") + +print("🔍 DIAGNOSTIC: Module-level database initialization complete") logger.info("✅ Module-level database initialization complete") +print("=" * 80) if __name__ == "__main__":