framework: Multiple crons problem

  • Laravel Version: 5.5.20
  • PHP Version: 7.1

Description:

After upgrading from 5.5.19 into 5.5.20 started exceptions related with crons. (very rare but happens, and I don’t like that)

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction (SQL: delete from `multi_server_event` where `mutex` = 74d07339684141a8f7edbeb61c835586 and `complete` < 2017-11-17 23:27:51 and `next` < 2017-11-17 23:29:00)

Together I use https://github.com/jdavidbakr/MultiServerEvent

CACHE_DRIVER=redis

I suspect that doesn’t work https://github.com/laravel/framework/blob/5.5/src/Illuminate/Console/Scheduling/Event.php#L170 after changes in 5.5.20. There was 9events in 2days so far (6 yesterday, 3 till now). Cron works every minute, I have 3crons: 1: every minute 2: every minute 3: every day at 6h o’clock Duration for them is not so long, I guess up to 5seconds. Also I have 2servers, so this error means, that same cron is executed when should not been executed.

Can it be Redis related somehow? Or is it changes in 5.5.20 broken functionality at very edge cases?

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Comments: 20 (19 by maintainers)

Most upvoted comments

I’ve done a PR for this feature. Turns out it seems really easy to add this feature: https://github.com/laravel/framework/pull/22137

Lets move any further discussion there…

You’re both right. The overlapping stuff works if all your machines execute the jobs at the same time. However, it will not protect you against crontab jittering, slightly out-of-sync clocks and tears in the spacetime continuum.

Also, as the image shows, it will not help if there is a large scheduled task to execute. One of them gets to do it, and will then afterwards start executing the other jobs since the first server has already completed them.

This issue has been present for a long time. I wouldn’t call it a bug, the implementation is not meant to be distributed onto several machines. A solution would be to have a dedicated machine that runs the scheduler and dispatches jobs handled by your queue workers.

Okay, experiment proved for me that bug not related with redis mechanism at all, because has does not affected create as I thought… I guess I have very strange issue, when inserted record in database won’t appear for other php process. (I had such issue and I know) so my used library fails on that case.

Anyway, POC, that you both required:

<?php

namespace App\Console;

use Illuminate\Console\Command;
use Illuminate\Console\Scheduling\Schedule;
use Illuminate\Foundation\Console\Kernel as ConsoleKernel;

class Kernel extends ConsoleKernel
{
    protected $commands = [
        Command1::class,
        Command2::class,
        Command3::class,
    ];

    protected function schedule(Schedule $schedule): void
    {
        $schedule->command(Command1::class)
            ->everyMinute()
            ->withoutOverlapping();
        $schedule->command(Command2::class)
            ->everyMinute()
            ->withoutOverlapping();
        $schedule->command(Command3::class)
            ->everyMinute()
            ->withoutOverlapping();
    }

    protected function commands(): void
    {
        require base_path('routes/console.php');
    }
}

class Command1 extends Command
{
    protected $signature = 'command:first';

    public function handle()
    {
        sleep(3);
        logger($this->signature);
    }
}

class Command2 extends Command
{
    protected $signature = 'command:second';

    public function handle()
    {
        sleep(20);
        logger($this->signature);
    }
}

class Command3 extends Command
{
    protected $signature = 'command:third';

    public function handle()
    {
        sleep(4);
        logger($this->signature);
    }
}

crontab (which simulates 2servers)

* * * * * php /project/artisan schedule:run
* * * * * php /project/artisan schedule:run

result:

[2017-11-18 12:01:42] local.DEBUG: command:first
[2017-11-18 12:01:59] local.DEBUG: command:third
[2017-11-18 12:01:59] local.DEBUG: command:second
[2017-11-18 12:02:22] local.DEBUG: command:third
[2017-11-18 12:02:37] local.DEBUG: command:first
[2017-11-18 12:02:51] local.DEBUG: command:third
[2017-11-18 12:02:55] local.DEBUG: command:second
[2017-11-18 12:03:09] local.DEBUG: command:third
[2017-11-18 12:03:34] local.DEBUG: command:first
[2017-11-18 12:03:51] local.DEBUG: command:third

This is bug, because cron command itself doesn’t know that it was executed already or not. Proven by two people with different approaches, but eventually got same results, that third command runs twice in the same minute.