Skip to content

Commit 462ef48

Browse files
authored
fix: correct telemetry span nesting and lifecycle (#2561)
1 parent c558865 commit 462ef48

68 files changed

Lines changed: 2150 additions & 175 deletions

File tree

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

documentation/components/core/transformations.md

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -232,6 +232,14 @@ This pattern is particularly useful when you need to:
232232
- Create transformation pipelines that can be reused
233233
- Separate transformation logic from extraction and loading
234234

235+
The `Transformation` is expanded **once per loader instance**, on the first batch, and every subsequent batch is
236+
streamed through that same pipeline. Stateful transformations - `limit()`, `add_row_index()` - therefore apply across
237+
the whole stream, not per batch.
238+
239+
Batching transformations (`batch_size()`, `batch_by()`) expand to a `Processor`, which re-batches only within the
240+
batches the outer pipeline hands the loader - a `Loader` never sees the stream. To re-batch the pipeline itself, use
241+
`$df->batchSize(...)` instead of `to_transformation(batch_size(...), ...)`.
242+
235243
## Creating Custom Transformations
236244

237245
You can create custom transformations by implementing the `Transformation` interface:

documentation/components/libs/telemetry.md

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -286,6 +286,36 @@ $span->setAttribute('order.total', 99.99);
286286
$tracer->complete($span);
287287
```
288288

289+
**Nesting spans:**
290+
291+
Creating a span does not make it the current one — per the OpenTelemetry specification, span creation must not
292+
change the active context. A span created inside another becomes its child only if the outer span was activated:
293+
294+
```php
295+
<?php
296+
297+
$order = $tracer->span('process-order');
298+
$scope = $tracer->activate($order);
299+
300+
try {
301+
// child of 'process-order'
302+
$tracer->complete($tracer->span('charge-card'));
303+
} finally {
304+
$scope->detach();
305+
$tracer->complete($order);
306+
}
307+
```
308+
309+
Without `activate()`, `charge-card` is a sibling of `process-order`, not a child.
310+
311+
Detach scopes in reverse order of activation, and before completing the span. `Scope::detach()` returns
312+
`Scope::DETACHED` on success, `Scope::INACTIVE` if the scope was already detached, and `Scope::MISMATCH` if it was
313+
not the innermost active scope.
314+
315+
Do **not** activate a span whose lifetime is an object rather than a block — a file stream, a database cursor, a
316+
long-running transaction handle. Several of those are open at once, so activating them makes each the parent of
317+
whichever is opened next, producing a staircase instead of siblings. Start such spans and leave them inactive.
318+
289319
For automatic exception handling and span completion, use the `trace()` method:
290320

291321
```php

documentation/components/libs/telemetry/contracts.md

Lines changed: 21 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -67,8 +67,9 @@ Three small immutable value objects in `Flow\Telemetry\Batch` carry the payload
6767

6868
**Interface:** `Flow\Telemetry\Context\ContextStorage`
6969

70-
Stores and retrieves telemetry context (active span, baggage) within a request lifecycle. Enables automatic context
71-
propagation to child spans.
70+
Stores and retrieves telemetry context (active span, baggage) within a request lifecycle. `attach()` returns a
71+
`Scope` that must be detached in reverse order; a span becomes the parent of later spans only while its scope is
72+
attached — see `Tracer::activate()`.
7273

7374
| Implementation | Package | Description |
7475
|------------------------|----------------------|--------------------------------------------|
@@ -102,12 +103,12 @@ sits between the Tracer and the unified `Exporter`. The `exporter()` accessor re
102103
Makes sampling decisions for traces. Determines whether a span should be recorded and exported based on configurable
103104
rules.
104105

105-
| Implementation | Package | Description |
106-
|----------------------------|----------------------|-----------------------------------------------------|
107-
| `AlwaysOnSampler` | `flow-php/telemetry` | Records all traces |
108-
| `AlwaysOffSampler` | `flow-php/telemetry` | Records no traces |
109-
| `TraceIdRatioBasedSampler` | `flow-php/telemetry` | Records a configurable percentage of traces |
110-
| `ParentBasedSampler` | `flow-php/telemetry` | Inherits sampling decision from parent span context |
106+
| Implementation | Package | Description |
107+
|----------------------------|----------------------|----------------------------------------------------------------------------------------------------------|
108+
| `AlwaysOnSampler` | `flow-php/telemetry` | Records all traces |
109+
| `AlwaysOffSampler` | `flow-php/telemetry` | Records no traces |
110+
| `TraceIdRatioBasedSampler` | `flow-php/telemetry` | Records a configurable percentage of traces |
111+
| `ParentBasedSampler` | `flow-php/telemetry` | Inherits sampling decision from parent span context |
111112
| `AttributeMatchingSampler` | `flow-php/telemetry` | Drops spans matching an `AttributeFilter` (start-time attributes), defers the rest to a delegate sampler |
112113

113114
---
@@ -168,13 +169,13 @@ Processes log records from loggers. Determines how logs are buffered and when th
168169
(marker interface extending `LogProcessor`) identifies the terminal/leaf processors; `PipelineLogProcessor` runs an
169170
ordered chain of `LogMiddleware` and forwards survivors to one `LogSink`.
170171

171-
| Implementation | Package | Sink? | Description |
172-
|---------------------------|----------------------|-------|------------------------------------------------------|
173-
| `PassThroughLogProcessor` | `flow-php/telemetry` | yes | Exports each log immediately when recorded |
174-
| `BatchingLogProcessor` | `flow-php/telemetry` | yes | Buffers logs and exports in configurable batches |
175-
| `CompositeLogProcessor` | `flow-php/telemetry` | yes | Delegates to multiple processors |
176-
| `MemoryLogProcessor` | `flow-php/telemetry` | yes | Stores logs in memory for testing |
177-
| `VoidLogProcessor` | `flow-php/telemetry` | yes | No-op processor that discards all logs |
172+
| Implementation | Package | Sink? | Description |
173+
|---------------------------|----------------------|-------|--------------------------------------------------------|
174+
| `PassThroughLogProcessor` | `flow-php/telemetry` | yes | Exports each log immediately when recorded |
175+
| `BatchingLogProcessor` | `flow-php/telemetry` | yes | Buffers logs and exports in configurable batches |
176+
| `CompositeLogProcessor` | `flow-php/telemetry` | yes | Delegates to multiple processors |
177+
| `MemoryLogProcessor` | `flow-php/telemetry` | yes | Stores logs in memory for testing |
178+
| `VoidLogProcessor` | `flow-php/telemetry` | yes | No-op processor that discards all logs |
178179
| `PipelineLogProcessor` | `flow-php/telemetry` | no | Runs middleware in order, then forwards to a `LogSink` |
179180

180181
### LogMiddleware
@@ -184,11 +185,11 @@ ordered chain of `LogMiddleware` and forwards survivors to one `LogSink`.
184185
A chainable step inside a `PipelineLogProcessor`. `process(LogEntry): ?LogEntry` returns the entry to pass on (possibly
185186
enriched) or `null` to drop it. Stateless - flush/shutdown belong to the pipeline's `LogSink`.
186187

187-
| Implementation | Package | Description |
188-
|------------------------------------|----------------------|------------------------------------------------------|
189-
| `EnrichingLogMiddleware` | `flow-php/telemetry` | Merges default attributes (call-site values win) |
190-
| `SeverityFilteringLogMiddleware` | `flow-php/telemetry` | Drops log entries below a minimum severity threshold |
191-
| `AttributeFilteringLogMiddleware` | `flow-php/telemetry` | Drops/keeps log entries by an `AttributeFilter` |
188+
| Implementation | Package | Description |
189+
|-----------------------------------|----------------------|------------------------------------------------------|
190+
| `EnrichingLogMiddleware` | `flow-php/telemetry` | Merges default attributes (call-site values win) |
191+
| `SeverityFilteringLogMiddleware` | `flow-php/telemetry` | Drops log entries below a minimum severity threshold |
192+
| `AttributeFilteringLogMiddleware` | `flow-php/telemetry` | Drops/keeps log entries by an `AttributeFilter` |
192193

193194
---
194195

documentation/upgrading.md

Lines changed: 55 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,59 @@ specific version to ensure a smooth upgrade process.
77

88
---
99

10+
## Upgrading from 0.42.x to 0.43.x
11+
12+
### 1) `flow-php/etl` - `to_transformation()` expands a `Transformation` once per loader, not once per batch
13+
14+
| Before | After |
15+
|-----------------------------------------------------------------------------------|-------------------------|
16+
| `to_transformation(limit(3), $loader)`, 6 batches → 6 rows loaded | 3 rows loaded |
17+
| `to_transformation(add_row_index('n'), $loader)`, 6 batches → `n = [1,1,1,1,1,1]` | `n = [1,2,3,4,5,6]` |
18+
| nested `DataFrame` span per batch | one nested span per run |
19+
20+
Unchanged: any pipeline using `->collect()`, `drop()`, `select()`, `mask_columns()`, `batch_size()`, `batch_by()`.
21+
22+
### 2) `flow-php/telemetry` - `Tracer::span()` no longer activates the span
23+
24+
| Before | After |
25+
|----------------------------------------------------|-------------------------------------------------------------------|
26+
| `$tracer->span('x')` makes the span current | does not; `$tracer->activate($span): Scope` does |
27+
| `$tracer->complete($span)` also detaches the scope | ends the span only |
28+
| `span(…, SpanContext $parentContext)` | `span(…, Context $parent)` |
29+
| `trace(…, SpanContext $parentContext)` | `trace(…, Context $parent)` |
30+
| `Scope::detach()` always returns `0` | returns `Scope::DETACHED`, `Scope::INACTIVE` or `Scope::MISMATCH` |
31+
32+
Call sites relying on implicit nesting still compile and silently produce siblings. Rewrite each one that needs
33+
children:
34+
35+
Before:
36+
37+
```php
38+
$span = $tracer->span('parent');
39+
40+
try {
41+
// ...
42+
} finally {
43+
$tracer->complete($span);
44+
}
45+
```
46+
47+
After:
48+
49+
```php
50+
$span = $tracer->span('parent');
51+
$scope = $tracer->activate($span);
52+
53+
try {
54+
// ...
55+
} finally {
56+
$scope->detach();
57+
$tracer->complete($span);
58+
}
59+
```
60+
61+
---
62+
1063
## Upgrading from 0.41.x to 0.42.x
1164

1265
### 1) `flow-php/symfony-telemetry-bundle` - messenger tracing simplified
@@ -479,6 +532,7 @@ Custom aggregators must implement `references()` - return the references the agg
479532
| `DataFrame::pivot()` | removed; `GroupedDataFrame::pivot()` only |
480533

481534
### 32) `flow-php/etl-adapter-csv`, `-excel`, `-json`,
535+
482536
`-xml` - explicit schema no longer projects partition columns away
483537

484538
| Before | After |
@@ -2255,7 +2309,7 @@ After:
22552309
->run();
22562310
```
22572311

2258-
### 4) ConfigBuilder::putInputIntoRows () output is now prefixed with _ (underscore)
2312+
### 4) ConfigBuilder::putInputIntoRows () output is now prefixed with _ (underscore)
22592313

22602314
In order to avoid collisions with datasets columns, additional columns created after using putInputIntoRows ()
22612315
would now be prefixed with `_` (underscore) symbol.

src/bridge/monolog/telemetry/tests/Flow/Bridge/Monolog/Telemetry/Tests/Integration/TelemetryHandlerIntegrationTest.php

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -233,7 +233,9 @@ public function test_logs_after_span_completion_have_no_trace_context(): void
233233
$monolog->pushHandler(telemetry_handler($context->logger));
234234

235235
$span = $tracer->span('short-operation');
236+
$scope = $tracer->activate($span);
236237
$monolog->info('Inside span');
238+
$scope->detach();
237239
$tracer->complete($span);
238240

239241
$monolog->info('After span completed');
@@ -255,10 +257,12 @@ public function test_logs_within_active_span_include_trace_and_span_ids(): void
255257
$monolog->pushHandler(telemetry_handler($context->logger));
256258

257259
$span = $tracer->span('process-order');
260+
$scope = $tracer->activate($span);
258261

259262
$monolog->info('Processing order', ['order_id' => 123]);
260263
$monolog->warning('Low inventory', ['product_id' => 456]);
261264

265+
$scope->detach();
262266
$tracer->complete($span);
263267

264268
$entries = $context->processor->entries();
@@ -436,14 +440,18 @@ public function test_nested_spans_propagate_child_span_id_to_logs(): void
436440
$monolog->pushHandler(telemetry_handler($context->logger));
437441

438442
$parentSpan = $tracer->span('parent-operation');
443+
$parentScope = $tracer->activate($parentSpan);
439444
$monolog->info('In parent span');
440445

441446
$childSpan = $tracer->span('child-operation');
447+
$childScope = $tracer->activate($childSpan);
442448
$monolog->info('In child span');
443449

450+
$childScope->detach();
444451
$tracer->complete($childSpan);
445452
$monolog->info('Back in parent span');
446453

454+
$parentScope->detach();
447455
$tracer->complete($parentSpan);
448456

449457
$entries = $context->processor->entries();

src/bridge/phpunit/telemetry/src/Flow/Bridge/PHPUnit/Telemetry/SpanStack.php

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -4,13 +4,14 @@
44

55
namespace Flow\Bridge\PHPUnit\Telemetry;
66

7+
use Flow\Telemetry\Context\Scope;
78
use Flow\Telemetry\Tracer\Span;
89
use SplStack;
910

1011
final class SpanStack
1112
{
1213
/**
13-
* @var \SplStack<Span>
14+
* @var \SplStack<array{span: Span, scope: Scope}>
1415
*/
1516
private SplStack $stack;
1617

@@ -21,14 +22,14 @@ final class SpanStack
2122

2223
public function __construct()
2324
{
24-
/** @var \SplStack<Span> $stack */
25+
/** @var \SplStack<array{span: Span, scope: Scope}> $stack */
2526
$stack = new SplStack();
2627
$this->stack = $stack;
2728
}
2829

2930
public function clear(): void
3031
{
31-
/** @var \SplStack<Span> $stack */
32+
/** @var \SplStack<array{span: Span, scope: Scope}> $stack */
3233
$stack = new SplStack();
3334
$this->stack = $stack;
3435
$this->suiteSpans = [];
@@ -40,7 +41,7 @@ public function current(): ?Span
4041
return null;
4142
}
4243

43-
return $this->stack->top();
44+
return $this->stack->top()['span'];
4445
}
4546

4647
public function getSuiteSpan(string $suiteName): ?Span
@@ -53,18 +54,25 @@ public function isEmpty(): bool
5354
return $this->stack->isEmpty();
5455
}
5556

57+
/**
58+
* Detaches the entry's context scope before returning it, so the stack owns the LIFO ordering that
59+
* Scope::detach() requires.
60+
*/
5661
public function pop(): ?Span
5762
{
5863
if ($this->stack->isEmpty()) {
5964
return null;
6065
}
6166

62-
return $this->stack->pop();
67+
$entry = $this->stack->pop();
68+
$entry['scope']->detach();
69+
70+
return $entry['span'];
6371
}
6472

65-
public function push(Span $span): void
73+
public function push(Span $span, Scope $scope): void
6674
{
67-
$this->stack->push($span);
75+
$this->stack->push(['span' => $span, 'scope' => $scope]);
6876
}
6977

7078
public function removeSuiteSpan(string $suiteName): void

src/bridge/phpunit/telemetry/src/Flow/Bridge/PHPUnit/Telemetry/Subscriber/TestPreparationStartedSubscriber.php

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -58,7 +58,8 @@ public function notify(PreparationStarted $event): void
5858
PHPUnitTelemetryAttributes::ATTR_TEST_METHOD => $methodName,
5959
]);
6060

61-
$this->spanStack->push($span);
61+
// activated: spans the test itself emits must nest under the test span
62+
$this->spanStack->push($span, $tracer->activate($span));
6263
} catch (Throwable) {
6364
// Silent failure - telemetry must never break tests
6465
}

src/bridge/phpunit/telemetry/src/Flow/Bridge/PHPUnit/Telemetry/Subscriber/TestSuiteFinishedSubscriber.php

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -84,9 +84,10 @@ public function notify(Finished $event): void
8484
]);
8585
}
8686

87+
// pop first: it detaches the context scope, which must happen before the span completes
88+
$this->spanStack->pop();
8789
$tracer->complete($span);
8890

89-
$this->spanStack->pop();
9091
$this->spanStack->removeSuiteSpan($suiteName);
9192
}
9293

src/bridge/phpunit/telemetry/src/Flow/Bridge/PHPUnit/Telemetry/Subscriber/TestSuiteStartedSubscriber.php

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,9 @@ public function notify(Started $event): void
5353
PHPUnitTelemetryAttributes::ATTR_SUITE_IS_ROOT => $isRoot,
5454
]);
5555

56+
// activated: suites nest, and test spans must nest under their suite
5657
$this->spanStack->setSuiteSpan($suite->name(), $span);
57-
$this->spanStack->push($span);
58+
$this->spanStack->push($span, $tracer->activate($span));
5859
$this->suiteOutcomes->push();
5960
} catch (Throwable) {
6061
// Silent failure - telemetry must never break tests

src/bridge/phpunit/telemetry/tests/Flow/Bridge/PHPUnit/Telemetry/Tests/Unit/SpanStackTest.php

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
namespace Flow\Bridge\PHPUnit\Telemetry\Tests\Unit;
66

77
use Flow\Bridge\PHPUnit\Telemetry\SpanStack;
8+
use Flow\Telemetry\Tests\Mother\ScopeMother;
89
use Flow\Telemetry\Tests\Mother\SpanMother;
910
use PHPUnit\Framework\TestCase;
1011

@@ -17,8 +18,8 @@ public function test_clear_removes_all_spans(): void
1718
$span2 = SpanMother::create('span-2');
1819
$suiteSpan = SpanMother::create('suite-span');
1920

20-
$stack->push($span1);
21-
$stack->push($span2);
21+
$stack->push($span1, ScopeMother::attached());
22+
$stack->push($span2, ScopeMother::attached());
2223
$stack->setSuiteSpan('TestSuite', $suiteSpan);
2324

2425
$stack->clear();
@@ -32,7 +33,7 @@ public function test_current_returns_top_without_removing(): void
3233
$stack = new SpanStack();
3334
$span = SpanMother::create('test-span');
3435

35-
$stack->push($span);
36+
$stack->push($span, ScopeMother::attached());
3637

3738
static::assertSame($span, $stack->current());
3839
static::assertSame($span, $stack->current());
@@ -46,9 +47,9 @@ public function test_lifo_order(): void
4647
$span2 = SpanMother::create('span-2');
4748
$span3 = SpanMother::create('span-3');
4849

49-
$stack->push($span1);
50-
$stack->push($span2);
51-
$stack->push($span3);
50+
$stack->push($span1, ScopeMother::attached());
51+
$stack->push($span2, ScopeMother::attached());
52+
$stack->push($span3, ScopeMother::attached());
5253

5354
static::assertSame($span3, $stack->pop());
5455
static::assertSame($span2, $stack->pop());
@@ -61,7 +62,7 @@ public function test_push_and_pop(): void
6162
$stack = new SpanStack();
6263
$span = SpanMother::create('test-span');
6364

64-
$stack->push($span);
65+
$stack->push($span, ScopeMother::attached());
6566

6667
static::assertFalse($stack->isEmpty());
6768
static::assertSame($span, $stack->current());

0 commit comments

Comments
 (0)