Merge pull request #7659 from nesquena/stage/7636-profile-home-cache
Release: profile-home resolve cache (#7636) + access-log stdout independence (#7643)
This commit is contained in:
11 files changed
+685
-14
No files matched your search
@@ -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)
|
||||
|
||||
+3
-2
@@ -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'],
|
||||
|
||||
@@ -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
|
||||
+78
-2
@@ -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:
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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.
|
||||
@@ -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 <container>` 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.
|
||||
|
||||
@@ -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."""
|
||||
|
||||
@@ -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
|
||||
@@ -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"
|
||||
@@ -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"
|
||||
)
|
||||
Reference in new issue
Block a user