diff --git a/.changeset/evaluation-metrics.md b/.changeset/evaluation-metrics.md new file mode 100644 index 00000000..7a79f8cb --- /dev/null +++ b/.changeset/evaluation-metrics.md @@ -0,0 +1,5 @@ +--- +'@vercel/flags-core': minor +--- + +Add aggregated flag evaluation telemetry and a `clientName` option for the Vercel Flags client. diff --git a/packages/vercel-flags-core/CLAUDE.md b/packages/vercel-flags-core/CLAUDE.md index 0c3fc0f4..bd70d2dc 100644 --- a/packages/vercel-flags-core/CLAUDE.md +++ b/packages/vercel-flags-core/CLAUDE.md @@ -257,7 +257,8 @@ The Controller tags all data with its origin using `tagData(data, origin)` from ### Usage Tracking -- Batches flag read events (max 50 events, max 5s wait) +- Batches flag read/evaluation events; flushes on any of: 50 distinct events, a 5s idle window (reset on every event), or a 60s max window (starts with the batch, never reset) +- The scheduled flush awaits the full ingest send (incl. retries) before its `waitUntil` promise resolves; `shutdown()` drains any in-flight batch instead of orphaning it - Sends to `flags.vercel.com/v1/ingest` - At runtime: deduplicates by request context (per-instance WeakSet in UsageTracker) - During builds: deduplicates all reads to a single event (buildReadTracked flag in Controller), since there is no request context available diff --git a/packages/vercel-flags-core/src/black-box.test.ts b/packages/vercel-flags-core/src/black-box.test.ts index 2c2bc18a..6414c9ef 100644 --- a/packages/vercel-flags-core/src/black-box.test.ts +++ b/packages/vercel-flags-core/src/black-box.test.ts @@ -104,6 +104,54 @@ const originalEnv = { ...process.env }; describe('Controller (black-box)', () => { const date = new Date(); + function minuteBucketTs(ts: number): number { + return Math.floor(ts / 60_000) * 60_000; + } + + function expectEvaluationOnlyIngest( + evaluationCount = 1, + extraEvents: Array<{ + flagKey: string; + variant: string | undefined; + reason: string; + evaluationCount: number; + periodStartedAt?: number; + }> = [], + ) { + const periodStartedAt = minuteBucketTs(date.getTime()); + + expect(fetchMock).toHaveBeenLastCalledWith( + 'https://flags.vercel.com/v1/ingest', + { + body: JSON.stringify([ + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount, + periodStartedAt, + }, + }, + ...extraEvents.map( + ({ periodStartedAt: eventPeriod, ...payload }) => ({ + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + ...payload, + periodStartedAt: eventPeriod ?? periodStartedAt, + }, + }), + ), + ]), + headers: ingestRequestHeaders, + method: 'POST', + }, + ); + } + beforeEach(() => { vi.useFakeTimers(); vi.setSystemTime(date); @@ -207,8 +255,9 @@ describe('Controller (black-box)', () => { expect(fetchMock).not.toHaveBeenCalled(); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable (build step has no request context) - expect(fetchMock).not.toHaveBeenCalled(); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(1); + expectEvaluationOnlyIngest(); }); it('should detect build step when NEXT_PHASE=phase-production-build', async () => { @@ -227,8 +276,9 @@ describe('Controller (black-box)', () => { expect(fetchMock).not.toHaveBeenCalled(); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable - expect(fetchMock).not.toHaveBeenCalled(); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(1); + expectEvaluationOnlyIngest(); }); it('should NOT detect build step when neither CI nor NEXT_PHASE is set', async () => { @@ -332,6 +382,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + }, + }, ]), headers: ingestRequestHeaders, method: 'POST', @@ -388,8 +449,16 @@ describe('Controller (black-box)', () => { await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable (build step has no request context) - expect(fetchMock).toHaveBeenCalledTimes(1); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(2); + expectEvaluationOnlyIngest(1, [ + { + flagKey: 'flagB', + variant: undefined, + reason: 'error', + evaluationCount: 1, + }, + ]); }); it('should throw when bundled definitions missing and fetch fails during build (no defaultValue)', async () => { @@ -1171,6 +1240,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: after.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(after.getTime()), + }, + }, ]), headers: ingestRequestHeaders, method: 'POST', @@ -1249,6 +1329,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: after.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(after.getTime()), + }, + }, ]), headers: ingestRequestHeaders, method: 'POST', @@ -2116,6 +2207,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + }, + }, ]), }, ], @@ -2494,6 +2596,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime() + 60, + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime() + 60), + }, + }, ]), }, ); @@ -3201,6 +3314,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 3, + periodStartedAt: minuteBucketTs(date.getTime()), + }, + }, ]), headers: ingestRequestHeaders, method: 'POST', @@ -3247,8 +3371,9 @@ describe('Controller (black-box)', () => { stream.close(); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable - expect(fetchMock).toHaveBeenCalledTimes(1); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(2); + expectEvaluationOnlyIngest(3); }); it('should start only one retry loop when concurrent evaluate() calls hit a failing stream', async () => { @@ -3403,6 +3528,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + }, + }, ]), }, ); @@ -3503,6 +3639,7 @@ describe('Controller (black-box)', () => { expect(result).toEqual({ value: false, + variantId: null, reason: 'error', errorMessage: expect.stringContaining( '@vercel/flags-core: No flag definitions available', @@ -3553,6 +3690,109 @@ describe('Controller (black-box)', () => { // Usage tracking // --------------------------------------------------------------------------- describe('usage tracking', () => { + it('should report counted FLAG_EVALUATION events', async () => { + const cleanupCtx = setRequestContext({ host: 'example.com' }); + fetchMock.mockImplementation((input) => { + const url = typeof input === 'string' ? input : input.toString(); + if (url.includes('/v1/ingest')) { + return Promise.resolve(new Response(null, { status: 200 })); + } + return Promise.reject(new Error(`Unexpected fetch: ${url}`)); + }); + + const client = createClient(sdkKey, { + fetch: fetchMock, + stream: false, + polling: false, + clientName: 'checkout', + datafile: makeBundled({ + definitions: { + flagA: { + variantIds: ['var_off', 'var_on'], + environments: { production: 1 }, + variants: [false, true], + }, + flagB: { + environments: { production: { fallthrough: 0 } }, + variants: ['control', 'variant'], + }, + }, + }), + }); + + await client.evaluate('flagA'); + await client.evaluate('missing-flag', false); + await client.bulkEvaluate([{ key: 'flagA' }, { key: 'flagB' }]); + + await client.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(fetchMock).toHaveBeenLastCalledWith( + 'https://flags.vercel.com/v1/ingest', + { + body: JSON.stringify([ + { + type: 'FLAGS_CONFIG_READ', + ts: date.getTime(), + payload: { + invocationHost: 'example.com', + configOrigin: 'in-memory', + cacheStatus: 'HIT', + cacheAction: 'NONE', + cacheIsFirstRead: true, + cacheIsBlocking: false, + duration: 0, + configUpdatedAt: 1, + mode: 'offline', + revision: '1', + environment: 'production', + }, + }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: 'var_on', + reason: 'paused', + evaluationCount: 2, + periodStartedAt: minuteBucketTs(date.getTime()), + clientName: 'checkout', + }, + }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'missing-flag', + variant: undefined, + reason: 'error', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + clientName: 'checkout', + }, + }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagB', + variant: undefined, + reason: 'fallthrough', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + clientName: 'checkout', + }, + }, + ]), + headers: ingestRequestHeaders, + method: 'POST', + }, + ); + + cleanupCtx(); + }); + it('should report FLAGS_CONFIG_READ when using provided datafile in build step', async () => { const passedDatafile = makeBundled({ configUpdatedAt: 2, @@ -3599,14 +3839,16 @@ describe('Controller (black-box)', () => { outcomeType: 'value', reason: 'paused', value: true, + variantId: null, }); expect(fetchMock).not.toHaveBeenCalled(); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable (build step has no request context) - expect(fetchMock).not.toHaveBeenCalled(); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(1); + expectEvaluationOnlyIngest(); }); it('should not track FLAGS_CONFIG_READ during build step (no request context)', async () => { @@ -3625,8 +3867,9 @@ describe('Controller (black-box)', () => { await client.evaluate('flagA'); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable - expect(fetchMock).not.toHaveBeenCalled(); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(1); + expectEvaluationOnlyIngest(3); }); it('should report FLAGS_CONFIG_READ with FOLLOWING cacheAction when streaming', async () => { @@ -3690,6 +3933,17 @@ describe('Controller (black-box)', () => { environment: 'production', }, }, + { + type: 'FLAG_EVALUATION', + ts: date.getTime(), + payload: { + flagKey: 'flagA', + variant: undefined, + reason: 'paused', + evaluationCount: 1, + periodStartedAt: minuteBucketTs(date.getTime()), + }, + }, ]), headers: ingestRequestHeaders, method: 'POST', @@ -3723,14 +3977,16 @@ describe('Controller (black-box)', () => { outcomeType: 'value', reason: 'paused', value: true, + variantId: null, }); expect(fetchMock).not.toHaveBeenCalled(); await client.shutdown(); - // No ingest call: trackRead skips when request context is unavailable - expect(fetchMock).not.toHaveBeenCalled(); + // Config reads skip without request context, but evaluations are still reported. + expect(fetchMock).toHaveBeenCalledTimes(1); + expectEvaluationOnlyIngest(); }); }); }); diff --git a/packages/vercel-flags-core/src/controller-fns.ts b/packages/vercel-flags-core/src/controller-fns.ts index f6b779b9..26b2e29a 100644 --- a/packages/vercel-flags-core/src/controller-fns.ts +++ b/packages/vercel-flags-core/src/controller-fns.ts @@ -14,6 +14,7 @@ import type { Packed, } from './types'; import { ErrorCode, ResolutionReason } from './types'; +import type { TrackEvaluationOptions } from './utils/usage/flags-evaluation'; export type ControllerInstance = { controller: ControllerInterface; @@ -23,6 +24,10 @@ export type ControllerInstance = { export const controllerInstanceMap = new Map(); +type EvaluationTrackingController = ControllerInterface & { + trackEvaluation?: (options: TrackEvaluationOptions) => void; +}; + function getInstance(id: number): ControllerInstance { const instance = controllerInstanceMap.get(id); if (!instance) { @@ -51,13 +56,20 @@ export function getFallbackDatafile(id: number): Promise { throw new Error('flags: This data source does not support fallbacks'); } +function trackEvaluation( + controller: EvaluationTrackingController, + options: TrackEvaluationOptions, +): void { + controller.trackEvaluation?.(options); +} + export async function evaluate>( id: number, flagKey: string, defaultValue?: T, entities?: E, ): Promise> { - const controller = getInstance(id).controller; + const controller = getInstance(id).controller as EvaluationTrackingController; let datafile: Datafile; try { @@ -65,12 +77,19 @@ export async function evaluate>( } catch (error) { // All data sources failed. Fall back to defaultValue if provided. if (defaultValue !== undefined) { - return { + const result: EvaluationResult = { value: defaultValue, + variantId: null, reason: ResolutionReason.ERROR, errorMessage: error instanceof Error ? error.message : 'Failed to read datafile', }; + trackEvaluation(controller, { + flagKey, + variant: null, + reason: result.reason, + }); + return result; } throw error; } @@ -86,8 +105,9 @@ export async function evaluate>( }); } - return { + const result: EvaluationResult = { value: defaultValue, + variantId: null, reason: ResolutionReason.ERROR, errorCode: ErrorCode.FLAG_NOT_FOUND, errorMessage: `@vercel/flags-core: Definition not found for flag "${flagKey}"`, @@ -100,6 +120,12 @@ export async function evaluate>( mode: datafile.metrics.mode, }, }; + trackEvaluation(controller, { + flagKey, + variant: null, + reason: result.reason, + }); + return result; } const evalStartTime = Date.now(); @@ -124,6 +150,12 @@ export async function evaluate>( }); } + trackEvaluation(controller, { + flagKey, + variant: result.variantId, + reason: result.reason, + }); + return Object.assign(result, { metrics: { evaluationMs: evaluationDurationMs, @@ -141,7 +173,7 @@ export async function bulkEvaluate>( flags: BulkEvaluateInput[], entities?: E, ): Promise>> { - const controller = getInstance(id).controller; + const controller = getInstance(id).controller as EvaluationTrackingController; let datafile: Datafile; try { @@ -156,7 +188,13 @@ export async function bulkEvaluate>( value: flag.defaultValue, reason: ResolutionReason.ERROR, errorMessage, + variantId: null, }; + trackEvaluation(controller, { + flagKey: flag.key, + variant: null, + reason: ResolutionReason.ERROR, + }); } return results; } @@ -191,7 +229,13 @@ export async function bulkEvaluate>( errorCode: ErrorCode.FLAG_NOT_FOUND, errorMessage: `@vercel/flags-core: Definition not found for flag "${key}"`, metrics: { evaluationMs: 0, ...baseMetrics }, + variantId: null, }; + trackEvaluation(controller, { + flagKey: key, + variant: null, + reason: ResolutionReason.ERROR, + }); continue; } @@ -219,6 +263,11 @@ export async function bulkEvaluate>( : undefined, }); } + trackEvaluation(controller, { + flagKey: key, + variant: result.variantId, + reason: result.reason, + }); results[key] = Object.assign(result, { metrics: { evaluationMs: evaluationDurationMs, ...baseMetrics }, }); diff --git a/packages/vercel-flags-core/src/controller/index.ts b/packages/vercel-flags-core/src/controller/index.ts index e841bfd9..fa4b0a00 100644 --- a/packages/vercel-flags-core/src/controller/index.ts +++ b/packages/vercel-flags-core/src/controller/index.ts @@ -6,7 +6,9 @@ import type { Metrics, } from '../types'; import { readBundledDefinitions } from '../utils/read-bundled-definitions'; -import { type TrackReadOptions, UsageTracker } from '../utils/usage-tracker'; +import type { TrackReadOptions } from '../utils/usage/flags-config-read'; +import type { TrackEvaluationOptions } from '../utils/usage/flags-evaluation'; +import { UsageTracker } from '../utils/usage-tracker'; import { BundledSource } from './bundled-source'; import { fetchDatafile } from './fetch-datafile'; import { @@ -346,7 +348,7 @@ export class Controller implements ControllerInterface { ? tagData(this.options.datafile, 'provided') : undefined; this.transition('shutdown'); - await this.usageTracker.flush(); + await this.usageTracker.shutdown(); } /** @@ -814,4 +816,16 @@ export class Controller implements ControllerInterface { } this.usageTracker.trackRead(trackOptions); } + + /** + * Tracks a flag evaluation for usage analytics. + */ + trackEvaluation(options: TrackEvaluationOptions): void { + if (this.unauthorized) return; + + this.usageTracker.trackEvaluation({ + ...options, + clientName: options.clientName ?? this.options.clientName, + }); + } } diff --git a/packages/vercel-flags-core/src/controller/normalized-options.ts b/packages/vercel-flags-core/src/controller/normalized-options.ts index f17b15a4..9eda555c 100644 --- a/packages/vercel-flags-core/src/controller/normalized-options.ts +++ b/packages/vercel-flags-core/src/controller/normalized-options.ts @@ -52,6 +52,11 @@ export type ControllerOptions = { * @default globalThis.fetch */ fetch?: typeof globalThis.fetch; + + /** + * Custom client name included in evaluation telemetry. + */ + clientName?: string; }; export type NormalizedOptions = { @@ -62,6 +67,7 @@ export type NormalizedOptions = { buildStep: boolean; fetch: typeof globalThis.fetch; host: string; + clientName: string | undefined; }; export function normalizeOptions( @@ -111,5 +117,6 @@ export function normalizeOptions( buildStep, fetch: options.fetch ?? globalThis.fetch, host: 'https://flags.vercel.com', + clientName: options.clientName, }; } diff --git a/packages/vercel-flags-core/src/evaluate.test.ts b/packages/vercel-flags-core/src/evaluate.test.ts index 4fdcafee..07fc77d0 100644 --- a/packages/vercel-flags-core/src/evaluate.test.ts +++ b/packages/vercel-flags-core/src/evaluate.test.ts @@ -23,6 +23,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -40,6 +41,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.PAUSED, outcomeType: OutcomeType.VALUE, }); @@ -59,6 +61,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.ERROR, errorMessage: 'Could not find envConfig for "this-env-does-not-exist-and-will-cause-an-error"', @@ -88,6 +91,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -115,6 +119,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -140,6 +145,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -167,6 +173,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -183,6 +190,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.PAUSED, outcomeType: OutcomeType.VALUE, }); @@ -199,6 +207,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.PAUSED, outcomeType: OutcomeType.VALUE, }); @@ -237,6 +246,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -258,6 +268,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.PAUSED, outcomeType: OutcomeType.VALUE, }); @@ -281,6 +292,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.TARGET_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -335,6 +347,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -352,6 +365,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -376,6 +390,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -398,6 +413,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -417,6 +433,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -442,6 +459,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -464,6 +482,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -484,6 +503,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -512,6 +532,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -538,6 +559,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -1954,6 +1976,7 @@ describe('evaluate', () => { }), ).toEqual({ value: result, + variantId: null, reason: result ? ResolutionReason.RULE_MATCH : ResolutionReason.FALLTHROUGH, @@ -1992,6 +2015,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -2027,6 +2051,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -2062,6 +2087,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -2168,6 +2194,7 @@ describe('evaluate', () => { }), ).toEqual({ value: result, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.SPLIT, }); @@ -2255,6 +2282,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.ROLLOUT, }); @@ -2274,6 +2302,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.ROLLOUT, }); @@ -2293,6 +2322,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.ROLLOUT, }); @@ -2312,6 +2342,7 @@ describe('evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.ROLLOUT, }); @@ -2437,6 +2468,7 @@ describe('evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.ROLLOUT, }); @@ -2484,16 +2516,19 @@ describe('bulkEvaluate', () => { ).toEqual({ active: { value: true, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }, paused: { value: false, + variantId: null, reason: ResolutionReason.PAUSED, outcomeType: OutcomeType.VALUE, }, ruled: { value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }, @@ -2516,11 +2551,13 @@ describe('bulkEvaluate', () => { expect(results.a).toEqual({ value: true, + variantId: null, reason: ResolutionReason.ERROR, errorMessage: 'Could not find envConfig for "this-env-does-not-exist"', }); expect(results.b).toEqual({ value: false, + variantId: null, reason: ResolutionReason.ERROR, errorMessage: 'Could not find envConfig for "this-env-does-not-exist"', }); @@ -2565,6 +2602,7 @@ describe('bulkEvaluate', () => { const expected: EvaluationResult = { value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }; diff --git a/packages/vercel-flags-core/src/evaluate.ts b/packages/vercel-flags-core/src/evaluate.ts index 3ce46f6f..48b43a7f 100644 --- a/packages/vercel-flags-core/src/evaluate.ts +++ b/packages/vercel-flags-core/src/evaluate.ts @@ -6,6 +6,7 @@ import { OutcomeType, Packed, ResolutionReason, + type VariantId, } from './types'; type PathArray = (string | number)[]; @@ -364,13 +365,27 @@ function handleSegmentOutcome( } } -function getVariant(variants: unknown[], index: number): T { +function getVariant( + definition: Packed.FlagDefinition, + index: number, +): { value: T; variantId: VariantId | null } { + const { variants, variantIds } = definition; + if (index < 0 || index >= variants.length) { throw new Error( `@vercel/flags-core: Invalid variant index ${index}, variants length is ${variants.length}`, ); } - return variants[index] as T; + + let variantId: VariantId | null = null; + if (variantIds && index < variantIds.length) { + variantId = variantIds[index] ?? null; + } + + return { + value: variants[index] as T, + variantId, + }; } function handleOutcome( @@ -379,10 +394,12 @@ function handleOutcome( ): { value: T; outcomeType: OutcomeType; + variantId: VariantId | null; } { if (typeof outcome === 'number') { + const variant = getVariant(params.definition, outcome); return { - value: getVariant(params.definition.variants, outcome), + ...variant, outcomeType: OutcomeType.VALUE, }; } @@ -390,13 +407,16 @@ function handleOutcome( case 'split': { const lhs = access(outcome.base, params); const defaultOutcome = getVariant( - params.definition.variants, + params.definition, outcome.defaultVariant, ); // serve the default variant if the lhs is not a string if (typeof lhs !== 'string') { - return { value: defaultOutcome, outcomeType: OutcomeType.SPLIT }; + return { + ...defaultOutcome, + outcomeType: OutcomeType.SPLIT, + }; } /** @@ -407,37 +427,40 @@ function handleOutcome( const value = hashInput(lhs, params.definition.seed); const scaledWeights = getScaledWeights(outcome); const variantIndex = findWeightedIndex(scaledWeights, value, UINT32_MAX); + const variant = + variantIndex === -1 + ? defaultOutcome + : getVariant(params.definition, variantIndex); return { - value: - variantIndex === -1 - ? defaultOutcome - : getVariant(params.definition.variants, variantIndex), + ...variant, outcomeType: OutcomeType.SPLIT, }; } case 'rollout': { const lhs = access(outcome.base, params); const defaultOutcome = getVariant( - params.definition.variants, + params.definition, outcome.defaultVariant, ); // serve the default variant if the lhs is not a string if (typeof lhs !== 'string') { - return { value: defaultOutcome, outcomeType: OutcomeType.ROLLOUT }; + return { ...defaultOutcome, outcomeType: OutcomeType.ROLLOUT }; } // Determine active slot based on elapsed time const now = Date.now(); const elapsed = now - outcome.startTimestamp; + const rollFromVariant = getVariant( + params.definition, + outcome.rollFromVariant, + ); + // Before rollout starts or no slots, serve rollFromVariant if (elapsed < 0 || outcome.slots.length === 0) { return { - value: getVariant( - params.definition.variants, - outcome.rollFromVariant, - ), + ...rollFromVariant, outcomeType: OutcomeType.ROLLOUT, }; } @@ -462,19 +485,17 @@ function handleOutcome( // short-circuit common edges if (currentPromille <= 0) { return { - value: getVariant( - params.definition.variants, - outcome.rollFromVariant, - ), + ...rollFromVariant, outcomeType: OutcomeType.ROLLOUT, }; } + const rollToVariant = getVariant( + params.definition, + outcome.rollToVariant, + ); if (currentPromille >= 100_000) { return { - value: getVariant( - params.definition.variants, - outcome.rollToVariant, - ), + ...rollToVariant, outcomeType: OutcomeType.ROLLOUT, }; } @@ -482,14 +503,10 @@ function handleOutcome( const value = hashInput(lhs, params.definition.seed); const threshold = (currentPromille / 100_000) * UINT32_MAX; + const variant = value < threshold ? rollToVariant : rollFromVariant; + return { - value: - value < threshold - ? getVariant(params.definition.variants, outcome.rollToVariant) - : getVariant( - params.definition.variants, - outcome.rollFromVariant, - ), + ...variant, outcomeType: OutcomeType.ROLLOUT, }; } @@ -531,6 +548,7 @@ export function evaluate( reason: ResolutionReason.ERROR, errorMessage: `Could not find envConfig for "${params.environment}"`, value: params.defaultValue, + variantId: null, }; } @@ -551,6 +569,7 @@ export function evaluate( reason: ResolutionReason.ERROR, errorMessage: `Circular environment reuse detected: "${envConfig.reuse}"`, value: params.defaultValue, + variantId: null, }; } visited.add(params.environment); diff --git a/packages/vercel-flags-core/src/index.make.test.ts b/packages/vercel-flags-core/src/index.make.test.ts index 52e533ac..ba7497d7 100644 --- a/packages/vercel-flags-core/src/index.make.test.ts +++ b/packages/vercel-flags-core/src/index.make.test.ts @@ -101,6 +101,21 @@ describe('make', () => { expect(client).toBeDefined(); }); + it('should pass clientName to the controller', () => { + const createRawClient = createMockCreateRawClient(); + const { createClient } = make(createRawClient); + + const client = createClient('vf_server_test_key', { + clientName: 'checkout', + }); + + expect(Controller).toHaveBeenCalledWith({ + auth: expect.objectContaining({ sdkKey: 'vf_server_test_key' }), + clientName: 'checkout', + }); + expect(client).toBeDefined(); + }); + it('should throw for empty SDK key', () => { const createRawClient = createMockCreateRawClient(); const { createClient } = make(createRawClient); diff --git a/packages/vercel-flags-core/src/integration.test.ts b/packages/vercel-flags-core/src/integration.test.ts index 5ac8e88b..a1d9e968 100644 --- a/packages/vercel-flags-core/src/integration.test.ts +++ b/packages/vercel-flags-core/src/integration.test.ts @@ -151,6 +151,7 @@ describe('integration evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -173,6 +174,7 @@ describe('integration evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); @@ -193,6 +195,7 @@ describe('integration evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -221,6 +224,7 @@ describe('integration evaluate', () => { }), ).toEqual({ value: true, + variantId: null, reason: ResolutionReason.RULE_MATCH, outcomeType: OutcomeType.VALUE, }); @@ -247,6 +251,7 @@ describe('integration evaluate', () => { }), ).toEqual({ value: false, + variantId: null, reason: ResolutionReason.FALLTHROUGH, outcomeType: OutcomeType.VALUE, }); diff --git a/packages/vercel-flags-core/src/types.ts b/packages/vercel-flags-core/src/types.ts index 77f0adf8..6e7fbe4d 100644 --- a/packages/vercel-flags-core/src/types.ts +++ b/packages/vercel-flags-core/src/types.ts @@ -246,6 +246,10 @@ export type EvaluationResult = * Indicates whether the outcome was a single variant or a split */ outcomeType?: OutcomeType; + /** + * The variant we want to report for o11y + */ + variantId: VariantId | null; /** * Indicates why the flag evaluated to a certain value */ @@ -260,6 +264,10 @@ export type EvaluationResult = errorMessage: string; errorCode?: ErrorCode; outcomeType?: never; + /** + * The variant we want to report for o11y + */ + variantId: VariantId | null; /** * In cases of errors this is the defaultValue if one was provided */ diff --git a/packages/vercel-flags-core/src/utils/ingest.ts b/packages/vercel-flags-core/src/utils/ingest.ts new file mode 100644 index 00000000..8248c553 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/ingest.ts @@ -0,0 +1,98 @@ +import { getVercelOidcToken } from '@vercel/oidc'; +import { version } from '../../package.json'; +import type { Auth } from '../controller/auth'; +import { getRetryDelayMs } from './backoff'; +import type { UsageEvent } from './usage/events'; + +const MAX_RETRIES = 3; + +export const EVALUATING_OIDC_TOKEN_HEADER = 'X-Vercel-Flags-OIDC-Token'; + +const isDebugMode = process.env.DEBUG?.includes('@vercel/flags-core'); + +const debugLog = (...args: any[]) => { + if (!isDebugMode) return; + console.log(...args); +}; + +export interface IngestOptions { + auth: Auth; + host: string; + fetch: typeof fetch; +} + +async function getEvaluatingOidcToken(auth: Auth): Promise { + if (!auth.sdkKey) return undefined; + + try { + return await getVercelOidcToken(); + } catch { + return undefined; + } +} + +async function getIngestHeaders( + options: IngestOptions, +): Promise> { + const token = await options.auth.resolveToken(); + const evaluatingOidcToken = await getEvaluatingOidcToken(options.auth); + + return { + 'Content-Type': 'application/json', + Authorization: `Bearer ${token}`, + 'User-Agent': `VercelFlagsCore/${version}`, + ...(process.env.VERCEL_ENV + ? { 'X-Vercel-Env': process.env.VERCEL_ENV } + : null), + ...(evaluatingOidcToken + ? { [EVALUATING_OIDC_TOKEN_HEADER]: evaluatingOidcToken } + : null), + ...(isDebugMode ? { 'x-vercel-debug-ingest': '1' } : null), + }; +} + +export async function sendIngestEvents( + options: IngestOptions, + events: UsageEvent[], + flushId: number, +): Promise { + const eventsToSend = events.map((event) => event.ingestEvent()); + + for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { + try { + const response = await options.fetch(`${options.host}/v1/ingest`, { + method: 'POST', + headers: await getIngestHeaders(options), + body: JSON.stringify(eventsToSend), + }); + + debugLog( + `@vercel/flags-core: Ingest response ${response.status} for ${eventsToSend.length} events on ${response.headers.get('x-vercel-id')}`, + ); + + if (response.ok) { + break; + } + + throw new Error( + `Ingest endpoint responded with status ${response.status} for ${eventsToSend.length} events on request ${response.headers.get('x-vercel-id')}.\n` + + `Response body: ${await response.text().catch(() => null)}`, + ); + } catch (error) { + console.error( + `@vercel/flags-core: Error sending events (attempt=${attempt}/${MAX_RETRIES} flushId=${flushId}):`, + error, + ); + if (attempt < MAX_RETRIES) { + const delayMs = getRetryDelayMs(attempt); + await new Promise((res) => setTimeout(res, delayMs)); + } else { + // All retries exhausted - surface a structured warning so consumers + // can alert on dropped batches. The events are not persisted anywhere. + console.error( + `@vercel/flags-core: Dropped ${eventsToSend.length} events after ${MAX_RETRIES} attempts (flushId=${flushId})`, + ); + } + } + } +} diff --git a/packages/vercel-flags-core/src/utils/request-context.ts b/packages/vercel-flags-core/src/utils/request-context.ts new file mode 100644 index 00000000..a8c748b6 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/request-context.ts @@ -0,0 +1,29 @@ +interface RequestContext { + ctx: object | undefined; + headers: Record | undefined; +} + +const SYMBOL_FOR_REQ_CONTEXT = Symbol.for('@vercel/request-context'); +const fromSymbol = globalThis as typeof globalThis & { + [key: symbol]: + | { get?: () => { headers?: Record } } + | undefined; +}; + +/** + * Gets the Vercel request context and headers from the global symbol. + */ +export function getRequestContext(): RequestContext { + try { + const ctx = fromSymbol[SYMBOL_FOR_REQ_CONTEXT]?.get?.(); + if (ctx && Object.hasOwn(ctx, 'headers')) { + return { + ctx, + headers: ctx.headers as Record, + }; + } + return { ctx, headers: undefined }; + } catch { + return { ctx: undefined, headers: undefined }; + } +} diff --git a/packages/vercel-flags-core/src/utils/scheduler.test.ts b/packages/vercel-flags-core/src/utils/scheduler.test.ts new file mode 100644 index 00000000..02f46c40 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/scheduler.test.ts @@ -0,0 +1,220 @@ +import { waitUntil } from '@vercel/functions'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { Scheduler } from './scheduler'; + +vi.mock('@vercel/functions', () => ({ + waitUntil: vi.fn(), +})); + +const waitUntilMock = vi.mocked(waitUntil); + +function deferred() { + let resolve!: (value: T) => void; + const promise = new Promise((res) => { + resolve = res; + }); + return { promise, resolve }; +} + +describe('Scheduler', () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.spyOn(Math, 'random').mockReturnValue(0.5); + waitUntilMock.mockReset(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it('flushes after the idle window', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + + await vi.advanceTimersByTimeAsync(4999); + expect(onFlush).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + }); + + it('applies jitter to the idle window', async () => { + vi.spyOn(Math, 'random').mockReturnValue(0); + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + + await vi.advanceTimersByTimeAsync(3999); + expect(onFlush).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + }); + + it('resets the idle window when a new flush is scheduled', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + await vi.advanceTimersByTimeAsync(4999); + + scheduler.scheduleFlush(); + await vi.advanceTimersByTimeAsync(4999); + expect(onFlush).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + }); + + it('flushes when the count reaches the max batch size', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + for (let i = 0; i < 49; i++) { + scheduler.increment(); + } + expect(onFlush).not.toHaveBeenCalled(); + + scheduler.increment(); + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + }); + + it('registers the scheduled flush with waitUntil', () => { + const scheduler = new Scheduler(vi.fn()); + + scheduler.scheduleFlush(); + + expect(waitUntilMock).toHaveBeenCalledTimes(1); + expect(waitUntilMock).toHaveBeenCalledWith(expect.any(Promise)); + }); + + it('starts a fresh batch after a flush completes', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + for (let i = 0; i < 50; i++) { + scheduler.increment(); + } + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + + // A new batch should accumulate independently and flush again. + scheduler.scheduleFlush(); + for (let i = 0; i < 50; i++) { + scheduler.increment(); + } + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(2); + }); + }); + + it('does not resolve the waitUntil promise until the async flush completes', async () => { + const flushDeferred = deferred(); + const onFlush = vi.fn(() => flushDeferred.promise); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + + const pending = waitUntilMock.mock.calls[0]![0] as Promise; + let settled = false; + void pending.then(() => { + settled = true; + }); + + // Trigger the flush via the count threshold. + for (let i = 0; i < 50; i++) { + scheduler.increment(); + } + + // onFlush has been invoked, but the pending promise must not resolve yet. + await vi.advanceTimersByTimeAsync(0); + expect(onFlush).toHaveBeenCalledTimes(1); + expect(settled).toBe(false); + + flushDeferred.resolve(); + await vi.advanceTimersByTimeAsync(0); + expect(settled).toBe(true); + }); + + it('flushes at the max window under continuous traffic', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + // Keep scheduling every 4s so the 5s idle timer never fires. + scheduler.scheduleFlush(); + for (let elapsed = 0; elapsed < 56000; elapsed += 4000) { + await vi.advanceTimersByTimeAsync(4000); + expect(onFlush).not.toHaveBeenCalled(); + scheduler.scheduleFlush(); + } + + // At the 60s mark since the first event, the max window fires. + await vi.advanceTimersByTimeAsync(4000); + + await vi.waitFor(() => { + expect(onFlush).toHaveBeenCalledTimes(1); + }); + }); + + it('resolves a pending flush on shutdown', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + + await scheduler.shutdown(); + + expect(onFlush).toHaveBeenCalledTimes(1); + }); + + it('shutdown resolves without hanging when nothing is pending', async () => { + const onFlush = vi.fn(); + const scheduler = new Scheduler(onFlush); + + await scheduler.shutdown(); + + expect(onFlush).not.toHaveBeenCalled(); + }); + + it('shutdown awaits the in-flight ingest', async () => { + const flushDeferred = deferred(); + const onFlush = vi.fn(() => flushDeferred.promise); + const scheduler = new Scheduler(onFlush); + + scheduler.scheduleFlush(); + + let shutdownResolved = false; + const shutdownPromise = scheduler.shutdown().then(() => { + shutdownResolved = true; + }); + + await vi.advanceTimersByTimeAsync(0); + expect(onFlush).toHaveBeenCalledTimes(1); + expect(shutdownResolved).toBe(false); + + flushDeferred.resolve(); + await shutdownPromise; + expect(shutdownResolved).toBe(true); + }); +}); diff --git a/packages/vercel-flags-core/src/utils/scheduler.ts b/packages/vercel-flags-core/src/utils/scheduler.ts new file mode 100644 index 00000000..770e0e8e --- /dev/null +++ b/packages/vercel-flags-core/src/utils/scheduler.ts @@ -0,0 +1,109 @@ +import { waitUntil } from '@vercel/functions'; +import { getJitteredWaitMs } from './backoff'; + +const MAX_COUNT = 50; +const IDLE_FLUSH_WAIT_MS = 5000; +const IDLE_FLUSH_JITTER_RATIO = 0.2; +const MAX_FLUSH_WAIT_MS = 60000; + +/** + * Schedule helper that flushes when any of the following occur: + * - the batch size is reached ({@link MAX_COUNT} distinct events), + * - the idle window elapses ({@link IDLE_FLUSH_WAIT_MS}, reset on every event), or + * - the max window elapses ({@link MAX_FLUSH_WAIT_MS}, starts with the batch and is + * never reset, so a batch always flushes under continuous traffic). + * + * The scheduled flush awaits {@link onFlush} (including its ingest send + retries), + * so the promise handed to `waitUntil` does not resolve until ingest completes. + */ +export class Scheduler { + private count: number = 0; + private resolveWait: (() => void) | null = null; + private pending: null | Promise = null; + private idleTimeout: null | ReturnType = null; + private maxTimeout: null | ReturnType = null; + + constructor(private readonly onFlush: () => void | Promise) {} + + increment(): void { + this.count += 1; + + // immediately flush if we've reached the batch size + if (this.count >= MAX_COUNT) { + this.resolveScheduledFlush(); + } + } + + scheduleFlush(): void { + if (!this.pending) { + this.pending = (async () => { + // wait for a timeout or the event count to reach the batch size + await new Promise((res) => { + this.resolveWait = res; + }); + + // free state so new events start a fresh batch while ingest runs + this.reset(); + + // genuinely await ingest (incl. retries) so waitUntil covers the send + await this.onFlush(); + })(); + + try { + waitUntil(this.pending); + } catch { + // waitUntil is best-effort; falling through leaves a floating promise + } + + // max window: starts with the batch and is never reset + this.maxTimeout = setTimeout( + () => this.resolveScheduledFlush(), + MAX_FLUSH_WAIT_MS, + ); + } + + // idle window: reset on every event + this.resetIdleTimeout(); + } + + /** + * Resolves any in-flight scheduled flush and waits for its ingest to finish. + */ + async shutdown(): Promise { + this.clearTimeouts(); + const pending = this.pending; + this.resolveWait?.(); + if (pending) await pending; + } + + private resetIdleTimeout(): void { + if (this.idleTimeout) clearTimeout(this.idleTimeout); + this.idleTimeout = setTimeout( + () => this.resolveScheduledFlush(), + getJitteredWaitMs(IDLE_FLUSH_WAIT_MS, IDLE_FLUSH_JITTER_RATIO), + ); + } + + private resolveScheduledFlush(): void { + this.clearTimeouts(); + this.resolveWait?.(); + } + + private reset(): void { + this.pending = null; + this.resolveWait = null; + this.count = 0; + this.clearTimeouts(); + } + + private clearTimeouts(): void { + if (this.idleTimeout) { + clearTimeout(this.idleTimeout); + this.idleTimeout = null; + } + if (this.maxTimeout) { + clearTimeout(this.maxTimeout); + this.maxTimeout = null; + } + } +} diff --git a/packages/vercel-flags-core/src/utils/usage-tracker.test.ts b/packages/vercel-flags-core/src/utils/usage-tracker.test.ts index 86895f60..a0418d61 100644 --- a/packages/vercel-flags-core/src/utils/usage-tracker.test.ts +++ b/packages/vercel-flags-core/src/utils/usage-tracker.test.ts @@ -1,15 +1,68 @@ +import { waitUntil } from '@vercel/functions'; import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import type { Auth } from '../controller/auth'; import { setRequestContext } from '../test-utils'; -import { type FlagsConfigReadEvent, UsageTracker } from './usage-tracker'; +import { ResolutionReason } from '../types'; +import { EVALUATING_OIDC_TOKEN_HEADER, type IngestOptions } from './ingest'; +import { UsageTracker } from './usage-tracker'; + +type SerializedConfigReadEvent = { + type: 'FLAGS_CONFIG_READ'; + ts: number; + payload: { + deploymentId?: string; + region?: string; + invocationHost?: string; + vercelRequestId?: string; + cacheStatus?: string; + cacheAction?: string; + cacheIsBlocking?: boolean; + cacheIsFirstRead?: boolean; + duration?: number; + configUpdatedAt?: number; + configOrigin?: string; + mode?: string; + revision?: string; + environment?: string; + }; +}; + +type SerializedEvaluationEvent = { + type: 'FLAG_EVALUATION'; + ts: number; + payload: { + flagKey: string; + variant: string; + reason: ResolutionReason; + clientName?: string; + evaluationCount: number; + periodStartedAt: number; + }; +}; + +const getVercelOidcTokenMock = vi.hoisted(() => vi.fn()); + +vi.mock('@vercel/oidc', () => ({ + getVercelOidcToken: getVercelOidcTokenMock, +})); // Mock @vercel/functions vi.mock('@vercel/functions', () => ({ waitUntil: vi.fn(), })); +const waitUntilMock = vi.mocked(waitUntil); + const fetchMock = vi.fn(); +function deferred() { + let resolve!: (value: T) => void; + const promise = new Promise((res) => { + resolve = res; + }); + return { promise, resolve }; +} + function jsonResponse( body: unknown, init?: { status?: number; headers?: Record }, @@ -30,13 +83,17 @@ let cleanupContext: (() => void) | undefined; beforeEach(() => { // Set up request context so trackRead doesn't skip (it's skipped when ctx is unavailable) cleanupContext = setRequestContext({ host: 'example.com' }); + vi.spyOn(Math, 'random').mockReturnValue(0.5); + waitUntilMock.mockReset(); }); afterEach(() => { cleanupContext?.(); cleanupContext = undefined; fetchMock.mockReset(); + getVercelOidcTokenMock.mockReset(); vi.restoreAllMocks(); + vi.useRealTimers(); vi.unstubAllEnvs(); }); @@ -49,11 +106,12 @@ function createAuth(sdkKey = 'test-key'): Auth { }; } -function createTracker(sdkKey = 'test-key') { +function createTracker(sdkKey = 'test-key', options?: Partial) { return new UsageTracker({ auth: createAuth(sdkKey), host: 'https://example.com', fetch: fetchMock, + ...options, }); } @@ -85,7 +143,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(fetchMock).not.toHaveBeenCalled(); }); @@ -96,16 +154,32 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(fetchMock).toHaveBeenCalledTimes(1); - const events = getBody() as FlagsConfigReadEvent[]; + const events = getBody() as SerializedConfigReadEvent[]; expect(events).toHaveLength(1); - const event = events[0] as FlagsConfigReadEvent; + const event = events[0] as SerializedConfigReadEvent; expect(event.type).toBe('FLAGS_CONFIG_READ'); expect(event.ts).toBeTypeOf('number'); }); + it('should timestamp config read events when they are tracked', async () => { + vi.useFakeTimers(); + const trackedAt = new Date('2026-01-01T00:00:00.000Z'); + vi.setSystemTime(trackedAt); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackRead(); + vi.setSystemTime(new Date(trackedAt.getTime() + 10_000)); + await tracker.shutdown(); + + const events = getBody() as SerializedConfigReadEvent[]; + expect(events[0]?.ts).toBe(trackedAt.getTime()); + }); + it('should include deployment ID and region from environment', async () => { vi.stubEnv('VERCEL_DEPLOYMENT_ID', 'dpl_123'); vi.stubEnv('VERCEL_REGION', 'iad1'); @@ -115,10 +189,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.deploymentId).toBe('dpl_123'); expect(event.payload.region).toBe('iad1'); }); @@ -137,7 +211,7 @@ describe('UsageTracker', () => { }); tracker.trackRead(); } - await tracker.flush(); + await tracker.shutdown(); const events = getBody() as Array<{ type: string }>; expect(events).toHaveLength(3); @@ -153,9 +227,56 @@ describe('UsageTracker', () => { }); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); + + expect(getHeaders().Authorization).toBe('Bearer my-secret-key'); + }); + + it('should send evaluating OIDC header when SDK key auth is used', async () => { + getVercelOidcTokenMock.mockResolvedValue('oidc-token'); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker('my-secret-key'); + + tracker.trackRead(); + await tracker.shutdown(); + + expect(getHeaders().Authorization).toBe('Bearer my-secret-key'); + expect(getHeaders()[EVALUATING_OIDC_TOKEN_HEADER]).toBe('oidc-token'); + }); + + it('should omit evaluating OIDC header when OIDC is unavailable', async () => { + getVercelOidcTokenMock.mockRejectedValue(new Error('No OIDC')); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker('my-secret-key'); + + tracker.trackRead(); + await tracker.shutdown(); expect(getHeaders().Authorization).toBe('Bearer my-secret-key'); + expect(getHeaders()[EVALUATING_OIDC_TOKEN_HEADER]).toBeUndefined(); + }); + + it('should not send evaluating OIDC header when OIDC is primary auth', async () => { + getVercelOidcTokenMock.mockResolvedValue('evaluating-oidc-token'); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = new UsageTracker({ + auth: { + resolveToken: () => Promise.resolve('primary-oidc-token'), + resolveBundledDefinitionsLookup: () => + Promise.resolve({ type: 'project-id', projectId: 'prj_123' }), + }, + host: 'https://example.com', + fetch: fetchMock, + }); + + tracker.trackRead(); + await tracker.shutdown(); + + expect(getHeaders().Authorization).toBe('Bearer primary-oidc-token'); + expect(getHeaders()[EVALUATING_OIDC_TOKEN_HEADER]).toBeUndefined(); }); it('should send correct content-type header', async () => { @@ -164,7 +285,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(getHeaders()['Content-Type']).toBe('application/json'); }); @@ -175,7 +296,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(getHeaders()['User-Agent']).toMatch(/^VercelFlagsCore\//); }); @@ -185,12 +306,32 @@ describe('UsageTracker', () => { const tracker = createTracker(); - // Flush without tracking anything - await tracker.flush(); + // Shut down without tracking anything + await tracker.shutdown(); expect(fetchMock).not.toHaveBeenCalled(); }); + it('should not emit flag evaluation metrics when disabled by env var', async () => { + vi.stubEnv('VERCEL_FLAGS_DISABLE_FLAG_EVALUATIONS', '1'); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackRead({ configOrigin: 'in-memory' }); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(getBody()).toEqual([ + expect.objectContaining({ type: 'FLAGS_CONFIG_READ' }), + ]); + }); + it('should handle fetch errors gracefully', async () => { const consoleSpy = vi .spyOn(console, 'error') @@ -201,7 +342,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // Should not throw, errors are logged via console.error expect(consoleSpy).toHaveBeenCalled(); @@ -217,7 +358,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // Should not throw, errors are logged via console.error expect(consoleSpy).toHaveBeenCalled(); @@ -245,7 +386,7 @@ describe('UsageTracker', () => { }); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(getHeaders()['x-vercel-debug-ingest']).toBe('1'); expect(consoleSpy).toHaveBeenCalledWith( @@ -261,7 +402,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(getHeaders()['x-vercel-debug-ingest']).toBeUndefined(); }); @@ -283,7 +424,7 @@ describe('UsageTracker', () => { }); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); expect(consoleSpy).toHaveBeenCalledWith( expect.stringContaining( @@ -293,7 +434,309 @@ describe('UsageTracker', () => { }); }); - describe('flush', () => { + describe('trackEvaluation', () => { + it('should aggregate matching evaluations into counted buckets', async () => { + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + clientName: 'checkout', + }); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + clientName: 'checkout', + }); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_disabled', + reason: ResolutionReason.FALLTHROUGH, + clientName: 'checkout', + }); + + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + const events = getBody() as SerializedEvaluationEvent[]; + expect(events).toHaveLength(2); + expect(events).toContainEqual( + expect.objectContaining({ + type: 'FLAG_EVALUATION', + payload: expect.objectContaining({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + clientName: 'checkout', + evaluationCount: 2, + periodStartedAt: expect.any(Number), + }), + }), + ); + expect(events).toContainEqual( + expect.objectContaining({ + payload: expect.objectContaining({ + flagKey: 'flag-a', + variant: 'var_disabled', + reason: ResolutionReason.FALLTHROUGH, + clientName: 'checkout', + evaluationCount: 1, + periodStartedAt: expect.any(Number), + }), + }), + ); + }); + + it('should preserve evaluation timestamps and bucket periodStartedAt to the current minute', async () => { + vi.useFakeTimers(); + const trackedAt = new Date('2026-01-01T00:00:15.123Z'); + const bucketTs = new Date('2026-01-01T00:00:00.000Z').getTime(); + vi.setSystemTime(trackedAt); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + vi.setSystemTime(new Date(trackedAt.getTime() + 10_000)); + await tracker.shutdown(); + + const events = getBody() as SerializedEvaluationEvent[]; + expect(events[0]?.ts).toBe(trackedAt.getTime()); + expect(events[0]?.payload.periodStartedAt).toBe(bucketTs); + }); + + it('should keep exact minute boundaries in the same bucket', async () => { + vi.useFakeTimers(); + const trackedAt = new Date('2026-01-01T00:01:00.000Z'); + vi.setSystemTime(trackedAt); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + + await tracker.shutdown(); + + const events = getBody() as SerializedEvaluationEvent[]; + expect(events[0]?.ts).toBe(trackedAt.getTime()); + expect(events[0]?.payload.periodStartedAt).toBe(trackedAt.getTime()); + }); + + it('should aggregate matching evaluations in the same minute bucket', async () => { + vi.useFakeTimers(); + const bucketTs = new Date('2026-01-01T00:00:00.000Z').getTime(); + vi.setSystemTime(new Date('2026-01-01T00:00:15.000Z')); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + vi.setSystemTime(new Date('2026-01-01T00:00:59.999Z')); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + vi.setSystemTime(new Date('2026-01-01T00:01:10.000Z')); + await tracker.shutdown(); + + const events = getBody() as SerializedEvaluationEvent[]; + expect(events).toHaveLength(1); + expect(events[0]?.ts).toBe( + new Date('2026-01-01T00:00:15.000Z').getTime(), + ); + expect(events[0]?.payload.periodStartedAt).toBe(bucketTs); + expect(events[0]?.payload.evaluationCount).toBe(2); + }); + + it('should keep matching evaluations in different minute buckets separate', async () => { + vi.useFakeTimers(); + const firstBucketTs = new Date('2026-01-01T00:00:00.000Z').getTime(); + const secondBucketTs = new Date('2026-01-01T00:01:00.000Z').getTime(); + vi.setSystemTime(new Date('2026-01-01T00:00:59.999Z')); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + vi.setSystemTime(new Date('2026-01-01T00:01:00.001Z')); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + }); + await tracker.shutdown(); + + const events = getBody() as SerializedEvaluationEvent[]; + expect(events).toHaveLength(2); + expect(events).toContainEqual({ + type: 'FLAG_EVALUATION', + ts: new Date('2026-01-01T00:00:59.999Z').getTime(), + payload: { + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + evaluationCount: 1, + periodStartedAt: firstBucketTs, + }, + }); + expect(events).toContainEqual({ + type: 'FLAG_EVALUATION', + ts: new Date('2026-01-01T00:01:00.001Z').getTime(), + payload: { + flagKey: 'flag-a', + variant: 'var_enabled', + reason: ResolutionReason.FALLTHROUGH, + evaluationCount: 1, + periodStartedAt: secondBucketTs, + }, + }); + }); + + it('should send read and evaluation events in the same flush payload', async () => { + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackRead({ configOrigin: 'in-memory' }); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(getBody()).toEqual([ + expect.objectContaining({ type: 'FLAGS_CONFIG_READ' }), + { + type: 'FLAG_EVALUATION', + ts: expect.any(Number), + payload: { + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + evaluationCount: 1, + periodStartedAt: expect.any(Number), + }, + }, + ]); + }); + + it('should reset the idle flush timer when evaluations keep arriving', async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date('2026-01-01T00:00:10.000Z')); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + + await vi.advanceTimersByTimeAsync(4999); + expect(fetchMock).not.toHaveBeenCalled(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + + await vi.advanceTimersByTimeAsync(4999); + expect(fetchMock).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + + await vi.waitFor(() => { + expect(fetchMock).toHaveBeenCalledTimes(1); + }); + const events = getBody() as SerializedEvaluationEvent[]; + expect(events[0]?.payload.evaluationCount).toBe(2); + }); + + it('should not count repeated evaluations of the same bucket toward the batch threshold', async () => { + vi.useFakeTimers(); + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + // Track the same bucket well past the 50-event threshold. + for (let i = 0; i < 60; i++) { + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + } + + // No count-based flush should fire (a single distinct bucket). + await vi.advanceTimersByTimeAsync(4999); + expect(fetchMock).not.toHaveBeenCalled(); + + // The aggregated event still carries the full repeated count. + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + const events = getBody() as SerializedEvaluationEvent[]; + expect(events).toHaveLength(1); + expect(events[0]?.payload.evaluationCount).toBe(60); + }); + + it('should track when request context is unavailable', async () => { + cleanupContext?.(); + cleanupContext = undefined; + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(getBody()).toEqual([ + { + type: 'FLAG_EVALUATION', + ts: expect.any(Number), + payload: { + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + evaluationCount: 1, + periodStartedAt: expect.any(Number), + }, + }, + ]); + }); + }); + + describe('shutdown', () => { it('should trigger immediate flush of pending events', async () => { fetchMock.mockImplementation(() => jsonResponse({ ok: true })); @@ -301,21 +744,75 @@ describe('UsageTracker', () => { tracker.trackRead(); - // Flush immediately instead of waiting for timeout - await tracker.flush(); + // Shut down immediately instead of waiting for timeout + await tracker.shutdown(); + + expect(fetchMock).toHaveBeenCalledTimes(1); + }); + + it('should keep the waitUntil promise pending until the scheduled ingest completes', async () => { + vi.useFakeTimers(); + const fetchDeferred = deferred(); + fetchMock.mockImplementation(() => fetchDeferred.promise); + + const tracker = createTracker(); + tracker.trackRead(); + + // Trigger the scheduled flush via the idle window. + await vi.advanceTimersByTimeAsync(5000); + + expect(waitUntilMock).toHaveBeenCalledTimes(1); + const pending = waitUntilMock.mock.calls[0]![0] as Promise; + let settled = false; + void pending.then(() => { + settled = true; + }); + + // Ingest has started but not resolved; the waitUntil promise must wait. + await vi.advanceTimersByTimeAsync(0); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(settled).toBe(false); + + fetchDeferred.resolve( + new Response(JSON.stringify({ ok: true }), { + status: 200, + headers: { 'Content-Type': 'application/json' }, + }), + ); + await pending; + expect(settled).toBe(true); + }); + + it('should drain a pending scheduled batch without double-sending', async () => { + fetchMock.mockImplementation(() => jsonResponse({ ok: true })); + + const tracker = createTracker(); + + // Both events sit in a pending scheduled batch (idle timer running). + tracker.trackRead(); + tracker.trackEvaluation({ + flagKey: 'flag-a', + variant: 'var_0', + reason: ResolutionReason.FALLTHROUGH, + }); + + await tracker.shutdown(); + // Exactly one ingest batch carrying both events; the trailing + // safety-net flush is a no-op (maps already cleared). expect(fetchMock).toHaveBeenCalledTimes(1); + expect(getBody()).toHaveLength(2); }); - it('should be safe to call flush multiple times', async () => { + it('should be safe to call shutdown multiple times', async () => { fetchMock.mockImplementation(() => jsonResponse({ ok: true })); const tracker = createTracker(); tracker.trackRead(); - tracker.flush(); - tracker.flush(); - await tracker.flush(); + await tracker.shutdown(); + await tracker.shutdown(); + await tracker.shutdown(); expect(fetchMock).toHaveBeenCalledTimes(1); }); @@ -336,7 +833,7 @@ describe('UsageTracker', () => { tracker.trackRead(); tracker.trackRead(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // Only one event should be recorded due to deduplication const events = getBody() as Array<{ type: string }>; @@ -356,10 +853,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.vercelRequestId).toBe('req_123'); expect(event.payload.invocationHost).toBe('myapp.vercel.app'); @@ -391,8 +888,8 @@ describe('UsageTracker', () => { // Both trackers track with the same request context tracker1.trackRead(); tracker2.trackRead(); - await tracker1.flush(); - await tracker2.flush(); + await tracker1.shutdown(); + await tracker2.shutdown(); // Each tracker should have sent its own event expect(fetchMock).toHaveBeenCalledTimes(2); @@ -420,7 +917,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // 2 failed + 1 success = 3 total expect(requestCount).toBe(3); @@ -442,7 +939,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // 2 failed + 1 success = 3 total expect(requestCount).toBe(3); @@ -458,7 +955,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); // All 3 attempts fail; SDK logs an extra "Dropped" line expect(fetchMock).toHaveBeenCalledTimes(3); @@ -488,7 +985,7 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead(); - await tracker.flush(); + await tracker.shutdown(); const droppedLogs = consoleSpy.mock.calls.filter( ([msg]) => typeof msg === 'string' && msg.includes('Dropped'), @@ -552,10 +1049,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead({ configOrigin: 'in-memory' }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.configOrigin).toBe('in-memory'); }); @@ -565,10 +1062,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead({ configOrigin: 'in-memory', cacheStatus: 'HIT' }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.cacheStatus).toBe('HIT'); }); @@ -578,10 +1075,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead({ configOrigin: 'in-memory', cacheIsFirstRead: true }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.cacheIsFirstRead).toBe(true); }); @@ -591,10 +1088,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead({ configOrigin: 'in-memory', cacheIsBlocking: true }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.cacheIsBlocking).toBe(true); }); @@ -604,10 +1101,10 @@ describe('UsageTracker', () => { const tracker = createTracker(); tracker.trackRead({ configOrigin: 'in-memory', duration: 150 }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.duration).toBe(150); }); @@ -621,10 +1118,10 @@ describe('UsageTracker', () => { configOrigin: 'in-memory', configUpdatedAt: timestamp, }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.configUpdatedAt).toBe(timestamp); }); @@ -642,10 +1139,10 @@ describe('UsageTracker', () => { duration: 200, configUpdatedAt: timestamp, }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.configOrigin).toBe('in-memory'); expect(event.payload.cacheStatus).toBe('MISS'); expect(event.payload.cacheIsFirstRead).toBe(true); @@ -661,10 +1158,10 @@ describe('UsageTracker', () => { // Only pass configOrigin, omit others tracker.trackRead({ configOrigin: 'embedded' }); - await tracker.flush(); + await tracker.shutdown(); - const events = getBody() as FlagsConfigReadEvent[]; - const event = events[0] as FlagsConfigReadEvent; + const events = getBody() as SerializedConfigReadEvent[]; + const event = events[0] as SerializedConfigReadEvent; expect(event.payload.configOrigin).toBe('embedded'); expect(event.payload.cacheStatus).toBeUndefined(); expect(event.payload.cacheIsFirstRead).toBeUndefined(); diff --git a/packages/vercel-flags-core/src/utils/usage-tracker.ts b/packages/vercel-flags-core/src/utils/usage-tracker.ts index df251286..3557aab6 100644 --- a/packages/vercel-flags-core/src/utils/usage-tracker.ts +++ b/packages/vercel-flags-core/src/utils/usage-tracker.ts @@ -1,146 +1,54 @@ -import { waitUntil } from '@vercel/functions'; -import { version } from '../../package.json'; -import type { Auth } from '../controller/auth'; -import { getJitteredWaitMs, getRetryDelayMs } from './backoff'; - -const RESOLVED_VOID: Promise = Promise.resolve(); - -const isDebugMode = process.env.DEBUG?.includes('@vercel/flags-core'); - -const debugLog = (...args: any[]) => { - if (!isDebugMode) return; - console.log(...args); -}; - -export interface FlagsConfigReadEvent { - type: 'FLAGS_CONFIG_READ'; - ts: number; - payload: { - deploymentId?: string; - region?: string; - invocationHost?: string; - vercelRequestId?: string; - cacheStatus?: 'HIT' | 'MISS' | 'BYPASS' | 'STALE'; - cacheAction?: 'REFRESHING' | 'FOLLOWING' | 'NONE'; - cacheIsBlocking?: boolean; - cacheIsFirstRead?: boolean; - duration?: number; - configUpdatedAt?: number; - configOrigin?: 'in-memory' | 'embedded' | 'poll' | 'stream' | 'constructor'; - mode?: 'poll' | 'stream' | 'build' | 'offline'; - revision?: string; - environment?: string; - }; -} - -interface EventBatcher { - events: FlagsConfigReadEvent[]; - /** Resolves the current wait period early (e.g., when batch size is reached) */ - resolveWait: (() => void) | null; - /** Promise for flush operation */ - pending: null | Promise; -} - -const MAX_RETRIES = 3; -const MAX_BATCH_SIZE = 50; -const MAX_BATCH_WAIT_MS = 5000; - -/** - * Symmetric jitter applied to MAX_BATCH_WAIT_MS so that independent processes - * that started at the same wall-clock time do not flush in lockstep. - */ -const BATCH_WAIT_JITTER_RATIO = 0.2; - -interface RequestContext { - ctx: object | undefined; - headers: Record | undefined; -} - -const SYMBOL_FOR_REQ_CONTEXT = Symbol.for('@vercel/request-context'); -const fromSymbol = globalThis as typeof globalThis & { - [key: symbol]: - | { get?: () => { headers?: Record } } - | undefined; -}; - -/** - * Gets the Vercel request context and headers from the global symbol. - */ -function getRequestContext(): RequestContext { - try { - const ctx = fromSymbol[SYMBOL_FOR_REQ_CONTEXT]?.get?.(); - if (ctx && Object.hasOwn(ctx, 'headers')) { - return { - ctx, - headers: ctx.headers as Record, - }; - } - return { ctx, headers: undefined }; - } catch { - return { ctx: undefined, headers: undefined }; - } -} - -export interface UsageTrackerOptions { - auth: Auth; - host: string; - fetch: typeof fetch; -} - -export interface TrackReadOptions { - /** Whether the config was read from in-memory cache or embedded bundle */ - configOrigin: 'in-memory' | 'embedded'; - /** HIT when definitions exist in memory, MISS when not, BYPASS when using fallback as primary source */ - cacheStatus?: 'HIT' | 'MISS' | 'BYPASS'; - /** FOLLOWING when streaming, REFRESHING when polling, NONE otherwise */ - cacheAction?: 'REFRESHING' | 'FOLLOWING' | 'NONE'; - /** True for the very first getData call */ - cacheIsFirstRead?: boolean; - /** Whether the cache read was blocking */ - cacheIsBlocking?: boolean; - /** Duration in milliseconds from start of getData until trackRead */ - duration?: number; - /** Timestamp when the config was last updated */ - configUpdatedAt?: number; - /** The mode the SDK is operating in */ - mode?: 'poll' | 'stream' | 'build' | 'offline'; - /** Revision of the config */ - revision?: number; +import { type IngestOptions, sendIngestEvents } from './ingest'; +import { getRequestContext } from './request-context'; +import { Scheduler } from './scheduler'; +import { + FlagsConfigReadEvent, + type TrackReadOptions, +} from './usage/flags-config-read'; +import { + evaluationBatchKey, + FlagsEvaluationEvent, + minuteBucketTs, + type TrackEvaluationOptions, +} from './usage/flags-evaluation'; + +const DISABLE_FLAG_EVALUATIONS_ENV = 'VERCEL_FLAGS_DISABLE_FLAG_EVALUATIONS'; + +function isFlagEvaluationTrackingDisabled(): boolean { + const value = process.env[DISABLE_FLAG_EVALUATIONS_ENV]?.toLowerCase(); + return value === '1' || value === 'true'; } /** * Tracks usage events and batches them for submission to the ingest endpoint. */ export class UsageTracker { - private flushCounter: number = 0; - private options: UsageTrackerOptions; + private flushCount: number = 0; + + private options: IngestOptions; + private scheduler: Scheduler; + private trackedRequests = new WeakSet(); - private batcher: EventBatcher = { - events: [], - resolveWait: null, - pending: null, - }; - constructor(options: UsageTrackerOptions) { + private readEvents: FlagsConfigReadEvent[] = []; + private evaluationEvents = new Map(); + + constructor(options: IngestOptions) { this.options = options; + this.scheduler = new Scheduler(() => this.flushEvents()); } /** * Triggers an immediate flush of any pending events. * Returns a promise that resolves when the flush completes. */ - flush(): Promise { - if (this.batcher.pending) { - this.batcher.resolveWait?.(); - return this.batcher.pending; - } - - // No scheduled flush yet — flush directly if there are queued events - if (this.batcher.events.length > 0) { - return this.flushEvents(); - } + async shutdown() { + // Drain any in-flight scheduled batch (incl. its ingest send). + await this.scheduler.shutdown(); - return RESOLVED_VOID; + // Safety net for events tracked after the drained batch reset; if the + // drained flush already sent everything this returns early (maps cleared). + await this.flushEvents(); } /** @@ -157,158 +65,67 @@ export class UsageTracker { if (this.trackedRequests.has(ctx)) return; this.trackedRequests.add(ctx); - const event: FlagsConfigReadEvent = { - type: 'FLAGS_CONFIG_READ', - ts: Date.now(), - payload: { - deploymentId: process.env.VERCEL_DEPLOYMENT_ID, - region: process.env.VERCEL_REGION, - }, - }; - - if (headers) { - event.payload.vercelRequestId = headers['x-vercel-id'] ?? undefined; - event.payload.invocationHost = headers.host ?? undefined; - } - - if (options) { - event.payload.configOrigin = options.configOrigin; - if (options.cacheStatus !== undefined) { - event.payload.cacheStatus = options.cacheStatus; - } - if (options.cacheAction !== undefined) { - event.payload.cacheAction = options.cacheAction; - } - if (options.cacheIsFirstRead !== undefined) { - event.payload.cacheIsFirstRead = options.cacheIsFirstRead; - } - if (options.cacheIsBlocking !== undefined) { - event.payload.cacheIsBlocking = options.cacheIsBlocking; - } - if (options.duration !== undefined) { - event.payload.duration = options.duration; - } - if (options.configUpdatedAt !== undefined) { - event.payload.configUpdatedAt = options.configUpdatedAt; - } - if (options.mode !== undefined) { - event.payload.mode = options.mode; - } - if (options.revision !== undefined) { - event.payload.revision = String(options.revision); - } - } - - const environment = - process.env.VERCEL_ENV || process.env.NODE_ENV || undefined; - if (environment) { - event.payload.environment = environment; - } + this.readEvents.push(new FlagsConfigReadEvent(headers, options)); - this.batcher.events.push(event); - this.scheduleFlush(); + // always schedule and increment since we are adding a new event here + this.scheduler.scheduleFlush(); + this.scheduler.increment(); } catch (error) { // trackRead should never throw, but log the error console.error('@vercel/flags-core: Failed to record event:', error); } } - private scheduleFlush(): void { - if (!this.batcher.pending) { - let timeout: null | ReturnType = null; - - const pending = (async () => { - await new Promise((res) => { - this.batcher.resolveWait = res; - timeout = setTimeout( - res, - getJitteredWaitMs(MAX_BATCH_WAIT_MS, BATCH_WAIT_JITTER_RATIO), - ); - }); - - this.batcher.pending = null; - this.batcher.resolveWait = null; - if (timeout) clearTimeout(timeout); + /** + * Tracks a flag evaluation event. + */ + trackEvaluation(options: TrackEvaluationOptions): void { + try { + if (isFlagEvaluationTrackingDisabled()) return; - await this.flushEvents(); - })(); + const bucketedOptions = { + ...options, + bucketTs: minuteBucketTs(), + }; + const batchKey = evaluationBatchKey(bucketedOptions); + + const existingEvent = this.evaluationEvents.get(batchKey); + // increment if we already have an event for this batch key + if (existingEvent) { + existingEvent.increment(); + } else { + this.evaluationEvents.set( + batchKey, + new FlagsEvaluationEvent(bucketedOptions), + ); - // Use waitUntil to keep the function alive until flush completes - // If `waitUntil` is not available this will be a no-op and leave - // a floating promise that will be completed in the background - try { - waitUntil(pending); - } catch { - // waitUntil is best-effort; falling through leaves a floating promise + // only increment the scheduler if we are adding a new event + this.scheduler.increment(); } - this.batcher.pending = pending; - } - - // Trigger early flush if threshold was reached - if (this.batcher.events.length >= MAX_BATCH_SIZE) { - this.batcher.resolveWait?.(); + // always schedule to reset the timer + this.scheduler.scheduleFlush(); + } catch (error) { + console.error( + '@vercel/flags-core: Failed to record evaluation event:', + error, + ); } } - private async flushEvents(): Promise { - if (this.batcher.events.length === 0) return; - - // Take all events and clear the queue - const eventsToSend = this.batcher.events; - this.batcher.events = []; - - const flushId = ++this.flushCounter; - - for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { - try { - const token = await this.options.auth.resolveToken(); - - const response = await this.options.fetch( - `${this.options.host}/v1/ingest`, - { - method: 'POST', - headers: { - 'Content-Type': 'application/json', - Authorization: `Bearer ${token}`, - 'User-Agent': `VercelFlagsCore/${version}`, - ...(process.env.VERCEL_ENV - ? { 'X-Vercel-Env': process.env.VERCEL_ENV } - : null), - ...(isDebugMode ? { 'x-vercel-debug-ingest': '1' } : null), - }, - body: JSON.stringify(eventsToSend), - }, - ); + /** + * Send all events to the ingest service + */ + private async flushEvents() { + const events = [...this.readEvents, ...this.evaluationEvents.values()]; + if (events.length === 0) return; - debugLog( - `@vercel/flags-core: Ingest response ${response.status} for ${eventsToSend.length} events on ${response.headers.get('x-vercel-id')}`, - ); + this.flushCount += 1; + const flushId = this.flushCount; - if (response.ok) { - break; // Break the loop if the request succeeded - } + this.readEvents = []; + this.evaluationEvents.clear(); - throw new Error( - `Ingest endpoint responded with status ${response.status} for ${eventsToSend.length} events on request ${response.headers.get('x-vercel-id')}.\n` + - `Response body: ${await response.text().catch(() => null)}`, - ); - } catch (error) { - console.error( - `@vercel/flags-core: Error sending events (attempt=${attempt}/${MAX_RETRIES} flushId=${flushId}):`, - error, - ); - if (attempt < MAX_RETRIES) { - const delayMs = getRetryDelayMs(attempt); - await new Promise((res) => setTimeout(res, delayMs)); - } else { - // All retries exhausted — surface a structured warning so consumers - // can alert on dropped batches. The events are not persisted anywhere. - console.error( - `@vercel/flags-core: Dropped ${eventsToSend.length} events after ${MAX_RETRIES} attempts (flushId=${flushId})`, - ); - } - } - } + await sendIngestEvents(this.options, events, flushId); } } diff --git a/packages/vercel-flags-core/src/utils/usage/events.ts b/packages/vercel-flags-core/src/utils/usage/events.ts new file mode 100644 index 00000000..62153bf1 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/usage/events.ts @@ -0,0 +1,9 @@ +export interface IngestEvent { + type: string; + ts: number; + payload: object; +} + +export interface UsageEvent { + ingestEvent(): IngestEvent; +} diff --git a/packages/vercel-flags-core/src/utils/usage/flags-config-read.ts b/packages/vercel-flags-core/src/utils/usage/flags-config-read.ts new file mode 100644 index 00000000..c9657343 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/usage/flags-config-read.ts @@ -0,0 +1,100 @@ +import type { UsageEvent } from './events'; + +export interface TrackReadOptions { + /** Whether the config was read from in-memory cache or embedded bundle */ + configOrigin: 'in-memory' | 'embedded'; + /** HIT when definitions exist in memory, MISS when not, BYPASS when using fallback as primary source */ + cacheStatus?: 'HIT' | 'MISS' | 'BYPASS'; + /** FOLLOWING when streaming, REFRESHING when polling, NONE otherwise */ + cacheAction?: 'REFRESHING' | 'FOLLOWING' | 'NONE'; + /** True for the very first getData call */ + cacheIsFirstRead?: boolean; + /** Whether the cache read was blocking */ + cacheIsBlocking?: boolean; + /** Duration in milliseconds from start of getData until trackRead */ + duration?: number; + /** Timestamp when the config was last updated */ + configUpdatedAt?: number; + /** The mode the SDK is operating in */ + mode?: 'poll' | 'stream' | 'build' | 'offline'; + /** Revision of the config */ + revision?: number; +} + +export class FlagsConfigReadEvent implements UsageEvent { + private readonly ts = Date.now(); + + private payload: { + deploymentId?: string; + region?: string; + invocationHost?: string; + vercelRequestId?: string; + cacheStatus?: 'HIT' | 'MISS' | 'BYPASS' | 'STALE'; + cacheAction?: 'REFRESHING' | 'FOLLOWING' | 'NONE'; + cacheIsBlocking?: boolean; + cacheIsFirstRead?: boolean; + duration?: number; + configUpdatedAt?: number; + configOrigin?: 'in-memory' | 'embedded' | 'poll' | 'stream' | 'constructor'; + mode?: 'poll' | 'stream' | 'build' | 'offline'; + revision?: string; + environment?: string; + }; + + constructor( + headers: Record | undefined, + options?: TrackReadOptions, + ) { + this.payload = { + deploymentId: process.env.VERCEL_DEPLOYMENT_ID, + region: process.env.VERCEL_REGION, + }; + + if (headers) { + this.payload.vercelRequestId = headers['x-vercel-id'] ?? undefined; + this.payload.invocationHost = headers.host ?? undefined; + } + + if (options) { + this.payload.configOrigin = options.configOrigin; + if (options.cacheStatus !== undefined) { + this.payload.cacheStatus = options.cacheStatus; + } + if (options.cacheAction !== undefined) { + this.payload.cacheAction = options.cacheAction; + } + if (options.cacheIsFirstRead !== undefined) { + this.payload.cacheIsFirstRead = options.cacheIsFirstRead; + } + if (options.cacheIsBlocking !== undefined) { + this.payload.cacheIsBlocking = options.cacheIsBlocking; + } + if (options.duration !== undefined) { + this.payload.duration = options.duration; + } + if (options.configUpdatedAt !== undefined) { + this.payload.configUpdatedAt = options.configUpdatedAt; + } + if (options.mode !== undefined) { + this.payload.mode = options.mode; + } + if (options.revision !== undefined) { + this.payload.revision = String(options.revision); + } + } + + const environment = + process.env.VERCEL_ENV || process.env.NODE_ENV || undefined; + if (environment) { + this.payload.environment = environment; + } + } + + ingestEvent() { + return { + type: 'FLAGS_CONFIG_READ' as const, + ts: this.ts, + payload: this.payload, + }; + } +} diff --git a/packages/vercel-flags-core/src/utils/usage/flags-evaluation.ts b/packages/vercel-flags-core/src/utils/usage/flags-evaluation.ts new file mode 100644 index 00000000..c0498b45 --- /dev/null +++ b/packages/vercel-flags-core/src/utils/usage/flags-evaluation.ts @@ -0,0 +1,70 @@ +import type { ResolutionReason, VariantId } from '../../types'; +import type { UsageEvent } from './events'; + +export interface TrackEvaluationOptions { + flagKey: string; + variant: VariantId | null; + reason: ResolutionReason; + clientName?: string; +} + +const MINUTE_MS = 60_000; + +export function minuteBucketTs(ts = Date.now()): number { + return Math.floor(ts / MINUTE_MS) * MINUTE_MS; +} + +export type BucketedTrackEvaluationOptions = TrackEvaluationOptions & { + bucketTs: number; +}; + +export function evaluationBatchKey( + options: BucketedTrackEvaluationOptions, +): string { + return JSON.stringify([ + options.flagKey, + options.variant, + options.reason, + options.clientName ?? null, + options.bucketTs, + ]); +} + +export class FlagsEvaluationEvent implements UsageEvent { + private readonly ts = Date.now(); + + payload: { + flagKey: string; + variant?: string; + reason: ResolutionReason; + clientName?: string; + evaluationCount: number; + periodStartedAt: number; + }; + + constructor(eventOptions: BucketedTrackEvaluationOptions) { + this.payload = { + flagKey: eventOptions.flagKey, + variant: eventOptions.variant ?? undefined, + reason: eventOptions.reason, + evaluationCount: 1, + periodStartedAt: eventOptions.bucketTs, + }; + + if (eventOptions.clientName) { + this.payload.clientName = eventOptions.clientName; + } + } + + increment(): void { + this.payload.evaluationCount += 1; + } + + ingestEvent() { + return { + type: 'FLAG_EVALUATION' as const, + ts: this.ts, + payload: this.payload, + }; + } +}