mirror of
https://github.com/stablyai/orca.git
synced 2026-10-30 16:47:34 +00:00
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 <chad@sodadigital.com.au>
This commit is contained in:
@@ -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<typeof PostHogTransport>('./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<void> {
|
||||
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<string, string | undefined>
|
||||
let settings: GlobalSettings
|
||||
let store: Store
|
||||
let sdk: MockPostHog
|
||||
let sdk: MockPostHog & { flush: ReturnType<typeof vi.fn> }
|
||||
|
||||
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[] = []
|
||||
|
||||
@@ -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<N extends EventName>(name: N, props: EventProps<N>): 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<void> {
|
||||
// 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
|
||||
|
||||
@@ -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<PostHog['capture']>[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<typeof setTimeout> | 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()
|
||||
}
|
||||
|
||||
@@ -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.
|
||||
|
||||
Reference in New Issue
Block a user