Skip to content

Commit e3427ff

Browse files
Alexey Panfilovclaude
andcommitted
fix(usage): record UsageLog on the streaming path too
Stage A.1 hooked only Router.Chat; the production agent uses Router.ChatStream, so after deploy usage_log stayed empty despite "usage logging enabled" and successful LLM calls. Fix plumbs usage through the streaming path end to end: * StreamChunk gets a Usage field populated on the final Done chunk. * openai_compat.readSSE parses the SSE terminal chunk's usage block (OpenRouter sends one with choices=[] when usage.include=true), including cached_tokens and reasoning_tokens from the nested *_details sub-objects. Bumps the SSE scanner buffer to 1MB so long reasoning traces don't hide the usage chunk. * Router.ChatStream wraps the provider's channel with instrumentedStream: it tees chunks through to the caller, and when the Done chunk arrives it calls the same recordUsage routine Router.Chat uses. Start-of-stream errors and sync/fallback paths also get a UsageLog row (with error_class set) so dashboards surface failed calls. After this, every LLM request — streamed or not, successful or not — produces exactly one usage_log record per provider hop. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
1 parent 22c80ac commit e3427ff

3 files changed

Lines changed: 74 additions & 9 deletions

File tree

internal/llm/openai_compat.go

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -140,13 +140,15 @@ type rawChatRequest struct {
140140

141141
// rawStreamDelta is an SSE chunk from an OpenAI-compatible streaming response.
142142
type rawStreamDelta struct {
143+
ID string `json:"id"`
143144
Choices []struct {
144145
Delta struct {
145146
Content string `json:"content"`
146147
ToolCalls []rawToolCall `json:"tool_calls"`
147148
} `json:"delta"`
148149
FinishReason *string `json:"finish_reason"`
149150
} `json:"choices"`
151+
Usage *rawUsage `json:"usage"` // last chunk (usually after finish_reason) carries this when usage.include=true
150152
}
151153

152154
// rawMessage uses `any` for Content so we can serialize null, string, or array.
@@ -455,8 +457,14 @@ func (p *openAICompatProvider) readSSE(resp *http.Response, ch chan<- StreamChun
455457

456458
// Accumulate tool calls across deltas (they arrive in fragments).
457459
var toolCallsByIdx = make(map[int]*rawToolCall)
460+
var usage Usage
461+
var haveUsage bool
458462

459463
scanner := bufio.NewScanner(resp.Body)
464+
// Stream responses can include large payloads (reasoning traces, long tool
465+
// arguments). Default Scanner buffer is 64KB; bump to 1MB so we don't miss
466+
// the final usage chunk on long responses.
467+
scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024)
460468
for scanner.Scan() {
461469
line := scanner.Text()
462470
if !strings.HasPrefix(line, "data: ") {
@@ -471,6 +479,24 @@ func (p *openAICompatProvider) readSSE(resp *http.Response, ch chan<- StreamChun
471479
if err := json.Unmarshal([]byte(data), &delta); err != nil {
472480
continue
473481
}
482+
483+
// Usage block: OpenRouter sends a terminal chunk with choices=[] and
484+
// a populated usage object when usage.include=true.
485+
if delta.Usage != nil {
486+
usage.PromptTokens = delta.Usage.PromptTokens
487+
usage.CompletionTokens = delta.Usage.CompletionTokens
488+
if delta.Usage.PromptTokensDetails != nil {
489+
usage.CachedPromptTokens = delta.Usage.PromptTokensDetails.CachedTokens
490+
}
491+
if delta.Usage.CompletionTokensDetails != nil {
492+
usage.ReasoningTokens = delta.Usage.CompletionTokensDetails.ReasoningTokens
493+
}
494+
haveUsage = true
495+
}
496+
if delta.ID != "" && usage.RequestID == "" {
497+
usage.RequestID = delta.ID
498+
}
499+
474500
if len(delta.Choices) == 0 {
475501
continue
476502
}
@@ -517,6 +543,9 @@ func (p *openAICompatProvider) readSSE(resp *http.Response, ch chan<- StreamChun
517543
})
518544
}
519545
}
546+
if haveUsage {
547+
final.Usage = usage
548+
}
520549
if err := scanner.Err(); err != nil {
521550
final.Err = err
522551
}

internal/llm/provider.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -68,6 +68,7 @@ type StreamChunk struct {
6868
ToolCalls []ToolCall // populated only in the final Done chunk if the LLM returned tool calls
6969
Done bool // true when the stream is finished
7070
Err error // non-nil if the stream encountered an error
71+
Usage Usage // populated on the final Done chunk when the provider reports token counts
7172
}
7273

7374
// StreamProvider is an optional interface for providers that support streaming.

internal/llm/router.go

Lines changed: 44 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -436,30 +436,64 @@ func splitProviderName(name string) (provider, model string) {
436436
// Falls back to wrapping a synchronous Chat() in a single-chunk channel.
437437
func (r *Router) ChatStream(ctx context.Context, messages []Message, systemPrompt string, tools []Tool) (<-chan StreamChunk, error) {
438438
provider := r.pick(ctx, messages)
439+
primaryKey := r.keyFor(provider)
439440
r.mu.Lock()
440441
r.lastRouted = provider.Name()
441-
r.lastRoutedKey = r.keyFor(provider)
442+
r.lastRoutedKey = primaryKey
442443
r.mu.Unlock()
443444
if sp, ok := provider.(StreamProvider); ok {
444445
ch, err := sp.ChatStream(ctx, messages, systemPrompt, tools)
445-
if err != nil && isUnavailable(err) {
446-
// Try fallback providers synchronously.
447-
return r.syncFallbackStream(ctx, provider, messages, systemPrompt, tools, err)
446+
if err != nil {
447+
// Even a start-of-stream failure deserves a usage record with
448+
// error_class set so dashboards see it.
449+
r.recordUsage(ctx, provider, primaryKey, Response{}, err, 0)
450+
if isUnavailable(err) {
451+
return r.syncFallbackStream(ctx, provider, messages, systemPrompt, tools, err)
452+
}
453+
return nil, err
448454
}
449-
return ch, err
455+
return r.instrumentedStream(ctx, provider, primaryKey, ch), nil
450456
}
451457
// Provider does not stream — wrap synchronous call.
452458
return r.syncStream(ctx, provider, messages, systemPrompt, tools)
453459
}
454460

455-
// syncStream wraps a synchronous Chat() call in a channel.
461+
// instrumentedStream tees the provider's stream to the caller and records a
462+
// UsageLog entry when the terminal chunk arrives. Usage data comes from the
463+
// provider (openai_compat parses it out of the SSE payload); when absent the
464+
// record still lands with zero tokens so dashboards show the call happened.
465+
func (r *Router) instrumentedStream(ctx context.Context, provider Provider, role string, upstream <-chan StreamChunk) <-chan StreamChunk {
466+
out := make(chan StreamChunk, 64)
467+
start := time.Now()
468+
go func() {
469+
defer close(out)
470+
var finalResp Response
471+
var finalErr error
472+
for chunk := range upstream {
473+
out <- chunk
474+
if chunk.Done {
475+
finalResp = Response{ToolCalls: chunk.ToolCalls, Usage: chunk.Usage}
476+
finalErr = chunk.Err
477+
}
478+
}
479+
r.recordUsage(ctx, provider, role, finalResp, finalErr, time.Since(start))
480+
}()
481+
return out
482+
}
483+
484+
// syncStream wraps a synchronous Chat() call in a channel. Usage is recorded
485+
// via the same path as Router.Chat so streaming callers that hit non-stream
486+
// providers still produce UsageLog rows.
456487
func (r *Router) syncStream(ctx context.Context, provider Provider, messages []Message, systemPrompt string, tools []Tool) (<-chan StreamChunk, error) {
488+
role := r.keyFor(provider)
489+
start := time.Now()
457490
resp, err := provider.Chat(ctx, messages, systemPrompt, tools)
491+
r.recordUsage(ctx, provider, role, resp, err, time.Since(start))
458492
if err != nil {
459493
return nil, err
460494
}
461495
ch := make(chan StreamChunk, 1)
462-
ch <- StreamChunk{Delta: resp.Content, ToolCalls: resp.ToolCalls, Done: true}
496+
ch <- StreamChunk{Delta: resp.Content, ToolCalls: resp.ToolCalls, Done: true, Usage: resp.Usage}
463497
close(ch)
464498
return ch, nil
465499
}
@@ -479,12 +513,13 @@ func (r *Router) syncFallbackStream(ctx context.Context, failed Provider, messag
479513
if r.OnFallback != nil {
480514
r.OnFallback(failed.Name(), next.Name())
481515
}
482-
// Try streaming on fallback if supported.
516+
// Try streaming on fallback if supported — still instrumented.
483517
if sp, ok := next.(StreamProvider); ok {
484518
ch, err := sp.ChatStream(ctx, messages, systemPrompt, tools)
485519
if err == nil {
486-
return ch, nil
520+
return r.instrumentedStream(ctx, next, "fallback", ch), nil
487521
}
522+
r.recordUsage(ctx, next, "fallback", Response{}, err, 0)
488523
}
489524
// Otherwise sync.
490525
return r.syncStream(ctx, next, messages, systemPrompt, tools)

0 commit comments

Comments
 (0)