[opentelemetry-php-contrib] [Symfony auto-instrumentation] Exception events not recorded on spans when Symfony handles errors via sub-request

[Apoorva64]

Summary

When an exception is thrown in a Symfony controller, the exception event is not visible in the exported trace, even though the span shows Status: Error. This is because the terminate hook retrieves the wrong span (the error_controller sub-request span) instead of the original main request span.

Environment

• PHP 8.4
• Symfony 8
• open-telemetry/opentelemetry-auto-symfony ^1.1.1

Reproduction

Test endpoint: GET /v1/menu/test/error/division

#[Route('/test/error/division', name: 'test_division_error', methods: ['GET'])]
public function testDivisionError(): JsonResponse
{
    $a = 10;
    $b = 0;
    $result = intdiv($a, $b); // DivisionByZeroError
    
    return $this->json(['result' => $result]);
}

Problem Description

When an exception occurs in a Symfony application:

1. The exception is thrown in the controller
2. handleThrowable is called and records the exception on the main request span
3. Symfony creates a sub-request to error_controller to render the error page
4. The sub-request creates a new span that gets pushed onto the context storage stack
5. terminate is called and retrieves the span from Context::storage()->scope()
6. Bug: This returns the sub-request span, not the main request span
7. The main request span (with the exception event) is never properly ended/exported

The span names confirm this in debug:

• handleThrowable: span name is "GET"
• terminate: span name is "GET error_controller"

BEFORE: Trace output (missing exception event)

Span #0
    Trace ID       : d500694f4e175ce558a22ef2692c9dd4
    Parent ID      : 763b808e5ea7cb22
    ID             : 11f365f73b482185
    Name           : GET /v1/menu/test/error/division
    Kind           : Internal
    Start time     : 2025-12-30 14:21:16.917804532 +0000 UTC
    End time       : 2025-12-30 14:21:18.603553128 +0000 UTC
    Status code    : Error
    Status message :                          <-- Empty!
    DroppedAttributesCount: 0
    DroppedEventsCount: 0                     <-- No events!
    DroppedLinksCount: 0
Attributes:
     -> http.response.status_code: Int(500)
     -> http.route: Str(/v1/menu/test/error/division)
     ...
                                              <-- No Events section!

Note: The span shows Status: Error but has no exception event and no status message.

Root Cause

Issue Sub-request spans never ended

The handle POST hook only processes when there's an exception:

post: static function (...) {
    // ...
    if (null === $scope || null === $exception) {
        return;  // <-- Sub-request completes successfully, returns early
    }
    // Span never detached or ended!
}

The error_controller sub-request completes successfully (it renders the error page), so its span is created but never ended.

Issue terminate() gets wrong span

// In terminate hook:
$scope = Context::storage()->scope();  // Returns top of stack = sub-request span
$span = Span::fromContext($scope->context());  // Wrong span!

The context storage is a stack. The sub-request span was pushed on top but never popped, so terminate gets the wrong span.

Solution

Fix: Handle sub-requests in handle POST hook

Always end sub-request spans in the handle POST hook since terminate() only handles the main request:

post: static function (...) {
    $scope = Context::storage()->scope();
    if (null === $scope) {
        return;
    }

    $type = $params[1] ?? HttpKernelInterface::MAIN_REQUEST;
    $isSubRequest = ($type === HttpKernelInterface::SUB_REQUEST);

    // MAIN_REQUEST without exception: let terminate() handle everything
    if (!$isSubRequest && null === $exception) {
        return;
    }

    $span = Span::fromContext($scope->context());
    $scope->detach();

    // Record exception if present
    if (null !== $exception) {
        $span->recordException($exception, [
            TraceAttributes::EXCEPTION_ESCAPED => true,
        ]);
        $span->setStatus(StatusCode::STATUS_ERROR, $exception->getMessage());
    }

    // SUB_REQUEST: end span here since terminate() only handles MAIN_REQUEST
    if ($isSubRequest) {
        if (null !== $response) {
            $span->setAttribute(TraceAttributes::HTTP_RESPONSE_STATUS_CODE, $response->getStatusCode());
        }
        $span->end();
    }
}

AFTER: Trace output (with fix applied)

Now we get two spans with proper exception recording:

Span #0 - Sub-request (error_controller)

Span #0
    Trace ID       : f392848bd679c0a6e2f38ca888cc2fbf
    Parent ID      : f7c3f8b3f8ecd552
    ID             : ...
    Name           : GET error_controller
    Kind           : Internal
    Status code    : Unset
    -> http.response.status_code: Int(500)

Span #1 - Main request (with exception event!)

Span #1
    Trace ID       : f392848bd679c0a6e2f38ca888cc2fbf
    Parent ID      : 
    ID             : f7c3f8b3f8ecd552
    Name           : GET /v1/menu/test/error/division
    Kind           : Server
    Start time     : 2025-12-30 14:23:42.004143064 +0000 UTC
    End time       : 2025-12-30 14:23:44.928306556 +0000 UTC
    Status code    : Error
    Status message : 
Attributes:
     -> http.response.status_code: Int(500)
     -> http.route: Str(/v1/menu/test/error/division)
     -> network.protocol.version: Str(1.1)
     -> http.response.body.size: Int(92985)

Events:
SpanEvent #0
     -> Name: exception
     -> Timestamp: 2025-12-30 14:23:43.154858485 +0000 UTC
     -> Attributes::
          -> exception.type: Str(DivisionByZeroError)
          -> exception.message: Str(Division by zero)
          -> exception.stacktrace: Str(DivisionByZeroError: Division by zero
            at intdiv(MenuController.php:429)
            at App.Controller.MenuController.testDivisionError(MenuController.php:429)
            at Symfony.Component.HttpKernel.HttpKernel.handleRaw(HttpKernel.php:183)
            at Symfony.Component.HttpKernel.HttpKernel.handle(HttpKernel.php:76)
            at Symfony.Component.HttpKernel.Kernel.handle(Kernel.php:191)
            ...)