fix(traces): keep the inbound trace context through nested spans

.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.

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>): 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(

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.

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')

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(','))
+    })
   })
 })