From 759b44aeeabc304b9e0b441acbd4aa75958a8afd Mon Sep 17 00:00:00 2001 From: Ruben Van Assche Date: Thu, 28 May 2026 11:43:11 +0200 Subject: [PATCH] Tie trace ids to active lifetime, add Flare::start()/end() Fixes a correlation bug where the boot-time traceId/spanId persisted whenever a trace was not actively sampling. In long-lived processes (queue workers, Octane, or any setup with tracing disabled), every error and log across every request carried the same ids, so the backend could not distinguish one logical unit of work from another. Trace context lifecycle: - Tracer no longer pre-generates ids in the constructor. currentTraceId/SpanId start as null. - startTrace generates fresh ids per call, is idempotent while a trace is active (currentTraceId !== null), and adopts inbound traceparent ids even when the tracer is disabled so logs stay correlated. - endTrace and unsample clear the ids unconditionally. - Lifecycle::terminated always calls endTrace, including for unsampled traces, so the trace context is always cleaned up between iterations. - traceParent() returns ?string; null when there is no active context. Recorders: - SpansRecorder skips when there is no active trace, so recorders consume trace context instead of fabricating it. Convenience API: - Flare::start() registers the global handlers and opens the lifecycle in a single call. Throws in subtask mode. - Flare::end() finalises the lifecycle. Optional, the shutdown handler still covers process exit. Tests that bypass Lifecycle now call startTrace explicitly. The UPGRADING.md and PHP docs/install guides recommend Flare::start(). --- UPGRADING.md | 12 +++ src/Flare.php | 35 ++++++++ src/Recorders/SpansRecorder.php | 8 +- src/Support/Lifecycle.php | 2 + src/Tracer.php | 90 ++++++++++--------- tests/FlareTest.php | 18 ++++ .../QueryRecorder/QueryRecorderTest.php | 2 + tests/Recorders/SpanEventsRecorderTest.php | 4 + tests/Recorders/SpansRecorderTest.php | 8 ++ tests/TracerTest.php | 74 +++++++++++---- 10 files changed, 193 insertions(+), 60 deletions(-) diff --git a/UPGRADING.md b/UPGRADING.md index 334209e9..53c4e5cd 100644 --- a/UPGRADING.md +++ b/UPGRADING.md @@ -2,6 +2,18 @@ There are some breaking changes you should be aware of. We've categorized them so you can prioritize. This guide covers the most common cases. Edge cases may not be covered, and PRs to improve it are welcome. +## From v3.0 to v3.1 + +`Tracer::currentTraceId()`, `currentSpanId()`, and `traceParent()` now return `?string`, with `null` when no trace is active. Recorders skip silently without an active trace instead of recording orphan spans. + +If you use `spatie/laravel-flare` no changes are needed. For framework agnostic apps, replace `registerFlareHandlers()` with `$flare->start()`, which also opens the lifecycle: + +```php +$flare = Flare::make($config)->start(); +``` + +For subtask mode (queue workers, long-running processes), keep using `$flare->lifecycle->startSubtask()` per work unit. + ## From v2 to v3 The new version of the package adds better support for logging and tracing lifetimes. We don't expect upgrading to require a lot of code changes for typical applications. diff --git a/src/Flare.php b/src/Flare.php index 1a2fed0f..d5775f1e 100755 --- a/src/Flare.php +++ b/src/Flare.php @@ -64,6 +64,41 @@ public static function make( return $container->get(Flare::class); } + public function start( + ?int $timeUnixNano = null, + array $attributes = [], + ?string $traceparent = null, + ): self { + if ($this->lifecycle->usesSubtasks) { + throw new Exception( + 'Flare::start() is for the main lifecycle. In subtask mode, use $flare->lifecycle->startSubtask() per work unit.' + ); + } + + $this->reporter->registerFlareHandlers(); + $this->lifecycle->start($timeUnixNano, $attributes, $traceparent); + + return $this; + } + + public function end( + ?int $timeUnixNano = null, + array $additionalTerminationAttributes = [], + array $additionalApplicationAttributes = [], + ): void { + if ($this->lifecycle->usesSubtasks) { + throw new Exception( + 'Flare::end() is for the main lifecycle. In subtask mode, use $flare->lifecycle->endSubtask() per work unit.' + ); + } + + $this->lifecycle->terminated( + $timeUnixNano, + $additionalTerminationAttributes, + $additionalApplicationAttributes, + ); + } + public function registerFlareHandlers(): self { $this->reporter->registerFlareHandlers(); diff --git a/src/Recorders/SpansRecorder.php b/src/Recorders/SpansRecorder.php index d35157ac..76952c31 100644 --- a/src/Recorders/SpansRecorder.php +++ b/src/Recorders/SpansRecorder.php @@ -86,6 +86,12 @@ final protected function startSpan( return null; } + $currentTraceId = $this->tracer->currentTraceId(); + + if ($currentTraceId === null) { + return null; + } + if ($nameAndAttributes !== null) { ['name' => $name, 'attributes' => $attributes] = $nameAndAttributes(); } else { @@ -98,7 +104,7 @@ final protected function startSpan( $spanId = $this->tracer->nextSpanId(); $span = new Span( - traceId: $this->tracer->currentTraceId(), + traceId: $currentTraceId, spanId: $spanId, parentSpanId: $parentSpanId, name: $name, diff --git a/src/Support/Lifecycle.php b/src/Support/Lifecycle.php index be699835..87243427 100644 --- a/src/Support/Lifecycle.php +++ b/src/Support/Lifecycle.php @@ -324,6 +324,8 @@ public function terminated( $this->stage = LifecycleStage::Terminated; if ($this->tracer->sampling === false) { + $this->tracer->endTrace(); + return; } diff --git a/src/Tracer.php b/src/Tracer.php index 8e5227b6..c014dd05 100644 --- a/src/Tracer.php +++ b/src/Tracer.php @@ -36,11 +36,11 @@ class Tracer /** @var array @param array{max_spans: int, max_attributes_per_span: int, max_span_events_per_span: int, max_attributes_per_span_event: int}|null */ public readonly array $limits; - protected string $currentTraceId; + protected ?string $currentTraceId = null; - protected string $currentSpanId; + protected ?string $currentSpanId = null; - protected bool $currentSpanIdAvailable; + protected bool $currentSpanIdAvailable = true; /** * @param array{max_spans: int, max_attributes_per_span: int, max_span_events_per_span: int, max_attributes_per_span_event: int}|null $limits @@ -64,10 +64,6 @@ public function __construct( public readonly bool $disabled = false, protected Closure|null $gracefulSpanEnderClosure = null, ) { - $this->currentTraceId = $this->ids->trace(); - $this->currentSpanId = $this->ids->span(); - $this->currentSpanIdAvailable = true; - $this->limits = [ 'max_spans' => $limits['max_spans'] ?? self::DEFAULT_MAX_SPANS_LIMIT, 'max_attributes_per_span' => $limits['max_attributes_per_span'] ?? self::DEFAULT_MAX_ATTRIBUTES_PER_SPAN_LIMIT, @@ -81,35 +77,38 @@ public function startTrace( ?string $spanId = null, ?string $traceParent = null, ): bool { - if ($this->disabled === true) { - return false; + if ($this->currentTraceId !== null) { + return $this->sampling; } - if ($this->sampling) { - return $this->sampling; + if (($traceId === null) !== ($spanId === null)) { + throw new Exception('If one of traceId or spanId is provided, both must be provided.'); } $parentSampled = null; + $currentSpanAvailable = true; - if ($traceParent !== null) { - $parsed = $this->ids->parseTraceparent($traceParent); + $parsedTraceParent = $traceParent !== null + ? $this->ids->parseTraceparent($traceParent) + : null; - if ($parsed !== null) { - $traceId = $parsed['traceId']; - $spanId = $parsed['parentSpanId']; - $parentSampled = $parsed['sampling']; - } + if ($traceId !== null && $spanId !== null) { + $currentSpanAvailable = false; } - if (($traceId === null) !== ($spanId === null)) { - throw new Exception('If one of traceId or spanId is provided, both must be provided.'); + if ($parsedTraceParent) { + $traceId = $parsedTraceParent['traceId']; + $spanId = $parsedTraceParent['parentSpanId']; + $parentSampled = $parsedTraceParent['sampling']; + $currentSpanAvailable = false; } - if ($traceId !== null && $spanId !== null) { - $this->currentTraceId = $traceId; - $this->currentSpanId = $spanId; - $this->currentSpanIdAvailable = false; - $this->spans = []; + $this->currentTraceId = $traceId ?? $this->ids->trace(); + $this->currentSpanId = $spanId ?? $this->ids->span(); + $this->currentSpanIdAvailable = $currentSpanAvailable; + + if ($this->disabled === true) { + return false; } return $this->sampling = $this->sampler->shouldSample( @@ -124,12 +123,8 @@ public function endTrace(): void $this->sampler->reset(); } - if ($this->sampling === false) { - return; - } - - $this->currentTraceId = $this->ids->trace(); - $this->currentSpanId = $this->ids->span(); + $this->currentTraceId = null; + $this->currentSpanId = null; $this->currentSpanIdAvailable = true; $this->sampling = false; @@ -173,11 +168,8 @@ public function unsample(): void } $this->paused = false; - - if ($this->sampling === false) { - return; - } - + $this->currentTraceId = null; + $this->currentSpanId = null; $this->currentSpanIdAvailable = true; $this->sampling = false; $this->spans = []; @@ -213,12 +205,12 @@ public function isSamplingPaused(): bool return $this->paused; } - public function currentTraceId(): string + public function currentTraceId(): ?string { return $this->currentTraceId; } - public function currentSpanId(): string + public function currentSpanId(): ?string { return $this->currentSpanId; } @@ -232,7 +224,7 @@ public function currentParentSpanId(): ?string public function nextSpanId(): string { - if ($this->sampling && $this->currentSpanIdAvailable === true) { + if ($this->sampling && $this->currentSpanIdAvailable === true && $this->currentSpanId !== null) { $this->currentSpanIdAvailable = false; return $this->currentSpanId; @@ -241,11 +233,15 @@ public function nextSpanId(): string return $this->ids->span(); } - public function traceParent(): string + public function traceParent(): ?string { + if ($this->currentTraceId === null || $this->currentSpanId === null) { + return null; + } + return $this->ids->traceParent( - $this->currentTraceId ?? '', - $this->currentSpanId ?? '', + $this->currentTraceId, + $this->currentSpanId, $this->isSampling(), ); } @@ -283,6 +279,10 @@ public function hasCurrentSpan(?FlareSpanType $spanType = null): bool public function currentSpan(): ?Span { + if ($this->currentSpanId === null) { + return null; + } + return $this->spans[$this->currentSpanId] ?? null; } @@ -312,12 +312,16 @@ public function startSpan( ?int $time = null, array $attributes = [], ): Span|AddSpanResult { + if ($this->currentTraceId === null) { + throw new Exception('Cannot start a span without an active trace.'); + } + // Order of operations is important here, do not inline! $parentSpanId = $this->currentParentSpanId(); $spanId = $this->nextSpanId(); $span = new Span( - traceId: $this->currentTraceId ?? $this->ids->trace(), + traceId: $this->currentTraceId, spanId: $spanId, parentSpanId: $parentSpanId, name: $name, diff --git a/tests/FlareTest.php b/tests/FlareTest.php index b7ee07bd..20170c97 100644 --- a/tests/FlareTest.php +++ b/tests/FlareTest.php @@ -43,6 +43,16 @@ ); }); +it('can start and end a flare lifecycle', function () { + $flare = setupFlare(alwaysSampleTraces: true)->start(); + + expect($flare->tracer->isSampling())->toBeTrue(); + + $flare->end(); + + expect($flare->tracer->isSampling())->toBeFalse(); +}); + it('can reset queued exceptions', function () { $flare = setupFlare(fn (FlareConfig $config) => $config->collectContext()); @@ -375,6 +385,8 @@ it('can add queries', function () { $flare = setupFlare(fn (FlareConfig $config) => $config->collectQueries()); + $flare->tracer->startTrace(); + $flare->query()->record( 'select * from users where id = ?', TimeHelper::milliseconds(250), @@ -423,6 +435,8 @@ it('can begin and commit transactions', function () { $flare = setupFlare(fn (FlareConfig $config) => $config->collectTransactions()); + $flare->tracer->startTrace(); + $flare->transaction()->recordBegin(); FakeTime::setup('2019-01-01 12:34:57'); // One second later 1546346097000000 @@ -446,6 +460,8 @@ it('can begin and rollback transactions', function () { $flare = setupFlare(fn (FlareConfig $config) => $config->collectTransactions()); + $flare->tracer->startTrace(); + $flare->transaction()->recordBegin(); FakeTime::setup('2019-01-01 12:34:57'); // One second later 1546346097000000 @@ -831,6 +847,8 @@ ]) ); + $flare->tracer->startTrace(); + $flare->recorder('spans')->record('Hi', duration: TimeHelper::milliseconds(300)); $throwable = new RuntimeException('This is a test'); diff --git a/tests/Recorders/QueryRecorder/QueryRecorderTest.php b/tests/Recorders/QueryRecorder/QueryRecorderTest.php index 45eacf53..fc9e9d10 100644 --- a/tests/Recorders/QueryRecorder/QueryRecorderTest.php +++ b/tests/Recorders/QueryRecorder/QueryRecorderTest.php @@ -235,6 +235,8 @@ ] ); + $flare->tracer->startTrace(); + $recorder->record('select * from users where id = ?', TimeHelper::milliseconds(299), ['id' => 1], 'users', 'mysql'); expect($recorder->getSpans())->toHaveCount(1); diff --git a/tests/Recorders/SpanEventsRecorderTest.php b/tests/Recorders/SpanEventsRecorderTest.php index 572ed044..659b7896 100644 --- a/tests/Recorders/SpanEventsRecorderTest.php +++ b/tests/Recorders/SpanEventsRecorderTest.php @@ -124,6 +124,8 @@ 'with_traces' => true, ]); + $flare->tracer->startTrace(); + $span = $flare->tracer->startSpan( 'root span' ); @@ -236,6 +238,8 @@ public function record(string $message): ?SpanEvent 'find_origin' => false, ]); + $flare->tracer->startTrace(); + $span = $flare->tracer->startSpan('Parent Span'); $recorder->record('Hello World'); diff --git a/tests/Recorders/SpansRecorderTest.php b/tests/Recorders/SpansRecorderTest.php index bc0ab7f6..351fed7e 100644 --- a/tests/Recorders/SpansRecorderTest.php +++ b/tests/Recorders/SpansRecorderTest.php @@ -42,6 +42,8 @@ 'with_traces' => false, ]); + $flare->tracer->startTrace(); + $recorder->record('Span', 100); $spans = $recorder->getSpans(); @@ -65,6 +67,8 @@ 'max_items_with_errors' => 35, ]); + $flare->tracer->startTrace(); + foreach (range(1, 40) as $i) { $recorder->pushSpan("Span - Hello {$i}"); $recorder->popSpan(); @@ -83,6 +87,8 @@ 'max_items_with_errors' => null, ]); + $flare->tracer->startTrace(); + foreach (range(1, 250) as $i) { $recorder->pushSpan("Hello {$i}"); $recorder->popSpan(); @@ -164,6 +170,8 @@ public function recordMessage(string $message): ?Span $flare = setupFlare(alwaysSampleTraces: true); + $flare->tracer->startTrace(); + expect(fn () => (new TestConcreteSpanRecorderExecution($flare->tracer, $flare->backTracer, config: [ 'with_traces' => true, 'with_errors' => true, diff --git a/tests/TracerTest.php b/tests/TracerTest.php index b2865343..7db02988 100644 --- a/tests/TracerTest.php +++ b/tests/TracerTest.php @@ -241,17 +241,16 @@ expect($span->spanId)->not()->toBeNull(); }); -it('can unsample a trace and all its spans', function () { +it('can unsample a trace and clear its state', function () { $tracer = setupFlare(alwaysSampleTraces: true)->tracer; $tracer->startTrace(); - - $span = $tracer->startSpan('Some span'); + $tracer->startSpan('Some span'); $tracer->unsample(); - expect($tracer->currentTraceId())->toBe($span->traceId); - expect($tracer->currentSpanId())->toBe($span->spanId); + expect($tracer->currentTraceId())->toBeNull(); + expect($tracer->currentSpanId())->toBeNull(); expect($tracer->sampling)->toBeFalse(); expect($tracer->currentTrace())->toBeEmpty(); }); @@ -387,27 +386,70 @@ expect($span->events[0]->name)->toEqual('Some event'); }); -it('will always have a trace and span id even when a trace start call has not happened yet', function () { +it('has no trace and span id before startTrace is called', function () { $tracer = setupFlare()->tracer; - expect($tracer->currentTraceId())->not()->toBeNull(); - expect($tracer->currentSpanId())->not()->toBeNull(); + expect($tracer->currentTraceId())->toBeNull(); + expect($tracer->currentSpanId())->toBeNull(); }); -it('will use the initial trace and span id until a trace is started', function () { +it('clears the trace and span id when a sampled trace ends', function () { $tracer = setupFlare(alwaysSampleTraces: true)->tracer; - expect($tracer->currentTraceId())->not()->toBeNull(); - expect($tracer->currentSpanId())->not()->toBeNull(); + $tracer->startTrace(); + $tracer->startSpan('Some span'); + $tracer->endSpan(); + $tracer->endTrace(); + + expect($tracer->currentTraceId())->toBeNull(); + expect($tracer->currentSpanId())->toBeNull(); +}); - $currentTraceId = $tracer->currentTraceId(); - $currentSpanId = $tracer->currentSpanId(); + +it('preserves the active trace when startTrace is called again on an unsampled trace', function () { + $tracer = setupFlare(fn (FlareConfig $config) => $config->sampler(NeverSampler::class))->tracer; $tracer->startTrace(); - $span = $tracer->startSpan('Some span'); - expect($span->traceId)->toBe($currentTraceId); - expect($span->spanId)->toBe($currentSpanId); + $firstTraceId = $tracer->currentTraceId(); + $firstSpanId = $tracer->currentSpanId(); + + $tracer->startTrace(); + + expect($tracer->currentTraceId())->toBe($firstTraceId); + expect($tracer->currentSpanId())->toBe($firstSpanId); +}); + +it('adopts an inbound traceparent even when the tracer is disabled so logs stay correlated', function () { + $tracer = setupFlare(fn (FlareConfig $config) => $config->trace = false)->tracer; + + $tracer->startTrace(traceParent: '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01'); + + expect($tracer->sampling)->toBeFalse(); + expect($tracer->currentTraceId())->toBe('0af7651916cd43dd8448eb211c80319c'); + expect($tracer->currentSpanId())->toBe('b7ad6b7169203331'); +}); + +it('returns a null traceparent when there is no active trace context', function () { + $tracer = setupFlare()->tracer; + + expect($tracer->traceParent())->toBeNull(); +}); + +it('returns a traceparent with the local sampling flag when a trace context exists', function () { + $tracer = setupFlare(alwaysSampleTraces: true)->tracer; + + $tracer->startTrace(); + + expect($tracer->traceParent())->toMatch('/^00-[0-9a-f]{32}-[0-9a-f]{16}-01$/'); +}); + +it('propagates an inherited traceparent for downstream services even when not sampling locally', function () { + $tracer = setupFlare(fn (FlareConfig $config) => $config->trace = false)->tracer; + + $tracer->startTrace(traceParent: '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01'); + + expect($tracer->traceParent())->toMatch('/^00-0af7651916cd43dd8448eb211c80319c-[0-9a-f]{16}-00$/'); }); it('can include the peak memory usage when ending a span', function () {