diff --git a/.changeset/node-before-span-send.md b/.changeset/node-before-span-send.md new file mode 100644 index 0000000000..8d2afd5521 --- /dev/null +++ b/.changeset/node-before-span-send.md @@ -0,0 +1,7 @@ +--- +'posthog-node': minor +'@posthog/core': minor +'@posthog/types': minor +--- + +Add a `traces.beforeSpanSend` hook to edit a finished span before it is queued, or drop it by returning `null` — a hook that throws, or returns anything that is not a span record, also drops the span. diff --git a/.changeset/node-exception-stacktrace.md b/.changeset/node-exception-stacktrace.md new file mode 100644 index 0000000000..e4cfa02136 --- /dev/null +++ b/.changeset/node-exception-stacktrace.md @@ -0,0 +1,7 @@ +--- +'posthog-node': minor +'@posthog/core': minor +'@posthog/types': minor +--- + +Attach `exception.stacktrace` to the exception events recorded by `recordException` and by a throwing `withSpan` callback — remove it in `traces.beforeSpanSend` to keep your server's file paths out of PostHog. diff --git a/.changeset/node-span-limits.md b/.changeset/node-span-limits.md new file mode 100644 index 0000000000..fbe06127fc --- /dev/null +++ b/.changeset/node-span-limits.md @@ -0,0 +1,7 @@ +--- +'posthog-node': minor +'@posthog/core': minor +'@posthog/types': minor +--- + +Cap spans at 128 user attributes, 128 events and 8192 characters per string, configurable with `traces.maxAttributesPerSpan`, `traces.maxEventsPerSpan` and `traces.maxAttributeValueLength`. The earliest entries are kept, and a span that lost any reports how many as `droppedAttributesCount` and `droppedEventsCount`. The event cap is absolute, so an `exception` event the SDK records for you spends an ordinary slot. diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index 8a3aad8015..dfe61ff460 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -92,6 +92,9 @@ export { SyncSpanContextManager } from './traces/context' export { inertSpan, runWithActiveSpan } from './traces/span' export { resolveTracesConfig } from './traces/config' export type { ResolvedTracesConfig, SpanContextManager, TraceSdkContext } from './traces/types' +// The `beforeSpanSend` shapes come straight from @posthog/types: hooks see the +// public record, not core's internal one, which also carries `traceState`. +export type { SpanRecord, BeforeSpanSendFn } from '@posthog/types' // Same barrel convention as logs and metrics for the user-facing tracing types. export type { Span, diff --git a/packages/core/src/traces/config.spec.ts b/packages/core/src/traces/config.spec.ts index 902e5f35f5..5237a0d52d 100644 --- a/packages/core/src/traces/config.spec.ts +++ b/packages/core/src/traces/config.spec.ts @@ -1,16 +1,53 @@ +import { createMockLogger } from '@/testing' import { resolveTracesConfig } from './config' describe('resolveTracesConfig', () => { + it.each([ + ['zero', 0], + ['negative', -1], + ['not a number', NaN], + // Floored, these read as 1, 2 and 3 — caps an order of magnitude below what + // the caller wrote, applied silently. + ['a fraction', 1.5], + ['a large fraction', 200.5], + ['infinity', Infinity], + ])('falls back to the default per-span caps when given %s', (_label, value) => { + const resolved = resolveTracesConfig({ + maxAttributesPerSpan: value, + maxEventsPerSpan: value, + maxAttributeValueLength: value, + }) + expect(resolved.maxAttributesPerSpan).toBe(128) + expect(resolved.maxEventsPerSpan).toBe(128) + expect(resolved.maxAttributeValueLength).toBe(8192) + }) + + it('honours explicit per-span caps', () => { + // Without this the resolver can ignore maxEventsPerSpan entirely and every + // other test still passes, because they all assert the default. + expect(resolveTracesConfig({ maxAttributesPerSpan: 5, maxEventsPerSpan: 7 })).toMatchObject({ + maxAttributesPerSpan: 5, + maxEventsPerSpan: 7, + }) + }) + it('applies the documented defaults', () => { expect(resolveTracesConfig(undefined)).toMatchObject({ flushIntervalMs: 5000, maxExportBatchSize: 512, maxQueueSize: 2048, + maxAttributesPerSpan: 128, + maxEventsPerSpan: 128, + maxAttributeValueLength: 8192, maxLiveSpans: 10_000, maxSpanAgeMs: 3_600_000, }) }) + it('honours an explicit attribute value bound', () => { + expect(resolveTracesConfig({ maxAttributeValueLength: 256 }).maxAttributeValueLength).toBe(256) + }) + it('honours explicit live-span bounds', () => { expect(resolveTracesConfig({ maxLiveSpans: 50, maxSpanAgeMs: 30_000 })).toMatchObject({ maxLiveSpans: 50, @@ -65,14 +102,23 @@ describe('resolveTracesConfig', () => { } ) - it('floors a fractional batch size to an integer', () => { - expect(resolveTracesConfig({ maxExportBatchSize: 10.9 }).maxExportBatchSize).toBe(10) + it('takes the default for a fractional batch size rather than flooring it', () => { + // Every numeric knob resolves the same way, so a fraction is a value the + // caller did not mean rather than one to round down behind their back. + expect(resolveTracesConfig({ maxExportBatchSize: 10.9 }).maxExportBatchSize).toBe(512) }) - it.each([0, -1, Number.NaN])('falls back to the default for an unusable flushIntervalMs (%p)', (value) => { + it.each([0, -1, 1.5, Number.NaN])('falls back to the default for an unusable flushIntervalMs (%p)', (value) => { expect(resolveTracesConfig({ flushIntervalMs: value }).flushIntervalMs).toBe(5000) }) + it.each([0.5, 10_000.5])('falls back to the defaults for fractional live-span bounds (%p)', (value) => { + expect(resolveTracesConfig({ maxLiveSpans: value, maxSpanAgeMs: value })).toMatchObject({ + maxLiveSpans: 10_000, + maxSpanAgeMs: 3_600_000, + }) + }) + it('keeps the queue at least as large as the export batch', () => { // A queue smaller than the flush trigger would stop the depth-based flush // from ever firing. @@ -135,6 +181,50 @@ describe('resourceAttributes guarding', () => { expect(resolved.resourceAttributes).toEqual({ region: 'us' }) }) + it('ignores a beforeSpanSend entry that is not a function', () => { + // A plain-JS caller passing the wrong shape would otherwise have every span + // dropped by a hook that throws on call, with tracing silently off. + const scrub = (span: any): any => span + const resolved = resolveTracesConfig({ beforeSpanSend: ['not a function', scrub] as never }) + + expect(resolved.beforeSpanSend).toEqual([scrub]) + }) + + it('warns about a dropped hook, since the redaction it was configured for is gone', () => { + const logger = createMockLogger() + const scrub = (span: any): any => span + + resolveTracesConfig({ beforeSpanSend: ['not a function', scrub] as never }, undefined, logger) + + // `critical`, not `warn`: every other level is gated behind `debug: true`. + expect(logger.critical).toHaveBeenCalledWith(expect.stringContaining('ignoring 1 of 2 entries')) + }) + + it('stays quiet for a conditionally disabled hook', () => { + // `[featureEnabled && scrub]` is ordinary JS; nothing was configured to + // redact, so claiming redaction is broken would be false alarm. + const logger = createMockLogger() + + const resolved = resolveTracesConfig({ beforeSpanSend: [false, null, undefined] as never }, undefined, logger) + + expect(resolved.beforeSpanSend).toEqual([]) + expect(logger.critical).not.toHaveBeenCalled() + }) + + it('stays quiet when every hook is callable', () => { + const logger = createMockLogger() + + resolveTracesConfig({ beforeSpanSend: [(span: any): any => span] }, undefined, logger) + + expect(logger.critical).not.toHaveBeenCalled() + }) + + it('resolves to no hooks when beforeSpanSend is the wrong type entirely', () => { + const resolved = resolveTracesConfig({ beforeSpanSend: { scrub: true } as never }) + + expect(resolved.beforeSpanSend).toEqual([]) + }) + it('does not throw when an identity accessor throws', () => { const hostile = {} Object.defineProperty(hostile, 'service.name', { diff --git a/packages/core/src/traces/config.ts b/packages/core/src/traces/config.ts index 4cec80a594..dc60973a43 100644 --- a/packages/core/src/traces/config.ts +++ b/packages/core/src/traces/config.ts @@ -1,12 +1,22 @@ import { assignUserAttributes } from '../utils/json-utils' import type { ResolvedTracesConfig } from './types' -import type { TracesConfig } from '@posthog/types' +import type { BeforeSpanSendFn, TracesConfig } from '@posthog/types' +import type { Logger } from '../types' // OpenTelemetry's BatchSpanProcessor defaults, which sit comfortably under the // server's 2 MB body cap. const DEFAULT_FLUSH_INTERVAL_MS = 5000 const DEFAULT_MAX_EXPORT_BATCH_SIZE = 512 const DEFAULT_MAX_QUEUE_SIZE = 2048 +// OpenTelemetry's per-span defaults. +const DEFAULT_MAX_ATTRIBUTES_PER_SPAN = 128 +const DEFAULT_MAX_EVENTS_PER_SPAN = 128 +// OpenTelemetry leaves the value length unlimited, which is what lets one +// multi-MB attribute make a span too large for the endpoint to accept — and an +// oversized span is dropped whole. 8 KB holds a deep stack trace and any +// realistic header, query string or payload excerpt, and keeps a span at the +// attribute cap under 1 MB, comfortably inside the 2 MB body cap. +const DEFAULT_MAX_ATTRIBUTE_VALUE_LENGTH = 8192 // Live-span bounds. A server can legitimately hold thousands of spans open at // once, and refusing a legitimate span is worse than tolerating a leak, so the @@ -20,9 +30,13 @@ const DEFAULT_MAX_SPAN_AGE_MS = 3_600_000 /** * Coerces a caller-supplied positive-integer option. `0`, a negative, or `NaN` * reaching the export loop would stall it. + * + * A fraction takes the default rather than being floored: these are documented + * as positive integers, and silently reading `maxAttributesPerSpan: 1.5` as `1` + * caps a span an order of magnitude below what the caller wrote. */ function positiveInteger(value: number | undefined, fallback: number): number { - return typeof value === 'number' && Number.isFinite(value) && value >= 1 ? Math.floor(value) : fallback + return typeof value === 'number' && Number.isInteger(value) && value >= 1 ? value : fallback } const IDENTITY_KEYS = ['service.name', 'service.version', 'deployment.environment'] as const @@ -54,6 +68,36 @@ function withUsableIdentityKeys(attributes: TracesConfig['resourceAttributes']): } } +/** + * Keeps only the callable hooks. Anything else is dropped rather than called: an + * untyped caller passing the wrong shape would otherwise have every span dropped + * by a hook that throws, leaving tracing silently off. + * + * Dropping one is reported rather than thrown on. `beforeSpanSend` is where + * redaction lives, so a configuration that silently filters nothing ships the + * values it was meant to remove — but a client constructor that throws takes the + * application down with it, which is the worse of the two. `critical`, because + * every other level is gated behind `debug: true`, and a redaction hook that is + * quietly inert is exactly what an operator has to hear about without opting in. + */ +function resolveBeforeSpanSend(beforeSpanSend: TracesConfig['beforeSpanSend'], logger?: Logger): BeforeSpanSendFn[] { + if (!beforeSpanSend) { + return [] + } + // `[featureEnabled && scrub]` is ordinary JS, and a caller who wrote it did not + // configure a hook at all — only a value that was meant to be one is worth + // shouting about. + const supplied = [beforeSpanSend].flat().filter((hook) => Boolean(hook)) + const hooks = supplied.filter((hook): hook is BeforeSpanSendFn => typeof hook === 'function') + if (hooks.length !== supplied.length) { + logger?.critical( + `beforeSpanSend: ignoring ${supplied.length - hooks.length} of ${supplied.length} entries that are not functions. ` + + 'Spans export without them, so whatever they were redacting is not redacted.' + ) + } + return hooks +} + /** * Resolves the public `traces` config into the shape core `PostHogTraces` consumes. * OTLP resource attributes take precedence over the named fields, matching the @@ -62,7 +106,8 @@ function withUsableIdentityKeys(attributes: TracesConfig['resourceAttributes']): */ export function resolveTracesConfig( config: TracesConfig | undefined, - hostResourceAttributes?: Record + hostResourceAttributes?: Record, + logger?: Logger ): ResolvedTracesConfig { // Copied key by key rather than spread: a throwing accessor on a user-supplied // attribute would otherwise escape the first `startSpan`. @@ -76,6 +121,10 @@ export function resolveTracesConfig( serviceVersion: (resourceAttributes?.['service.version'] as string | undefined) ?? config?.serviceVersion, environment: (resourceAttributes?.['deployment.environment'] as string | undefined) ?? config?.environment, resourceAttributes, + beforeSpanSend: resolveBeforeSpanSend(config?.beforeSpanSend, logger), + maxAttributesPerSpan: positiveInteger(config?.maxAttributesPerSpan, DEFAULT_MAX_ATTRIBUTES_PER_SPAN), + maxEventsPerSpan: positiveInteger(config?.maxEventsPerSpan, DEFAULT_MAX_EVENTS_PER_SPAN), + maxAttributeValueLength: positiveInteger(config?.maxAttributeValueLength, DEFAULT_MAX_ATTRIBUTE_VALUE_LENGTH), flushIntervalMs: positiveInteger(config?.flushIntervalMs, DEFAULT_FLUSH_INTERVAL_MS), maxExportBatchSize, // Never below the flush trigger, or the depth-based flush could never fire. diff --git a/packages/core/src/traces/index.spec.ts b/packages/core/src/traces/index.spec.ts index a6d5aeb4a5..0712ea99f8 100644 --- a/packages/core/src/traces/index.spec.ts +++ b/packages/core/src/traces/index.spec.ts @@ -6,6 +6,7 @@ import type { OtlpTracesPayload, ResolvedTracesConfig, SendTracesBatchOutcome, + SpanRecord, TraceSdkContext, } from './types' import type { Logger } from '../types' @@ -18,6 +19,10 @@ const resolveForTest = (partial?: Partial): ResolvedTraces flushIntervalMs: 5000, maxExportBatchSize: 512, maxQueueSize: 2048, + beforeSpanSend: [], + maxAttributesPerSpan: 128, + maxEventsPerSpan: 128, + maxAttributeValueLength: 8192, maxLiveSpans: 10000, maxSpanAgeMs: 3600000, ...partial, @@ -376,6 +381,7 @@ describe('PostHogTraces', () => { attributes: [ { key: 'exception.type', value: { stringValue: 'TypeError' } }, { key: 'exception.message', value: { stringValue: 'boom' } }, + { key: 'exception.stacktrace', value: { stringValue: expect.stringContaining('TypeError: boom') } }, ], }) }) @@ -657,6 +663,1048 @@ describe('PostHogTraces', () => { }) }) + describe('reset', () => { + it('says so when it discards queued spans', async () => { + // Terminal loss: there is no next flush to retry on, and the export + // failure the caller already saw promises one. + const instance = createMockInstance({ + _sendTracesBatch: vi.fn(() => Promise.resolve({ kind: 'retry-later' as const, error: new Error('down') })), + }) + const traces = createTraces({}, instance) + traces.startSpan('a').end() + traces.startSpan('b').end() + await traces.flush() + + traces.reset() + + expect(logger.critical).toHaveBeenCalledWith(expect.stringContaining('Discarding 2 span(s)')) + }) + + it('stays quiet when nothing was queued', () => { + const traces = createTraces() + + traces.reset() + + expect(logger.critical).not.toHaveBeenCalled() + }) + }) + + describe('flush reentrancy', () => { + it('does not re-send the head batch when a span ends during the flush prefix', async () => { + // `_flushInner` runs synchronously as far as its first await, and it reads + // the resource attributes in that window. A getter there that ends a span + // used to re-enter the flush with no pass yet recorded, and the same head + // batch went out again on every pass — thousands of times, unbounded. + const resourceAttributes: Record = {} + Object.defineProperty(resourceAttributes, 'tenant', { + enumerable: true, + // Reads `traces` only when a flush runs, which is after it is assigned. + get: () => { + traces.startSpan('late').end() + return 'acme' + }, + }) + const instance = createMockInstance() + const traces = createTraces({ maxExportBatchSize: 2, resourceAttributes }, instance) + + traces.startSpan('a').end() + traces.startSpan('b').end() + await traces.flush() + await traces.flush() + + expect(sentPayloads(instance)).toHaveLength(2) + expect(sentSpans(instance).map((s) => s.name)).toEqual(['a', 'b', 'late']) + }) + }) + + describe('beforeSpanSend', () => { + const endOneSpan = (beforeSpanSend: any): PostHogTraces => { + const traces = createTraces({ beforeSpanSend: [beforeSpanSend].flat() }) + traces.startSpan('checkout', { attributes: { userId: 42 } }).end() + return traces + } + + it('drops a span when the hook returns null', async () => { + await endOneSpan(() => null).flush() + expect(sentSpans()).toHaveLength(0) + }) + + it('drops the span when the hook throws', async () => { + await endOneSpan(() => { + throw new Error('scrubber broke') + }).flush() + + expect(sentSpans()).toHaveLength(0) + expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('beforeSpanSend failed'), expect.anything()) + }) + + it('counts a span the hook dropped', async () => { + await endOneSpan(() => null).flush() + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('beforeSpanSend dropped it')) + }) + + it('counts a span dropped because the hook threw', async () => { + // A permanently broken scrubber otherwise drops every span with the drop + // counter reading zero. + await endOneSpan(() => { + throw new Error('scrubber broke') + }).flush() + + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('beforeSpanSend failed')) + }) + + it('hands the hook plain values, not the OTLP encoding', () => { + const seen: unknown[] = [] + endOneSpan((span: SpanRecord) => { + seen.push(span.attributes.userId) + return span + }) + + expect(seen).toEqual([42]) + }) + + it('keeps the original ids when a hook rewrites them', async () => { + const traces = createTraces({ + beforeSpanSend: [ + (span: any) => { + span.traceId = '0'.repeat(32) + span.spanId = '1'.repeat(16) + return span + }, + ], + }) + const started = traces.startSpan('checkout') + const originalTraceId = started.traceparent()!.split('-')[1] + started.end() + await traces.flush() + + const [span] = sentSpans() + expect(span.traceId).toBe(originalTraceId) + expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('identity field')) + }) + + it('exports a span whose record the hook froze', async () => { + // A defensive hook may freeze what it returns. Assigning to a frozen + // property throws even when the value is the one already there, so the + // post-hook pass works on a copy — otherwise every span the hook saw is + // dropped by the fail-closed branch, with only a debug line to say so. + const traces = createTraces({ + beforeSpanSend: [(span: SpanRecord) => Object.freeze({ ...span, attributes: { route: '/checkout' } })], + }) + const span = traces.startSpan('checkout') + + expect(() => span.end()).not.toThrow() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['route']) + }) + + it('exports a span whose attributes the hook froze', async () => { + const traces = createTraces({ + maxAttributesPerSpan: 1, + beforeSpanSend: [ + (span: SpanRecord) => ({ ...span, attributes: Object.freeze({ route: '/checkout', extra: 1 }) as never }), + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['route']) + expect(sent.droppedAttributesCount).toBe(1) + }) + + it('rejects a timestamp the server could not decode', async () => { + const instance = createMockInstance() + const traces = createTraces( + { beforeSpanSend: [(span: SpanRecord) => ({ ...span, startTime: span.startTime * 1e6 })] }, + instance + ) + traces.startSpan('poison').end() + await traces.flush() + + const [span] = sentSpans(instance) + expect(span.startTimeUnixNano.length).toBeLessThanOrEqual(19) + }) + + it('keeps tracestate a rebuilding hook would have dropped', async () => { + const instance = createMockInstance() + const traces = createTraces( + { beforeSpanSend: [(span: SpanRecord) => ({ ...span, traceState: undefined }) as SpanRecord] }, + instance + ) + traces.startSpan('child', { parent: `00-${TRACE_ID}-${REMOTE_SPAN_ID}-01`, tracestate: 'vendor=abc' }).end() + await traces.flush() + + expect(sentSpans(instance)[0].traceState).toBe('vendor=abc') + }) + + it('keeps the trace flags and parent remoteness a rebuilding hook would have dropped', async () => { + const instance = createMockInstance() + const traces = createTraces({ beforeSpanSend: [(span: SpanRecord) => ({ ...span }) as SpanRecord] }, instance) + traces.startSpan('child', { parent: `00-${TRACE_ID}-${REMOTE_SPAN_ID}-00` }).end() + await traces.flush() + + // Sampled-out inbound flag, plus both remoteness bits for a header parent. + expect(sentSpans(instance)[0].flags).toBe(0x300) + }) + + it('keeps them when the hook builds its record from the fields it can see', async () => { + // Spreading carries the propagation fields through even though no public + // type declares them; naming the public fields is what drops them. + const instance = createMockInstance() + const traces = createTraces( + { + beforeSpanSend: [ + (span: SpanRecord) => + ({ + traceId: span.traceId, + spanId: span.spanId, + parentSpanId: span.parentSpanId, + name: span.name, + kind: span.kind, + status: span.status, + attributes: span.attributes, + events: span.events, + startTime: span.startTime, + endTime: span.endTime, + }) as SpanRecord, + ], + }, + instance + ) + traces.startSpan('child', { parent: `00-${TRACE_ID}-${REMOTE_SPAN_ID}-00` }).end() + await traces.flush() + + expect(sentSpans(instance)[0].flags).toBe(0x300) + }) + + it('keeps them when the rebuilding hook also freezes what it returns', async () => { + // Restoring these onto the returned record would throw here, and a throwing + // hook drops the span. + const instance = createMockInstance() + const traces = createTraces( + { beforeSpanSend: [(span: SpanRecord) => Object.freeze({ ...span }) as SpanRecord] }, + instance + ) + traces.startSpan('child', { parent: `00-${TRACE_ID}-${REMOTE_SPAN_ID}-00` }).end() + await traces.flush() + + expect(sentSpans(instance).map((s) => s.flags)).toEqual([0x300]) + }) + + it('does not resurrect a prototype-named attribute the hook removed', async () => { + // `key in attributes` walks the prototype chain, so a deleted `constructor` + // read back as the inherited function and shipped as [Function]. + const instance = createMockInstance() + const traces = createTraces( + { + beforeSpanSend: [ + (span: SpanRecord) => { + delete (span.attributes as Record).constructor + return span + }, + ], + }, + instance + ) + const span = traces.startSpan('ghost') + span.setAttribute('constructor', 'user-value') + span.setAttribute('safe', 'ok') + span.end() + await traces.flush() + + expect(sentSpans(instance)[0].attributes.map((a) => a.key)).toEqual(['safe']) + }) + + it('does not let prototype-named ghosts evict what the hook kept', async () => { + // Worse than resurrection: at the cap the ghosts won the slots and the + // attribute the hook deliberately kept was the one dropped. + const instance = createMockInstance() + const traces = createTraces( + { + maxAttributesPerSpan: 2, + beforeSpanSend: [(span: SpanRecord) => ({ ...span, attributes: { onlyThis: 'yes' } }) as SpanRecord], + }, + instance + ) + const span = traces.startSpan('ghosts') + span.setAttribute('toString', 1) + span.setAttribute('valueOf', 2) + span.end() + await traces.flush() + + expect(sentSpans(instance)[0].attributes.map((a) => a.key)).toEqual(['onlyThis']) + }) + + it('keeps the earliest-set attributes when the hook adds an integer-like key', async () => { + // Object.keys hoists integer-like keys whatever the write order, so a key + // the hook added last outranked one the caller set before it ran. + const instance = createMockInstance() + const traces = createTraces( + { + maxAttributesPerSpan: 3, + beforeSpanSend: [ + (span: SpanRecord) => { + span.attributes['0'] = 'added-last' + return span + }, + ], + }, + instance + ) + const span = traces.startSpan('ordered') + span.setAttribute('alpha', 1) + span.setAttribute('beta', 2) + span.setAttribute('gamma', 3) + span.end() + await traces.flush() + + expect(sentSpans(instance)[0].attributes.map((a) => a.key)).toEqual(['alpha', 'beta', 'gamma']) + }) + + it('ignores a forged identity from a frozen hook rather than dropping the span', async () => { + // Writing the id back onto a frozen return throws, and a throwing hook + // drops the span, so forging plus freezing used to lose every span. + const instance = createMockInstance() + const traces = createTraces( + { beforeSpanSend: [(span: SpanRecord) => Object.freeze({ ...span, traceId: '0'.repeat(32) }) as SpanRecord] }, + instance + ) + traces.startSpan('forged').end() + await traces.flush() + + expect(sentSpans(instance)).toHaveLength(1) + expect(sentSpans(instance)[0].traceId).not.toBe('0'.repeat(32)) + expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('keeping the original ids')) + }) + + it('exports a child span whose record a frozen hook rebuilt without the parent id', async () => { + // The shape that loses children but keeps roots: a rebuilt record has no + // parentSpanId to match, so restoring it wrote to a frozen object. + const instance = createMockInstance() + const traces = createTraces( + { + beforeSpanSend: [ + (span: SpanRecord) => + Object.freeze({ + traceId: span.traceId, + spanId: span.spanId, + name: span.name, + kind: span.kind, + attributes: span.attributes, + events: span.events, + startTime: span.startTime, + endTime: span.endTime, + }) as SpanRecord, + ], + }, + instance + ) + const root = traces.startSpan('root') + traces.startSpan('child', { parent: root }).end() + root.end() + await traces.flush() + + expect( + sentSpans(instance) + .map((s) => s.name) + .sort() + ).toEqual(['child', 'root']) + }) + + it('runs hooks left to right and stops at the first null', async () => { + const order: string[] = [] + await endOneSpan([ + (span: SpanRecord) => { + order.push('first') + return span + }, + () => { + order.push('second') + return null + }, + (span: SpanRecord) => { + order.push('third') + return span + }, + ]).flush() + + expect(order).toEqual(['first', 'second']) + expect(sentSpans()).toHaveLength(0) + }) + + it('exports the edits a hook made', async () => { + await endOneSpan((span: SpanRecord) => { + delete span.attributes.userId + span.name = 'redacted' + return span + }).flush() + + const [span] = sentSpans() + expect(span.name).toBe('redacted') + expect(span.attributes?.find((attribute) => attribute.key === 'userId')).toBeUndefined() + }) + }) + + describe('beforeSpanSend validity', () => { + it('sanitises an event the hook pushed without a timestamp', async () => { + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + span.events.push({ name: 'audited' } as never) + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + const [event] = sentSpans()[0].events! + expect(event.name).toBe('audited') + expect(event.timeUnixNano).toMatch(/^\d+$/) + }) + + it('clamps an out-of-range timestamp on a hook-supplied event', async () => { + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + span.events.push({ name: 'audited', timestamp: -1 } as never) + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()[0].events![0].timeUnixNano).toMatch(/^\d+$/) + }) + + it('bounds a status message the hook rewrote', async () => { + const traces = createTraces({ + maxAttributeValueLength: 4, + beforeSpanSend: [ + (span) => { + span.status = { code: 'error', message: 'abcdefgh' } + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()[0].status).toEqual({ code: 2, message: 'abcd' }) + }) + + it('keeps the original status when the hook writes an unknown code', async () => { + // An unknown code maps to nothing and encodes as an empty status object, + // which silently loses an error the span really had. + const traces = createTraces({ + beforeSpanSend: [(span) => ({ ...span, status: { code: 'ERROR' as never, message: 'boom' } })], + }) + const span = traces.startSpan('checkout') + span.setStatus('error', 'boom') + span.end() + await traces.flush() + + expect(sentSpans()[0].status).toEqual({ code: 2, message: 'boom' }) + }) + + it('ignores a dropped count the hook invented', async () => { + const traces = createTraces({ + beforeSpanSend: [(span) => ({ ...span, droppedAttributesCount: 'lots' as never })], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()[0].droppedAttributesCount).toBeUndefined() + }) + + it('lets a hook scrub the auto-context keys', async () => { + // The exemption is from the count cap only. A hook is the documented + // scrubbing point, so it has to be able to remove the join keys as well. + context = { distinctId: 'user-1', sessionId: 'session-1' } + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + delete span.attributes.posthogDistinctId + delete span.attributes.sessionId + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()[0].attributes).toBeUndefined() + }) + + it('keeps the error status when the event cap costs the exception event', async () => { + // The status is set independently of the event, so a span whose exception + // event did not fit still exports as failed and still counts the loss. + // That pair is what makes the case findable once traces is live. + const traces = createTraces({ + maxEventsPerSpan: 1, + beforeSpanSend: [ + (span) => { + span.events.push({ name: 'audited', timestamp: Date.now() }) + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('step') + span.recordException(new Error('boom')) + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.events!.map((event) => event.name)).toEqual(['step']) + expect(sent.droppedEventsCount).toBe(2) + expect(sent.status).toEqual({ code: 2, message: 'boom' }) + }) + + it('keeps the original status when the hook mutates the code in place', async () => { + // The hook is documented as editing the record in place, so snapshotting a + // reference to `status` would restore the mutation onto itself. + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + ;(span.status as { code: string }).code = 'ERROR' + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.setStatus('error', 'boom') + span.end() + await traces.flush() + + expect(sentSpans()[0].status).toEqual({ code: 2, message: 'boom' }) + }) + + it('exports a span whose record is a class instance with prototype getters', async () => { + // A spread copies own properties only, so `events` behind a prototype + // getter arrived undefined and the fail-closed branch ate every span. + class Wrapped { + constructor(private readonly _inner: SpanRecord) {} + get traceId(): string { + return this._inner.traceId + } + get spanId(): string { + return this._inner.spanId + } + get name(): string { + return this._inner.name + } + get kind(): SpanRecord['kind'] { + return this._inner.kind + } + get attributes(): SpanRecord['attributes'] { + return this._inner.attributes + } + get events(): SpanRecord['events'] { + return this._inner.events + } + get startTime(): number { + return this._inner.startTime + } + get endTime(): number { + return this._inner.endTime + } + } + const traces = createTraces({ + beforeSpanSend: [(span: SpanRecord) => new Wrapped(span) as unknown as SpanRecord], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans().map((span) => span.name)).toEqual(['checkout']) + }) + + it('survives a hook that leaves a hole in the events array', async () => { + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + span.events.length = 2 + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('step') + span.end() + await traces.flush() + + expect(sentSpans()[0].events!.map((event) => event.name)).toEqual(['step']) + }) + + it('keeps the span-side dropped count when the hook overwrites the counter', async () => { + const traces = createTraces({ + maxEventsPerSpan: 1, + beforeSpanSend: [ + (span) => { + ;(span as unknown as { droppedEventsCount: unknown }).droppedEventsCount = 'lots' + span.events.push({ name: 'audited', timestamp: Date.now() }) + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('step-0') + span.addEvent('step-1') + span.end() + await traces.flush() + + // One dropped at the span, one by the post-hook re-apply. + expect(sentSpans()[0].droppedEventsCount).toBe(2) + }) + + it('drops only the event the hook made unreadable', async () => { + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + span.events = [span.events[0], null as never, span.events[1]] + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('step-0') + span.addEvent('step-1') + span.end() + await traces.flush() + + expect(sentSpans()[0].events!.map((event) => event.name)).toEqual(['step-0', 'step-1']) + }) + + it.each([ + ['attributes replaced with null', (span: SpanRecord) => ({ ...span, attributes: null as never })], + ['attributes replaced with an array', (span: SpanRecord) => ({ ...span, attributes: ['a'] as never })], + ['events replaced with null', (span: SpanRecord) => ({ ...span, events: null as never })], + ['an async hook returning a promise', (span: SpanRecord) => Promise.resolve(span) as never], + // Carrying both collections was the whole shape check, so these reached + // the wire as a span named `unknown` at a fallback time with no join keys. + ['only the two collections', () => ({ attributes: {}, events: [] }) as never], + ['no name', (span: SpanRecord) => ({ ...span, name: undefined as never })], + ['no kind', (span: SpanRecord) => ({ ...span, kind: undefined as never })], + ['no start time', (span: SpanRecord) => ({ ...span, startTime: undefined as never })], + ['no end time', (span: SpanRecord) => ({ ...span, endTime: undefined as never })], + ])('drops the span when the hook returns %s', async (_label, beforeSpanSend) => { + // Repairing these would export a nameless span carrying no join keys. + const traces = createTraces({ beforeSpanSend: [beforeSpanSend] }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()).toHaveLength(0) + }) + + it('counts an incomplete hook result as a drop rather than losing it silently', async () => { + const traces = createTraces({ beforeSpanSend: [() => ({ attributes: {}, events: [] }) as never] }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('beforeSpanSend returned an unusable record')) + }) + + it('still exports a span whose required fields the hook left in place', async () => { + // The shape check reads presence, so an ordinary scrub is untouched by it. + const traces = createTraces({ + beforeSpanSend: [ + (span) => { + delete span.attributes.secret + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { secret: 'shh', keep: 1 } }).end() + await traces.flush() + + expect(sentSpans()).toHaveLength(1) + expect(sentSpans()[0].name).toBe('checkout') + expect(sentSpans()[0].attributes!.map((a) => a.key)).toContain('keep') + expect(sentSpans()[0].attributes!.map((a) => a.key)).not.toContain('secret') + }) + + it('gives a later hook the real identity after an earlier one froze a forged record', async () => { + // The export reads the snapshot either way, but a hook that samples or + // routes on an id must not see one an earlier hook invented. + const seen: { traceId: string; spanId: string }[] = [] + const traces = createTraces({ + beforeSpanSend: [ + (span) => Object.freeze({ ...span, traceId: '0'.repeat(32), spanId: 'f'.repeat(16) }), + (span) => { + seen.push({ traceId: span.traceId, spanId: span.spanId }) + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()).toHaveLength(1) + expect(seen[0].traceId).toBe(sentSpans()[0].traceId) + expect(seen[0].spanId).toBe(sentSpans()[0].spanId) + expect(seen[0].traceId).not.toBe('0'.repeat(32)) + }) + + it('leaves the rest of a frozen forged record readable to the next hook', async () => { + // The corrected view is built from the record's own descriptors, so a hook + // reading anything but identity sees exactly what the previous one returned. + let seen: SpanRecord | undefined + const traces = createTraces({ + beforeSpanSend: [ + (span) => Object.freeze({ ...span, name: 'renamed', traceId: '0'.repeat(32) }), + (span) => { + seen = span + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { keep: 1 } }).end() + await traces.flush() + + expect(seen!.name).toBe('renamed') + expect(seen!.attributes.keep).toBe(1) + expect(Object.keys(seen!)).toContain('name') + expect(sentSpans()[0].name).toBe('renamed') + }) + + it('applies the event cap to what a hook leaves behind', async () => { + // A hook can append events or rewrite them, neither of which goes through + // `addEvent`, so the cap has to be re-applied to whatever it returns. + const traces = createTraces({ + maxEventsPerSpan: 1, + beforeSpanSend: [ + (span) => { + span.events.push({ name: 'exception', timestamp: Date.now() }) + span.events.push({ name: 'appended', timestamp: Date.now() }) + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('step-0') + span.end() + await traces.flush() + + expect(sentSpans()[0].events!.map((event) => event.name)).toEqual(['step-0']) + }) + + it('exports the span when the hook status message refuses to stringify', async () => { + // The encoder downstream only marks the field, so coercing here must not + // be the thing that costs the span. + const traces = createTraces({ + maxAttributeValueLength: 4, + beforeSpanSend: [ + (span) => { + span.status = { + code: 'error', + message: { + toString() { + throw new Error('nope') + }, + } as never, + } + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()).toHaveLength(1) + expect(sentSpans()[0].status?.code).toBe(2) + }) + + it('bounds a non-string status message the hook wrote', async () => { + const traces = createTraces({ + maxAttributeValueLength: 4, + beforeSpanSend: [ + (span) => { + span.status = { code: 'error', message: { toString: () => 'abcdefgh' } as never } + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + expect(sentSpans()[0].status).toEqual({ code: 2, message: 'abcd' }) + }) + + it('does not spend cap budget on a value the hook blanked', async () => { + const traces = createTraces({ + maxAttributesPerSpan: 2, + beforeSpanSend: [ + (span) => { + span.attributes.secret = null + span.attributes.scrubbed = true + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { secret: 'sk-live', route: '/checkout' } }).end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['route', 'scrubbed']) + expect(sent.droppedAttributesCount).toBeUndefined() + }) + }) + + describe('span limits', () => { + it('keeps the earliest attributes and counts the rest', async () => { + const traces = createTraces({ maxAttributesPerSpan: 3 }) + const span = traces.startSpan('checkout') + for (let i = 0; i < 5; i++) { + span.setAttribute(`key-${i}`, i) + } + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['key-0', 'key-1', 'key-2']) + expect(sent.droppedAttributesCount).toBe(2) + }) + + it('re-applies the attribute cap to what beforeSpanSend added', async () => { + const traces = createTraces({ + maxAttributesPerSpan: 2, + beforeSpanSend: [ + (span) => { + for (let i = 0; i < 5; i++) { + span.attributes[`added-${i}`] = i + } + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { kept: true } }).end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['kept', 'added-0']) + expect(sent.droppedAttributesCount).toBe(4) + }) + + it('re-applies the event cap to what beforeSpanSend added', async () => { + const traces = createTraces({ + maxEventsPerSpan: 1, + beforeSpanSend: [ + (span) => { + span.events.push({ name: 'added', timestamp: span.startTime }) + return span + }, + ], + }) + const span = traces.startSpan('checkout') + span.addEvent('original') + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.events!.map((event) => event.name)).toEqual(['original']) + expect(sent.droppedEventsCount).toBe(1) + }) + + it('keeps the auto-context keys when beforeSpanSend pushes past the cap', async () => { + context = { distinctId: 'alice', sessionId: 'session-1' } + const traces = createTraces({ + maxAttributesPerSpan: 1, + beforeSpanSend: [ + (span) => { + span.attributes.late = true + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { early: true } }).end() + await traces.flush() + + const keys = sentSpans()[0].attributes!.map((attribute) => attribute.key) + expect(keys).toEqual(expect.arrayContaining(['posthogDistinctId', 'sessionId', 'early'])) + expect(keys).not.toContain('late') + }) + + it('re-applies the value bound to what beforeSpanSend wrote', async () => { + const traces = createTraces({ + maxAttributeValueLength: 8, + beforeSpanSend: [ + (span) => { + span.attributes.enriched = 'y'.repeat(5000) + span.events.push({ name: 'added', timestamp: span.startTime, attributes: { blob: 'z'.repeat(5000) } }) + return span + }, + ], + }) + traces.startSpan('checkout').end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.find((attribute) => attribute.key === 'enriched')!.value).toEqual({ + stringValue: 'yyyyyyyy', + }) + expect(sent.events!.at(-1)!.attributes!.find((attribute) => attribute.key === 'blob')!.value).toEqual({ + stringValue: 'zzzzzzzz', + }) + }) + + it('does not invent a dropped count when beforeSpanSend only removes', async () => { + const traces = createTraces({ + maxAttributesPerSpan: 5, + beforeSpanSend: [ + (span) => { + delete span.attributes.secret + return span + }, + ], + }) + traces.startSpan('checkout', { attributes: { secret: 'x', kept: true } }).end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['kept']) + expect(sent.droppedAttributesCount).toBeUndefined() + }) + + it('never evicts the auto-context keys', async () => { + context = { distinctId: 'alice', sessionId: 'session-1' } + const traces = createTraces({ maxAttributesPerSpan: 1 }) + const span = traces.startSpan('checkout') + for (let i = 0; i < 5; i++) { + span.setAttribute(`key-${i}`, i) + } + span.end() + await traces.flush() + + const keys = sentSpans()[0].attributes!.map((attribute) => attribute.key) + expect(keys).toEqual(expect.arrayContaining(['posthogDistinctId', 'sessionId', 'key-0'])) + expect(keys).not.toContain('key-1') + }) + + it('caps events and counts the rest', async () => { + const traces = createTraces({ maxEventsPerSpan: 2 }) + const span = traces.startSpan('checkout') + for (let i = 0; i < 4; i++) { + span.addEvent(`event-${i}`) + } + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.events!.map((event) => event.name)).toEqual(['event-0', 'event-1']) + expect(sent.droppedEventsCount).toBe(2) + }) + + it('lets a caller overwrite an attribute it already set while at the cap', async () => { + const traces = createTraces({ maxAttributesPerSpan: 1 }) + const span = traces.startSpan('checkout') + span.setAttribute('plan', 'free') + span.setAttribute('plan', 'pro') + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes).toEqual([{ key: 'plan', value: { stringValue: 'pro' } }]) + expect(sent.droppedAttributesCount).toBeUndefined() + }) + + it('omits the counters when nothing was dropped', async () => { + const traces = createTraces() + traces.startSpan('checkout', { attributes: { plan: 'pro' } }).end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent).not.toHaveProperty('droppedAttributesCount') + expect(sent).not.toHaveProperty('droppedEventsCount') + }) + + it('counts a parsed __proto__ key against the cap instead of smuggling it through', async () => { + // JSON.parse produces an own `__proto__` key; a plain object store would + // swap its prototype and leak every nested key past the cap. + const traces = createTraces({ maxAttributesPerSpan: 2 }) + const parsed = JSON.parse('{"__proto__": {"leaked": 1}, "orderId": "abc"}') + traces.startSpan('checkout', { attributes: parsed }).end() + await traces.flush() + + const keys = sentSpans()[0].attributes!.map((attribute) => attribute.key) + expect(keys).not.toContain('leaked') + expect(keys).toContain('orderId') + }) + + it('does not let reserved property names bypass the cap', async () => { + const traces = createTraces({ maxAttributesPerSpan: 1 }) + const span = traces.startSpan('checkout') + span.setAttribute('kept', 1) + span.setAttribute('toString', 'nope') + span.setAttribute('constructor', 'nope') + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['kept']) + expect(sent.droppedAttributesCount).toBe(2) + }) + + it('does not spend cap budget on values that are dropped at encode time', async () => { + const traces = createTraces({ maxAttributesPerSpan: 2 }) + const span = traces.startSpan('checkout') + span.setAttribute('skipped-a', undefined) + span.setAttribute('skipped-b', null) + span.setAttribute('orderId', 'abc-123') + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['orderId']) + expect(sent.droppedAttributesCount).toBeUndefined() + }) + + it('still caps a key first seen with an optional value', async () => { + const traces = createTraces({ maxAttributesPerSpan: 2 }) + const span = traces.startSpan('checkout') + for (let i = 0; i < 5; i++) { + span.setAttribute(`field-${i}`, undefined) + } + for (let i = 0; i < 5; i++) { + span.setAttribute(`field-${i}`, i) + } + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes).toHaveLength(2) + expect(sent.droppedAttributesCount).toBe(3) + }) + + it('clears a key that is set back to null', async () => { + const traces = createTraces({ maxAttributesPerSpan: 2 }) + const span = traces.startSpan('checkout') + span.setAttribute('orderId', 'abc-123') + span.setAttribute('orderId', null) + span.setAttribute('a', 1) + span.setAttribute('b', 2) + span.end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['a', 'b']) + expect(sent.droppedAttributesCount).toBeUndefined() + }) + + it('caps attributes supplied at start', async () => { + const traces = createTraces({ maxAttributesPerSpan: 2 }) + traces.startSpan('checkout', { attributes: { a: 1, b: 2, c: 3 } }).end() + await traces.flush() + + const [sent] = sentSpans() + expect(sent.attributes!.map((attribute) => attribute.key)).toEqual(['a', 'b']) + expect(sent.droppedAttributesCount).toBe(1) + }) + }) + describe('export', () => { it('flushes when the queue reaches the batch size', async () => { const traces = createTraces({ maxExportBatchSize: 2 }) @@ -1043,6 +2091,54 @@ describe('PostHogTraces', () => { expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('2 span(s)')) expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('the user has opted out')) }) + + it('stops draining a backlog when optOut() lands while a batch is in flight', async () => { + const instance = createMockInstance() + instance._sendTracesBatch = vi.fn(() => + Promise.resolve({ kind: 'retry-later' as const, error: new Error('down') }) + ) + const traces = createTraces({ maxExportBatchSize: 2 }, instance) + context = { distinctId: 'alice', sessionId: 'session-1' } + for (let i = 0; i < 6; i++) { + traces.startSpan(`span-${i}`).end() + await flushMicrotasks() + } + expect(instance._sendTracesBatch).toHaveBeenCalledTimes(1) + + instance._sendTracesBatch.mockImplementation(() => + Promise.resolve().then(() => { + instance.optedOut = true + return { kind: 'ok' as const } + }) + ) + await traces.flush() + + expect(instance._sendTracesBatch).toHaveBeenCalledTimes(2) + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('4 span(s)')) + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('the user has opted out')) + }) + + it('stops draining a backlog when the client is disabled while a batch is in flight', async () => { + const instance = createMockInstance() + instance._sendTracesBatch = vi.fn(() => + Promise.resolve({ kind: 'retry-later' as const, error: new Error('down') }) + ) + const traces = createTraces({ maxExportBatchSize: 2 }, instance) + for (let i = 0; i < 6; i++) { + traces.startSpan(`span-${i}`).end() + await flushMicrotasks() + } + + instance._sendTracesBatch.mockImplementation(() => + Promise.resolve().then(() => { + instance.isDisabled = true + return { kind: 'ok' as const } + }) + ) + await traces.flush() + + expect(instance._sendTracesBatch).toHaveBeenCalledTimes(2) + }) }) describe('flush backoff', () => { @@ -1187,6 +2283,20 @@ describe('PostHogTraces', () => { expect(sentSpans().map((span) => span.name)).toEqual(['checkout']) }) + it('bounds a long resource attribute value', async () => { + // Resource attributes are caller-supplied like span attributes, and they + // ride on every batch rather than on one span. + const traces = createTraces({ + maxAttributeValueLength: 4, + resourceAttributes: { 'host.name': 'abcdefgh' } as never, + }) + traces.startSpan('checkout').end() + await traces.flush() + + const resource = sentPayloads()[0].resourceSpans[0].resource!.attributes + expect(resource.find((attribute) => attribute.key === 'host.name')?.value).toEqual({ stringValue: 'abcd' }) + }) + it('does not throw on a Date-like object with no Date slot', () => { const traces = createTraces() const fakeDate = Object.create(Date.prototype) diff --git a/packages/core/src/traces/index.ts b/packages/core/src/traces/index.ts index 3776416872..5d67e00d81 100644 --- a/packages/core/src/traces/index.ts +++ b/packages/core/src/traces/index.ts @@ -1,17 +1,26 @@ -import type { Span, SpanAttributes, StartSpanOptions } from '@posthog/types' +import type { Span, SpanAttributes, SpanRecord as HookSpanRecord, StartSpanOptions } from '@posthog/types' import type { Logger } from '../types' import type { OtlpSpan, ResolvedTracesConfig, SpanContextManager, + SpanEventRecord, SpanRecord, TraceSdkContext, TracesHost, } from './types' -import { PostHogSpan, describeError, inertSpan, monotonicNow, runWithActiveSpan } from './span' +import { + PostHogSpan, + applySpanLimits, + describeError, + inertSpan, + monotonicNow, + runWithActiveSpan, + truncateAttributes, +} from './span' import { newSpanId, newTraceId } from './ids' import { parseTraceparent, sanitizeTracestate } from './traceparent' -import { resolveStartTime, sanitizeName } from './sanitize' +import { clampEndTime, resolveStartTime, resolveSuppliedTime, sanitizeName, toEpochMs } from './sanitize' import { assignUserAttributes } from '../utils/json-utils' import { buildOtlpSpan, buildOtlpTracesPayload, buildTracesResourceAttributes } from './otlp' import { isPromise, safeSetTimeout } from '../utils' @@ -50,6 +59,79 @@ function looksLikeSpan(value: unknown): boolean { } } +/** + * The rebuilt record with every field named, optional ones included. A field + * added to either half of `SpanRecord` is a compile error at the rebuild until + * it says whether a hook may set that field or the span keeps its own value. + */ +type RebuiltSpanRecord = { [K in keyof Required]: SpanRecord[K] } + +interface SpanIdentity { + traceId: string + spanId: string + parentSpanId?: string + traceState?: string +} + +/** + * Whether a `beforeSpanSend` return value still carries every field the public + * `SpanRecord` declares as required. An array is rejected for `attributes`: it + * would encode as `{ "0": ... }` rather than fail. + * + * Presence, not usability: a field that is there but holds the wrong type is a + * hook editing a real record badly, and the sanitising below is what answers + * that. A field that is absent means the hook returned something that was never + * a span record, and the fallbacks would dress it up as one. + */ +function isSpanRecordShape(record: SpanRecord): boolean { + return ( + !!record.attributes && + typeof record.attributes === 'object' && + !Array.isArray(record.attributes) && + Array.isArray(record.events) && + record.name !== undefined && + record.kind !== undefined && + record.startTime !== undefined && + record.endTime !== undefined + ) +} + +/** Writes `value` onto `record` only when it isn't already there. */ +function restoreField(record: SpanIdentity, field: K, value: SpanIdentity[K]): void { + if (record[field] !== value) { + record[field] = value + } +} + +/** + * A stand-in for a record whose identity could not be written back, carrying the + * original ids and everything else the hook returned. + * + * Built from the descriptors rather than spread so a class instance keeps its + * prototype — `instanceof` and a field exposed as a prototype getter both still + * answer — and so `Object.keys` reads what it read before. Only the four + * identity descriptors are replaced, which is what makes the copy writable where + * the original was frozen. + */ +function withRestoredIdentity(hooked: HookSpanRecord, original: SpanIdentity): HookSpanRecord { + try { + const descriptors = Object.getOwnPropertyDescriptors(hooked) as Record + for (const field of ['traceId', 'spanId', 'parentSpanId', 'traceState'] as const) { + descriptors[field] = { + value: original[field], + enumerable: true, + writable: true, + configurable: true, + } + } + return Object.create(Object.getPrototypeOf(hooked) as object | null, descriptors) as HookSpanRecord + } catch { + // A hostile descriptor read. The export still uses the snapshot, so this + // costs the next hook a correct id rather than the span. + return hooked + } +} + interface ParentContext { traceId: string parentSpanId?: string @@ -147,6 +229,8 @@ export class PostHogTraces { // so a backdated `startTime` neither ages a span early nor exempts it. this._liveSpans.set(spanId, clockNow()) + const autoAttributes = this._autoContextAttributes() + return new PostHogSpan( { traceId: parent?.traceId ?? newTraceId(), @@ -155,14 +239,18 @@ export class PostHogTraces { traceState: parent?.traceState, traceFlags: parent?.traceFlags, parentIsRemote: parent?.isRemote, - name: sanitizeName(name, 'Span name', this._logger), + name: sanitizeName(name, 'Span name', this._config.maxAttributeValueLength, this._logger), kind: options?.kind ?? 'internal', // Auto-context first so user-supplied attributes win on collision. - attributes: assignUserAttributes(this._autoContextAttributes(), options?.attributes), + attributes: assignUserAttributes({ ...autoAttributes }, options?.attributes), + autoAttributeKeys: Object.keys(autoAttributes), + maxAttributes: this._config.maxAttributesPerSpan, + maxEvents: this._config.maxEventsPerSpan, + maxAttributeValueLength: this._config.maxAttributeValueLength, startTime, backdated: startTime !== now, }, - (record) => this._onSpanEnd(record), + (record, autoKeys) => this._onSpanEnd(record, autoKeys), this._logger ) } @@ -239,14 +327,25 @@ export class PostHogTraces { private _startFlush(): Promise { this._clearFlushTimer() - const promise = this._flushInner().finally(() => { - // Only clear the slot this call installed: a `reset()` mid-flight may - // already have installed a newer one. - if (this._flushPromise === promise) { - this._flushPromise = null - } - this._armFlushTimerIfQueued() - }) + // Deferred by a microtask so the slot below is installed before the pass + // reads anything: `_flushInner` runs synchronously as far as its first + // await, and a resource-attribute getter or `toJSON` that ends a span in + // that window would otherwise re-enter here, find no pass in flight, and + // send the same head batch again — without bound. + // Sampled before the microtask, not inside `_flushInner`: a `reset()` landing + // in the window would otherwise be invisible to this pass, which would then + // drain the post-reset queue alongside the pass `reset()` started. + const startedAtGeneration = this._generation + const promise = Promise.resolve() + .then(() => (startedAtGeneration === this._generation ? this._flushInner() : 0)) + .finally(() => { + // Only clear the slot this call installed: a `reset()` mid-flight may + // already have installed a newer one. + if (this._flushPromise === promise) { + this._flushPromise = null + } + this._armFlushTimerIfQueued() + }) this._flushPromise = promise return promise } @@ -254,6 +353,16 @@ export class PostHogTraces { /** Clears the queue and timer. Used on shutdown and between tests. */ reset(): void { this._clearFlushTimer() + if (this._queue.length) { + // Critical, and said here rather than counted: this is the last chance to + // say anything about these spans, the drop warning is gated behind `debug` + // on some hosts, and the only other line the caller sees is the export + // failure promising a retry on a flush that will never come. + this._logger.critical( + `Discarding ${this._queue.length} span(s) that were still queued when tracing was shut down. ` + + 'Raise the shutdown timeout or flush earlier if they matter.' + ) + } this._queue = [] this._liveSpans.clear() this._flushPromise = null @@ -339,8 +448,12 @@ export class PostHogTraces { if (!(span instanceof PostHogSpan)) { return } - const { type, message } = describeError(error) - span.addEvent('exception', { 'exception.type': type, 'exception.message': message }) + const { type, message, stack } = describeError(error) + span.addEvent('exception', { + 'exception.type': type, + 'exception.message': message, + ...(stack && { 'exception.stacktrace': stack }), + }) if (!span.statusIsExplicitlyOk) { span.setStatus('error', message) } @@ -367,9 +480,9 @@ export class PostHogTraces { } } - private _onSpanEnd(record: SpanRecord): void { - // Deleted before any other gate, so an opted-out span still returns its slot. - if (!this._liveSpans.delete(record.spanId)) { + private _onSpanEnd(incoming: SpanRecord, autoKeys: ReadonlySet): void { + // Deleted before any other gate, so a span dropped later still returns its slot. + if (!this._liveSpans.delete(incoming.spanId)) { // Evicted for age while live: never exported, and already counted as a drop. return } @@ -380,6 +493,11 @@ export class PostHogTraces { return } + const record = this._runBeforeSpanSend(incoming, autoKeys) + if (!record) { + return + } + if (this._queue.length >= this._config.maxQueueSize) { // Drop the incoming span, not queued ones: those are completed parents whose // children may already have shipped. @@ -407,6 +525,183 @@ export class PostHogTraces { } } + /** + * Runs the `beforeSpanSend` chain, returning the span to enqueue or `null` to + * drop it. + * + * A throwing hook drops the span: the hook is the documented scrubbing point, + * so a broken scrubber must not let the unscrubbed record through. Identity + * fields are restored afterwards, since rewriting them orphans shipped children. + */ + private _runBeforeSpanSend(record: SpanRecord, autoKeys: ReadonlySet): SpanRecord | null { + if (!this._config.beforeSpanSend.length) { + return record + } + + // Snapshotted before any hook runs: a hook that mutates in place would + // otherwise leave nothing to restore from. + const identity = { + traceId: record.traceId, + spanId: record.spanId, + parentSpanId: record.parentSpanId, + traceState: record.traceState, + } + const originalTimes = { startTime: record.startTime, endTime: record.endTime } + // Snapshotted with the rest: the hook mutates the record in place, so reading + // these back afterwards reads whatever the hook left there. + const originalDropped = { + attributes: record.droppedAttributesCount, + events: record.droppedEventsCount, + } + // Read here rather than restored onto the hook's return value: writing them + // back would throw on a frozen record, and neither is on the record a hook + // is handed, so a rebuilding hook always arrives without them. + // The order the span itself wrote them in, so the caps below can keep the + // earliest-set entries even when a hook adds an integer-like key. + const keysBeforeHook = Object.keys(record.attributes) + const originalPropagation = { + traceFlags: record.traceFlags, + parentIsRemote: record.parentIsRemote, + } + // Copied, not referenced: the hook is documented as mutating the record in + // place, and a reference would restore the mutation onto itself. + const originalStatus = record.status && { ...record.status } + let hooked: HookSpanRecord = record + let current = record + try { + for (const hook of this._config.beforeSpanSend) { + const result = hook(hooked) + if (!result) { + this._recordDrop(1, 'beforeSpanSend dropped it') + return null + } + hooked = this._keepSpanIdentity(result, identity) + } + + // Rebuilt field by field before anything below writes to it. The hook's + // return value may be frozen, where every write here would throw, or a + // class instance whose fields are prototype getters a spread would miss. + // Naming them also bounds what can reach the wire. + const rebuilt: RebuiltSpanRecord = { + // All four from the snapshot, never from the hook's return value. A hook + // that forges an id has it ignored, which is the documented behaviour, + // and one that also freezes what it returns keeps its span: writing the + // id back onto a frozen object throws, and a throw here drops the span. + traceId: identity.traceId, + spanId: identity.spanId, + parentSpanId: identity.parentSpanId, + traceState: identity.traceState, + name: hooked.name, + kind: hooked.kind, + status: hooked.status, + attributes: hooked.attributes, + events: hooked.events, + startTime: hooked.startTime, + endTime: hooked.endTime, + // Taken from the span for the same reason as the dropped counts: no + // public type declares them, so a rebuilding hook returns without them + // and a `?? fallback` here would export a sampled-out trace as sampled. + traceFlags: originalPropagation.traceFlags, + parentIsRemote: originalPropagation.parentIsRemote, + // Taken from the span, not from the hook's return value: these are SDK + // bookkeeping that no public type declares, so a hook overwriting them + // must not erase what the span actually dropped. + droppedAttributesCount: originalDropped.attributes, + droppedEventsCount: originalDropped.events, + } + current = rebuilt + // A value missing a required field is not a span record — an `async` hook + // returns a Promise, truthy and `undefined` for every field. Filling the + // gaps in would export a span named `unknown` at a fallback time carrying + // no person or session, joinable to nothing and silent about it. + if (!isSpanRecordShape(current)) { + this._logger.debug('beforeSpanSend did not return a span record; dropping the span') + this._recordDrop(1, 'beforeSpanSend returned an unusable record') + return null + } + + // Re-applied to whatever the hook returned: one undecodable timestamp 400s + // the whole request, taking unrelated spans with it. + current.name = sanitizeName(current.name, 'Span name', this._config.maxAttributeValueLength, this._logger) + // A status the hook rewrote never went through `setStatus`. An unknown code + // encodes as an empty status object, which loses an error the span really had. + if (current.status && current.status.code !== 'ok' && current.status.code !== 'error') { + this._logger.debug('beforeSpanSend set an unknown span status; keeping the original') + current.status = originalStatus + } + current.startTime = toEpochMs(current.startTime) ?? originalTimes.startTime + current.endTime = clampEndTime(toEpochMs(current.endTime) ?? originalTimes.endTime, current.startTime) + // Events a hook pushed never went through `addEvent`, so they carry no + // sanitised name or timestamp; an unvalidated one encodes as `NaN000NaN` + // and the ingestion service refuses the whole batch. + const sanitizedEvents: SpanEventRecord[] = [] + for (const event of current.events) { + try { + sanitizedEvents.push({ + ...event, + name: sanitizeName(event.name, 'Span event name', this._config.maxAttributeValueLength, this._logger), + timestamp: resolveSuppliedTime(event.timestamp, current.startTime, 'event timestamp', this._logger), + }) + } catch { + // A hook can leave a `null` in the array or a throwing accessor on an + // event. That costs the event; the rest of the span still ships. + this._logger.debug('beforeSpanSend left an unreadable span event; dropping it') + } + } + current.events = sanitizedEvents + applySpanLimits( + current, + autoKeys, + this._config.maxAttributesPerSpan, + this._config.maxEventsPerSpan, + this._config.maxAttributeValueLength, + keysBeforeHook + ) + return current + } catch (error) { + // Covers the hook and everything done to its return value: a frozen or + // hostile record must not throw out of `end()` into application code. + this._logger.debug('beforeSpanSend failed; dropping the span rather than exporting it unscrubbed', error) + this._recordDrop(1, 'beforeSpanSend failed') + return null + } + } + + /** + * Restores the fields a hook must not change. Runs per hook so a later hook in + * the chain cannot sample on an id an earlier one forged. + */ + private _keepSpanIdentity(hooked: HookSpanRecord, original: SpanIdentity): HookSpanRecord { + if ( + hooked.traceId !== original.traceId || + hooked.spanId !== original.spanId || + hooked.parentSpanId !== original.parentSpanId + ) { + this._logger.debug('beforeSpanSend changed a span identity field; keeping the original ids') + } + // Only the fields that actually differ are written back. Assigning a value + // to a frozen property throws even when it is the value already there, and + // a hook that freezes the record it returns would otherwise drop every span. + // Best-effort, for the next hook in the chain only: the record this builds + // is not what gets exported. A frozen return refuses every write, and the + // span must survive that. + try { + restoreField(hooked, 'traceId', original.traceId) + restoreField(hooked, 'spanId', original.spanId) + restoreField(hooked, 'parentSpanId', original.parentSpanId) + // A hook that rebuilds the record instead of spreading it would otherwise + // drop tracestate, which is not part of the record the hook is handed. + restoreField(hooked, 'traceState', original.traceState) + } catch { + // Frozen, so the writes above were refused and this record still carries + // whatever identity the hook forged. The export reads the snapshot either + // way, but the next hook in the chain reads this — and would sample or + // route on a forged id, which identity immutability exists to prevent. + return withRestoredIdentity(hooked, original) + } + return hooked + } + private _recordDrop(count: number, reason: string): void { this._droppedSinceWarning += count this._dropReasons.add(reason) @@ -446,27 +741,38 @@ export class PostHogTraces { return encoded } + /** + * Discards the queue when consent has been withdrawn, returning how many spans + * it dropped. Spans carry `posthogDistinctId` and `sessionId`, so anything still + * queued when the user opts out must not be exported. + */ + private _discardQueueIfConsentWithdrawn(): number { + if (!this._instance.isDisabled && !this._instance.optedOut) { + return 0 + } + const discarded = this._queue.length + this._queue = [] + this._recordDrop(discarded, 'the user has opted out') + this._warnAboutDrops() + return discarded + } + /** Returns how many spans it removed from the queue, sent or dropped. */ private async _flushInner(): Promise { if (!this._queue.length) { return 0 } - // Consent can flip between a span being queued and this pass running. Spans - // carry `posthogDistinctId` and `sessionId`, so anything still queued when - // the user opts out must be discarded rather than exported. - if (this._instance.isDisabled || this._instance.optedOut) { - const discarded = this._queue.length - this._queue = [] - this._recordDrop(discarded, 'the user has opted out') - this._warnAboutDrops() - return discarded + const discardedBeforeDrain = this._discardQueueIfConsentWithdrawn() + if (discardedBeforeDrain) { + return discardedBeforeDrain } - const resourceAttributes = buildTracesResourceAttributes( - this._config, - this._instance.getLibraryId(), - this._instance.getLibraryVersion() + // Bounded like span attributes: resource attributes are caller-supplied too, + // and they ride on every batch rather than on one span. + const resourceAttributes = truncateAttributes( + buildTracesResourceAttributes(this._config, this._instance.getLibraryId(), this._instance.getLibraryVersion()), + this._config.maxAttributeValueLength ) const scopeName = this._instance.getLibraryId() const scopeVersion = this._instance.getLibraryVersion() @@ -478,6 +784,13 @@ export class PostHogTraces { try { while (remaining > 0 && this._queue.length > 0) { + // Re-checked per batch: a send suspends, so the user can opt out while one + // batch is in flight and the batches behind it would still export. + const discardedMidDrain = this._discardQueueIfConsentWithdrawn() + if (discardedMidDrain) { + return removed + discardedMidDrain + } + // Floor at one, or a non-positive batch size loops forever on an empty batch. const cap = this._headBatchFailures > 0 diff --git a/packages/core/src/traces/live-spans.spec.ts b/packages/core/src/traces/live-spans.spec.ts index 895fda1c79..47ab14c5d9 100644 --- a/packages/core/src/traces/live-spans.spec.ts +++ b/packages/core/src/traces/live-spans.spec.ts @@ -20,6 +20,10 @@ describe('live spans', () => { maxQueueSize: 2048, maxLiveSpans: 10000, maxSpanAgeMs: 3600000, + beforeSpanSend: [], + maxAttributesPerSpan: 128, + maxEventsPerSpan: 128, + maxAttributeValueLength: 8192, } const createTraces = (): PostHogTraces => diff --git a/packages/core/src/traces/otlp.spec.ts b/packages/core/src/traces/otlp.spec.ts index a36dded70d..641171df2d 100644 --- a/packages/core/src/traces/otlp.spec.ts +++ b/packages/core/src/traces/otlp.spec.ts @@ -140,6 +140,10 @@ describe('OTLP span encoding', () => { flushIntervalMs: 5000, maxExportBatchSize: 512, maxQueueSize: 2048, + beforeSpanSend: [], + maxAttributesPerSpan: 128, + maxEventsPerSpan: 128, + maxAttributeValueLength: 8192, maxLiveSpans: 10000, maxSpanAgeMs: 3600000, ...partial, diff --git a/packages/core/src/traces/otlp.ts b/packages/core/src/traces/otlp.ts index 6da9bfb2e2..686b7e8e86 100644 --- a/packages/core/src/traces/otlp.ts +++ b/packages/core/src/traces/otlp.ts @@ -9,6 +9,7 @@ import type { } from '@posthog/types' import type { Logger } from '../types' import type { ResolvedTracesConfig, SpanRecord } from './types' +import { nonNegativeCount } from './span' import { toOtlpKeyValueList } from '../utils/otlp-any-value' import { UNSERIALIZABLE_VALUE, sanitizeString } from '../utils/json-utils' import { buildOtlpResourceAttributes } from '../utils/otlp-resource' @@ -130,6 +131,16 @@ export function buildOtlpSpan(record: SpanRecord, logger?: Logger): OtlpSpan { if (record.events.length) { span.events = record.events.map((event) => toOtlpEvent(event, logger)) } + // Coerced: a `beforeSpanSend` hook can write anything onto the record, and a + // non-integer here is refused for the whole request. + const droppedAttributes = nonNegativeCount(record.droppedAttributesCount) + if (droppedAttributes) { + span.droppedAttributesCount = droppedAttributes + } + const droppedEvents = nonNegativeCount(record.droppedEventsCount) + if (droppedEvents) { + span.droppedEventsCount = droppedEvents + } if (record.status) { span.status = { code: SPAN_STATUS_TO_OTLP[record.status.code], diff --git a/packages/core/src/traces/sanitize.ts b/packages/core/src/traces/sanitize.ts index 258620cf53..701286f4db 100644 --- a/packages/core/src/traces/sanitize.ts +++ b/packages/core/src/traces/sanitize.ts @@ -23,9 +23,12 @@ const DEEP_BACKDATE_WARNING_MS = 24 * 60 * 60 * 1000 * replaced rather than dropped, so a mis-instrumented call site loses its name, * not its span. `label` names what is being sanitized in the warning. */ -export function sanitizeName(name: unknown, label: string, logger?: Logger): string { +export function sanitizeName(name: unknown, label: string, maxLength: number, logger?: Logger): string { if (typeof name === 'string' && name.trim()) { - return name + // Bounded like a status message and an attribute value: a name built from a + // URL or a payload is caller-controlled too, and one large enough takes the + // span past the ingestion body limit, which drops it whole. + return name.length > maxLength ? name.slice(0, maxLength) : name } logger?.debug(`${label} must be a non-empty string; using "${FALLBACK_SPAN_NAME}"`) return FALLBACK_SPAN_NAME diff --git a/packages/core/src/traces/span.spec.ts b/packages/core/src/traces/span.spec.ts index 15ce17709d..2039adc43a 100644 --- a/packages/core/src/traces/span.spec.ts +++ b/packages/core/src/traces/span.spec.ts @@ -1,8 +1,10 @@ -import { NOOP_SPAN, PostHogSpan, describeError } from './span' +import { NOOP_SPAN, PostHogSpan, describeError, truncateAttributeValue } from './span' +import { buildOtlpSpan } from './otlp' import type { SpanInit } from './span' import type { SpanRecord } from './types' import type { Logger } from '../types' import { createMockLogger } from '@/testing' +import { MAX_JSON_SAFE_VALUE_ITEMS, MAX_JSON_SAFE_VALUE_NODES } from '../utils/json-utils' const TRACE_ID = '4bf92f3577b34da6a3ce929d0e0e4736' const SPAN_ID = '00f067aa0ba902b7' @@ -21,6 +23,10 @@ describe('PostHogSpan', () => { attributes: {}, startTime: Date.now(), backdated: false, + autoAttributeKeys: [], + maxAttributes: 128, + maxEvents: 128, + maxAttributeValueLength: 8192, ...init, }, (record) => ended.push(record), @@ -166,6 +172,75 @@ describe('PostHogSpan', () => { expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('OK')) }) + describe('event cap', () => { + const fillEvents = (span: PostHogSpan, count: number): void => { + for (let i = 0; i < count; i++) { + span.addEvent(`step-${i}`) + } + } + + it('drops an exception event on a span that has filled its events', () => { + // The cap is absolute, so an exception arriving last is dropped like any + // other event. The span keeps its `error` status and `droppedEventsCount` + // reports the loss, which is what makes the case findable in production. + const span = createSpan({ maxEvents: 2 }) + fillEvents(span, 2) + span.recordException(new Error('boom')) + span.end() + + expect(ended[0].events.map((event) => event.name)).toEqual(['step-0', 'step-1']) + expect(ended[0].status).toEqual({ code: 'error', message: 'boom' }) + expect(ended[0].droppedEventsCount).toBe(1) + }) + + it('records an exception like any other event while the cap has room', () => { + const span = createSpan({ maxEvents: 128 }) + for (let i = 0; i < 20; i++) { + span.recordException(new Error(`boom-${i}`)) + } + span.end() + + expect(ended[0].events).toHaveLength(20) + expect(ended[0].droppedEventsCount).toBeUndefined() + }) + + it('does not let an exception-named event bypass the cap', () => { + // The cap counts events, not names: nothing about the name `exception` + // buys a slot, whoever wrote it. + const span = createSpan({ maxEvents: 2 }) + for (let i = 0; i < 7; i++) { + span.addEvent('exception', { mine: i }) + } + span.end() + + expect(ended[0].events).toHaveLength(2) + expect(ended[0].droppedEventsCount).toBe(5) + }) + + it('drops ordinary events past the cap', () => { + const span = createSpan({ maxEvents: 2 }) + fillEvents(span, 5) + span.end() + + expect(ended[0].events.map((event) => event.name)).toEqual(['step-0', 'step-1']) + expect(ended[0].droppedEventsCount).toBe(3) + }) + }) + + describe('attribute store hygiene', () => { + it('does not copy a polluted Object.prototype key into the span', () => { + ;(Object.prototype as any).polluted = 'yes' + try { + const span = createSpan({ attributes: { real: 1 } }) + span.end() + + expect(Object.keys(ended[0].attributes)).toEqual(['real']) + } finally { + delete (Object.prototype as any).polluted + } + }) + }) + describe('poison attributes', () => { const withThrowingGetter = (): any => { const attributes: any = { ok: 1 } @@ -224,10 +299,471 @@ describe('PostHogSpan', () => { expect(ended[0].events).toEqual([ expect.objectContaining({ name: 'exception', - attributes: { 'exception.type': 'TypeError', 'exception.message': 'boom' }, + attributes: expect.objectContaining({ 'exception.type': 'TypeError', 'exception.message': 'boom' }), }), ]) }) + + it('attaches the stack as exception.stacktrace', () => { + const span = createSpan() + span.recordException(new TypeError('boom')) + span.end() + + const stack = ended[0].events[0].attributes?.['exception.stacktrace'] + expect(stack).toEqual(expect.stringContaining('TypeError: boom')) + }) + + it('bounds the stack by maxAttributeValueLength', () => { + const span = createSpan({ maxAttributeValueLength: 40 }) + const error = new Error('boom') + error.stack = `Error: boom\n${' at somewhere deep\n'.repeat(500)}` + + span.recordException(error) + span.end() + + expect(ended[0].events[0].attributes?.['exception.stacktrace']).toHaveLength(40) + }) + + it('records an exception with no stack without inventing one', () => { + const span = createSpan() + span.recordException('just a string') + span.end() + + expect(ended[0].events[0].attributes).not.toHaveProperty('exception.stacktrace') + }) + }) + + describe('maxAttributeValueLength', () => { + it('truncates a long string attribute without counting it as dropped', () => { + const span = createSpan({ maxAttributeValueLength: 10 }) + span.setAttribute('payload', 'x'.repeat(5000)) + span.end() + + expect(ended[0].attributes.payload).toBe('xxxxxxxxxx') + // The count is for whole entries; a trimmed value is still exported. + expect(ended[0].droppedAttributesCount).toBeUndefined() + }) + + it('truncates the strings inside an array attribute, and leaves other types alone', () => { + const span = createSpan({ maxAttributeValueLength: 3 }) + span.setAttributes({ tags: ['abcdef', 'ab'], count: 1234567, flag: true }) + span.end() + + expect(ended[0].attributes).toMatchObject({ tags: ['abc', 'ab'], count: 1234567, flag: true }) + }) + + it('truncates strings nested inside an object value', () => { + // `setAttribute('payload', { body: res.body })` is the natural way to attach + // a response, and an unbounded one is what pushes a span past the endpoint. + const span = createSpan({ maxAttributeValueLength: 4 }) + span.setAttribute('payload', { body: 'abcdefgh', status: 200 }) + span.end() + + expect(ended[0].attributes.payload).toEqual({ body: 'abcd', status: 200 }) + }) + + it('truncates strings nested inside an array value', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + span.setAttribute('rows', [{ body: 'abcdefgh' }, ['abcdefgh']]) + span.end() + + expect(ended[0].attributes.rows).toEqual([{ body: 'abcd' }, ['abcd']]) + }) + + it('bounds the work a shared subtree costs, not just a cyclic one', () => { + // Siblings pointing at one object are re-walked once per path, so this + // reaches the same leaves ten million times. Only the node budget stops it. + const leaf: string[] = [] + for (let i = 0; i < 1000; i++) { + leaf.push('x'.repeat(2000)) + } + const mid = Array.from({ length: 1000 }, () => leaf) + const shared = Array.from({ length: 10 }, () => mid) + + const bounded = truncateAttributeValue(shared, 8) + + // Counting what the walk shortened, not what the result can reach: past + // the budget the original is handed back by reference. + const cap = MAX_JSON_SAFE_VALUE_NODES * 2 + let shortened = 0 + const stack: unknown[] = [bounded] + while (stack.length && shortened <= cap) { + const value = stack.pop() + if (typeof value === 'string') { + if (value.length === 8) { + shortened++ + } + } else if (Array.isArray(value) && value !== leaf && value !== mid) { + stack.push(...value) + } + } + expect(shortened).toBeLessThanOrEqual(cap) + }) + + it('terminates on a self-referencing value', () => { + const cyclic: any = { body: 'abcdefgh' } + cyclic.self = cyclic + const span = createSpan({ maxAttributeValueLength: 4 }) + + expect(() => { + span.setAttribute('payload', cyclic) + span.end() + }).not.toThrow() + }) + + it('charges a throwing accessor to its own key, still bounding its siblings', () => { + // A lazy ORM relation next to a large field is the shape that matters: if + // the throw abandons the whole walk, the large field ships at full length. + const span = createSpan({ maxAttributeValueLength: 4 }) + const hostile = { + ok: 'abcdefgh', + get boom() { + throw new Error('getter exploded') + }, + } + + expect(() => { + span.setAttribute('payload', hostile as any) + span.end() + }).not.toThrow() + + const payload = ended[0].attributes.payload as Record + expect(payload.ok).toBe('abcd') + expect(payload.boom).toBe('[Unserializable]') + }) + + it('does not walk into a value whose toJSON redacts it', () => { + // Copying the object's own keys would hand the encoder a plain object it + // no longer recognises as self-describing, putting the internals of a + // value that redacts itself on the wire. + class Redacted { + constructor(public secret: string) {} + toJSON(): null { + return null + } + } + const span = createSpan({ maxAttributeValueLength: 10 }) + + span.setAttribute('payload', { inner: new Redacted('S'.repeat(50)) } as any) + span.end() + + // The string the encoder builds from the same `null`, so the wire is + // unchanged, and the secret is nowhere in what the span kept. + expect((ended[0].attributes.payload as any).inner).toBe('null') + expect(JSON.stringify(ended[0].attributes)).not.toContain('S') + }) + + it('materializes a toJSON that resolves to nothing, so a second call cannot answer differently', () => { + // Keeping the object itself left the encoder to probe toJSON again. A + // serializer that answered `null` here could answer with a megabyte + // there, past the bound entirely. + let calls = 0 + const stateful = { + toJSON: () => { + calls++ + return calls === 1 ? null : 'x'.repeat(100) + }, + } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('doc', stateful as any) + span.end() + + expect(calls).toBe(1) + expect(ended[0].attributes.doc).toBe('null') + }) + + it('keeps a stateful toJSON bounded through to the encoded span', () => { + // End to end, because the second call is the encoder's: what the span + // stored has to leave it nothing to call. + let calls = 0 + const stateful = { + toJSON: () => { + calls++ + return calls === 1 ? null : 'x'.repeat(100) + }, + } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('doc', stateful as any) + span.end() + const encoded = buildOtlpSpan(ended[0]) + + expect(calls).toBe(1) + expect(encoded.attributes?.find((attribute) => attribute.key === 'doc')).toEqual({ + key: 'doc', + value: { stringValue: 'null' }, + }) + }) + + it('describes a toJSON resolving to undefined the way the encoder would', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('ghost', { toJSON: () => undefined } as any) + span.end() + + // Not trimmed to the bound: this is the SDK's own marker, like + // `[Circular]`, and `unde` reads as nothing at all. + expect(ended[0].attributes.ghost).toBe('undefined') + }) + + it('bounds event attributes too', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + span.addEvent('cache.miss', { key: 'abcdefgh' }) + span.end() + + expect(ended[0].events[0].attributes).toEqual({ key: 'abcd' }) + }) + + it('walks a value that points at itself twice only once', () => { + // Depth alone is not a bound. Two back-references at each level cost + // 2 ** 20 visits, which is a quarter-second inside the caller's own + // `setAttribute` call, and a third reference is minutes. + let reads = 0 + const cyclic: any = { + get body() { + reads++ + return 'abcdefgh' + }, + } + cyclic.self1 = cyclic + cyclic.self2 = cyclic + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', cyclic) + span.end() + + expect(reads).toBe(1) + }) + + it('bounds the nodes an acyclic value costs, not just its depth', () => { + // Siblings sharing a subtree are not a cycle, so the ancestor set does not + // catch them: 3 ** 12 visits without a node budget. + let reads = 0 + let level: any = { + get body() { + reads++ + return 'abcdefgh' + }, + } + for (let i = 0; i < 12; i++) { + level = { a: level, b: level, c: level } + } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', level) + span.end() + + expect(reads).toBeLessThanOrEqual(10_000) + }) + + it('bounds the value a toJSON produces, which is what the encoder puts on the wire', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('doc', { toJSON: () => 'abcdefgh' } as any) + span.end() + + expect(ended[0].attributes.doc).toBe('abcd') + }) + + it('resolves toJSON exactly once, so a second call cannot dodge the bound', () => { + // Returning the original object when nothing needed shortening left the + // encoder to call toJSON again — a value that answered differently the + // second time reached the wire unbounded. + let calls = 0 + const doc = { + toJSON: () => { + calls++ + return calls === 1 ? 'ab' : 'x'.repeat(4000) + }, + } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('doc', doc as any) + span.end() + + expect(calls).toBe(1) + expect(ended[0].attributes.doc).toBe('ab') + }) + + it('bounds a string that follows a large collection of nulls', () => { + // The encoder drops a nullish value without spending its budget, so a walk + // that charges for one runs out first and leaves the string after it + // unbounded on both sides — a 2 MB value under a bound of 8. + const span = createSpan({ maxAttributeValueLength: 8 }) + + span.setAttribute('payload', { + rows: Array.from({ length: 400 }, () => + Object.fromEntries(Array.from({ length: 50 }, (_unused, index) => [`c${index}`, null])) + ), + html: 'X'.repeat(50000), + }) + span.end() + + expect((ended[0].attributes.payload as any).html).toHaveLength(8) + }) + + it('bounds a string that follows a large collection', () => { + // The traversal budget is spent on containers, not leaves: a big array + // used to exhaust it and leave every later string at full length. + const span = createSpan({ maxAttributeValueLength: 8 }) + + span.setAttribute('payload', { + rows: Array.from({ length: 20000 }, (_, index) => index), + html: 'X'.repeat(50000), + }) + span.end() + + expect((ended[0].attributes.payload as any).html).toHaveLength(8) + }) + + it('keeps a nested __proto__ key as an ordinary entry', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', JSON.parse('{"__proto__": {"body": "abcdefgh"}}')) + span.end() + + const payload = ended[0].attributes.payload as Record + expect(Object.keys(payload)).toEqual(['__proto__']) + expect(Object.getOwnPropertyDescriptor(payload, '__proto__')?.value).toEqual({ body: 'abcd' }) + }) + + it('bounds an event name the SDK records like any other', () => { + const span = createSpan({ maxAttributeValueLength: 8, maxEvents: 4 }) + + span.recordException(new Error('boom')) + span.end() + + expect(ended[0].events[0].name).toBe('exceptio') + expect(ended[0].events[0].attributes?.['exception.type']).toBe('Error') + }) + + it('bounds a span name and an event name, like a status message', () => { + // A name built from a URL is caller-controlled, and one large enough takes + // the span past the ingestion body limit. + const span = createSpan({ maxAttributeValueLength: 12 }) + + span.updateName('abcdefghijklmnop') + span.addEvent('abcdefghijklmnop') + span.end() + + expect(ended[0].name).toBe('abcdefghijkl') + expect(ended[0].events[0].name).toBe('abcdefghijkl') + }) + + it('bounds a status message', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setStatus('error', 'abcdefgh') + span.end() + + expect(ended[0].status).toEqual({ code: 'error', message: 'abcd' }) + }) + + it('bounds the status message recordException sets, like the event attribute', () => { + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.recordException(new Error('abcdefgh')) + span.end() + + expect(ended[0].status?.message).toBe('abcd') + expect(ended[0].events[0].attributes?.['exception.message']).toBe('abcd') + }) + + it('replaces a back-reference with the marker rather than the value itself', () => { + // Handing the raw ancestor back left it inside a copied parent, where the + // encoder's own cycle detection no longer recognised it and walked one + // more level of its strings at full length. + const cyclic: any = { body: 'abcdefgh' } + cyclic.self = cyclic + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', cyclic) + span.end() + + expect(ended[0].attributes.payload).toEqual({ body: 'abcd', self: '[Circular]' }) + }) + + it('still bounds an array whose accessor past the encoder cap throws', () => { + // `slice()` read the whole array to copy it, so one throwing accessor + // beyond the encoder's cap cost every item in range its bound. + const rows: unknown[] = ['abcdefgh'] + for (let index = 1; index < MAX_JSON_SAFE_VALUE_ITEMS + 200; index++) { + rows.push('x') + } + Object.defineProperty(rows, MAX_JSON_SAFE_VALUE_ITEMS + 100, { + get: () => { + throw new Error('lazy relation') + }, + enumerable: true, + configurable: true, + }) + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('rows', rows as any) + span.end() + + expect((ended[0].attributes.rows as unknown[])[0]).toBe('abcd') + }) + + it('stops reading keys where the encoder stops emitting them', () => { + // Every key was read even though the encoder emits at most the cap, so a + // wide object charged `setAttribute` for getters that never ship. + let reads = 0 + const wide: Record = {} + for (let index = 0; index < MAX_JSON_SAFE_VALUE_ITEMS * 2; index++) { + Object.defineProperty(wide, `k${index}`, { + get: () => { + reads++ + return 'v' + }, + enumerable: true, + configurable: true, + }) + } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', wide) + span.end() + + expect(reads).toBe(MAX_JSON_SAFE_VALUE_ITEMS) + }) + + it('copies a nested value the caller goes on to mutate', () => { + // A value that needed no truncation was attached as it came, so the span + // held caller-owned state and shipped whatever it was changed to. + const nested = { body: 'ok' } + const span = createSpan({ maxAttributeValueLength: 4 }) + + span.setAttribute('payload', { nested }) + nested.body = 'abcdefgh' + span.end() + + expect(ended[0].attributes.payload).toEqual({ nested: { body: 'ok' } }) + }) + + it('leaves a Date whole rather than truncating its timestamp', () => { + // The encoder emits a Date from its own branch ahead of any `toJSON`, so + // bounding it here shipped a cut-off timestamp instead of a shorter one. + const span = createSpan({ maxAttributeValueLength: 10 }) + + span.setAttribute('when', new Date('2020-01-02T03:04:05.000Z') as never) + span.end() + + expect(ended[0].attributes.when).toEqual(new Date('2020-01-02T03:04:05.000Z')) + }) + + it('bounds an SDK-attached value, which is exempt from the count cap only', () => { + const span = createSpan({ + maxAttributeValueLength: 4, + attributes: { posthogDistinctId: 'user-12345' }, + autoAttributeKeys: ['posthogDistinctId'], + }) + span.setAttribute('posthogDistinctId', 'user-12345') + span.end() + + expect(ended[0].attributes.posthogDistinctId).toBe('user') + }) }) describe('timestamps', () => { @@ -349,6 +885,61 @@ describe('NoopSpan', () => { }) }) +describe('attribute store', () => { + it('hands out a record whose attributes behave like an ordinary object', () => { + const ended: SpanRecord[] = [] + const span = new PostHogSpan( + { + traceId: TRACE_ID, + spanId: SPAN_ID, + name: 'checkout', + kind: 'internal', + attributes: { plan: 'pro' }, + startTime: Date.now(), + backdated: false, + autoAttributeKeys: [], + maxAttributes: 128, + maxEvents: 128, + maxAttributeValueLength: 8192, + }, + (record) => ended.push(record) + ) + span.end() + + const { attributes } = ended[0] + expect(Object.getPrototypeOf(attributes)).toBe(Object.prototype) + expect(Object.prototype.hasOwnProperty.call(attributes, 'plan')).toBe(true) + expect(() => JSON.stringify(attributes)).not.toThrow() + }) + + it('keeps a parsed __proto__ key as an ordinary attribute', () => { + const ended: SpanRecord[] = [] + const span = new PostHogSpan( + { + traceId: TRACE_ID, + spanId: SPAN_ID, + name: 'checkout', + kind: 'internal', + attributes: JSON.parse('{"__proto__": {"leaked": 1}, "orderId": "abc"}'), + startTime: Date.now(), + backdated: false, + autoAttributeKeys: [], + maxAttributes: 128, + maxEvents: 128, + maxAttributeValueLength: 8192, + }, + (record) => ended.push(record) + ) + span.end() + + const keys: string[] = [] + for (const key in ended[0].attributes) { + keys.push(key) + } + expect(keys).not.toContain('leaked') + }) +}) + describe('describeError', () => { it.each([ ['an Error', new Error('boom'), { type: 'Error', message: 'boom' }], @@ -357,7 +948,23 @@ describe('describeError', () => { ['an object with a message', { name: 'CustomError', message: 'oops' }, { type: 'CustomError', message: 'oops' }], ['an object without a name', { message: 'oops' }, { type: 'Object', message: 'oops' }], ])('describes %s', (_name, error, expected) => { - expect(describeError(error)).toEqual(expected) + expect(describeError(error)).toMatchObject(expected) + }) + + it('carries the stack where the thrown value has one, and nothing where it does not', () => { + expect(describeError(new Error('boom')).stack).toEqual(expect.stringContaining('Error: boom')) + expect(describeError('just a string').stack).toBeUndefined() + expect(describeError({ message: 'oops' }).stack).toBeUndefined() + }) + + it('survives a throwing stack accessor', () => { + const hostile = { + message: 'oops', + get stack() { + throw new Error('nope') + }, + } + expect(describeError(hostile)).toEqual({ type: 'Object', message: 'oops' }) }) it('describes a thrown primitive', () => { diff --git a/packages/core/src/traces/span.ts b/packages/core/src/traces/span.ts index a93ea62d31..3124945c9d 100644 --- a/packages/core/src/traces/span.ts +++ b/packages/core/src/traces/span.ts @@ -3,8 +3,15 @@ import type { Logger } from '../types' import type { SpanContextManager, SpanEventRecord, SpanRecord } from './types' import { formatTraceparent, normalizeTraceparent, sanitizeTracestate, TRACE_FLAGS_SAMPLED } from './traceparent' import { clampEndTime, resolveSuppliedTime, sanitizeName } from './sanitize' -import { assignUserAttributes } from '../utils/json-utils' -import { isError } from '../utils' +import { isArray, isError, isNullish } from '../utils' +import { + CIRCULAR_VALUE, + MAX_JSON_SAFE_VALUE_DEPTH, + MAX_JSON_SAFE_VALUE_ITEMS, + MAX_JSON_SAFE_VALUE_NODES, + UNSERIALIZABLE_VALUE, + assignUserAttributes, +} from '../utils/json-utils' /** * A monotonic millisecond reading where the platform has one, so an NTP @@ -31,6 +38,11 @@ export interface SpanInit { startTime: number /** True when the caller supplied an explicit `startTime`. */ backdated: boolean + /** Keys the SDK attached itself. Exempt from the attribute cap and never evicted. */ + autoAttributeKeys: string[] + maxAttributes: number + maxEvents: number + maxAttributeValueLength: number } export class PostHogSpan implements Span { @@ -50,10 +62,18 @@ export class PostHogSpan implements Span { private _events: SpanEventRecord[] = [] private _status?: { code: SpanStatusCode; message?: string } private _ended = false + private readonly _autoKeys: Set + private readonly _maxAttributes: number + private readonly _maxEvents: number + private readonly _maxAttributeValueLength: number + private _userAttributeCount = 0 + private _userEventCount = 0 + private _droppedAttributes = 0 + private _droppedEvents = 0 constructor( init: SpanInit, - private readonly _onEnd: (record: SpanRecord) => void, + private readonly _onEnd: (record: SpanRecord, autoKeys: ReadonlySet) => void, private readonly _logger?: Logger ) { this._traceId = init.traceId @@ -64,7 +84,19 @@ export class PostHogSpan implements Span { this._parentIsRemote = init.parentIsRemote ?? false this._name = init.name this._kind = init.kind - this._attributes = init.attributes + this._autoKeys = new Set(init.autoAttributeKeys) + this._maxAttributes = init.maxAttributes + this._maxEvents = init.maxEvents + this._maxAttributeValueLength = init.maxAttributeValueLength + // Null-prototype: a `__proto__` key would otherwise swap this object's prototype + // instead of becoming an entry, and `toString` and friends would read as + // already-present. + this._attributes = Object.create(null) as SpanAttributes + // Object.keys, not for...in: the latter walks the prototype chain, so a + // polluted `Object.prototype` key would become an attribute of every span. + for (const key of Object.keys(init.attributes)) { + this._writeAttribute(key, init.attributes[key]) + } this._startTime = init.startTime this._startMono = init.backdated ? undefined : monotonicNow() } @@ -92,27 +124,72 @@ export class PostHogSpan implements Span { return true } + /** + * Writes an attribute unless the span is already at its user-attribute cap. + * + * Overwriting a key already on the span always succeeds — the cap counts + * distinct user keys, not writes — and SDK-attached keys never count toward + * it, so a span at the cap still carries its person and session ids. + */ + private _writeAttribute(key: string, value: SpanAttributeValue): void { + // Nullish removes the key rather than occupying it: storing one would spend no + // budget and make every later write to that key free, exceeding the cap. + if (isNullish(value)) { + if (key in this._attributes && !this._autoKeys.has(key)) { + this._userAttributeCount-- + } + delete this._attributes[key] + return + } + // The cap is checked before the value is bounded: walking a value the span is + // about to drop is the dominant cost of a span that overflows its cap. + if (!this._autoKeys.has(key) && !(key in this._attributes)) { + if (this._userAttributeCount >= this._maxAttributes) { + this._droppedAttributes++ + return + } + this._userAttributeCount++ + } + this._attributes[key] = truncateAttributeValue(value, this._maxAttributeValueLength) + } + setAttribute(key: string, value: SpanAttributeValue): this { if (this._mutable('setAttribute')) { - Object.defineProperty(this._attributes, key, { value, enumerable: true, writable: true, configurable: true }) + this._writeAttribute(key, value) } return this } setAttributes(attributes: SpanAttributes): this { if (this._mutable('setAttributes')) { - assignUserAttributes(this._attributes, attributes) + // Read through the shared guard first — own enumerable keys only, and a + // throwing getter costs its own key — then write each through the cap. + const safe: SpanAttributes = assignUserAttributes({}, attributes) + for (const key of Object.keys(safe)) { + this._writeAttribute(key, safe[key]) + } } return this } addEvent(name: string, attributes?: SpanAttributes, timestamp?: SpanTimeInput): this { if (this._mutable('addEvent')) { + // An exception the SDK records spends an ordinary slot like any other + // event. A span that fills its events and then throws therefore keeps its + // `error` status but loses the exception detail, which `droppedEventsCount` + // reports — enough to find the case in production if it turns out to occur. + if (this._userEventCount >= this._maxEvents) { + this._droppedEvents++ + return this + } + this._userEventCount++ this._events.push({ - name: sanitizeName(name, 'Span event name', this._logger), + name: sanitizeName(name, 'Span event name', this._maxAttributeValueLength, this._logger), timestamp: resolveSuppliedTime(timestamp, this._now(), 'event timestamp', this._logger), // Copied so a caller reusing one object across events can't mutate a recorded one. - ...(attributes && { attributes: assignUserAttributes({}, attributes) }), + ...(attributes && { + attributes: truncateAttributes(assignUserAttributes({}, attributes), this._maxAttributeValueLength), + }), }) } return this @@ -124,7 +201,12 @@ export class PostHogSpan implements Span { this._logger?.debug(`Ignoring unknown span status "${String(status)}"; expected "ok" or "error"`) return this } - this._status = { code: status, ...(message && { message }) } + // Bounded like an attribute value: a status message is one more string the + // caller controls, and one large enough takes the span past the body limit. + this._status = { + code: status, + ...(message && { message: truncateString(message, this._maxAttributeValueLength) }), + } } return this } @@ -138,10 +220,11 @@ export class PostHogSpan implements Span { if (!this._mutable('recordException')) { return this } - const { type, message } = describeError(error) - this.addEvent('exception', { + const { type, message, stack } = describeError(error) + this.addEvent(EXCEPTION_EVENT_NAME, { 'exception.type': type, 'exception.message': message, + ...(stack && { 'exception.stacktrace': stack }), }) // recordException is itself an explicit call, so it follows last-write-wins // rather than deferring to an earlier `ok`. @@ -150,7 +233,7 @@ export class PostHogSpan implements Span { updateName(name: string): this { if (this._mutable('updateName')) { - this._name = sanitizeName(name, 'Span name', this._logger) + this._name = sanitizeName(name, 'Span name', this._maxAttributeValueLength, this._logger) } return this } @@ -184,22 +267,147 @@ export class PostHogSpan implements Span { const derived = this._now() const resolved = resolveSuppliedTime(endTime, derived, 'end time', this._logger) - this._onEnd({ - traceId: this._traceId, - spanId: this._spanId, - ...(this._parentSpanId && { parentSpanId: this._parentSpanId }), - ...(this._traceState && { traceState: this._traceState }), - traceFlags: this._traceFlags, - parentIsRemote: this._parentIsRemote, - name: this._name, - kind: this._kind, - ...(this._status && { status: this._status }), - attributes: this._attributes, - events: this._events, - startTime: this._startTime, - endTime: clampEndTime(resolved, this._startTime), + this._onEnd( + { + traceId: this._traceId, + spanId: this._spanId, + ...(this._parentSpanId && { parentSpanId: this._parentSpanId }), + ...(this._traceState && { traceState: this._traceState }), + traceFlags: this._traceFlags, + parentIsRemote: this._parentIsRemote, + name: this._name, + kind: this._kind, + ...(this._status && { status: this._status }), + // Copied out with an ordinary prototype: the store is null-prototype, but a + // record handed to user code should behave like a normal object. + attributes: { ...this._attributes }, + events: this._events, + startTime: this._startTime, + endTime: clampEndTime(resolved, this._startTime), + ...(this._droppedAttributes && { droppedAttributesCount: this._droppedAttributes }), + ...(this._droppedEvents && { droppedEventsCount: this._droppedEvents }), + }, + this._autoKeys + ) + } +} + +const EXCEPTION_EVENT_NAME = 'exception' + +/** A value as its string form, or the encoder's marker when it refuses to produce one. */ +function safeString(value: unknown): string { + try { + return typeof value === 'string' ? value : String(value) + } catch { + return UNSERIALIZABLE_VALUE + } +} + +/** A caller-visible counter read back as a number, or 0 for anything else. */ +export function nonNegativeCount(value: unknown): number { + return typeof value === 'number' && Number.isFinite(value) && value > 0 ? Math.floor(value) : 0 +} + +/** + * Re-applies the per-span caps to a record a `beforeSpanSend` hook has already + * seen. The hook writes to the plain record, not through the span's own guarded + * writer, so an enriching hook would otherwise push a span past the cap it was + * trimmed to and back into the 413 path the cap exists to avoid. + * + * Earliest-set entries win, matching the span-side rule; SDK-attached keys are + * exempt. Counts add to whatever the span already dropped. + */ +/** + * The record's keys with the ones the span itself set first, in that order. + * + * `Object.keys` hoists integer-like keys to the front whatever the write order, + * so a hook adding `attributes['0']` would otherwise outrank an attribute the + * caller set before the hook ran — and the cap is documented as earliest-set-wins. + */ +function orderedKeys(attributes: SpanAttributes, keysBeforeHook: readonly string[]): string[] { + if (!keysBeforeHook.length) { + return Object.keys(attributes) + } + // The encoder's own predicate: `in` would walk the prototype chain, so a key + // the caller set that collides with Object.prototype survives the hook deleting + // it and reads back as the inherited member, and `hasOwnProperty` would keep a + // key the hook hid by making it non-enumerable, which the encoder never emits. + const beforeHook = keysBeforeHook.filter((key) => Object.prototype.propertyIsEnumerable.call(attributes, key)) + const seen = new Set(beforeHook) + return [...beforeHook, ...Object.keys(attributes).filter((key) => !seen.has(key))] +} + +export function applySpanLimits( + record: SpanRecord, + autoKeys: ReadonlySet, + maxAttributes: number, + maxEvents: number, + maxAttributeValueLength: number, + keysBeforeHook: readonly string[] = [] +): void { + let kept = 0 + let droppedAttributes = 0 + // Built fresh rather than edited in place: a hook is free to return a record + // whose attributes it froze, and a `delete` on one throws. + const attributes: SpanAttributes = {} + for (const key of orderedKeys(record.attributes, keysBeforeHook)) { + const value = record.attributes[key] + // Matches `_writeAttribute`: the encoder drops these, so a hook that blanks a + // value rather than deleting the key must not evict a real attribute. + if (isNullish(value)) { + continue + } + if (!autoKeys.has(key)) { + if (kept >= maxAttributes) { + droppedAttributes++ + continue + } + kept++ + } + Object.defineProperty(attributes, key, { + value: truncateAttributeValue(value, maxAttributeValueLength), + enumerable: true, + writable: true, + configurable: true, }) } + record.attributes = attributes + if (droppedAttributes) { + // Coerced, not trusted: a hook can put anything in the counter, and a + // non-number there would erase the count the span itself accumulated. + record.droppedAttributesCount = nonNegativeCount(record.droppedAttributesCount) + droppedAttributes + } + + // Walked rather than sliced: a hook can append events or rewrite their + // attributes, neither of which goes through `addEvent`, so each one still + // needs its attributes bounded on the way past. + let keptEvents = 0 + let droppedEvents = 0 + const events: SpanEventRecord[] = [] + for (const event of record.events) { + if (keptEvents >= maxEvents) { + droppedEvents++ + continue + } + keptEvents++ + if (event.attributes) { + event.attributes = truncateAttributes({ ...event.attributes }, maxAttributeValueLength) + } + events.push(event) + } + record.events = events + if (droppedEvents) { + record.droppedEventsCount = nonNegativeCount(record.droppedEventsCount) + droppedEvents + } + if (record.status?.message) { + // Coerced first: a non-string would reach the encoder to be stringified at + // full length. Guarded, because a throwing `toString` here would cost the + // span, where the encoder downstream only marks the field. + record.status = { + ...record.status, + message: truncateString(safeString(record.status.message), maxAttributeValueLength), + } + } } /** @@ -264,6 +472,21 @@ export class PassThroughSpan extends NoopSpan { } } +/** + * The `stack` of whatever was thrown, as OTel's `exception.stacktrace`. Reads + * the property behind its own guard: a getter on a hostile object throws, and a + * thrown string has no stack at all. The value is bounded like any other + * attribute, by `maxAttributeValueLength`. + */ +function readStack(error: unknown): { stack?: string } { + try { + const stack = (error as { stack?: unknown }).stack + return typeof stack === 'string' && stack ? { stack } : {} + } catch { + return {} + } +} + /** * The handle to return when a span cannot be recorded: a pass-through when the * caller supplied a usable `parent` header, the shared no-op otherwise. @@ -291,6 +514,197 @@ function readHandle(parent: unknown, method: 'traceparent' | 'tracestate'): unkn } } +/** + * The same depth, node and item caps `encodeAnyValue` uses, but spent per + * attribute rather than per bag: the encoder allocates one budget for a whole + * attribute map, this walk allocates one per value. That makes the encoder's + * budget the stricter of the two — whatever this walk hands back unbounded, the + * encoder has already stopped short of — at the cost of a wide span paying for + * a walk whose results the encoder then discards. + */ +interface TruncateState { + /** Containers on the current path, so a back-reference stops the walk. */ + ancestors: WeakSet + remainingNodes: number +} + +/** + * Bounds every string reachable from an attribute value to `maxLength` + * characters, including the strings nested inside arrays and objects. Numbers + * and booleans are bounded already. + * + * An unbounded value is the one thing the per-span caps do not stop: a single + * multi-MB attribute makes the whole span too large for the ingestion endpoint, + * and the 413 path then drops that span whole. `setAttribute('payload', { body })` + * is the usual way one arrives, so the bound has to reach inside the value. + * + * Returns the value it was given when nothing needed shortening, so the common + * case allocates nothing. + */ +function truncateString(value: string, maxLength: number): string { + return value.length > maxLength ? value.slice(0, maxLength) : value +} + +export function truncateAttributeValue(value: SpanAttributeValue, maxLength: number): SpanAttributeValue { + return truncateValue(value, maxLength, { ancestors: new WeakSet(), remainingNodes: MAX_JSON_SAFE_VALUE_NODES }, 0) +} + +/** + * Walks under the same depth cap, node budget and ancestor set as + * `encodeAnyValue`, charging the same values. The encoder spends one budget + * across the whole attribute bag where this spends one per value, so it runs out + * no later and marks whatever this walk returned whole. + * + * Depth alone does not bound this: a value whose children point back at their + * siblings costs `fanout ** depth` visits, which is minutes of synchronous work + * inside the caller's own `setAttribute` call. + */ +function truncateValue( + value: SpanAttributeValue, + maxLength: number, + state: TruncateState, + depth: number +): SpanAttributeValue { + if (value === null || typeof value !== 'object') { + // Free, as it is in the encoder, which drops a nullish leaf without charging. + if (isNullish(value)) { + return value + } + // A shared subtree is re-walked once per path reaching it, so a leaf that + // skips the charge lets one value cost `budget * items` string copies. + if (state.remainingNodes <= 0) { + return value + } + state.remainingNodes-- + return typeof value === 'string' ? truncateString(value, maxLength) : value + } + if (state.ancestors.has(value)) { + // The marker the encoder would produce, not the value itself. Handing the + // raw ancestor back puts it inside a *copied* parent, where the encoder's + // own cycle detection no longer recognises it and walks one more level of + // its strings at full length. + return CIRCULAR_VALUE + } + if (state.remainingNodes <= 0 || depth >= MAX_JSON_SAFE_VALUE_DEPTH) { + return value + } + state.remainingNodes-- + state.ancestors.add(value) + try { + // A Date is emitted by the encoder from its own branch, ahead of any + // `toJSON` probe, so bounding it here would ship a truncated timestamp + // rather than a shorter one. + if (value instanceof Date) { + return value + } + // The representation the value defines for itself is what the encoder puts + // on the wire, so it is what has to be bounded — a `toJSON` returning a + // megabyte of text is invisible to a walk over the object's own keys. + const resolved = resolveToJson(value) + if (resolved.selfDescribed) { + // Resolving to nothing is the value's answer. Walking its keys anyway + // would build a plain object the encoder no longer treats as + // self-describing, putting the internals of a redacted value on the wire. + // Stored as the string the encoder builds from that same nullish result + // rather than as the value itself: the encoder probes `toJSON` a second + // time, so one that answers `null` here is free to answer with a megabyte + // there, past the bound this walk exists to apply. Left unbounded like the + // other markers — nine characters at most, and trimming it to `unde` would + // only make it unreadable. + return isNullish(resolved.value) + ? String(resolved.value) + : truncateValue(resolved.value, maxLength, state, depth + 1) + } + if (isArray(value)) { + // Only the items the encoder will emit are walked; it stops at the same + // cap, so bounding the rest is work spent on values that never ship. + const walked = Math.min(value.length, MAX_JSON_SAFE_VALUE_ITEMS) + // Accumulated rather than copied from the value: `slice()` reads every + // element, accessors past the cap included, and one of those throwing + // would reach the outer catch and cost the whole array its bound. + const boundedItems: SpanAttributeValue[] = [] + for (let index = 0; index < walked; index++) { + try { + boundedItems.push(truncateValue(value[index], maxLength, state, depth + 1)) + } catch { + // A throwing accessor costs its own item, as it does in the encoder. + boundedItems.push(UNSERIALIZABLE_VALUE) + } + } + // Carried so the encoder still marks what it cut. + if (value.length > walked) { + boundedItems.length = value.length + } + return boundedItems + } + const bounded: SpanAttributes = {} + // Counted the way the encoder counts, so the walk stops where its output + // does: a key it skips costs no slot, and reading past the last one it can + // emit is getter work on values that never ship. + let emittable = 0 + for (const key of Object.keys(value)) { + if (emittable >= MAX_JSON_SAFE_VALUE_ITEMS) { + break + } + let boundedItem: SpanAttributeValue + try { + // Read once: re-reading to compare would run a getter a second time. + boundedItem = truncateValue((value as SpanAttributes)[key], maxLength, state, depth + 1) + } catch { + // A throwing accessor costs its own key. Reaching the walk's own catch + // would abandon the whole value unbounded, which is how a lazy ORM + // relation next to a large field puts that field on the wire whole. + boundedItem = UNSERIALIZABLE_VALUE + } + if (key && !isNullish(boundedItem)) { + emittable++ + } + // defineProperty, not assignment: a nested `__proto__` key would otherwise + // swap the copy's prototype and vanish. + Object.defineProperty(bounded, key, { + value: boundedItem, + enumerable: true, + writable: true, + configurable: true, + }) + } + return bounded + } catch { + // Whatever is left — a hostile `Object.keys`, a `slice` that throws — costs + // this value its bound rather than the span. Per-key reads are guarded + // above, so a single bad property does not reach here. + return value + } finally { + // Siblings pointing at the same object are duplication, not a cycle. + state.ancestors.delete(value) + } +} + +/** + * The value's own serialized form. `selfDescribed` is false when it defines no + * `toJSON`, or when reading one throws — both fall through to the plain walk, + * as they do in the encoder. + */ +function resolveToJson(value: object): { selfDescribed: boolean; value?: SpanAttributeValue } { + try { + const toJSON = (value as { toJSON?: unknown }).toJSON + if (typeof toJSON === 'function') { + return { selfDescribed: true, value: toJSON.call(value) as SpanAttributeValue } + } + } catch { + // Falls through to the plain walk. + } + return { selfDescribed: false } +} + +/** `truncateAttributeValue` across an attribute bag, in place. */ +export function truncateAttributes(attributes: SpanAttributes, maxLength: number): SpanAttributes { + for (const key of Object.keys(attributes)) { + attributes[key] = truncateAttributeValue(attributes[key], maxLength) + } + return attributes +} + /** * Runs `fn` with `span` active, which every scoped helper does the same way. * @@ -307,10 +721,11 @@ export function runWithActiveSpan(contextManager: SpanContextManager, span: S * Extracts the OTel `exception.type` / `exception.message` pair from whatever was * thrown. Anything can be thrown in JS, so non-Errors are described by type. */ -export function describeError(error: unknown): { type: string; message: string } { +export function describeError(error: unknown): { type: string; message: string; stack?: string } { try { + const stack = readStack(error) if (isError(error)) { - return { type: error.name || 'Error', message: error.message || '' } + return { type: error.name || 'Error', message: error.message || '', ...stack } } if (typeof error === 'string') { return { type: 'string', message: error } @@ -318,7 +733,7 @@ export function describeError(error: unknown): { type: string; message: string } if (error && typeof error === 'object') { const maybe = error as { name?: unknown; message?: unknown } if (typeof maybe.message === 'string') { - return { type: typeof maybe.name === 'string' ? maybe.name : 'Object', message: maybe.message } + return { type: typeof maybe.name === 'string' ? maybe.name : 'Object', message: maybe.message, ...stack } } } return { type: typeof error, message: String(error) } diff --git a/packages/core/src/traces/types.ts b/packages/core/src/traces/types.ts index 2b1e392570..7360c70a26 100644 --- a/packages/core/src/traces/types.ts +++ b/packages/core/src/traces/types.ts @@ -7,6 +7,7 @@ export type { SpanTimeInput, StartSpanOptions, TracesConfig, + BeforeSpanSendFn, OtlpSpan, OtlpSpanEvent, OtlpSpanKeyValue, @@ -14,7 +15,16 @@ export type { OtlpTracesPayload, } from '@posthog/types' -import type { OtlpTracesPayload, Span, SpanAttributes, SpanKind, SpanStatusCode, TracesConfig } from '@posthog/types' +import type { + BeforeSpanSendFn, + OtlpTracesPayload, + Span, + SpanAttributes, + SpanKind, + SpanRecord as HookSpanRecord, + SpanStatusCode, + TracesConfig, +} from '@posthog/types' /** Same tagged outcome shape as `SendLogsBatchOutcome` — one policy for all three signals. */ export type SendTracesBatchOutcome = @@ -56,26 +66,19 @@ export interface SpanEventRecord { } /** - * A completed span in plain, pre-encoding form: strings for kind and status, a - * plain attribute map, ms-epoch timestamps. + * A finished span as the SDK carries it, which is the hook-visible record plus + * the fields no hook may rewrite. Declaring only the additions keeps the shared + * half from drifting; a field added here rather than to the public record is a + * field `beforeSpanSend` cannot see, and so cannot corrupt. */ -export interface SpanRecord { - traceId: string - spanId: string - parentSpanId?: string +export interface SpanRecord extends HookSpanRecord { traceState?: string /** The W3C trace-flags byte this span propagates, e.g. `01` sampled. */ traceFlags: string /** True when the parent came from a `traceparent` header rather than a local handle. */ parentIsRemote: boolean - name: string - kind: SpanKind - status?: { code: SpanStatusCode; message?: string } - attributes: SpanAttributes - events: SpanEventRecord[] - /** ms epoch. */ - startTime: number - endTime: number + droppedAttributesCount?: number + droppedEventsCount?: number } /** @@ -102,6 +105,10 @@ export interface ResolvedTracesConfig extends TracesConfig { * dropped rather than queued ones, whose children may already have shipped. */ maxQueueSize: number + beforeSpanSend: BeforeSpanSendFn[] + maxAttributesPerSpan: number + maxEventsPerSpan: number + maxAttributeValueLength: number /** Bound on spans started but not yet ended. At the bound `startSpan` returns a no-op handle. */ maxLiveSpans: number /** How long a span may stay live before it stops being accounted for and can never export. */ diff --git a/packages/node/src/__tests__/traces.spec.ts b/packages/node/src/__tests__/traces.spec.ts index 79990cd842..964bc075ab 100644 --- a/packages/node/src/__tests__/traces.spec.ts +++ b/packages/node/src/__tests__/traces.spec.ts @@ -31,6 +31,9 @@ describe('PostHog traces', () => { const attributeOf = (span: OtlpSpan, key: string): any => span.attributes?.find((a) => a.key === key)?.value + const attributeOfEvent = (event: NonNullable[number], key: string): any => + event.attributes?.find((a: any) => a.key === key)?.value + // Traces run their own flush cycle; this advances it without calling flush(). const DEFAULT_TRACES_FLUSH_INTERVAL_MS = 5000 const flushTraces = async (): Promise => { @@ -333,6 +336,35 @@ describe('PostHog traces', () => { const [span] = sentSpans() expect(span.status).toEqual({ code: 2, message: 'boom' }) expect(span.events?.[0].name).toBe('exception') + expect(attributeOfEvent(span.events![0], 'exception.stacktrace')).toEqual({ + stringValue: expect.stringContaining('TypeError: boom'), + }) + }) + + it('beforeSpanSend can scrub a stacktrace', async () => { + const scrubbed = createClient({ + traces: { + serviceName: 'checkout-api', + beforeSpanSend: (span: any) => { + for (const event of span.events) { + if (event.attributes?.['exception.stacktrace']) { + event.attributes['exception.stacktrace'] = '[redacted]' + } + } + return span + }, + }, + }) + + expect(() => + scrubbed.withSpan('job', () => { + throw new TypeError('boom') + }) + ).toThrow('boom') + await scrubbed.shutdown() + + const [span] = sentSpans() + expect(attributeOfEvent(span.events![0], 'exception.stacktrace')).toEqual({ stringValue: '[redacted]' }) }) }) @@ -505,6 +537,93 @@ describe('PostHog traces', () => { }) }) + describe('beforeSpanSend', () => { + it('scrubs attributes before they leave the process', async () => { + const client = createClient({ + traces: { + serviceName: 'svc', + beforeSpanSend: (span: any) => { + delete span.attributes.password + return span + }, + }, + }) + client.startSpan('login', { attributes: { password: 'hunter2', ok: true } }).end() + await client.shutdown() + + const [span] = sentSpans() + expect(span.attributes?.find((a) => a.key === 'password')).toBeUndefined() + expect(span.attributes?.find((a) => a.key === 'ok')).toBeDefined() + }) + + it('runs an array of hooks through the client option', async () => { + const client = createClient({ + traces: { + serviceName: 'svc', + beforeSpanSend: [ + (span: any) => { + span.attributes.first = true + return span + }, + (span: any) => { + span.attributes.second = true + return span + }, + ], + }, + }) + client.startSpan('checkout').end() + await client.shutdown() + + const keys = sentSpans()[0].attributes?.map((a) => a.key) + expect(keys).toEqual(expect.arrayContaining(['first', 'second'])) + }) + + it('drops a span the hook rejects', async () => { + const client = createClient({ + traces: { + serviceName: 'svc', + beforeSpanSend: (span: any) => (span.attributes['http.route'] === '/health' ? null : span), + }, + }) + client.startSpan('GET /health', { attributes: { 'http.route': '/health' } }).end() + client.startSpan('GET /orders', { attributes: { 'http.route': '/orders' } }).end() + await client.shutdown() + + expect(sentSpans().map((s) => s.name)).toEqual(['GET /orders']) + }) + }) + + describe('span limits', () => { + it('caps attributes and reports how many were dropped', async () => { + const client = createClient({ traces: { serviceName: 'svc', maxAttributesPerSpan: 2 } }) + const span = client.startSpan('checkout') + span.setAttribute('a', 1) + span.setAttribute('b', 2) + span.setAttribute('c', 3) + span.end() + await client.shutdown() + + const [sent] = sentSpans() + expect(sent.attributes?.map((a) => a.key)).toEqual(['a', 'b']) + expect(sent.droppedAttributesCount).toBe(1) + }) + + it('defaults to the OpenTelemetry cap of 128', async () => { + const client = createClient({ traces: { serviceName: 'svc' } }) + const span = client.startSpan('checkout') + for (let i = 0; i < 130; i++) { + span.setAttribute(`key-${i}`, i) + } + span.end() + await client.shutdown() + + const [sent] = sentSpans() + expect(sent.attributes).toHaveLength(128) + expect(sent.droppedAttributesCount).toBe(2) + }) + }) + describe('shutdown', () => { it('is bounded by the shutdown timeout when the transport hangs', async () => { const client = createClient() diff --git a/packages/node/src/__tests__/waituntil-flush.spec.ts b/packages/node/src/__tests__/waituntil-flush.spec.ts index e16c36cb8c..6cb4855988 100644 --- a/packages/node/src/__tests__/waituntil-flush.spec.ts +++ b/packages/node/src/__tests__/waituntil-flush.spec.ts @@ -12,6 +12,42 @@ function getFlushedBatches(): any[][] { .map((c) => JSON.parse((c[1] as any).body).batch) } +describe('flush combines events and spans', () => { + it('waits for the span export even when the event flush rejects', async () => { + // `Promise.all` settled on the event rejection, so a serverless host could + // freeze the invocation with the span request still open. + vi.useRealTimers() + const order: string[] = [] + mockedFetch.mockImplementation(async (url: any) => { + if (String(url).includes('/i/v1/traces')) { + order.push('traces-start') + await new Promise((resolve) => setTimeout(resolve, 30)) + order.push('traces-done') + return { status: 200, text: () => Promise.resolve('{}'), json: () => Promise.resolve({}) } as any + } + throw new Error('events endpoint down') + }) + const posthog = new PostHog('key', { + host: 'http://example.com', + flushAt: 1, + fetchRetryCount: 0, + traces: { serviceName: 'svc' }, + disableCompression: true, + }) + posthog.capture({ distinctId: 'u', event: 'e' }) + posthog.startSpan('s').end() + + await expect(posthog.flush()).rejects.toThrow() + order.push('flush-returned') + + // Exact, not an index comparison: before the fix `traces-done` is absent + // when flush returns, and `indexOf` gives -1, which passes any `lessThan`. + expect(order).toEqual(['traces-start', 'traces-done', 'flush-returned']) + await posthog.shutdown() + vi.useFakeTimers() + }) +}) + describe('waitUntil debounced flush', () => { vi.useFakeTimers() diff --git a/packages/node/src/client.ts b/packages/node/src/client.ts index adf99bee1a..92a9cd99c4 100644 --- a/packages/node/src/client.ts +++ b/packages/node/src/client.ts @@ -1,6 +1,7 @@ import { version } from './version' import { + allSettled, FeatureFlagValue, getEventUuid, isBlockedUA, @@ -298,7 +299,15 @@ export abstract class PostHogBackendClient extends PostHogCoreStateless implemen if (!this._traces) { return events } - return Promise.all([events, this._traces.flush().catch(() => {})]).then(() => undefined) + // Settled, not `all`: `all` rejects the moment the event flush does, and a + // serverless host that treats this promise as the end of the invocation can + // freeze it with the span request still open. The events rejection is still + // the one the caller sees. + return allSettled([events, this._traces.flush().catch(() => {})]).then(([eventsResult]) => { + if (eventsResult.status === 'rejected') { + throw eventsResult.reason + } + }) } override async flush(): Promise { @@ -662,7 +671,7 @@ export abstract class PostHogBackendClient extends PostHogCoreStateless implemen if (!this._traces) { this._traces = new PostHogTraces( this, - resolveTracesConfig(this.options.traces, this.hostResourceAttributes()), + resolveTracesConfig(this.options.traces, this.hostResourceAttributes(), this._logger), this._logger, () => this._tracingContext(), this._spanContextManager, diff --git a/packages/node/src/exports.ts b/packages/node/src/exports.ts index 23e4897a93..35950883a4 100644 --- a/packages/node/src/exports.ts +++ b/packages/node/src/exports.ts @@ -24,6 +24,8 @@ export type { SpanStatusCode, SpanTimeInput, StartSpanOptions, + SpanRecord, + BeforeSpanSendFn, TracesConfig, } from '@posthog/core' diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index 04e2974cce..4d550f07f0 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -138,6 +138,8 @@ export type { SpanTimeInput, StartSpanOptions, Span, + SpanRecord, + BeforeSpanSendFn, TracesConfig, OtlpSpanKeyValue, OtlpSpanEvent, diff --git a/packages/types/src/traces.ts b/packages/types/src/traces.ts index 8e6239fd9b..eaf84e2309 100644 --- a/packages/types/src/traces.ts +++ b/packages/types/src/traces.ts @@ -133,8 +133,10 @@ export interface Span { /** * Record an exception on the span: sets status `error` and attaches an - * `exception` event carrying `exception.type` and `exception.message`. - * Does not end the span. + * `exception` event carrying `exception.type`, `exception.message` and, + * where the thrown value has one, `exception.stacktrace`. The stack is + * truncated to `maxAttributeValueLength` like any other attribute value, + * and `beforeSpanSend` sees it before it is exported. Does not end the span. */ recordException(error: unknown): this @@ -174,6 +176,43 @@ export interface Span { end(endTime?: SpanTimeInput): void } +/** + * A completed span as `beforeSpanSend` sees it: plain values, not the OTLP wire + * encoding — `userId: 42` reads as `42`, not `{ intValue: "42" }`. + * + * @experimental Subject to change in a minor release. + */ +export interface SpanRecord { + /** + * Assignment to any of the three identity fields is ignored with a debug + * warning: rewriting ids orphans children that already shipped. + */ + readonly traceId: string + readonly spanId: string + /** Absent on a root span. */ + readonly parentSpanId?: string + name: string + kind: SpanKind + status?: { code: SpanStatusCode; message?: string } + /** Editable in place; this is where to redact. */ + attributes: SpanAttributes + events: { name: string; /** Millisecond epoch. */ timestamp: number; attributes?: SpanAttributes }[] + /** Millisecond epoch. */ + startTime: number + /** Millisecond epoch. */ + endTime: number +} + +/** + * Inspects, edits or drops a finished span. Return `null` to drop it. + * + * The hook runs synchronously as part of `end()`; a returned promise is not + * awaited and the span is dropped. + * + * @experimental Subject to change in a minor release. + */ +export type BeforeSpanSendFn = (span: SpanRecord) => SpanRecord | null + /** * Configuration for distributed tracing, passed as the `traces` client option. * Tracing stays off until this object is supplied. @@ -239,6 +278,68 @@ export interface TracesConfig { */ maxQueueSize?: number + /** + * Runs on every finished span before it is queued. Edit the span in place, + * or return `null` to drop it. An array runs left to right, and the first + * hook to return `null` stops the chain. + * + * This is the place to scrub sensitive attributes, so a hook that throws + * drops the span rather than exporting an unscrubbed one. + * + * @example Drop health checks and redact a header + * ```ts + * traces: { + * beforeSpanSend: (span) => { + * if (span.attributes['http.route'] === '/health') return null + * delete span.attributes['http.request.header.authorization'] + * return span + * }, + * } + * ``` + */ + beforeSpanSend?: BeforeSpanSendFn | BeforeSpanSendFn[] + + /** + * Maximum user-supplied attributes on a single span. Attributes the SDK + * attaches itself — `posthogDistinctId`, `sessionId` and friends — are + * exempt and are never evicted, because they are what links a span to a + * person and a session. + * + * On overflow the earliest-set attributes are kept and later ones are + * dropped, with the number dropped reported on the exported span. + * + * @default 128 + */ + maxAttributesPerSpan?: number + + /** + * Maximum events on a single span. On overflow the earliest events are kept + * and later ones are dropped, with the number dropped reported on the + * exported span. + * + * The cap is absolute: an `exception` event the SDK records on your behalf + * spends an ordinary slot like any other, so a span that fills its events + * and then throws keeps its `error` status but not the exception detail. + * Raise the cap on spans that record many events and can also fail. + * + * @default 128 + */ + maxEventsPerSpan?: number + + /** + * Maximum length of a string attribute value. Longer values are truncated, + * and the bound reaches every string the value contains, including the ones + * nested inside arrays and objects. It applies to span attributes, event + * attributes, span names, event names, status messages and resource + * attributes alike — including `exception.stacktrace`. + * + * The bound is what keeps one large value from making a span too large for + * the ingestion endpoint, which drops an oversized span whole. + * + * @default 8192 + */ + maxAttributeValueLength?: number + /** * Bound on how many spans may be live (started but not ended) at once. At * the bound `startSpan` returns an inert handle, so code that leaks spans @@ -305,6 +406,10 @@ export interface OtlpSpan { * it — plus OTel's parent-remoteness bits (`0x100` known, `0x200` remote). */ flags?: number + /** User attributes dropped by `maxAttributesPerSpan`. Omitted when none were. */ + droppedAttributesCount?: number + /** Events dropped by `maxEventsPerSpan`. Omitted when none were. */ + droppedEventsCount?: number } export interface OtlpTracesPayload {