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.