getsentry / sentry-laravel

The official Laravel SDK for Sentry (sentry.io)
https://sentry.io
MIT License
1.26k stars 188 forks source link

Queue Worker Job is not tagged and not traceable. #763

Closed AidasK closed 1 year ago

AidasK commented 1 year ago

Problem Statement

It's impossible to know which queue job is failing since Job class is not tagged and not added to the breadcrumbs. Since our application has more than 50+ different jobs running on the same queue it's impossible to know where to look for an issue. There is also no stack trace on this issue.

Example:

image

Solution Brainstorm

Add queue listener which would tag each job class before running it.

cleptric commented 1 year ago

Can you please provide us with all the information we ask for when creating a new issue via our bug template?

Which Laravel version you are using?

Did you report this manually, or are you using a log channel?

AidasK commented 1 year ago

SDK: 3.6.1 Laravel 9.52.10. PHP: 8.2.4 We are using saas sentry.io. Error was reported automatically with the log channel.

In breadcrumbs I have enabled queue_info, cache, command_info and logs. None of them contains any useful information to detect a job.

Steps to reporduce:

  1. Change exception handler to this class. All it does is making that ModelNotFoundException would be reportable in the queues so that we log these issues as they might contain some meaningful errors in our use case. It works as expected, but sentry issues does not contain job identifiable data.
<?php

declare(strict_types=1);

namespace App\Exceptions;

use App\Exceptions\Orders\Payments\SubscriptionChargeFailed;
use Illuminate\Database\Eloquent\ModelNotFoundException;
use Illuminate\Database\RecordsNotFoundException;
use Illuminate\Foundation\Exceptions\Handler as ExceptionHandler;

class Handler extends ExceptionHandler
{
    /**
     * A list of the exception types that are not reported.
     *
     * @var array
     */
    protected $dontReport = [
        SubscriptionChargeFailed::class,
    ];

    /**
     * A list of the inputs that are never flashed for validation exceptions.
     *
     * @var array
     */
    protected $dontFlash = [
        'current_password',
        'password',
        'password_confirmation',
    ];

    public function register()
    {
        $report = [
            RecordsNotFoundException::class,
            ModelNotFoundException::class,
        ];
        $this->internalDontReport = array_filter(
            $this->internalDontReport,
            fn ($value) => !in_array($value, $report, true)
        );
        $this->reportable(function (ModelNotFoundException $e) {
            return app()->runningInConsole();
        });
    }
}
  1. Dispatch a job with an non existent model like SendEmail::dispatch(99999). User should not exist with id 99999. Queue driver should be redis or database. Example:
    
    <?php

declare(strict_types=1);

namespace App\Jobs;

use Illuminate\Bus\Queueable; use Illuminate\Contracts\Queue\ShouldQueue; use Illuminate\Foundation\Bus\Dispatchable; use Illuminate\Queue\InteractsWithQueue;

class SendEmail implements ShouldQueue { use Dispatchable; use InteractsWithQueue; use Queueable;

public function __construct(private User $user)
{
}

public function handle(): void
{

// do nothing } }



3. Sentry should contain some information about SendEmail Job. Currently it only contains a command tag which does not help.
cleptric commented 1 year ago

We'll take a look

stayallive commented 1 year ago

I think you are leaving out some information. The queue job as described cannot be dispatched like SendEmail::dispatch(99999), because it wants a User so you need to supply it with a user model not just a ID. You are also not having the SerializesModels trait on the job, so even if you would dispatch a job with that it would just serialize the full model class and not do a query to get it from the database, which doesn't trigger the ModelNotFoundException.

But let's assume you just threw together an example and missed those bits, I've used the following job instead:

<?php

namespace App\Jobs;

use App\Models\User;
use Illuminate\Bus\Queueable;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Foundation\Bus\Dispatchable;
use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Queue\SerializesModels;

class SendEmail implements ShouldQueue
{
    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels;

    public function __construct(
        private User $user,
    ) {}

    public function handle(): void
    {
    }
}

And I dispatch it like so (on a Redis queue):

Route::get('/queue', function () {
    $user = new \App\Models\User();
    $user->id = 9999;
    $user->exists = true;

    dispatch(new \App\Jobs\SendEmail($user));

    return 'Dispatched!';
});

I also copied your ExceptionHandler into my fresh Laravel 9.52.10 project and ran a worker and called the /queue endpoint.

This of course fails with the following message in the Laravel logs:

[2023-09-01 07:40:43] local.ERROR: No query results for model [App\Models\User]. {"exception":"[object] (Illuminate\\Database\\Eloquent\\ModelNotFoundException(code: 0): No query results for model [App\\Models\\User]. at /Users/alex/dev/sentry-laravel-9-test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:598)

Now I am going to add Sentry, fresh from the box and set it up not using a reportable but with log channels: https://docs.sentry.io/platforms/php/guides/laravel/usage/#log-channels

I'll also take your version of the SDK (which is a few versions behind). You mentioned everything is was pretty much default so I've just followed the docs and added a Sentry log channel and added it to my default stack channel.

Now to run the example again (restarting queue etc.) and after running I get the following event in Sentry:

image

It's a proper exception with all the bells and whistles, including the following breadcrumb:

image

Now, your event on the other hand looks like a "message" so it didn't have an exception attached and it might have even be sent outside the normal queue work loop, which would explain the missing context since we of course reset the queue job context after every job.

So I have a hard time pinpointing what might be going on and why you are missing the exception in the log message, maybe there is some other handler or a failed method on the job or something catching the exception and converting it to a simple log message.

Hope you can shine a bit more light because from my reproduction it works as intended with the code you've shown me. Let me know what I missed!

AidasK commented 1 year ago

Thanks for taking a look @stayallive, that's super useful. Though I could not send you the exact steps to reproduce this, since the error above did not had queue.job breadcrumb in the stack. So I was not able to tell which job had this problem and on our system we have more than 50+ of different jobs. As you pointed out, I can see queue.job breadcrumb on other errors so probably we are having issues with some one job in our system.

Currently our sentry does not contain this error anymore, so I can not tell if we still have it or it was fixed somehow.

The strangest thing what caught my eye was that breadcrumbs did not contain queue.job, but instead it contained queue:restart cache event, but no events from queue itself. Even though it contained a tag command: queue:work. It even contained database query which means that queue job class should have been resolved and it started processing.

image

Anyway, I guess we can close it for now as we can not see it anymore. Thanks for all the tips!