[eric] backend: INFO logging visible in dev plus ms-level traces across the fast path

backend/apps/agents/agent_manager.py

@@ -3358,6 +3358,8 @@ class AgentManager:
         session = self.sessions.get(session_id)
         if not session:
             return
+        _fp_t0 = time.monotonic()
+        _fp_path = verdict
         logger.info(f"[browser-fast-path] direct dispatch for session {session_id} ({verdict})")
         text = ""
         try:
@@ -3371,6 +3373,8 @@ class AgentManager:
                 text = await browser_fast_read.try_fast_read(
                     prompt, brief, load_settings(), get_api_type(session.model),
                 ) or ""
+                if not text:
+                    _fp_path = "read->browser"
 
             async def _dispatch(task_text: str) -> str:
                 results = await run_browser_agents(
@@ -3390,8 +3394,10 @@ class AgentManager:
                     # retry identically, so skip it and tell the user instead.
                     if ws_manager.global_connections:
                         logger.info(f"[browser-fast-path] first dispatch failed for {session_id}; one recovery dispatch")
+                        _fp_path += "+recovery"
                         text = await _dispatch(browser_fast_path.recovery_task(prompt, text))
                     else:
+                        _fp_path += "+no-dashboard"
                         text = browser_fast_path.NO_DASHBOARD_REPLY
                 if not text:
                     text = "The browser agent couldn't complete this and gave no report."
@@ -3401,6 +3407,10 @@ class AgentManager:
             logger.warning(f"[browser-fast-path] dispatch failed: {e}")
             text = f"The browser agent couldn't complete this: {e}"
 
+        logger.info(
+            f"[browser-fast-path] session {session_id} done: path={_fp_path} "
+            f"reply={len(text)}ch in {int((time.monotonic() - _fp_t0) * 1000)}ms"
+        )
         asst_msg = Message(role="assistant", content=text, branch_id=session.active_branch_id)
         session.messages.append(asst_msg)
         await ws_manager.send_to_session(session_id, "agent:message", {

backend/apps/agents/browser/browser_fast_path.py

@@ -19,6 +19,7 @@ Three gates, all conservative; any miss falls through to the orchestrator:
 import asyncio
 import logging
 import re
+import time
 
 logger = logging.getLogger(__name__)
 
@@ -157,6 +158,7 @@ def _normalize_for_classifier(prompt: str) -> str:
 async def classify_and_brief(prompt: str, settings, primary_api: str | None) -> tuple[str, str]:
     """One cheap aux call returns a READ/ACT/NO verdict plus a routing brief
     (entry URL + step outline), timeboxed; any failure means NO (normal path)."""
+    t0 = time.monotonic()
     try:
         from backend.apps.settings.credentials import get_anthropic_client_for_model
         from backend.apps.agents.providers.registry import resolve_aux_model
@@ -177,7 +179,10 @@ async def classify_and_brief(prompt: str, settings, primary_api: str | None) ->
         )
         from backend.apps.agents.core.aux_llm import _safe_resp_text
         verdict, brief = _parse_verdict_and_brief(_safe_resp_text(resp))
-        logger.info(f"[browser-fast-path] classifier: {verdict.upper()} brief={len(brief)}ch")
+        logger.info(
+            f"[browser-fast-path] classifier: {verdict.upper()} brief={len(brief)}ch "
+            f"model={aux_model} in {int((time.monotonic() - t0) * 1000)}ms"
+        )
         return verdict, brief
     except Exception as e:
         logger.warning(f"[browser-fast-path] classifier unavailable, normal path: {e}")

backend/apps/agents/browser/browser_fast_read.py

@@ -9,6 +9,7 @@ old path, never a wrong answer from a thin read.
 import asyncio
 import logging
 import re
+import time
 
 logger = logging.getLogger(__name__)
 
@@ -43,18 +44,22 @@ async def try_fast_read(prompt: str, brief: str, settings, primary_api: str | No
     """Answer text on success; None means fall back to the browser leg."""
     entry = extract_entry_url(brief)
     if not entry:
+        logger.info("[browser-fast-read] no ENTRY url in brief; browser fallback")
         return None
     try:
         from backend.apps.agents.tools.web import WebFetchTool
 
+        t0 = time.monotonic()
         parts = await asyncio.wait_for(
             WebFetchTool().execute({"url": entry, "prompt": prompt}, None),
             timeout=12.0,
         )
         text = "\n".join(p.get("text", "") for p in parts if p.get("type") == "text")
+        fetch_ms = int((time.monotonic() - t0) * 1000)
         if page_is_thin(text):
-            logger.info(f"[browser-fast-read] thin/errored read of {entry}; browser fallback")
+            logger.info(f"[browser-fast-read] thin/errored read of {entry} ({len(text)}ch in {fetch_ms}ms); browser fallback")
             return None
+        logger.info(f"[browser-fast-read] fetched {entry}: {len(text)}ch in {fetch_ms}ms")
 
         from backend.apps.settings.credentials import get_anthropic_client_for_model
         from backend.apps.agents.providers.registry import resolve_aux_model
@@ -64,6 +69,7 @@ async def try_fast_read(prompt: str, brief: str, settings, primary_api: str | No
             settings, preferred_tier="haiku", primary_api=primary_api,
         )
         client = get_anthropic_client_for_model(settings, aux_model)
+        t1 = time.monotonic()
         resp = await asyncio.wait_for(
             client.messages.create(
                 model=aux_model,
@@ -78,9 +84,11 @@ async def try_fast_read(prompt: str, brief: str, settings, primary_api: str | No
             timeout=15.0,
         )
         answer = _safe_resp_text(resp).strip()
+        answer_ms = int((time.monotonic() - t1) * 1000)
         if not answer or answer.upper().startswith("INSUFFICIENT"):
-            logger.info(f"[browser-fast-read] aux found page insufficient; browser fallback")
+            logger.info(f"[browser-fast-read] aux found page insufficient ({answer_ms}ms); browser fallback")
             return None
+        logger.info(f"[browser-fast-read] answered in {answer_ms}ms ({len(answer)}ch, model={aux_model})")
         return f"{answer}\n\n(Source: {entry})"
     except Exception as e:
         logger.info(f"[browser-fast-read] failed ({e}); browser fallback")

backend/main.py

@@ -4,6 +4,18 @@ import logging
 import os
 from uuid import uuid4
 
+# App-level INFO logs (fast-path gates, skill recording, replay decisions) were
+# invisible because nothing configured the 'backend' logger; every debugging
+# session re-paid that blindness. Idempotent so uvicorn reloads don't stack
+# handlers; uvicorn's own access logs are untouched.
+_backend_logger = logging.getLogger("backend")
+if not _backend_logger.handlers:
+    _h = logging.StreamHandler()
+    _h.setFormatter(logging.Formatter("%(asctime)s %(levelname).1s %(name)s: %(message)s", "%H:%M:%S"))
+    _backend_logger.addHandler(_h)
+    _backend_logger.setLevel(logging.INFO)
+    _backend_logger.propagate = False
+
 logger = logging.getLogger(__name__)
 
 from fastapi.responses import JSONResponse, HTMLResponse