From 8a4fa7ca6a2e96d5b9836f1cf969dd08ee5ad5b4 Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 11:37:49 +0200 Subject: [PATCH 1/8] Fix missing @uses --- src/Sentry/Laravel/Tracing/EventHandler.php | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/Sentry/Laravel/Tracing/EventHandler.php b/src/Sentry/Laravel/Tracing/EventHandler.php index d971d32a..6fb32ee2 100644 --- a/src/Sentry/Laravel/Tracing/EventHandler.php +++ b/src/Sentry/Laravel/Tracing/EventHandler.php @@ -144,6 +144,9 @@ public function __construct(Container $container, BacktraceHelper $backtraceHelp * * @uses self::routeMatchedHandler() * @uses self::queryExecutedHandler() + * @uses self::httpClientRequestSendingHandler() + * @uses self::httpClientResponseReceivedHandler() + * @uses self::httpClientConnectionFailedHandler() */ public function subscribe(): void { From 84dd4f9bb6a94c954a5f4933a2a47d42f4ab7d6b Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 12:31:58 +0200 Subject: [PATCH 2/8] wip --- src/Sentry/Laravel/Tracing/EventHandler.php | 84 ++++++++++++++------- 1 file changed, 57 insertions(+), 27 deletions(-) diff --git a/src/Sentry/Laravel/Tracing/EventHandler.php b/src/Sentry/Laravel/Tracing/EventHandler.php index 6fb32ee2..16e413ed 100644 --- a/src/Sentry/Laravel/Tracing/EventHandler.php +++ b/src/Sentry/Laravel/Tracing/EventHandler.php @@ -15,6 +15,7 @@ use RuntimeException; use Sentry\Laravel\Integration; use Sentry\SentrySdk; +use Sentry\Tracing\Span; use Sentry\Tracing\SpanContext; use Sentry\Tracing\SpanStatus; use Sentry\Tracing\TransactionContext; @@ -86,32 +87,32 @@ class EventHandler private $traceQueueJobsAsTransactions; /** - * Holds a reference to the parent queue job span. + * Holds a reference to the parent http client request span. * * @var \Sentry\Tracing\Span|null */ - private $parentQueueJobSpan; + private $parentHttpClientRequestSpan; /** - * Holds a reference to the current queue job span or transaction. + * Holds a reference to the current http client request span. * - * @var \Sentry\Tracing\Transaction|\Sentry\Tracing\Span|null + * @var \Sentry\Tracing\Span|null */ - private $currentQueueJobSpan; + private $currentHttpClientRequestSpan; /** - * Holds a reference to the parent http client request span. + * Hold the stack of parent spans that need to be put back on the scope. * - * @var \Sentry\Tracing\Span|null + * @var array */ - private $parentHttpClientRequestSpan; + private array $parentSpanStack = []; /** - * Holds a reference to the current http client request span. + * Hold the stack of current spans that need to be finished still. * - * @var \Sentry\Tracing\Span|null + * @var array */ - private $currentHttpClientRequestSpan; + private array $currentSpanStack = []; /** * The backtrace helper. @@ -189,9 +190,9 @@ public function subscribeQueueEvents(QueueManager $queue): void return $payload; }); - $queue->looping(function () { - $this->afterQueuedJob(); - }); +// $queue->looping(function () { +// $this->afterQueuedJob(); +// }); try { /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ @@ -340,7 +341,9 @@ private function afterHttpClientRequest(): void protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): void { - $parentSpan = Integration::currentTracingSpan(); + $parentSpan = SentrySdk::getCurrentHub()->getSpan(); + + logger()->debug('queueJobProcessingHandler, current span: ' . $parentSpan?->getSpanId()); // If there is no tracing span active and we don't trace jobs as transactions there is no need to handle the event if ($parentSpan === null && !$this->traceQueueJobsAsTransactions) { @@ -371,7 +374,7 @@ protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): $job = [ 'job' => $event->job->getName(), 'queue' => $event->job->getQueue(), - 'resolved' => $event->job->resolveName(), + 'resolved' => $resolvedJobName, 'attempts' => $event->job->attempts(), 'connection' => $event->connectionName, ]; @@ -387,14 +390,13 @@ protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): // When the parent span is null we start a new transaction otherwise we start a child of the current span if ($parentSpan === null) { - $this->currentQueueJobSpan = SentrySdk::getCurrentHub()->startTransaction($context); + $span = SentrySdk::getCurrentHub()->startTransaction($context); } else { - $this->currentQueueJobSpan = $parentSpan->startChild($context); + $span = $parentSpan->startChild($context); + logger()->debug('Starting child of ' . $parentSpan->getSpanId() . ', child is ' . $span->getSpanId()); } - $this->parentQueueJobSpan = $parentSpan; - - SentrySdk::getCurrentHub()->setSpan($this->currentQueueJobSpan); + $this->pushSpan($span); } protected function queueJobExceptionOccurredHandler(QueueEvents\JobExceptionOccurred $event): void @@ -409,15 +411,43 @@ protected function queueJobProcessedHandler(QueueEvents\JobProcessed $event): vo private function afterQueuedJob(?SpanStatus $status = null): void { - if ($this->currentQueueJobSpan === null) { + $span = $this->popSpan(); + + if ($span === null) { return; } - $this->currentQueueJobSpan->setStatus($status); - $this->currentQueueJobSpan->finish(); - $this->currentQueueJobSpan = null; + $span->setStatus($status); + $span->finish(); + } + + private function pushSpan(Span $span): void + { +// logger()->debug('push: got ' . count($this->currentSpanStack) . ' spans on the stack'); + + $this->parentSpanStack[] = SentrySdk::getCurrentHub()->getSpan(); + + SentrySdk::getCurrentHub()->setSpan($span); + + $this->currentSpanStack[] = $span; + + logger()->debug('push: new span is ' . $span->getSpanId() . ', current: ' . SentrySdk::getCurrentHub()->getSpan()->getSpanId()); + } + + private function popSpan(): ?Span + { + if (count($this->currentSpanStack) === 0) { + return null; + } + +// logger()->debug('pop: got ' . count($this->currentSpanStack) . ' spans on the stack'); + + $parent = array_pop($this->parentSpanStack); + + SentrySdk::getCurrentHub()->setSpan($parent); + + logger()->debug('pop: new span is ' . $parent->getSpanId() . ', current: ' . SentrySdk::getCurrentHub()->getSpan()->getSpanId()); - SentrySdk::getCurrentHub()->setSpan($this->parentQueueJobSpan); - $this->parentQueueJobSpan = null; + return array_pop($this->currentSpanStack); } } From dd5293023d50ff99b9b59acfa97ed8bb599bd293 Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 13:36:43 +0200 Subject: [PATCH 3/8] wip --- src/Sentry/Laravel/EventHandler.php | 72 +++------- src/Sentry/Laravel/Integration.php | 33 +---- src/Sentry/Laravel/ServiceProvider.php | 27 ++-- src/Sentry/Laravel/Tracing/EventHandler.php | 133 ++++-------------- .../Integrations/LighthouseIntegration.php | 2 +- src/Sentry/Laravel/Tracing/Middleware.php | 23 ++- .../Laravel/Tracing/ServiceProvider.php | 22 +-- .../Laravel/Tracing/ViewEngineDecorator.php | 3 +- test/Sentry/Tracing/EventHandlerTest.php | 4 +- 9 files changed, 111 insertions(+), 208 deletions(-) diff --git a/src/Sentry/Laravel/EventHandler.php b/src/Sentry/Laravel/EventHandler.php index 41d87a06..e2f32924 100644 --- a/src/Sentry/Laravel/EventHandler.php +++ b/src/Sentry/Laravel/EventHandler.php @@ -140,9 +140,9 @@ class EventHandler /** * Indicates if we pushed a scope for the queue. * - * @var bool + * @var int */ - private $pushedQueueScope = false; + private $pushedQueueScopeCount = 0; /** * Indicates if we pushed a scope for Octane. @@ -173,76 +173,40 @@ public function __construct(Container $container, array $config) /** * Attach all event handlers. */ - public function subscribe(): void + public function subscribe(Dispatcher $dispatcher): void { - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - try { - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$eventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$eventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } /** * Attach all authentication event handlers. */ - public function subscribeAuthEvents(): void + public function subscribeAuthEvents(Dispatcher $dispatcher): void { - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - try { - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$authEventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$authEventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } /** * Attach all queue event handlers. */ - public function subscribeOctaneEvents(): void + public function subscribeOctaneEvents(Dispatcher $dispatcher): void { - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - try { - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$octaneEventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$octaneEventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } /** * Attach all queue event handlers. - * - * @param \Illuminate\Queue\QueueManager $queue */ - public function subscribeQueueEvents(QueueManager $queue): void + public function subscribeQueueEvents(Dispatcher $dispatcher): void { - $queue->looping(function () { - $this->cleanupScopeForTaskWithinLongRunningProcessWhen($this->pushedQueueScope); - - $this->pushedQueueScope = false; - }); - - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - try { - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$queueEventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$queueEventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } @@ -382,11 +346,9 @@ private function configureUserScopeFromModel($authUser): void protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): void { - $this->cleanupScopeForTaskWithinLongRunningProcessWhen($this->pushedQueueScope); - $this->prepareScopeForTaskWithinLongRunningProcess(); - $this->pushedQueueScope = true; + ++$this->pushedQueueScopeCount; if (!$this->recordQueueInfo) { return; @@ -415,11 +377,15 @@ protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): protected function queueJobExceptionOccurredHandler(QueueEvents\JobExceptionOccurred $event): void { + $this->cleanupScopeForTaskWithinLongRunningProcessWhen($this->pushedQueueScopeCount > 0); + $this->afterTaskWithinLongRunningProcess(); } protected function queueJobProcessedHandler(QueueEvents\JobProcessed $event): void { + $this->cleanupScopeForTaskWithinLongRunningProcessWhen($this->pushedQueueScopeCount > 0); + $this->afterTaskWithinLongRunningProcess(); } diff --git a/src/Sentry/Laravel/Integration.php b/src/Sentry/Laravel/Integration.php index 8f683781..a9df0948 100644 --- a/src/Sentry/Laravel/Integration.php +++ b/src/Sentry/Laravel/Integration.php @@ -3,10 +3,7 @@ namespace Sentry\Laravel; use Illuminate\Routing\Route; -use Illuminate\Support\Str; use Sentry\SentrySdk; -use Sentry\Tracing\Span; -use Sentry\Tracing\Transaction; use Sentry\Tracing\TransactionSource; use function Sentry\addBreadcrumb; use function Sentry\configureScope; @@ -118,7 +115,7 @@ public static function extractNameAndSourceForRoute(Route $route): array { return [ '/' . ltrim($route->uri(), '/'), - TransactionSource::route() + TransactionSource::route(), ]; } @@ -140,7 +137,7 @@ public static function sentryMeta(): string */ public static function sentryTracingMeta(): string { - $span = self::currentTracingSpan(); + $span = SentrySdk::getCurrentHub()->getSpan(); if ($span === null) { return ''; @@ -157,7 +154,7 @@ public static function sentryTracingMeta(): string */ public static function sentryBaggageMeta(): string { - $span = self::currentTracingSpan(); + $span = SentrySdk::getCurrentHub()->getSpan(); if ($span === null) { return ''; @@ -165,28 +162,4 @@ public static function sentryBaggageMeta(): string return sprintf('', $span->toBaggage()); } - - /** - * Get the current active tracing span from the scope. - * - * @return \Sentry\Tracing\Transaction|null - * - * @internal This is used internally as an easy way to retrieve the current active transaction. - */ - public static function currentTransaction(): ?Transaction - { - return SentrySdk::getCurrentHub()->getTransaction(); - } - - /** - * Get the current active tracing span from the scope. - * - * @return \Sentry\Tracing\Span|null - * - * @internal This is used internally as an easy way to retrieve the current active tracing span. - */ - public static function currentTracingSpan(): ?Span - { - return SentrySdk::getCurrentHub()->getSpan(); - } } diff --git a/src/Sentry/Laravel/ServiceProvider.php b/src/Sentry/Laravel/ServiceProvider.php index 5b8bf12a..5e01a2c6 100644 --- a/src/Sentry/Laravel/ServiceProvider.php +++ b/src/Sentry/Laravel/ServiceProvider.php @@ -2,6 +2,8 @@ namespace Sentry\Laravel; +use Illuminate\Contracts\Container\BindingResolutionException; +use Illuminate\Contracts\Events\Dispatcher; use Illuminate\Contracts\Http\Kernel as HttpKernelInterface; use Illuminate\Foundation\Application as Laravel; use Illuminate\Foundation\Http\Kernel as HttpKernel; @@ -95,18 +97,25 @@ protected function bindEvents(): void $handler = new EventHandler($this->app, $userConfig); - $handler->subscribe(); + try { + /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ + $dispatcher = $this->app->make(Dispatcher::class); - if ($this->app->bound('octane')) { - $handler->subscribeOctaneEvents(); - } + $handler->subscribe($dispatcher); - if ($this->app->bound('queue')) { - $handler->subscribeQueueEvents($this->app->make('queue')); - } + if ($this->app->bound('octane')) { + $handler->subscribeOctaneEvents($dispatcher); + } - if (isset($userConfig['send_default_pii']) && $userConfig['send_default_pii'] !== false) { - $handler->subscribeAuthEvents(); + if ($this->app->bound('queue')) { + $handler->subscribeQueueEvents($dispatcher, $this->app->make('queue')); + } + + if (isset($userConfig['send_default_pii']) && $userConfig['send_default_pii'] !== false) { + $handler->subscribeAuthEvents($dispatcher); + } + } catch (BindingResolutionException $e) { + // If we cannot resolve the event dispatcher we also cannot listen to events } } diff --git a/src/Sentry/Laravel/Tracing/EventHandler.php b/src/Sentry/Laravel/Tracing/EventHandler.php index 16e413ed..36b0a096 100644 --- a/src/Sentry/Laravel/Tracing/EventHandler.php +++ b/src/Sentry/Laravel/Tracing/EventHandler.php @@ -3,8 +3,6 @@ namespace Sentry\Laravel\Tracing; use Exception; -use Illuminate\Contracts\Container\BindingResolutionException; -use Illuminate\Contracts\Container\Container; use Illuminate\Contracts\Events\Dispatcher; use Illuminate\Database\Events as DatabaseEvents; use Illuminate\Http\Client\Events as HttpClientEvents; @@ -23,9 +21,8 @@ class EventHandler { - public const QUEUE_PAYLOAD_TRACE_PARENT_DATA = 'sentry_trace_parent_data'; - public const QUEUE_PAYLOAD_BAGGAGE_DATA = 'sentry_baggage_data'; + public const QUEUE_PAYLOAD_TRACE_PARENT_DATA = 'sentry_trace_parent_data'; /** * Map event handlers to events. @@ -51,13 +48,6 @@ class EventHandler QueueEvents\JobExceptionOccurred::class => 'queueJobExceptionOccurred', ]; - /** - * The Laravel container. - * - * @var \Illuminate\Contracts\Container\Container - */ - private $container; - /** * Indicates if we should we add SQL queries as spans. * @@ -86,33 +76,19 @@ class EventHandler */ private $traceQueueJobsAsTransactions; - /** - * Holds a reference to the parent http client request span. - * - * @var \Sentry\Tracing\Span|null - */ - private $parentHttpClientRequestSpan; - - /** - * Holds a reference to the current http client request span. - * - * @var \Sentry\Tracing\Span|null - */ - private $currentHttpClientRequestSpan; - /** * Hold the stack of parent spans that need to be put back on the scope. * * @var array */ - private array $parentSpanStack = []; + private $parentSpanStack = []; /** * Hold the stack of current spans that need to be finished still. * * @var array */ - private array $currentSpanStack = []; + private $currentSpanStack = []; /** * The backtrace helper. @@ -123,21 +99,16 @@ class EventHandler /** * EventHandler constructor. - * - * @param \Illuminate\Contracts\Container\Container $container - * @param \Sentry\Laravel\Tracing\BacktraceHelper $backtraceHelper - * @param array $config */ - public function __construct(Container $container, BacktraceHelper $backtraceHelper, array $config) + public function __construct(array $config, BacktraceHelper $backtraceHelper) { - $this->container = $container; - $this->backtraceHelper = $backtraceHelper; - $this->traceSqlQueries = ($config['sql_queries'] ?? true) === true; $this->traceSqlQueryOrigins = ($config['sql_origin'] ?? true) === true; $this->traceQueueJobs = ($config['queue_jobs'] ?? false) === true; $this->traceQueueJobsAsTransactions = ($config['queue_job_transactions'] ?? false) === true; + + $this->backtraceHelper = $backtraceHelper; } /** @@ -149,30 +120,21 @@ public function __construct(Container $container, BacktraceHelper $backtraceHelp * @uses self::httpClientResponseReceivedHandler() * @uses self::httpClientConnectionFailedHandler() */ - public function subscribe(): void + public function subscribe(Dispatcher $dispatcher): void { - try { - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$eventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$eventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } /** * Attach all queue event handlers. * - * @param \Illuminate\Queue\QueueManager $queue - * * @uses self::queueJobProcessingHandler() * @uses self::queueJobProcessedHandler() * @uses self::queueJobExceptionOccurredHandler() */ - public function subscribeQueueEvents(QueueManager $queue): void + public function subscribeQueueEvents(Dispatcher $dispatcher, QueueManager $queue): void { // If both types of queue job tracing is disabled also do not register the events if (!$this->traceQueueJobs && !$this->traceQueueJobsAsTransactions) { @@ -180,7 +142,7 @@ public function subscribeQueueEvents(QueueManager $queue): void } Queue::createPayloadUsing(static function (?string $connection, ?string $queue, ?array $payload): ?array { - $currentSpan = Integration::currentTracingSpan(); + $currentSpan = SentrySdk::getCurrentHub()->getSpan(); if ($currentSpan !== null && $payload !== null) { $payload[self::QUEUE_PAYLOAD_TRACE_PARENT_DATA] = $currentSpan->toTraceparent(); @@ -190,19 +152,8 @@ public function subscribeQueueEvents(QueueManager $queue): void return $payload; }); -// $queue->looping(function () { -// $this->afterQueuedJob(); -// }); - - try { - /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ - $dispatcher = $this->container->make(Dispatcher::class); - - foreach (static::$queueEventHandlerMap as $eventName => $handler) { - $dispatcher->listen($eventName, [$this, $handler]); - } - } catch (BindingResolutionException $e) { - // If we cannot resolve the event dispatcher we also cannot listen to events + foreach (static::$queueEventHandlerMap as $eventName => $handler) { + $dispatcher->listen($eventName, [$this, $handler]); } } @@ -222,14 +173,14 @@ public function __call(string $method, array $arguments) try { call_user_func_array([$this, $handlerMethod], $arguments); - } catch (Exception $exception) { - // Ignore + } catch (Exception $e) { + // Ignore to prevent bubbling up errors in the SDK } } protected function routeMatchedHandler(RoutingEvents\RouteMatched $match): void { - $transaction = Integration::currentTransaction(); + $transaction = SentrySdk::getCurrentHub()->getTransaction(); if ($transaction === null) { return; @@ -247,7 +198,7 @@ protected function queryExecutedHandler(DatabaseEvents\QueryExecuted $query): vo return; } - $parentSpan = Integration::currentTracingSpan(); + $parentSpan = SentrySdk::getCurrentHub()->getSpan(); // If there is no tracing span active there is no need to handle the event if ($parentSpan === null) { @@ -291,7 +242,7 @@ private function resolveQueryOriginFromBacktrace(): ?string protected function httpClientRequestSendingHandler(HttpClientEvents\RequestSending $event): void { - $parentSpan = Integration::currentTracingSpan(); + $parentSpan = SentrySdk::getCurrentHub()->getSpan(); if ($parentSpan === null) { return; @@ -303,48 +254,33 @@ protected function httpClientRequestSendingHandler(HttpClientEvents\RequestSendi $context->setDescription($event->request->method() . ' ' . $event->request->url()); $context->setStartTimestamp(microtime(true)); - $this->currentHttpClientRequestSpan = $parentSpan->startChild($context); - - $this->parentHttpClientRequestSpan = $parentSpan; - - SentrySdk::getCurrentHub()->setSpan($this->currentHttpClientRequestSpan); + $this->pushSpan($parentSpan->startChild($context)); } protected function httpClientResponseReceivedHandler(HttpClientEvents\ResponseReceived $event): void { - if ($this->currentHttpClientRequestSpan !== null) { - $this->currentHttpClientRequestSpan->setHttpStatus($event->response->status()); - $this->afterHttpClientRequest(); + $span = $this->popSpan(); + + if ($span !== null) { + $span->finish(); + $span->setHttpStatus($event->response->status()); } } protected function httpClientConnectionFailedHandler(HttpClientEvents\ConnectionFailed $event): void { - if ($this->currentHttpClientRequestSpan !== null) { - $this->currentHttpClientRequestSpan->setStatus(SpanStatus::internalError()); - $this->afterHttpClientRequest(); - } - } + $span = $this->popSpan(); - private function afterHttpClientRequest(): void - { - if ($this->currentHttpClientRequestSpan === null) { - return; + if ($span !== null) { + $span->finish(); + $span->setStatus(SpanStatus::internalError()); } - - $this->currentHttpClientRequestSpan->finish(); - $this->currentHttpClientRequestSpan = null; - - SentrySdk::getCurrentHub()->setSpan($this->parentHttpClientRequestSpan); - $this->parentHttpClientRequestSpan = null; } protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): void { $parentSpan = SentrySdk::getCurrentHub()->getSpan(); - logger()->debug('queueJobProcessingHandler, current span: ' . $parentSpan?->getSpanId()); - // If there is no tracing span active and we don't trace jobs as transactions there is no need to handle the event if ($parentSpan === null && !$this->traceQueueJobsAsTransactions) { return; @@ -393,7 +329,6 @@ protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event): $span = SentrySdk::getCurrentHub()->startTransaction($context); } else { $span = $parentSpan->startChild($context); - logger()->debug('Starting child of ' . $parentSpan->getSpanId() . ', child is ' . $span->getSpanId()); } $this->pushSpan($span); @@ -423,15 +358,13 @@ private function afterQueuedJob(?SpanStatus $status = null): void private function pushSpan(Span $span): void { -// logger()->debug('push: got ' . count($this->currentSpanStack) . ' spans on the stack'); + $hub = SentrySdk::getCurrentHub(); - $this->parentSpanStack[] = SentrySdk::getCurrentHub()->getSpan(); + $this->parentSpanStack[] = $hub->getSpan(); - SentrySdk::getCurrentHub()->setSpan($span); + $hub->setSpan($span); $this->currentSpanStack[] = $span; - - logger()->debug('push: new span is ' . $span->getSpanId() . ', current: ' . SentrySdk::getCurrentHub()->getSpan()->getSpanId()); } private function popSpan(): ?Span @@ -440,14 +373,10 @@ private function popSpan(): ?Span return null; } -// logger()->debug('pop: got ' . count($this->currentSpanStack) . ' spans on the stack'); - $parent = array_pop($this->parentSpanStack); SentrySdk::getCurrentHub()->setSpan($parent); - logger()->debug('pop: new span is ' . $parent->getSpanId() . ', current: ' . SentrySdk::getCurrentHub()->getSpan()->getSpanId()); - return array_pop($this->currentSpanStack); } } diff --git a/src/Sentry/Laravel/Tracing/Integrations/LighthouseIntegration.php b/src/Sentry/Laravel/Tracing/Integrations/LighthouseIntegration.php index dc443a35..3a36257a 100644 --- a/src/Sentry/Laravel/Tracing/Integrations/LighthouseIntegration.php +++ b/src/Sentry/Laravel/Tracing/Integrations/LighthouseIntegration.php @@ -57,7 +57,7 @@ public function setupOnce(): void public function handleStartRequest(StartRequest $startRequest): void { - $this->previousSpan = Integration::currentTracingSpan(); + $this->previousSpan = SentrySdk::getCurrentHub()->getSpan(); if ($this->previousSpan === null) { return; diff --git a/src/Sentry/Laravel/Tracing/Middleware.php b/src/Sentry/Laravel/Tracing/Middleware.php index 33d2afe2..7bc21b43 100644 --- a/src/Sentry/Laravel/Tracing/Middleware.php +++ b/src/Sentry/Laravel/Tracing/Middleware.php @@ -28,6 +28,13 @@ class Middleware */ protected $appSpan; + /** + * The span for the `route` part of the application. + * + * @var \Sentry\Tracing\Span|null + */ + protected $routeSpan; + /** * The timestamp of application bootstrap completion. * @@ -49,7 +56,16 @@ public function handle(Request $request, Closure $next) $this->startTransaction($request, app(HubInterface::class)); } - return $next($request); + $response = $next($request); + + if ($this->routeSpan) { + $this->routeSpan->finish(); + $this->routeSpan = null; + + SentrySdk::getCurrentHub()->setSpan($this->appSpan); + } + + return $response; } /** @@ -98,6 +114,11 @@ public function setBootedTimestamp(?float $timestamp = null): void $this->bootedTimestamp = $timestamp ?? microtime(true); } + public function setRouteSpan(Span $span): void + { + $this->routeSpan = $span; + } + private function startTransaction(Request $request, HubInterface $sentry): void { $requestStartTime = $request->server('REQUEST_TIME_FLOAT', microtime(true)); diff --git a/src/Sentry/Laravel/Tracing/ServiceProvider.php b/src/Sentry/Laravel/Tracing/ServiceProvider.php index 336e6025..1071b8fb 100644 --- a/src/Sentry/Laravel/Tracing/ServiceProvider.php +++ b/src/Sentry/Laravel/Tracing/ServiceProvider.php @@ -2,6 +2,8 @@ namespace Sentry\Laravel\Tracing; +use Illuminate\Contracts\Container\BindingResolutionException; +use Illuminate\Contracts\Events\Dispatcher; use Illuminate\Contracts\Http\Kernel as HttpKernelInterface; use Illuminate\Contracts\View\Engine; use Illuminate\Contracts\View\View; @@ -59,17 +61,21 @@ public function register(): void private function bindEvents(array $tracingConfig): void { $handler = new EventHandler( - $this->app, - $this->app->make(BacktraceHelper::class), - $tracingConfig + $tracingConfig, + $this->app->make(BacktraceHelper::class) ); - $handler->subscribe(); + try { + /** @var \Illuminate\Contracts\Events\Dispatcher $dispatcher */ + $dispatcher = $this->app->make(Dispatcher::class); - if ($this->app->bound('queue')) { - $handler->subscribeQueueEvents( - $this->app->make('queue') - ); + $handler->subscribe($dispatcher); + + if ($this->app->bound('queue')) { + $handler->subscribeQueueEvents($dispatcher, $this->app->make('queue')); + } + } catch (BindingResolutionException $e) { + // If we cannot resolve the event dispatcher we also cannot listen to events } } diff --git a/src/Sentry/Laravel/Tracing/ViewEngineDecorator.php b/src/Sentry/Laravel/Tracing/ViewEngineDecorator.php index 79e262b5..a153243f 100644 --- a/src/Sentry/Laravel/Tracing/ViewEngineDecorator.php +++ b/src/Sentry/Laravel/Tracing/ViewEngineDecorator.php @@ -4,7 +4,6 @@ use Illuminate\Contracts\View\Engine; use Illuminate\View\Factory; -use Sentry\Laravel\Integration; use Sentry\SentrySdk; use Sentry\Tracing\SpanContext; @@ -29,7 +28,7 @@ public function __construct(Engine $engine, Factory $viewFactory) */ public function get($path, array $data = []): string { - $parentSpan = Integration::currentTracingSpan(); + $parentSpan = SentrySdk::getCurrentHub()->getSpan(); if ($parentSpan === null) { return $this->engine->get($path, $data); diff --git a/test/Sentry/Tracing/EventHandlerTest.php b/test/Sentry/Tracing/EventHandlerTest.php index f71faac8..4e67b9cb 100644 --- a/test/Sentry/Tracing/EventHandlerTest.php +++ b/test/Sentry/Tracing/EventHandlerTest.php @@ -17,7 +17,7 @@ public function test_missing_event_handler_throws_exception() { $this->safeExpectException(RuntimeException::class); - $handler = new EventHandler($this->app, $this->app->make(BacktraceHelper::class), []); + $handler = new EventHandler([], $this->app->make(BacktraceHelper::class)); $handler->thisIsNotAHandlerAndShouldThrowAnException(); } @@ -31,7 +31,7 @@ public function test_all_mapped_event_handlers_exist() private function tryAllEventHandlerMethods(array $methods): void { - $handler = new EventHandler($this->app, $this->app->make(BacktraceHelper::class), []); + $handler = new EventHandler([], $this->app->make(BacktraceHelper::class)); $methods = array_map(static function ($method) { return "{$method}Handler"; From 3a0294c159010df5657b58866fc12458e583199b Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 13:41:54 +0200 Subject: [PATCH 4/8] Add changelog entries --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 96e945f4..017efd76 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - Drop support for Laravel 5.x (#581) - Remove `Sentry\Integration::extractNameForRoute()`, it's alternative `Sentry\Integration::extractNameAndSourceForRoute()` is marked as `@internal` (#580) - Remove extracting route name or controller for transaction names (#583). This unifies the transaction names to a more concise format. +- Remove internal `Sentry\Integration::currentTransaction()` and `Sentry\Integration::currentTracingSpan()`, use `SentrySdk::getCurrentHub()->getTransaction()` and `SentrySdk::getCurrentHub()->getSpan()` directly (#592) **Other changes** @@ -19,6 +20,7 @@ - Set the tracing transaction name on the `Illuminate\Routing\Events\RouteMatched` instead of at the end of the request (#580) - Add tracing span for Laravel HTTP client requests (#585) - Simplify Sentry meta tag retrieval, by adding `Sentry\Laravel\Integration::sentryMeta()` (#586) +- Fix tracing with nested queue jobs (mostly when running jobs in the `sync` driver) (#592) ## 2.14.2 From e2d3819f64c092b1809e179abe1f5c738efd3dfd Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 13:42:56 +0200 Subject: [PATCH 5/8] Remove code not meant to be in here --- src/Sentry/Laravel/Tracing/Middleware.php | 23 +---------------------- 1 file changed, 1 insertion(+), 22 deletions(-) diff --git a/src/Sentry/Laravel/Tracing/Middleware.php b/src/Sentry/Laravel/Tracing/Middleware.php index 7bc21b43..33d2afe2 100644 --- a/src/Sentry/Laravel/Tracing/Middleware.php +++ b/src/Sentry/Laravel/Tracing/Middleware.php @@ -28,13 +28,6 @@ class Middleware */ protected $appSpan; - /** - * The span for the `route` part of the application. - * - * @var \Sentry\Tracing\Span|null - */ - protected $routeSpan; - /** * The timestamp of application bootstrap completion. * @@ -56,16 +49,7 @@ public function handle(Request $request, Closure $next) $this->startTransaction($request, app(HubInterface::class)); } - $response = $next($request); - - if ($this->routeSpan) { - $this->routeSpan->finish(); - $this->routeSpan = null; - - SentrySdk::getCurrentHub()->setSpan($this->appSpan); - } - - return $response; + return $next($request); } /** @@ -114,11 +98,6 @@ public function setBootedTimestamp(?float $timestamp = null): void $this->bootedTimestamp = $timestamp ?? microtime(true); } - public function setRouteSpan(Span $span): void - { - $this->routeSpan = $span; - } - private function startTransaction(Request $request, HubInterface $sentry): void { $requestStartTime = $request->server('REQUEST_TIME_FLOAT', microtime(true)); From ed9212dab67858191fce22ab3e936947d9ecca3f Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Fri, 14 Oct 2022 14:29:51 +0200 Subject: [PATCH 6/8] Fix changelog entry --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 017efd76..d08b3d5f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,7 +12,7 @@ - Drop support for Laravel 5.x (#581) - Remove `Sentry\Integration::extractNameForRoute()`, it's alternative `Sentry\Integration::extractNameAndSourceForRoute()` is marked as `@internal` (#580) - Remove extracting route name or controller for transaction names (#583). This unifies the transaction names to a more concise format. -- Remove internal `Sentry\Integration::currentTransaction()` and `Sentry\Integration::currentTracingSpan()`, use `SentrySdk::getCurrentHub()->getTransaction()` and `SentrySdk::getCurrentHub()->getSpan()` directly (#592) +- Remove internal `Sentry\Integration::currentTracingSpan()`, use `SentrySdk::getCurrentHub()->getSpan()` if you were using this internal method. (#592) **Other changes** From 9254120d5b4445136663404326d2208685ca9ba5 Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Mon, 17 Oct 2022 13:58:23 +0200 Subject: [PATCH 7/8] Add `db.transaction` span (#594) --- CHANGELOG.md | 1 + src/Sentry/Laravel/Tracing/EventHandler.php | 41 ++++++++++++++++++++- 2 files changed, 41 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d08b3d5f..d9f1c0de 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ - Add tracing span for Laravel HTTP client requests (#585) - Simplify Sentry meta tag retrieval, by adding `Sentry\Laravel\Integration::sentryMeta()` (#586) - Fix tracing with nested queue jobs (mostly when running jobs in the `sync` driver) (#592) +- Add a `db.transaction` span, this span indicates the time that is spent inside a database transaction (#594) ## 2.14.2 diff --git a/src/Sentry/Laravel/Tracing/EventHandler.php b/src/Sentry/Laravel/Tracing/EventHandler.php index 36b0a096..3850d540 100644 --- a/src/Sentry/Laravel/Tracing/EventHandler.php +++ b/src/Sentry/Laravel/Tracing/EventHandler.php @@ -35,6 +35,9 @@ class EventHandler HttpClientEvents\RequestSending::class => 'httpClientRequestSending', HttpClientEvents\ResponseReceived::class => 'httpClientResponseReceived', HttpClientEvents\ConnectionFailed::class => 'httpClientConnectionFailed', + DatabaseEvents\TransactionBeginning::class => 'transactionBeginning', + DatabaseEvents\TransactionCommitted::class => 'transactionCommitted', + DatabaseEvents\TransactionRolledBack::class => 'transactionRolledBack', ]; /** @@ -116,6 +119,9 @@ public function __construct(array $config, BacktraceHelper $backtraceHelper) * * @uses self::routeMatchedHandler() * @uses self::queryExecutedHandler() + * @uses self::transactionBeginningHandler() + * @uses self::transactionCommittedHandler() + * @uses self::transactionRolledBackHandler() * @uses self::httpClientRequestSendingHandler() * @uses self::httpClientResponseReceivedHandler() * @uses self::httpClientConnectionFailedHandler() @@ -240,6 +246,40 @@ private function resolveQueryOriginFromBacktrace(): ?string return "{$filePath}:{$firstAppFrame->getLine()}"; } + protected function transactionBeginningHandler(DatabaseEvents\TransactionBeginning $event): void + { + $parentSpan = SentrySdk::getCurrentHub()->getSpan(); + + if ($parentSpan === null) { + return; + } + + $context = new SpanContext; + $context->setOp('db.transaction'); + + $this->pushSpan($parentSpan->startChild($context)); + } + + protected function transactionCommittedHandler(DatabaseEvents\TransactionCommitted $event): void + { + $span = $this->popSpan(); + + if ($span !== null) { + $span->finish(); + $span->setStatus(SpanStatus::ok()); + } + } + + protected function transactionRolledBackHandler(DatabaseEvents\TransactionRolledBack $event): void + { + $span = $this->popSpan(); + + if ($span !== null) { + $span->finish(); + $span->setStatus(SpanStatus::internalError()); + } + } + protected function httpClientRequestSendingHandler(HttpClientEvents\RequestSending $event): void { $parentSpan = SentrySdk::getCurrentHub()->getSpan(); @@ -252,7 +292,6 @@ protected function httpClientRequestSendingHandler(HttpClientEvents\RequestSendi $context->setOp('http.client'); $context->setDescription($event->request->method() . ' ' . $event->request->url()); - $context->setStartTimestamp(microtime(true)); $this->pushSpan($parentSpan->startChild($context)); } From d8f1a8a014f54f9586823d7eaed0711b95e870a7 Mon Sep 17 00:00:00 2001 From: Alex Bouma Date: Mon, 17 Oct 2022 14:00:59 +0200 Subject: [PATCH 8/8] Add `http.route` span (#593) --- CHANGELOG.md | 1 + .../TracingCallableDispatcherTracing.php | 24 +++++++++++++ .../TracingControllerDispatcherTracing.php | 29 +++++++++++++++ .../Routing/TracingRoutingDispatcher.php | 36 +++++++++++++++++++ .../Laravel/Tracing/ServiceProvider.php | 17 +++++++++ 5 files changed, 107 insertions(+) create mode 100644 src/Sentry/Laravel/Tracing/Routing/TracingCallableDispatcherTracing.php create mode 100644 src/Sentry/Laravel/Tracing/Routing/TracingControllerDispatcherTracing.php create mode 100644 src/Sentry/Laravel/Tracing/Routing/TracingRoutingDispatcher.php diff --git a/CHANGELOG.md b/CHANGELOG.md index d9f1c0de..a5eefcec 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ - Add tracing span for Laravel HTTP client requests (#585) - Simplify Sentry meta tag retrieval, by adding `Sentry\Laravel\Integration::sentryMeta()` (#586) - Fix tracing with nested queue jobs (mostly when running jobs in the `sync` driver) (#592) +- Add a `http.route` span, this span indicates the time that is spent inside a controller method or route closure (#593) - Add a `db.transaction` span, this span indicates the time that is spent inside a database transaction (#594) ## 2.14.2 diff --git a/src/Sentry/Laravel/Tracing/Routing/TracingCallableDispatcherTracing.php b/src/Sentry/Laravel/Tracing/Routing/TracingCallableDispatcherTracing.php new file mode 100644 index 00000000..7ccb1062 --- /dev/null +++ b/src/Sentry/Laravel/Tracing/Routing/TracingCallableDispatcherTracing.php @@ -0,0 +1,24 @@ +dispatcher = $dispatcher; + } + + public function dispatch(Route $route, $callable) + { + return $this->wrapRouteDispatch(function () use ($route, $callable) { + return $this->dispatcher->dispatch($route, $callable); + }, $route); + } +} diff --git a/src/Sentry/Laravel/Tracing/Routing/TracingControllerDispatcherTracing.php b/src/Sentry/Laravel/Tracing/Routing/TracingControllerDispatcherTracing.php new file mode 100644 index 00000000..1cedda2c --- /dev/null +++ b/src/Sentry/Laravel/Tracing/Routing/TracingControllerDispatcherTracing.php @@ -0,0 +1,29 @@ +dispatcher = $dispatcher; + } + + public function dispatch(Route $route, $controller, $method) + { + return $this->wrapRouteDispatch(function () use ($route, $controller, $method) { + return $this->dispatcher->dispatch($route, $controller, $method); + }, $route); + } + + public function getMiddleware($controller, $method) + { + return $this->dispatcher->getMiddleware($controller, $method); + } +} diff --git a/src/Sentry/Laravel/Tracing/Routing/TracingRoutingDispatcher.php b/src/Sentry/Laravel/Tracing/Routing/TracingRoutingDispatcher.php new file mode 100644 index 00000000..98212973 --- /dev/null +++ b/src/Sentry/Laravel/Tracing/Routing/TracingRoutingDispatcher.php @@ -0,0 +1,36 @@ +getSpan(); + + // When there is no active transaction we can skip doing anything and just immediately return the callable + if ($parentSpan === null) { + return $dispatch(); + } + + $context = new SpanContext; + $context->setOp('http.route'); + $context->setDescription($route->getActionName()); + + $span = $parentSpan->startChild($context); + + SentrySdk::getCurrentHub()->setSpan($span); + + try { + return $dispatch(); + } finally { + $span->finish(); + + SentrySdk::getCurrentHub()->setSpan($parentSpan); + } + } +} diff --git a/src/Sentry/Laravel/Tracing/ServiceProvider.php b/src/Sentry/Laravel/Tracing/ServiceProvider.php index 1071b8fb..cd56d2d4 100644 --- a/src/Sentry/Laravel/Tracing/ServiceProvider.php +++ b/src/Sentry/Laravel/Tracing/ServiceProvider.php @@ -8,10 +8,14 @@ use Illuminate\Contracts\View\Engine; use Illuminate\Contracts\View\View; use Illuminate\Foundation\Http\Kernel as HttpKernel; +use Illuminate\Routing\Contracts\CallableDispatcher; +use Illuminate\Routing\Contracts\ControllerDispatcher; use Illuminate\View\Engines\EngineResolver; use Illuminate\View\Factory as ViewFactory; use InvalidArgumentException; use Sentry\Laravel\BaseServiceProvider; +use Sentry\Laravel\Tracing\Routing\TracingCallableDispatcherTracing; +use Sentry\Laravel\Tracing\Routing\TracingControllerDispatcherTracing; use Sentry\Serializer\RepresentationSerializer; class ServiceProvider extends BaseServiceProvider @@ -29,6 +33,8 @@ public function boot(): void $this->bindViewEngine($tracingConfig); + $this->decorateRoutingDispatchers(); + if ($this->app->bound(HttpKernelInterface::class)) { /** @var \Illuminate\Foundation\Http\Kernel $httpKernel */ $httpKernel = $this->app->make(HttpKernelInterface::class); @@ -119,4 +125,15 @@ private function wrapViewEngine(Engine $realEngine): Engine return new ViewEngineDecorator($realEngine, $viewFactory); } + + private function decorateRoutingDispatchers(): void + { + $this->app->extend(CallableDispatcher::class, static function (CallableDispatcher $dispatcher) { + return new TracingCallableDispatcherTracing($dispatcher); + }); + + $this->app->extend(ControllerDispatcher::class, static function (ControllerDispatcher $dispatcher) { + return new TracingControllerDispatcherTracing($dispatcher); + }); + } }