telemetry: don't record error on chat span after successful LLM completion#3281
Conversation
docker-agent
left a comment
There was a problem hiding this comment.
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.
6960f55 to
ec2a5b4
Compare
docker-agent
left a comment
There was a problem hiding this comment.
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 { |
There was a problem hiding this comment.
[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()There was a problem hiding this comment.
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.
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]>
ec2a5b4 to
27b0b84
Compare
Summary
handleStreamreturns the moment it sees a terminalfinish_reason(a deliberate latency optimisation — don't block the next turn on trailingmessage_stop/EOF). The deferredstream.Close()then closes the HTTP/2 body while the reader goroutine is still blocked inRecv(), causing that read to return"http2: response body closed"(or"context canceled"if the per-attemptstreamCancelfires first).instrumentedStreamwas recording this transport-level teardown as a span error even when the completion had fully succeeded — every affected span also carriesgen_ai.response.finish_reasons=["stop"]and full token usage, confirming the response was complete.docker-agenterror rate on every LLM call. Observed consistently across allharbor_watch.investigationtraces in Tempo.Fix: add
finishReasonSeen booltoinstrumentedStream(set-once on the single-consumerRecvpath). Once a terminal finish reason is delivered, skipRecordErrorfor subsequent transport errors — they're benign teardown, not failures.endOnceis still called so the span closes.Test plan
genaipackage tests pass:go test ./pkg/telemetry/genai/...chat claude-*spans withfinish_reasons=stopno longer appear asSTATUS_CODE_ERROR🤖 Generated with Claude Code