diff --git a/.changeset/traces-age-sweep-at-bound.md b/.changeset/traces-age-sweep-at-bound.md new file mode 100644 index 0000000000..2d29c20ab0 --- /dev/null +++ b/.changeset/traces-age-sweep-at-bound.md @@ -0,0 +1,7 @@ +--- +'@posthog/core': patch +'posthog-node': patch +'@posthog/types': patch +--- + +Stop dropping long spans that end: `maxSpanAgeMs` now evicts spans only once `maxLiveSpans` is reached, so a span that runs past the age limit and then ends is exported, and its children are no longer orphaned. diff --git a/packages/core/src/traces/index.spec.ts b/packages/core/src/traces/index.spec.ts index ee1e80324b..1deb0994b9 100644 --- a/packages/core/src/traces/index.spec.ts +++ b/packages/core/src/traces/index.spec.ts @@ -3192,11 +3192,11 @@ describe('PostHogTraces', () => { }) it('never exports a span evicted for exceeding maxSpanAgeMs', async () => { - const traces = createTraces({ maxSpanAgeMs: 60_000 }) + const traces = createTraces({ maxLiveSpans: 1, maxSpanAgeMs: 60_000 }) const leaked = traces.startSpan('leaked') await vi.advanceTimersByTimeAsync(61_000) - // Eviction is lazy: the next startSpan sweeps. + // Eviction is lazy: the next startSpan at the bound sweeps. traces.startSpan('later').end() leaked.end() await traces.flush() @@ -3205,9 +3205,22 @@ describe('PostHogTraces', () => { expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('still live after 60000ms')) }) + it('exports a long span that ends while under the bound', async () => { + const traces = createTraces({ maxSpanAgeMs: 60_000 }) + const longRunning = traces.startSpan('batch') + + await vi.advanceTimersByTimeAsync(61_000) + traces.startSpan('probe').end() + longRunning.end() + await traces.flush() + + expect(sentSpans().map((s) => s.name)).toEqual(['probe', 'batch']) + }) + it('returns the slot on age eviction so a leak cannot disable tracing', async () => { const traces = createTraces({ maxLiveSpans: 1, maxSpanAgeMs: 60_000 }) traces.startSpan('leaked-forever') + expect(traces.startSpan('refused')).toBe(NOOP_SPAN) await vi.advanceTimersByTimeAsync(61_000) traces.startSpan('after-the-leak').end() @@ -3217,15 +3230,15 @@ describe('PostHogTraces', () => { }) it('ages from startSpan, not from a caller-supplied startTime', async () => { - const traces = createTraces({ maxSpanAgeMs: 60_000 }) - // Backdated an hour: aging off the supplied time would evict it immediately. + const traces = createTraces({ maxLiveSpans: 1, maxSpanAgeMs: 60_000 }) + // Backdated an hour: aging off the supplied time would evict it at the next sweep. const backdated = traces.startSpan('backdated', { startTime: Date.now() - 3_600_000 }) - traces.startSpan('sweep-trigger').end() + expect(traces.startSpan('sweep-trigger')).toBe(NOOP_SPAN) backdated.end() await traces.flush() - expect(sentSpans().map((s) => s.name)).toEqual(['sweep-trigger', 'backdated']) + expect(sentSpans().map((s) => s.name)).toEqual(['backdated']) }) }) diff --git a/packages/core/src/traces/index.ts b/packages/core/src/traces/index.ts index a2f77e7ad1..d6b9773d4d 100644 --- a/packages/core/src/traces/index.ts +++ b/packages/core/src/traces/index.ts @@ -237,9 +237,12 @@ export class PostHogTraces { 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. - this._evictAgedSpans() + // Swept only at the bound, so a long span that does end is still exported, + // while a process that has leaked its way to the bound recovers on the + // first `startSpan` after the leaks age out. + if (this._liveSpans.size >= this._config.maxLiveSpans) { + this._evictAgedSpans() + } if (this._liveSpans.size >= this._config.maxLiveSpans) { this._recordDrop( 1, diff --git a/packages/core/src/traces/types.ts b/packages/core/src/traces/types.ts index f22ccc7301..8828ee3ba0 100644 --- a/packages/core/src/traces/types.ts +++ b/packages/core/src/traces/types.ts @@ -133,8 +133,8 @@ export interface ResolvedTracesConfig extends TracesConfig { maxEventsPerSpan: number maxAttributesPerEvent: number maxAttributeValueLength: number - /** Bound on spans started but not yet ended. At the bound `startSpan` returns a no-op handle. */ + /** Bound on spans started but not yet ended. At the bound `startSpan` evicts aged spans, then returns a no-op handle if still at the bound. */ maxLiveSpans: number - /** How long a span may stay live before it stops being accounted for and can never export. */ + /** Age at which a live span counts as leaked. Checked only at `maxLiveSpans`, where aged spans are evicted and never exported. */ maxSpanAgeMs: number } diff --git a/packages/types/src/traces.ts b/packages/types/src/traces.ts index 1881574ef1..da3fbd1fef 100644 --- a/packages/types/src/traces.ts +++ b/packages/types/src/traces.ts @@ -356,9 +356,11 @@ export interface TracesConfig { maxLiveSpans?: number /** - * How long a span may stay live before the SDK stops accounting for it, in - * milliseconds. An evicted span is never exported, and its slot is returned - * so one leak cannot disable tracing for the rest of the process. Measured + * Age at which a live span counts as leaked, in milliseconds. Checked only + * once `maxLiveSpans` is reached: spans this old are then evicted and never + * exported, and their slots are returned so one leak cannot disable tracing + * for the rest of the process. Below the bound, a long span that ends is + * exported as usual. Measured * as monotonic elapsed time since `startSpan`, so a caller-supplied * `startTime` neither ages a span early nor exempts it. *