fix(telemetry): report each terminal outcome once and stamp usage_context on every event - #954
Conversation
…text on every event Two defects let execution_completed count things that were not executions. Duplicate lifecycle events were forwarded verbatim. A terminal status callback re-delivered after a lost 200 used to re-run every side effect, publishing a second completed event for an execution that had already been reported (#951 closed that path in the handler; the SDKs retry a callback up to five times, so one execution could report several). The telemetry client had no defense of its own: it minted a stable telemetry_event_id and left deduplication entirely to the ingest side. It now remembers the terminal outcomes it has reported and drops a repeat, so a republished event cannot inflate a count regardless of what ingest does with the event ID. Only stable identities are eligible — the random ones belong to transitions allowed to recur, such as timeout -> running -> timeout, and collapsing those would lose real events. The set is bounded at 8192 keys with oldest-first eviction; a duplicate arrives within seconds, so eviction can only drop keys long past the window where they could suppress anything. usage_context rode only on control_plane_started. A CI job starts the control plane on a fresh volume, so it mints a new install ID and its executions look exactly like a real first-time user's — and with the context on the startup event alone, nothing downstream could separate them after ingestion. Disabling telemetry for the functional-test compose stacks was a fix for one known producer; this makes every producer distinguishable at the source. It is now stamped on every event, so execution_completed can be filtered to dev_or_local/server and CI traffic excluded. Schema version goes to 3 so the ingest side can tell a build that stamps usage_context everywhere from one that does not, and know when the filter is trustworthy. Co-authored-by: Santosh kumar <santoshkumarradha@users.noreply.github.com>
📊 Coverage gateThresholds from
✅ Gate passedNo surface regressed past the allowed threshold and the aggregate stayed above the floor. |
📐 Patch coverage gateThreshold: 80% on lines this PR touches vs
✅ Patch gate passedEvery surface whose lines were touched by this PR has patch coverage at or above the threshold. |
AbirAbbas
left a comment
AbirAbbas
left a comment
There was a problem hiding this comment.
Answering the open question in the description: the relay is strict, so this can't merge as-is.
In website2.0, app/api/oss/telemetry/route.ts:79:
telemetry_schema_version: z.union([z.literal(1), z.literal(2)]).optional(),That's safeParse -> 400 invalid_telemetry_event on failure (route.ts:114-117), and posthog.capture is never reached. So a v3 payload isn't degraded or treated as informational, it's dropped whole. There's an explicit regression test pinning it: route.test.ts:158-167 asserts telemetry_schema_version: 3 returns 400. Bumping the constant without a relay change silently zeroes out all control-plane telemetry, which is a worse version of the problem this PR is fixing.
The good news is that the usage_context half needs no relay work at all. It's already in the shared property schema (route.ts:53, z.enum(['ci','server','dev_or_local','unknown'])), and that schema applies to every event name -- there's no per-event discrimination -- so it's accepted and forwarded on execution_completed today via the property spread at route.ts:137. detectUsageContext only ever returns those three values, so they all land.
Which leaves the version bump buying nothing. Nothing about the wire format actually changed here: usage_context is additive and already allowlisted, and the suppression is producer-side and invisible to ingest. I'd keep telemetrySchemaVersion at 2 and ship this now, saving the bump for a change that genuinely breaks the v2 shape. If you'd rather bump anyway, the relay change has to land and deploy first.
One real bug on the suppression ordering, left inline.
Two smaller things. detectUsageContext treats any non-empty value as CI (telemetry.go:187-190), so CI=false -- a real convention people use to opt out of CI behavior -- buckets a genuine user's traffic as ci and filters it out of the product numbers. Checking for a falsy value would avoid discarding real data.
And on the belt-and-braces framing: for stable identities (the only ones eligible for suppression) EventID is always set, and the relay already derives a deterministic PostHog UUID from it (route.ts:97-104 and 127), so ingest already collapses republishes. This layer doesn't add dedupe power the relay lacks -- what it adds is that a republish stops being observable. If a producer bug starts re-emitting terminal events, the counts stay right and the bug goes silent. The only trace is a Debug log; a counter or a Warn would keep that signal alive.
Gates on my end: go build, go vet, -race on ./internal/observability/, and ./internal/handlers/... ./internal/server/... ./internal/events/... all clean. The two execute_agent_restart_test.go failures I hit on the first pass were load-induced flake -- they pass in isolation and on a clean re-run, and on main.
| // Only stable identities are eligible: the random ones above belong to | ||
| // transitions that are allowed to recur, and collapsing those would lose | ||
| // real events. | ||
| if stable && s.reported.observe(eventName+"\x00"+identityMaterial) { |
There was a problem hiding this comment.
observe records the key before enqueue runs, and enqueue can drop the event on a full queue (telemetry.go:253-257 -- 256 deep behind a single worker doing network POSTs with a timeout).
When that happens the outcome is marked reported but never sent, and the republish that would have delivered it is now suppressed. Pre-PR that retry got through. So a transient backpressure drop turns into permanent loss of that execution's terminal event, and it under-counts exactly when volume is high -- the opposite failure of the one you're fixing.
Recording only on a successful send would close it: have enqueue return whether it queued, and call observe in that branch.
3 participants
Summary
Investigating an
execution_completedspike in product metrics (~7k/day baseline → 70k on Aug 22 → 363k on a partial Aug 23) surfaced two defects in the OSS telemetry client that let the event count things that were not executions. This fixes both: a terminal outcome is now reported once per execution, andusage_contextis stamped on every event so CI traffic can be told apart from real usage.Neither defect is the whole story of that spike — the count is aggregated by a hosted relay outside this repo — but both are real, both inflate the same metric, and both were live during the window.
Duplicate lifecycle events were forwarded verbatim. A terminal status callback re-delivered after a lost 200 used to re-run every side effect in
handleStatusUpdate, publishing a secondexecution_completedfor an execution that had already been reported. #951 closed that path in the handler on Aug 23 and measured it directly ("two duplicate succeeded callbacks and one failed callback emitted threeexecution_completedevents"); all three SDKs retry a status callback up to five times, so a single execution could report several. The telemetry client had no defense of its own — it minted a stabletelemetry_event_idand delegated deduplication entirely to the ingest side, so any republish reached the wire and counted if ingest did not honor the ID.handleExecutionEventnow remembers the terminal outcomes it has reported and drops a repeat. Only stable identities are eligible; the random ones assigned in theelsebranch belong to transitions that are allowed to recur (timeout → running → timeout) and collapsing those would lose real events. The set is bounded at 8192 keys with oldest-first eviction — a duplicate arrives within seconds of the original, so eviction can only ever drop a key long past the window in which it could still suppress anything. Keys are built from raw execution IDs and never leave the process; only the existing HMAC is sent.usage_contextrode only oncontrol_plane_started. A CI job starts the control plane on a fresh volume, so it mints a new install ID and its executions are indistinguishable from a real first-time user's. With the context carried by the startup event alone, no downstream query could separate the two after ingestion — which is why the polluted range cannot be cleaned by filtering and has to be trimmed by date instead. #942 disabled telemetry for the functional-test compose stacks, which fixes one known producer; stamping the property on every event makes every producer distinguishable at the source, including ones we have not found yet.detectUsageContextalready existed and already detected CI — it was simply never applied beyond startup.telemetry_schema_versiongoes to2→3so the ingest side can tell a build that stampsusage_contexteverywhere from one that does not, and therefore know for which date ranges ausage_contextfilter is trustworthy. This needs confirmation against the relay atagentfield.ai/api/oss/telemetrybefore merge — if that endpoint validates the version strictly rather than treating it as advisory, a bump would drop events, which is the opposite of what this PR is for.Type of change
Test plan
cd control-plane && go test ./internal/observability/ -count=1cd control-plane && go test ./internal/observability/ -count=1 -race(the suppression set is mutex-guarded)cd control-plane && go test ./internal/observability/... ./internal/handlers/... ./internal/server/... ./internal/events/... -count=1— all greencd control-plane && go build ./... && go vet ./internal/observability/New tests, all in
telemetry_test.go:TestTelemetryTerminalOutcomeReportedOnce— four identical completed/failed/cancelled events enqueue one.TestTelemetryTerminalSuppressionIsPerExecution— two executions completing both report.TestTelemetryNonTerminalEventsAreNotSuppressed— a repeatedexecution_startedis not collapsed.TestTelemetryReportedSetEvictsOldestPastCapacity— bounded growth, oldest-first eviction.TestTelemetryUsageContextStampedOnEveryEvent— execution, node, and plain enqueued events all carry it.TestTelemetryDetectsUsageContext— each CI variable, plusserveranddev_or_local. Clears the ambient CI environment first, or every case would pass on the runner's ownCI=true.TestTelemetryExecutionEventIdentityIsStableAndOpaquechanged rather than being deleted: it used to send the same event twice and read two queue entries, which now blocks because the duplicate is suppressed. It recomputes the identity a republish would carry and asserts it matches the one already sent — the property that actually mattered (ingest can recognize a re-delivery as the same outcome) — and keeps the payload-opacity assertions unchanged.Existing coverage that pins behavior this PR deliberately does not change:
TestTelemetryTimeoutEventIdentityDoesNotCollapseRepeatedTransitionsandTestTelemetryExecutionEventIdentityDoesNotCollapseMissingIDsboth still pass.Test coverage
coverage-baseline.jsonis untouched.Notes for review
usage_contextkeeps the data and makes it filterable, which seemed strictly better than dropping it; turning collection off by default in CI is a product call, and the opt-out is now documented instead.telemetry_event_idremains the cross-process idempotency mechanism, and this is a second line of defense, not a replacement.telemetryReportedSet's zero value is usable and allocates on firstobserve, so a caller constructingTelemetryServicedirectly (as every test in the package does) gets the same behavior as production rather than silently getting none.Related issues / PRs