From e781542bf44ac575423784e9f87747ed6e3dd796 Mon Sep 17 00:00:00 2001 From: hermes Date: Fri, 18 Sep 2026 16:36:46 +0100 Subject: [PATCH 1/8] Cache profile home resolution to fix N+1 slowdown in session list _resolve_profile_home_param() called Path.resolve() on the profile's home directory with no caching. The webui session list builds one Session per CLI session row, and Session.__init__ calls this function once per row, so with ~484 sessions on the same profile it redundantly re-resolved the identical path hundreds of times per request. Individually cheap (~1ms), but under host load this compounded into multi-second sidebar hangs, confirmed via journalctl showing repeated 'Slow WebUI request still running' warnings (5-17s) pinned to this exact call site. The mapping from a profile argument to its home path is a pure function of process-startup constants (_DEFAULT_HERMES_HOME / _INITIAL_HERMES_HOME) that are resolved once at import time and never mutated afterwards, so memoizing per profile argument for the life of the process is safe. Profile creation only creates the directory at the already-deterministic path; it does not change what path a profile argument resolves to. Co-Authored-By: Claude Sonnet 5 --- api/workspace.py | 34 ++++++++++++++++++++-- tests/test_profile_home_resolve_caching.py | 34 ++++++++++++++++++++++ 2 files changed, 66 insertions(+), 2 deletions(-) create mode 100644 tests/test_profile_home_resolve_caching.py diff --git a/api/workspace.py b/api/workspace.py index d8ffb282..ebeaacaa 100644 --- a/api/workspace.py +++ b/api/workspace.py @@ -207,6 +207,36 @@ def _is_remote_terminal_backend(terminal_cfg: dict | None) -> bool: return backend not in ('', 'local') +# Per-profile-argument 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). +# +# Caching is safe for the life of the process: the mapping from a profile +# argument to its home path is a pure function of process-startup constants +# (`api.profiles._DEFAULT_HERMES_HOME`, `_INITIAL_HERMES_HOME`) that are +# resolved once at import time and never mutated afterwards. Profile +# *creation* only creates the directory at that already-deterministic path +# -- it does not change what path a given profile argument resolves to -- +# so there is no runtime path that needs to invalidate an entry here. +_PROFILE_HOME_RESOLVE_CACHE: dict[Path, Path] = {} + + +def _cached_safe_resolve_profile_home(pre_resolve: Path) -> Path: + """Memoized `_safe_resolve()` for profile-home paths (see cache doc above).""" + cached = _PROFILE_HOME_RESOLVE_CACHE.get(pre_resolve) + if cached is not None: + return cached + resolved = _safe_resolve(pre_resolve) + _PROFILE_HOME_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 +274,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/tests/test_profile_home_resolve_caching.py b/tests/test_profile_home_resolve_caching.py new file mode 100644 index 00000000..f2a16587 --- /dev/null +++ b/tests/test_profile_home_resolve_caching.py @@ -0,0 +1,34 @@ +"""Regression test: `_resolve_profile_home_param` memoizes its filesystem +`.resolve()` call per profile argument (N+1 sidebar-hang fix). + +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 old code redundantly re-resolved the identical path via +a filesystem `.resolve()` on every single row. This asserts repeated calls +with the same profile argument return an equal Path while invoking the +underlying `_safe_resolve()` filesystem call only once. +""" +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 + + +def test_resolve_profile_home_param_caches_repeated_path_argument(tmp_path): + ws._PROFILE_HOME_RESOLVE_CACHE.clear() + 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 == 1, ( + "expected the filesystem resolve() to run once and be served from " + f"cache thereafter, but it ran {spy.call_count} times" + ) From 67d6c3ff50182fec756023f8d310251f5ac23ca3 Mon Sep 17 00:00:00 2001 From: hermes Date: Fri, 18 Sep 2026 16:57:17 +0100 Subject: [PATCH 2/8] Add regression test for cached profile-name-string resolution branch _resolve_profile_home_param has two branches feeding the same _cached_safe_resolve_profile_home() memoization: an explicit Path, and a logical profile-name string resolved via get_hermes_home_for_profile(). The existing regression test only covered the Path branch. Add a matching test that repeatedly resolves a profile-name string and confirms it returns the correct home and that _safe_resolve is invoked only once across repeated calls, i.e. the cache is genuinely hit for the string-keyed path too. Co-Authored-By: Claude Sonnet 5 --- tests/test_profile_home_resolve_caching.py | 27 ++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/tests/test_profile_home_resolve_caching.py b/tests/test_profile_home_resolve_caching.py index f2a16587..ccc8f63f 100644 --- a/tests/test_profile_home_resolve_caching.py +++ b/tests/test_profile_home_resolve_caching.py @@ -32,3 +32,30 @@ def test_resolve_profile_home_param_caches_repeated_path_argument(tmp_path): "expected the filesystem resolve() to run once and be served from " f"cache thereafter, but it ran {spy.call_count} times" ) + + +def test_resolve_profile_home_param_caches_repeated_profile_name_argument(tmp_path): + """Same fix, 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. This mirrors the + Path-argument test above but drives the string branch (workspace.py's + ``isinstance(profile, Path)`` check is False), confirming the cache is + genuinely hit -- not just for explicit Path callers -- and that the + resolved home is correct. + """ + ws._PROFILE_HOME_RESOLVE_CACHE.clear() + 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: + 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 and be served from " + f"cache thereafter, but it ran {spy.call_count} times" + ) From 8a335d5af202edbdf26c1c0c011ba68c5e7924d5 Mon Sep 17 00:00:00 2001 From: hermes Date: Sat, 19 Sep 2026 00:20:05 +0100 Subject: [PATCH 3/8] fix(webui): scope profile-home resolve cache to one session-list build The process-lifetime cache from the previous commit was flagged in PR review (nesquena-hermes): Path.resolve() is a filesystem call, not a pure function of process-startup constants. A profile-home symlink can be retargeted while the long-running webui process stays up, and _safe_resolve() deliberately falls back to the unresolved input after a transient OSError/RuntimeError/ValueError -- a process-lifetime cache would serve either a stale symlink target or a stale fallback forever. Redesign: replace the module-level dict with a contextvars.ContextVar that defaults to None (no active scope -> resolve fresh, exactly like pre-PR behavior). profile_home_resolve_cache_scope() sets it to a fresh dict for the duration of one call and resets it in a finally block, so no cache entry survives past that call. It now wraps only _load_cli_sessions_uncached as a decorator -- the actual N+1 hot loop (hundreds of Session.__init__ calls per sidebar build, each resolving the same profile argument). All other call sites of _resolve_profile_home_param (confirmed via repo-wide grep: all internal to api/workspace.py, none elsewhere) get fresh resolution on every call, same as before this PR existed. Rewrote tests/test_profile_home_resolve_caching.py to prove: (a) repeated resolves within one scope still hit the cache once, (b) two separate scopes (simulating two requests) do not share state -- a symlink change between them is observed on the second scope, and (c) calls outside any scope never cache at all. Co-Authored-By: Claude Sonnet 5 --- api/models.py | 3 +- api/workspace.py | 70 ++++++++-- tests/test_profile_home_resolve_caching.py | 146 ++++++++++++++++----- 3 files changed, 175 insertions(+), 44 deletions(-) diff --git a/api/models.py b/api/models.py index eca27ab5..270e50b8 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, diff --git a/api/workspace.py b/api/workspace.py index ebeaacaa..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,7 +209,7 @@ def _is_remote_terminal_backend(terminal_cfg: dict | None) -> bool: return backend not in ('', 'local') -# Per-profile-argument cache for `_resolve_profile_home_param`'s filesystem +# 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 @@ -217,23 +219,67 @@ def _is_remote_terminal_backend(terminal_cfg: dict | None) -> bool: # host load (confirmed via repeated "Slow WebUI request still running" # warnings pinned to this call site). # -# Caching is safe for the life of the process: the mapping from a profile -# argument to its home path is a pure function of process-startup constants -# (`api.profiles._DEFAULT_HERMES_HOME`, `_INITIAL_HERMES_HOME`) that are -# resolved once at import time and never mutated afterwards. Profile -# *creation* only creates the directory at that already-deterministic path -# -- it does not change what path a given profile argument resolves to -- -# so there is no runtime path that needs to invalidate an entry here. -_PROFILE_HOME_RESOLVE_CACHE: dict[Path, Path] = {} +# 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: - """Memoized `_safe_resolve()` for profile-home paths (see cache doc above).""" - cached = _PROFILE_HOME_RESOLVE_CACHE.get(pre_resolve) + """`_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) - _PROFILE_HOME_RESOLVE_CACHE[pre_resolve] = resolved + cache[pre_resolve] = resolved return resolved diff --git a/tests/test_profile_home_resolve_caching.py b/tests/test_profile_home_resolve_caching.py index ccc8f63f..89836230 100644 --- a/tests/test_profile_home_resolve_caching.py +++ b/tests/test_profile_home_resolve_caching.py @@ -1,12 +1,29 @@ """Regression test: `_resolve_profile_home_param` memoizes its filesystem -`.resolve()` call per profile argument (N+1 sidebar-hang fix). +`.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 old code redundantly re-resolved the identical path via -a filesystem `.resolve()` on every single row. This asserts repeated calls -with the same profile argument return an equal Path while invoking the -underlying `_safe_resolve()` filesystem call only once. +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 @@ -17,8 +34,84 @@ sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) import api.workspace as ws # noqa: E402 -def test_resolve_profile_home_param_caches_repeated_path_argument(tmp_path): - ws._PROFILE_HOME_RESOLVE_CACHE.clear() +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() @@ -28,34 +121,25 @@ def test_resolve_profile_home_param_caches_repeated_path_argument(tmp_path): 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 and be served from " - f"cache thereafter, but it ran {spy.call_count} times" + 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_resolve_profile_home_param_caches_repeated_profile_name_argument(tmp_path): - """Same fix, second branch: a logical profile-NAME STRING (not a Path) +def test_scope_decorator_use_matches_load_cli_sessions_uncached_wiring(): + """Sanity check that `profile_home_resolve_cache_scope()` is usable as a - resolves through `get_hermes_home_for_profile()` before hitting the same - `_cached_safe_resolve_profile_home()` memoization. This mirrors the - Path-argument test above but drives the string branch (workspace.py's - ``isinstance(profile, Path)`` check is False), confirming the cache is - genuinely hit -- not just for explicit Path callers -- and that the - resolved home is correct. + decorator (the way it wraps `_load_cli_sessions_uncached` in + `api/models.py`), and that the ContextVar is active only during the + decorated call. """ - ws._PROFILE_HOME_RESOLVE_CACHE.clear() - home_dir = tmp_path / "named_profile_home" - home_dir.mkdir() + assert ws._PROFILE_HOME_RESOLVE_SCOPE.get() is None - with patch("api.profiles.get_hermes_home_for_profile", return_value=home_dir), \ - patch.object(ws, "_safe_resolve", wraps=ws._safe_resolve) as spy: - first = ws._resolve_profile_home_param("myprofile") - second = ws._resolve_profile_home_param("myprofile") - third = ws._resolve_profile_home_param("myprofile") + @ws.profile_home_resolve_cache_scope() + def _inside(): + return ws._PROFILE_HOME_RESOLVE_SCOPE.get() - assert first == second == third == home_dir.resolve() - assert spy.call_count == 1, ( - "expected the filesystem resolve() to run once and be served from " - f"cache thereafter, but it ran {spy.call_count} times" - ) + cache_during_call = _inside() + assert cache_during_call is not None + assert ws._PROFILE_HOME_RESOLVE_SCOPE.get() is None From 93814b9629491eeb86b15e9c3ec98282cb951e52 Mon Sep 17 00:00:00 2001 From: hermes Date: Sat, 19 Sep 2026 00:43:06 +0100 Subject: [PATCH 4/8] fix(webui): use the memoized workspace closure in the webhook chip pass The webhook second-pass loop in _load_cli_sessions_uncached called get_last_workspace(profile=_cli_profile) directly per row instead of the _cli_workspace() closure the main/cron/kanban passes already use, so it paid its own redundant file reads/is_dir() probe on every webhook row even though the loop already sits inside the profile-home resolve cache scope. Flagged in PR #7636 review (greptile): this is the one concrete gap in an otherwise-correct fix. Also adds an integration-level regression test proving the actual N+1 this PR targets -- Session.__init__ constructed via _state_projection_sidecar_metadata's Session.load_metadata_only() fallback on a cold sidecar-metadata cache -- is deduped by @profile_home_resolve_cache_scope() on _load_cli_sessions_uncached, with a companion test showing the same fixture scales linearly (one filesystem resolve per row) when the scope is bypassed. This directly answers the review claim that the cache scope doesn't reach any Session construction: it does, verified by counting real _safe_resolve() filesystem calls rather than call counts on the memoizing wrapper alone. Co-Authored-By: Claude Sonnet 5 --- api/models.py | 2 +- tests/test_profile_home_resolve_caching.py | 204 +++++++++++++++++++++ 2 files changed, 205 insertions(+), 1 deletion(-) diff --git a/api/models.py b/api/models.py index 270e50b8..43ae4720 100644 --- a/api/models.py +++ b/api/models.py @@ -8006,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/tests/test_profile_home_resolve_caching.py b/tests/test_profile_home_resolve_caching.py index 89836230..b41cc531 100644 --- a/tests/test_profile_home_resolve_caching.py +++ b/tests/test_profile_home_resolve_caching.py @@ -32,6 +32,7 @@ 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): @@ -143,3 +144,206 @@ def test_scope_decorator_use_matches_load_cli_sessions_uncached_wiring(): 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" + ) From d544a12ec8435b09b813f7e667d9220f46d46cc3 Mon Sep 17 00:00:00 2001 From: hermes Date: Sat, 19 Sep 2026 00:50:33 +0100 Subject: [PATCH 5/8] docs(architecture): document the profile-home resolve call-scoped cache PR #7636 review (greptile-apps) flagged the profile-home resolve cache scoping (profile_home_resolve_cache_scope() / _PROFILE_HOME_RESOLVE_SCOPE in api/workspace.py) as an undocumented runtime contract per AGENTS.md. Record what is cached, the call-scoped (not process-lifetime) lifecycle, which single call site owns it while every other caller resolves fresh, and the freshness guarantee this gives against symlink retargets and transient resolve fallbacks; index the document from docs/CONTRACTS.md, following the same pattern used for the /api/models cache invalidation contract. Docs only. Co-Authored-By: Claude Sonnet 5 --- docs/CONTRACTS.md | 8 ++ .../profile-home-resolve-cache.md | 87 +++++++++++++++++++ 2 files changed, 95 insertions(+) create mode 100644 docs/architecture/profile-home-resolve-cache.md 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. From 1a7b82d41e02bcaac400196e3128572901123e6c Mon Sep 17 00:00:00 2001 From: danpark Date: Sat, 19 Sep 2026 07:26:12 -0400 Subject: [PATCH 6/8] fix: preserve access logs during agent stdout capture (#2684) Own a private stdout descriptor before agent imports and serialize request log writes. Keep logging failures isolated from HTTP responses. Add successful chat/start subprocess delivery regressions and document header-latency semantics and cron ownership. --- api/request_logging.py | 26 ++++++++ docs/troubleshooting.md | 20 +++++++ server.py | 6 +- tests/test_access_log_delivery.py | 92 +++++++++++++++++++++++++++++ tests/test_issue2775_log_request.py | 22 +++++-- 5 files changed, 156 insertions(+), 10 deletions(-) create mode 100644 api/request_logging.py create mode 100644 tests/test_access_log_delivery.py 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/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" From 9239ed2112356fb51f0608ff90d36b793b6e61e9 Mon Sep 17 00:00:00 2001 From: nesquena-hermes Date: Sun, 20 Sep 2026 00:40:01 +0000 Subject: [PATCH 7/8] docs(changelog): stamp #7636 profile-home resolve cache Co-authored-by: totalitarian --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index ddd5a072..f9ed1382 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ ### Fixed +- **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) From a6f15d869bcac89ce8b1941b0956a956937121b9 Mon Sep 17 00:00:00 2001 From: nesquena-hermes Date: Sun, 20 Sep 2026 00:46:00 +0000 Subject: [PATCH 8/8] docs(changelog): stamp #7643 access-log stdout independence Co-authored-by: DevNexsler --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index f9ed1382..8e63b34e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ ### 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)