fix(streaming): attribute worker-thread failures to their session - #74875
fabiosiqueira wants to merge 1 commit into
Conversation
Related to #41726: that fix updates log context after compaction ID rotation; this patch addresses the separate streaming-worker thread boundary. |
teknium1
left a comment
There was a problem hiding this comment.
Thanks for isolating the thread-local logging gap; the standard streaming-worker premise is real on current main. hermes_logging.py:80 uses threading.local, while agent/chat_completion_helpers.py:61-64 copies only ContextVars into worker threads.
Problems
- The added binding covers only the normal
_callworker.interruptible_streaming_api_callalso runs Bedrock streaming in_bedrock_call(agent/chat_completion_helpers.py:2553), launched at:2669-2671; that worker can emit the stream-denial log at:2587-2591and remains untagged. tests/agent/test_stream_worker_session_context.pyexercises the helper directly, not the productioninterruptible_streaming_api_callworker placement, and has no Bedrock-path coverage.
Suggested changes
- Bind the session context at the start of
_bedrock_calltoo. - Add production-path tests for standard and Bedrock streaming workers, asserting a worker-created record carries the agent session tag.
Automated hermes-sweeper review.
| @@ -3679,6 +3703,8 @@ def _accept_anthropic_event(_event: Any) -> bool: | |||
| def _call(): | |||
| import httpx as _httpx | |||
|
|
|||
| bind_worker_session_context(agent) | |||
There was a problem hiding this comment.
This binds only the OpenAI/Anthropic worker. interruptible_streaming_api_call also starts the Bedrock _bedrock_call worker at current main agent/chat_completion_helpers.py:2553/:2669; its stream-denial branch logs at :2587, so please bind the same context there or Bedrock streaming remains unattributed.
085b5e4 to
ba83507
Compare
|
Both points addressed in 1. Bedrock workerYou were right that the binding covered only Worth naming why it's bound from 2. Production-path testsBoth tests now drive the real
Verified under mutation, not just green: dropping the bind from 3. The
|
Carries re-validated against production — all three live routes still OPEN upstream, so nothing converged this round: NousResearch#74875 streaming session tag → ours, rebased (see below) NousResearch#23715 skill_manager locked → OPEN, not in production NousResearch#25919 send_message edit → OPEN, not in production NousResearch#18565 cron memory provider → OPEN, not in production Conflict resolutions: - agent/chat_completion_helpers.py: took the rebased NousResearch#74875 branch wholesale (upstream/main + carry only). The old carry's `exc_info=True` half is gone — upstream's 8e191af converted that call to logger.exception, a superset. - tests/run_agent/test_memory_provider_init.py: kept only the carry's real additions (_build_agent + the three skip_memory_provider cases). The neighbouring test_aiagent_forwards_warning_callback_to_cli_memory_provider came through the 3-way as context but upstream deleted it deliberately in 6b81590 (test-prune wave 1); resurrecting it would undo that. - tests/tools/test_send_message_tool.py: additive import conflict, resolved by union. Also repaired in the carry: agent_init now reads config via load_config_readonly, so the carry's tests patching only load_config were silently a no-op and the provider never loaded. Patched both, matching the idiom the surrounding upstream tests already use. Verified: test_memory_provider_init, test_send_message_tool, test_skill_manager_tool, test_stream_worker_session_context — 65 passed, 1 skipped. skip_memory_provider coverage re-checked under mutation (knob ignored → 2 failures).
`interruptible_streaming_api_call` runs the provider call on a worker
thread — `_call` for the OpenAI/Anthropic path, `_bedrock_call` for
Bedrock Converse. The `[session]` tag every log line carries comes from a
`threading.local` in `hermes_logging`, and `_context_thread_target`
carries the caller's ContextVars across the boundary but cannot carry a
thread-local. Both workers therefore start unbound and everything they
log is formatted without a session tag.
The cost lands where it hurts most: each worker is where its own stream
failure is logged, so in a process serving concurrent sessions the one
line that carries the cause is the one line that names no session —
INFO agent.chat_completion_helpers: Streaming failed before delivery:
'dict' object has no attribute 'model_dump'
Bind the agent's session id onto both workers. Sourced from
`agent.session_id` rather than inherited from the calling thread: the
agent is the ground truth, and a caller that reached streaming without
going through `turn_context` is itself unbound. Best effort — a
session-less agent leaves the thread unbound instead of raising inside
the worker.
The tests drive the real `interruptible_streaming_api_call` on both
paths and assert on a record emitted from inside each worker, with the
calling thread deliberately left unbound; placement is the defect, so
exercising the helper alone would not catch a worker that was never
bound.
Same class of gap as NousResearch#41726, which synced the session context on
compaction id rotation.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
ba83507 to
9993261
Compare
Routine /fork-sync catch-up. Clean merge-tree dry run (0 conflicts, 8 files auto-merged: .gitignore, agent/agent_init.py, agent/curator.py, cron/scheduler.py, run_agent.py, tools/skill_manager_tool.py, tools/skill_usage.py, tools/skills_tool.py). Open upstream PRs NousResearch#74875, NousResearch#80382, NousResearch#78819, NousResearch#45809, NousResearch#27724 re-verified mergeable clean against the new tip; carry b1e8eb1 (skip_memory_provider) has no upstream route and stays local per prior audit.
The gap
hermes_loggingpromises one thing: every log record in the process carries a[session_id]tag, so lines from concurrent sessions can be told apart. Thetag comes from a
threading.local(hermes_logging.py:80), set byset_session_context().interruptible_streaming_api_callruns the provider call on a workerthread. Nothing binds that thread, so it starts unbound and every record it
emits is formatted without a session tag — the contract breaks silently, and it
breaks precisely where it costs the most: the worker is also where a stream
failure is logged. In a process serving concurrent sessions, the one line
that carries the cause of a failed stream is the one line that names no
session.
The second half of the same line:
Streaming failed before deliverylogs theexception without
exc_info. That branch is not transport-only — it alsocatches client-side exceptions raised while accumulating the stream. So all
that survives a failure is
No session (it cannot be tied to a turn) and no traceback (the raising frame,
ours or the SDK's, is unknown). I hit this debugging a project of my own: with
more than one session live in the process, that line was unattributable after
the fact, and the failure had to be chased by other means.
The change
Two edits in
agent/chat_completion_helpers.py:bind_worker_session_context(agent)— a small helper that bindsagent.session_idto the current thread's log context, called as the firststatement of the streaming worker's
_call(). Best-effort by contract: anagent without
session_idleaves the thread unbound rather than raisinginside the worker.
exc_info=Trueon the pre-delivery stream failure log.This is the same class of gap as #41726 (sync logging session context on
compaction id rotation) — a code path that runs outside the thread the context
was bound on. No behavior changes beyond attribution and the traceback; the log
level is unchanged.
Why not the existing
_context_thread_target?The worker is already wrapped with it (
chat_completion_helpers.py:4071), butthat helper propagates ContextVars, and the session context is a
threading.local(hermes_logging.py:80) —contextvars.copy_context()doesnot carry it. Making
_session_contextaContextVarwould fix this class ofgap everywhere at once and is arguably the better end state, but it changes the
semantics of
set_session_context/clear_session_contextfor every caller,so I kept this PR to the one call site. Happy to take that route instead if
you'd prefer it.
Tests
tests/agent/test_stream_worker_session_context.py— 4 cases covering thebinding's contract:
red if the helper is a no-op)
The helper resolves
hermes_loggingthroughsys.modulesand reinstalls therecord factory from the live module, so the tests are order-independent in the
full suite (several tests reload modules).
— 🤖 Claude Opus 5