diff --git a/.changeset/traces-context-and-time-fidelity.md b/.changeset/traces-context-and-time-fidelity.md new file mode 100644 index 0000000000..c2cab61516 --- /dev/null +++ b/.changeset/traces-context-and-time-fidelity.md @@ -0,0 +1,5 @@ +--- +'@posthog/core': patch +--- + +Forward an inbound `traceparent` whose version is above `00` whole, including the fields that version adds, rather than trimming it to the four this SDK reads. Keep the inbound context when a handle returned with tracing off is passed back as `parent`, so a child no longer starts a fresh trace. Warn when a span's `startTime` is in the future, which costs it its duration. diff --git a/packages/core/src/traces/index.spec.ts b/packages/core/src/traces/index.spec.ts index 20b412cfcc..a6d5aeb4a5 100644 --- a/packages/core/src/traces/index.spec.ts +++ b/packages/core/src/traces/index.spec.ts @@ -1,6 +1,6 @@ import { PostHogTraces } from './index' import { SyncSpanContextManager } from './context' -import { NOOP_SPAN } from './span' +import { NOOP_SPAN, inertSpan } from './span' import type { OtlpSpan, OtlpTracesPayload, @@ -171,6 +171,16 @@ describe('PostHogTraces', () => { expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('24 hours')) expect(sentSpans()).toHaveLength(1) }) + + it('warns when a start is in the future, which costs the span its duration', async () => { + const traces = createTraces() + traces.startSpan('ahead', { startTime: Date.now() + 60 * 60 * 1000 }).end() + await traces.flush() + + expect(logger.debug).toHaveBeenCalledWith(expect.stringContaining('in the future')) + const [span] = sentSpans() + expect(span.endTimeUnixNano).toBe(span.startTimeUnixNano) + }) }) describe('trace continuation', () => { @@ -493,6 +503,49 @@ describe('PostHogTraces', () => { expect(traces.startSpan('no-parent')).toBe(NOOP_SPAN) expect(traces.startSpan('bad-parent', { parent: 'not-a-traceparent' })).toBe(NOOP_SPAN) }) + + 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. + const traces = createTraces({}, createMockInstance({ optedOut: true })) + const parent = traces.startSpan('proxied', { parent: INBOUND_UNSAMPLED, tracestate: 'vendor=abc' }) + + const child = traces.startSpan('child', { parent }) + + expect(child.traceparent()).toBe(INBOUND_UNSAMPLED) + expect(child.tracestate()).toBe('vendor=abc') + expect(sentSpans()).toHaveLength(0) + }) + + it('records nothing for a child of a pass-through once tracing is back on', async () => { + // Spec: a child of an inert handle is inert, so this must propagate without + // enqueueing a span, even though this instance is recording. + const traces = createTraces() + const parent = inertSpan({ parent: INBOUND_UNSAMPLED }) + + const child = traces.startSpan('child', { parent }) + child.end() + await traces.flush() + + expect(child.traceparent()).toBe(INBOUND_UNSAMPLED) + expect(sentSpans()).toHaveLength(0) + }) + + it('yields a no-op for a child of a no-op', () => { + const traces = createTraces() + expect(traces.startSpan('child', { parent: NOOP_SPAN })).toBe(NOOP_SPAN) + }) + + it('survives a parent whose traceparent throws', () => { + const traces = createTraces() + const hostile = { + traceparent: () => { + throw new Error('nope') + }, + } + + expect(traces.startSpan('child', { parent: hostile as never })).toBe(NOOP_SPAN) + }) }) describe('auto-context', () => { @@ -992,6 +1045,49 @@ describe('PostHogTraces', () => { }) }) + describe('flush backoff', () => { + it('resumes the depth trigger after a non-retriable drop clears the backlog', async () => { + // A 503 burst raises the consecutive-failure count, which disables the + // depth trigger. Dropping the poison batch is progress, so the count has to + // clear with it or the queue stays on the slow timer while the endpoint is + // healthy. + mockInstance._sendTracesBatch + .mockResolvedValueOnce({ kind: 'retry-later', error: new Error('503') }) + .mockResolvedValueOnce({ kind: 'fatal', error: new Error('400') }) + .mockResolvedValue({ kind: 'ok' }) + + const traces = createTraces({ maxExportBatchSize: 1, flushIntervalMs: 10_000 }) + traces.startSpan('poison').end() + await flushMicrotasks() + await traces.flush() + mockInstance._sendTracesBatch.mockClear() + + // Depth trigger only fires again if the failure count was cleared. + traces.startSpan('after').end() + await flushMicrotasks() + + expect(mockInstance._sendTracesBatch).toHaveBeenCalled() + }) + + it('resumes the depth trigger after a too-large single-span drop', async () => { + mockInstance._sendTracesBatch + .mockResolvedValueOnce({ kind: 'retry-later', error: new Error('503') }) + .mockResolvedValueOnce({ kind: 'too-large' }) + .mockResolvedValue({ kind: 'ok' }) + + const traces = createTraces({ maxExportBatchSize: 1, flushIntervalMs: 10_000 }) + traces.startSpan('huge').end() + await flushMicrotasks() + await traces.flush() + mockInstance._sendTracesBatch.mockClear() + + traces.startSpan('after').end() + await flushMicrotasks() + + expect(mockInstance._sendTracesBatch).toHaveBeenCalled() + }) + }) + describe('drop accounting', () => { it('still warns about queue-full drops while the endpoint is failing', async () => { mockInstance._sendTracesBatch.mockResolvedValue({ kind: 'retry-later', error: new Error('down') }) diff --git a/packages/core/src/traces/index.ts b/packages/core/src/traces/index.ts index 89b42f1a14..3776416872 100644 --- a/packages/core/src/traces/index.ts +++ b/packages/core/src/traces/index.ts @@ -8,7 +8,7 @@ import type { TraceSdkContext, TracesHost, } from './types' -import { NOOP_SPAN, PostHogSpan, describeError, inertSpan, monotonicNow, runWithActiveSpan } from './span' +import { PostHogSpan, describeError, inertSpan, monotonicNow, runWithActiveSpan } from './span' import { newSpanId, newTraceId } from './ids' import { parseTraceparent, sanitizeTracestate } from './traceparent' import { resolveStartTime, sanitizeName } from './sanitize' @@ -115,9 +115,11 @@ export class PostHogTraces { const explicitParent = options?.parent if (explicitParent && typeof explicitParent !== 'string' && !isOwnSpan(explicitParent)) { if (looksLikeSpan(explicitParent)) { - // A child of a no-op is itself a no-op, never an orphan with invented ids. + // 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 NOOP_SPAN + return inertSpan(options) } // No `traceparent()` to read: `req.headers.traceparent` is `string[]` when the // header arrives twice, and a span from another tracer exposes `spanContext()` @@ -523,6 +525,7 @@ export class PostHogTraces { remaining -= 1 removed += 1 this._recordDrop(1, 'the ingestion endpoint rejected it as too large') + this._consecutiveFlushFailures = 0 this._headBatchFailures = 0 continue } @@ -560,6 +563,7 @@ export class PostHogTraces { this._queue.splice(0, size) remaining -= size removed += size + this._consecutiveFlushFailures = 0 this._headBatchFailures = 0 this._recordDrop(size, 'the ingestion endpoint rejected the batch') } diff --git a/packages/core/src/traces/sanitize.ts b/packages/core/src/traces/sanitize.ts index bd31398941..258620cf53 100644 --- a/packages/core/src/traces/sanitize.ts +++ b/packages/core/src/traces/sanitize.ts @@ -75,6 +75,10 @@ export function resolveStartTime(value: SpanTimeInput | undefined, now: number, logger?.debug( 'Span startTime is more than 24 hours in the past; the server will clamp it to receive time and keep the original in $originalTimestamp' ) + } else if (supplied > now) { + // Warned rather than clamped, matching the deep-backdate rule: the value is + // the caller's. The duration is what suffers, since the end clamps to it. + logger?.debug('Span startTime is in the future; the span may export with a zero duration') } return supplied } diff --git a/packages/core/src/traces/span.ts b/packages/core/src/traces/span.ts index 6336c00cbb..a93ea62d31 100644 --- a/packages/core/src/traces/span.ts +++ b/packages/core/src/traces/span.ts @@ -269,11 +269,26 @@ export class PassThroughSpan extends NoopSpan { * caller supplied a usable `parent` header, the shared no-op otherwise. */ export function inertSpan(options?: { parent?: unknown; tracestate?: unknown }): Span { - const traceparent = normalizeTraceparent(options?.parent) + const parent = options?.parent + // 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') + const traceparent = normalizeTraceparent(inbound) if (!traceparent) { return NOOP_SPAN } - return new PassThroughSpan(traceparent, sanitizeTracestate(options?.tracestate)) + const tracestate = + typeof parent === 'string' || parent == null ? options?.tracestate : readHandle(parent, 'tracestate') + return new PassThroughSpan(traceparent, sanitizeTracestate(tracestate)) +} + +function readHandle(parent: unknown, method: 'traceparent' | 'tracestate'): unknown { + try { + const fn = (parent as Span)[method] + return typeof fn === 'function' ? fn.call(parent) : undefined + } catch { + return undefined + } } /** diff --git a/packages/core/src/traces/traceparent.spec.ts b/packages/core/src/traces/traceparent.spec.ts index 872fea75cd..2b65face90 100644 --- a/packages/core/src/traces/traceparent.spec.ts +++ b/packages/core/src/traces/traceparent.spec.ts @@ -140,8 +140,12 @@ describe('normalizeTraceparent', () => { expect(normalizeTraceparent(`01-${TRACE_ID}-${SPAN_ID}-01`)).toBe(`01-${TRACE_ID}-${SPAN_ID}-01`) }) - it("trims surrounding whitespace, and drops a higher version's trailing fields", () => { - expect(normalizeTraceparent(` 01-${TRACE_ID}-${SPAN_ID}-01-extra `)).toBe(`01-${TRACE_ID}-${SPAN_ID}-01`) + it("keeps a higher version's trailing fields, so a peer that reads them still can", () => { + expect(normalizeTraceparent(`01-${TRACE_ID}-${SPAN_ID}-01-extra`)).toBe(`01-${TRACE_ID}-${SPAN_ID}-01-extra`) + }) + + it('trims surrounding whitespace', () => { + expect(normalizeTraceparent(` 00-${TRACE_ID}-${SPAN_ID}-01 `)).toBe(`00-${TRACE_ID}-${SPAN_ID}-01`) }) it.each([ diff --git a/packages/core/src/traces/traceparent.ts b/packages/core/src/traces/traceparent.ts index 826cd22456..1593ffecf0 100644 --- a/packages/core/src/traces/traceparent.ts +++ b/packages/core/src/traces/traceparent.ts @@ -70,13 +70,14 @@ function matchTraceparent(value: unknown): TraceparentFields | undefined { } /** - * The canonical form of an inbound `traceparent`, or `undefined` when it is - * malformed. Version and flags are carried through as received, so a service - * that forwards this value continues the caller's trace exactly as sent. + * The inbound `traceparent` as received, or `undefined` when it is malformed. + * + * Returned whole rather than rebuilt: a version above `00` may append fields + * this SDK does not read, and rebuilding would forward a header still labelled + * with that version but missing what the version defines. */ export function normalizeTraceparent(value: unknown): string | undefined { - const fields = matchTraceparent(value) - return fields && `${fields.version}-${fields.traceId}-${fields.spanId}-${fields.flags}` + return matchTraceparent(value) && (value as string).trim() } /** The W3C sampled bit, set on a trace this SDK started. */