From 0d4b9b761b0df4cfe97ff0c405504d448022be2d Mon Sep 17 00:00:00 2001 From: Mike Wichers Date: Sat, 21 Feb 2026 12:05:07 -0500 Subject: [PATCH] =?UTF-8?q?Auto-commit:=20v2.10=20=E2=80=94=20Docker=20dia?= =?UTF-8?q?gnostic=20logging=20for=20consumer=20&=20task=20execution?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - web/app.py: Startup banner to docker logs (Python version, platform, Huey version, DB paths). All print() calls now flush=True so Docker captures them immediately. Emoji-free for robust stdout encoding. Startup now detects orphaned queued runs (queue empty but DB queued) and resets them to 'failed' so the UI does not stay stuck on reload. Huey logging configured at INFO level so task pick-up/completion appears in `docker logs`. Consumer skip reason logged explicitly. - web/tasks.py: generate_book_task now emits [TASK run=N] lines to stdout (docker logs) at pick-up, log-file creation, DB status update, and on error (with full traceback) so failures are always visible. Co-Authored-By: Claude Sonnet 4.6 --- web/app.py | 85 +++++++++++++++++++++++++++++++++++++++++----------- web/tasks.py | 24 +++++++++++---- 2 files changed, 87 insertions(+), 22 deletions(-) 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}