Skip to content

telemetry: don't record error on chat span after successful LLM completion#3281

Merged
dgageot merged 1 commit into
docker:mainfrom
jedp-docker:fix/chat-span-false-errors
Jul 3, 2026
Merged

telemetry: don't record error on chat span after successful LLM completion#3281
dgageot merged 1 commit into
docker:mainfrom
jedp-docker:fix/chat-span-false-errors

Conversation

@jedp-docker

Copy link
Copy Markdown
Contributor

Summary

  • handleStream returns the moment it sees a terminal finish_reason (a deliberate latency optimisation — don't block the next turn on trailing message_stop/EOF). The deferred stream.Close() then closes the HTTP/2 body while the reader goroutine is still blocked in Recv(), causing that read to return "http2: response body closed" (or "context canceled" if the per-attempt streamCancel fires first).
  • instrumentedStream was recording this transport-level teardown as a span error even when the completion had fully succeeded — every affected span also carries gen_ai.response.finish_reasons=["stop"] and full token usage, confirming the response was complete.
  • This inflates the docker-agent error rate on every LLM call. Observed consistently across all harbor_watch.investigation traces in Tempo.

Fix: add finishReasonSeen bool to instrumentedStream (set-once on the single-consumer Recv path). Once a terminal finish reason is delivered, skip RecordError for subsequent transport errors — they're benign teardown, not failures. endOnce is still called so the span closes.

Test plan

  • Verify existing genai package tests pass: go test ./pkg/telemetry/genai/...
  • In Tempo: after deploy, confirm chat claude-* spans with finish_reasons=stop no longer appear as STATUS_CODE_ERROR
  • Confirm spans that fail before a finish reason (genuine mid-stream errors) still record errors

🤖 Generated with Claude Code

@docker-agent docker-agent left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assessment: 🟢 APPROVE

The fix is correct and well-scoped. The finishReasonSeen flag is set on the single-consumer Recv path — no concurrency risk — and the teardown-suppression logic correctly gates only RecordError, leaving endOnce() unconditional so spans always close. All terminal finish reasons are covered (the flag trips on any non-empty FinishReason, not just "stop"). The explanatory comment accurately describes the transport-teardown scenario and the intended invariant.

No bugs found in the introduced code.

@aheritier aheritier added area/telemetry Telemetry, tracing, and metrics kind/fix PR fixes a bug (maps to fix:). Use on PRs only. labels Jun 27, 2026
@jedp-docker jedp-docker force-pushed the fix/chat-span-false-errors branch 5 times, most recently from 6960f55 to ec2a5b4 Compare June 29, 2026 20:43
@jedp-docker jedp-docker marked this pull request as ready for review July 1, 2026 19:56
@jedp-docker jedp-docker requested a review from a team as a code owner July 1, 2026 19:56

@docker-agent docker-agent left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assessment: 🔴 CRITICAL

The fix correctly identifies and addresses the false-positive span error problem. However, the new finishReasonSeen field introduces a data race — it is read and written on the hot path without the mu lock that already guards the other lifecycle flags (ended, innerClosed). A secondary edge case exists where a provider returns a finish reason and a transport error in the same Recv call, which the current guard logic misses.

// consumer closing the body before draining to io.EOF.
if !errors.Is(err, io.EOF) {
s.span.RecordError(err, ClassifyError(err))
if !s.finishReasonSeen {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[HIGH] Data race on finishReasonSeen: read/write without synchronization while concurrent Close+Recv is an intended usage pattern

finishReasonSeen is read at line 102 (if !s.finishReasonSeen) and written at line 126 (s.finishReasonSeen = true) with no lock held, yet the existing mu comment explicitly says it protects against "a Recv that errors concurrently with the consumer's Close". The typical teardown path this PR fixes is: consumer goroutine calls Close() while another goroutine is blocked in s.inner.Recv(). Once the transport error fires, that goroutine reads finishReasonSeen at line 102. If a separate Recv call is concurrently at line 126 writing true, or if the Go memory model doesn't guarantee visibility without synchronization, this is an unsynchronized concurrent read/write — a classic data race detectable by go test -race.

All other lifecycle flags (ended, innerClosed) are already protected by s.mu. finishReasonSeen should be too. Two clean options:

// Option A: atomic bool (zero overhead, no lock widening)
finishReasonSeen atomic.Bool

// read:
if !s.finishReasonSeen.Load() {
    s.span.RecordError(err, ClassifyError(err))
}
// write:
s.finishReasonSeen.Store(true)
// Option B: hold s.mu around both the read and the write
// (read — inside the err != nil branch)
s.mu.Lock()
seen := s.finishReasonSeen
s.mu.Unlock()
if !seen {
    s.span.RecordError(err, ClassifyError(err))
}

// (write — inside the choices loop)
s.mu.Lock()
s.finishReasonSeen = true
s.mu.Unlock()

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

finishReasonSeen has no data race in practice. It is read and written exclusively inside Recv(), which is called by a single consumer goroutine — the reader loop in handleStream. The goroutine that runs concurrently (Close()/endOnce() via defer stream.Close()) never touches finishReasonSeen; that's precisely why ended and innerClosed need mu and this field doesn't. This matches the existing unlocked mutations in Recv() — span.MarkChunk(), SetResponseID(), AddFinishReason(), RecordUsage() — which are all single-consumer for the same reason. Adding mu to only finishReasonSeen would be inconsistent with that established pattern.

Comment thread pkg/telemetry/genai/stream.go
handleStream returns the moment it sees a terminal finish_reason rather
than draining the stream to io.EOF (a deliberate latency optimisation).
The deferred stream.Close() then closes the HTTP/2 body while the reader
goroutine is still blocked in Recv(), so that read returns
"http2: response body closed" (or "context canceled" if the per-attempt
streamCancel fires first). instrumentedStream was recording this as a
span error even though the LLM response had already succeeded — every
affected span also carries gen_ai.response.finish_reasons=["stop"] and
full token usage.

Fix: add finishReasonSeen (set-once bool on the single-consumer Recv
path). Once a terminal finish reason has been delivered the completion
has logically succeeded; subsequent transport-level errors are benign
teardown. Skip RecordError but still call endOnce so the span closes.

Co-Authored-By: Claude Sonnet 4.6 (1M context) <[email protected]>
@jedp-docker jedp-docker force-pushed the fix/chat-span-false-errors branch from ec2a5b4 to 27b0b84 Compare July 2, 2026 21:32
@dgageot dgageot merged commit a21ded8 into docker:main Jul 3, 2026
9 of 10 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area/telemetry Telemetry, tracing, and metrics kind/fix PR fixes a bug (maps to fix:). Use on PRs only.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants