Search code examples
phplaravelqueuelaravel-queuelaravel-horizon

Laravel - Job reporting as failed (even though it exits correctly)


I am using the latest version of Homestead. I also have Laravel Horizon set up. I am using Redis as the queue driver. Laravel is version 5.6 and is a fresh install.

What's happening is my jobs are all failing (even though the job exits correctly).

I am running the job through command line by using a custom command:

vagrant@homestead:~/myapp$ artisan crawl:start
vagrant@homestead:~/myapp$ <-- No CLI errors after running

app/Console/Command/crawl.php

<?php

namespace MyApp\Console\Commands;

use Illuminate\Console\Command;
use MyApp\Jobs\Crawl;

class crawl extends Command
{
    /**
     * The name and signature of the console command.
     *
     * @var string
     */
    protected $signature = 'crawl:start';

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Start long running job.';

    /**
     * Create a new command instance.
     *
     * @return void
     */
    public function __construct()
    {
        parent::__construct();
    }

    /**
     * Execute the console command.
     *
     * @return mixed
     */
    public function handle()
    {


        Crawl::dispatch();

    }

}

app/Jobs/Crawl.php

<?php

namespace MyApp\Jobs;

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

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

    /**
     * The number of seconds the job can run before timing out.
     *
     * @var int
     */
    public $timeout = 3600;

    /**
     * The number of times the job may be attempted.
     *
     * @var int
     */
    public $tries = 1;

    /**
     * Create a new job instance.
     *
     * @return void
     */
    public function __construct()
    {

    }

    /**
     * Execute the job.
     *
     * @return void
     */
    public function handle()
    {


        $crawl = new Crawl();
        $crawl->start();


    }
}

app/Crawl.php

<?php
namespace MyApp;

class Crawl
{

    public function start()
    {

        ini_set('memory_limit','256M');
        set_time_limit(3600);

        echo "Started."; 
        sleep(30);
        echo "Exited.";
        exit(); 

    }
}

worker.log

[2018-03-21 10:14:27][1] Processing: MyApp\Jobs\Crawl
Started.
Exited.
[2018-03-21 10:15:59][1] Processing: MyApp\Jobs\Crawl
[2018-03-21 10:15:59][1] Failed:     MyApp\Jobs\Crawl

From Horizon's failed job detail

Failed At    18-03-21 10:15:59
Error        Illuminate\Queue\MaxAttemptsExceededException:
             MyApp\Jobs\Crawl has been attempted too many 
             times or run too long. The job may have previously 
             timed out. in /home/vagrant/app/vendor/laravel
             /framework/src/Illuminate/Queue/Worker.php:396

laravel-worker.conf

[program:laravel-worker]
process_name=%(program_name)s_%(process_num)02d
command=php /home/vagrant/myapp/artisan queue:work --sleep=3 --tries=1 --timeout=3600
autostart=true
autorestart=true
user=vagrant
numprocs=1
redirect_stderr=true
stdout_logfile=/home/vagrant/myapp/worker.log

config/queue.php

'redis' => [
    'driver' => 'redis',
    'connection' => 'default',
    'queue' => 'default',
    'retry_after' => 90,
    'block_for' => null,
],

.env

QUEUE_DRIVER=redis

Synopsis

Looking at my worker.log I can see that the output from my class has worked:

Started.
Exited.

But the job is reported as failed. Why? Strangely, also in the worker.log, it says Processing twice for one job:

[2018-03-21 10:15:59][1] Processing: MyApp\Jobs\Crawl
[2018-03-21 10:15:59][1] Failed:     MyApp\Jobs\Crawl

Any help is greatly appreciated!

UPDATE

Removing the exit() has resolved the issue - this is strange as the PHP manual says that you can use exit() to exit the program "normally":

https://secure.php.net/manual/en/function.exit.php
<?php

//exit program normally
exit;
exit();
exit(0);

Solution

  • Removing the exit() has resolved the issue - this is strange as the PHP manual says that you can use exit() to exit the program "normally"

    This is true for regular programs, but a queued job in Laravel doesn't follow the same lifecycle.

    When the queue system processes a job, that job executes in an existing queue worker process. Specifically, the queue worker fetches the job data from the backend and then calls the job's handle() method. When that method returns, the queue worker runs some code to finalize the job.

    If we exit from a job—by calling exit(), die(), or by triggering a fatal error—PHP stops the worker process running the job as well, so the queue system never finishes the job lifecycle, and the job is never marked "complete."

    We don't need to explicitly exit from a job. If we want to finish the job early, we can simply return from the handle() method:

    public function handle() 
    {
        // ...some code...
    
        if ($exitEarly) {
            return;
        }
    
        // ...more code...
    }
    

    Laravel also includes a trait, InteractsWithQueue, that provides an API which enables a job to manage itself. In this case, we can call the delete() method from a job that exhibits this trait:

    public function handle()
    {
        if ($exitEarly) {
            $this->delete();
        }
    }
    

    But the job is reported as failed. Why? Strangely, also in the worker.log, it says Processing twice for one job

    As described above, the job could not finish successfully because we called exit(), so the queue system dutifully attempted to retry the job.