08 September 2010, 7:49

Hi,

I noticed the following error message in my cron.log earlier this morning. It seems to correspond to a hung cron job:

My question is: should I be worried about this or is it okay to just kill the process and carry on? I'm running Mahara 1.3 RC with PostgreSQL 8.3

08 September 2010, 16:53

Alex,

I've filed a bug for that error here: https://bugs.launchpad.net/mahara/+bug/633578

I doubt that's what's causing your cron job to hang though; it should still exit. In my experience the thing that takes the most time is fetching the content from rss feed blocktypes.  I've noticed a couple of cron jobs that have kept running for a few minutes because of that.

Killing it shouldn't have any devastating consequences, you may get a few missed notifications, but probably nothing too serious and it should recover the next couple of times it runs.

R.

14 September 2010, 6:40

Thanks, Richard! Since installing 1.3.0 final, this particular bug hasn't been popping up in my logs anymore, but I'm still experiencing hung cron jobs. Here is a screenshot that shows what I'm talking about:

So I tracked down a couple more errors from the past couple of days and came upon these, which repeat rather frequently:

https://www.meportfolio.ca/cron_error.rtf

https://www.meportfolio.ca/cron_error_1.rtf

Ever since I upgraded to 1.3.0RC, I've had to deal with killing all of these cron jobs every single day. Right now I'm running 1.3.0 final under Ubuntu 8.04 LTS.

14 September 2010, 17:26

Hi Alex,

It seems to be in the cron_check_for_updates function.  I'll try to fix it before the next release, but in the meantime, it'd be worth just removing the cron_check_for_updates row from the cron table - let me know if that clears up the problem (if you don't want to remove that row completely, you could also just set it to run once a year by changing the minute, hour, day, month columns appropriately).

By the way, that cron_check_for_updates function is totally unnecessary - all it does is tries to scrape the latest Mahara version from launchpad.net so that it can put a notice in the admin area when a new version of Mahara is available for installation.  It's obviously having problems parsing the html it gets back from launchpad, so we'll need to make it less fragile.

17 September 2010, 6:29

Alright, so it's been a couple of days and I'm still seeing hung cron jobs and I have to kill exactly five processes every morning. The tasks even hang at exactly the same time every morning--5AM. I know this because I look at top and it says that the tasks have been running for 180 minutes and I get in to work at 8AM. 

Unfortunately, I can't find anything noticeable in the cron log at that time. Here is the log file from the period between yesterday morning (created after I killed the hung processes) and this morning. 

https://www.meportfolio.ca/cron.log

The top screenshot above applies to this. In addition, here are the entries in ps aux:

root     10751  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10752  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10753 40.3  1.0 150260 21168 ?        R    Sep16 206:51 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10754  0.0  0.3 102632  8108 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(60040) idle                                                                               

root     10758  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10759  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10760 39.6  1.0 150260 21168 ?        R    Sep16 202:39 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10761  0.0  0.3 102632  8116 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(60041) idle                                                                               

root     10765  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10766  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10767 38.5  1.0 150264 21172 ?        R    Sep16 196:55 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10768  0.0  0.3 102632  8124 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35957) idle                                                                               

root     10771  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10772  0.0  0.0   9408  1400 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10773 39.8  1.0 150260 21168 ?        R    Sep16 202:44 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10774  0.0  0.3 102632  8120 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35958) idle                                                                          

root     10780  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10781  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10782 40.3  1.0 150268 21208 ?        R    Sep16 205:00 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10783  0.0  0.4 102692  8232 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35959) idle            

root     10751  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10752  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10753 40.3  1.0 150260 21168 ?        R    Sep16 206:51 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10754  0.0  0.3 102632  8108 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(60040) idle                                                                               

root     10758  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10759  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10760 39.6  1.0 150260 21168 ?        R    Sep16 202:39 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10761  0.0  0.3 102632  8116 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(60041) idle                                                                               

root     10765  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10766  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10767 38.5  1.0 150264 21172 ?        R    Sep16 196:55 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10768  0.0  0.3 102632  8124 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35957) idle                                                                               

root     10771  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10772  0.0  0.0   9408  1400 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10773 39.8  1.0 150260 21168 ?        R    Sep16 202:44 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10774  0.0  0.3 102632  8120 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35958) idle                                                                               

root     10780  0.0  0.0  28376   956 ?        S    Sep16   0:00 /USR/SBIN/CRON

mahara   10781  0.0  0.0   9408  1396 ?        Ss   Sep16   0:00 /bin/sh -c php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php >> /var/www/mahara/logs/cron.log 2>&1

mahara   10782 40.3  1.0 150268 21208 ?        R    Sep16 205:00 php -c /etc/php5/apache2/php.ini /var/www/mahara/mahara/lib/cron.php

postgres 10783  0.0  0.4 102692  8232 ?        Ss   Sep16   0:00 postgres: mahara mahara 127.0.0.1(35959) idle            

If there is any additional information that I can provide, let me know. Alternatively, if this can be fixed by switching to using curl for the cron jobs instead of php, I will do that. I'm rather at my wits end right now.

19 September 2010, 19:10

Okay, so it's nothing to do with those parse errors then.  I agree there's nothing helpful in that log, so I think we could use more information, it might help us to track down a particular function that's hanging.

Could you add some more log_debug() calls into htdocs/lib/cron.php to log every time a cron function/cron job finishes?  For example adding the calls in this patch would be useful:

http://mahara.org/artefact/file/download.php?file=89385

Then we'll hopefully know exactly what starts and doesn't finish.

It might also be useful to take a look in all the *cron tables (cron, artefact_cron, blocktype_cron, notification_cron, interaction_cron, etc.) and see if there's anything in any of them that's scheduled to start around 5am every day (though if there were, it probably would have shown up in your log).

And if none of that helps, it's probably something else on your server running at 5am that's interfering with the mahara processes.

22 September 2010, 7:29

I patched cron.php as you suggested. Here is a day's worth of cron tasks in the log. I've actually (correctly) calculated the time of the crashes today. According to top and ps aux, they took place at almost exactly 5:30AM. What confuses me, though, is that there are two tasks that ran within one minute of each other, both of which crashed:

23364 mahara    20   0  146m  20m 6220 R   39  1.0 232:05.45 php

23371 mahara    20   0  146m  20m 6220 R   37  1.0 232:35.12 php                                                                                                                    

https://www.meportfolio.ca/cron.log

Anyway, I can't seem to find any mention of these tasks in the cron log. Everything seems to start and stop at exactly the minute mark. 

I couldn't find any entries in the database corresponding to the hung cron jobs. The only thing I saw was a job that runs at 5:25AM, but only on Fridays. 

I've checked out the crontabs for all my users and the only task that runs close to 5:30AM is something for the Webmin control panel that simply deletes temporary files. 

53 4 * * * /etc/webmin/cron/tempdelete.pl #Delete Webmin temporary file

22 September 2010, 17:09

Cool, that log is quite useful, I think we should add the 'exiting...' lines to the log by default.

There are a bunch of jobs starting after 23:50 running cron_site_data_daily that never finish, so the problem is in that function.

It might be helpful to add in a call to that function on a normal page somewhere, hit the page and see if you can get any useful errors coming out in the webserver log.

If it's just dying silently the only option is to selectively comment stuff out & keep trying till you track down the offending part.

23 September 2010, 8:26

Alright, so I manually ran cron_site_data_daily() in a php file and saw this in my error logs:

[Thu Sep 23 10:19:04 2010] [error] [client xxxxxxx] [WAR] 63 (lib/pear/Image/Canvas/GD/PNG.php:119) imagepng() [function.imagepng]: Unable to open '/var/www/mahara/maharadata/images/viewtypes.png' for writing: Permission denied;

So I did a chown() on the data directory (since there were permission denied errors). On subsequent runs of the test file, I saw no errors whatsoever. Let's see if the fix is as simple as that.

23 September 2010, 16:31

Yeah, that should work fine.  I've always made the mahara cron run as the webserver user, which I guess is why I haven't seen that error.

I'll put something at the top of cron.php to check that dataroot is writable.