Repository navigation
fix(harness): hold the Claude prompt until Claude Code can trace the turn - #2943
Conversation
…turn Signed-off-by: David Haifley <[email protected]>
krisztianfekete
left a comment
krisztianfekete
left a comment
There was a problem hiding this comment.
I am fine shipping this with the fixes below. There are some stuff that are currently specific to Claude Code only, so longer term, I think we want something like this:
How about solving this in our runtime as that already seems to be a good fit for this? Drivers turn their output into runtime.EventSink events, and one executor emits invoke_agent. If we add an event for model calls (model, tokens, stop reason, timing, etc.), the executor can emit GenAI semconv spans and metrics for every harness in one place, checked by the Weaver registry from #2906. Native spans like claude_code.* then will become optional extra enhancement layer, and the core functionality will work even without them.
| SkillRoot: skillRoot, PluginDirs: pluginDirs, Environment: environment, | ||
| MaxEventBytes: cfg.MaxEventBytes, MaxStderrBytes: cfg.MaxStderrBytes, | ||
| InterruptGrace: cfg.InterruptGrace(), | ||
| InterruptGrace: cfg.InterruptGrace(), AwaitTracing: slices.Contains(environment, "OTEL_TRACES_EXPORTER=otlp"), |
There was a problem hiding this comment.
Will logs have the same race problem? In my testing Claude emits user_prompt and api_request before init and the debug log shows Event dropped. With OTEL_LOGS_EXPORTER=otlp and traces off, those events are lost silently and nothing gates. Since nativeTelemetryEnvironment already computes the traces-or-logs condition a few lines down, what about deriving AwaitTracing from that instead of repeating the string match here. The name could be something like AwaitTelemetry, or similar. Wdyt?
There was a problem hiding this comment.
Yes, I think you're right, and metrics have the same race. Claude Code creates its event logger and its metric counters in the same initialization that registers the tracer provider, and anything recorded before then is dropped, which matches the Event dropped lines you saw. It increments the session counter only after all three are in place, so the same gate covers them. In a9b9a1d nativeTelemetryEnvironment returns whether it turned Claude Code telemetry on, and the adapter passes that as AwaitTelemetry, so the prompt is held whenever any signal is exported, including logs with traces off.
|
|
||
| const ( | ||
| // sessionCountMetric is the Prometheus name of claude_code.session.count. | ||
| sessionCountMetric = "claude_code_session_count" |
There was a problem hiding this comment.
This is an implementation detail, that can change in the future without notice. It works in 2.1.260 and 2.1.280 in my local testing, so let's include this in the comment above, + mention that when there's a Claude Code release that awaits telemetry init in print mode, we can likely remove this. We should also see if we can pin to tested versions in tests/CI.
There was a problem hiding this comment.
Agreed. The comment on sessionCountMetric now says the ordering is an implementation detail, verified on 2.1.260 and 2.1.282, that can change without notice, and that the gate can likely go once a release waits for telemetry initialization in print mode. The README says the same, and it matches your 2.1.280 testing. On pinning, I think we're already covered. The image installs 2.1.260 by checksum, and the compiled config sets StrictVersion with PinnedClaudeVersion, so the harness refuses to start on any other version, and the e2e runs that image. I also added a note on PinnedClaudeVersion that a bump must recheck the gate.
| return | ||
| } | ||
| if err != nil { | ||
| logging.FromContext(ctx).WarnContext(ctx, "tracing was not ready before the prompt, so this turn's Claude spans may be missing", |
There was a problem hiding this comment.
Can we add a span event on the current span here, and the same on L188 when the port cannot be reserved, so an incomplete trace is explainable from the trace itself? A counter for gate timeouts would also let us see how often this happens in real deployments, but that can be a follow-up.
There was a problem hiding this comment.
Good idea. In a9b9a1d both fallbacks go through one helper that logs the warning and adds a kagent.claude.telemetry_not_ready event to the invoke_agent span, with error.type set to timeout or port_unavailable. I kept the event out of the Weaver registry for now. Would it make sense to register it together with the timeout counter in the follow-up, so the event and the metric land in the contract at the same time?
| Code increments only after its tracer provider is registered. The wait is bounded | ||
| at 10 seconds, so a stalled settings fetch delays a turn by at most that much, and | ||
| the turn then runs without its Claude spans. | ||
|
|
There was a problem hiding this comment.
Wondering if we should open an upstream bug report for this.
There was a problem hiding this comment.
Yes, I think we should.
| sessionCountMetric = "claude_code_session_count" | ||
| // tracingReadyTimeout caps the delay a stalled managed settings fetch adds | ||
| // to a turn, which then runs without its Claude spans. | ||
| tracingReadyTimeout = 10 * time.Second |
There was a problem hiding this comment.
Claude's (undocumented) barrier backstop is 30 s ("Loading promise timed out, resolving anyway"), and the settings request is 10s with retries. With a 10s gate, a stalled fetch sends the prompt, and telemetry can still come up mid-turn. That gives the partially traced turn with orphan roots this PR is fixing, just rarer. How about matching the 30s ceiling or documenting in the README that a stall past 10s produces orphan roots, not a clean absence?
There was a problem hiding this comment.
You're right, and thanks for finding this. I confirmed it in the 2.1.260 bundle, where remote settings use a 10 s request timeout and a 30 s barrier that resolves anyway. I'd lean toward keeping the 10 s bound, though. Every turn starts a new Claude process and a new settings fetch, so during a sustained stall the full wait lands on every turn, and I think 30 s per turn costs more than a partially traced turn that is now marked. The README and the tracingReadyTimeout comment now say that in a turn that runs past Claude's 30 s, spans started after its telemetry initializes become roots of new traces rather than being absent, and those turns carry the new kagent.claude.telemetry_not_ready event.
…telemetry signal Signed-off-by: David Haifley <[email protected]>
…turn (kagent-dev#2943) A Claude Harness turn against the real Anthropic API exports no `claude_code.*` spans under the turn's trace, so the trace holds only the harness runtime's spans (kagent-dev#2922). This holds each prompt until Claude Code can trace it, which makes Claude's spans arrive on every turn. Closes kagent-dev#2922 **Why** Claude Code starts a print-mode turn without waiting for its own OpenTelemetry initialization. With an Anthropic API key and no custom base URL, it first waits on a fetch of the organization's managed settings from `api.anthropic.com/api/claude_code/settings`. Until the tracer provider and W3C propagator register, every span is a no-op span and `TRACEPARENT` is ignored. In an actor the turn starts first, so `claude_code.interaction` is lost and later `llm_request` and `tool` spans become roots of new traces. With Claude Code's debug log routed out of the actor, the first turn logged `[engine] turn 1 start` 16 ms before `isTelemetryEnabled`, and the second 110 ms before the settings fetch settled. The e2e passes because its mock sets `ANTHROPIC_BASE_URL`, which skips the fetch. It is not a flush problem. The driver already waits for the process to exit, and Claude Code flushes what it recorded on exit. Claude Code 2.1.260 and 2.1.282 behave the same, and neither has a setting that makes print mode wait. **What changes** - The driver passes the prompt on stdin with `--input-format stream-json` instead of as an argument, and closes stdin on the terminal result so Claude exits as before. - When traces are exported, the driver adds Claude Code's `prometheus` metrics reader on a free loopback port. It writes the prompt once `claude_code.session.count` appears there. Claude increments that counter only after `initializeTelemetry` has registered the tracer provider and propagator, so the counter proves the turn will be traced. Both are documented Claude Code telemetry surfaces. - The wait is bounded at 10 seconds, which caps the delay a stalled settings fetch can add. Claude Code gives each settings request 10 seconds and retries it, so during such a stall the turn runs without its Claude spans and logs a warning, as it also does if the port cannot be reserved. - `OTEL_EXPORTER_PROMETHEUS_HOST` and `OTEL_EXPORTER_PROMETHEUS_PORT` join the Claude-owned environment, so a Harness cannot redirect the reader. The gate costs about 100 ms on a turn whose settings fetch is still in flight, and next to nothing when it has settled. Bedrock, Vertex and custom base URLs skip the fetch, so their gate opens as soon as initialization finishes, which also closes the smaller race they had. **Verification** - On kind with Agent Substrate 0.2.0-beta5, this change applied to `v1.0.0-alpha2` and the real Anthropic API, 10 of 10 turns exported Claude's spans under the turn's trace. They were cold and warm unary turns, a Bash tool turn (`chat`, `execute_tool`, `chat`) and a `SendStreamingMessage` turn. The published `claude-harness` image on the same cluster exported none in 7 of 7 turns, 3 of them run alongside. - Without Substrate, the pinned image in Docker behind a proxy that adds 1.5 s to `api.anthropic.com` exported nothing in 2 of 2 warm runs with stream-json input alone. With the gate it exported both runs' spans, and the turn started 47 to 50 ms after initialization. - `TestProcessDriverAwaitsTracing` runs the test binary as a Claude Code that registers tracing 200 ms after start, and asserts the prompt arrives afterwards. It fails with the gate off. `TestTracingGateWait`, `TestTracingGateReadyReportsUnreadableScrape`, `TestTracingGateEnvironment` and the updated `TestProcessDriverArgumentsAndStream` cover the bound, early exit, a scrape that cannot be read, the metrics environment and the stdin message. - `go test ./harness/... ./core/internal/translator/...`, `go vet`, `gofmt` and `go fix` are clean, and so is golangci-lint over `./harness/claude/...` with the repository config minus its kube-api-linter plugin, which does not load on macOS and checks only API types. --------- Signed-off-by: David Haifley <[email protected]>
A Claude Harness turn against the real Anthropic API exports no
claude_code.*spans under the turn's trace, so the trace holds only the harness runtime's spans (#2922). This holds each prompt until Claude Code can trace it, which makes Claude's spans arrive on every turn.Closes #2922
Why
Claude Code starts a print-mode turn without waiting for its own OpenTelemetry initialization. With an Anthropic API key and no custom base URL, it first waits on a fetch of the organization's managed settings from
api.anthropic.com/api/claude_code/settings. Until the tracer provider and W3C propagator register, every span is a no-op span andTRACEPARENTis ignored. In an actor the turn starts first, soclaude_code.interactionis lost and laterllm_requestandtoolspans become roots of new traces. With Claude Code's debug log routed out of the actor, the first turn logged[engine] turn 1 start16 ms beforeisTelemetryEnabled, and the second 110 ms before the settings fetch settled. The e2e passes because its mock setsANTHROPIC_BASE_URL, which skips the fetch. It is not a flush problem. The driver already waits for the process to exit, and Claude Code flushes what it recorded on exit. Claude Code 2.1.260 and 2.1.282 behave the same, and neither has a setting that makes print mode wait.What changes
--input-format stream-jsoninstead of as an argument, and closes stdin on the terminal result so Claude exits as before.prometheusmetrics reader on a free loopback port. It writes the prompt onceclaude_code.session.countappears there. Claude increments that counter only afterinitializeTelemetryhas registered the tracer provider and propagator, so the counter proves the turn will be traced. Both are documented Claude Code telemetry surfaces.OTEL_EXPORTER_PROMETHEUS_HOSTandOTEL_EXPORTER_PROMETHEUS_PORTjoin the Claude-owned environment, so a Harness cannot redirect the reader.The gate costs about 100 ms on a turn whose settings fetch is still in flight, and next to nothing when it has settled. Bedrock, Vertex and custom base URLs skip the fetch, so their gate opens as soon as initialization finishes, which also closes the smaller race they had.
Verification
v1.0.0-alpha2and the real Anthropic API, 10 of 10 turns exported Claude's spans under the turn's trace. They were cold and warm unary turns, a Bash tool turn (chat,execute_tool,chat) and aSendStreamingMessageturn. The publishedclaude-harnessimage on the same cluster exported none in 7 of 7 turns, 3 of them run alongside.api.anthropic.comexported nothing in 2 of 2 warm runs with stream-json input alone. With the gate it exported both runs' spans, and the turn started 47 to 50 ms after initialization.TestProcessDriverAwaitsTracingruns the test binary as a Claude Code that registers tracing 200 ms after start, and asserts the prompt arrives afterwards. It fails with the gate off.TestTracingGateWait,TestTracingGateReadyReportsUnreadableScrape,TestTracingGateEnvironmentand the updatedTestProcessDriverArgumentsAndStreamcover the bound, early exit, a scrape that cannot be read, the metrics environment and the stdin message.go test ./harness/... ./core/internal/translator/...,go vet,gofmtandgo fixare clean, and so is golangci-lint over./harness/claude/...with the repository config minus its kube-api-linter plugin, which does not load on macOS and checks only API types.