[opentelemetry-php-contrib] Symfony: a throwing kernel.view listener splits one request into two traces and loses http.route

[kreciszd]

Package

open-telemetry/opentelemetry-auto-symfony 1.4.0 (latest release)

Environment

• Symfony 5.4.45, PHP 8.2, php-fpm
• open-telemetry/sdk 1.15.0, open-telemetry/api 1.10.0, ext-opentelemetry
• Exporter: OTLP http/protobuf → Grafana Alloy → Tempo

What happens

When a request fails with a 500 raised from a kernel.view listener, one HTTP request is
exported as two error spans in two different traces, and neither is complete:

span	kind	name	http.route	http.response.status_code	events
A	SERVER	DELETE	absent	absent	exception
B	INTERNAL	DELETE api_customer_records_delete_item	present	500	none

The two spans carry different trace_ids.

Counts match failures 1:1 — over 24h on two clusters: 2 failing requests produced 2 A-spans
and 2 B-spans; 1 failing request produced 1 and 1. Successful requests are unaffected: a
single SERVER span, correctly named {method} {route}.

Why it matters

• Span-derived RED metrics (traces_spanmetrics_calls_total) bucket every 5xx under the
  bare HTTP method, so server errors cannot be attributed to an endpoint.
• The span holding the exception is not the span holding the status code, and they are not
  in the same trace, so no single trace shows a complete picture of the failure.

Where it appears to come from

In SymfonyInstrumentation::register() a scope is attached in the handle pre hook for
every request type, but detached in only two places:

• handle post — returns early without detaching when $exception === null
  (the normal path, including a request that produced a 500 response);
• terminate post — pops exactly one scope, and that is where http.route and the
  status code are stamped.

When the error is rendered through a sub-request, a second scope is attached and the stack
ends up unbalanced, so terminate appears to stamp the route and status onto the
sub-request span rather than the main SERVER span.

Caveat

The table above is measured; the explanation is inferred from reading
SymfonyInstrumentation.php — I have not stepped through the hook ordering to confirm it.
Happy to put together a minimal reproducer if that would help.

[kreciszd]

Follow-up: I reproduced this locally and the mechanism is simpler than what I guessed above. The sub-request explanation in the original report is wrong — please disregard it.

The trigger is HttpKernel::handle() on Symfony 5.4:

try { return $this->handleRaw($request, $type); }
catch (\Exception $e) { ... return $this->handleThrowable($e, $request, $type); }

It catches \Exception, not \Throwable. So a raw \Error — a typed property read before initialization, an argument type mismatch, a call on null — escapes handle() outright. handleThrowable is never reached and kernel.exception never fires.

That means the handle post hook sees a non-null $exception and takes this branch:

$span = Span::fromContext($scope->context());
$scope->detach();
$span->recordException($exception);
$span->setStatus(StatusCode::STATUS_ERROR, $exception->getMessage());
$span->end();

The span is detached and ended right there — before terminate runs, and terminate is the only place that stamps http.route and the status code. Hence the span that carries the exception event has no route and no status, exactly as in the table above.

An HttpException takes the other branch, is handled inside handle(), reaches terminate normally, and comes out correctly named. That is the whole difference between the two rows.

Reproduced with a script that builds the real HttpKernel and the real ErrorListener by hand under ext-opentelemetry with this instrumentation loaded, throwing NotFoundHttpException in one case and a raw \Error in the other. Same code path in both, only the thrown class differs.

Worth noting the same escape breaks log↔trace correlation: the uncaught \Error is logged by the global ErrorHandler, outside handle(), at which point the span is already ended, so Span::getCurrent() is invalid and the log line describing the fatal carries no trace id.

Symfony 6.x widened this catch to \Throwable, so on 6+ the exception should stay inside the kernel — I have not verified that, but if so the fix here may only need to cover the 5.4 escape path.