From Bugzilla Helper: User-Agent: Mozilla/4.75 (Macintosh; U; PPC) Commands in my crontab occasionally run twice. In my case, it is fetching a second image from a remote field site. Log files indicate that 2 instances of a script are started 1 second apart. Below are comments from another user to the discussion of Bug #29160... ------- Additional comments from dan 2001-02-27 12:14:40 ------- I've got another big problem, which I probably will need to submit a new bug for. With all this talk about crond, check this out: now that I've got this new vixie-cron-3.0.1-61, my crons are all running incorrectly. I'm getting *duplicate* runnings, but not every time. For instance, one cron entry runs at "0 23 * * *", which is 11:00 each night. Well, according to my cron logs, the command was issued at 10:59:59 and then *AGAIN* at 11:00:00 (one second later). This was a backup software command, so the backup got all messed up because two instances were fired up at almost the same time. I looked in the cron logs, and my "minutely" mailman cron is doing the same thing: it runs at xx:xx:59 and then at xx:xx+1:00 (one second later), but not every time. Some times it just runs at xx:xx:00. I'm about 4 minutes away from getting the old version of vixie-cron off of the CD and putting it back. Can anyone tell me what's up!? Reproducible: Sometimes Steps to Reproduce: 1. enter a command in crontab, write date-stamped output to a log file. 2. 3. Actual Results: Command in crontab occasionally runs twice. Instances started during consecutive clock seconds. Expected Results: Should run only once on the specified minute. Noticed problem after updating RPM package to vixie-cron-3.0.1-61
I've experienced the same problem. Cron jobs seem to run twice on occassion. I posted previously about this in response bug #21001. The problem began after upgrading vixie-cron to 3.0.1-61. The install stopped and restarted crond without incident. I have found a possible reason, but not a solution to the problem. I use ntpdate to update system time from /etc/crontab every 2 hours. (0 */2 * * * root /usr/sbin/ntpdate -u time-a.nist.gov). While cron does not execute twice after every time update, it does so frequently. However, it _never_ executes twice during the 'off' hour when ntpdate doesn't run. Incidently, the time offsets are small. (27 Feb 10:00:00 ntpdate[24689]: step time server 129.6.15.28 offset -0.843928 sec) Below are some entries from my cron log. Feb 27 12:00:00 samantha CROND[24875]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Feb 27 12:00:59 samantha CROND[24881]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 12:01:01 samantha CROND[24900]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 13:01:00 samantha CROND[24991]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 14:00:00 samantha CROND[25080]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Feb 27 14:00:59 samantha CROND[25086]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 14:01:01 samantha CROND[25105]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 15:01:00 samantha CROND[25196]: (root) CMD (run-parts /etc/cron.hourly) Feb 27 16:00:00 samantha CROND[25285]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Feb 27 16:01:00 samantha CROND[25291]: (root) CMD (run-parts /etc/cron.hourly) Feb 26 17:01:00 samantha CROND[22446]: (root) CMD (run-parts /etc/cron.hourly) Feb 26 18:00:00 samantha CROND[22535]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Feb 26 18:01:00 samantha CROND[22541]: (root) CMD (run-parts /etc/cron.hourly)
original reporter (or anyone else reading): are you also using NTP or something similar?
If you rebuild vixie-cron-3.0.1-61 without the vixie-cron-3.0.1-time.patch, does the problem go away?
I've recompiled without the time.patch, and restarted cron.d. I'll check the logs and let you know as soon as possible.
Rebuilding the vixie-cron-3.0.1-61 rpm without the vixie-cron-3.0.1-time.patch appears to make the problem go away.
When I installed vc3.0.1-61, I was using rdate to set the system clock twice a day. The cron glitches happened at other - seemingly random - times of the day. Two days ago I changed from rdate to ntpd. Haven't seen any change in crond's behavior.
The thing is, I'm not sure that this is a bug. That patch fixed a problem with crond; if your time was way ahead, and you set it back, it would then sleep until it got to whatever the previous wrong time was. This patch fixes that. I'll poke at it to see if there is some conflict that's causing this behavior, but if the system time does roll past the hourly point twice in a row (due to the time being reset), it really does make sense for cron to activate twice.
Please note that on my system I run ntpdate only twice per day: once in the morning and once in the evening. However, the duplicate cron executions continue all day long, when there is no ntpdate running to mess up the clock.
I've done some further testing. The following changes were made to my system: Re-installed the 'stock' version of vixie-cron-3.0.1-61 (with the time.patch). (perhaps related to bug #29160, crond didn't get stopped or restarted by the install scripts, I had to do so manually) Changed ntpdate to run on the half hour, to avoid adjusting the clock while cron is running it's jobs. In all cases, the clock was adjusted by less than 1 second. Cron ran twice far less often than previously, never duplicating the hourly entries. It did however run cron.daily twice, 90 minutes after the last clock adjustment. Here is the log since restarting crond: Feb 28 23:40:15 samantha crond[10045]: (CRON) STARTUP (fork ok) Mar 1 00:01:00 samantha CROND[10194]: (root) CMD (run-parts /etc/cron.hourly) Mar 1 00:30:00 samantha CROND[10370]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Mar 1 01:01:00 samantha CROND[10552]: (root) CMD (run-parts /etc/cron.hourly) Mar 1 02:01:00 samantha CROND[10881]: (root) CMD (run-parts /etc/cron.hourly) Mar 1 02:30:00 samantha CROND[10944]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Mar 1 03:01:00 samantha CROND[10989]: (root) CMD (run-parts /etc/cron.hourly) Mar 1 04:01:00 samantha CROND[11090]: (root) CMD (run-parts /etc/cron.hourly) Mar 1 04:01:59 samantha CROND[11117]: (root) CMD (run-parts /etc/cron.daily) Mar 1 04:02:00 samantha CROND[11133]: (root) CMD (run-parts /etc/cron.daily) Mar 1 04:02:01 samantha anacron[11138]: Updated timestamp for job `cron.daily' to 2001-03-01 Mar 1 04:30:00 samantha CROND[12027]: (root) CMD (/usr/sbin/ntpdate -u time-a.nist.gov) Mar 1 04:42:00 samantha CROND[12046]: (root) CMD (run-parts /etc/cron.monthly) Mar 1 05:01:00 samantha CROND[12097]: (root) CMD (run-parts /etc/cron.hourly)
To avoid confussion... anacron updated the time stamp for cron.daily twice, as expected. I missed a log entry in the previous message.
wow ... it's been 6+ years since i've had to open up vixie-cron for debugging. i believe what's happening here is a race condition with sleep that is manifesting as a really bizarre looking example of a general flaw in the scheduling logic introduced by the last time related fix. if we look at cron_sync() as generating a sequence of minute-resolution time instants, a simple rule will eliminate the ambiguous case, of which this bug is an example. let t[i] be the ith value in the sequence of time instants generated by cron_sync(). the rule is: t[i+1] != t[i]. that is, time as seen by cron is sufficiently elastic to absorb adjustments of 60 seconds or less. why? time adjustments of a minute or less are ambiguious. imagine the time adjustment happening on a real clock. if we make an adjustment of -30 seconds, did we backtrack into the previous minute? without knowing the time of the adjustment with greater precision than we have avaliable (minutes), we cannot answer the question. each answer has equal probablility. if we do not know whether we backtracked into the previous minute, we do not know if the same "top of the minute" occurs once only, or twice in a row. we do not know if we *should* execute the jobs again or not. the current code will execute the jobs for time t[i] twice if the time moves back by a minute or less. i submit that this behavior will result in undesirable results more often than not. the alternative is to stretch the "current" minute to cover the delay caused by the time adjustment. this will result in the jobs being executed only once, as they would have if no time change had taken place. i submit that this is the more desirable, and hence, more "correct" solution. double queueing immediately following an automated time adjustment is the normal case of this bug. i suspect, but have not proven, that we also have a race condition, where sleeping "at least n seconds" means "longer than n - 1 seconds". so it's 09:00:00, we sleep for 60 seconds, and when we wake up, it's not 09:01:00, but 09:00:59.99. this would of course cause the same code behavior as the above discussed small backwards time adjusments. patch enforcing the above discussed rule will follow in a couple of minutes.
Created attachment 12062 [details] src rpm with updated spec, new patch file
vixie-cron-3.0.1-62 should be in the next rawhide release - thanks!
*** Bug 36104 has been marked as a duplicate of this bug. ***
I installed vixie-cron-3.0.1-61 yesterday and am again (as when I originally reported the bug) getting duplicate start-ups of cron jobs. They always happen at :59 and :00 seconds into the minute. As I understand it, they should only start at (or slightly after) 00 seconds. Here are some lines from /var/log/ messages: Apr 17 12:23:59 hanish CROND[29928]: (trachier) CMD (sleep 12; ... Apr 17 12:23:59 hanish CROND[29929]: (trachier) CMD (sleep 10; ... Apr 17 12:23:59 hanish CROND[29931]: (trachier) CMD (sleep 8; ... Apr 17 12:23:59 hanish CROND[29933]: (trachier) CMD (sleep 6; ... Apr 17 12:23:59 hanish CROND[29935]: (trachier) CMD (sleep 4; ... Apr 17 12:23:59 hanish CROND[29938]: (trachier) CMD (sleep 2; ... Apr 17 12:23:59 hanish CROND[29937]: (trachier) CMD ((cd ./datasys; ... Apr 17 12:24:00 hanish CROND[29952]: (trachier) CMD (sleep 12; ... Apr 17 12:24:00 hanish CROND[29953]: (trachier) CMD (sleep 10; ... Apr 17 12:24:00 hanish CROND[29955]: (trachier) CMD (sleep 8; ... Apr 17 12:24:00 hanish CROND[29957]: (trachier) CMD (sleep 6; ... Apr 17 12:24:00 hanish CROND[29959]: (trachier) CMD (sleep 4; ... Apr 17 12:24:00 hanish CROND[29962]: (trachier) CMD (sleep 2; ... Apr 17 12:24:00 hanish CROND[29961]: (trachier) CMD ((cd ./datasys; ...
Sorry, guys. A little more information will help. When I ran up2date yesterday, it loaded vixie-cron-3.0.1-61.i386.rpm which is the older buggy version. My oversight, but am surprised that redhat.com doesn't yet have the fixed version available to up2date. Where can I find the fixed version? Thanks.
*** Bug 36318 has been marked as a duplicate of this bug. ***
*** Bug 45304 has been marked as a duplicate of this bug. ***
*** Bug 45647 has been marked as a duplicate of this bug. ***