Laravel Artisan: How does `schedule:run` work?

Question

I have a dummy Command job set up, whose handle() function is as follows:

public function handle()
{
    $this->line('==================');
    $this->line('Running my job at ' . Carbon::now());
    $this->line('Ending my job at ' . Carbon::now());
}

As you see, it doesn't actually do anything but return a few lines of info to the standard output.

Now, in my App\Console\Kernel class, I have set up the following schedule:

protected function schedule(Schedule $schedule)
{
    $schedule
        -> command('cbh:dummyCommand')
        -> everyMinute()
        -> appendOutputTo (storage_path().'/logs/laravel_output.log');
}

Now, from the command-line I run php artisan schedule:run. The output in my laravel_output.log file reads

==================
Running my job at 2018-02-08 11:01:33
Ending my job at 2018-02-08 11:01:33

So far so good. It seems that my schedule is running. However, if I run the command again within the same minute, my logfile now reads:

==================
Running my job at 2018-02-08 11:01:33
Ending my job at 2018-02-08 11:01:33
==================
Running my job at 2018-02-08 11:01:51
Ending my job at 2018-02-08 11:01:51

In other words, the schedule appears to be running more frequently than every minute, which appears to me to break the rules I defined in my schedule.

What's more confusing is that I can change the schedule to run every 5 minutes instead of every minute:

protected function schedule(Schedule $schedule)
{
    $schedule
        -> command('cbh:dummyCommand')
        -> everyFiveMinutes()
        -> appendOutputTo (storage_path().'/logs/laravel_output.log');
}

then run php artisan schedule:run, then I get the following output

No scheduled commands are ready to run.

I can wait as long as you like (i.e. more than 5 minutes) and still I get no output to my log file.

I observe exactly the same behaviour when I schedule my command with Windows Task Scheduler (yes, my development environment is a Windows 7 box, and yes, this is the Windows equivalent of a cron-job).

The Question

So what's going on? How does the artisan schedule:run command figure out which commands are "waiting" on the schedule to be executed? I had imagined that there would be some kind of log-file to record the fact that "Command X is on a 1-hour schedule and last ran at 09:00, so don't execute it again before 10:00", but I have been able to find no trace of such a log.

Can someone give me a clue?

Thanks!!

@tkausl Could you elaborate please? Your comment isn't very useful in isolation. — cartbeforehorse, Feb 08 '18 at 11:35

score 32 · Accepted Answer · answered Feb 08 '18 at 14:48

32

Not cool to answer your own question, I know. Anyhow, let's imagine this is my schedule:

protected function schedule(Schedule $schedule)
{
    $schedule
        -> command('cbh:dummyCommand')
        -> everyFiveMinutes()
        -> appendOutputTo ('/my/logs/laravel_output.log');
}

What I've discovered is that this code doesn't set your job to run every 5 minutes. Nor does it prevent the command running again if it was run less than 5-minutes ago.

A better way to think about it is that this code sets the named command "to be runnable every time the minute-figure of the current time is 0 or 5". In other words, if I run the command-line argument: php artisan schedule:run at 11:04, then the response is:

# No scheduled commands are ready to run.

But if I run the same command at 11:00 or 11:05, then we get:

# Running scheduled command: php artisan cbh:dummyCommand >> /my/logs/laravel_output.log 2>&1

And I end up with output in my log-file.

I discovered the above when my everyFiveMinutes() schedule was creating a log in my file every 10 minutes based on the fact that my task-scheduler was running every 2 minutes.

answered Feb 08 '18 at 14:48

cartbeforehorse

3,045
1
34
49

11

*Not cool to answer your own question, I know*: on the contrary, [answering your own question](https://stackoverflow.com/help/self-answer) here is not only permitted, it is actually encouraged! – CODE-REaD Feb 21 '20 at 17:32
2

That's pretty ghetto. So if my cron runs 60 seconds late, and my task is hourly, I miss a whole hour? – mpen May 31 '20 at 20:19
@mpen Yes, more or less. However, if your Cron job "misses" its execution slot, there's probably something badly wrong with your OS. One possible solution would be to execute all your jobs every minute, but build in a safety check into the job itself. Your job would stamp a database or file after execution, then on the next run, check the timestamp wasn't less than an hour ago. – cartbeforehorse May 31 '20 at 21:17
1

@cartbeforehorse I'm using kubernetes to run my cronjobs now. It might take a minute to spin up the container and start the job. It's not exactly a defect. But yeah, my commands are idempotent so it should probably be fine, but Laravel could have handled this gracefully by simply logging the last time the command was ran. – mpen May 31 '20 at 23:31
Oh, that's not intuitive! Thanks for sharing your findings! I know thanking in comments is not encouraged, but I feel especially grateful because things like this save me so much trouble! – Daniel Katz Sep 15 '21 at 08:40

score 12 · Answer 2 · answered Mar 16 '20 at 13:51

I'm answering this just to let other people know it (since I was having the same confusion).

Laravel scheduler does exactly the same job than Linux cron, by checking if a task cronned time (in minutes) is exactly the same of current time.

When you set in crontab * * * * * ... php artisan schedule:run >> ... you are running schedule:run every minute at 0 secs, like '1:00:00', '1:01:00', '1:02:00', etc.

So, if you set your command to run (let's say) on 'mondays at 1:00' in your Laravel scheduler, and you are on a monday at 1:00, it will be executed, regardless the current seconds. And the last part (seconds) is important to understand how it works.

For example, you are on monday at 1:00:05 (5 seconds after 1:00), so cron already launched schedule:run and your task is being executed. Then you open your terminal, go to your project's root directory and launch, manually, php artisan schedule:run. At that time, it may be 1:00:30 (30 seconds after 1:00). Well, now your task will be executed again because 1:00:30 is still part of 1:00. So you can execute N times schedule:run at 1:00 and it will execute N times your task scheduled to run at 1:00.

And that's the magic of no needing a table or a file to control process launching time. Minutes is the minimum unit in cron, so unless you are doing the things wrong (like duplicating schedule:run line, a hack to run a command more often than a minute, etc.) your Laravel tasks will be executing once at the desired time.

Just a note: Check that your timezone is correct in config/app.php. I got crazy to understand why things like everyMinute(), everyFiveMinutes() were working, and dailyAt('1:10') were not. Of course, with Laravel in UTC and me being in GMT-3 (server clock), I had a great difference in hours.

_This_ is the thing that might confuse you or bite you in the behind... The resolution to a minute is generally not a thing you care about until you force an `artisan schedule:run` and then you totally _forget_ that because it's minute it'll fire always. In other words, `schedule:run` is not _wrong_ , but it's not _stateful_ either and so it doesn't save the seconds anywhere and so will trigger always. It definitely took me a while to realise what was going on... — Elven Spellmaker, Mar 01 '23 at 21:55

Sayandeep Majumdar · Answer 3 · 2023-07-27T08:08:41.323

1

It's too late to reply this question but I am adding some value to this question's solution.

I've used this command php artisan schedule:work for the solution and then no need to run schedule:run every seconds or mins.

I hope this will add value to the problem.

edited Jul 27 '23 at 08:08

answered Mar 20 '23 at 07:05

Sayandeep Majumdar

370
1
9
20

Laravel Artisan: How does `schedule:run` work?

The Question

3 Answers3

Linked

Related