alexsmirnovdotcom commented 9 months ago

Laravel Version

10.4.1

PHP Version

8.2

Database Driver & Version

No response

Description

In last versions of laravel 10 was added sub-minute intervals. But i have strange behavior of runnig of cron task. All works in Docker with docker-compose. Cron works in separate from Laravel container. I have no any errors in logs.

Crontab file:

* * * * * php /var/www/api/artisan schedule:run >> /var/www/api/storage/logs/cron.log 2>&1

\App\Console\Kernel.php:

<?php

namespace App\Console;

use App\Jobs\OneC\SyncChangesFrom1C;
use Illuminate\Console\Scheduling\Schedule;
use Illuminate\Foundation\Console\Kernel as ConsoleKernel;
use Illuminate\Support\Facades\Log;

class Kernel extends ConsoleKernel
{
    /**
     * Register the commands for the application.
     */
    protected function commands(): void
    {
        $this->load(__DIR__ . '/Commands');

        require base_path('routes/console.php');
    }

    /**
     * Define the application's command schedule.
     */
    protected function schedule(Schedule $schedule): void
    {
        Log::debug('SCHEDULE RUN');
        $schedule->job(new SyncChangesFrom1C)->everyTenSeconds();
    }
}

SyncChangesFrom1C is a queued job. handle method is empty.

Logs of Laravel:

[2023-12-25 08:22:01] local.DEBUG: SCHEDULE RUN
[2023-12-25 08:24:00] local.DEBUG: SCHEDULE RUN
[2023-12-25 08:26:00] local.DEBUG: SCHEDULE RUN
[2023-12-25 08:28:00] local.DEBUG: SCHEDULE RUN

Logs of Cron:

2023-12-25 08:26:00 Running [App\Jobs\OneC\SyncChangesFrom1C] .... 14ms DONE
2023-12-25 08:26:10 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 6ms DONE
2023-12-25 08:26:20 Running [App\Jobs\OneC\SyncChangesFrom1C] .... 10ms DONE
2023-12-25 08:26:30 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 5ms DONE
2023-12-25 08:26:41 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 3ms DONE
2023-12-25 08:26:51 Running [App\Jobs\OneC\SyncChangesFrom1C] .... 15ms DONE

2023-12-25 08:28:00 Running [App\Jobs\OneC\SyncChangesFrom1C] .... 39ms DONE
2023-12-25 08:28:10 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 3ms DONE
2023-12-25 08:28:21 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 2ms DONE
2023-12-25 08:28:31 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 2ms DONE
2023-12-25 08:28:41 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 5ms DONE
2023-12-25 08:28:51 Running [App\Jobs\OneC\SyncChangesFrom1C] ..... 2ms DONE

If i`m change to everyMinute:

    /**
     * Define the application's command schedule.
     */
    protected function schedule(Schedule $schedule): void
    {
        Log::debug('SCHEDULE RUN');
        $schedule->job(new SyncChangesFrom1C)->everyMinute();
    }

It work perfect, and run every minute.

Why it skip a minute before new run if used sub-minutes interval?

Steps To Reproduce

-

crynobone commented 9 months ago

Hey there, thanks for reporting this issue.

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"

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!

alexsmirnovdotcom commented 9 months ago

Hi!

I make repository to reproduce bug in one command. (This is clear laravel installation with only one added queued TestJob) https://github.com/alexsmirnovdotcom/laravel-cron-bug

How to Start

Clone this repository.
Navigate to the project directory.
Run docker-compose build && docker-compose down --remove-orphans && docker-compose up -d.

Where to Find the Issue

After launching the Docker containers, the Laravel application will start, and a test queued job will be executed in the schedule.

All logs are located in the standard Laravel logs folder:

{path_to_project}/laravel/storage/logs/laravel.log (for Laravel logs).
{path_to_project}/laravel/storage/logs/cron.log (for Cron logs).

A portion of these logs is also available in the repository for easy access without the need to run the application.

Important note

In \Illuminate\Console\Scheduling\ScheduleRunCommand::repeatEvents() if i change condition of while loop from

Date::now()->lte($this->startedAt->endOfMinute())

to

Date::now()->lte($this->startedAt->endOfMinute()->subSeconds(20))

It works perfect...

I was unable to identify why cron skips running the php artisan schedule:run command. It is possible that the execution of the previous command does not have time to complete before trying to start a new one. But as far as I know, cron does not check this and must run the command even if the previous one has not completed yet...

driesvints commented 9 months ago

Hi there. I was not able to reproduce this on a local Laravel app with the latest version. Why this isn't working for you in your Docker setup, I do not know. But this unfortunately is beyond the support we can offer here. Please try a support channel:

laravel / framework

Cron task for Laravel schedule with sub-minute repeating skip a next minute running #49488