2

We're running a Redhat server (2.6.33.3-85.fc13.x86_64) and experienced some odd behaviour with our cron setup. We're running an out-of-the-box installation of cron.

We have a task that runs daily at 2am and has done so successfully for many months. However yesterday (27/03/2011) morning 8 instances of the task were started.

Here is the relevant section of our cron log file:

...
Mar 27 02:00:01 fs1 CROND[19557]: (root) CMD (true && /home/youdev/you_server/NEW_FS1/housekeeping_scripts/copy_pdf_printer_files_to_fs2.sh)
Mar 27 02:00:01 fs1 CROND[19563]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:02 fs1 CROND[19597]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:12 fs1 CROND[19931]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:22 fs1 CROND[20060]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:32 fs1 CROND[20067]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:42 fs1 CROND[20077]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:00:52 fs1 CROND[20084]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:01:02 fs1 CROND[20094]: (youdev) CMD (true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh)
Mar 27 02:01:02 fs1 CROND[20095]: (root) CMD (run-parts /etc/cron.hourly)
Mar 27 02:01:02 fs1 CROND[20096]: (root) CMD (true && /home/youdev/you_server/NEW_FS1/housekeeping_scripts/copy_pdf_printer_files_to_fs2.sh)
Mar 27 02:01:02 fs1 run-parts(/etc/cron.hourly)[20095]: starting 0anacron
...

Each of the fetch_db_data.sh scripts started correctly (they're just a shell script that calls a rsync - and the rsync tmp files exist as do the files that were successfully rsynced across).

This is the only job we have that starts at 02:00, yet we have a job that runs on the minute (copy_pdf_printer_files_to_fs2.sh) and this correctly ran just once at 02:00.

The only thing that we can think could have caused it is a daylight saving issue (we're in the UK so went from GMT to BST at 02:00 on the day in question) - however all the digging we've done says that cron handles daylight saving issues fine. And even then, shouldn't we have expected 0 runs (as time skipped from 00:59 to 02:00) rather than 8?

Here is the crontab entry:

MAILTO=XXX@XXX.YYY

# BACKUP LATEST DB FROM LIVE (takes approx one hour)
0 2 * * * true && /home/youdev/you_server/NEW_FS1/backup_scripts/fetch_db_data.sh

Many thanks in advance for reading this and for any help and suggestions,

Chris.

ChrisW
  • 283
  • 2
  • 9
  • Without making any other comment, I note that on Sunday morning the clock skipped from 0100 to 0200, not 0300, so you would still have expected it to run. We only went forward one hour, not two! – MadHatter Mar 28 '11 at 15:04
  • Yes, but with respect, you edited it wrong. The time "skipped" from 00:59:59GMT to 02:00:00BST, not 01:59:59GMT to 03:00:00BST; we really did have an 0200 on Sunday morning. The Wikipedia article on British Summer Time references the Summer Time Order 2002 as saying that BST applies during "the period beginning at one o'clock, Greenwich mean time, in the morning of the last Sunday in March and ending at one o'clock, Greenwich mean time, in the morning of the last Sunday in October" – MadHatter Mar 28 '11 at 15:48

2 Answers2

2

I'd use Ockham's Razor with this. It's bound to be the Summer Time clock changes.

Jonathan Ross
  • 2,173
  • 11
  • 14
  • 2
    You're more than likely right - but why would it trigger 8 ? I could see the case for 1 extra (maybe even a couple more than that) but 8 seems really quite odd. – ChrisW Mar 28 '11 at 15:42
  • 1
    I've had a couple of Servers repeat cron jobs around the start of the hour but never eight times ! Once was down to a manual cronned NTP entry jumping the clock back a few seconds each hour. Are you running NTP ? – Jonathan Ross Mar 28 '11 at 15:45
  • Jonathan's answer is probably more likely than it being DST changes IMHO. In my experience DST could account for 2 runs, but not 8. Note that you can avoid all of this trouble by setting the server's clock to UTC (Just Sayin' -- I don't do it myself :P) – voretaq7 Mar 28 '11 at 16:01
  • Yes, ntpd is running (and was running at the time) – ChrisW Mar 28 '11 at 16:08
  • I think maybe a combination of NTP and DST caused the bizarre number of Cron runs. Ockham's Razor again :-) – Jonathan Ross Mar 29 '11 at 06:17
  • Unfortunately that's what we're going to put it down to. Would be nice to know exactly what went on. Thanks for your thoughts @Jonathan. – ChrisW Mar 29 '11 at 09:40
  • Our 'fix' to (hopefully) prevent this from happening in 12 months time is a real numpty one. We're changing the time that our backup job fires to be 02:05 - and we're hoping that the crazy behaviour will have had chance to sort itself out in the 5 minutes before the job fires. (@voretaq7 : thanks for the suggestion about running in UTC time - but for us, it's just going to be too big a head ache to change things over) – ChrisW Mar 29 '11 at 09:45
  • @YouGroup Tech That's what always prevents me from switching over, plus the headache of mentally context-switching between UTC, EST and EDT every time I look at a log file. The "Run at 2:05" (or 3AM) fix is usually my solution :-) – voretaq7 Mar 29 '11 at 13:58
2

Please see Daniël van Eeden answer to question Cron job executed multiple times daylight saving time:

It is a known bug:

http://bugs.centos.org/view.php?id=5590

https://bugzilla.redhat.com/show_bug.cgi?id=436694

I've seen it happen on CentOS 6.2 with cronie-1.4.4-7.el6.x86_64 on the 31st of march (CET -> CEST)

Community
  • 1
FelixEnescu
  • 197
  • 1
  • 10