Auto-commit: v2.11 — Fix live UI log feed (db_log_callback + run_status)

- 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 <noreply@anthropic.com>

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)*

web/routes/run.py

@@ -74,23 +74,64 @@ def view_run(id):
 @run_bp.route('/run/<int:id>/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:
+        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') as f: log_content = f.read()
+                with open(run.log_file, 'r', encoding='utf-8', errors='replace') 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")
+                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') as f: log_content = f.read()
+                    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,

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):