diff --git a/CHANGELOG.md b/CHANGELOG.md index ddd5a072..8e63b34e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,10 @@ ### Fixed +- **HTTP access logs survive agent stdout capture.** Agent and tool code replaces or closes `sys.stdout` to capture subprocess output, and the server's per-request access records were being swallowed into that capture instead of reaching the service log — so requests made while a tool was running simply vanished from the log. Access-log records now go through a dedicated writer that owns its own duplicate of the process's original stdout descriptor, taken at import time before any agent code loads, so replacing or closing Python's `sys.stdout` can no longer intercept them. Delivery is proven end to end by a subprocess test that redirects and then closes `sys.stdout` and still observes the records on the real process stdout. Record format, destination and ordering are unchanged for a normal launch, the write is guarded so a broken sink can never break an HTTP response, and `SIGPIPE` is already ignored before serving starts. Thanks @DevNexsler. (#7643, #2684) + +- **The session list stops re-resolving the same profile home once per row.** Building the sidebar's session list called `_resolve_profile_home_param()` for every projected row, and each call did a real filesystem resolve of the same path — a production trace pinned 5-17 s of a slow `/api/session` build to that one call site, reached through `Session.__init__` on every sidecar-metadata cache miss. The resolve is now memoized for the duration of a single session-list build via a call-scoped `ContextVar` entered by `_load_cli_sessions_uncached`, so N rows sharing a profile pay one resolve instead of N. Outside that scope the memo is inert, so nothing else in the process can serve a cached path, and the scope is released on exit including on exception — a value resolved under one profile can never be served to another. The active workspace is hoisted the same way, since it returns the same value for every row in a scan. Thanks @totalitarian. (#7636) + - **Server-side speech now honors the TTS engine you configured.** `POST /api/tts` only ever consulted the `engine` field on the request body, so any caller that omitted it — an extension, a native client, a script — silently fell back to Edge regardless of the `tts_engine` saved in Settings. A request that omits `engine` (or sends a whitespace-only value) now inherits the persisted engine, resolved before the provider branches run. An explicit request engine still wins, and a persisted value the server cannot use — `browser`, an extension-only engine, an unknown string, a non-string — still collapses to the historical Edge fallback, because browser speech synthesis has no server-side counterpart. The first-party WebUI callers are unchanged: both now send `engine` explicitly, verified by driving the real production request builders and asserting the outgoing body. Thanks @mvanhorn. (#7394, #7391) - **Session responses stop redoing the same redaction work on every request.** Redacting a session payload rescanned every string from scratch on each `/api/session` call, including large unchanged transcript bodies that can never contain a secret. Two caches now sit in front of that work: a bounded LRU for large strings and a memoized prefilter that skips values with no candidate pattern, with clean values returned without a copy. Correctness is preserved across runtime policy changes — a plugin calling `register_redaction_patterns()` mid-process invalidates both caches, so a newly registered secret pattern cannot be bypassed by a cached pre-registration result, and the cache is bounded by object size as well as entry count so a single oversized value cannot pin memory. Thanks @ruizanthony. (#7276) diff --git a/api/models.py b/api/models.py index eca27ab5..43ae4720 100644 --- a/api/models.py +++ b/api/models.py @@ -35,7 +35,7 @@ from api.config import ( LOCK, STREAMS, STREAMS_LOCK, DEFAULT_WORKSPACE, DEFAULT_MODEL, PROJECTS_FILE, HOME, get_effective_default_model, _get_session_agent_lock, ) -from api.workspace import get_last_workspace, _resolve_path +from api.workspace import get_last_workspace, _resolve_path, profile_home_resolve_cache_scope from api.usage import prompt_cache_hit_percent from api.agent_sessions import ( _is_continuation_session, @@ -7708,6 +7708,7 @@ def _state_projection_sidecar_metadata(sid: str) -> dict: return dict(metadata) +@profile_home_resolve_cache_scope() def _load_cli_sessions_uncached( hermes_home: Path, db_path: Path, @@ -8005,7 +8006,7 @@ def _load_cli_sessions_uncached( cli_sessions.append({ 'session_id': sid, 'title': _display_title, - 'workspace': str(get_last_workspace(profile=_cli_profile)), + 'workspace': _cli_workspace(), 'model': row['model'] or None, 'message_count': row['message_count'] or row['actual_message_count'] or 0, 'created_at': row['started_at'], diff --git a/api/request_logging.py b/api/request_logging.py new file mode 100644 index 00000000..df9df817 --- /dev/null +++ b/api/request_logging.py @@ -0,0 +1,26 @@ +"""Request output independent of agent/tool stdout capture.""" + +import os +import threading + + +# Import before agent code. Own the descriptor so replacing or closing Python's +# sys.stdout cannot capture access/error records intended for the service log. +try: + _STREAM = os.fdopen( + os.dup(1), "w", encoding="utf-8", errors="backslashreplace", buffering=1, + ) +except OSError: + _STREAM = None +_LOCK = threading.Lock() + + +def emit_request_log(message: str) -> None: + """Flush one complete record without letting a broken sink break HTTP.""" + try: + if _STREAM is not None: + with _LOCK: + _STREAM.write(message + "\n") + _STREAM.flush() + except Exception: + pass diff --git a/api/workspace.py b/api/workspace.py index d8ffb282..511aa9f1 100644 --- a/api/workspace.py +++ b/api/workspace.py @@ -19,6 +19,8 @@ import stat import subprocess import sys import concurrent.futures +import contextlib +import contextvars import threading import time from collections.abc import Callable @@ -207,6 +209,80 @@ def _is_remote_terminal_backend(terminal_cfg: dict | None) -> bool: return backend not in ('', 'local') +# Call-scoped cache for `_resolve_profile_home_param`'s filesystem +# `.resolve()` call. The webui's session list builds one `Session` per CLI +# session row (`_load_cli_sessions_uncached`), and `Session.__init__` calls +# `_resolve_profile_home_param(profile)` once per row -- with only one +# profile in play (the common case) that is the SAME path resolved hundreds +# of times per request. Individually a resolve() is ~1ms, but at a few +# hundred sessions this compounded into multi-second sidebar hangs under +# host load (confirmed via repeated "Slow WebUI request still running" +# warnings pinned to this call site). +# +# IMPORTANT: this is deliberately NOT a process-lifetime cache. An earlier +# revision of this fix cached forever, on the premise that a profile +# argument always resolves to the same path for the life of the process -- +# but `Path.resolve()` is a filesystem call, not a pure function of +# startup constants: a profile-home symlink can be retargeted while the +# webui process keeps running for days/weeks, and `_safe_resolve()` below +# deliberately falls back to returning the UNRESOLVED input after a +# transient `OSError`/`RuntimeError`/`ValueError`, which a process-lifetime +# cache would then serve forever. Both are real correctness bugs (caught in +# PR #7636 review), not style nitpicks. +# +# Instead the cache is scoped to exactly ONE invocation of the hot loop +# (`_load_cli_sessions_uncached`, wrapped below in `profile_home_resolve_cache_scope`) +# via a `ContextVar` that holds a fresh dict only while that single +# sidebar-list build is running, and is `None` everywhere else. Every other +# call site -- and every request that isn't actively inside that one +# build -- resolves fresh every time, exactly like pre-PR behavior, so a +# symlink retarget or a transient resolve error is never masked past the +# single call that would have paid for the redundant resolves anyway. +_PROFILE_HOME_RESOLVE_SCOPE: "contextvars.ContextVar[dict[Path, Path] | None]" = ( + contextvars.ContextVar("_PROFILE_HOME_RESOLVE_SCOPE", default=None) +) + + +@contextlib.contextmanager +def profile_home_resolve_cache_scope(): + """Enable memoization of `_resolve_profile_home_param` for one call. + + Use as a decorator (or a `with` block) around the single hot-path + operation that resolves the SAME profile argument hundreds of times in a + tight loop -- currently `_load_cli_sessions_uncached` building the + CLI/cron session list. While active, repeated resolves of the same + profile argument are served from a dict that lives ONLY for the + duration of the call. Outside of it -- including before/after, and any + call site other than the one wrapped -- `_resolve_profile_home_param` + resolves fresh every time, with no caching, matching pre-PR behavior + exactly. Nested/reentrant use restores the previous (outer) value on + exit rather than clobbering it, so this is safe to nest. + """ + token = _PROFILE_HOME_RESOLVE_SCOPE.set({}) + try: + yield + finally: + _PROFILE_HOME_RESOLVE_SCOPE.reset(token) + + +def _cached_safe_resolve_profile_home(pre_resolve: Path) -> Path: + """`_safe_resolve()` for profile-home paths. + + Memoized only while a `profile_home_resolve_cache_scope()` is active + (see module doc above); otherwise resolves fresh every call, matching + pre-PR behavior. + """ + cache = _PROFILE_HOME_RESOLVE_SCOPE.get() + if cache is None: + return _safe_resolve(pre_resolve) + cached = cache.get(pre_resolve) + if cached is not None: + return cached + resolved = _safe_resolve(pre_resolve) + cache[pre_resolve] = resolved + return resolved + + def _resolve_profile_home_param(profile: str | Path | None) -> Path: """Resolve a profile parameter (name string, directory path string, or Path) to a profile home Path. @@ -244,14 +320,14 @@ def _resolve_profile_home_param(profile: str | Path | None) -> Path: raw = str(profile).strip() if isinstance(profile, Path): - return _safe_resolve(profile.expanduser()) + return _cached_safe_resolve_profile_home(profile.expanduser()) # Strings are LOGICAL PROFILE IDS ONLY — no path-shaped strings, ever. if not _PROFILE_NAME_RE.fullmatch(raw): raise ValueError(f"invalid profile name: {raw!r}") from api.profiles import get_hermes_home_for_profile - return _safe_resolve(get_hermes_home_for_profile(raw)) + return _cached_safe_resolve_profile_home(get_hermes_home_for_profile(raw)) def _is_default_profile_home(profile_home: Path) -> bool: diff --git a/docs/CONTRACTS.md b/docs/CONTRACTS.md index 46f66fa7..2989b587 100644 --- a/docs/CONTRACTS.md +++ b/docs/CONTRACTS.md @@ -89,6 +89,14 @@ contributor guidance; it does not change runtime behavior or CI gates. `models_cache.json` refresh timestamps), the stat-identity fallbacks, and the schema/version stamps. Start here before changing model-catalog caching, the `/api/models` cache keys, or the Codex catalog dependency (#2443, #7540). +- [`docs/architecture/profile-home-resolve-cache.md`](architecture/profile-home-resolve-cache.md): + current contract for the call-scoped memoization around + `_resolve_profile_home_param()` in `api/workspace.py`: what it caches, the + one-hot-loop scope (`_load_cli_sessions_uncached`) versus every other call + site getting fresh resolution, and the freshness guarantee that a symlink + retarget or transient resolve fallback is always observed on the next call. + Start here before widening this cache's scope or adding a similar + call-scoped cache elsewhere (#7636). When a change touches streaming, recovery, replay, compression, context reconstruction, cancellation, approval/clarify, session metadata, or run state, diff --git a/docs/architecture/profile-home-resolve-cache.md b/docs/architecture/profile-home-resolve-cache.md new file mode 100644 index 00000000..8ed97e58 --- /dev/null +++ b/docs/architecture/profile-home-resolve-cache.md @@ -0,0 +1,87 @@ +# Profile-home resolve call-scoped cache (`api/workspace.py`) + +This document records the current scope, ownership, and freshness contract for +the call-scoped memoization added around `_resolve_profile_home_param()` in +`api/workspace.py`. It describes shipped behavior and changes no runtime +behavior. It was added after PR #7636 review flagged this cache lifecycle as +an undocumented runtime contract. + +## What is cached + +- **What:** the resolved `Path` returned by `_safe_resolve()` for a given + pre-resolve profile-home `Path`, inside `_cached_safe_resolve_profile_home()`. +- **Key:** the unresolved profile-home `Path` passed in. +- **Store:** a plain `dict[Path, Path]` held by the + `_PROFILE_HOME_RESOLVE_SCOPE` `contextvars.ContextVar`, which defaults to + `None` (no active scope). + +## Scope: one call, not the process lifetime + +The cache is deliberately **call-scoped**, not process-lifetime. It exists only +for the duration of one wrapped call to `_load_cli_sessions_uncached` — the +CLI/cron sidebar session-list build that resolves the same profile argument +once per `Session` row (hundreds of times per request in the common case, +which is the N+1 this cache fixes). `profile_home_resolve_cache_scope()` sets +the `ContextVar` to a fresh `{}` on entry and resets it to the previous value +in a `finally` block on exit, so no cache entry survives past the single call +it was created for. An earlier revision of this fix cached for the life of the +process; that was reverted in review (see #7636) because `Path.resolve()` is a +filesystem call, not a pure function of process-startup constants. + +## Ownership: which call sites get caching + +- `profile_home_resolve_cache_scope()` is applied, as a decorator, to exactly + one call site today: `_load_cli_sessions_uncached` in `api/models.py`. +- Every other caller of `_resolve_profile_home_param()` / + `_cached_safe_resolve_profile_home()` — and every call to those functions + from outside an active scope, including calls that happen before or after + the one wrapped call — gets **no caching**: `_PROFILE_HOME_RESOLVE_SCOPE.get()` + returns `None`, and `_cached_safe_resolve_profile_home()` falls straight + through to a fresh `_safe_resolve()` call, exactly matching pre-PR behavior. +- Nested/reentrant use of `profile_home_resolve_cache_scope()` restores the + previous (outer) value on exit rather than clobbering it, so nesting is safe + but still never leaks a cache entry past the scope that created it. + +## Freshness guarantee + +Because the cache is call-scoped and discarded in `finally` after each use, a +profile-home symlink retarget or a transient `_safe_resolve()` fallback +(`OSError`/`RuntimeError`/`ValueError`, which deliberately returns the +unresolved input) is always observed fresh on the **next** call — the cache +never outlives the call that populated it. The only staleness window is +*within* a single call, i.e. across the hundreds of `Session` rows built by one +`_load_cli_sessions_uncached` invocation — which is correct and intended, since +nothing about a profile's home path should change mid-call. + +## Change protocol + +1. If a new hot loop needs this memoization, wrap it with + `profile_home_resolve_cache_scope()` (as a decorator or a `with` block) at + its own call boundary — do not widen the existing scope on + `_load_cli_sessions_uncached` to also cover unrelated code. +2. Do not turn this into a process-lifetime or otherwise longer-lived cache. + The scoping is the fix for the correctness bugs described above, not an + incidental detail. +3. This is a runtime contract: changes here update this document and are + described in the PR body. + +## Tests + +`tests/test_profile_home_resolve_caching.py` covers: repeated resolves within +one scope hit the cache once +(`test_resolve_profile_home_param_caches_within_one_scope`, +`test_resolve_profile_home_param_caches_within_one_scope_for_profile_name`); +two separate scopes never share state, so a symlink change between them is +observed on the second scope +(`test_cache_does_not_persist_across_separate_scopes`); calls outside any +scope never cache at all (`test_no_caching_outside_any_scope`); the decorator +is actually wired onto `_load_cli_sessions_uncached` +(`test_scope_decorator_use_matches_load_cli_sessions_uncached_wiring`); and the +N+1 fix itself, both that it dedupes resolves on a cold sidecar-cache miss +(`test_load_cli_sessions_uncached_dedupes_profile_home_resolve_on_sidecar_cache_miss`) +and that resolve calls scale linearly with the fix disabled +(`test_load_cli_sessions_uncached_profile_home_resolve_scales_with_fix_disabled`). + +## References + +PR: #7636. diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index f3335f98..35cba162 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -6,6 +6,26 @@ If your symptom isn't listed and the diagnostics don't narrow it down, file a bu --- +## Requests succeed but access records disappear during agent work + +The server emits `[webui]` JSON access records to its original process stdout, +using a private duplicate captured before agent imports. This keeps request and +HTTP error logs visible when an in-process tool redirects or closes `sys.stdout`. +Logging failures still must not interrupt HTTP responses. + +Check the service's captured stdout (for example, `docker logs ` or +the journal for your WebUI unit). Verify successful `POST /api/chat/start` and +`GET /api/chat/stream` records, not only health probes or rejected requests. +Records include `method`, `path`, `status`, and `ms`: elapsed time until response +headers, **not** the lifetime of an SSE stream or the agent turn. A missing record +before response headers does not distinguish a pending request from a logging +failure. Keep the launcher's output destination open for the process lifetime. + +Scheduled cron execution belongs to the Hermes Agent gateway scheduler, not the +WebUI HTTP server. Investigate cron outcomes in the gateway's logs and the +active Hermes home's `cron/executions.db`; WebUI access records show HTTP cron +management requests, not every scheduled execution. + ## "AIAgent not available -- check that hermes-agent is on sys.path" **Symptom.** WebUI starts, shows the chat interface, but every chat request fails immediately with this error in the response or the server log. As of v0.51.6 the error includes a diagnostic block with the running Python interpreter, the relevant `sys.path` entries, and the most-common fix; on older versions the message is bare. diff --git a/server.py b/server.py index 364d5988..040d80c1 100644 --- a/server.py +++ b/server.py @@ -99,6 +99,7 @@ from urllib.parse import urlparse logger = logging.getLogger(__name__) +from api.request_logging import emit_request_log from api.auth import check_auth, reset_trusted_auth_request_state from api.config import HOST, PORT, STATE_DIR, SESSION_DIR, DEFAULT_WORKSPACE from api.helpers import ( @@ -338,10 +339,7 @@ class Handler(BaseHTTPRequestHandler): @staticmethod def _safe_webui_print(message: str) -> None: """Emit a request log line without letting logging break responses.""" - try: - print(message, flush=True) - except Exception: - pass + emit_request_log(message) def log_request(self, code: str='-', size: str='-') -> None: """Structured JSON logs for each request.""" diff --git a/tests/test_access_log_delivery.py b/tests/test_access_log_delivery.py new file mode 100644 index 00000000..9096d925 --- /dev/null +++ b/tests/test_access_log_delivery.py @@ -0,0 +1,92 @@ +"""Access records must reach the process output, even during agent capture.""" + +import json +import os +from pathlib import Path +import subprocess +import sys +import textwrap + +import pytest + + +@pytest.mark.parametrize("capture", ["redirected", "closed"]) +def test_successful_chat_start_delivers_access_record(tmp_path, capture): + # A subprocess tests the delivered fd text, not an internal counter or a + # patched print. Keep the real chat route and HTTP response/logging stack; + # replace only model discovery and execution with deterministic fixtures. + script = textwrap.dedent(''' + import io + import json + import sys + import threading + import time + from unittest.mock import patch + from server import Handler + from api import routes + from api.models import Session + + handler = Handler.__new__(Handler) + handler.command = "POST" + handler.path = "/api/chat/start" + handler.requestline = "POST /api/chat/start HTTP/1.1" + handler.request_version = "HTTP/1.1" + handler.client_address = ("127.0.0.1", 12345) + handler.headers = {} + handler.wfile = io.BytesIO() + handler._req_t0 = time.time() + session = Session(session_id="log-delivery", model="fixture") + original = sys.stdout + captured = io.StringIO() + if sys.argv[1] == "closed": + captured.close() + + def start_run(session, **kwargs): + # Agent tool capture can redirect stdout from another thread before + # chat/start writes its acceptance response. + def capture_output(): + sys.stdout = captured + worker = threading.Thread(target=capture_output) + worker.start() + worker.join() + return {"stream_id": "log-stream", "session_id": session.session_id} + + try: + with ( + patch.object(routes, "_agent_runtime_barrier_response", return_value=None), + patch.object(routes, "_get_or_materialize_session", return_value=session), + patch.object(routes, "_resolve_chat_workspace_with_recovery", return_value="/tmp"), + patch.object(routes, "_read_profile_model_config", return_value=(None, "fixture", {})), + patch.object(routes, "get_config", return_value={}), + patch.object(routes, "_resolve_compatible_session_model_state", return_value=("fixture", None, False)), + patch.object(routes, "_start_run", side_effect=start_run), + ): + routes._handle_chat_start(handler, {"session_id": session.session_id, "message": "wake"}) + finally: + sys.stdout = original + response = handler.wfile.getvalue() + assert b"HTTP/1.1 200" in response, response + assert json.loads(response.split(b"\\r\\n\\r\\n", 1)[1])["stream_id"] == "log-stream" + ''') + env = { + "PATH": os.environ["PATH"], + "HOME": str(tmp_path), + "HERMES_HOME": str(tmp_path / "home"), + "HERMES_WEBUI_STATE_DIR": str(tmp_path / "state"), + "HERMES_WEBUI_TEST_NETWORK_BLOCK": "1", + } + result = subprocess.run( + [sys.executable, "-c", script, capture], + cwd=Path(__file__).resolve().parents[1], env=env, + capture_output=True, text=True, timeout=30, + ) + assert result.returncode == 0, result.stderr + records = [ + json.loads(line.removeprefix("[webui] ")) + for line in result.stdout.splitlines() if line.startswith("[webui] ") + ] + assert len(records) == 1, f"Successful chat/start lost its access record: {result.stdout!r}" + assert records[0]["method"] == "POST" + assert records[0]["path"] == "/api/chat/start" + assert records[0]["status"] == 200 + assert records[0]["ms"] >= 0 diff --git a/tests/test_issue2775_log_request.py b/tests/test_issue2775_log_request.py index 687c1830..0bfbb0e2 100644 --- a/tests/test_issue2775_log_request.py +++ b/tests/test_issue2775_log_request.py @@ -1,16 +1,26 @@ import json +import io + +import pytest from server import Handler -def test_log_request_handles_malformed_request_without_path(capsys): +@pytest.fixture +def log_output(monkeypatch): + output = io.StringIO() + monkeypatch.setattr("api.request_logging._STREAM", output) + return output + + +def test_log_request_handles_malformed_request_without_path(log_output): """Malformed request lines can call log_request before path is assigned.""" handler = Handler.__new__(Handler) handler.command = None Handler.log_request(handler, "400") - line = capsys.readouterr().out.strip() + line = log_output.getvalue().strip() assert line.startswith("[webui] ") record = json.loads(line.removeprefix("[webui] ")) assert record["method"] == "-" @@ -19,7 +29,7 @@ def test_log_request_handles_malformed_request_without_path(capsys): assert record["remote"] == "-" -def test_log_request_includes_remote_address(capsys): +def test_log_request_includes_remote_address(log_output): handler = Handler.__new__(Handler) handler.command = "POST" handler.path = "/api/auth/login" @@ -28,13 +38,13 @@ def test_log_request_includes_remote_address(capsys): Handler.log_request(handler, "401") - line = capsys.readouterr().out.strip() + line = log_output.getvalue().strip() record = json.loads(line.removeprefix("[webui] ")) assert record["remote"] == "192.0.2.10" assert "forwarded_for" not in record -def test_log_request_includes_first_forwarded_for_address(capsys): +def test_log_request_includes_first_forwarded_for_address(log_output): class Headers: def get(self, key): assert key == "X-Forwarded-For" @@ -48,7 +58,7 @@ def test_log_request_includes_first_forwarded_for_address(capsys): Handler.log_request(handler, "401") - line = capsys.readouterr().out.strip() + line = log_output.getvalue().strip() record = json.loads(line.removeprefix("[webui] ")) assert record["remote"] == "192.0.2.10" assert record["forwarded_for"] == "203.0.113.7" diff --git a/tests/test_profile_home_resolve_caching.py b/tests/test_profile_home_resolve_caching.py new file mode 100644 index 00000000..b41cc531 --- /dev/null +++ b/tests/test_profile_home_resolve_caching.py @@ -0,0 +1,349 @@ +"""Regression test: `_resolve_profile_home_param` memoizes its filesystem +`.resolve()` call, but ONLY for the duration of a single +`profile_home_resolve_cache_scope()` (currently wrapping +`_load_cli_sessions_uncached`, the sidebar's session-list build). + +Building the CLI session list calls `_resolve_profile_home_param(profile)` +once per session row (`Session.__init__`), so with hundreds of sessions on +the same profile the unscoped code redundantly re-resolved the identical +path via a filesystem `.resolve()` on every single row. + +An earlier revision of this fix cached the result in a plain process-lifetime +module dict. That was flagged in PR #7636 review: `Path.resolve()` is a +filesystem call, not a pure function of process-startup constants -- a +profile-home symlink can be retargeted while the webui process keeps +running, and `_safe_resolve()` deliberately falls back to the UNRESOLVED +input after a transient error, so a process-lifetime cache could serve a +stale or wrong path for the rest of the process's life. + +This file tests the corrected, call-scoped design: + (a) within one scope, repeated resolves of the same argument hit the cache + (single underlying `_safe_resolve()` call) -- same benefit as before. + (b) across two SEPARATE scopes (simulating two different requests/list + builds), the cache does NOT persist -- `_safe_resolve()` runs again + fresh on the second scope, proving no cross-request staleness. + (c) outside any scope, `_resolve_profile_home_param` resolves fresh every + time with no caching at all, matching pre-PR behavior exactly. +""" +import sys +from pathlib import Path +from unittest.mock import patch + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +import api.workspace as ws # noqa: E402 +import api.models as models # noqa: E402 + + +def test_resolve_profile_home_param_caches_within_one_scope(tmp_path): + """(a) Same as the original test, but the cache now requires an active scope.""" + home_dir = tmp_path / "profile_home" + home_dir.mkdir() + + with patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as spy: + with ws.profile_home_resolve_cache_scope(): + first = ws._resolve_profile_home_param(home_dir) + second = ws._resolve_profile_home_param(home_dir) + third = ws._resolve_profile_home_param(home_dir) + + assert first == second == third == home_dir.resolve() + assert spy.call_count == 1, ( + "expected the filesystem resolve() to run once within one scope and " + f"be served from cache thereafter, but it ran {spy.call_count} times" + ) + + +def test_resolve_profile_home_param_caches_within_one_scope_for_profile_name(tmp_path): + """(a), second branch: a logical profile-NAME STRING (not a Path) resolves + + through `get_hermes_home_for_profile()` before hitting the same + `_cached_safe_resolve_profile_home()` memoization. Confirms the + within-scope cache is genuinely hit for named profiles too, not just + explicit Path callers. + """ + home_dir = tmp_path / "named_profile_home" + home_dir.mkdir() + + with patch("api.profiles.get_hermes_home_for_profile", return_value=home_dir), \ + patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as spy: + with ws.profile_home_resolve_cache_scope(): + first = ws._resolve_profile_home_param("myprofile") + second = ws._resolve_profile_home_param("myprofile") + third = ws._resolve_profile_home_param("myprofile") + + assert first == second == third == home_dir.resolve() + assert spy.call_count == 1, ( + "expected the filesystem resolve() to run once within one scope and " + f"be served from cache thereafter, but it ran {spy.call_count} times" + ) + + +def test_cache_does_not_persist_across_separate_scopes(tmp_path): + """(b) Two separate scoped calls (simulating two different requests) must + + NOT share a cache -- the whole point of the PR #7636 review fix. If a + symlink were retargeted between the two "requests", the second scope + must be free to observe the new target; that's only possible if + `_safe_resolve()` is invoked again fresh on scope #2. + """ + home_dir = tmp_path / "profile_home" + home_dir.mkdir() + + with patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as spy: + with ws.profile_home_resolve_cache_scope(): + ws._resolve_profile_home_param(home_dir) + ws._resolve_profile_home_param(home_dir) + assert spy.call_count == 1 + + # Second, separate scope -- simulates a later, independent request. + with ws.profile_home_resolve_cache_scope(): + ws._resolve_profile_home_param(home_dir) + ws._resolve_profile_home_param(home_dir) + + assert spy.call_count == 2, ( + "expected the second scope to re-resolve fresh (no cross-scope/" + f"cross-request caching), but _safe_resolve ran {spy.call_count} times total" + ) + + +def test_no_caching_outside_any_scope(tmp_path): + """(c) Outside a scope, every call resolves fresh -- matching pre-PR + + behavior exactly, since most call sites of `_resolve_profile_home_param` + are NOT the sidebar list-build hot loop and must never see a cached + (possibly stale) result. + """ + home_dir = tmp_path / "profile_home" + home_dir.mkdir() + + with patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as spy: + first = ws._resolve_profile_home_param(home_dir) + second = ws._resolve_profile_home_param(home_dir) + third = ws._resolve_profile_home_param(home_dir) + + assert first == second == third == home_dir.resolve() + assert spy.call_count == 3, ( + "expected every call outside an active scope to resolve fresh with " + f"no caching, but _safe_resolve ran {spy.call_count} times for 3 calls" + ) + + +def test_scope_decorator_use_matches_load_cli_sessions_uncached_wiring(): + """Sanity check that `profile_home_resolve_cache_scope()` is usable as a + + decorator (the way it wraps `_load_cli_sessions_uncached` in + `api/models.py`), and that the ContextVar is active only during the + decorated call. + """ + assert ws._PROFILE_HOME_RESOLVE_SCOPE.get() is None + + @ws.profile_home_resolve_cache_scope() + def _inside(): + return ws._PROFILE_HOME_RESOLVE_SCOPE.get() + + cache_during_call = _inside() + assert cache_during_call is not None + assert ws._PROFILE_HOME_RESOLVE_SCOPE.get() is None + + +def _make_cli_sessions_uncached_fixture(tmp_path, n, *, message_count=3): + """state.db + matching MODERN WebUI sidecars (message_count present in the + prefix, literal 'default' profile string -- exactly what real production + sidecars carry, confirmed against a live deployment's webui/sessions/*.json) + for `n` cron rows. + + A "modern" sidecar (one that carries `message_count` in its JSON-prefix) + is required to reach the fast branch of `Session.load_metadata_only()` + (a single `Session(**parsed)` construction) instead of falling back to the + legacy `cls.load()` re-parse path -- see #5854. That keeps this fixture + isolated to the exact N+1 call shape under test: one `Session.__init__` + (and therefore one `_resolve_profile_home_param` call) per sidecar row. + """ + import sqlite3 + import time + + db_path = tmp_path / "state.db" + conn = sqlite3.connect(str(db_path)) + conn.executescript( + """ + CREATE TABLE sessions ( + id TEXT PRIMARY KEY, + source TEXT, + session_source TEXT, + title TEXT, + model TEXT, + started_at REAL NOT NULL, + message_count INTEGER DEFAULT 0, + parent_session_id TEXT, + ended_at REAL, + end_reason TEXT + ); + CREATE INDEX idx_sessions_started ON sessions(started_at); + CREATE TABLE messages ( + id TEXT PRIMARY KEY, + session_id TEXT, + role TEXT, + content TEXT, + timestamp REAL + ); + CREATE INDEX idx_messages_session ON messages(session_id, timestamp); + """ + ) + now = time.time() + sids = [] + for i in range(n): + sid = f"cron_job{i:04d}_{int(now) + i}" + sids.append(sid) + conn.execute( + "INSERT INTO sessions (id, source, session_source, title, model," + " started_at, message_count, parent_session_id, ended_at, end_reason)" + " VALUES (?, 'cron', 'cron', NULL, 'deepseek/deepseek-chat', ?, 1," + " NULL, NULL, NULL)", + (sid, now + i), + ) + conn.execute( + "INSERT INTO messages (id, session_id, role, content, timestamp)" + " VALUES (?, ?, 'user', 'cron task', ?)", + (f"cron_msg_{sid}", sid, now + i), + ) + conn.commit() + conn.close() + + session_dir = tmp_path / "sessions" + session_dir.mkdir() + for sid in sids: + (session_dir / f"{sid}.json").write_text( + '{"session_id": "%s", "title": "Renamed %s", "created_at": 1.0,' + ' "updated_at": 2.0, "archived": false, "message_count": %d,' + ' "profile": "default", "messages": []}' + % (sid, sid, message_count), + encoding="utf-8", + ) + return db_path, sids + + +def _count_profile_home_resolve_calls(call_args_list, expected_profile_home): + """Filter a `_safe_resolve` spy's call list down to just the profile-home + + branch (`pre_resolve == expected_profile_home`), excluding the unrelated + per-row `_safe_resolve()` call that resolves the session's `workspace` + path (same call count either way -- not part of this PR, not what + greptile's comment or the production stack trace was about). + """ + return sum( + 1 for call in call_args_list + if call.args and call.args[0] == expected_profile_home + ) + + +def test_load_cli_sessions_uncached_dedupes_profile_home_resolve_on_sidecar_cache_miss(tmp_path): + """Real N+1 reproduction for PR #7636 review comment (greptile, + api/models.py:7711): on a COLD `_SIDECAR_METADATA_CACHE` (fresh process, + or the first time each sid's sidecar is seen), `_state_projection_sidecar_metadata` + falls through to `Session.load_metadata_only(sid)` for EVERY row that has a + sidecar -- and that constructs a real `Session` via `Session.__init__`, + which resolves the session's `profile` param through + `_resolve_path -> _remote_terminal_workspace_candidate -> + _remote_terminal_cwd -> _resolve_profile_home_param -> _safe_resolve()`, + matching the exact stack trace captured in production + ("Slow WebUI request still running", 5-17s, pinned to this call site). + Real production sidecars carry the literal string "default" for `profile` + (confirmed against a live deployment's webui/sessions/*.json), which is + what this fixture uses too. + + This is a DIFFERENT code path than the direct dict-projection rows + greptile's comment focused on -- it fires from the sidecar-metadata + overlay, not from the row-to-dict projection itself. It IS covered by + `@profile_home_resolve_cache_scope()` on `_load_cli_sessions_uncached`, + because contextvars propagate through ordinary synchronous nested calls + (no thread pool / executor / asyncio task is involved anywhere in this + call chain) -- proven here by counting only the profile-home-resolving + `_safe_resolve()` invocations (filtered by argument), not the session's + unrelated per-row workspace-path resolve, which this PR never touched and + still runs once per row regardless. + """ + from unittest import mock + + import api.profiles as profiles + import api.workspace as ws + + models.clear_sidecar_metadata_cache() + n = 60 + db_path, sids = _make_cli_sessions_uncached_fixture(tmp_path, n) + + with ( + mock.patch("api.models.get_claude_code_sessions", return_value=[]), + mock.patch("api.models.get_last_workspace", return_value=str(tmp_path)), + mock.patch("api.models.ensure_cron_project", return_value="cron-pid"), + mock.patch("api.models.SESSION_DIR", tmp_path / "sessions"), + # Isolate the measurement: `_remote_terminal_cwd()` also calls + # `get_config_for_profile_home()` right after `_resolve_profile_home_param()`, + # and THAT helper does its own two direct, uncached `_safe_resolve()` calls + # on the same profile-home path (api/config.py, a pre-existing, separate + # hot path this PR does not touch and greptile's comment did not raise). + # Left unmocked those calls alias onto the same argument value and would + # make an unrelated inefficiency look like a failure of THIS cache. + mock.patch("api.config.get_config_for_profile_home", return_value={}), + mock.patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as safe_resolve_spy, + ): + result = models._load_cli_sessions_uncached(tmp_path, db_path, None) + + assert len(result) == n + profile_home_resolves = _count_profile_home_resolve_calls( + safe_resolve_spy.call_args_list, profiles._DEFAULT_HERMES_HOME + ) + # Every row's sidecar was a genuine cache miss (fresh clear above), so + # Session.load_metadata_only() ran -- and therefore Session.__init__() ran + # -- once per row: len(sids) separate `_resolve_profile_home_param("default")` + # calls. Without the fix each of those pays its own `_safe_resolve()` + # filesystem call; with the fix active only the FIRST one does, and the + # remaining len(sids) - 1 are served from the call-scoped cache. + assert profile_home_resolves == 1, ( + f"the profile-home _safe_resolve() ran {profile_home_resolves} times across " + f"{n} sidecar-miss rows sharing one profile -- expected exactly 1 (the rest " + "should be served from the call-scoped cache)" + ) + + +def test_load_cli_sessions_uncached_profile_home_resolve_scales_with_fix_disabled(tmp_path): + """Companion to the test above: calling the UNDECORATED function directly + + (bypassing `profile_home_resolve_cache_scope()` via `__wrapped__`, i.e. + reproducing pre-PR behavior) shows the real filesystem resolve DOES scale + linearly with row count -- confirming the dedup measured above is the + scope's doing, not an artifact of some other cache. + """ + from unittest import mock + + import api.workspace as ws + + models.clear_sidecar_metadata_cache() + n = 60 + db_path, sids = _make_cli_sessions_uncached_fixture(tmp_path, n) + + with ( + mock.patch("api.models.get_claude_code_sessions", return_value=[]), + mock.patch("api.models.get_last_workspace", return_value=str(tmp_path)), + mock.patch("api.models.ensure_cron_project", return_value="cron-pid"), + mock.patch("api.models.SESSION_DIR", tmp_path / "sessions"), + # Same isolation as the test above -- see its comment. + mock.patch("api.config.get_config_for_profile_home", return_value={}), + mock.patch.object(ws, "_cached_safe_resolve_profile_home", wraps=ws._cached_safe_resolve_profile_home) as memo_spy, + mock.patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as safe_resolve_spy, + ): + undecorated = models._load_cli_sessions_uncached.__wrapped__ + result = undecorated(tmp_path, db_path, None) + + assert len(result) == n + # The memoizing function is still called once per row either way... + assert memo_spy.call_count == n + # ...but with no active scope it never hits its cache branch, so every + # single call pays its own real filesystem resolve. + import api.profiles as profiles + profile_home_resolves = _count_profile_home_resolve_calls( + safe_resolve_spy.call_args_list, profiles._DEFAULT_HERMES_HOME + ) + assert profile_home_resolves == n, ( + f"expected the profile-home _safe_resolve() to run once per row ({n}) with no " + f"active cache scope, but it ran {profile_home_resolves} times" + )