Skip to content

fix(cli): stop losing render telemetry to the exit race#2105

Open
kiritowoo wants to merge 1 commit into
heygen-com:mainfrom
kiritowoo:fix/render-telemetry-flush
Open

fix(cli): stop losing render telemetry to the exit race#2105
kiritowoo wants to merge 1 commit into
heygen-com:mainfrom
kiritowoo:fix/render-telemetry-flush

Conversation

@kiritowoo

Copy link
Copy Markdown
Contributor

render_complete / render_error almost never survived a real render: the lazy beforeExit flush() drained the queue and started an async POST, then the render command's teardown killed the process (agent-pipe EPIPE -> process.exit(0), error paths -> process.exit(1)) with the request still in flight -- and the drained events were gone. Only ~10-15% of successful renders (measured against cli_command_result command=render, exit 0) ever produced a render_complete, and the survivors skewed toward users with low RTT to PostHog. cli_command_result itself always survived because the exit handler ships it via a detached child process.

  • flush() now forgets events only after the request completes; on failure or mid-flight process death the queue keeps them, so the exit-time flushSync() child (the already-reliable path) re-sends them.
  • Every event carries a client-generated uuid, making the fallback re-send idempotent on PostHog's side instead of double-counting.
  • trackRenderComplete / trackRenderError flush eagerly: right after a render the process is alive and idle -- no reason to wait for exit and race the teardown.

What

Brief description of the change.

Why

Why is this change needed?

How

How was this implemented? Any notable design decisions?

Test plan

How was this tested?

  • Unit tests added/updated
  • Manual testing performed
  • Documentation updated (if applicable)

render_complete / render_error almost never survived a real render: the
lazy beforeExit flush() drained the queue and started an async POST, then
the render command's teardown killed the process (agent-pipe EPIPE ->
process.exit(0), error paths -> process.exit(1)) with the request still
in flight -- and the drained events were gone. Only ~10-15% of successful
renders (measured against cli_command_result command=render, exit 0) ever
produced a render_complete, and the survivors skewed toward users with
low RTT to PostHog. cli_command_result itself always survived because the
exit handler ships it via a detached child process.

- flush() now forgets events only after the request completes; on failure
  or mid-flight process death the queue keeps them, so the exit-time
  flushSync() child (the already-reliable path) re-sends them.
- Every event carries a client-generated uuid, making the fallback
  re-send idempotent on PostHog's side instead of double-counting.
- trackRenderComplete / trackRenderError flush eagerly: right after a
  render the process is alive and idle -- no reason to wait for exit and
  race the teardown.

@miga-heygen miga-heygen left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM — clean fix for a real data-loss race.

The root cause is well-identified: flush() drained the queue (clearing it) before the HTTP request completed, so when process.exit killed the in-flight request, the events were gone from both the queue and the wire. ~85-90% of render_complete events were lost this way.

The fix is structurally sound:

  1. Deferred queue clearingflush() now snapshots the queue, sends the snapshot, and only removes those specific events on success. Events queued mid-flight survive. Events from a failed send survive for the flushSync() fallback.

  2. Client-generated UUIDs — each event gets a randomUUID() at enqueue time, making the flushSync() re-send idempotent on PostHog's side. This is the right layer for the UUID (enqueue, not send), since the whole point is that the same event may traverse both the async and sync send paths.

  3. Eager flush after render eventsvoid flush() after trackRenderComplete / trackRenderError sends while the process is still alive and idle, instead of gambling on the beforeExit race. The void operator correctly discards the promise so it doesn't block the render pipeline.

  4. Tests cover the exact failure modes — delivery-gated removal, retry with stable UUID, mid-flight enqueue safety, and flushSync drain. Solid coverage of the contract.

One minor observation: concurrent flush() calls are possible (eager flush + beforeExit flush racing), but the snapshot-then-filter approach handles this correctly — no double-removal, no data loss, and PostHog dedupes on UUID. No action needed.

— Miga

@james-russo-rames-d-jusso james-russo-rames-d-jusso left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at 1377995.

Clean, targeted fix. The queue-persistence + client-uuid design is the right shape — non-eager events (trackRenderObservation, trackSubTimelineWaitFallback, etc.) get the same reliability benefit for free (they're kept in queue until the exit-time flushSync child delivers them), while render_complete + render_error additionally get the eager-flush optimization. Tests are well-scoped: the same-uuid-on-retry assertion pins the idempotency invariant, and the gated "does not drop events queued while a flush is in flight" test is exactly the right shape for the concurrent-add semantic. The void flush() in trackRenderComplete / trackRenderError also incidentally holds the event loop long enough that beforeExit fires only after the eager flush completes, so there's no concurrent-flush window on the CLI's normal-exit path — nice bonus.

Nits

  • flush() docstring is incomplete on call sites. packages/cli/src/telemetry/client.ts:135-148 says "Called before normal process exit via beforeExit, and eagerly after high-value events" — but the same function is also awaited by packages/cli/src/commands/feedback.ts:52, feedback.ts:167, commands/events.ts:56, and commands/figma/cliError.ts:33. Either drop the enumeration or generalize to "Called eagerly after high-value events, before normal exit via beforeExit, and awaited directly by commands that need to persist telemetry before returning".

  • flushSync test only asserts the queue drains, not that the child would deliver. packages/cli/src/telemetry/client.test.ts:106-113 verifies the queue is empty after flushSync(), but never mocks node:child_process.spawn — so a regression that broke the child spawn (e.g. a typo in the inline -e string, a missed argument, or a change to detached: true / child.unref()) would still pass this test. Cheap defensive addition: vi.mock("node:child_process", ...) with a spawn spy, then assert spawn.mock.calls[0]?.[1]?.[1] contains the batch payload. Optional; the two paths that matter most (queue-persistence on failure, same-uuid on retry) already have good coverage.

Questions

  • Adjacent observation — cli.ts EPIPE path sets commandFailed = true (packages/cli/src/cli.ts:272-274, outside this PR's diff). The PR body describes EPIPE as the NORMAL exit path for render — "agent pipe closing triggers the EPIPE process.exit(0)". But then the exit handler at cli.ts:264 records success: code === 0 && !commandFailed, which evaluates to false for those EPIPE-successful renders (exit code is 0, but commandFailed was flipped in the EPIPE branch). If the "~10-15% of successful renders" baseline is computed against cli_command_result command=render AND exitCode=0, the baseline is fine. If it's computed against success=true, the baseline may be systematically undercounting the very population this fix targets, which would make the before/after impact measurement harder to trust. Worth a quick sanity check on the PostHog query used to compute the rate. Not gating.

What I didn't verify

  • PostHog's dedup-on-uuid behavior against your project's actual ingestion configuration. The PR reasoning (and the same-uuid-on-retry test) rely on PostHog treating the client-supplied uuid as the event id. That's standard per their capture docs, but I haven't confirmed against your project settings or observed a dedup happen live in staging.

  • CI is green at HEAD (13779953) on run 29034335653 for what's completed; Build, Test, Typecheck, Studio: load smoke, CLI smoke (required), Windows render, Preview parity, CLI: npx shim (windows-latest), and Analyze (javascript-typescript) were still in progress at review time.

Review by Rames D Jusso

@miguel-heygen miguel-heygen left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The implementation direction looks right: flush() snapshots the queue and removes only confirmed-delivered events, and render complete/error now trigger eager async flush with UUIDs for retry idempotency.

blocker: packages/cli/src/telemetry/client.test.ts:40 is failing required Test CI because the job runs with HYPERFRAMES_NO_TELEMETRY=1. trackEvent() reaches client.ts:49, disables telemetry, caches telemetryEnabled = false, and queues nothing, so the three new fetch assertions see zero calls. The test needs to clear/stub HYPERFRAMES_NO_TELEMETRY (and likely DO_NOT_TRACK) before exercising/importing the client, or expose/reset the cached telemetry decision for this test file, then rerun CI.

— Magi

Verdict: REQUEST CHANGES
Reasoning: The code shape is sound, but a required CI check is red on the PR's own telemetry tests, so this cannot be stamped until the test environment/cache interaction is fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants