From 5757a09434856efeb44a1482d24f4ca05076ab1b Mon Sep 17 00:00:00 2001 From: Anna Garcia Date: Tue, 8 Sep 2026 10:17:17 -0400 Subject: [PATCH] fix(traces): keep the inbound trace context through nested spans An inbound `traceparent` now parents a span that names no parent, on both the recording and inert paths, so a nested span no longer starts a new trace. Also accepts a one-element header array and trims an over-long `tracestate` instead of dropping it. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01BjT26chjUzuPSyJZqh4AWQ --- .changeset/node-distributed-tracing.md | 2 +- packages/core/src/traces/index.spec.ts | 71 ++++++++++++++++- packages/core/src/traces/index.ts | 82 ++++++++++++++------ packages/core/src/traces/span.ts | 17 ++-- packages/core/src/traces/traceparent.spec.ts | 14 +++- packages/core/src/traces/traceparent.ts | 34 ++++++-- packages/node/src/client.ts | 4 +- 7 files changed, 183 insertions(+), 41 deletions(-) diff --git a/.changeset/node-distributed-tracing.md b/.changeset/node-distributed-tracing.md index 222606bce6..d2e9393b7d 100644 --- a/.changeset/node-distributed-tracing.md +++ b/.changeset/node-distributed-tracing.md @@ -4,4 +4,4 @@ '@posthog/types': minor --- -Add experimental distributed tracing to `posthog-node`: `startSpan`, `withSpan` and `getActiveSpan` record spans against a new `traces` client option. +Add experimental distributed tracing to `posthog-node`: `startSpan`, `withSpan` and `getActiveSpan` record spans against a new `traces` client option. A service with tracing off still forwards an inbound `traceparent`, including from spans nested inside the one that received it, so a distributed trace is not severed. A `traceparent` may be passed as the one-element array `req.headersDistinct` gives. diff --git a/packages/core/src/traces/index.spec.ts b/packages/core/src/traces/index.spec.ts index c3f0584527..e6b6c60011 100644 --- a/packages/core/src/traces/index.spec.ts +++ b/packages/core/src/traces/index.spec.ts @@ -15,6 +15,7 @@ import { createMockLogger } from '@/testing' const TRACE_ID = '4bf92f3577b34da6a3ce929d0e0e4736' const REMOTE_SPAN_ID = '00f067aa0ba902b7' +const DUPLICATED_HEADERS = [`00-${TRACE_ID}-${REMOTE_SPAN_ID}-01`, `00-${TRACE_ID}-${REMOTE_SPAN_ID}-00`] const resolveForTest = (partial?: Partial): ResolvedTracesConfig => ({ flushIntervalMs: 5000, @@ -269,11 +270,22 @@ describe('PostHogTraces', () => { expect(span.parentSpanId).toBeUndefined() }) - it('starts a fresh root when the parent is not a span, as a duplicated header is', async () => { + it('continues the trace when the header arrives as a one-element array', async () => { + // What `headersDistinct.traceparent` hands over for a single inbound header. const traces = createTraces() traces.startSpan('handler', { parent: [`00-${TRACE_ID}-${REMOTE_SPAN_ID}-01`] as unknown as string }).end() await traces.flush() + const [span] = sentSpans() + expect(span.traceId).toBe(TRACE_ID) + expect(span.parentSpanId).toBe(REMOTE_SPAN_ID) + }) + + it('starts a fresh root when the parent is not a span, as two inbound headers are', async () => { + const traces = createTraces() + traces.startSpan('handler', { parent: DUPLICATED_HEADERS as unknown as string }).end() + await traces.flush() + const [span] = sentSpans() expect(span.traceId).not.toBe(TRACE_ID) expect(span.parentSpanId).toBeUndefined() @@ -302,7 +314,7 @@ describe('PostHogTraces', () => { it('parents to the active span when the parent is not a span', async () => { const traces = createTraces() traces.withSpan('handler', () => { - traces.startSpan('child', { parent: [`00-${TRACE_ID}-${REMOTE_SPAN_ID}-01`] as unknown as string }).end() + traces.startSpan('child', { parent: DUPLICATED_HEADERS as unknown as string }).end() }) await traces.flush() @@ -532,6 +544,33 @@ describe('PostHogTraces', () => { expect(traces.startSpan('bad-parent', { parent: 'not-a-traceparent' })).toBe(NOOP_SPAN) }) + it('keeps the inbound context in a nested span that names no parent', () => { + const traces = createTraces({}, createMockInstance({ optedOut: true })) + + const propagated = traces.withSpan('outer', { parent: INBOUND_UNSAMPLED }, () => + traces.withSpan('inner', (span) => span.traceparent()) + ) + + expect(propagated).toBe(INBOUND_UNSAMPLED) + }) + + it('parents a recorded span to an active pass-through handle', async () => { + // Tracing is on, but the span that received the header was inert, so its + // child is the first recorded span of the inbound trace. + const foreign = { traceparent: () => INBOUND_UNSAMPLED, tracestate: () => 'vendor=abc' } + const traces = createTraces() + + traces.withSpan('proxied', { parent: foreign as unknown as Span }, () => { + traces.startSpan('child').end() + }) + await traces.flush() + + const child = sentSpans().find((span) => span.name === 'child')! + expect(child.traceId).toBe(TRACE_ID) + expect(child.parentSpanId).toBe(REMOTE_SPAN_ID) + expect(child.traceState).toBe('vendor=abc') + }) + it('keeps the inbound context when a pass-through handle is used as a parent', () => { // The child is inert either way; what it must not do is drop the context // and leave everything downstream of it on a fresh trace. @@ -837,6 +876,34 @@ describe('PostHogTraces', () => { expect(sent.droppedAttributesCount).toBe(1) }) + it('reports every limit drop once per span, hook drops included', () => { + const traces = createTraces({ + maxAttributesPerSpan: 1, + maxEventsPerSpan: 1, + beforeSpanSend: [ + (span: SpanRecord) => ({ ...span, attributes: { ...span.attributes, added: 1, alsoAdded: 2 } }), + ], + }) + + const span = traces.startSpan('checkout', { attributes: { route: '/checkout' } }) + span.addEvent('first', { a: 1 }) + span.addEvent('second') + span.end() + + const messages = logger.debug.mock.calls.map(([message]) => String(message)) + expect(messages.filter((message) => message.includes('Span limits discarded'))).toEqual([ + 'Span limits discarded data from "checkout": 2 attributes, 1 events, 0 event attributes', + ]) + }) + + it('stays quiet for a span that lost nothing', () => { + const traces = createTraces() + traces.startSpan('checkout', { attributes: { route: '/checkout' } }).end() + + const messages = logger.debug.mock.calls.map(([message]) => String(message)) + expect(messages.some((message) => message.includes('Span limits discarded'))).toBe(false) + }) + it('rejects a timestamp the server could not decode', async () => { const instance = createMockInstance() const traces = createTraces( diff --git a/packages/core/src/traces/index.ts b/packages/core/src/traces/index.ts index 3a130d4219..bf25098deb 100644 --- a/packages/core/src/traces/index.ts +++ b/packages/core/src/traces/index.ts @@ -10,6 +10,7 @@ import type { TracesHost, } from './types' import { + PassThroughSpan, PostHogSpan, applySpanLimits, describeError, @@ -19,7 +20,7 @@ import { truncateAttributes, } from './span' import { newSpanId, newTraceId } from './ids' -import { parseTraceparent, sanitizeTracestate } from './traceparent' +import { parseTraceparent, sanitizeTracestate, traceparentHeader } from './traceparent' import { clampEndTime, resolveStartTime, resolveSuppliedTime, sanitizeName, toEpochMs } from './sanitize' import { assignUserAttributes } from '../utils/json-utils' import { buildOtlpSpan, buildOtlpTracesPayload, buildTracesResourceAttributes } from './otlp' @@ -51,6 +52,21 @@ function isOwnSpan(value: unknown): value is PostHogSpan { } } +/** A `traceparent` header as the parent context it describes, or nothing if it is malformed. */ +function remoteContext(header: string, tracestate: string | undefined): ParentContext | undefined { + const remote = parseTraceparent(header) + if (!remote) { + return undefined + } + return { + traceId: remote.traceId, + parentSpanId: remote.spanId, + traceState: sanitizeTracestate(tracestate), + traceFlags: remote.flags, + isRemote: true, + } +} + function looksLikeSpan(value: unknown): boolean { try { return typeof (value as Span).traceparent === 'function' @@ -193,25 +209,26 @@ export class PostHogTraces { */ startSpan(name: string, options?: StartSpanOptions): Span { if (this._instance.isDisabled || this._instance.optedOut) { - return inertSpan(options) + return inertSpan(options, this._contextManager.active()) } - const explicitParent = options?.parent + const explicitParent = traceparentHeader(options?.parent) if (explicitParent && typeof explicitParent !== 'string' && !isOwnSpan(explicitParent)) { if (looksLikeSpan(explicitParent)) { // Inert like its parent, never an orphan with invented ids — but a // pass-through parent's inbound context carries to the child rather than // the trace ending here. this._logger.debug('Span parent is not a span from this SDK; returning an inert span') - return inertSpan(options) + return inertSpan(options, this._contextManager.active()) } - // No `traceparent()` to read: `req.headers.traceparent` is `string[]` when the - // header arrives twice, and a span from another tracer exposes `spanContext()` - // instead. Ignored: falls back to the active span, or to a new trace. + // No `traceparent()` to read: a span from another tracer exposes + // `spanContext()` instead, and `headersDistinct.traceparent` is a `string[]` + // holding more than one inbound value. Ignored: falls back to the active + // span, or to a new trace. this._logger.debug('Ignoring an unusable span parent') } - const parent = this._resolveParent(options) + const parent = this._resolveParent(explicitParent, options) // Swept before the bound is read, so a process that has leaked its way to // the bound recovers on the first `startSpan` after the leaks age out. @@ -221,7 +238,7 @@ export class PostHogTraces { 1, `the live-span limit (${this._config.maxLiveSpans}) was reached — spans are being started and never ended` ) - return inertSpan(options) + return inertSpan(options, this._contextManager.active()) } const now = Date.now() @@ -383,22 +400,13 @@ export class PostHogTraces { * Resolves a span's parent: an explicit `parent`, then the active span, then a * fresh root. A no-op explicit parent is rejected earlier, in `startSpan`. */ - private _resolveParent(options?: StartSpanOptions): ParentContext | undefined { - const explicit = options?.parent - + private _resolveParent(explicit: unknown, options?: StartSpanOptions): ParentContext | undefined { if (typeof explicit === 'string') { - const remote = parseTraceparent(explicit) + const remote = remoteContext(explicit, options?.tracestate) if (!remote) { this._logger.debug('Ignoring malformed traceparent; starting a new trace') - return undefined - } - return { - traceId: remote.traceId, - parentSpanId: remote.spanId, - traceState: sanitizeTracestate(options?.tracestate), - traceFlags: remote.flags, - isRemote: true, } + return remote } if (isOwnSpan(explicit)) { @@ -408,7 +416,16 @@ export class PostHogTraces { } const active = this._contextManager.active() - return isOwnSpan(active) ? active.childContext() : undefined + if (isOwnSpan(active)) { + return active.childContext() + } + // A pass-through handle is active when an earlier span in this trace could + // not be recorded. Its context still parents this one, so the inbound trace + // survives a span the SDK declined rather than ending there. + if (active instanceof PassThroughSpan) { + return remoteContext(active.traceparent(), active.tracestate() ?? undefined) + } + return undefined } /** @@ -500,6 +517,7 @@ export class PostHogTraces { if (!record) { return } + this._reportLimitDrops(record) if (this._queue.length >= this._config.maxQueueSize) { // Drop the incoming span, not queued ones: those are completed parents whose @@ -528,6 +546,26 @@ export class PostHogTraces { } } + /** + * One diagnostic per span when its limits discarded anything, which is what + * OTel asks for. Counted after the post-hook pass, so drops a `beforeSpanSend` + * hook caused are included. + */ + private _reportLimitDrops(record: SpanRecord): void { + const attributes = record.droppedAttributesCount ?? 0 + const events = record.droppedEventsCount ?? 0 + let eventAttributes = 0 + for (const event of record.events) { + eventAttributes += event.droppedAttributesCount ?? 0 + } + if (attributes || events || eventAttributes) { + this._logger.debug( + `Span limits discarded data from "${record.name}": ` + + `${attributes} attributes, ${events} events, ${eventAttributes} event attributes` + ) + } + } + /** * Runs the `beforeSpanSend` chain, returning the span to enqueue or `null` to * drop it. diff --git a/packages/core/src/traces/span.ts b/packages/core/src/traces/span.ts index c7f5906f11..f36397b0e7 100644 --- a/packages/core/src/traces/span.ts +++ b/packages/core/src/traces/span.ts @@ -1,7 +1,13 @@ import type { Span, SpanAttributes, SpanAttributeValue, SpanKind, SpanStatusCode, SpanTimeInput } from '@posthog/types' import type { Logger } from '../types' import type { SpanContextManager, SpanEventRecord, SpanRecord } from './types' -import { formatTraceparent, normalizeTraceparent, sanitizeTracestate, TRACE_FLAGS_SAMPLED } from './traceparent' +import { + formatTraceparent, + normalizeTraceparent, + sanitizeTracestate, + traceparentHeader, + TRACE_FLAGS_SAMPLED, +} from './traceparent' import { clampEndTime, resolveSuppliedTime, sanitizeName } from './sanitize' import { isArray, isError, isNullish } from '../utils' import { @@ -512,13 +518,14 @@ function readStack(error: unknown): { stack?: string } { } /** - * 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. + * The handle to return when a span cannot be recorded: a pass-through when a + * context is available, the shared no-op otherwise. With no explicit `parent` + * the active handle supplies it, so an inbound trace survives nesting. * * @internal Exposed for cross-package use within this SDK; not part of the stable public API. */ -export function inertSpan(options?: { parent?: unknown; tracestate?: unknown }): Span { - const parent = options?.parent +export function inertSpan(options?: { parent?: unknown; tracestate?: unknown }, active?: Span): Span { + const parent = traceparentHeader(options?.parent) ?? active // A handle parent reports its own context, read behind a guard because a // foreign handle's accessor may throw. A no-op reports none and stays a no-op. const inbound = typeof parent === 'string' || parent == null ? parent : readHandle(parent, 'traceparent') diff --git a/packages/core/src/traces/traceparent.spec.ts b/packages/core/src/traces/traceparent.spec.ts index 2b65face90..4621e69223 100644 --- a/packages/core/src/traces/traceparent.spec.ts +++ b/packages/core/src/traces/traceparent.spec.ts @@ -107,11 +107,21 @@ describe('traceparent', () => { ['a member without a value', 'vendor'], ['a non-string', 42], ['undefined', undefined], - ['more than 32 members', Array.from({ length: 33 }, (_v, i) => `k${i}=v`).join(',')], - ['an overlong value', `vendor=${'a'.repeat(600)}`], + ['a single member longer than the whole limit', `vendor=${'a'.repeat(600)}`], ])('discards %s', (_name, value) => { expect(sanitizeTracestate(value)).toBeUndefined() }) + + it('keeps the first 32 members of a longer list', () => { + const members = Array.from({ length: 33 }, (_v, i) => `k${i}=v`) + expect(sanitizeTracestate(members.join(','))).toBe(members.slice(0, 32).join(',')) + }) + + it('keeps the members that fit inside the length limit', () => { + // 102 characters each, so the fifth crosses 512 and the first four stay. + const members = Array.from({ length: 6 }, (_v, i) => `k${i}=${'a'.repeat(100)}`) + expect(sanitizeTracestate(members.join(','))).toBe(members.slice(0, 4).join(',')) + }) }) }) diff --git a/packages/core/src/traces/traceparent.ts b/packages/core/src/traces/traceparent.ts index 1593ffecf0..cee0e310da 100644 --- a/packages/core/src/traces/traceparent.ts +++ b/packages/core/src/traces/traceparent.ts @@ -80,6 +80,15 @@ export function normalizeTraceparent(value: unknown): string | undefined { return matchTraceparent(value) && (value as string).trim() } +/** + * A `traceparent` as the string it is, unwrapping the one-element array Node's + * `headersDistinct` hands over. A longer array is two different inbound values, + * and picking either would be a guess. + */ +export function traceparentHeader(value: unknown): unknown { + return Array.isArray(value) && value.length === 1 ? value[0] : value +} + /** The W3C sampled bit, set on a trace this SDK started. */ export const TRACE_FLAGS_SAMPLED = '01' @@ -103,15 +112,19 @@ const TRACESTATE_MAX_LENGTH = 512 /** * Validates an incoming `tracestate` far enough to know it is safe to echo back. - * An invalid one is discarded without invalidating its traceparent, so a - * malformed vendor entry never costs us the trace continuation. + * A malformed one is discarded without invalidating its traceparent, so a bad + * vendor entry never costs us the trace continuation. + * + * Over-long input is trimmed rather than discarded: W3C makes the limits a + * reason to drop members from the end, so the entries that fit are still valid + * state the next hop can use. */ export function sanitizeTracestate(value: unknown): string | undefined { if (typeof value !== 'string') { return undefined } const trimmed = value.trim() - if (!trimmed || trimmed.length > TRACESTATE_MAX_LENGTH) { + if (!trimmed) { return undefined } // W3C restricts tracestate to printable ASCII plus HTAB as optional whitespace. @@ -121,9 +134,6 @@ export function sanitizeTracestate(value: unknown): string | undefined { return undefined } const members = trimmed.split(',') - if (members.length > TRACESTATE_MAX_MEMBERS) { - return undefined - } for (const member of members) { // An empty member is tolerated by the spec (list optional-white-space), but // a member without a `=` is not a key/value pair at all. @@ -131,5 +141,15 @@ export function sanitizeTracestate(value: unknown): string | undefined { return undefined } } - return trimmed + const kept: string[] = [] + let length = 0 + for (const member of members.slice(0, TRACESTATE_MAX_MEMBERS)) { + const separator = kept.length ? 1 : 0 + if (length + separator + member.length > TRACESTATE_MAX_LENGTH) { + break + } + kept.push(member) + length += separator + member.length + } + return kept.length ? kept.join(',') : undefined } diff --git a/packages/node/src/client.ts b/packages/node/src/client.ts index 5b83a9524f..8194d73224 100644 --- a/packages/node/src/client.ts +++ b/packages/node/src/client.ts @@ -714,7 +714,7 @@ export abstract class PostHogBackendClient extends PostHogCoreStateless implemen * ``` */ startSpan(name: string, options?: StartSpanOptions): Span { - return this._tracesPipeline?.startSpan(name, options) ?? inertSpan(options) + return this._tracesPipeline?.startSpan(name, options) ?? inertSpan(options, this._spanContextManager.active()) } /** @@ -756,7 +756,7 @@ export abstract class PostHogBackendClient extends PostHogCoreStateless implemen // Tracing off: still run the callback exactly once, with an inert handle. // A handle carrying an inbound `parent` is activated, so `getActiveSpan()` // inside the callback can propagate the trace onward. - return runWithActiveSpan(this._spanContextManager, inertSpan(options), fn) + return runWithActiveSpan(this._spanContextManager, inertSpan(options, this._spanContextManager.active()), fn) } return options ? pipeline.withSpan(name, options, fn) : pipeline.withSpan(name, fn) }