diff --git a/.changeset/fix-span-streaming.md b/.changeset/fix-span-streaming.md new file mode 100644 index 0000000..81570d6 --- /dev/null +++ b/.changeset/fix-span-streaming.md @@ -0,0 +1,5 @@ +--- +"@vercel/otel": patch +--- + +Fix long-running invocations (e.g. Vercel Workflows) losing most spans from the first part of the run. The exporter now enforces strict per-trace `reportSpans` payloads: spans are grouped by their own trace id, buffered per trace, and shipped in one payload at the trace's final flush through the request context captured for that trace at root-span start. Untracked traces keep shipping immediately through the ambient context, unattributable spans are retained and retried instead of silently dropped, and the processor drains the BatchSpanProcessor queue in-context on span end so long runs cannot overflow its maxQueueSize. An opt-in streaming mode (`VERCEL_OTEL_STREAM_SPANS=1`) ships every trace's spans on every flush instead. diff --git a/packages/otel/build.ts b/packages/otel/build.ts index 4b7bc1e..db23ed6 100644 --- a/packages/otel/build.ts +++ b/packages/otel/build.ts @@ -6,8 +6,8 @@ const MINIFY = true; const SOURCEMAP = true; const MAX_SIZES = { - "dist/node/index.js": 300_000, // Increased from original 217KB limit - "dist/edge/index.js": 191_000, // Increased from original 185KB limit + "dist/node/index.js": 305_000, // Increased from 300KB for the span-attribution fix (main was within ~2KB of the limit) + "dist/edge/index.js": 193_000, // Increased from 191KB for the span-attribution fix (main was within ~100 bytes of the limit) }; type ExternalPluginFactory = (external: string[]) => Plugin; diff --git a/packages/otel/src/processor/composite-span-processor.test.ts b/packages/otel/src/processor/composite-span-processor.test.ts new file mode 100644 index 0000000..7eb05b7 --- /dev/null +++ b/packages/otel/src/processor/composite-span-processor.test.ts @@ -0,0 +1,179 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import type { + ReadableSpan, + Span, + SpanProcessor, +} from "@opentelemetry/sdk-trace-base"; +import { hrTime } from "@opentelemetry/core"; +import { ROOT_CONTEXT, TraceFlags, SpanKind, SpanStatusCode } from "@opentelemetry/api"; +import { resourceFromAttributes } from "@opentelemetry/resources"; +import type { VercelRequestContext } from "../vercel-request-context/api"; +import { hasVercelRequestContextForTrace } from "../vercel-request-context/api"; +import { CompositeSpanProcessor } from "./composite-span-processor"; + +const TRACE_ID = "ee75cd9e534ff5e9ed78b4a0c706f0f2"; +const VRC_SYMBOL = Symbol.for("@vercel/request-context"); +type GlobalWithReader = Record; + +function installAmbient(ctx: VercelRequestContext | undefined): void { + (globalThis as GlobalWithReader)[VRC_SYMBOL] = { get: () => ctx }; +} + +function fakeVrc(): VercelRequestContext & { + flushes: Array<() => Promise>; +} { + const flushes: Array<() => Promise> = []; + return { + flushes, + waitUntil: (promiseOrFunc) => { + if (typeof promiseOrFunc === "function") { + flushes.push(promiseOrFunc as () => Promise); + } + }, + headers: {}, + url: "https://example.com", + telemetry: { reportSpans: () => undefined }, + }; +} + +function readableSpanFields(spanId: string, parent: boolean) { + const spanContext = { + traceId: TRACE_ID, + spanId, + traceFlags: TraceFlags.SAMPLED, + isRemote: false, + }; + return { + name: `span-${spanId}`, + kind: SpanKind.INTERNAL, + spanContext: () => spanContext, + parentSpanContext: parent + ? { + spanId: "7e2a325411bdc191", + traceId: TRACE_ID, + traceFlags: TraceFlags.SAMPLED, + } + : undefined, + startTime: hrTime(1), + endTime: hrTime(2), + status: { code: SpanStatusCode.UNSET }, + attributes: {}, + links: [], + events: [], + duration: hrTime(1), + ended: true, + resource: resourceFromAttributes({}), + instrumentationScope: { name: "default" }, + droppedAttributesCount: 0, + droppedEventsCount: 0, + droppedLinksCount: 0, + }; +} + +function createRootSpan(spanId: string): Span { + return { + ...readableSpanFields(spanId, false), + setAttribute: () => undefined, + setAttributes: () => undefined, + addEvent: () => undefined, + addLink: () => undefined, + addLinks: () => undefined, + setStatus: () => undefined, + updateName: () => undefined, + end: () => undefined, + isRecording: () => true, + recordException: () => undefined, + } as unknown as Span; +} + +function createChildEnd(spanId: string): ReadableSpan { + return readableSpanFields(spanId, true) as unknown as ReadableSpan; +} + +function fakeProcessor(): { + processor: SpanProcessor; + forceFlush: ReturnType; +} { + const forceFlush = vi.fn().mockResolvedValue(undefined); + const processor: SpanProcessor = { + onStart: vi.fn(), + onEnd: vi.fn(), + forceFlush, + shutdown: vi.fn().mockResolvedValue(undefined), + }; + return { processor, forceFlush }; +} + +describe("CompositeSpanProcessor", () => { + afterEach(() => { + installAmbient(undefined); + vi.unstubAllEnvs(); + vi.restoreAllMocks(); + }); + + it("registers the request context for the trace at root start and finalizes it after the final flush", async () => { + const vrc = fakeVrc(); + installAmbient(vrc); + const { processor: downstream, forceFlush } = fakeProcessor(); + const processor = new CompositeSpanProcessor([downstream], undefined); + + const root = createRootSpan("7e2a325411bdc191"); + processor.onStart(root, ROOT_CONTEXT); + + // The trace's owning context is now captured, independent of the ambient one. + installAmbient(undefined); + expect(hasVercelRequestContextForTrace(TRACE_ID)).toBe(true); + + // Root ends; the waitUntil-registered final flush drains the processors + // and finalizes (ships + unregisters) the trace. + processor.onEnd(root as unknown as ReadableSpan); + expect(vrc.flushes).toHaveLength(1); + await vrc.flushes[0]?.(); + expect(forceFlush).toHaveBeenCalled(); + expect(hasVercelRequestContextForTrace(TRACE_ID)).toBe(false); + }); + + it("flushes in-context once the batch-size threshold of ended spans is reached", () => { + installAmbient(fakeVrc()); + vi.stubEnv("OTEL_BSP_MAX_EXPORT_BATCH_SIZE", "3"); + const { processor: downstream, forceFlush } = fakeProcessor(); + const processor = new CompositeSpanProcessor([downstream], undefined); + + processor.onEnd(createChildEnd("0000000000000001")); + processor.onEnd(createChildEnd("0000000000000002")); + expect(forceFlush).toHaveBeenCalledTimes(0); + + processor.onEnd(createChildEnd("0000000000000003")); + expect(forceFlush).toHaveBeenCalledTimes(1); + }); + + it("flushes in-context once the schedule delay elapses between ended spans", () => { + installAmbient(fakeVrc()); + vi.stubEnv("OTEL_BSP_MAX_EXPORT_BATCH_SIZE", "1000000"); + vi.stubEnv("OTEL_BSP_SCHEDULE_DELAY", "5000"); + const { processor: downstream, forceFlush } = fakeProcessor(); + const processor = new CompositeSpanProcessor([downstream], undefined); + + const now = vi.spyOn(Date, "now"); + now.mockReturnValue(1000); + processor.onEnd(createChildEnd("0000000000000001")); + processor.onEnd(createChildEnd("0000000000000002")); + expect(forceFlush).toHaveBeenCalledTimes(0); + + now.mockReturnValue(7000); + processor.onEnd(createChildEnd("0000000000000003")); + expect(forceFlush).toHaveBeenCalledTimes(1); + }); + + it("does not flush off-Vercel (no request context)", () => { + installAmbient(undefined); + vi.stubEnv("OTEL_BSP_MAX_EXPORT_BATCH_SIZE", "2"); + const { processor: downstream, forceFlush } = fakeProcessor(); + const processor = new CompositeSpanProcessor([downstream], undefined); + + for (let i = 1; i <= 5; i++) { + processor.onEnd(createChildEnd(`00000000000000${i}0`)); + } + expect(forceFlush).toHaveBeenCalledTimes(0); + }); +}); diff --git a/packages/otel/src/processor/composite-span-processor.ts b/packages/otel/src/processor/composite-span-processor.ts index 7ca514a..30c1cb9 100644 --- a/packages/otel/src/processor/composite-span-processor.ts +++ b/packages/otel/src/processor/composite-span-processor.ts @@ -5,7 +5,12 @@ import type { ReadableSpan, SpanProcessor, } from "@opentelemetry/sdk-trace-base"; -import { getVercelRequestContext } from "../vercel-request-context/api"; +import { getNumberFromEnv } from "@opentelemetry/core"; +import { + finalizeTrace, + getVercelRequestContext, + registerVercelRequestContextForTrace, +} from "../vercel-request-context/api"; import { getVercelRequestContextAttributes } from "../vercel-request-context/attributes"; import { isSampled } from "../util/sampled"; import type { AttributesFromHeaders } from "../types"; @@ -18,6 +23,13 @@ export class CompositeSpanProcessor implements SpanProcessor { >(); private readonly waitSpanEnd = new Map void>(); + private readonly flushBatchSize = + getNumberFromEnv("OTEL_BSP_MAX_EXPORT_BATCH_SIZE") ?? 512; + private readonly flushDelayMs = + getNumberFromEnv("OTEL_BSP_SCHEDULE_DELAY") ?? 5000; + private spansSinceFlush = 0; + private lastFlushMs = 0; + constructor( private processors: SpanProcessor[], private attributesFromHeaders: AttributesFromHeaders | undefined, @@ -58,8 +70,15 @@ export class CompositeSpanProcessor implements SpanProcessor { span.setAttributes(vercelRequestContextAttrs); } - // Flush the streams to avoid data loss. if (vrc) { + // Capture the request context that owns this trace. The exporter + // streams this trace's spans as single-trace payloads through this + // context's telemetry channel on every flush (the runtime only + // reliably persists payloads composed of one active trace), and the + // finalize below ships whatever is left when the request ends. + registerVercelRequestContextForTrace(traceId, vrc); + + // Flush the streams to avoid data loss. vrc.waitUntil(async () => { if (this.rootSpanIds.has(traceId)) { // Not root has not completed yet, so no point in flushing. @@ -81,7 +100,15 @@ export class CompositeSpanProcessor implements SpanProcessor { clearTimeout(timer); } } - return this.forceFlush(); + try { + // Drain the processors so every one of this trace's remaining + // spans reaches the exporter's per-trace buffer... + return await this.forceFlush(); + } finally { + // ...then ship the buffer in one report and drop the captured + // context. + finalizeTrace(traceId); + } }); } } @@ -135,6 +162,33 @@ export class CompositeSpanProcessor implements SpanProcessor { this.waitSpanEnd.delete(traceId); pending(); } + } else if (sampled && getVercelRequestContext()) { + // Periodic in-context drain, Vercel-only. Long-running invocations + // produce more spans than the BatchSpanProcessor's queue holds (it + // silently drops past maxQueueSize), so drain it regularly into the + // exporter, which streams each trace's spans out as single-trace + // payloads. Off-Vercel this is skipped and the stock timer behaves as + // before. The root span's final flush is handled by the waitUntil + // registered in onStart. + this.maybeFlush(); + } + } + + private maybeFlush(): void { + this.spansSinceFlush += 1; + const now = Date.now(); + if (this.lastFlushMs === 0) { + this.lastFlushMs = now; + } + if ( + this.spansSinceFlush >= this.flushBatchSize || + now - this.lastFlushMs >= this.flushDelayMs + ) { + this.spansSinceFlush = 0; + this.lastFlushMs = now; + void this.forceFlush().catch((e) => { + diag.error("@vercel/otel: periodic flush failed:", e); + }); } } } diff --git a/packages/otel/src/vercel-request-context/api.ts b/packages/otel/src/vercel-request-context/api.ts index f173fc8..2057b25 100644 --- a/packages/otel/src/vercel-request-context/api.ts +++ b/packages/otel/src/vercel-request-context/api.ts @@ -35,3 +35,87 @@ export function getVercelRequestContext(): VercelRequestContext | undefined { const reader = (globalThis as GlobalWithReader)[symbol]; return reader?.get(); } + +/** + * Registry of request contexts keyed by trace id, so span exports can reach + * the telemetry channel of the request that OWNS each span even when the + * flush runs outside any request context. + * + * Why this exists: the BatchSpanProcessor's queue is shared by every request + * running on the function instance, and its scheduled flush runs in a bare + * `setTimeout` OUTSIDE any request's AsyncLocalStorage, where the ambient + * context resolves to nothing (the exporter used to silently drop those + * batches). The runtime also only reliably persists payloads composed of a + * SINGLE trace belonging to an active request; mixed-queue payloads used to + * be dropped whole or misfiled depending on which span sat first in the + * batch. Long-running invocations, e.g. Vercel Workflows, used to lose every + * span flushed mid-run: their traces looked blank except for the last few + * seconds. + * + * The context is captured per trace while inside the owning request (root + * span `onStart`); the exporter streams each trace's spans as single-trace + * payloads through it, and `finalizeTrace` (invoked from the request's + * `waitUntil`, after the final flush) ships whatever is left. A hard cap + * bounds the registry against traces whose root span never ends. + */ +const traceContextRegistry = new Map(); + +const MAX_REGISTRY_SIZE = 1024; + +type TraceFinalizer = (traceId: string) => void; + +/** Callbacks (e.g. the runtime span exporter) shipping a trace's buffer. */ +const traceFinalizers = new Set(); + +/** @internal Register a callback invoked when a trace is finalized. */ +export function onTraceFinalize(finalizer: TraceFinalizer): void { + traceFinalizers.add(finalizer); +} + +/** @internal Capture the request context that owns a given trace. */ +export function registerVercelRequestContextForTrace( + traceId: string, + context: VercelRequestContext, +): void { + if ( + traceContextRegistry.size >= MAX_REGISTRY_SIZE && + !traceContextRegistry.has(traceId) + ) { + // Evict the oldest entry (Map preserves insertion order) so a leak of + // never-ending traces cannot grow the registry unboundedly. + const oldest: string | undefined = traceContextRegistry.keys().next() + .value as string | undefined; + if (oldest !== undefined) { + traceContextRegistry.delete(oldest); + } + } + traceContextRegistry.set(traceId, context); +} + +/** @internal Whether a trace has a captured owning context. */ +export function hasVercelRequestContextForTrace(traceId: string): boolean { + return traceContextRegistry.has(traceId); +} + +/** @internal Resolve the request context that owns a trace. */ +export function getVercelRequestContextForTrace( + traceId: string, +): VercelRequestContext | undefined { + return traceContextRegistry.get(traceId); +} + +/** + * @internal Ship a trace's remaining buffered spans (via the registered + * finalizers) and drop its captured context. Called from the owning + * request's `waitUntil` after the final flush, so the last payload is sent + * while the invocation is still able to deliver telemetry. + */ +export function finalizeTrace(traceId: string): void { + try { + for (const finalizer of traceFinalizers) { + finalizer(traceId); + } + } finally { + traceContextRegistry.delete(traceId); + } +} \ No newline at end of file diff --git a/packages/otel/src/vercel-request-context/exporter.test.ts b/packages/otel/src/vercel-request-context/exporter.test.ts new file mode 100644 index 0000000..abcac0d --- /dev/null +++ b/packages/otel/src/vercel-request-context/exporter.test.ts @@ -0,0 +1,266 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import type { ReadableSpan } from "@opentelemetry/sdk-trace-base"; +import { ExportResultCode, hrTime } from "@opentelemetry/core"; +import { TraceFlags, SpanKind, SpanStatusCode } from "@opentelemetry/api"; +import type { IExportTraceServiceRequest } from "@opentelemetry/otlp-transformer/build/src/trace/internal-types"; +import { resourceFromAttributes } from "@opentelemetry/resources"; +import type { VercelRequestContext } from "./api"; +import { finalizeTrace, registerVercelRequestContextForTrace } from "./api"; +import { VercelRuntimeSpanExporter } from "./exporter"; + +const TRACE_A = "aa75cd9e534ff5e9ed78b4a0c706f0f2"; +const TRACE_B = "bb75cd9e534ff5e9ed78b4a0c706f0f2"; +const VRC_SYMBOL = Symbol.for("@vercel/request-context"); + +type GlobalWithReader = Record; + +function createSpan(spanId: string, traceId = TRACE_A): ReadableSpan { + const spanContext = { + traceId, + spanId, + traceFlags: TraceFlags.SAMPLED, + isRemote: false, + }; + return { + name: `span-${spanId}`, + kind: SpanKind.INTERNAL, + spanContext: () => spanContext, + parentSpanContext: undefined, + startTime: hrTime(1), + endTime: hrTime(2), + status: { code: SpanStatusCode.UNSET }, + attributes: {}, + links: [], + events: [], + duration: hrTime(1), + ended: true, + resource: resourceFromAttributes({}), + instrumentationScope: { name: "default" }, + droppedAttributesCount: 0, + droppedEventsCount: 0, + droppedLinksCount: 0, + }; +} + +function makeContext(): { + ctx: VercelRequestContext; + reportSpans: ReturnType; +} { + const reportSpans = vi.fn(); + const ctx: VercelRequestContext = { + waitUntil: () => undefined, + headers: {}, + url: "https://example.com", + telemetry: { reportSpans }, + }; + return { ctx, reportSpans }; +} + +function installAmbient(ctx: VercelRequestContext | undefined): void { + (globalThis as GlobalWithReader)[VRC_SYMBOL] = { get: () => ctx }; +} + +function shippedTraceIds( + reportSpans: ReturnType, + call = 0, +): string[] { + const data = reportSpans.mock.calls[call]?.[0] as IExportTraceServiceRequest; + return (data.resourceSpans ?? []).flatMap((rs) => + rs.scopeSpans.flatMap((ss) => + (ss.spans ?? []).map((s) => String(s.traceId)), + ), + ); +} + +function shippedSpanCount( + reportSpans: ReturnType, + call = 0, +): number { + return shippedTraceIds(reportSpans, call).length; +} + +function makeStreamingExporter(): VercelRuntimeSpanExporter { + process.env.VERCEL_OTEL_STREAM_SPANS = "1"; + try { + return new VercelRuntimeSpanExporter(); + } finally { + delete process.env.VERCEL_OTEL_STREAM_SPANS; + } +} + +describe("VercelRuntimeSpanExporter (streaming mode, VERCEL_OTEL_STREAM_SPANS=1)", () => { + afterEach(() => { + installAmbient(undefined); + // Clear any registrations left behind by a test. + finalizeTrace(TRACE_A); + finalizeTrace(TRACE_B); + vi.restoreAllMocks(); + }); + + it("streams a registered trace's spans on every flush, as single-trace payloads", () => { + const owner = makeContext(); + registerVercelRequestContextForTrace(TRACE_A, owner.ctx); + installAmbient(undefined); + + const exporter = makeStreamingExporter(); + const result = vi.fn(); + exporter.export([createSpan("0000000000000001", TRACE_A)], result); + exporter.export([createSpan("0000000000000002", TRACE_A)], result); + + expect(result).toHaveBeenCalledWith({ + code: ExportResultCode.SUCCESS, + error: undefined, + }); + // Two mid-run flushes -> two reports, each shipped immediately. + expect(owner.reportSpans).toHaveBeenCalledTimes(2); + expect(shippedSpanCount(owner.reportSpans, 0)).toBe(1); + expect(shippedSpanCount(owner.reportSpans, 1)).toBe(1); + + // Finalize with an empty buffer reports nothing further. + finalizeTrace(TRACE_A); + expect(owner.reportSpans).toHaveBeenCalledTimes(2); + }); + + it("never mixes traces into one payload: each trace ships separately to its own context", () => { + const ownerA = makeContext(); + const ownerB = makeContext(); + registerVercelRequestContextForTrace(TRACE_A, ownerA.ctx); + registerVercelRequestContextForTrace(TRACE_B, ownerB.ctx); + + const exporter = makeStreamingExporter(); + exporter.export( + [ + createSpan("0000000000000001", TRACE_A), + createSpan("0000000000000002", TRACE_B), + createSpan("0000000000000003", TRACE_A), + ], + vi.fn(), + ); + + expect(ownerA.reportSpans).toHaveBeenCalledTimes(1); + expect(ownerB.reportSpans).toHaveBeenCalledTimes(1); + expect(new Set(shippedTraceIds(ownerA.reportSpans))).toEqual( + new Set([TRACE_A]), + ); + expect(shippedSpanCount(ownerA.reportSpans)).toBe(2); + expect(new Set(shippedTraceIds(ownerB.reportSpans))).toEqual( + new Set([TRACE_B]), + ); + expect(shippedSpanCount(ownerB.reportSpans)).toBe(1); + }); + + it("ships untracked traces through the ambient context, still one payload per trace", () => { + const ambient = makeContext(); + installAmbient(ambient.ctx); + + const exporter = makeStreamingExporter(); + exporter.export( + [ + createSpan("0000000000000001", TRACE_A), + createSpan("0000000000000002", TRACE_B), + ], + vi.fn(), + ); + + // Two payloads (one per trace), never a mixed one. + expect(ambient.reportSpans).toHaveBeenCalledTimes(2); + expect(new Set(shippedTraceIds(ambient.reportSpans, 0)).size).toBe(1); + expect(new Set(shippedTraceIds(ambient.reportSpans, 1)).size).toBe(1); + }); + + it("buffers spans with no reachable channel and ships them on a later flush", () => { + const exporter = makeStreamingExporter(); + + installAmbient(undefined); + const firstResult = vi.fn(); + exporter.export([createSpan("0000000000000001", TRACE_B)], firstResult); + expect(firstResult).toHaveBeenCalledWith({ + code: ExportResultCode.SUCCESS, + error: undefined, + }); + + const { ctx, reportSpans } = makeContext(); + installAmbient(ctx); + exporter.export([createSpan("0000000000000002", TRACE_B)], vi.fn()); + + // Buffered + incoming ship together (same trace, one payload). + expect(reportSpans).toHaveBeenCalledTimes(1); + expect(shippedSpanCount(reportSpans)).toBe(2); + }); + + it("ships leftovers at finalizeTrace through the owning context", () => { + const exporter = makeStreamingExporter(); + + // No channel at flush time: spans stay buffered. + installAmbient(undefined); + exporter.export([createSpan("0000000000000001", TRACE_A)], vi.fn()); + + // The trace's request registers + finalizes (waitUntil path). + const owner = makeContext(); + registerVercelRequestContextForTrace(TRACE_A, owner.ctx); + finalizeTrace(TRACE_A); + + expect(owner.reportSpans).toHaveBeenCalledTimes(1); + expect(shippedSpanCount(owner.reportSpans)).toBe(1); + }); + + it("retains a trace's spans when its channel throws and retries on the next flush", () => { + const owner = makeContext(); + owner.reportSpans.mockImplementationOnce(() => { + throw new Error("boom"); + }); + registerVercelRequestContextForTrace(TRACE_A, owner.ctx); + + const exporter = makeStreamingExporter(); + const result = vi.fn(); + exporter.export([createSpan("0000000000000001", TRACE_A)], result); + expect(result).toHaveBeenCalledWith({ + code: ExportResultCode.SUCCESS, + error: undefined, + }); + expect(owner.reportSpans).toHaveBeenCalledTimes(1); + + // Next flush retries the retained span together with the new one. + exporter.export([createSpan("0000000000000002", TRACE_A)], vi.fn()); + expect(owner.reportSpans).toHaveBeenCalledTimes(2); + expect(shippedSpanCount(owner.reportSpans, 1)).toBe(2); + }); +}); + +describe("VercelRuntimeSpanExporter (default accumulate mode)", () => { + afterEach(() => { + installAmbient(undefined); + finalizeTrace(TRACE_A); + finalizeTrace(TRACE_B); + vi.restoreAllMocks(); + }); + + it("accumulates a registered trace's spans and ships them once at finalizeTrace", () => { + const owner = makeContext(); + const ambient = makeContext(); + registerVercelRequestContextForTrace(TRACE_A, owner.ctx); + installAmbient(ambient.ctx); + + const exporter = new VercelRuntimeSpanExporter(); + exporter.export([createSpan("0000000000000001", TRACE_A)], vi.fn()); + exporter.export([createSpan("0000000000000002", TRACE_A)], vi.fn()); + // Nothing ships mid-run in accumulate mode. + expect(owner.reportSpans).toHaveBeenCalledTimes(0); + expect(ambient.reportSpans).toHaveBeenCalledTimes(0); + + finalizeTrace(TRACE_A); + expect(owner.reportSpans).toHaveBeenCalledTimes(1); + expect(shippedSpanCount(owner.reportSpans)).toBe(2); + }); + + it("still ships untracked traces immediately via the ambient context", () => { + const ambient = makeContext(); + installAmbient(ambient.ctx); + + const exporter = new VercelRuntimeSpanExporter(); + exporter.export([createSpan("0000000000000001", TRACE_B)], vi.fn()); + + expect(ambient.reportSpans).toHaveBeenCalledTimes(1); + expect(shippedSpanCount(ambient.reportSpans)).toBe(1); + }); +}); diff --git a/packages/otel/src/vercel-request-context/exporter.ts b/packages/otel/src/vercel-request-context/exporter.ts index ff9f959..3fd1b33 100644 --- a/packages/otel/src/vercel-request-context/exporter.ts +++ b/packages/otel/src/vercel-request-context/exporter.ts @@ -3,32 +3,87 @@ import type { ReadableSpan, SpanExporter } from "@opentelemetry/sdk-trace-base"; import { ExportResultCode, type ExportResult } from "@opentelemetry/core"; import { JsonTraceSerializer } from "@opentelemetry/otlp-transformer/build/src/trace/json/trace"; import type { IExportTraceServiceRequest } from "@opentelemetry/otlp-transformer/build/src/trace/internal-types"; -import { getVercelRequestContext } from "./api"; +import { + getVercelRequestContext, + getVercelRequestContextForTrace, + onTraceFinalize, + type VercelRequestContext, +} from "./api"; +/** + * Upper bound on spans buffered per trace while no telemetry channel is + * available to ship them. When the cap is hit the oldest spans are dropped + * with a warning rather than growing memory unboundedly. + */ +const MAX_TRACE_BUFFER_SIZE = 8192; + +/** + * Ships spans to the Vercel runtime's telemetry channel. + * + * The runtime attributes a `reportSpans` payload from its content, and only + * payloads composed of a SINGLE trace that belongs to a currently-active + * request are reliably persisted end to end. Mixed-trace payloads (the OTel + * BatchSpanProcessor queue is shared by every concurrent request on the + * instance, so its flushes ship whatever is queued) used to be dropped whole + * or misfiled depending on which span happened to sit first in the batch. + * + * So this exporter enforces strict per-trace payload discipline, streaming + * spans out as they are flushed: + * + * - Every incoming span is grouped by ITS OWN trace id, and each trace's + * spans ship as their own single-trace payload. Traces are never mixed + * into one payload, so one stale span can no longer poison other traces' + * delivery. + * - Spans ship EAGERLY on every flush, through the telemetry channel of the + * context captured for their trace (see + * `registerVercelRequestContextForTrace`), falling back to the ambient + * context for untracked traces. This bounds client memory on long + * invocations and gets spans out of the process while the run is still + * executing. + * - Spans with no reachable telemetry channel are buffered per trace + * (bounded) and retried on the next flush; the trace's final flush + * (`finalizeTrace`, from the owning request's `waitUntil`) ships whatever + * is left instead of silently dropping it. + */ export class VercelRuntimeSpanExporter implements SpanExporter { + private readonly traceBuffers = new Map(); + private droppedSpansCount = 0; + /** + * Opt-in streaming mode (`VERCEL_OTEL_STREAM_SPANS=1`): ship every trace's + * spans on every flush instead of accumulating until the trace's final + * flush. NOTE: today the platform drops full-size trace chunks that the + * runtime forwards mid-response, so streamed spans of long traces are + * lost past the runtime's chunk threshold; keep this OFF until that is + * fixed. Default (off) accumulates per trace and ships once at + * `finalizeTrace`, which is reliable end to end. + */ + private readonly streamSpans = + process.env.VERCEL_OTEL_STREAM_SPANS === "1"; + + constructor() { + onTraceFinalize((traceId) => this.shipTrace(traceId)); + } + export( spans: ReadableSpan[], resultCallback: (result: ExportResult) => void, ): void { - const context = getVercelRequestContext(); - if (!context?.telemetry) { - diag.warn("@vercel/otel: no telemetry context found"); - resultCallback({ code: ExportResultCode.SUCCESS, error: undefined }); - return; + // Group incoming spans per trace (strict: traces never share a payload). + for (const span of spans) { + this.bufferForTrace(span.spanContext().traceId, span); } try { - const serializedData = JsonTraceSerializer.serializeRequest(spans); - - if (!serializedData) { - throw new Error("Failed to serialize spans"); + for (const traceId of Array.from(this.traceBuffers.keys())) { + if (this.streamSpans || !getVercelRequestContextForTrace(traceId)) { + // Streaming mode ships everything on every flush. Accumulate mode + // (default) keeps registered traces buffered until their + // finalizeTrace, and only ships untracked traces (no owning + // request captured, e.g. spans created outside an instrumented + // request) now via the ambient context. + this.shipTrace(traceId); + } } - // Convert back to object format for the Vercel telemetry API - const data = JSON.parse( - new TextDecoder().decode(serializedData), - ) as IExportTraceServiceRequest; - - context.telemetry.reportSpans(data); resultCallback({ code: ExportResultCode.SUCCESS, error: undefined }); } catch (e) { resultCallback({ @@ -38,6 +93,74 @@ export class VercelRuntimeSpanExporter implements SpanExporter { } } + /** + * Ship a trace's buffered spans as a single-trace payload through the + * telemetry channel of the context that owns the trace (captured at root + * span start), falling back to the ambient context. Leaves the spans + * buffered when no channel is reachable (they retry on the next flush and + * at `finalizeTrace`). + */ + private shipTrace(traceId: string): void { + const spans = this.traceBuffers.get(traceId); + if (!spans || spans.length === 0) { + this.traceBuffers.delete(traceId); + return; + } + const context = + getVercelRequestContextForTrace(traceId) ?? getVercelRequestContext(); + if (!context?.telemetry) { + // No reachable channel right now (e.g. a bare-setTimeout timer flush + // for an untracked trace). Keep the spans buffered for a later flush + // instead of silently dropping them. + diag.debug( + `@vercel/otel: no telemetry context for trace ${traceId}; keeping ${spans.length} span(s) buffered`, + ); + return; + } + this.traceBuffers.delete(traceId); + try { + reportSpans(context.telemetry, spans); + } catch (e) { + // Put them back so the next flush or the trace's finalize retries. + this.retainForTrace(traceId, spans); + diag.warn("@vercel/otel: failed to report spans, retained:", e); + } + } + + private bufferForTrace(traceId: string, span: ReadableSpan): void { + let buffer = this.traceBuffers.get(traceId); + if (!buffer) { + buffer = []; + this.traceBuffers.set(traceId, buffer); + } + buffer.push(span); + this.enforceCap(buffer); + } + + private retainForTrace(traceId: string, spans: ReadableSpan[]): void { + const buffer = this.traceBuffers.get(traceId); + if (buffer) { + // Newer spans may have been buffered while we were shipping; keep + // start-order by prepending the failed batch. + buffer.unshift(...spans); + this.enforceCap(buffer); + } else { + this.traceBuffers.set(traceId, spans); + this.enforceCap(spans); + } + } + + private enforceCap(buffer: ReadableSpan[]): void { + const overflow = buffer.length - MAX_TRACE_BUFFER_SIZE; + if (overflow > 0) { + buffer.splice(0, overflow); + this.droppedSpansCount += overflow; + diag.warn( + `@vercel/otel: trace span buffer full, dropped ${this.droppedSpansCount} span(s) total`, + ); + } + } + shutdown(): Promise { return Promise.resolve(); } @@ -46,3 +169,21 @@ export class VercelRuntimeSpanExporter implements SpanExporter { return Promise.resolve(); } } + +function reportSpans( + telemetry: NonNullable | undefined, + spans: ReadableSpan[], +): void { + if (!telemetry) { + throw new Error("no telemetry channel"); + } + const serializedData = JsonTraceSerializer.serializeRequest(spans); + if (!serializedData) { + throw new Error("Failed to serialize spans"); + } + // Convert back to object format for the Vercel telemetry API + const data = JSON.parse( + new TextDecoder().decode(serializedData), + ) as IExportTraceServiceRequest; + telemetry.reportSpans(data); +}