romanzipp / Laravel-Queue-Monitor

Monitoring Laravel Jobs with your Database
https://packagist.org/packages/romanzipp/laravel-queue-monitor
MIT License
693 stars 91 forks source link

Failed jobs are marked as succeeded #67

Closed dkarvounaris closed 1 year ago

dkarvounaris commented 3 years ago

I have a scheduler, which schedules some jobs. These jobs are running as usually in a queue.

In the job I call the "fail" method when it should be marked as failed, which is also logged properly in Laravel's 'failed_jobs' database. However, in Laravel-Queue-Monitor, all jobs are marked as succeeded, regardless their real status.

For testing purposes I reduced the job to just this:

    public function handle()
    {
        $this->fail(new SupplierFeedUnretrievable($this->supplierFeed));
    }

While artisan queue:work recognizes that the job failed and shows:

[2021-05-19 16:50:02][52] Processing: App\Jobs\ProcessSupplierDownload
[2021-05-19 16:50:02][52] Failed:     App\Jobs\ProcessSupplierDownload
[2021-05-19 16:50:02][52] Processed:  App\Jobs\ProcessSupplierDownload

The job is still shown as "Success" in the UI and in the queue_monitor table the column failed is 0.

Is this a bug or am I doing something wrong?

dkarvounaris commented 3 years ago

If I modify in src/Providers/QueueMonitorProvider.php line 55 like this:

        $manager->after(static function (JobProcessed $event) {
            if (!$event->job->hasFailed()) {
                QueueMonitor::handleJobProcessed($event);
            }
        });

it seems to show "Success" and "Failed" properly. But I'm not sure, if this is all correct as I only dived very quickly in the source.

Without checking the rest of the source, I believe, that at first it logs the job correctly as failed, but the after method overwrites it as Laravel seems to call the event "Processed" too when failed like this, something that doesn't seem to happen if the job fails for some other reasons (ie. undefined class errors).

romanzipp commented 3 years ago

Actually I have never seen a job being emitted as failed and processed. Did you implement the failed method in your job class? A small code excerpt would be helpful to reproduce this issue.

dkarvounaris commented 3 years ago

This is one of the classes, completely stripped down to an absolute minimum and only parts left, which may matter or have an effect on how something is executed.

<?php

namespace App\Jobs;

use App\Exceptions\IcecatFeedInvalidFile;
use App\Models\IcecatFeed;
use Illuminate\Bus\Queueable;
use Illuminate\Contracts\Queue\ShouldBeUnique;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Foundation\Bus\Dispatchable;
use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Queue\SerializesModels;
use romanzipp\QueueMonitor\Traits\IsMonitored;

class ProcessIcecatDownload implements ShouldQueue, ShouldBeUnique
{
    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels, IsMonitored;

    protected IcecatFeed $icecatFeed;

    public function __construct(IcecatFeed $icecatFeed)
    {
        $this->icecatFeed = $icecatFeed;
    }

    public function uniqueId(): string
    {
        return static::class . $this->icecatFeed['table'] . $this->icecatFeed['language'];
    }

    public function handle(): void
    {
        $this->fail(new IcecatFeedInvalidFile());
    }
}

In my classes, I utilize manual failing because it's the only way to mark the job as failed with what the checks I have to do. If I use an exception in combination with it, as on the example, doesn't really matter.

The jobs are triggered by a schedule service, which is actually just simply another class called be a scheduling task, containing the tasks.

<?php

namespace App\Schedules;

use App\Jobs\ProcessIcecatImport;
use App\Models\IcecatFeed;
use Illuminate\Console\Scheduling\Schedule;

class IcecatScheduleService extends ScheduleService
{
    protected string $feed_slug = 'icecat-feeds';
    protected string $import_slug = 'icecat-imports';

    public function registerSchedule(Schedule $schedule): int
    {
        $icecatFeeds = IcecatFeed::all();
        $jobs = 0;

        foreach ($icecatFeeds as $icecatFeed) {
            if ($icecatFeed->interval > 0) {
                $jobs++;
                $minutes = (int)($icecatFeed->interval / 60);
                $minutes = ($minutes === 0) ? 1 : $minutes;
                $jobChain = new ProcessIcecatDownload($icecatFeed);
                $jobChain->chain([(new ProcessIcecatImport(IcecatFeed::firstWhere('id', $icecatFeed->id)))->onQueue($this->import_slug)]);
                $schedule
                    ->job($jobChain, $this->feed_slug)
                    ->description('IcecatDownload & IcecatImport [' . $icecatFeed['table'] . '.' . $icecatFeed->language . ']')
                    ->cron('*/' . $minutes . ' * * * *')
                    ->runInBackground()
                ;
            }
        }
        return $jobs;
    }
}

For testing, all the model-related stuff could be actually be removed and just reduce it to a simple scheduler, calling the job(new ProcessIcecatDownload()) method only, with no chaining either. Seems to make no difference, as far it relates to the issue.

I hope that code is enough? Didn't wanted to throw a bunch lots of code at you and overcomplicate it. Just the parts that seem important, still doing things as in my classes.

I don't think the fact, that the job is triggered by a scheduler may be important, but I haven't tested it without either. The project I'm working on is very job-heavy, I'll have some jobs next, which can be triggered manually, and I can test it there explicitly.

This simple class will already trigger both states (first failed and then processed), and also the queue worker on the console will show that. It won't always do that, when the job fails for some other reasons, but it will always happen when only the manual failing is triggered. Though, Laravel will still have the job correctly marked as failed in it's failed jobs table. I tried to dig into Laravel's code which processes the jobs, but from what I saw, I don't think that's a bug in Laravel in that regard.

Regardless, the snippet I posted earlier to fix it, seems to handle things always correct, even after adding many more jobs and having things run several hundreds of times during development so far.

parzival42codes commented 1 year ago

Sorry for my bad English, I use the Google Translator: D.

The workaround for the problem is to also throw an exception:

$this->fail('Exeption in failed_jobs'); 
throw new Exception('Exeption in queue_monitor');

So the job is correctly displayed as a fail.

Only it has to be thrown twice, so to speak ...

romanzipp commented 1 year ago

I've finished work on the next major version 3.0 (PR #103) which will resolve this issue but also contains some breaking changes. Would you be willing to test this version out before I tag a stable release?

Please reference the upgrade guide for further instructions.

composer require romanzipp/laravel-queue-monitor "^3.0.0"
dkarvounaris commented 1 year ago

The upgrade guide link doesn't seem to link to a valid page. Returns 404.

If I know the breaking changes, I may be able to do the upgrade in the next 1-2 weeks.

Not having to throw an exception, as it's a long-running service with supervisord, would be best.

romanzipp commented 1 year ago

I've updated the upgrade guide link 👍

andrii-trush commented 1 year ago

I've finished work on the next major version 3.0 (PR #103) which will resolve this issue but also contains some breaking changes. Would you be willing to test this version out before I tag a stable release?

Please reference the upgrade guide for further instructions.

composer require romanzipp/laravel-queue-monitor "^3.0.0"

Hello @romanzipp I have upgraded to 3.0.1 and confirm still not working.

It looks like if you made Manually Failing A Job your script hires 2 events. First is fail event and after that success event

here are a peace of my code:

  if ($queueProgress->setTag('user-campaigns')->isInProgress($this->userCampaign->uuid)) {
            $this->fail(new Error('Other same job is running now'));
            $this->deleteQueueMonitor();
            return;
        }

and other peace of code is

try{
// ....
} catch (Throwable $exception) {
            $this->fail($exception);
        }  finally {
            // ... 
        }

As you see in first case I can solve a problem with deleteQueueMonitor method But in second case I need correct displaying in Monitor.

nopice commented 1 year ago

I can confirm that the problem still persist, even in v4.0.2

I put Log::info() into each case.

$manager->after(static function (JobProcessed $event) {
    Log::info('handle job processed');
    QueueMonitor::handleJobProcessed($event);
});

$manager->failing(static function (JobFailed $event) {
    Log::info('handle job failed');
    QueueMonitor::handleJobFailed($event);
});

Then I started the job, made it fail by using $this->fail() and looked at the log file. The message 'handle job failed' came first, followed by 'handle job processed'.

Perhaps, QueueMonitor::handleJobProcessed($event) got called after QueueMonitor::handleJobFailed($event) is the reason why jobs are always marked as succeeded?

However, adding the if (!$event->job->hasFailed()) clause like dkarvounaris did also fixed the problem for me.

freyca commented 5 months ago

Hi there,

refloating this issue since by now, the problem still persists...