Skip to content

Trace sink is process-global: multi-session traces are interleaved and unattributable #306

Description

@jbellis

Summary

append_trace_record resolves its destination from the process-global ANVIL_TRACE_JSONL environment variable, read fresh on every call (src/trace_logging.rs:7). Nothing scopes a trace record to the session that produced it, and records carry no session identifier — a grep for session_id across the 21 append_trace_record call sites in tool_loop.rs returns zero.

A single anvil process holds many sessions concurrently (sessions: Arc<RwLock<HashMap<String, Session>>>, session.rs:2949). So when two sessions run at once with tracing enabled, both append into the same file, interleaved, with no way to attribute any record to a session.

Why it hasn't bitten yet

The benchmark harness runs one anvil per container per task (bpr_agent_engine.py:765 sets ANVIL_TRACE_JSONL per container), so there is exactly one session per process. The defect is latent, not active. It surfaces for any deployment that serves concurrent sessions from one process with tracing on.

How it surfaced

The same root cause produced a ~1-in-4 flake in asgard::orchestration::tests::review_reminds_pending_and_allows_evidence_finalize. Six asgard tests set ANVIL_TRACE_JSONL and serialize on ENV_GUARD, but the ~100 tests that merely emit records take no guard and write into whichever file is currently configured. The test matched an asgard_finalize record on evidence alone, and at least four other tests finalize with the same ["w1m1"] evidence, so it intermittently asserted against a sibling's record.

Worked around in a495fe4 by matching on a commit that resolves in the test's own repo. That fixes the test; it does not fix the sink.

Suggested fix

Replace the ambient global with a sink threaded through the values that already reach every call site — e.g. a TraceSink handle on SessionStore, or passed alongside cx/llm. That crosses tokio::spawn by construction, and is the natural point to stamp session_id into every record.

Rejected alternative: a tokio::task_local override. It scopes correctly for tests (asgard v2 runs workers in a FuturesUnordered in one task), but task_local does not cross tokio::spawn — a spawned task starts with an empty set and silently falls back to the env var. acp.rs has four spawns in the request path, so this would give isolation that works until someone adds a spawn, then degrades silently. That is the worst failure mode for a telemetry sink.

Scope

~47 append_trace_record call sites (tool_loop.rs 21, asgard/orchestration.rs 20, train_bifrost.rs 5, bedrock_client.rs 2, asgard/intake.rs 1). Call sites keep the same shape; the sink argument changes.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions