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!!

Answer 1

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.