Telescope Jobs watcher causes queued job exception

[Yahav]

Telescope Version

Latest

Laravel Version

10

PHP Version

8.2

Database Driver & Version

MariaDB

Description

When the Job watcher is enabled, jobs that are deleting the model they receive are never marked as Done nor the JobProcessed event dispached.
The problem is that Telescope listens to the JobProcessed event and try to fetch the model, however the model was already deleted and so a ModelNotFoundException is thrown causing the job to fail without being marked as failed or done.
Important to say that the job was actually completed but was never marked as such because of this issue.

Illuminate\Database\Eloquent\ModelNotFoundException No query results for model [App\Models\User].
vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:621 Illuminate\Database\Eloquent\Builder::firstOrFail
vendor/laravel/framework/src/Illuminate/Queue/SerializesAndRestoresModelIdentifiers.php:109 App\Jobs\DeleteUser::restoreModel
vendor/laravel/framework/src/Illuminate/Queue/SerializesAndRestoresModelIdentifiers.php:62 App\Jobs\DeleteUser::getRestoredPropertyValue
vendor/laravel/framework/src/Illuminate/Queue/SerializesModels.php:93 App\Jobs\DeleteUser::__unserialize
[internal] unserialize
vendor/laravel/telescope/src/Watchers/JobWatcher.php:247 Laravel\Telescope\Watchers\JobWatcher::getCommand
vendor/laravel/telescope/src/Watchers/JobWatcher.php:213 Laravel\Telescope\Watchers\JobWatcher::updateBatch
vendor/laravel/telescope/src/Watchers/JobWatcher.php:106 Laravel\Telescope\Watchers\JobWatcher::recordProcessedJob
vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php:458 Illuminate\Events\Dispatcher::Illuminate\Events{closure}
vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php:286 Illuminate\Events\Dispatcher::invokeListeners
vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php:266 Illuminate\Events\Dispatcher::dispatch
vendor/fntneves/laravel-transactional-events/src/Neves/Events/TransactionalDispatcher.php:110 Neves\Events\TransactionalDispatcher::dispatch
vendor/laravel/framework/src/Illuminate/Queue/Worker.php:668 Illuminate\Queue\Worker::raiseAfterJobEvent
vendor/laravel/framework/src/Illuminate/Queue/Worker.php:442 Illuminate\Queue\Worker::process
vendor/laravel/framework/src/Illuminate/Queue/Worker.php:390 Illuminate\Queue\Worker::runJob
vendor/laravel/framework/src/Illuminate/Queue/Worker.php:177 Illuminate\Queue\Worker::daemon
vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php:137 Illuminate\Queue\Console\WorkCommand::runWorker
vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php:120 Illuminate\Queue\Console\WorkCommand::handle
vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:36 Illuminate\Container\BoundMethod::Illuminate\Container{closure}
vendor/laravel/framework/src/Illuminate/Container/Util.php:41 Illuminate\Container\Util::unwrapIfClosure
vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:93 Illuminate\Container\BoundMethod::callBoundMethod
vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:35 Illuminate\Container\BoundMethod::call
vendor/laravel/framework/src/Illuminate/Container/Container.php:662 Illuminate\Container\Container::call
vendor/laravel/framework/src/Illuminate/Console/Command.php:211 Illuminate\Console\Command::execute
vendor/symfony/console/Command/Command.php:326 Symfony\Component\Console\Command\Command::run
vendor/laravel/framework/src/Illuminate/Console/Command.php:180 Illuminate\Console\Command::run
vendor/symfony/console/Application.php:1096 Symfony\Component\Console\Application::doRunCommand
vendor/symfony/console/Application.php:324 Symfony\Component\Console\Application::doRun
vendor/symfony/console/Application.php:175 Symfony\Component\Console\Application::run
vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php:201 Illuminate\Foundation\Console\Kernel::handle
artisan:35 [main]

Steps To Reproduce

Enable Telescope Job watcher
Create a job that receives a model and deletes it
Queue and run it

[driesvints]

Heya, thanks for reporting.

We'll need more info and/or code to debug this further. Can you please create a repository with the command below, commit the code that reproduces the issue as one separate commit on the main/master branch and share the repository here? Please make sure that you have the latest version of the Laravel installer in order to run this command. Please also make sure you have both Git & the GitHub CLI tool properly set up.

laravel new bug-report --github="--public"

Please do not amend and create a separate commit with your custom changes. After you've posted the repository, we'll try to reproduce the issue.

Thanks!

[moessimple]

Hey. I think i can reproduce the bug.

• git clone [email protected]:moessimple/bug-report.git
• cd bug-report
• composer install
• php artisan migrate
• php artisan reproduce-bug -vvv

Custom Changes

moessimple/bug-report@afd5bd1

Background

The QUEUE_CONNECTION is set to sync and I ignore missing models with public $deleteWhenMissingModels = true;.

Expectation

I expected that no exception would be thrown, but it throws a ModelNotFoundException.

Output

Illuminate\Database\Eloquent\ModelNotFoundException

No query results for model [App\Models\User].

at vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:629
625▕         if (! is_null($model = $this->first($columns))) {
626▕             return $model;
627▕         }
628▕
➜ 629▕         throw (new ModelNotFoundException)->setModel(get_class($this->model));
630▕     }
631▕
632▕     /**
633▕      * Execute the query and get the first result or call a callback.

1   vendor/laravel/framework/src/Illuminate/Queue/SerializesAndRestoresModelIdentifiers.php:109
Illuminate\Database\Eloquent\Builder::firstOrFail()

2   vendor/laravel/framework/src/Illuminate/Queue/SerializesAndRestoresModelIdentifiers.php:62
App\Jobs\DeleteUserJob::restoreModel(Object(Illuminate\Contracts\Database\ModelIdentifier))

3   vendor/laravel/framework/src/Illuminate/Queue/SerializesModels.php:93
App\Jobs\DeleteUserJob::getRestoredPropertyValue(Object(Illuminate\Contracts\Database\ModelIdentifier))

4   [internal]:0
App\Jobs\DeleteUserJob::__unserialize([Object(Illuminate\Contracts\Database\ModelIdentifier)])
5   vendor/laravel/telescope/src/Watchers/JobWatcher.php:247

6   vendor/laravel/telescope/src/Watchers/JobWatcher.php:213
Laravel\Telescope\Watchers\JobWatcher::getCommand(["App\Jobs\DeleteUserJob", "O:22:"App\Jobs\DeleteUserJob":1:{s:4:"user";O:45:"Illuminate\Contracts\Database\ModelIdentifier":5:{s:5:"class";s:15:"App\Models\User";s:2:"id";i:1;s:9:"relations";a:0:{}s:10:"connection";s:6:"sqlite";s:15:"collectionClass";N;}}"])

7   vendor/laravel/telescope/src/Watchers/JobWatcher.php:106
Laravel\Telescope\Watchers\JobWatcher::updateBatch()

8   vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php:458
Laravel\Telescope\Watchers\JobWatcher::recordProcessedJob(Object(Illuminate\Queue\Events\JobProcessed))
...

[driesvints]

Thanks for the repo. I managed to reproduce it this way.

This indeed seems like a bad combo of this scenario with Telescope. I don't feel the deleteWhenMissingModels property should have any influence here as the same thing happens without it.

I'm really wondering what the solution here is. Ideally we should be able to extract the command regardless of the missing property model(s) and then later one ignore or redact missing property models when we extract them. Difficult one..

Would really appreciate more insights or suggestions here, thanks.

[github-actions]

Thank you for reporting this issue!

As Laravel is an open source project, we rely on the community to help us diagnose and fix issues as it is not possible to research and fix every issue reported to us via GitHub.

If possible, please make a pull request fixing the issue you have described, along with corresponding tests. All pull requests are promptly reviewed by the Laravel team.

Thank you!

[driesvints]

Btw, an easy solution and something I always recommend doing for these kind of jobs is not passing along the entire model but just the identifier and then retrieving the model inside the job itself.

[Yahav]

Btw, an easy solution and something I always recommend doing for these kind of jobs is not passing along the entire model but just the identifier and then retrieving the model inside the job itself.

That's not really a solution now, is it?
The recommended way to handle job dependencies is to actually do pass the model itself, that is the "Laravel way" imho (granted, i'm in no position to lecture you about the "Laravel way") ; proper type-hinting and all the benefits that comes with that, automatic dependency resolution etc, those are to be gained by this way.
What's the benefit of not passing the model itself? (besides to make this specific Telescope issue work)

As for the solution for this, i haven't dug into Telescope source so i won't be able to provide a proper solution, but it seems to me that since a worker can only pick one job at the time and that JobWatcher methods are mainly statically called, it makes sense to have some sort of a temporary storage mechanism for jobs while they processed. eg:
You pickup a job, add its details to a static property, in updateBatch, catch ModelNotFound exception in order for them not to be caught by the worker, and use the temporary storage property to fetch the job command or whatever else is necessary for Telescope logging.

[alaminfirdows]

I'm also experiencing the same issue with Laravel 11.

[davemagro]

happens to me with Laravel 11 as well. reported it as an issue to laravel/framework initially and was able to trace it back to telescope. laravel/framework#51860

I have the same findings as the author, it being the unserialize function executed on the model that is already deleted therefore raising a ModelNotFoundException exception.

[hadees-ahmed]

@driesvints @taylorotwell I have investigated this issue a bit and I think i have a solution for it but need to confirm will this make sense or not.
Solution
we can solve this by putting a check to __unserialize only if the job is failed , not processed etc but in the case if the job is executed successfully and performed its action that it is supposed to do we should skip this __unserialize step in this way we can overcome this problem.

if this seems fine please let me know I will create a PR in Laravel Repo with solution thanks

[driesvints]

Thanks @hadees-ahmed. We'd really need some code to look at so feel free to make that PR so we can consider it.

[andrey-helldar]

I've run into this problem too.

Laravel Framework 11.23.4
Laravel Telescope 5.2.2

This job doesn't work:

class TestJob implements ShouldQueue
{
    use Dispatchable;
    use InteractsWithQueue;
    use Queueable;
    use SerializesModels;

    public function __construct(
        protected Webhook $model
    ) {}

    public function handle(): void
    {
        $this->model->delete();
    }
}

When I switch the TELESCOPE_JOB_WATCHER parameter to false, then there are no errors.

But I found one more interesting detail - if I remove the SerializesModels trait from the job class, then the error disappears:

class TestJob implements ShouldQueue
{
    use Dispatchable;
    use InteractsWithQueue;
    use Queueable;
    // use SerializesModels;

    public function __construct(
        protected Webhook $model
    ) {}

    public function handle(): void
    {
        $this->model->delete();
    }
}

[hapidjus]

Same problem here but different cause (tenant database connection not instantiated)

Been looking at the code for a while now and the only solution I've come up with is to use preg_match for getting the batch_id instead of unserializing the payload. But it feels a bit janky.

I've put together a PR in order to show some code. #1539