From 4642bc00d6198ae90a91eeacd60f8fff53389312 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Thu, 29 Oct 2026 06:26:41 -0700 Subject: [PATCH] fix(telemetry): never deliver held startup events later than an eager client (#35949) #35798 holds pre-window captures until the first window shows, which can delay delivery past what an eager client does: 20 quick events waited instead of tripping flushAt, and the first flush moved from 10s after the first event to 10s after the client started. Held events now start the client as soon as they reach flushAt, and a deadline 10s after the first held event starts the client if needed and flushes. It stands in for the timer an eager client would have armed, so it retires at the SDK's first flush attempt (the flushAt-th enqueue, whether that send succeeds or fails); after that the SDK's own flushAt and flushInterval alone decide batching. Held events are dropped when consent was withdrawn before start, and quit no longer loads the SDK just to drop them. Fixes #35752 Co-authored-by: Chad Tolkien --- .../telemetry/client-deferred-start.test.ts | 111 ++++++++++++++++-- src/main/telemetry/client.ts | 10 +- src/main/telemetry/posthog-client-start.ts | 75 ++++++++++-- src/main/telemetry/posthog-transport.ts | 6 +- 4 files changed, 177 insertions(+), 25 deletions(-) diff --git a/src/main/telemetry/client-deferred-start.test.ts b/src/main/telemetry/client-deferred-start.test.ts index 601b1676db5..52fe5f38743 100644 --- a/src/main/telemetry/client-deferred-start.test.ts +++ b/src/main/telemetry/client-deferred-start.test.ts @@ -1,4 +1,5 @@ import { afterAll, afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import type { GlobalSettings } from '../../shared/global-settings-types' import type { Store } from '../persistence' import type * as PostHogTransport from './posthog-transport' import { @@ -21,7 +22,15 @@ vi.mock('./posthog-transport', async (importOriginal) => ({ createPostHogClient })) +const realTransport = await vi.importActual('./posthog-transport') const { initTelemetry, setOptIn, shutdownTelemetry, track } = await import('./client') +const realSetTimeout = globalThis.setTimeout +// SDK gzip is really async, so wait in real time while the fake clock stands still. +async function settle(done: () => boolean = () => false): Promise { + for (let i = 0; i < 200 && !done(); i++) { + await new Promise((resolve) => realSetTimeout(resolve, 10)) + } +} const scheduleClientStart = vi.fn<(start: () => void) => void>() afterAll(() => { @@ -31,28 +40,29 @@ afterAll(() => { describe('deferred PostHog client start', () => { let envStash: Record + let settings: GlobalSettings let store: Store - let sdk: MockPostHog + let sdk: MockPostHog & { flush: ReturnType } beforeEach(() => { vi.useFakeTimers({ now: new Date('2026-10-29T00:00:00Z') }) envStash = stashAndClearConsentEnv() vi.spyOn(console, 'warn').mockImplementation(() => {}) - sdk = makeMockPostHog() + sdk = { ...makeMockPostHog(), flush: vi.fn(async () => {}) } createPostHogClient.mockImplementation(() => sdk) - store = makeFakeStore( - makeFakeSettings({ - optedIn: true, - installId: BASE_COMMON.install_id, - existedBeforeTelemetryRelease: false - }) - ) + settings = makeFakeSettings({ + optedIn: true, + installId: BASE_COMMON.install_id, + existedBeforeTelemetryRelease: false + }) + store = makeFakeStore(settings) initTelemetry(store, scheduleClientStart) }) afterEach(async () => { await shutdownTelemetry() vi.useRealTimers() + vi.unstubAllGlobals() vi.restoreAllMocks() createPostHogClient.mockReset() scheduleClientStart.mockReset() @@ -76,6 +86,89 @@ describe('deferred PostHog client start', () => { ]) }) + it('flushes held events 10s after the first one, as an eager client would', () => { + track('app_opened', {}) + vi.advanceTimersByTime(2_000) + scheduleClientStart.mock.calls[0][0]() + vi.advanceTimersByTime(7_999) + expect(sdk.flush).not.toHaveBeenCalled() + + vi.advanceTimersByTime(1) + + expect(sdk.flush).toHaveBeenCalledTimes(1) + }) + + it('starts and flushes on that deadline when no window ever shows', () => { + track('app_opened', {}) + + vi.advanceTimersByTime(10_000) + + expect(sdk.capture).toHaveBeenCalledWith(expect.objectContaining({ event: 'app_opened' })) + expect(sdk.flush).toHaveBeenCalledTimes(1) + }) + + it('sends a full batch of held events immediately, as the SDK flushAt threshold would', async () => { + const fetch = vi.fn(async () => new Response('{}', { status: 200 })) + vi.stubGlobal('fetch', fetch) + createPostHogClient.mockImplementation(realTransport.createPostHogClient) + for (let i = 0; i < realTransport.POSTHOG_FLUSH_AT; i++) { + vi.setSystemTime(new Date(Date.UTC(2026, 9, 29, 0, 0, 0, i))) + expect(track('telemetry_opted_in', { via: 'settings' })).toBe(true) + } + + // Gzip is really async; waitFor's fake-clock advance stays under the 10s flush deadline. + await vi.waitFor( + () => + expect(fetch).toHaveBeenCalledWith(expect.stringContaining('/batch'), expect.anything()), + { timeout: 5_000, interval: 50 } + ) + }) + + it.each([200, 400])( + 'leaves batching to the SDK after a flushAt send answered %i, matching an eager client', + async (firstStatus) => { + vi.spyOn(console, 'error').mockImplementation(() => {}) + const fetch = vi.fn(async () => new Response('{}', { status: 200 })) + fetch.mockImplementationOnce(async () => new Response('{}', { status: firstStatus })) + vi.stubGlobal('fetch', fetch) + createPostHogClient.mockImplementation(realTransport.createPostHogClient) + for (let i = 0; i < realTransport.POSTHOG_FLUSH_AT; i++) { + track('telemetry_opted_in', { via: 'settings' }) + vi.advanceTimersByTime(50) + } + await settle(() => fetch.mock.calls.length === 1) + await vi.advanceTimersByTimeAsync(1_000) + track('telemetry_opted_in', { via: 'settings' }) + await settle(() => false) + + // An eager client's interval restarted at the 2s capture; the startup deadline must not flush at 10s. + await vi.advanceTimersByTimeAsync(8_500) + await settle(() => fetch.mock.calls.length > 1) + expect(fetch).toHaveBeenCalledTimes(1) + await vi.advanceTimersByTimeAsync(1_600) + await settle(() => fetch.mock.calls.length > 1) + expect(fetch).toHaveBeenCalledTimes(2) + } + ) + + it('drops held events when consent is withdrawn before the client starts', () => { + track('app_opened', {}) + settings.telemetry!.optedIn = false + + scheduleClientStart.mock.calls[0][0]() + + expect(sdk.capture).not.toHaveBeenCalled() + }) + + it('drops held events at quit without loading the SDK when consent was withdrawn', async () => { + track('app_opened', {}) + settings.telemetry!.optedIn = false + + await shutdownTelemetry() + + expect(createPostHogClient).not.toHaveBeenCalled() + }) + it('starts the client early to flush held events and enqueue the opt-out before opting out', async () => { track('app_opened', {}) const order: string[] = [] diff --git a/src/main/telemetry/client.ts b/src/main/telemetry/client.ts index 5af7a21ee77..8e1fbadb1e2 100644 --- a/src/main/telemetry/client.ts +++ b/src/main/telemetry/client.ts @@ -83,7 +83,7 @@ export function initTelemetry(store: Store, scheduleStart: postHogStart.StartSch } posthog = null - postHogStart.deferStart(WRITE_KEY, scheduleStart, ensurePostHogClient) + postHogStart.deferStart(WRITE_KEY, store, scheduleStart, ensurePostHogClient) } function ensurePostHogClient(): PostHog | null { @@ -94,9 +94,7 @@ function ensurePostHogClient(): PostHog | null { try { // Apply consent as it stands now; the live per-event check already gated each held capture. posthog = createPostHogClient(start.writeKey, resolveConsent(storeRef.getSettings())) - for (const message of start.held) { - posthog.capture(message) - } + postHogStart.replayHeld(posthog, start.held) } catch (err) { // Callers include opt-out and quit, which must still complete without a client. console.warn('[telemetry] PostHog client failed to start or replay held events:', err) @@ -210,7 +208,7 @@ export function track(name: N, props: EventProps): boole if (posthog) { posthog.capture(message) } else { - postHogStart.holdCapture(message) + postHogStart.holdCapture(message, ensurePostHogClient) } if (dashboardActiveSurface && settings.telemetry) { trackedDashboardActiveDays.set(dashboardActiveSurface, dashboardActiveDay) @@ -325,7 +323,7 @@ export function trackAppOpenedOnce(): void { export async function shutdownTelemetry(): Promise { // Fence before flushing so late IPC cannot enqueue. shuttingDown = true - const instance = postHogStart.hasHeldCaptures() ? ensurePostHogClient() : posthog + const instance = postHogStart.hasSendableHeldCaptures() ? ensurePostHogClient() : posthog postHogStart.resetStart() if (!instance) { return diff --git a/src/main/telemetry/posthog-client-start.ts b/src/main/telemetry/posthog-client-start.ts index 5f966d23faa..1b42f8baea6 100644 --- a/src/main/telemetry/posthog-client-start.ts +++ b/src/main/telemetry/posthog-client-start.ts @@ -1,15 +1,26 @@ import type { PostHog } from 'posthog-node' +import type { Store } from '../persistence' +import { resolveConsent } from './consent' +import { POSTHOG_FLUSH_AT, POSTHOG_FLUSH_INTERVAL_MS } from './posthog-transport' type CaptureMessage = Parameters[0] /** Desktop passes a first-window scheduler; Electron stays out of this plain-Node module. */ export type StartScheduler = (start: () => void) => void let writeKey: string | null = null +let storeRef: Store | null = null +let firstFlushTimer: ReturnType | null = null const heldCaptures: CaptureMessage[] = [] /** Hold captures until the scheduled start so the SDK stays off the startup path (#35752). */ -export function deferStart(key: string, schedule: StartScheduler, start: () => void): void { +export function deferStart( + key: string, + store: Store, + schedule: StartScheduler, + start: () => void +): void { writeKey = key + storeRef = store schedule(start) } @@ -17,26 +28,74 @@ export function isStartDeferred(): boolean { return writeKey !== null } -/** Keep the capture time so replayed events land when they happened. */ -export function holdCapture(message: CaptureMessage): void { +/** Keep capture time for replay; send no later than an eager client would (flushAt or flushInterval). */ +export function holdCapture(message: CaptureMessage, start: () => PostHog | null): void { heldCaptures.push({ ...message, timestamp: new Date() }) + if (heldCaptures.length >= POSTHOG_FLUSH_AT) { + // Replaying a full batch trips the SDK's own flushAt send. + start() + return + } + if (firstFlushTimer) { + return + } + firstFlushTimer = setTimeout(() => { + firstFlushTimer = null + start() + ?.flush() + .catch((err: unknown) => console.warn('[telemetry] first flush failed:', err)) + }, POSTHOG_FLUSH_INTERVAL_MS) + firstFlushTimer.unref?.() } -export function hasHeldCaptures(): boolean { - return heldCaptures.length > 0 +function consentAllows(): boolean { + return storeRef !== null && resolveConsent(storeRef.getSettings()).effective === 'enabled' } -/** Claim the deferred start once; returns the held captures to replay in order. */ +/** Quit loads the SDK only for held events that consent still allows. */ +export function hasSendableHeldCaptures(): boolean { + return heldCaptures.length > 0 && consentAllows() +} + +function retireFirstFlushDeadline(): void { + if (firstFlushTimer) { + clearTimeout(firstFlushTimer) + firstFlushTimer = null + } +} + +/** Replay in order; the deadline stands in for the timer an eager client armed at the first held event. */ +export function replayHeld(client: PostHog, held: CaptureMessage[]): void { + // Before its first flush the SDK queue holds every enqueue, so the flushAt-th enqueue is the only SDK flush + // attempt that can precede the deadline; retire it then, whether that send succeeds or fails. + let enqueued = 0 + const stopListening = client.on('capture', (payload: unknown) => { + // Opted-out captures report a string instead of enqueuing. + if (payload !== null && typeof payload === 'object' && ++enqueued >= POSTHOG_FLUSH_AT) { + stopListening() + retireFirstFlushDeadline() + } + }) + for (const message of held) { + client.capture(message) + } +} + +/** Claim the deferred start once; held events are dropped if consent was withdrawn since capture. */ export function takeStart(): { writeKey: string; held: CaptureMessage[] } | null { if (writeKey === null) { return null } - const start = { writeKey, held: heldCaptures.splice(0) } - resetStart() + const held = heldCaptures.splice(0) + // The first-flush deadline survives so replayed events keep it. + const start = { writeKey, held: consentAllows() ? held : [] } + writeKey = null return start } export function resetStart(): void { writeKey = null + storeRef = null heldCaptures.length = 0 + retireFirstFlushDeadline() } diff --git a/src/main/telemetry/posthog-transport.ts b/src/main/telemetry/posthog-transport.ts index e28e597aa81..8367fd8e88d 100644 --- a/src/main/telemetry/posthog-transport.ts +++ b/src/main/telemetry/posthog-transport.ts @@ -5,6 +5,8 @@ import type { CommonProps, EventName } from '../../shared/telemetry-events' import type { ConsentState } from './consent' const OPT_OUT_CAPTURE_ENQUEUE_TIMEOUT_MS = 1_000 +export const POSTHOG_FLUSH_AT = 20 +export const POSTHOG_FLUSH_INTERVAL_MS = 10_000 export function buildCommonProps( installId: string, @@ -77,8 +79,8 @@ function loadPostHogSdk(): typeof PostHogSdk { export function createPostHogClient(writeKey: string, consent: ConsentState): PostHogSdk.PostHog { const client = new (loadPostHogSdk().PostHog)(writeKey, { host: 'https://us.i.posthog.com', - flushAt: 20, - flushInterval: 10_000, + flushAt: POSTHOG_FLUSH_AT, + flushInterval: POSTHOG_FLUSH_INTERVAL_MS, // Disable SDK GeoIP/IP enrichment to keep the wire inside the declared allow-list. disableGeoip: true, // Increase offline buffer from 1000 to 5000; overflow drops oldest events.