Files
coder/coderd/x/chatd/messagepartbuffer/message_part_buffer_test.go
T
4b7494be72 feat: harden chat generation runtime instrumentation for billing (#27451)
Closes CODAGT-835

## Summary

`chat_messages.runtime_ms` becomes the billing source of truth for Coder
Agents runtime (summed hourly by #27312), but it was built for
debugging: the June refactor (#26270) silently stopped recording
tool-step runtime, compaction was never measured, and interrupted turns
lost their partial runtime entirely. This PR defines the billable
metric, closes the paths that dropped it, and documents the definition
where the data lives.

## The billable definition

**`runtime_ms` is the wall-clock duration of the model invocation that
produced the persisted message content**, measured from just before the
provider stream opens until it is fully consumed.

What counts:

- Assistant generation steps, in top-level and sub-agent chats
(sub-agents are ordinary chats on the same generation path).
- Compaction summarization calls, persisted on the compaction assistant
message (**new**).
- Interrupted attempts: the message-part episode's lifetime is persisted
on the partial assistant message committed by `FinishInterruption`, so
partial generation time survives interruption (**new**; measured via a
new `Buffer.EpisodeDuration`, which works even though the generation
goroutine and the interrupt task are different tasks).

What deliberately does not count (each is documented in code and docs):

- **Local tool execution.** Tool wall time includes idle waits, most
importantly `wait_agent` polling a sub-agent chat that already bills its
own model invocations; billing the batch would double count, and
excluding one tool from a concurrent batch's wall time is ill-defined.
Pre-refactor instrumentation did include tool time; this makes the
exclusion an explicit product definition instead of a silent regression.
- **Failed model calls whose output is discarded** (retried attempts,
terminal errors, content-filter refusals). They persist no content, so
they bill nothing; billing errs toward undercounting. Notably a
stream-silence timeout can burn 10 idle minutes before a retry, which
should not be billable "active generation". If product later wants
failed attempts billed, that needs a place to persist runtime on error
turns (`FinishError` inserts no rows today) and is a deliberate
follow-up, not instrumentation drift.
- **Ancillary calls that produce no chat messages** (title generation,
advisor, turn summaries) and all idle/parked time (`requires_action`,
queueing).

The definition is documented as `COMMENT ON COLUMN
chat_messages.runtime_ms` (migration 000551, surfacing as a Go doc
comment on `ChatMessage.RuntimeMs`), on
`chatloop.PersistedStep.Runtime`, in the chatd architecture doc, and in
the Spend Management docs page.

## Index for the hourly scan

None needed: `GetTotalChatMessageRuntimeMsInRange` (#27312) filters an
hour-wide `created_at` range, which the existing
`idx_chat_messages_created_at` b-tree already serves; the residual
`runtime_ms IS NOT NULL` filter applies to one hour of rows. A partial
index would add permanent write amplification for a query that runs once
an hour.

> [!NOTE]
> Migration 000551 is also claimed by #27312; whichever merges second
renumbers via `fix_migration_numbers.sh`.

## Tests

- End-to-end: the existing full-server generation test now asserts
`RuntimeMs.Valid` on the committed assistant row (it previously read
`.Int64` without checking `.Valid`, so it passed on NULL).
- Interrupted turn: full task-level test (real DB, mock clock) asserting
the partial assistant message persists the attempt's runtime.
- Errored stream: asserts a failed invocation yields no step and no
runtime.
- Tool-using turn: asserts runtime lands on the assistant row only and
tool rows stay NULL.
- Compaction: asserts the summarization call duration is recorded and
lands on the compaction assistant message only.
- `messagepartbuffer.EpisodeDuration` unit coverage.

Blocks: CODAGT-843 (B3), CODAGT-838 (D8).

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Co-authored-by: Hugo Dutka <hugo@coder.com>
2026-08-06 16:09:38 +07:00

464 lines
15 KiB
Go

package messagepartbuffer_test
import (
"context"
"encoding/json"
"testing"
"time"
"github.com/google/uuid"
"github.com/stretchr/testify/require"
"github.com/coder/coder/v2/coderd/x/chatd/messagepartbuffer"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/coder/v2/testutil"
"github.com/coder/quartz"
)
func TestBuffer_CreateEpisodeRejectsDuplicate(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.ErrorIs(t, buffer.CreateEpisode(key), messagepartbuffer.ErrEpisodeExists)
}
func TestBuffer_AddPartAndGetParts(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("hello")))
parts, err := buffer.GetParts(key)
require.NoError(t, err)
require.Len(t, parts, 1)
require.Equal(t, int64(1), parts[0].Seq)
require.Equal(t, codersdk.ChatMessageRoleAssistant, parts[0].Role)
require.Equal(t, codersdk.ChatMessageText("hello"), parts[0].MessagePart)
}
func TestBuffer_AddPartMissingEpisodeReturnsNotFound(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
err := buffer.AddPart(testEpisodeKey(), codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("hello"))
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
}
func TestBuffer_GetPartsMissingEpisodeReturnsNotFound(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
_, err := buffer.GetParts(testEpisodeKey())
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
}
func TestBuffer_AddPartFullEpisodeReturnsFull(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{MaxEpisodeBytes: 1})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
err := buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("hello"))
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeFull)
parts, getErr := buffer.GetParts(key)
require.NoError(t, getErr)
require.Empty(t, parts)
}
func TestBuffer_CloseEpisodeMissingCreatesClosedEpisode(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CloseEpisode(key))
parts, err := buffer.GetParts(key)
require.NoError(t, err)
require.Empty(t, parts)
err = buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("tail"))
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeClosed)
}
func TestBuffer_CloseEpisodeIdempotent(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.CloseEpisode(key))
require.NoError(t, buffer.CloseEpisode(key))
}
func TestBuffer_ModelInvokedAt(t *testing.T) {
t.Parallel()
clock := quartz.NewMock(t)
buffer := messagepartbuffer.New(messagepartbuffer.Options{Clock: clock})
defer buffer.Close()
key := testEpisodeKey()
require.Zero(t, buffer.ModelInvokedAt(key), "unknown episode has no invocation stamp")
require.ErrorIs(t, buffer.StartModelInvocation(key), messagepartbuffer.ErrEpisodeNotFound)
require.NoError(t, buffer.CreateEpisode(key))
require.Zero(t, buffer.ModelInvokedAt(key), "episode without a provider stream has no invocation stamp")
// Attempt setup happens before the provider stream opens and is
// not billable.
clock.Advance(time.Second)
require.NoError(t, buffer.StartModelInvocation(key))
invokedAt := buffer.ModelInvokedAt(key)
require.Equal(t, clock.Now(), invokedAt)
// A repeat call re-stamps the start so only the most recent
// invocation is billed.
clock.Advance(time.Second)
require.NoError(t, buffer.StartModelInvocation(key))
require.Equal(t, clock.Now(), buffer.ModelInvokedAt(key))
// Closing must not move the recorded stamp, and a closed episode
// no longer accepts an invocation start.
invokedAt = buffer.ModelInvokedAt(key)
clock.Advance(1500 * time.Millisecond)
require.NoError(t, buffer.CloseEpisode(key))
require.ErrorIs(t, buffer.StartModelInvocation(key), messagepartbuffer.ErrEpisodeClosed)
require.Equal(t, invokedAt, buffer.ModelInvokedAt(key))
// Episodes that never open a provider stream, such as local tool
// execution batches, report no invocation stamp.
toolBatch := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(toolBatch))
clock.Advance(time.Second)
require.NoError(t, buffer.CloseEpisode(toolBatch))
require.Zero(t, buffer.ModelInvokedAt(toolBatch))
// Episodes created implicitly by CloseEpisode never started a
// generation attempt, so they report no invocation stamp.
implicit := testEpisodeKey()
require.NoError(t, buffer.CloseEpisode(implicit))
require.Zero(t, buffer.ModelInvokedAt(implicit))
}
func TestBuffer_SubscribeExistingReplaysThenStreamsLiveParts(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("before")))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
require.Equal(t, "before", receivePart(t, ch).MessagePart.Text)
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("after")))
require.Equal(t, "after", receivePart(t, ch).MessagePart.Text)
}
func TestBuffer_SubscribeClosedEpisodeReplaysThenCloses(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("before")))
require.NoError(t, buffer.CloseEpisode(key))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
require.Equal(t, "before", receivePart(t, ch).MessagePart.Text)
assertChannelClosed(t, ch)
}
func TestBuffer_SubscribeBeforeCreateReturnsAndWaitsWithoutNotFound(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
select {
case part := <-ch:
t.Fatalf("received part before episode create: %+v", part)
default:
}
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("live")))
require.Equal(t, "live", receivePart(t, ch).MessagePart.Text)
}
func TestBuffer_AddPartAssignsContiguousSeq(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
for i := range 3 {
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText(string(rune('a'+i)))))
}
parts, err := buffer.GetParts(key)
require.NoError(t, err)
require.Equal(t, []int64{1, 2, 3}, []int64{parts[0].Seq, parts[1].Seq, parts[2].Seq})
}
func TestBuffer_EpisodeByteLimitUsesJSONAccounting(t *testing.T) {
t.Parallel()
part := codersdk.ChatMessageText("hello")
limit := serializedPartBytes(t, messagepartbuffer.Part{Seq: 1, Role: codersdk.ChatMessageRoleAssistant, MessagePart: part})
buffer := messagepartbuffer.New(messagepartbuffer.Options{MaxEpisodeBytes: limit})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, part))
err := buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("too much"))
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeFull)
}
func TestBuffer_GCClosedEpisodeAfterGraceAndNoSubscribers(t *testing.T) {
t.Parallel()
clock := quartz.NewMock(t)
trap := clock.Trap().NewTimer("message-part-buffer", "subscriber-send")
defer trap.Close()
buffer := messagepartbuffer.New(messagepartbuffer.Options{
Clock: clock,
ClosedEpisodeRetention: time.Minute,
SubscriberSendTimeout: 10 * time.Minute,
})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("held")))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
require.NoError(t, buffer.CloseEpisode(key))
call := trap.MustWait(ctx)
call.MustRelease(ctx)
clock.Advance(time.Minute).MustWait(ctx)
clock.Advance(time.Second).MustWait(ctx)
_, err = buffer.GetParts(key)
require.NoError(t, err)
cancel()
drainUntilClosed(t, ch)
_, err = buffer.GetParts(key)
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
}
func TestBuffer_GCRetainedSubscribedEpisodeDoesNotBlockOtherExpiredEpisodes(t *testing.T) {
t.Parallel()
clock := quartz.NewMock(t)
trap := clock.Trap().NewTimer("message-part-buffer", "subscriber-send")
defer trap.Close()
buffer := messagepartbuffer.New(messagepartbuffer.Options{
Clock: clock,
ClosedEpisodeRetention: time.Minute,
SubscriberSendTimeout: 10 * time.Minute,
})
defer buffer.Close()
retainedKey := testEpisodeKey()
collectedKey := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(retainedKey))
require.NoError(t, buffer.AddPart(retainedKey, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("held")))
require.NoError(t, buffer.CreateEpisode(collectedKey))
require.NoError(t, buffer.AddPart(collectedKey, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("collect me")))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, retainedKey)
require.NoError(t, err)
defer cancel()
require.NoError(t, buffer.CloseEpisode(retainedKey))
require.NoError(t, buffer.CloseEpisode(collectedKey))
call := trap.MustWait(ctx)
call.MustRelease(ctx)
clock.Advance(time.Minute).MustWait(ctx)
clock.Advance(time.Second).MustWait(ctx)
_, err = buffer.GetParts(retainedKey)
require.NoError(t, err)
_, err = buffer.GetParts(collectedKey)
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
cancel()
drainUntilClosed(t, ch)
_, err = buffer.GetParts(retainedKey)
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
}
func TestBuffer_SlowSubscriberClosed(t *testing.T) {
t.Parallel()
clock := quartz.NewMock(t)
trap := clock.Trap().NewTimer("message-part-buffer", "subscriber-send")
defer trap.Close()
stopTrap := clock.Trap().TimerStop()
defer stopTrap.Close()
buffer := messagepartbuffer.New(messagepartbuffer.Options{
Clock: clock,
SubscriberSendTimeout: time.Second,
})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText("blocked")))
call := trap.MustWait(ctx)
call.MustRelease(ctx)
clock.Advance(time.Second).MustWait(ctx)
stopCall := stopTrap.MustWait(ctx)
stopCall.MustRelease(ctx)
assertChannelClosed(t, ch)
}
func TestBuffer_BurstyOutputDoesNotCloseSubscriberBeforeSendTimeout(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
require.NoError(t, buffer.CreateEpisode(key))
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
for i := range 8 {
require.NoError(t, buffer.AddPart(key, codersdk.ChatMessageRoleAssistant, codersdk.ChatMessageText(string(rune('a'+i)))))
}
for i := range 8 {
part := receivePart(t, ch)
require.Equal(t, string(rune('a'+i)), part.MessagePart.Text)
}
}
func TestBuffer_SubscribeCanceledBeforeCreateCanCreateEpisode(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
ctx, cancel := context.WithCancel(context.Background())
ch, cancelSub, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
cancel()
drainUntilClosed(t, ch)
cancelSub()
require.NoError(t, buffer.CreateEpisode(key))
}
func TestBuffer_SubscribeCanceledWithoutCreateReclaimsEpisode(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancelSub, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
cancelSub()
// The subscriber goroutine removes itself from the episode before closing
// the output channel, so cleanup is complete once the channel is closed.
drainUntilClosed(t, ch)
_, err = buffer.GetParts(key)
require.ErrorIs(t, err, messagepartbuffer.ErrEpisodeNotFound)
require.Equal(t, 0, buffer.EpisodeCount())
}
func TestBuffer_CloseClosesPendingSubscriptionAndRejectsOperations(t *testing.T) {
t.Parallel()
buffer := messagepartbuffer.New(messagepartbuffer.Options{})
defer buffer.Close()
key := testEpisodeKey()
ctx := testutil.Context(t, testutil.WaitLong)
ch, cancel, err := buffer.SubscribeToEpisode(ctx, key)
require.NoError(t, err)
defer cancel()
buffer.Close()
assertChannelClosed(t, ch)
require.ErrorIs(t, buffer.CreateEpisode(key), messagepartbuffer.ErrMessagePartBufferClosed)
}
func testEpisodeKey() messagepartbuffer.Key {
return messagepartbuffer.Key{ChatID: uuid.New(), HistoryVersion: 1, GenerationAttempt: 1}
}
func receivePart(t *testing.T, ch <-chan messagepartbuffer.Part) messagepartbuffer.Part {
t.Helper()
select {
case part, ok := <-ch:
require.True(t, ok)
return part
case <-time.After(testutil.WaitLong):
t.Fatal("timed out waiting for buffered part")
return messagepartbuffer.Part{}
}
}
func assertChannelClosed[T any](t *testing.T, ch <-chan T) {
t.Helper()
select {
case _, ok := <-ch:
require.False(t, ok)
case <-time.After(testutil.WaitLong):
t.Fatal("timed out waiting for channel close")
}
}
func drainUntilClosed[T any](t *testing.T, ch <-chan T) {
t.Helper()
for {
select {
case _, ok := <-ch:
if !ok {
return
}
case <-time.After(testutil.WaitLong):
t.Fatal("timed out waiting for channel close")
}
}
}
func serializedPartBytes(t *testing.T, part messagepartbuffer.Part) int64 {
t.Helper()
data, err := json.Marshal(struct {
Seq int64 `json:"seq"`
Role codersdk.ChatMessageRole `json:"role"`
Part codersdk.ChatMessagePart `json:"part"`
}{
Seq: part.Seq,
Role: part.Role,
Part: part.MessagePart,
})
require.NoError(t, err)
return int64(len(data))
}