Skip to content

Fix boundaries for Symfony HttpKernel auto instrumentation #317

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Fix boundaries for Symfony HttpKernel auto instrumentation #317

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 25 additions & 0 deletions src/Instrumentation/Symfony/src/SymfonyInstrumentation.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,30 @@ public static function register(): void
array $params,
?Response $response,
?\Throwable $exception
): void {
$scope = Context::storage()->scope();
if (null === $scope || null === $exception) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So if an exception occurs, this post callback will run, otherwise the terminate one will? If so, we should document this.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is correct.
I'm assuming this should be documented in the README.md, right?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The examples on this page seem to suggest that the handle and terminate can both run.

So it looks like you'd expect 2 spans to be created and then with these changes only close one of them? I'm not so sure that behaviour is correct.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There appears to be a parameter to configure whether handle should throw here.

So when $catch = false the handle post-hook might have an exception and terminate will not have been reached yet. I think this would be fine as it handles the recording of the exception and detaches the scope.

However, if $catch = false and there is no exception, then terminate() would be called after handle and the terminate post-hook could try to close a scope which does not belong to it.

Copy link
Author

@dciprian-petrisor dciprian-petrisor Nov 29, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ChrisLightfootWild

  1. If handle throws an exception which is never caught, then terminate will never be reached either, according to the HttpKernelRunner implementation.
    In this situation, it is correct to close the scope on the post hook of handle.

  2. If handle does not throw an exception (or has $catch = true), then terminate would run afterwards, closing the scope.

The only problem I see is there is not a 100% guarantee that terminate will always be executed after handle.

For example, something else might go wrong in HttpKernelRunner after handle was called, e.g. fastcgi_finish_request()/litespeed_finish_request() might crash, flush() might crash, etc, leaving the scope still open.

Unsure how much of a real issue this is, in most cases.

Normally this would be solved by hooking into HttpKernelRunner::run with both pre and post hooks, as it covers both handle and terminate, however $request and $response are not available as parameters there, so I am at a loss right now.

The main issue is that the parent span is lost in between handle and terminate, due to handle detaching it, thus producing two different traces for the same request:

  • one containing everything from the start of the HTTP request up to the end of handle
  • one containing just the dispatch of TerminateEvent done by $this->kernel->terminate afterwards

the second should be part of the first, as it is still logically part of the same HTTP request lifecycle.

We need either a compromise or another solution entirely.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for that @dciprian-petrisor - I had another look with less bleary eyes and I finally caught up to you guys 💪

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am having the same problem for Drupal, but opted to do an auto root span for now, which obviously duplicates the logic to do that.

That way I have a duplicated span for the Kernel::handle() + Kernel::terminate(), but that does not matter as it's still within one root trace.

The Auto Root Span uses the SDK ShutdownHandler::register so that might be also an option here.

The other thing is:

You could hook into KernelRunner::run(), but not open the scope here, but instead close it just during the post() [if ::run() was called in pre].

While that is more logic to handle, because handle() needs to check that ::run was actually called, so that it can close it, cross hook frontiers are a good way to handle this.

::run pre -> $runCalled = 1
::handle pre -> Open root scope like normal
::handle post -> if ($runCalled) {} -> Do not bother to close scope, else fallback to current logic
::terminate pre -> Open span like normal
::terminate post -> Close span like normal
::run post -> Close scope

In general I personally will still call the Auto Root Scope hook as early as possible (e.g. DrupalKernel::__construct in my case), because else there is always an ::IO extension call, which escapes.

Until that's converted to SPI obviously there are still race conditions.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is my implementation:

<?php

namespace OpenTelemetry\Contrib\Instrumentation\Drupal;

use Drupal\Core\DrupalKernel;
use OpenTelemetry\SDK\Trace\AutoRootSpan;
use function OpenTelemetry\Instrumentation\hook;

class DrupalAutoRootSpan {

  public static function register(): void {

    hook(
      DrupalKernel::class,
      '__construct',
      static::registerAutoRootSpan(),
      NULL,
    );
  }

  /**
   * @param \OpenTelemetry\API\Instrumentation\CachedInstrumentation $instrumentation
   *
   * @return \Closure
   */
  public static function registerAutoRootSpan(): \Closure {
    return static function (DrupalKernel $kernel, array $params, string $class, string $function, ?string $filename, ?int $lineno) {
      $request = AutoRootSpan::createRequest();

      if ($request) {
        AutoRootSpan::create($request);
        AutoRootSpan::registerShutdownHandler();
      }
    };
  }

}

It works really well.

return;
}

$span = Span::fromContext($scope->context());
$scope->detach();
$span->recordException($exception, [
TraceAttributes::EXCEPTION_ESCAPED => true,
]);
if (null !== $response && $response->getStatusCode() >= Response::HTTP_INTERNAL_SERVER_ERROR) {
$span->setStatus(StatusCode::STATUS_ERROR, $exception->getMessage());
}
}
);

hook(
HttpKernel::class,
'terminate',
post: static function (
HttpKernel $kernel,
array $params,
?\Throwable $exception
): void {
$scope = Context::storage()->scope();
if (null === $scope) {
Expand All @@ -101,6 +125,7 @@ public static function register(): void
$span = Span::fromContext($scope->context());

$request = ($params[0] instanceof Request) ? $params[0] : null;
$response = ($params[1] instanceof Response) ? $params[1] : null;
if (null !== $request) {
$routeName = $request->attributes->get('_route', '');

Expand Down
36 changes: 28 additions & 8 deletions src/Instrumentation/Symfony/tests/Integration/SymfonyInstrumentationTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,15 @@ public function test_http_kernel_handle_exception(): void
throw new \RuntimeException();
});
$this->assertCount(0, $this->storage);
$kernel->handle(new Request());

$response = $kernel->handle(new Request());
$kernel->terminate(new Request(), $response);

$this->assertArrayHasKey(
TraceResponsePropagator::TRACERESPONSE,
$response->headers->all(),
'traceresponse header is present if TraceResponsePropagator is present'
);
}

public function test_http_kernel_marks_root_as_erroneous(): void
Expand All @@ -40,7 +48,8 @@ public function test_http_kernel_marks_root_as_erroneous(): void
});
$this->assertCount(0, $this->storage);

$kernel->handle(new Request(), HttpKernelInterface::MAIN_REQUEST, true);
$response = $kernel->handle(new Request(), HttpKernelInterface::MAIN_REQUEST, true);
$kernel->terminate(new Request(), $response);

$this->assertCount(1, $this->storage);
$this->assertSame(500, $this->storage[0]->getAttributes()->get(TraceAttributes::HTTP_RESPONSE_STATUS_CODE));
Expand All @@ -55,7 +64,8 @@ public function test_http_kernel_handle_attributes(): void
$request = new Request();
$request->attributes->set('_route', 'test_route');

$kernel->handle($request);
$response = $kernel->handle($request);
$kernel->terminate($request, $response);

$attributes = $this->storage[0]->getAttributes();
$this->assertCount(1, $this->storage);
Expand All @@ -78,7 +88,9 @@ public function test_http_kernel_handle_stream_response(): void
}));
$this->assertCount(0, $this->storage);

$kernel->handle(new Request());
$response = $kernel->handle(new Request());
$kernel->terminate(new Request(), $response);

$this->assertCount(1, $this->storage);
$this->assertNull($this->storage[0]->getAttributes()->get(TraceAttributes::HTTP_RESPONSE_BODY_SIZE));
}
Expand All @@ -88,7 +100,9 @@ public function test_http_kernel_handle_binary_file_response(): void
$kernel = $this->getHttpKernel(new EventDispatcher(), fn () => new BinaryFileResponse(__FILE__));
$this->assertCount(0, $this->storage);

$kernel->handle(new Request());
$response = $kernel->handle(new Request());
$kernel->terminate(new Request(), $response);

$this->assertCount(1, $this->storage);
$this->assertNull($this->storage[0]->getAttributes()->get(TraceAttributes::HTTP_RESPONSE_BODY_SIZE));

Expand All @@ -101,7 +115,9 @@ public function test_http_kernel_handle_with_empty_route(): void
$request = new Request();
$request->attributes->set('_route', '');

$kernel->handle($request, HttpKernelInterface::MAIN_REQUEST, true);
$response = $kernel->handle($request, HttpKernelInterface::MAIN_REQUEST, true);
$kernel->terminate(new Request(), $response);

$this->assertCount(1, $this->storage);
$this->assertFalse($this->storage[0]->getAttributes()->has(TraceAttributes::HTTP_ROUTE));

Expand All @@ -112,7 +128,9 @@ public function test_http_kernel_handle_without_route(): void
$kernel = $this->getHttpKernel(new EventDispatcher());
$this->assertCount(0, $this->storage);

$kernel->handle(new Request(), HttpKernelInterface::MAIN_REQUEST, true);
$response = $kernel->handle(new Request(), HttpKernelInterface::MAIN_REQUEST, true);
$kernel->terminate(new Request(), $response);

$this->assertCount(1, $this->storage);
$this->assertFalse($this->storage[0]->getAttributes()->has(TraceAttributes::HTTP_ROUTE));

Expand All @@ -125,7 +143,9 @@ public function test_http_kernel_handle_subrequest(): void
$request = new Request();
$request->attributes->set('_controller', 'ErrorController');

$kernel->handle($request, HttpKernelInterface::SUB_REQUEST);
$response = $kernel->handle($request, HttpKernelInterface::SUB_REQUEST);
$kernel->terminate($request, $response);

$this->assertCount(1, $this->storage);

$span = $this->storage[0];
Expand Down
Loading