Skip to content

Commit f816387

Browse files
Telemetry updates
1 parent 19bac4e commit f816387

19 files changed

Lines changed: 689 additions & 59 deletions

‎docs/TELEMETRY.md‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,10 @@ any of the three drift apart.
5151
| usage_delta | input_tokens | provider-reported input tokens since the preceding usage event |
5252
| usage_delta | output_tokens | provider-reported output tokens since the preceding usage event |
5353
| usage_delta | total_tokens | the sum of this event's input and output tokens |
54+
| usage_delta | routing_provider | openrouter, openai, anthropic, google, bedrock, azure, ollama, other, or unknown |
55+
| usage_delta | model_family | deepseek, claude, gpt, gemini, llama, qwen, kimi, glm, other, or unknown |
56+
| usage_delta | usage_status | reported or missing |
57+
| usage_delta | accounting_source | provider or engine |
5458
| session_ended | mode | chat or task |
5559
| session_ended | duration | a band: under 1m, 1-5m, 5-30m, 30m-2h, 2h or more |
5660
| session_ended | turns | a count band |
@@ -67,8 +71,8 @@ any of the three drift apart.
6771

6872
Count bands are 0, 1, 2-5, 6-20, 21-100 and 100+. Dollar bands are 0, under
6973
0.01, 0.01-0.1, 0.1-1, 1-10 and 10+.
70-
Each numeric usage delta is written when provider accounting arrives, including
71-
tokens read from cache once. Missing usage contributes no event. Deltas, rather
74+
Each provider usage receipt is appended locally before provider accounting returns, including
75+
tokens read from cache once. Missing provider receipts produce a `usage_status = missing` event without token fields; a missing receipt never invents a zero total. Routing categories follow the actual attempt, including an explicitly authorized billing-door switch and any later generation receipt. Bounded routing and model-family categories describe reported usage without sending exact model names or endpoint addresses. Hosted engines currently report aggregate turn deltas with unknown routing and family, labelled `accounting_source = engine`; those aggregates are not per-call receipts and can be lost before a turn ends. Deltas, rather
7276
than repeated session totals, make the stream safe to sum while a run is open.
7377

7478
first_run carries only the every-event properties and is sent once per
@@ -82,7 +86,7 @@ ids never leave this machine.
8286

8387
Prompts, model replies, code, file names, paths, repo or directory names, git
8488
remotes, hostnames, usernames, IP addresses, environment values, API keys,
85-
email addresses, model names, error text, panic messages. A test builds every
89+
email addresses, exact model names, custom model names, error text, panic messages. Public model-family categories are sent as described above. A test builds every
8690
event from inputs stuffed with exactly these and fails if any of them reach
8791
the marshalled output.
8892

@@ -93,7 +97,7 @@ per request, every 30 seconds while a session is open and once more when it
9397
ends. Nothing older than 7 days is sent and at most 1000 lines are kept. An
9498
event whose version is unknown is dropped at send time and never leaves the
9599
machine. The spool is plain JSON lines, so what has not left yet can be read
96-
with any editor.
100+
with any editor. A local warning reports storage failures or counts discarded by the age/size limits; it contains no event contents. These warnings do not establish how many tokens were lost.
97101

98102
## Turning it off
99103

@@ -148,3 +152,5 @@ the count GitHub already shows on the release page. Sidecar files such as
148152
`.github/workflows/release-downloads.yml`; the script behind it is
149153
`scripts/release_downloads.py`, and running it with `--dry-run` prints the
150154
batch it would send.
155+
156+
The release-download workflow fails visibly when its production PostHog key or GitHub token is missing; dry-run still works without a PostHog key.
Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
---
2+
kind: changed
3+
title: Usage receipts distinguish routing, model families and missing counts
4+
pr: 1755
5+
surface: [engine, remote, build, docs]
6+
invalidates:
7+
- "Usage telemetry carried only positive token totals. It now includes bounded routing and model-family categories and explicitly records missing provider receipts without token totals."
8+
- "Provider usage appends ran on background goroutines. Completed receipts are now appended before accounting returns, while network delivery stays periodic."
9+
- "Usage categories named the initial service even after a plan overflow. They now follow the actual attempt route, including later generation receipt recovery. Periodic delivery no longer holds the local append lock across network requests."
10+
- "Missing release-download credentials silently passed the scheduled job. Production reporting now fails visibly when required credentials are absent."
11+
---

‎internal/manual/chat/telemetry.md‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
# Usage counts and privacy
2+
3+
## What anonymous usage counts collect
4+
5+
codeaf sends anonymous session counts and provider-reported input/output token counts when telemetry is enabled. Usage receipts include a bounded routing-service category and public model family, never an exact model name, endpoint address, prompt, code, path or API key. Missing provider receipts have a missing status and no invented token total. Completed local provider receipts are appended before accounting returns, then sent every 30 seconds and at shutdown. Hosted chat currently sends turn aggregates with unknown provider and family; work lost before a turn ends is not guaranteed to appear.
6+
7+
## Turning anonymous counts off
8+
9+
Set `CODEAF_TELEMETRY=off`, `DO_NOT_TRACK=1`, or the telemetry switch in `/settings`. Project settings can also turn telemetry off. Disabled telemetry sends no usage receipts. The detailed public contract is in `docs/TELEMETRY.md`.

‎internal/provider/calllog.go‎

Lines changed: 30 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -121,6 +121,9 @@ type callTrace struct {
121121
// row written after the transport returned always names the attempt that
122122
// actually produced the answer.
123123
attemptID string
124+
// attemptBase is the address this attempt actually used, including an
125+
// explicitly authorized plan overflow. It never leaves the process.
126+
attemptBase string
124127
// open is the attempt that has a start row on the wire and nothing under it
125128
// yet, and nil whenever the log is square.
126129
//
@@ -171,6 +174,7 @@ type openAttempt struct {
171174
request *ai.Request
172175
knobs callKnobs
173176
stream bool
177+
base string
174178
}
175179

176180
// The words [calllog.Record.Ended] uses. They are constants for the reason the
@@ -212,6 +216,7 @@ func (t *callTrace) track(facts recordFacts, id string) {
212216
request: facts.request,
213217
knobs: facts.knobs,
214218
stream: facts.stream,
219+
base: facts.baseFor(t.attemptBase),
215220
}
216221
}
217222

@@ -229,7 +234,7 @@ func (c *Client) closeOpenAttempt(ctx context.Context, trace *callTrace, ended s
229234
trace.open = nil
230235
c.record(recordFacts{
231236
ctx: ctx, request: open.request, knobs: open.knobs, stream: open.stream,
232-
attempt: open.attempt, began: open.began, ended: ended, id: open.id,
237+
attempt: open.attempt, began: open.began, ended: ended, id: open.id, base: open.base,
233238
})
234239
}
235240

@@ -270,6 +275,9 @@ func (t *callTrace) note(learned ...string) {
270275
// endpoint has no status and no tokens, and the emptiness law leaves both off
271276
// the line rather than writing a zero somebody could read as a measurement.
272277
type recordFacts struct {
278+
// base is explicit on synthetic endings of an earlier attempt.
279+
base string
280+
273281
ctx context.Context
274282
request *ai.Request
275283
knobs callKnobs
@@ -519,7 +527,15 @@ func (c *Client) record(facts recordFacts) {
519527
// sentence is the failure verdict and its cost the spend, 0 when absent.
520528
if record.Phase != calllog.PhaseStart {
521529
telemetry.CountModelCall(record.Error == "", record.Cost)
522-
telemetry.CountTokens(record.PromptTokens, record.CompletionTokens)
530+
status := "missing"
531+
if facts.response != nil && facts.response.Usage != nil {
532+
status = "reported"
533+
}
534+
telemetry.CountUsage(record.PromptTokens, record.CompletionTokens, telemetry.UsageDimensions{
535+
RoutingProvider: telemetry.RoutingProvider(facts.baseFor(c.config.BaseURL)),
536+
ModelFamily: telemetry.ModelFamily(model), UsageStatus: status,
537+
AccountingSource: "provider", ReceiptID: record.ID,
538+
})
523539
}
524540
c.recordBodies(facts, record, model)
525541
}
@@ -820,3 +836,15 @@ func (c *Client) relaxNames(model string, knobs callKnobs) []string {
820836
}
821837
return names
822838
}
839+
840+
// baseFor reads the route of this row's attempt rather than the client's
841+
// initial service, which can differ after an authorized billing-door switch.
842+
func (facts recordFacts) baseFor(fallback string) string {
843+
if facts.base != "" {
844+
return facts.base
845+
}
846+
if facts.knobs.trace != nil && facts.knobs.trace.attemptBase != "" {
847+
return facts.knobs.trace.attemptBase
848+
}
849+
return fallback
850+
}

‎internal/provider/client.go‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1116,7 +1116,7 @@ func (c *Client) completionInOnePiece(
11161116
began: logBegan, status: status, served: served, err: err,
11171117
response: &response, reasoningTokens: reasoningTokens, responseBody: payload,
11181118
})
1119-
c.settle(ctx, c.modelFor(request), &response, receiptRefusalReason, len(responseText(&response)))
1119+
c.settle(ctx, c.modelFor(request), &response, receiptRefusalReason, len(responseText(&response)), knobs.trace)
11201120
return nil, false, err
11211121
}
11221122
// AND THE SAME SPLIT THE STREAM TAKES, taken over the whole body (answer.go).
@@ -1818,7 +1818,7 @@ func (c *Client) completeWithMessagesStreaming(
18181818
// An endpoint producing soup has failed this lineage as surely as one
18191819
// that went quiet, so the pin moves too.
18201820
c.releaseEndpoint(ctx, c.modelFor(request))
1821-
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len())
1821+
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len(), knobs.trace)
18221822
return nil, false, cut
18231823
}
18241824
for {
@@ -1866,7 +1866,7 @@ func (c *Client) completeWithMessagesStreaming(
18661866
response: response, reasoningTokens: reasoningTokens,
18671867
ttft: firstTokenAfter(began, firstToken),
18681868
})
1869-
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len())
1869+
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len(), knobs.trace)
18701870
return nil, false, cut
18711871
}
18721872
// A stream that broke off for any reason but a cut — the caller
@@ -1879,7 +1879,7 @@ func (c *Client) completeWithMessagesStreaming(
18791879
response: response, reasoningTokens: reasoningTokens,
18801880
ttft: firstTokenAfter(began, firstToken),
18811881
})
1882-
c.settle(ctx, c.modelFor(request), response, receiptTornReason, content.Len())
1882+
c.settle(ctx, c.modelFor(request), response, receiptTornReason, content.Len(), knobs.trace)
18831883
return nil, false, decodeErr
18841884
}
18851885
if response.ID == "" {
@@ -1933,7 +1933,7 @@ func (c *Client) completeWithMessagesStreaming(
19331933
ttft: firstTokenAfter(began, firstToken),
19341934
})
19351935
c.releaseEndpoint(ctx, c.modelFor(request))
1936-
c.settle(ctx, c.modelFor(request), response, receiptRefusalReason, content.Len())
1936+
c.settle(ctx, c.modelFor(request), response, receiptRefusalReason, content.Len(), knobs.trace)
19371937
return nil, false, refusal
19381938
}
19391939
if chunk.Usage != nil {
@@ -2147,7 +2147,7 @@ func (c *Client) completeWithMessagesStreaming(
21472147
response: response, reasoningTokens: reasoningTokens,
21482148
ttft: firstTokenAfter(began, firstToken),
21492149
})
2150-
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len())
2150+
c.settle(ctx, c.modelFor(request), response, cut.Reason.word(), content.Len(), knobs.trace)
21512151
return nil, false, cut
21522152
}
21532153
response.Choices = []ai.Choice{{Index: 0, FinishReason: finishReason, Message: ai.Message{
@@ -2164,7 +2164,7 @@ func (c *Client) completeWithMessagesStreaming(
21642164
response: response, reasoningTokens: reasoningTokens,
21652165
ttft: firstTokenAfter(began, firstToken),
21662166
})
2167-
c.settle(ctx, c.modelFor(request), response, receiptRefusalReason, content.Len())
2167+
c.settle(ctx, c.modelFor(request), response, receiptRefusalReason, content.Len(), knobs.trace)
21682168
return nil, false, err
21692169
}
21702170
// The last call has no successor to close it, so the clean end of the stream

‎internal/provider/dispatch.go‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -467,6 +467,9 @@ func (c *Client) send(ctx context.Context, request *ai.Request, knobs callKnobs,
467467
// the end of it (calllog.go). The count lives on the knobs rather than
468468
// here because a call that is repaired or relaxed comes back through
469469
// this loop with a new body and the same trace.
470+
if knobs.trace != nil {
471+
knobs.trace.attemptBase = currentBase
472+
}
470473
knobs.trace.begin()
471474
if attempt > 0 && switchedDoor {
472475
// A BILLING-DOOR SWITCH IS NEITHER A RECONNECTION NOR A RETRY. The

‎internal/provider/funnel_law_test.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -345,12 +345,12 @@ func TestNothingOutsideTheFunnelTalksToAModelEndpoint(t *testing.T) {
345345
// which are request/response and carry no stream at all
346346
// Fetch sheetFetcher's GET of the lane sheet, which is not a model call
347347
// — it is the belief the choice is made from (lanes.go)
348-
// fetchReceipt the bounded background GET for a cut stream's exact generation
348+
// fetchReceiptAt the bounded background GET for a cut stream's exact generation
349349
// receipt; it creates no model work and never runs on the turn
350350
//
351351
// probeConnection is a credential-free HEAD of the configured origin. Its
352352
// contract tests forbid a prompt, a request body or redirect following.
353-
var funnelWireSenders = []string{"Fetch", "doEndpoint", "fetchReceipt", "probeConnection", "probeLane", "send"}
353+
var funnelWireSenders = []string{"Fetch", "doEndpoint", "fetchReceiptAt", "probeConnection", "probeLane", "send"}
354354

355355
// funnelSendCallers is every function that reaches [Client.send].
356356
//

‎internal/provider/receipt.go‎

Lines changed: 32 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,8 @@ import (
1212

1313
"github.com/Agent-Field/agentfield/sdk/go/ai"
1414
"github.com/Agent-Field/codeaf/internal/guard"
15+
"github.com/Agent-Field/codeaf/internal/modelsource"
16+
"github.com/Agent-Field/codeaf/internal/telemetry"
1517
)
1618

1719
// THE RECEIPT: MONEY A CUT STREAM LEFT OFF THE WIRE.
@@ -99,6 +101,8 @@ type receiptWork struct {
99101
result Reconciled
100102
sink ReconcileSink
101103
queued time.Time
104+
usage func(int, int)
105+
base string
102106
}
103107

104108
// deadline is the latest a receipt may be answered: [receiptFetchTimeout] after
@@ -157,7 +161,11 @@ func (m *receiptRouteMemo) heard(base string, now time.Time) {
157161
// measured first-frame in-band refusal is an upstream breaking before it
158162
// produced a generation, not money the provider charged. Those mutually
159163
// exclusive doors keep one call from ever being counted twice.
160-
func (c *Client) settle(ctx context.Context, model string, response *ai.Response, reason string, answerBytes int) {
164+
func (c *Client) settle(ctx context.Context, model string, response *ai.Response, reason string, answerBytes int, traces ...*callTrace) {
165+
base := c.config.BaseURL
166+
if len(traces) > 0 && traces[0] != nil && traces[0].attemptBase != "" {
167+
base = traces[0].attemptBase
168+
}
161169
if response != nil && response.Usage != nil {
162170
c.bill(ctx, model, response)
163171
return
@@ -166,7 +174,7 @@ func (c *Client) settle(ctx context.Context, model string, response *ai.Response
166174
// usage block supplies no measured figures to record, and calling the
167175
// router's route on the vendor would send that vendor a request and bearer
168176
// for a fact this client already knows cannot be there.
169-
if c.config.Direct {
177+
if c.config.Direct && (base == c.config.BaseURL || telemetry.RoutingProvider(base) != modelsource.DefaultID) {
170178
return
171179
}
172180
sink := reconcileFrom(ctx)
@@ -193,7 +201,11 @@ func (c *Client) settle(ctx context.Context, model string, response *ai.Response
193201
}
194202
return
195203
}
196-
work := receiptWork{result: result, sink: sink}
204+
work := receiptWork{result: result, sink: sink, base: base, usage: telemetry.CaptureUsageRecorder(telemetry.UsageDimensions{
205+
RoutingProvider: telemetry.RoutingProvider(base),
206+
ModelFamily: telemetry.ModelFamily(result.Model), UsageStatus: "reported",
207+
AccountingSource: "provider", ReceiptID: "generation:" + result.Ref,
208+
})}
197209
// THE WORK IS TOLD A RECEIPT IS OWED BEFORE IT IS QUEUED, and told it was
198210
// answered only after the sink has banked it, so a caller waiting for its
199211
// receipts cannot see zero owed while money is between the two
@@ -264,15 +276,18 @@ func (c *Client) nextReceipt() (receiptWork, bool) {
264276
// counted from when the receipt was queued ([receiptWork.deadline]).
265277
func (c *Client) reconcile(work receiptWork) {
266278
result := work.result
267-
base := strings.TrimRight(strings.TrimSpace(c.config.BaseURL), "/")
279+
base := strings.TrimRight(strings.TrimSpace(work.base), "/")
280+
if base == "" {
281+
base = strings.TrimRight(strings.TrimSpace(c.config.BaseURL), "/")
282+
}
268283
if !receiptRoutes.askable(base, time.Now()) {
269284
work.sink(result)
270285
return
271286
}
272287
ctx, cancel := context.WithDeadline(context.Background(), work.deadline())
273288
defer cancel()
274289
for attempt := 0; attempt < receiptAttempts; attempt++ {
275-
billed, found, noRoute := c.fetchReceipt(ctx, result.Ref)
290+
billed, found, noRoute := c.fetchReceiptAt(ctx, result.Ref, base)
276291
if noRoute {
277292
receiptRoutes.heard(base, time.Now())
278293
work.sink(result)
@@ -283,6 +298,12 @@ func (c *Client) reconcile(work receiptWork) {
283298
billed.Model = result.Model
284299
result.Billed = billed
285300
result.Found = true
301+
// Recovery is reached only when the stream had no usage block, so
302+
// these tokens replace an unknown receipt rather than add to a
303+
// previously reported total.
304+
if work.usage != nil {
305+
work.usage(billed.PromptTokens, billed.CompletionTokens)
306+
}
286307
work.sink(result)
287308
return
288309
}
@@ -312,7 +333,12 @@ type receiptWire struct {
312333
// receipt from the one durable capability answer; every other failure simply
313334
// leaves both false so the caller may follow its bounded retry schedule.
314335
func (c *Client) fetchReceipt(ctx context.Context, ref string) (Billed, bool, bool) {
315-
endpoint, err := url.Parse(strings.TrimSpace(c.config.BaseURL))
336+
return c.fetchReceiptAt(ctx, ref, c.config.BaseURL)
337+
}
338+
339+
// fetchReceiptAt follows the route the generation actually used.
340+
func (c *Client) fetchReceiptAt(ctx context.Context, ref, base string) (Billed, bool, bool) {
341+
endpoint, err := url.Parse(strings.TrimSpace(base))
316342
if err != nil {
317343
return Billed{}, false, false
318344
}

‎internal/provider/receipt_test.go‎

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import (
55
"fmt"
66
"net/http"
77
"net/http/httptest"
8+
"strings"
89
"sync"
910
"sync/atomic"
1011
"testing"
@@ -939,3 +940,35 @@ func TestAReceiptIsAnsweredWithinReceiptWaitOfBeingQueued(t *testing.T) {
939940
t.Fatalf("the receipt was answered %v after it was queued, past ReceiptWait %v", answered, ReceiptWait)
940941
}
941942
}
943+
944+
// The actual receipt wire door retains both response and caller-context bounds
945+
// when recovery selects the route of an overflow attempt.
946+
func TestActualReceiptWireDoorKeepsResponseAndDeadlineBounds(t *testing.T) {
947+
t.Run("response size", func(t *testing.T) {
948+
server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
949+
w.Header().Set("Content-Type", "application/json")
950+
_, _ = fmt.Fprint(w, strings.Repeat(" ", maxReceiptBytes)+`{"data":{"tokens_prompt":10,"tokens_completion":3}}`)
951+
}))
952+
t.Cleanup(server.Close)
953+
client := receiptTestClient(t, server)
954+
ctx, cancel := context.WithTimeout(context.Background(), time.Second)
955+
defer cancel()
956+
if _, found, _ := client.fetchReceiptAt(ctx, "oversized", server.URL); found {
957+
t.Fatal("receipt read beyond maxReceiptBytes")
958+
}
959+
})
960+
t.Run("caller deadline", func(t *testing.T) {
961+
server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { <-r.Context().Done() }))
962+
t.Cleanup(server.Close)
963+
client := receiptTestClient(t, server)
964+
ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond)
965+
defer cancel()
966+
began := time.Now()
967+
if _, found, _ := client.fetchReceiptAt(ctx, "waiting", server.URL); found {
968+
t.Fatal("expired receipt was reported found")
969+
}
970+
if time.Since(began) > time.Second {
971+
t.Fatal("receipt wire door ignored caller deadline")
972+
}
973+
})
974+
}

0 commit comments

Comments
 (0)