Repository: getsentry/sentry-laravel (php)

Issue:
Performance monitoring for jobs in queue
Hi there,
first of all, thanks for all you great work!

I correctly receive on sentry all errors and performance tracking info for "normal" web requests in my laravel apps. 

Is there a way to have performance monitoring tracking for jobs that run on queue via database adapter?

Should be nice to have them reported with the job name as transaction key, the same we have for standard request with route name as transaction key. It should respect sample trace ratio configured, of course.. 

If it is already implemented is there some doc to read to configure it? 

Pull request:
Add tracing support for queue jobs
This adds (opt-in) support for queue job tracing.

When the feature is disabled jobs running on the `sync` queue or with `dispatch_sync` (Laravel 8) will still show up when a transaction is active, but jobs running in a queue worker / Horizon will not generate transactions.

Also adds some other toggles to disable certain span if needed.

Fixes #456.

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index d1c3713..913ef53 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -5,6 +5,8 @@
 - Remove wrapper around the context of log entry breadcrumbs (#405)
 - Ensure user integrations are always executed after SDK integrations (#474)
 - Fix repeated booted callback registration from performance tracing middleware (#475)
+- Add tracing support for queue jobs (#478)
+- Add options to disable query and view tracing (#478)
 
 ## 2.4.2
 
diff --git a/config/sentry.php b/config/sentry.php
index b283146..ca093ba 100644
--- a/config/sentry.php
+++ b/config/sentry.php
@@ -27,6 +27,20 @@ return [
         'command_info' => true,
     ],
 
+    'tracing' => [
+        // Trace queue jobs as their own transactions
+        'queue_job_transactions' => env('SENTRY_TRACE_QUEUE_ENABLED', false),
+
+        // Capture queue jobs as spans when executed on the sync driver
+        'queue_jobs' => true,
+
+        // Capture SQL queries as spans
+        'sql_queries' => true,
+
+        // Capture views as spans
+        'views' => true,
+    ],
+
     // @see: https://docs.sentry.io/platforms/php/configuration/options/#send-default-pii
     'send_default_pii' => false,
 
diff --git a/src/Sentry/Laravel/Integration.php b/src/Sentry/Laravel/Integration.php
index 97dddb7..d69ea00 100644
--- a/src/Sentry/Laravel/Integration.php
+++ b/src/Sentry/Laravel/Integration.php
@@ -7,6 +7,7 @@ use Illuminate\Support\Str;
 use Sentry\FlushableClientInterface;
 use Sentry\SentrySdk;
 use Sentry\Tracing\Span;
+use Sentry\Tracing\Transaction;
 use function Sentry\addBreadcrumb;
 use function Sentry\configureScope;
 use Sentry\Breadcrumb;
diff --git a/src/Sentry/Laravel/ServiceProvider.php b/src/Sentry/Laravel/ServiceProvider.php
index 78baa89..39ffd51 100644
--- a/src/Sentry/Laravel/ServiceProvider.php
+++ b/src/Sentry/Laravel/ServiceProvider.php
@@ -22,7 +22,8 @@ class ServiceProvider extends BaseServiceProvider
      * List of configuration options that are Laravel specific and should not be sent to the base PHP SDK.
      */
     private const LARAVEL_SPECIFIC_OPTIONS = [
-        // We do not want this setting to hit our main client because it's Laravel specific
+        // We do not want these settings to hit the PHP SDK because it's Laravel specific and the SDK will throw errors
+        'tracing',
         'breadcrumbs',
         // We resolve the integrations through the container later, so we initially do not pass it to the SDK yet
         'integrations',
@@ -40,7 +41,7 @@ class ServiceProvider extends BaseServiceProvider
         $this->app->make(HubInterface::class);
 
         if ($this->hasDsnSet()) {
-            $this->bindEvents($this->app);
+            $this->bindEvents();
 
             if ($this->app instanceof Lumen) {
                 $this->app->middleware(SetRequestIpMiddleware::class);
diff --git a/src/Sentry/Laravel/Tracing/EventHandler.php b/src/Sentry/Laravel/Tracing/EventHandler.php
index ede7079..dcd497c 100644
--- a/src/Sentry/Laravel/Tracing/EventHandler.php
+++ b/src/Sentry/Laravel/Tracing/EventHandler.php
@@ -3,11 +3,18 @@
 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\QueryExecuted;
+use Illuminate\Database\Events as DatabaseEvents;
+use Illuminate\Queue\Events as QueueEvents;
+use Illuminate\Queue\QueueManager;
 use RuntimeException;
 use Sentry\Laravel\Integration;
+use Sentry\SentrySdk;
 use Sentry\Tracing\SpanContext;
+use Sentry\Tracing\SpanStatus;
+use Sentry\Tracing\TransactionContext;
 
 class EventHandler
 {
@@ -17,25 +24,76 @@ class EventHandler
      * @var array
      */
     protected static $eventHandlerMap = [
-        'illuminate.query'   => 'query',         // Until Laravel 5.1
-        QueryExecuted::class => 'queryExecuted', // Since Laravel 5.2
+        'illuminate.query' => 'query',                          // Until Laravel 5.1
+        DatabaseEvents\QueryExecuted::class => 'queryExecuted', // Since Laravel 5.2
     ];
 
     /**
-     * The Laravel event dispatcher.
+     * Map queue event handlers to events.
      *
-     * @var \Illuminate\Contracts\Events\Dispatcher
+     * @var array
+     */
+    protected static $queueEventHandlerMap = [
+        QueueEvents\JobProcessing::class => 'queueJobProcessing',               // Since Laravel 5.2
+        QueueEvents\JobProcessed::class => 'queueJobProcessed',                 // Since Laravel 5.2
+        QueueEvents\JobExceptionOccurred::class => 'queueJobExceptionOccurred', // Since Laravel 5.2
+    ];
+
+    /**
+     * The Laravel container.
+     *
+     * @var \Illuminate\Contracts\Container\Container
+     */
+    private $container;
+
+    /**
+     * Indicates if we should we add SQL queries as spans.
+     *
+     * @var bool
+     */
+    private $traceSqlQueries;
+
+    /**
+     * Indicates if we should trace queue job spans.
+     *
+     * @var bool
+     */
+    private $traceQueueJobs;
+
+    /**
+     * Indicates if we should trace queue jobs as separate transactions.
+     *
+     * @var bool
+     */
+    private $traceQueueJobsAsTransactions;
+
+    /**
+     * Holds a reference to the parent queue job span.
+     *
+     * @var \Sentry\Tracing\Span|null
+     */
+    private $parentQueueJobSpan;
+
+    /**
+     * Holds a reference to the current queue job span or transaction.
+     *
+     * @var \Sentry\Tracing\Transaction|\Sentry\Tracing\Span|null
      */
-    private $events;
+    private $currentQueueJobSpan;
 
     /**
      * EventHandler constructor.
      *
-     * @param \Illuminate\Contracts\Events\Dispatcher $events
+     * @param \Illuminate\Contracts\Container\Container $container
+     * @param array                                     $config
      */
-    public function __construct(Dispatcher $events)
+    public function __construct(Container $container, array $config)
     {
-        $this->events = $events;
+        $this->container = $container;
+
+        $this->traceSqlQueries = ($config['sql_queries'] ?? true) === true;
+        $this->traceQueueJobs = ($config['queue_jobs'] ?? false) === true;
+        $this->traceQueueJobsAsTransactions = ($config['queue_job_transactions'] ?? false) === true;
     }
 
     /**
@@ -43,8 +101,43 @@ class EventHandler
      */
     public function subscribe(): void
     {
-        foreach (static::$eventHandlerMap as $eventName => $handler) {
-            $this->events->listen($eventName, [$this, $handler]);
+        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
+        }
+    }
+
+    /**
+     * Attach all queue event handlers.
+     *
+     * @param \Illuminate\Queue\QueueManager $queue
+     */
+    public function subscribeQueueEvents(QueueManager $queue): void
+    {
+        // If both types of queue job tracing is disabled also do not register the events
+        if (!$this->traceQueueJobs && !$this->traceQueueJobsAsTransactions) {
+            return;
+        }
+
+        $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
         }
     }
 
@@ -62,13 +155,6 @@ class EventHandler
             throw new RuntimeException("Missing tracing event handler: {$handlerMethod}");
         }
 
-        $parentSpan = Integration::currentTracingSpan();
-
-        // If there is no tracing span active there is no need to handle the event
-        if ($parentSpan === null) {
-            return;
-        }
-
         try {
             call_user_func_array([$this, $handlerMethod], $arguments);
         } catch (Exception $exception) {
@@ -94,7 +180,7 @@ class EventHandler
      *
      * @param \Illuminate\Database\Events\QueryExecuted $query
      */
-    protected function queryExecutedHandler(QueryExecuted $query): void
+    protected function queryExecutedHandler(DatabaseEvents\QueryExecuted $query): void
     {
         $this->recordQuerySpan($query->sql, $query->time);
     }
@@ -107,8 +193,17 @@ class EventHandler
      */
     private function recordQuerySpan($query, $time): void
     {
+        if (!$this->traceSqlQueries) {
+            return;
+        }
+
         $parentSpan = Integration::currentTracingSpan();
 
+        // If there is no tracing span active there is no need to handle the event
+        if ($parentSpan === null) {
+            return;
+        }
+
         $context = new SpanContext();
         $context->setOp('sql.query');
         $context->setDescription($query);
@@ -117,4 +212,93 @@ class EventHandler
 
         $parentSpan->startChild($context);
     }
+
+    /**
+     * Since Laravel 5.2
+     *
+     * @param \Illuminate\Queue\Events\JobProcessing $event
+     */
+    protected function queueJobProcessingHandler(QueueEvents\JobProcessing $event)
+    {
+        $parentSpan = Integration::currentTracingSpan();
+
+        // 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;
+        }
+
+        // If there is a parent span we can record that job as a child unless configured to not do so
+        if ($parentSpan !== null && !$this->traceQueueJobs) {
+            return;
+        }
+
+        $this->parentQueueJobSpan = $parentSpan;
+
+        $spanContext = $parentSpan === null
+            ? new TransactionContext(
+                method_exists($event->job, 'resolveName')
+                    ? $event->job->resolveName()
+                    : $event->job->getName()
+            )
+            : new SpanContext();
+
+        $job = [
+            'job' => $event->job->getName(),
+            'queue' => $event->job->getQueue(),
+            'attempts' => $event->job->attempts(),
+            'connection' => $event->connectionName,
+        ];
+
+        // Resolve name exists only from Laravel 5.3+
+        if (method_exists($event->job, 'resolveName')) {
+            $job['resolved'] = $event->job->resolveName();
+        }
+
+        $spanContext->setOp('queue.job');
+        $spanContext->setData($job);
+        $spanContext->setStartTimestamp(microtime(true));
+
+        // 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($spanContext);
+        } else {
+            $this->currentQueueJobSpan = $parentSpan->startChild($spanContext);
+        }
+
+        SentrySdk::getCurrentHub()->setSpan($this->currentQueueJobSpan);
+    }
+
+    /**
+     * Since Laravel 5.2
+     *
+     * @param \Illuminate\Queue\Events\JobExceptionOccurred $event
+     */
+    protected function queueJobExceptionOccurredHandler(QueueEvents\JobExceptionOccurred $event)
+    {
+        $this->afterQueuedJob(SpanStatus::internalError());
+    }
+
+    /**
+     * Since Laravel 5.2
+     *
+     * @param \Illuminate\Queue\Events\JobProcessed $event
+     */
+    protected function queueJobProcessedHandler(QueueEvents\JobProcessed $event)
+    {
+        $this->afterQueuedJob(SpanStatus::ok());
+    }
+
+    private function afterQueuedJob(?SpanStatus $status = null): void
+    {
+        if ($this->currentQueueJobSpan === null) {
+            return;
+        }
+
+        $this->currentQueueJobSpan->setStatus($status);
+        $this->currentQueueJobSpan->finish();
+        $this->currentQueueJobSpan = null;
+
+        SentrySdk::getCurrentHub()->setSpan($this->parentQueueJobSpan);
+        $this->parentQueueJobSpan = null;
+    }
 }
diff --git a/src/Sentry/Laravel/Tracing/ServiceProvider.php b/src/Sentry/Laravel/Tracing/ServiceProvider.php
index f7bafbf..41eda3d 100644
--- a/src/Sentry/Laravel/Tracing/ServiceProvider.php
+++ b/src/Sentry/Laravel/Tracing/ServiceProvider.php
@@ -16,9 +16,11 @@ class ServiceProvider extends BaseServiceProvider
     public function boot(): void
     {
         if ($this->hasDsnSet()) {
-            $this->bindEvents($this->app);
+            $tracingConfig = $this->getUserConfig()['tracing'] ?? [];
 
-            $this->bindViewEngine();
+            $this->bindEvents($tracingConfig);
+
+            $this->bindViewEngine($tracingConfig);
 
             if ($this->app instanceof Lumen) {
                 $this->app->middleware(Middleware::class);
@@ -44,15 +46,23 @@ class ServiceProvider extends BaseServiceProvider
         }
     }
 
-    private function bindEvents(): void
+    private function bindEvents(array $tracingConfig): void
     {
-        $handler = new EventHandler($this->app->events);
+        $handler = new EventHandler($this->app, $tracingConfig);
 
         $handler->subscribe();
+
+        if ($this->app->bound('queue')) {
+            $handler->subscribeQueueEvents($this->app->queue);
+        }
     }
 
-    private function bindViewEngine(): void
+    private function bindViewEngine($tracingConfig): void
     {
+        if (($tracingConfig['views'] ?? true) !== true) {
+            return;
+        }
+
         $viewEngineWrapper = function (EngineResolver $engineResolver): void {
             foreach (['file', 'php', 'blade'] as $engineName) {
                 try {


Test patch:
diff --git a/test/Sentry/Tracing/EventHandlerTest.php b/test/Sentry/Tracing/EventHandlerTest.php
index 78f75d7..470363b 100644
--- a/test/Sentry/Tracing/EventHandlerTest.php
+++ b/test/Sentry/Tracing/EventHandlerTest.php
@@ -2,14 +2,11 @@
 
 namespace Sentry\Laravel\Tests\Tracing;
 
-use Mockery;
 use ReflectionClass;
 use Orchestra\Testbench\TestCase;
 use RuntimeException;
 use Sentry\Laravel\Tests\ExpectsException;
 use Sentry\Laravel\Tracing\EventHandler;
-use Sentry\SentrySdk;
-use Sentry\Tracing\TransactionContext;
 
 class EventHandlerTest extends TestCase
 {
@@ -19,7 +16,7 @@ class EventHandlerTest extends TestCase
     {
         $this->safeExpectException(RuntimeException::class);
 
-        $handler = new EventHandler($this->app->events);
+        $handler = new EventHandler($this->app, []);
 
         $handler->thisIsNotAHandlerAndShouldThrowAnException();
     }
@@ -31,32 +28,9 @@ class EventHandlerTest extends TestCase
         );
     }
 
-    public function test_handlers_are_not_called_when_no_transaction()
-    {
-        SentrySdk::getCurrentHub()->setSpan(null);
-
-        $eventHandlerMock = Mockery::mock(EventHandler::class)->makePartial();
-
-        $eventHandlerMock->shouldReceive('__call')->withArgs(['queryHandler', []]);
-
-        $eventHandlerMock->query();
-    }
-
-    public function test_handlers_are_called_when_transaction_is_present()
-    {
-        $transaction = SentrySdk::getCurrentHub()->startTransaction(new TransactionContext());
-        SentrySdk::getCurrentHub()->setSpan($transaction);
-
-        $eventHandlerMock = Mockery::mock(EventHandler::class)->makePartial()->shouldAllowMockingProtectedMethods();
-
-        $eventHandlerMock->shouldReceive('queryHandler')->withArgs(['', [], 0, ''])->once();
-
-        $eventHandlerMock->query('', [], 0, '');
-    }
-
     private function tryAllEventHandlerMethods(array $methods): void
     {
-        $handler = new EventHandler($this->app->events, []);
+        $handler = new EventHandler($this->app, []);
 
         $methods = array_map(static function ($method) {
             return "{$method}Handler";