Three fixes for the CI failures (lint + test shard 1):
1. B009 lint fix (api/routes.py:6281): Replace getattr(session, 'profile')
with session.profile — the guard on line 6275 already ensures it exists.
2. B905 lint fix (api/routes.py:13843): Add strict=True to zip() of
_draft_stages slices. Both sides are always the same length (shifted
by one), so strict=True is correct.
3. _emit_slow format-arg fix (api/request_diagnostics.py:186-195):
Keep the prefix in the format string and pass the JSON payload as a
separate positional argument. The test at
test_issue1855_request_diagnostics.py:33 does
json.loads(caplog.records[0].args[0]) and the old code embedded the
prefix in the payload string, breaking the JSON parse. Now
self.logger.warning("%s %s", prefix, payload) — wait, actually
self.logger.warning(f"{prefix} %s", payload) — so args[0] is the
raw JSON string, same as the pre-_emit_slow code.
Tier 2c added per-stage instrumentation on /api/session and added
'GET /api/session' to the RequestDiagnostics allowlist, but the
structured log emitted by RequestDiagnostics.finish() and the
pre-existing [SLOW] line both call logger.warning() — which the
WebUI process silently drops because the root logger has no handler
configured at boot.
The per-request 'ms' line has worked all along because it goes
through handler._safe_webui_print(), which writes directly to the
systemd journal socket.
This commit:
- adds a print_fn= parameter to RequestDiagnostics.__init__ and
RequestDiagnostics.maybe_start. When provided, finish() and
_on_timeout() route through it instead of self.logger.warning.
- routes the [SLOW] line in routes.py through handler._safe_webui_print
instead of logger.warning.
- passes print_fn=handler._safe_webui_print from the /api/session
handler to RequestDiagnostics.maybe_start.
After this fix, every slow /api/session request (and the existing
[SLOW] line) actually lands in the journal — the very data Tier 2c
was supposed to produce. Without this, the allowlist + handler
instrumentation would be a no-op in production despite the code
being present.
Measured: the same 2.97s /api/session call (sid 295592fd560e,
m=1 ml=30) which produced a per-request ms line but no [SLOW] line
before this fix, now produces both lines with full per-stage breakdown.
No public API change. The new print_fn parameter is optional and
defaults to None, preserving the existing logger.warning behavior
for any caller that hasn't been updated.
The /api/session handler already has _t0.._t6 local timers plus an
env-var-gated [SLOW] WARNING that logs the total wall time and the
_tN-to-_tN+1 deltas, but only when HERMES_DEBUG_SLOW is set or total
>= 2s. In production we cannot rely on the env var, and the 2s
threshold means the typical chat-open (sub-2s on Tier 1) never logs
at all — we only see the worst cases, never the marginal ones that
would tell us where the next bottleneck is.
This wires the handler into the existing RequestDiagnostics framework:
- add ('GET', '/api/session') to the allowlist
- call RequestDiagnostics.maybe_start() at the _t0 boundary
- call stage() at each of _t1.._t6
- call finish() before the response returns
The watchdog fires _on_timeout (with thread stack snapshot) when the
request crosses the per-path slow threshold, and finish() emits a
single structured log line on the same threshold crossing. The
existing env-var-gated [SLOW] log stays as a no-diag fallback.
Greptile P1 trap avoidance: previous allowlist additions for similar
endpoints were flagged as dead code because the handler was never
updated to call maybe_start/finish. Both halves are present in this
commit so the watchdog entry actually registers.
No behavior change observable on the happy path (diag is None for
non-allowlisted paths; the existing _tN log is the fallback for both
None-diag and slow cases). No public API change. The /api/sessions
and /api/profiles handlers already use this pattern.
Greptile flagged that _compute_user_message_count_lazy silently returns 0
when the SQLite query fails (DB locked, missing file, schema drift).
The pre-patch compact() walked self.messages in Python and returned the
correct count without ever touching the DB, so the silent zero
fallback is a regression that breaks _looks_like_stale_zero_message_row
under contention.
Fix: helper now takes an optional messages argument. On SQLite failure
it falls back to the same in-memory walk the original code used, so
callers see the same number they'd have seen before for any session
where Session.load() populated self.messages.
Also drop the dead ('GET', '/api/session') allowlist entry flagged by
Greptile — the /api/session handler already does its own per-stage
logging via the _t0.._t6 block (with auto-log on slow requests), and
adding RequestDiagnostics on top would just duplicate the slow-request
journal entries without adding information.
The slow-request journal showed /api/profiles, /api/models, and /api/session
fire on every session click but had no per-stage timing. Add:
- RequestDiagnostics coverage for GET /api/profiles, /api/models, /api/session
- Stage markers inside /api/profiles (list / active lookup / isolated check)
- Stage markers inside /api/models (freshness routing, serialize)
- Per-stage stage-log inside get_available_models_for_session_visit that
emits a [SLOW] line when total wall time crosses HERMES_DEBUG_SLOW ms
(default 500ms) so we can pinpoint which sub-step is blocking
No behavior change. Existing _t0.._t6 timing on /api/session and the
2.5s/10s TTL on /api/sessions are unchanged. Reversible: revert commit.
A threading.Timer per RequestDiagnostics spawns one OS thread per request, held
alive until finish() cancels it. Under sustained /api/sessions poll load this
exhausts the per-process thread cap (RuntimeError: can't start new thread) and
the server stops accepting connections. Replace with a single lazy-init
watchdog daemon thread that scans pending diags every ~1s; public API
unchanged. Caps timeout-tracking at 1 thread/process regardless of request rate.
Konstantin M