Schedule o'clock fails on AWS instance

[sylouuu]

Hey,

I made a small test with the scheduler on Laravel 5.2.

* * * * * php /Users/syl/Sites/pro/aotd-website/artisan schedule:run >> /dev/null 2>&1

protected function schedule(Schedule $schedule)
{
    Log::info('schedule:run');

    $schedule->command('newsletter:check')->everyMinute();
}

public function handle()
{
    Log::info('newsletter:check');
}

Here is what I see in my AWS instance in production:

...
[2016-05-06 13:59:01] production.INFO: schedule:run
[2016-05-06 13:59:01] production.INFO: schedule:run
[2016-05-06 13:59:01] production.INFO: newsletter:check
[2016-05-06 14:00:01] production.INFO: schedule:run
[2016-05-06 14:00:01] production.INFO: schedule:run
[2016-05-06 14:01:01] production.INFO: schedule:run
[2016-05-06 14:01:01] production.INFO: schedule:run
[2016-05-06 14:01:01] production.INFO: newsletter:check
...

Issue 1

Why the schedule:run log is printed twice?

Issue 2

My real problem, why the handle method has not been called at 14:00:01?

The same problem occurs with everyFiveMinutes().

Idea: as it seems to be OK on my OSX dev machine, what about the CRON parsing on AWS instance?

64bit Amazon Linux 2015.09 v2.0.8 running PHP 5.6

Bests

EDIT: May be related with #10588, but tested with 5 stars instead of 6 and still not working.

[sylouuu]

I think that the issue comes from: https://laracasts.com/discuss/channels/laravel/run-cron-job-tasks-simultaneously

[sebcode]

Wondered about this myself.

1. Kernel::schedule() is called each time an artisan command is executed. Since the scheduler runs one artisan command per scheduled command, you'll see an additional schedule:run log line for each executed scheduled command. Seems unnecessary but it should be harmless.
2. Scheduling a command with everyMinute actually means "run every time artisan schedule:run is executed". There's no guarantee that this actually will be every minute.
   As for everyFiveMinutes: The underlying cron-expression library uses timestamp % minutes == 0 to check if the cron is due. That requires that artisan is exactly invoked every minute. If your machine is under load this may not always be the case. Using a real cron job would be more reliable in this case, I guess.

[laurencei]

@sebcode - I dont think point 2 is correct.

I looked into it - and in the "CronExpression" isDue() function it specifically says:

This method assumes that the current number of seconds are irrelevant, and should be called once per minute.

And I checked the code in that function, and it definitely drops the seconds when doing an evaluation.

[themsaid]

@sylouuu I wonder if you had any updates or finding on this.

[sylouuu]

@themsaid I always had issues with the Laravel built-in CRON system so now I use the old school version by writing CRON expression to call an artisan command.

Besides I don't work on this project anymore but it could be nice if you can try the given snippet with the log info before closing this issue.

Best

[themsaid]

Thing is I used to have a job that runs every minute and I never noticed a skipped minute, going to give it another go.

[themsaid]

Closing this for lack of activity, if anybody is facing the same issue and stumbled upon this thread please ping me if you have more information that could help.

[patrickguevara]

Hey @themsaid, I'm running into this issue on an AWS instance as well.

AWS EC2 - Ubuntu 16.04
Laravel Framework 5.5.35

Here's the cron logs (we're using a single server called tools to SSH and run the cron job on the web server, mediapp4):

Apr  4 15:59:01 tools-prod CRON[19302]: (root) CMD (ssh ubuntu@mediapp4 'php /www/mediapp/artisan schedule:run' > /dev/null 2>&1)
Apr  4 16:00:01 tools-prod CRON[19473]: (root) CMD (ssh ubuntu@mediapp4 'php /www/mediapp/artisan schedule:run' > /dev/null 2>&1)
Apr  4 16:01:01 tools-prod CRON[19656]: (root) CMD (ssh ubuntu@mediapp4 'php /www/mediapp/artisan schedule:run' > /dev/null 2>&1)

And the logs from the web server (Mediapp4):

[2018-04-04 15:58:12] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: Start
[2018-04-04 15:58:13] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: End
[2018-04-04 15:59:12] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:59:12] production.INFO: App.Models.Utility.Trigger.process: End
[2018-04-04 15:59:12] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: Start
[2018-04-04 15:59:13] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: End
[2018-04-04 16:01:07] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 16:01:07] production.INFO: App.Models.Utility.Trigger.process: End
[2018-04-04 16:01:07] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: Start
[2018-04-04 16:01:08] production.INFO: App.Models.Email.QueuedEmail.processEmailQueue: End

You can see the schedule:run does in fact get fired at 16:00 from Tools, but we have no record of it in the Mediapp4 logs.

Any ideas?

[patrickguevara]

Upon further inspection, I've found that Mediapp4 does not have entries for 15 or 30 minutes:

[2018-04-04 15:14:12] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:14:12] production.INFO: App.Models.Utility.Trigger.process: End
[2018-04-04 15:16:07] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:16:07] production.INFO: App.Models.Utility.Trigger.process: End

[2018-04-04 15:29:12] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:29:12] production.INFO: App.Models.Utility.Trigger.process: End
[2018-04-04 15:31:07] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:31:07] production.INFO: App.Models.Utility.Trigger.process: End

[2018-04-04 15:44:12] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:44:12] production.INFO: App.Models.Utility.Trigger.process: End
[2018-04-04 15:46:06] production.INFO: App.Models.Utility.Trigger.process: Start
[2018-04-04 15:46:06] production.INFO: App.Models.Utility.Trigger.process: End