Skip to content

fix(dflash): make the configured local timeout reachable, and prove the request prefix is stable - #334

Merged
OmarB97 merged 6 commits into
mainfrom
fix/deep-context-stale-timeout-and-prefix-stability-fork-20260802
Aug 2, 2026
Merged

OmarB97 merged 6 commits into
mainfrom
fix/deep-context-stale-timeout-and-prefix-stability-fork-20260802

Conversation

@OmarB97

@OmarB97 OmarB97 commented Aug 2, 2026

Copy link
Copy Markdown
Owner

What does this PR do?

Deep agentic sessions on a local lane died two different deaths. Both are here,
each traced to its actual enforcement site rather than to the symptom.

1. turn:timed out — the configured timeout was never being read

The rendered turn:timed out · … comes from _derive_turn_outcome
(tui_gateway/server.py:6006), which only classifies an already-produced
error. The thing that actually kills the turn is the local-DFlash
pre-first-chunk watchdog resolved by
resolve_dflash_local_first_chunk_timeout (agent/chat_completion_helpers.py)
and fired from the streaming path. From ~/.hermes/logs/agent.log:

09:43:11 WARNING [20260802_085529_71456f] agent.chat_completion_helpers:
  Local dflash stream produced no first chunk for 240s (threshold 240s).
09:43:13 WARNING [20260802_085529_71456f] agent.conversation_loop:
  API call failed (attempt 1/1) error_type=TimeoutError
  provider=custom base_url=http://10.55.0.3:8000/v1
  model=deepseek-v4-flash-0731-ds4
  summary=Local dflash stream produced no first chunk after 240s (threshold: 240s)
09:43:13 ERROR ... API call failed after 1 retries. ... msgs=64 tokens=~85,293

attempt 1/1 → max-retries-exhausted → failure_reason="timeout" → the
regex in _derive_turn_outcometurn:timed out. The prefill on that lane
takes ~8 minutes at that depth. It was cut at 240s.

Why 240s when config says 900s. Note provider=custom. As #330 established,
resolve_runtime_provider() reports EVERY user-declared endpoint as the bare
string custom — the resolved billing class, not a routable identity. Timeout
resolution keyed straight off that, so it looked up providers["custom"], a key
that by construction never exists. Running the real resolvers against the real
~/.hermes/config.yaml:

--- as the runtime saw it (provider='custom') ---
stale  (custom)    : None
request(custom)    : None
--- what config.yaml actually says ---
stale  (ai-router) : 900.0
request(ai-router) : 1800.0

estimated tokens                          : 85300
managed W2 route                          : False
resolve_stream_stale_timeout              : 240.0
resolve_dflash_local_first_chunk_timeout  : 240.0     ← matches the log exactly

[counterfactual] if provider were 'ai-router':
  stale: 900.0   first_chunk: 900.0                    ← survives the 8-min prefill

So providers.<name>.stale_timeout_seconds and request_timeout_seconds were
silently unreachable on exactly the local endpoints whose long cold prefills are
the reason those knobs exist. Both resolvers now take the live base_url and
attribute a bare-custom provider to the providers: entry that owns the
endpoint — the same endpoint-identity rule #330 established for the picker,
reusing find_custom_provider_identity / canonical_custom_identity, whose
docstring already requires every persist/restore path to do this.

The watchdog is also no longer a flat ladder. It fell through to
>100k → 300s, >50k → 240s, …, which capped at 300s — so a 200k-token turn on a
262k-window model got the same deadline as a 101k one. It is now continuous:
base + per-1k prefill cost, widen-only. And first_chunk_timeout_seconds is a
new per-model/per-provider knob for operators who want to pin this phase
directly.

2. The prefix divergence is not the client's payload

The hypotheses were system-prompt instability, mid-session history rewriting, and
goal-loop insertion. All three are disconfirmed by measurement.

HERMES_PREFIX_PROBE=1 (new) hashes each request's cacheable prefix and logs
where it first differs from the previous call — element index, role, reusable
bytes. tests/agent/test_request_prefix_stability.py drives 12 real turns with
tool calls against an in-process HTTP provider and asserts every request is a
byte-identical extension of the one before it, under a long-lived agent and
under a fresh agent per turn reloading history from the store (the crash /
app-update / gateway path). System-prompt bytes and tool-schema bytes are pinned
constant across turns; the goal continuation is pinned append-only against the
real template.

Then the field data. Every API call #N line already logs provider-reported
cache=, so 225 deep-context calls (in>20k) across today's rotated logs can be
grouped by what else touched the lane between one call and the next:

own auxiliary call to the SAME endpoint another session on the lane HIT MISS miss%
no no 170 6 3%
no yes 4 9 69%
yes no 22 10 31%
yes yes 2 2 50%

Excluding the concurrency-confounded rows and splitting the auxiliary calls by
endpoint isolates it cleanly:

group HIT MISS miss%
no auxiliary call 170 6 3%
auxiliary call to a different endpoint 22 2 8%
auxiliary call to the same endpoint 0 8 100%

Mean latency: 10.3s on a hit, 143–237s on a miss — an independent physical
confirmation that the misses are real re-prefills, not just an absent usage field.

The client's serialized prefix is stable (3% baseline over 176 calls). What
destroys the KV cache is another prompt landing on the backend's single slot
between two turns
— a concurrent session, or Hermes' own auxiliary-model call
(approval classification et al.) auto-detecting onto the same local endpoint
the conversation lives on (agent/auxiliary_client.py, "Auxiliary auto-detect:
using main provider"). That is why the server logs ctx=0..M.

What this deliberately does not fix

The self-inflicted half of the eviction is diagnosed here, not repaired.
Stopping the auxiliary client from reusing the main local endpoint is a real
behavior change: on this config the aux call is the approval classifier, its
fallback policy is off, and skipping it makes a terminal call return
pending_approval — which in an unattended cron session stalls the tool. That
trade needs a deliberate decision (a dedicated aux route, or a documented
degrade), not a change smuggled into a timeout fix. The instrument and the table
above are what make that decision answerable; it should be its own PR.

Likewise the concurrent-session half is a scheduling property of one shared
single-slot backend and is not client-fixable in this shape.

The managed-W2 allowlist and its cold-start allowance are not widened. That
allowance encodes a measurement of one deployment (llama-swap load on taro,
138.5s); only the per-1k prefill term — which is arithmetic — generalizes.

Related Issue

No filed issue. Found from a 2026-08-02 desktop session on a local DeepSeek-V4
lane (~240 t/s prefill, 15–19 t/s decode, 262K ctx) that kept dying mid-turn.

Type of Change

  • 🐛 Bug fix (non-breaking change that fixes an issue)
  • ✨ New feature (env-gated diagnostic + one new config key)

Changes Made

  • hermes_cli/timeouts.pyget_provider_request_timeout /
    get_provider_stale_timeout take base_url; new
    _recover_custom_provider_key maps a bare-custom runtime provider to its
    providers: entry by endpoint identity. Attribution falls back to
    config.model.provider only when there is no base_url to match on —
    canonical_custom_identity always allows that fallback, which is right for
    credential recovery and wrong here, since an ad-hoc endpoint would otherwise
    inherit an unrelated provider's timeouts. The reverse lookup runs only when the
    direct key misses AND the provider is bare custom, so named/built-in providers
    keep their single dict lookup per API turn.
  • hermes_cli/timeouts.py — new get_provider_first_chunk_timeout.
  • run_agent.py, agent/agent_init.py, agent/agent_runtime_helpers.py,
    agent/chat_completion_helpers.py — thread the live base_url through every
    resolver call site (the fallback-chain site passes fb_base_url, not the
    agent's).
  • agent/chat_completion_helpers.py_dflash_prefill_scaled_timeout; the
    first-chunk resolver now honours first_chunk_timeout_seconds above
    stale_timeout_seconds, and the generic ladder is continuous instead of
    capped at 300s.
  • agent/prefix_probe.py (new) + one gated call in agent/conversation_loop.py
    at the existing preflight seam. File-backed state so the comparison survives an
    agent rebuild; wrapped so a diagnostic can never fail a turn.
  • hermes_cli/config.pyfirst_chunk_timeout_seconds added to the known
    provider keys (otherwise setting it warns on every load).
  • cli-config.yaml.example — documents the new key, why it outranks
    stale_timeout_seconds, and that these must be declared under the named
    provider entry rather than custom.
  • tests/hermes_cli/test_timeouts.py — 8 new tests.
  • tests/agent/test_request_prefix_stability.py (new) — 16 tests.

How to Test

  1. Reproduce the mis-attribution. With a providers: entry carrying
    stale_timeout_seconds and a session on that endpoint,
    get_provider_stale_timeout("custom", model) returns None before this
    change and the entry's value after it. The regression test is
    test_bare_custom_provider_resolves_entry_timeouts_via_base_url_regression.
  2. ./scripts/run_tests.sh tests/hermes_cli/test_timeouts.py -q25 passed
    (12 existing + new attribution coverage).
  3. ./scripts/run_tests.sh tests/agent/test_request_prefix_stability.py -q
    16 passed.
  4. Watch it live: HERMES_PREFIX_PROBE=1 hermes and grep agent.log for
    prefix-probe. prefix STABLE through N/N elements on a turn that still
    re-prefills is the proof the miss is not the client's.

Checklist

Code

  • I've read the Contributing Guide
  • Conventional Commits
  • Searched for existing PRs
  • Only changes related to this fix
  • pytest tests/ -q fully green — not claimed. A 154-file sweep over
    tests/run_agent/ plus every timeout/stale/stream suite is still running
    at the time of opening (262 passed, 0 failed so far); I will post the
    completed comparison as a comment and this should not merge before it
    lands.
  • Added tests
  • Tested on macOS 15 (Darwin 25.6.0), arm64

Documentation & Housekeeping

  • Docstrings + rationale comments at each decision point
  • cli-config.yaml.example updated for the new key
  • N/A — no architecture/workflow change
  • N/A — no tool schema change

Omar Baradei and others added 6 commits August 2, 2026 10:26
…nfig entry

`resolve_runtime_provider()` reports EVERY user-declared endpoint as the bare
string "custom" — the resolved billing class, not a routable identity (#330).
Timeout resolution keyed straight off that runtime id, so it looked up
`providers["custom"]`, a key that by construction never exists, and reported
"nothing configured". `providers.<name>.stale_timeout_seconds` and
`request_timeout_seconds` were therefore silently unreachable on exactly the
local endpoints whose long cold prefills are the reason those knobs exist.

Both resolvers now take the live base_url and, on a bare-custom provider,
attribute it to the `providers:` entry that owns the endpoint — the same
endpoint-identity rule #330 established for the picker, via the existing
`find_custom_provider_identity` / `canonical_custom_identity` helpers whose
docstring already requires every persist/restore path to do this.

Attribution is by endpoint identity whenever a base_url is available, and only
falls back to `config.model.provider` when there is no endpoint to match on.
`canonical_custom_identity` always permits that fallback, which is right for
credential recovery and wrong here: a genuinely ad-hoc endpoint would otherwise
inherit an unrelated provider's timeouts.

The reverse lookup runs only when the direct key misses AND the provider is
bare custom, so named and built-in providers keep their existing single
dict-lookup cost on every API turn.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…ence offset

When a long session starts re-prefilling from scratch every turn, the client
could not answer the only question that matters: did WE rewrite the prefix, or
did something evict the server's cache? Provider-reported cached_tokens tells
you a miss happened, never why.

HERMES_PREFIX_PROBE=1 records a rolling hash over each outbound request's
cacheable prefix — tool schemas first (chat templates render them ahead of the
conversation), then one element per message in wire order — and logs where it
first differs from the previous call in the same session, by element index,
role label and reusable character count.

Cumulative rather than per-element hashes, so the earliest differing index IS
the first prefix divergence: the point past which no cached work survives. A
pure append reports no divergence at all, which is the append-only contract a
healthy agentic turn must satisfy. Serialization sorts dict keys so key
ordering — which no chat template depends on and Python does not guarantee
across rebuilds — cannot masquerade as real drift. Sampling params are excluded
since they do not participate in the cached prefix.

State is file-backed under the session log dir rather than held on the agent,
because the cases worth catching are exactly the ones where the agent object
does not survive: a compute-host crash, an app update, a fresh per-turn agent
on the gateway path.

Hooked at the existing preflight seam in conversation_loop, where api_kwargs is
final and the request has not left yet. Gated by an env var alongside its
sibling HERMES_DUMP_REQUESTS two lines up; ships off, and every path is wrapped
so a diagnostic can never fail a turn.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Three statements sat between the kwargs assembly and the AIAgent
construction in _make_agent. Each trailing comma made them 1-element
tuple assignments to locals: base_url shadowed the function parameter
and api_key was a fresh unused local. Both ran after kwargs had already
captured the real values, so neither reached the returned AIAgent.

A merge artifact from an earlier edit. Removing them leaves behavior
unchanged; the file's 93 tests still pass.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
… the prefix

Two halves of the same deep-session failure.

WATCHDOG. The local DFlash first-chunk budget fell through to a step ladder
(>100k -> 300s, >50k -> 240s, ...) that flat-capped at 300s, so a 200k-token
turn on a 262k-window model got the same deadline as a 101k one. A ~95k-token
turn landed in the 240s bucket and had its connection killed mid-prefill while
the server was still healthily working. The budget is now continuous:
base + per-1k prefill cost, widen-only.

Only the per-1k prefill term generalizes — that is arithmetic, and a bigger
prompt takes proportionally longer on any backend. The cold-start allowance
encodes a measurement of one deployment (llama-swap model load on taro,
138.5s) and stays gated to the managed-W2 route it was measured on, along with
that route's 360s floor. So this widens every local DFlash lane by its real
prefill cost without lending one lane's number to another.

Adds `first_chunk_timeout_seconds` (per-model, then per-provider) so an
operator can pin the pre-first-chunk phase directly. It outranks
`stale_timeout_seconds` because the two measure different things: waiting for
the FIRST chunk is queue admission + model load + prefill of the whole prompt,
while the stale timeout measures the gap between chunks once generation is
under way. A lane can legitimately want minutes for one and seconds for the
other, so declaring both must not be contradictory.

PROOF. tests/agent/test_request_prefix_stability.py drives 12 real turns with
tool calls against an in-process HTTP provider and asserts every request is a
byte-identical extension of the one before it — under a long-lived agent AND
under a fresh agent per turn reloading history from the store, which is the
crash / app-update / gateway path. It also pins the system-prompt bytes and
tool-schema bytes constant across turns, and the goal-loop continuation as
append-only using the real template.

That is the measurement that rules the client out: the serialized prefix does
not drift turn to turn, so a re-prefill on a stable prefix is the server's KV
slot being taken, not our payload changing.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
… deepcopy

`find_custom_provider_identity` calls `load_config()`, which deepcopies the
whole config — and load_config's own docstring names
`get_provider_request_timeout` as the per-API-turn hot spot that must use
`load_config_readonly()` precisely to avoid that. Routing bare-custom
attribution through the general helper put the deepcopy right back on that
path, for every turn of every session on a user-declared endpoint.

Match the endpoint against the providers dict `_provider_config` has already
loaded. A timeout can only be read from a `providers:` entry anyway, so when
one owns the URL there is nothing left for the general helper to find; it stays
as the fallback for the `custom_providers:`-only shape and the no-base_url
case. Requires exactly one owner, the same rule #330 established — rows with
distinct credentials can share an endpoint and none can claim it alone.

URL normalization mirrors `runtime_provider._normalize_base_url_for_match` so
the fast path and the general helper can never disagree about whether two URLs
are the same endpoint.

Also documents `first_chunk_timeout_seconds` in cli-config.yaml.example (with
why it outranks `stale_timeout_seconds`, and that these must be declared under
the named provider entry rather than "custom"), and adds it to the known
provider keys in config.py — without which setting it warns on every load.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…eout

f(payload, f(payload, base)) adds the prefill term twice, so base must always
be a fixed starting point — a constant or a configured value — never a figure
this function already produced. Both callers pass _DFLASH_LOCAL_TIMEOUT_DEFAULT_S
or the legacy override, so neither double-counts today; the docstring was the
only thing that would have let a future caller do it.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@OmarB97
OmarB97 merged commit 656e2b6 into main Aug 2, 2026
OmarB97 added a commit that referenced this pull request Aug 2, 2026
…promises (#338)

`agent.local_stream_stale_timeout` (default 900) and its env twin
`HERMES_LOCAL_STREAM_STALE_TIMEOUT` were read by no code. A whole-tree grep
found exactly four references: the default in DEFAULT_CONFIG, the docs row, and
a test whose NAME mentions the knob but which asserted `float("inf")` — pinning
the absence of the ceiling.

The reader was dropped by #263 (d8aced7), which replaced the inline
`load_config()` + `env_float("HERMES_LOCAL_STREAM_STALE_TIMEOUT", ...)` block
with `resolve_stream_stale_timeout()` and never reinstated it. That commit
touched only agent/, run_agent.py and tests — the config default and the docs
row were left behind, still promising a bound that no longer existed. So every
generic (non-DFlash) local endpoint got `float("inf")`: exactly the infinite
disable the 900s default was introduced to replace.

A knob that is defaulted, documented, and inert is worse than no knob. This one
misdirected a root-cause investigation into deep-context turn timeouts on a
local lane, because the operator and the investigator both reasonably believed
a 900s ceiling was in force. The runtime cost is worse than a stale doc: with
the threshold at inf, `_stale_elapsed > _stream_stale_timeout` can never be
true, so the poll loop's stale branch is unreachable for a generic local
endpoint. A crashed or deadlocked local server that keeps the socket alive with
SSE pings parks the session forever — no reconnect, no fallback, no error.

`resolve_stream_stale_timeout` now resolves the ceiling instead of returning
inf: `HERMES_LOCAL_STREAM_STALE_TIMEOUT` (the documented escape hatch), then
`agent.local_stream_stale_timeout` (canonical), then 900s. Non-positive
disables the watchdog, so an unbounded wait stays reachable as a deliberate
choice for an exotically slow local model. A `providers.<id>.stale_timeout_seconds`
or an explicit `HERMES_STREAM_STALE_TIMEOUT` still wins outright, and the local
DeepSeek Flash family keeps its own tighter budget — this branch is reached
only when nothing more specific is set.

The ceiling is then widened — never narrowed — by the request's context-scaled
prefill cost, reusing `_dflash_prefill_scaled_timeout`. That helper is already
the portable half of the DFlash budget: the per-1k prefill term is arithmetic
(a bigger prompt takes proportionally longer on any backend), while the
cold-start allowance stays gated to the lane it was measured on. A FLAT
deadline is precisely how the old ladder killed healthy prefills mid-flight
(#278, #334: 240s at ~95k tokens, 240s at ~89k, 180s at ~33k, on a server that
was still working); trading "hangs forever" for "kills work that was fine"
would be the worse of the two. The same HERMES_DFLASH_FIRST_CHUNK_CEILING
(1800s) caps the result, so a wedged endpoint stays bounded at any prompt size.

Behavior change, stated plainly: a previously unbounded wedged local server now
trips at 900s + 4s/1k of prompt. The risk in the other direction is that this
path has no liveness probe (`_local_backend_generation_active` stays on the
DFlash first-chunk branch), so a healthy-but-very-slow generic local server
that exceeds the scaled ceiling is reconnected rather than waited out. The
mitigations are the generous base (5x the DFlash family's), the context
scaling, and a one-line escape hatch. Extending the probe to this branch is a
separate behavior change from wiring the knob.

test_generic_local_stream_stale_timeout_still_disables_by_default asserted inf.
That assertion pinned the regression, not the design — the config default and
the docs both describe a finite ceiling and #263 changed neither. Rewritten as
..._is_bounded_but_looser (900s, with the DFlash family's 180s asserted
alongside it on the same endpoint so the contrast is explicit).

TestGenericLocalStreamStaleCeiling resolves through the real config loader and
a real AIAgent: DEFAULT_CONFIG default, config.yaml value, env override,
unparseable env falling through to config rather than counting as an override,
0/negative disabling, context scaling (1260s at 90k, 904s at 1k), the 1800s
clamp at 400k, and explicit stale-timeout settings still winning.

TestGenericLocalStaleWatchdogActuallyFires drives the real poll loop in
`interruptible_streaming_api_call` against an endpoint that accepts the request
and never sends a chunk: the kill fires at 960s and counts toward the
cross-turn give-up breaker, and with the ceiling disabled 1200s of silence
produces no kill at all — the escape hatch, and a record of the pre-fix
behavior.

Two test-local mirrors of this resolution still said local means inf. The one
in test_stream_read_timeout_floor.py is exercised, so its local case now
asserts 900s — which makes it stronger, since it proves the local read-timeout
branch wins outright even when the stale value is finite. The one in
test_reasoning_stale_timeout_floor.py is never called with a local URL, so it
now raises instead of carrying a second, drifting copy of the rule.

Docs: HERMES_STREAM_RETRIES was documented as defaulting to 3; the code default
is 2, which yields 3 total attempts (corrected in the EN and zh-Hans env-var
tables and in the tips corpus). Three surfaces still said stale-stream
detection is "disabled entirely" for local providers — the
HERMES_STREAM_STALE_TIMEOUT row, the API-timeouts table and prose in
user-guide/configuration.md, and the table in guides/local-llm-on-mac.md — all
corrected to describe the ceiling, the scaling, and the 0 disable. Added the
knob to cli-config.yaml.example and expanded its DEFAULT_CONFIG comment, since
config.yaml is the canonical surface and the env var is the escape hatch.

Co-authored-by: Omar Baradei <omar@kostudios.io>
Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant