From 87f24d2bd88e7ae35434b69f90f6c58ac21664e7 Mon Sep 17 00:00:00 2001 From: Mike Wichers Date: Sat, 21 Feb 2026 15:28:27 -0500 Subject: [PATCH] =?UTF-8?q?Auto-commit:=20v2.11=20=E2=80=94=20Fix=20live?= =?UTF-8?q?=20UI=20log=20feed=20(db=5Flog=5Fcallback=20+=20run=5Fstatus)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - web/tasks.py: db_log_callback bare `except: break` replaced with explicit `except Exception as _e: print(...)` so insertion failures are visible in Docker logs. Also fixed datetime.utcnow() → .isoformat() for clean string storage in SQLite. Same fix applied to db_progress_callback. - web/routes/run.py (run_status): added db.session.expire_all() to force fresh reads; raw sqlite3 bypass query when ORM returns no rows; file fallback wrapped in try/except with stdout error reporting; secondary check for web_console.log inside the run directory; utf-8 encoding on all file opens. - ai_blueprint.md: bumped to v2.11, documented root causes and fixes. Co-Authored-By: Claude Sonnet 4.6 --- ai_blueprint.md | 3 ++- web/routes/run.py | 55 +++++++++++++++++++++++++++++++++++++++++------ web/tasks.py | 15 +++++++++---- 3 files changed, 61 insertions(+), 12 deletions(-) diff --git a/ai_blueprint.md b/ai_blueprint.md index b2ff621..a096b38 100644 --- a/ai_blueprint.md +++ b/ai_blueprint.md @@ -1,4 +1,4 @@ -# AI Context Optimization Blueprint (v2.10) +# AI Context Optimization Blueprint (v2.11) This blueprint outlines architectural improvements for how AI context is managed during the writing process. The goal is to provide the AI (Claude/Gemini) with **better, highly-targeted context upfront**, which will dramatically improve first-draft quality and reduce the reliance on expensive, time-consuming quality checks and rewrites (currently up to 5 attempts). @@ -172,3 +172,4 @@ The UI gets stuck indefinitely because the background Huey worker thread hangs b 12. ✅ **(v2.8)** Infrastructure & UI Bug Fixes: API timeouts (180s generation, 30s list_models) in `ai/models.py` + `ai/setup.py`; Huey consumer moved to module level with reloader guard in `web/app.py`; Jinja2 `UndefinedError` fix for `tropes`/`formatting_rules` in `project_setup.html`; `project_setup_wizard` now renders form instead of silent redirect when models fail; `create_project_final` `enrich()` call fixed to use correct per-book blueprint structure. *(Implemented v2.8)* 13. ✅ **(v2.9)** Background Task Hang Fixes: OAuth headless guard in `ai/setup.py` (skips `run_local_server` in non-main threads, logs warning, falls back to ADC); SQLite `timeout=30, check_same_thread=False` on all connections in `web/tasks.py`; initial log file touched immediately in `generate_book_task` so UI polling never sees an empty/missing file. *(Implemented v2.9)* 14. ✅ **(v2.10)** Huey Consumer Startup Fix: `Consumer.__init__()` in Huey 2.6.0 does NOT accept a `loglevel` keyword argument — the previous call `Consumer(huey, workers=1, worker_type='thread', loglevel=20)` raised `TypeError` on every app start, silently killing the consumer. All tasks stayed `queued` forever, causing the "Preparing environment / Waiting for logs" hang. Fixed by removing `loglevel=20`; Huey logging now configured via `logging.basicConfig`. Consumer startup errors now written to `data/consumer_error.log` for diagnosis. Also removed emoji characters from `print()` calls in `core/config.py` that caused `UnicodeEncodeError` on Windows `cp1252` terminals. Updated `VERSION` to `2.9` in `config.py`. *(Implemented v2.10)* +15. ✅ **(v2.11)** Live UI Log Feed Fix: The web UI status bar and console log were not updating even though the task was executing (ARCHITECT phase visible in Docker logs). Two root causes: (1) `db_log_callback` in `web/tasks.py` used a bare `except: break` that silently swallowed any non-OperationalError insertion failure — fixed to print `[db_log_callback ERROR]` to stdout with exception type and message. Also changed `datetime.utcnow()` → `datetime.utcnow().isoformat()` to ensure clean string storage. (2) `run_status` in `web/routes/run.py` only read `LogEntry` via SQLAlchemy ORM (potentially stale session) and its file fallback had no error visibility — fixed by: adding `db.session.expire_all()` at request start to force fresh DB reads; adding a raw sqlite3 bypass query that runs if ORM returns no rows; wrapping the file fallback in try/except that prints errors to stdout; adding a secondary check for `runs/run_{id}/web_console.log` (created after engine starts); encoding `utf-8, errors='replace'` on all file opens. *(Implemented v2.11)* diff --git a/web/routes/run.py b/web/routes/run.py index 58048fc..16c546f 100644 --- a/web/routes/run.py +++ b/web/routes/run.py @@ -74,23 +74,64 @@ def view_run(id): @run_bp.route('/run//status') @login_required def run_status(id): - run = db.session.get(Run, id) or Run.query.get_or_404(id) + import sqlite3 as _sql3 + import sys as _sys + from core import config as _cfg + + # Expire session so we always read fresh values from disk (not cached state) + db.session.expire_all() + run = db.session.get(Run, id) + if not run: + return {"status": "not_found", "log": "", "cost": 0, "percent": 0, "start_time": None}, 404 log_content = "" last_log = None + # 1. ORM query for log entries logs = LogEntry.query.filter_by(run_id=id).order_by(LogEntry.timestamp).all() if logs: log_content = "\n".join([f"[{l.timestamp.strftime('%H:%M:%S')}] {l.phase:<15} | {l.message}" for l in logs]) last_log = logs[-1] + # 2. Raw sqlite3 fallback — bypasses any SQLAlchemy session caching if not log_content: - if run.log_file and os.path.exists(run.log_file): - with open(run.log_file, 'r') as f: log_content = f.read() - elif run.status in ['queued', 'running']: - temp_log = os.path.join(run.project.folder_path, f"system_log_{run.id}.txt") - if os.path.exists(temp_log): - with open(temp_log, 'r') as f: log_content = f.read() + try: + _db_path = os.path.join(_cfg.DATA_DIR, "bookapp.db") + with _sql3.connect(_db_path, timeout=5) as _conn: + _rows = _conn.execute( + "SELECT timestamp, phase, message FROM log_entry WHERE run_id = ? ORDER BY timestamp", + (id,) + ).fetchall() + if _rows: + log_content = "\n".join([ + f"[{str(r[0])[:8]}] {str(r[1]):<15} | {r[2]}" + for r in _rows + ]) + except Exception as _e: + print(f"[run_status] sqlite3 fallback error for run {id}: {type(_e).__name__}: {_e}", flush=True, file=_sys.stdout) + + # 3. File fallback — reads the log file written by the task worker + if not log_content: + try: + if run.log_file and os.path.exists(run.log_file): + with open(run.log_file, 'r', encoding='utf-8', errors='replace') as f: + log_content = f.read() + elif run.status in ['queued', 'running']: + project_folder = run.project.folder_path + # Temp log written at task start (before run dir exists) + temp_log = os.path.join(project_folder, f"system_log_{run.id}.txt") + if os.path.exists(temp_log): + with open(temp_log, 'r', encoding='utf-8', errors='replace') as f: + log_content = f.read() + else: + # Also check inside the run directory (after engine creates it) + run_dir = os.path.join(project_folder, "runs", f"run_{run.id}") + console_log = os.path.join(run_dir, "web_console.log") + if os.path.exists(console_log): + with open(console_log, 'r', encoding='utf-8', errors='replace') as f: + log_content = f.read() + except Exception as _e: + print(f"[run_status] file fallback error for run {id}: {type(_e).__name__}: {_e}", flush=True, file=_sys.stdout) response = { "status": run.status, diff --git a/web/tasks.py b/web/tasks.py index e7b2d22..dcaba82 100644 --- a/web/tasks.py +++ b/web/tasks.py @@ -18,25 +18,32 @@ huey = SqliteHuey('bookapp_queue', filename=os.path.join(config.DATA_DIR, 'queue def db_log_callback(db_path, run_id, phase, msg): """Writes log entry directly to SQLite to avoid Flask Context issues in threads.""" + import sys as _sys for _ in range(5): try: with sqlite3.connect(db_path, timeout=30, check_same_thread=False) as conn: conn.execute("INSERT INTO log_entry (run_id, timestamp, phase, message) VALUES (?, ?, ?, ?)", - (run_id, datetime.utcnow(), phase, str(msg))) + (run_id, datetime.utcnow().isoformat(), phase, str(msg))) break except sqlite3.OperationalError: time.sleep(0.1) - except: break + except Exception as _e: + print(f"[db_log_callback ERROR run={run_id}] {type(_e).__name__}: {_e}", flush=True, file=_sys.stdout) + break def db_progress_callback(db_path, run_id, percent): """Updates run progress in SQLite.""" + import sys as _sys for _ in range(5): try: with sqlite3.connect(db_path, timeout=30, check_same_thread=False) as conn: conn.execute("UPDATE run SET progress = ? WHERE id = ?", (percent, run_id)) break - except sqlite3.OperationalError: time.sleep(0.1) - except: break + except sqlite3.OperationalError: + time.sleep(0.1) + except Exception as _e: + print(f"[db_progress_callback ERROR run={run_id}] {type(_e).__name__}: {_e}", flush=True, file=_sys.stdout) + break @huey.task() def generate_book_task(run_id, project_path, bible_path, allow_copy=True, feedback=None, source_run_id=None, keep_cover=False, exclude_folders=None):