Laravel queue (regardless of driver) processes a job only after the next is queued

Question

Answer: My patch to Tinker docs now made it to official Laravel documentation, see the warning frame here: https://laravel.com/docs/6.x/artisan#tinker

Yesterday I noticed this really weird Laravel queue behavior, where the queue always waits for the NEXT job to be scheduled to process the previously scheduled one. Please help me understand what is going on.

$ laravel new test
$ cd test
$ php artisan make:job TestQueue

Paste the following into the TestQueue class. Nothing fancy, really:

<?php

namespace App\Jobs;

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

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

    public $id;

    /**
     * Create a new job instance.
     *
     * @return void
     */
    public function __construct($id)
    {
        Log::info('Creating ' . $id);
        $this->id = $id;
    }

    /**
     * Execute the job.
     *
     * @return void
     */
    public function handle()
    {
        Log::info('Running ' . $this->id);
    }
}

Now, regardless of the QUEUE_CONNECTION env var (redis, beanstalkd, even sync!), I get the following behavior:

Please note I have php artisan queue:work running in a separate terminal.

$ php artisan tinker

>>> App\Jobs\TestQueue::dispatch(1)

logs:

[2018-10-30 22:38:01] local.INFO: Creating 1

>>> App\Jobs\TestQueue::dispatch(2)

logs:

[2018-10-30 22:38:04] local.INFO: Creating 2
[2018-10-30 22:38:06] local.INFO: Running 1

>>> App\Jobs\TestQueue::dispatch(3)

logs:

[2018-10-30 22:38:22] local.INFO: Creating 3
[2018-10-30 22:38:24] local.INFO: Running 2

I believe not only the queue, regardless of the driver, should pick up the first job and process it whenever queue is ready, but the sync driver should process every queued job immediately (calling its handle() method).

I feel like someone's trying to prove me 1+1=3 and I just can't see what I'm doing wrong. I'm sure this is not a bug in the framework, because the internet would be raving about it, and it is not.

Thank you for your time.

Laravel Framework 5.7.12

Edit: local environment, config is not cached

I think this is just an artefact of using tinker instead of the web interface. I can also reproduce this with tinker but not when doing it within a web request context — apokryfos
@apokryfos Oh gawd, that is so weird, you're right! Thank you so much. At least in the case with redis... Can you please verify if the sync driver logs both Creating and Running? I checked with sync as well and that one still fails, but even worse. It just keeps accepting (Creating x logged) jobs, but not ever calling handle() on them. Edit: Ignore that, I had the sync driver configured as null (not sure if that was default laravel template or I changed it). Regardless, please paste your comment as the answer, @apokryfos :). I'll file a bug. — karni
@apokryfos I filed a bug at laravel/framework. We'll see if that's the appropriate place to report it. Please post your comment as answer, so I can accept it. — karni

apokryfos apokryfos · Accepted Answer · 2018-10-31T10:10:45

As mentioned in the comment, I think this is just an artefact of using tinker instead of the web interface. I can also reproduce this with tinker but not when doing it within a web request context.

I am not sure why this happens, while tinker is very helpful for debugging purposes it might not be fully capable of handling operations like queuing.

You could file a bug with Laravel or directly at the Laravel tinker project at https://github.com/laravel/tinker

Laravel queue (regardless of driver) processes a job only after the next is queued

1 Answers