Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cron-job running twice #72

Closed
devendragohil opened this issue Jul 7, 2015 · 5 comments
Closed

Cron-job running twice #72

devendragohil opened this issue Jul 7, 2015 · 5 comments
Assignees
Labels

Comments

@devendragohil
Copy link

I am using laravel 4.2.

I've a project requirement to send some analysis report email to all the users every Monday 6 am.

Obviously its a scheduled task, hence I've decided to use cron-job.

For this I've installed liebig/cron package. The package is installed successfully.

To test email, I've added following code in app/start/global.php:

Event::listen('cron.collectJobs', function() {
    Cron::setEnablePreventOverlapping();
    Cron::add('user_analytics_report', '* * * * 2', function() {
             $maildata = array('email' => 'someemail@somedomain.com');

            Mail::send('emails.analytics', $maildata, function($message){
                        $message->to('user@gmail.com', 'firstname lastname')->subject('Some subject');
            });
            return null;
      });

    $report = \Cron::run();
    return null;
});

Also in app\config\packages\liebig\cron\config.php the key preventOverlapping is set to true.

Now, if I run it like php artisan cron:run, it sends the same email twice with the same time.

I've deployed the same code on my DigitalOcean development server (ubuntu) and set its crontab to execute this command every minute but still it is sending the same email twice.

The crontab command is:

* * * * 2 cd /var/www/html/mydomain.com/mydomain-ftp && php artisan cron:run

Also it is not generating lock file in ``app/storage` directory, according to some search results I've come to know that it creates a lock file to prevent overlapping. the directory has full permissions granted.

The laravel logs are as :

[2015-07-07 10:43:02] production.INFO: Cron run with manager id 41 is with 61 seconds between last run in time. [] []
[2015-07-07 10:43:02] production.INFO: The cron run with the manager id 41 was finished without errors. [] []
[2015-07-07 10:43:02] production.ERROR: Cron run with manager id 42 is with 0 seconds between last run too fast. [] []
[2015-07-07 10:43:02] production.INFO: The cron run with the manager id 42 was finished without errors. [] []
[2015-07-07 10:44:02] production.INFO: Cron run with manager id 43 is with 59 seconds between last run in time. [] []
[2015-07-07 10:44:02] production.INFO: The cron run with the manager id 43 was finished without errors. [] []
[2015-07-07 10:44:02] production.ERROR: Cron run with manager id 44 is with 1 seconds between last run too fast. [] []
[2015-07-07 10:44:02] production.INFO: The cron run with the manager id 44 was finished without errors. [] []
[2015-07-07 10:45:01] production.INFO: Cron run with manager id 45 is with 59 seconds between last run in time. [] []
[2015-07-07 10:45:01] production.INFO: The cron run with the manager id 45 was finished without errors. [] []
[2015-07-07 10:45:01] production.ERROR: Cron run with manager id 46 is with 0 seconds between last run too fast. [] []
[2015-07-07 10:45:01] production.INFO: The cron run with the manager id 46 was finished without errors. [] []
[2015-07-07 10:46:02] production.INFO: Cron run with manager id 47 is with 61 seconds between last run in time. [] []
[2015-07-07 10:46:02] production.INFO: The cron run with the manager id 47 was finished without errors. [] []
[2015-07-07 10:46:02] production.ERROR: Cron run with manager id 48 is with 0 seconds between last run too fast. [] []
[2015-07-07 10:46:02] production.INFO: The cron run with the manager id 48 was finished without errors. [] []
[2015-07-07 10:47:01] production.INFO: Cron run with manager id 49 is with 59 seconds between last run in time. [] []
[2015-07-07 10:47:01] production.INFO: The cron run with the manager id 49 was finished without errors. [] []
[2015-07-07 10:47:02] production.ERROR: Cron run with manager id 50 is with 0 seconds between last run too fast. [] []
[2015-07-07 10:47:02] production.INFO: The cron run with the manager id 50 was finished without errors. [] []
[2015-07-07 10:49:53] production.ERROR: Cron run with manager id 51 is with 171 seconds between last run too late. [] []
[2015-07-07 10:49:53] production.INFO: The cron run with the manager id 51 was finished without errors. [] []
[2015-07-07 10:49:53] production.ERROR: Cron run with manager id 52 is with 1 seconds between last run too fast. [] []
[2015-07-07 10:49:53] production.INFO: The cron run with the manager id 52 was finished without errors. [] []

The database table entries are as :

cron_job :

"1" "user_analytics_report" ""  "0.23"  "1"
"2" "user_analytics_report" ""  "0.10"  "2"
"3" "user_analytics_report" ""  "1.64"  "3"
"4" "user_analytics_report" ""  "0.09"  "4"
"5" "user_analytics_report" ""  "0.24"  "5"
"6" "user_analytics_report" ""  "0.08"  "6"
"7" "user_analytics_report" ""  "0.23"  "7"
"8" "user_analytics_report" ""  "0.09"  "8"
"9" "user_analytics_report" ""  "0.25"  "9"
"10"    "user_analytics_report" ""  "0.08"  "10"
"11"    "user_analytics_report" ""  "0.22"  "11"
"12"    "user_analytics_report" ""  "0.09"  "12"
"13"    "user_analytics_report" ""  "0.23"  "13"
"14"    "user_analytics_report" ""  "0.09"  "14"
"15"    "user_analytics_report" ""  "0.23"  "15"
"16"    "user_analytics_report" ""  "0.09"  "16"
"17"    "user_analytics_report" ""  "0.21"  "17"
"18"    "user_analytics_report" ""  "0.09"  "18"
"19"    "user_analytics_report" ""  "0.22"  "19"
"20"    "user_analytics_report" ""  "0.09"  "20"
"21"    "user_analytics_report" ""  "0.21"  "21"
"22"    "user_analytics_report" ""  "0.08"  "22"
"23"    "user_analytics_report" ""  "0.23"  "23"
"24"    "user_analytics_report" ""  "0.09"  "24"
"25"    "user_analytics_report" ""  "1.86"  "25"
"26"    "user_analytics_report" ""  "0.09"  "26"
"27"    "user_analytics_report" ""  "0.22"  "27"
"28"    "user_analytics_report" ""  "0.08"  "28"
"29"    "user_analytics_report" ""  "0.22"  "29"
"30"    "user_analytics_report" ""  "0.08"  "30"
"31"    "user_analytics_report" ""  "0.21"  "31"
"32"    "user_analytics_report" ""  "0.08"  "32"
"33"    "user_analytics_report" ""  "0.22"  "33"
"34"    "user_analytics_report" ""  "0.08"  "34"
"35"    "user_analytics_report" ""  "0.22"  "35"
"36"    "user_analytics_report" ""  "0.08"  "36"
"37"    "user_analytics_report" ""  "0.22"  "37"
"38"    "user_analytics_report" ""  "0.08"  "38"
"39"    "user_analytics_report" ""  "0.25"  "39"
"40"    "user_analytics_report" ""  "0.09"  "40"
"41"    "user_analytics_report" ""  "0.22"  "41"
"42"    "user_analytics_report" ""  "0.08"  "42"
"43"    "user_analytics_report" ""  "0.25"  "43"
"44"    "user_analytics_report" ""  "0.08"  "44"
"45"    "user_analytics_report" ""  "0.22"  "45"
"46"    "user_analytics_report" ""  "0.08"  "46"
"47"    "user_analytics_report" ""  "0.26"  "47"
"48"    "user_analytics_report" ""  "0.08"  "48"
"49"    "user_analytics_report" ""  "0.24"  "49"
"50"    "user_analytics_report" ""  "0.08"  "50"
"51"    "user_analytics_report" ""  "0.24"  "51"
"52"    "user_analytics_report" ""  "0.10"  "52"

cron_manager:

"1" "2015-07-07 09:02:45"   "0.23"
"2" "2015-07-07 09:02:46"   "0.10"
"3" "2015-07-07 09:57:39"   "1.64"
"4" "2015-07-07 09:57:40"   "0.09"
"5" "2015-07-07 10:03:21"   "0.24"
"6" "2015-07-07 10:03:21"   "0.08"
"7" "2015-07-07 10:26:01"   "0.23"
"8" "2015-07-07 10:26:01"   "0.09"
"9" "2015-07-07 10:27:01"   "0.25"
"10"    "2015-07-07 10:27:01"   "0.08"
"11"    "2015-07-07 10:28:02"   "0.22"
"12"    "2015-07-07 10:28:02"   "0.09"
"13"    "2015-07-07 10:29:01"   "0.23"
"14"    "2015-07-07 10:29:01"   "0.09"
"15"    "2015-07-07 10:30:01"   "0.23"
"16"    "2015-07-07 10:30:01"   "0.09"
"17"    "2015-07-07 10:31:01"   "0.22"
"18"    "2015-07-07 10:31:02"   "0.09"
"19"    "2015-07-07 10:32:01"   "0.22"
"20"    "2015-07-07 10:32:01"   "0.09"
"21"    "2015-07-07 10:33:02"   "0.21"
"22"    "2015-07-07 10:33:02"   "0.08"
"23"    "2015-07-07 10:34:01"   "0.23"
"24"    "2015-07-07 10:34:02"   "0.09"
"25"    "2015-07-07 10:35:01"   "1.86"
"26"    "2015-07-07 10:35:03"   "0.09"
"27"    "2015-07-07 10:36:01"   "0.22"
"28"    "2015-07-07 10:36:02"   "0.08"
"29"    "2015-07-07 10:37:01"   "0.22"
"30"    "2015-07-07 10:37:01"   "0.08"
"31"    "2015-07-07 10:38:02"   "0.21"
"32"    "2015-07-07 10:38:02"   "0.08"
"33"    "2015-07-07 10:39:01"   "0.22"
"34"    "2015-07-07 10:39:01"   "0.08"
"35"    "2015-07-07 10:40:01"   "0.22"
"36"    "2015-07-07 10:40:01"   "0.08"
"37"    "2015-07-07 10:41:01"   "0.22"
"38"    "2015-07-07 10:41:02"   "0.08"
"39"    "2015-07-07 10:42:01"   "0.25"
"40"    "2015-07-07 10:42:01"   "0.09"
"41"    "2015-07-07 10:43:02"   "0.22"
"42"    "2015-07-07 10:43:02"   "0.08"
"43"    "2015-07-07 10:44:01"   "0.25"
"44"    "2015-07-07 10:44:02"   "0.08"
"45"    "2015-07-07 10:45:01"   "0.22"
"46"    "2015-07-07 10:45:01"   "0.08"
"47"    "2015-07-07 10:46:02"   "0.26"
"48"    "2015-07-07 10:46:02"   "0.08"
"49"    "2015-07-07 10:47:01"   "0.24"
"50"    "2015-07-07 10:47:01"   "0.08"
"51"    "2015-07-07 10:49:52"   "0.24"
"52"    "2015-07-07 10:49:53"   "0.10"

Am I missing something?

@liebig
Copy link
Owner

liebig commented Jul 7, 2015

Thank you for using Cron. I am sorry about this issue and I will try to fix it. There were some issues with the problem "Cron job is running twice" like #67, but you are the first user who sends me the log file. Thank you for that. To localize the bug, can you please test if this problem does occur if you run Cron via web request and the integrated route, too? To do this please set the cronKey value in the Cron config file and use for example wget:
* * * * 2 wget -O - http://yourdomain.com/cron.php?key=securitykey >/dev/null 2>&1
Many thanks in advance.

@liebig liebig self-assigned this Jul 7, 2015
@liebig liebig added the bug label Jul 7, 2015
@devendragohil
Copy link
Author

I have set the crontab to run the job every 2 minutes using your script :

2 * * * * wget -O - http://yourdomain.com/cron.php?key=securitykey >/dev/null 2>&1

But it is not running. I think there is some problem. Again I'm pasting the laravel logs for today:

[2015-07-08 05:02:01] production.ERROR: Cron run with manager id 54 is with 370 seconds between last run too late. [] []
[2015-07-08 05:02:01] production.INFO: The cron run with the manager id 54 was finished without errors. [] []
[2015-07-08 05:02:01] production.ERROR: Cron run with manager id 55 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:02:01] production.INFO: The cron run with the manager id 55 was finished without errors. [] []
[2015-07-08 05:06:53] dev.ERROR: Cron run with manager id 56 is with 292 seconds between last run too late. [] []
[2015-07-08 05:06:53] dev.INFO: The cron run with the manager id 56 was finished without errors. [] []
[2015-07-08 05:06:53] dev.ERROR: Cron run with manager id 57 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:06:53] dev.INFO: The cron run with the manager id 57 was finished without errors. [] []
[2015-07-08 05:09:20] dev.ERROR: Cron run with manager id 58 is with 147 seconds between last run too late. [] []
[2015-07-08 05:09:20] dev.INFO: The cron run with the manager id 58 was finished without errors. [] []
[2015-07-08 05:09:20] dev.ERROR: Cron run with manager id 59 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:09:20] dev.INFO: The cron run with the manager id 59 was finished without errors. [] []
[2015-07-08 05:13:16] production.ERROR: Cron run with manager id 60 is with 236 seconds between last run too late. [] []
[2015-07-08 05:13:16] production.INFO: The cron run with the manager id 60 was finished without errors. [] []
[2015-07-08 05:13:16] production.ERROR: Cron run with manager id 61 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:13:16] production.INFO: The cron run with the manager id 61 was finished without errors. [] []
[2015-07-08 05:14:52] dev.ERROR: Cron run with manager id 62 is with 96 seconds between last run too late. [] []
[2015-07-08 05:14:52] dev.INFO: The cron run with the manager id 62 was finished without errors. [] []
[2015-07-08 05:14:52] dev.ERROR: Cron run with manager id 63 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:14:52] dev.INFO: The cron run with the manager id 63 was finished without errors. [] []
[2015-07-08 05:17:41] production.ERROR: Cron run with manager id 64 is with 169 seconds between last run too late. [] []
[2015-07-08 05:17:41] production.INFO: The cron run with the manager id 64 was finished without errors. [] []
[2015-07-08 05:17:41] production.ERROR: Cron run with manager id 65 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:17:41] production.INFO: The cron run with the manager id 65 was finished without errors. [] []
[2015-07-08 05:20:46] production.ERROR: Cron run with manager id 66 is with 185 seconds between last run too late. [] []
[2015-07-08 05:20:46] production.INFO: The cron run with the manager id 66 was finished without errors. [] []
[2015-07-08 05:20:46] production.ERROR: Cron run with manager id 67 is with 0 seconds between last run too fast. [] []
[2015-07-08 05:20:46] production.INFO: The cron run with the manager id 67 was finished without errors. [] []

If I hit the url in my browser to run the cron like:

http://yourdomain.com/cron.php?key=securitykey

It does not gives me any error but not firing the job I think because I'm not receiving the emails.

@liebig
Copy link
Owner

liebig commented Jul 9, 2015

Thank you for your reply. Please change the url value securitykey to the in the cron config file set value of the key cronKey. And for testing please you use var_dump to echo the report to the browser. Your fields should look like:
config.php

<?php
return array(

    // Interval defines the time in minutes between two run method calls - in other words, the time between the Cron route or command will be called
    'runInterval' => 1,

    // Should the Laravel integrated logger handle the logging
    'laravelLogging' => true,

    // Enable or disable database logging
    'databaseLogging' => true,

    // Enable or disable logging error jobs only
    'logOnlyErrorJobsToDatabase' => false,

    // Delte old database entries after how many hours - if this value is set to 0, no entries will be deleted
    'deleteDatabaseEntriesAfter' => 240,

    // Prevent job overlapping - if Cron is still running it could not be started a second time
    'preventOverlapping' => true,

    // Enable or disable the check if the current Cron run is in time
    'inTimeCheck' => true,

    // Cron application key for securing the integrated Cron run route - if the value is empty, the route is disabled 
    'cronKey' => 'secretKey12345'

);

global.php

Event::listen('cron.collectJobs', function() {
    Cron::setEnablePreventOverlapping();
    Cron::add('user_analytics_report', '* * * * 2', function() {
             $maildata = array('email' => 'someemail@somedomain.com');

            Mail::send('emails.analytics', $maildata, function($message){
                        $message->to('user@gmail.com', 'firstname lastname')->subject('Some subject');
            });
            return null;
      });
});

Crontab

2 * * * * wget -O - http://yourdomain.com/cron.php?key=secretKey12345 >/dev/null 2>&1

Or use your browser and call http://yourdomain.com/cron.php?key=secretKey12345. Please report your test result.

Many thanks in advance.

@liebig
Copy link
Owner

liebig commented Jul 15, 2015

Sorry for the late reply, but I had many things to do in the last days. I think I have got a solution for this. This behaviour is not a bug. Please just delete this from the global.php file:

    $report = \Cron::run();
    return null;

Now Cron should only run once. If you use the artisan command or the integrated route you don't have to execute \Cron::run(). The command and route do this after firing the cron.collectJobs event for you. So everything works fine. The overlapping prevention doesn't prevent this, because the \Cron::run() method is called successive, not in parallel.
Your global.php file should look like

Event::listen('cron.collectJobs', function() {
    Cron::setEnablePreventOverlapping();
    Cron::add('user_analytics_report', '* * * * 2', function() {
             $maildata = array('email' => 'someemail@somedomain.com');

            Mail::send('emails.analytics', $maildata, function($message){
                        $message->to('user@gmail.com', 'firstname lastname')->subject('Some subject');
            });
            return null;
      });
});

Please test this and give me a short reply.
Thank you.

@liebig liebig added question and removed bug labels Jul 15, 2015
@liebig
Copy link
Owner

liebig commented Jul 22, 2015

Closed due to inactivity.

@liebig liebig closed this as completed Jul 22, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants