From 99ba826be2dd266466aed57ee4f8c9f19dc13a7a Mon Sep 17 00:00:00 2001 From: ciregenz Date: Fri, 5 Jun 2026 16:12:32 -0700 Subject: [PATCH] [eric] backend: INFO logging visible in dev plus ms-level traces across the fast path --- backend/apps/agents/agent_manager.py | 10 ++++++++++ backend/apps/agents/browser/browser_fast_path.py | 7 ++++++- backend/apps/agents/browser/browser_fast_read.py | 12 ++++++++++-- backend/main.py | 12 ++++++++++++ 4 files changed, 38 insertions(+), 3 deletions(-) diff --git a/backend/apps/agents/agent_manager.py b/backend/apps/agents/agent_manager.py index 18835ce3..f7dbe45c 100644 --- a/backend/apps/agents/agent_manager.py +++ b/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", { diff --git a/backend/apps/agents/browser/browser_fast_path.py b/backend/apps/agents/browser/browser_fast_path.py index e83200ba..14339bb5 100644 --- a/backend/apps/agents/browser/browser_fast_path.py +++ b/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}") diff --git a/backend/apps/agents/browser/browser_fast_read.py b/backend/apps/agents/browser/browser_fast_read.py index 6c972123..5a7bf724 100644 --- a/backend/apps/agents/browser/browser_fast_read.py +++ b/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") diff --git a/backend/main.py b/backend/main.py index a4f3e124..4cac137d 100644 --- a/backend/main.py +++ b/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