diff --git a/web/app.py b/web/app.py index 2634b39..d89707e 100644 --- a/web/app.py +++ b/web/app.py @@ -1,4 +1,6 @@ import os +import sys +import platform from datetime import datetime from sqlalchemy import text from flask import Flask @@ -8,6 +10,19 @@ from web.db import db, User, Run from web.tasks import huey from core import config +# Ensure stdout is UTF-8 in all environments (Docker, Windows, Raspberry Pi) +if hasattr(sys.stdout, 'reconfigure'): + try: + sys.stdout.reconfigure(encoding='utf-8', errors='replace') + sys.stderr.reconfigure(encoding='utf-8', errors='replace') + except Exception: + pass + +def _log(msg): + """Print to stdout with flush so Docker logs capture it immediately.""" + print(msg, flush=True) + + # Calculate paths relative to this file (web/app.py -> project root is two levels up) BASE_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) TEMPLATE_DIR = os.path.join(BASE_DIR, 'templates') @@ -48,6 +63,22 @@ app.register_blueprint(persona_bp) app.register_blueprint(admin_bp) +# --- STARTUP DIAGNOSTIC BANNER --- +_log("=" * 60) +_log(f"BookApp v{config.VERSION} starting up") +_log(f" Python : {sys.version}") +_log(f" Platform : {platform.platform()}") +_log(f" Data dir : {config.DATA_DIR}") +_log(f" Queue db : {os.path.join(config.DATA_DIR, 'queue.db')}") +_log(f" App db : {os.path.join(config.DATA_DIR, 'bookapp.db')}") +try: + import huey as _huey_pkg + _log(f" Huey : {_huey_pkg.__version__}") +except Exception: + _log(" Huey : (version unknown)") +_log("=" * 60) + + # --- SETUP --- with app.app_context(): db.create_all() @@ -56,38 +87,50 @@ with app.app_context(): if config.ADMIN_USER and config.ADMIN_PASSWORD: admin = User.query.filter_by(username=config.ADMIN_USER).first() if not admin: - print(f"🔐 System: Creating Admin User '{config.ADMIN_USER}' from environment variables.") + _log(f"System: Creating Admin User '{config.ADMIN_USER}' from environment variables.") admin = User(username=config.ADMIN_USER, password=generate_password_hash(config.ADMIN_PASSWORD, method='pbkdf2:sha256'), is_admin=True) db.session.add(admin) db.session.commit() else: - print(f"🔐 System: Syncing Admin User '{config.ADMIN_USER}' settings from environment.") + _log(f"System: Syncing Admin User '{config.ADMIN_USER}' settings from environment.") if not admin.is_admin: admin.is_admin = True admin.password = generate_password_hash(config.ADMIN_PASSWORD, method='pbkdf2:sha256') db.session.add(admin) db.session.commit() elif not User.query.filter_by(is_admin=True).first(): - print("ℹī¸ System: No Admin credentials found in environment variables. Admin account not created.") + _log("System: No Admin credentials found in environment variables. Admin account not created.") # Migration: Add 'progress' column if missing try: with db.engine.connect() as conn: conn.execute(text("ALTER TABLE run ADD COLUMN progress INTEGER DEFAULT 0")) conn.commit() - print("✅ System: Added 'progress' column to Run table.") + _log("System: Added 'progress' column to Run table.") except: pass # Reset stuck runs on startup try: stuck_runs = Run.query.filter_by(status='running').all() if stuck_runs: - print(f"⚠ī¸ System: Found {len(stuck_runs)} stuck runs. Resetting to 'failed'.") + _log(f"System: Found {len(stuck_runs)} stuck run(s) — resetting to 'failed'.") for r in stuck_runs: r.status = 'failed' r.end_time = datetime.utcnow() db.session.commit() + # Also reset stuck 'queued' runs whose task entry was lost from queue.db + import sqlite3 as _sqlite3 + _queue_path = os.path.join(config.DATA_DIR, 'queue.db') + if os.path.exists(_queue_path): + with _sqlite3.connect(_queue_path, timeout=5) as _qconn: + pending_count = _qconn.execute("SELECT COUNT(*) FROM task").fetchone()[0] + queued_runs = Run.query.filter_by(status='queued').count() + _log(f"System: Queue has {pending_count} pending task(s), DB has {queued_runs} queued run(s).") + if queued_runs > 0 and pending_count == 0: + _log("System: WARNING — queued runs exist but queue is empty (tasks lost). Resetting to 'failed'.") + Run.query.filter_by(status='queued').update({'status': 'failed', 'end_time': datetime.utcnow()}) + db.session.commit() except Exception as e: - print(f"⚠ī¸ System: Failed to clean up stuck runs: {e}") + _log(f"System: Startup cleanup error: {e}") # --- HUEY CONSUMER --- @@ -98,23 +141,28 @@ import threading as _threading def _start_huey_consumer(): import logging as _logging - _logging.basicConfig(level=_logging.WARNING) + # INFO level so task pick-up/completion appears in docker logs + _logging.basicConfig( + level=_logging.INFO, + format='[%(asctime)s] HUEY %(levelname)s | %(message)s', + datefmt='%H:%M:%S', + stream=sys.stdout, + force=True, + ) try: from huey.consumer import Consumer + # NOTE: Huey 2.6.0 does NOT accept a `loglevel` kwarg — omit it. consumer = Consumer(huey, workers=1, worker_type='thread') - print("System: Huey task consumer started.") - consumer.run() + _log("System: Huey task consumer started successfully.") + consumer.run() # blocks until app exits except Exception as e: - msg = f"System: Huey consumer failed to start: {e}" - print(msg) - # Write the error to a persistent log so it is visible even when stdout is lost + msg = f"System: Huey consumer FAILED to start: {type(e).__name__}: {e}" + _log(msg) + # Also write to a persistent file for diagnosis when stdout is piped away try: - import os as _os - from core import config as _cfg - _err_path = _os.path.join(_cfg.DATA_DIR, "consumer_error.log") + _err_path = os.path.join(config.DATA_DIR, "consumer_error.log") with open(_err_path, 'a', encoding='utf-8') as _f: - import datetime as _dt - _f.write(f"[{_dt.datetime.now()}] {msg}\n") + _f.write(f"[{datetime.utcnow().isoformat()}] {msg}\n") except Exception: pass @@ -122,8 +170,11 @@ _is_reloader_child = os.environ.get('WERKZEUG_RUN_MAIN') == 'true' _is_testing = os.environ.get('FLASK_TESTING') == '1' if not _is_reloader_child and not _is_testing: + _log("System: Launching Huey consumer thread...") _huey_thread = _threading.Thread(target=_start_huey_consumer, daemon=True, name="huey-consumer") _huey_thread.start() +else: + _log(f"System: Skipping Huey consumer (WERKZEUG_RUN_MAIN={os.environ.get('WERKZEUG_RUN_MAIN')}, FLASK_TESTING={os.environ.get('FLASK_TESTING')}).") if __name__ == "__main__": diff --git a/web/tasks.py b/web/tasks.py index 884e38a..e7b2d22 100644 --- a/web/tasks.py +++ b/web/tasks.py @@ -43,6 +43,13 @@ def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedba """ Background task to run the book generation. """ + import sys as _sys + def _task_log(msg): + """Print directly to stdout (docker logs) regardless of utils state.""" + print(f"[TASK run={run_id}] {msg}", flush=True, file=_sys.stdout) + + _task_log(f"Task picked up by Huey worker. project_path={project_path}") + # 1. Setup Logging log_filename = f"system_log_{run_id}.txt" @@ -54,8 +61,9 @@ def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedba try: with open(initial_log, 'a', encoding='utf-8') as _f: pass - except Exception: - pass + _task_log(f"Log file created: {initial_log}") + except Exception as _e: + _task_log(f"WARNING: Could not touch log file {initial_log}: {_e}") utils.set_log_file(initial_log) @@ -68,10 +76,12 @@ def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedba try: with sqlite3.connect(db_path, timeout=30, check_same_thread=False) as conn: conn.execute("UPDATE run SET status = 'running' WHERE id = ?", (run_id,)) + _task_log("Run status set to 'running' in DB.") except sqlite3.OperationalError as e: - utils.log("SYSTEM", f"⚠ī¸ Database locked when setting run status (run {run_id}): {e}") - except Exception: - pass + _task_log(f"WARNING: DB locked when setting run status: {e}") + utils.log("SYSTEM", f"Database locked when setting run status (run {run_id}): {e}") + except Exception as e: + _task_log(f"WARNING: Could not set run status: {e}") utils.log("SYSTEM", f"Starting Job #{run_id}") @@ -169,6 +179,9 @@ def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedba status = "completed" except Exception as e: + import traceback as _tb + _task_log(f"ERROR: Job failed — {type(e).__name__}: {e}") + _task_log(_tb.format_exc()) utils.log("ERROR", f"Job Failed: {e}") status = "failed" @@ -203,6 +216,7 @@ def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedba except Exception as e: print(f"Failed to update run status in DB: {e}") + _task_log(f"Task finished. status={status} cost=${total_cost:.4f}") return {"run_id": run_id, "status": status, "cost": total_cost, "final_log": final_log_path}