Let me guess: you're in UTC+1 timezone and syslog is started before the timezone setting is applied.

Here's some more info:

# grep -y utc /etc/rc.conf
HARDWARECLOCK="UTC"

# grep -y timezone /etc/rc.conf
TIMEZONE="Europe/London"

# date
Thu Dec 15 15:39:24 GMT 2011


I've even checked this manually and found out that the cron job starts 1 hour early, so it doesn't look to be UTC issue.

Could you use "date >> /tmp/execution-dates-from-cronies-viewpoint" as a crontab?

Yes, here's the result.

# cat /tmp/execution-dates-from-cronies-viewpoint
Fri Dec 16 00:31:01 GMT 2011
# date
Fri Dec 16 00:31:11 GMT 2011

#tail -n 1 /var/log/crond.log
Dec 16 00:31:01 imran-plug /USR/SBIN/CROND[2417]: (root) CMD (/bin/date >> /tmp/execution-dates-from-cronies-viewpoint)

# crontab -l
* * * * * /bin/date >> /tmp/execution-dates-from-cronies-viewpoint

So the problem occurs when you give it specific time of the day to run the job.

I'll run the job after every hour and will see if that makes any difference (will put the results for that tomorrow).

Here are the results that I got:

# crontab -l
0 2 * * * /bin/date >> /tmp/execution-dates-from-cronies-viewpoint
0 4 * * * /bin/date >> /tmp/execution-dates-from-cronies-viewpoint
0 6 * * * /bin/date >> /tmp/execution-dates-from-cronies-viewpoint
0 8 * * * /bin/date >> /tmp/execution-dates-from-cronies-viewpoint

# cat /tmp/execution-dates-from-cronies-viewpoint
Fri Dec 16 02:00:01 GMT 2011
Fri Dec 16 04:00:01 GMT 2011
Fri Dec 16 06:00:02 GMT 2011
Fri Dec 16 08:00:01 GMT 2011

# grep execution-dates-from-cronies-viewpoint /var/log/crond.log
Dec 16 02:00:01 imran-plug /USR/SBIN/CROND[3890]: (root) CMD (/bin/date >> /tmp/execution-dates-from-cronies-viewpoint)
Dec 16 04:00:01 imran-plug /USR/SBIN/CROND[8435]: (root) CMD (/bin/date >> /tmp/execution-dates-from-cronies-viewpoint)
Dec 16 06:00:01 imran-plug /USR/SBIN/CROND[10183]: (root) CMD (/bin/date >> /tmp/execution-dates-from-cronies-viewpoint)
Dec 16 08:00:01 imran-plug /USR/SBIN/CROND[11933]: (root) CMD (/bin/date >> /tmp/execution-dates-from-cronies-viewpoint)


Looks like this one might have run on time but I haven't checked its execution time manually, however my old job still starts one hour before it's set time.

# crontab -l
0 0 * * * /usr/bin/rsnapshot daily

# grep rsnapshot /var/log/crond.log
Dec 15 23:00:01 imran-plug /USR/SBIN/CROND[5421]: (root) CMD (/usr/bin/rsnapshot daily)

May I suggest you try with `0 0 * * * /bin/date >> /tmp/getting-to-the-bottom-of-this`? For me it runs at midnight as expected.

I'll paste the results tonight.

It looks like the problem was because of the following cron entry:

# crontab -l
0 * * * * /usr/bin/ntpdate tick.greyware.com > /dev/null 2>&1

I made that to:

# crontab -l
30 * * * * /usr/bin/ntpdate tick.greyware.com > /dev/null 2>&1

and it's now running the jobs on their set time.

Right. So ntpdate was messing with your clock momentarily. I suggest you use ntpd instead.

Hi,

Could you please reopen this because the problem still exists, it might have been fixed only for one day but now it's again happening however this time I don't even have ntpd in my cron entries.

Following is some more info:

# grep rsnapshot /var/log/crond.log
Dec 18 23:00:01 imran-plug /USR/SBIN/CROND[10134]: (root) CMD (/usr/bin/rsnapshot daily)
Dec 19 23:00:01 imran-plug /USR/SBIN/CROND[31205]: (root) CMD (/usr/bin/rsnapshot daily)

# crontab -l
0 0 * * * /usr/bin/rsnapshot daily
0 4 * * 6 /usr/bin/rsnapshot weekly
0 8 1 * * /usr/bin/rsnapshot monthly
*/5 * * * * /usr/bin/sudo -u http /usr/bin/php /srv/http/cacti/poller.php > /dev/null 2>&1
0 0 * * * /usr/bin/faillog -r

# find /etc/cron.*
/etc/cron.d
/etc/cron.d/0hourly
/etc/cron.daily
/etc/cron.daily/shadow
/etc/cron.daily/logrotate
/etc/cron.daily/man-db
/etc/cron.daily/sysstat
/etc/cron.deny
/etc/cron.hourly
/etc/cron.hourly/sysstat
/etc/cron.hourly/0anacron
/etc/cron.hourly/date.sync
/etc/cron.monthly
/etc/cron.weekly

# date
Tue Dec 20 15:00:06 GMT 2011

# grep "DAEMONS=" /etc/rc.conf
DAEMONS=(syslog-ng network netfs crond sshd samba mysqld postfix lighttpd ntpd)

Hi,

Could you please reopen this because the problem still exists, it might have been fixed only for one day but now it's again happening however this time I don't even have ntpd in my cron entries.

Following is some more info:

# grep rsnapshot /var/log/crond.log
Dec 18 23:00:01 imran-plug /USR/SBIN/CROND[10134]: (root) CMD (/usr/bin/rsnapshot daily)
Dec 19 23:00:01 imran-plug /USR/SBIN/CROND[31205]: (root) CMD (/usr/bin/rsnapshot daily)

# crontab -l
0 0 * * * /usr/bin/rsnapshot daily
0 4 * * 6 /usr/bin/rsnapshot weekly
0 8 1 * * /usr/bin/rsnapshot monthly
*/5 * * * * /usr/bin/sudo -u http /usr/bin/php /srv/http/cacti/poller.php > /dev/null 2>&1
0 0 * * * /usr/bin/faillog -r

# find /etc/cron.*
/etc/cron.d
/etc/cron.d/0hourly
/etc/cron.daily
/etc/cron.daily/shadow
/etc/cron.daily/logrotate
/etc/cron.daily/man-db
/etc/cron.daily/sysstat
/etc/cron.deny
/etc/cron.hourly
/etc/cron.hourly/sysstat
/etc/cron.hourly/0anacron
/etc/cron.hourly/date.sync
/etc/cron.monthly
/etc/cron.weekly

# date
Tue Dec 20 15:00:06 GMT 2011

# grep "DAEMONS=" /etc/rc.conf
DAEMONS=(syslog-ng network netfs crond sshd samba mysqld postfix lighttpd ntpd)

What is that script? /etc/cron.hourly/date.sync

Hmm! that script has following contents in it.


=====================
#!/bin/bash

ntpdate tick.greyware.com > /dev/null 2>&1
=====================

I didn't realize it's still there.

It could have been that script causing the problem, let me run without that script and I'll paste the results here.

Here are the latest logs, the job is till starting at 23:00 rather than 00:00

# find /etc/cron*
/etc/cron.d
/etc/cron.d/0hourly
/etc/cron.daily
/etc/cron.daily/shadow
/etc/cron.daily/logrotate
/etc/cron.daily/man-db
/etc/cron.daily/sysstat
/etc/cron.deny
/etc/cron.hourly
/etc/cron.hourly/sysstat
/etc/cron.hourly/0anacron
/etc/cron.monthly
/etc/cron.weekly

# crontab -l
0 0 * * * /usr/bin/rsnapshot daily
0 4 * * 6 /usr/bin/rsnapshot weekly
0 8 1 * * /usr/bin/rsnapshot monthly
*/5 * * * * /usr/bin/sudo -u http /usr/bin/php /srv/http/cacti/poller.php > /dev/null 2>&1
0 0 * * * /usr/bin/faillog -r

# grep rsnapshot /var/log/crond.log
Dec 21 23:00:01 imran-plug /USR/SBIN/CROND[13460]: (root) CMD (/usr/bin/rsnapshot daily)
Dec 22 23:00:01 imran-plug /USR/SBIN/CROND[17403]: (root) CMD (/usr/bin/rsnapshot daily)

Could we finally try `x y * * * /bin/date >> /tmp/getting-to-the-bottom-of-this` for (x,y) in (0,23), (59,23), (0,0), (1,0), and (0,1)?
It's really not helping to re-paste the same data each time: try with something else than rsnapshot, try skimming down your cronie configuration and crontabs as much as you can until you cannot reproduce the problem anymore, etc.

Ok, I'll get that data tonight.

Here are he results from the above:

# crontab -l | grep getting-to-the-bottom-of-this
0 23 * * * /bin/date >> /root/getting-to-the-bottom-of-this
59 23 * * * /bin/date >> /root/getting-to-the-bottom-of-this
0 0 * * * /bin/date >> /root/getting-to-the-bottom-of-this
1 0 * * * /bin/date >> /root/getting-to-the-bottom-of-this
0 1 * * * /bin/date >> /root/getting-to-the-bottom-of-this

# grep getting-to-the-bottom-of-this /var/log/crond.log
Dec 23 22:00:01 imran-plug /USR/SBIN/CROND[23734]: (root) CMD (/bin/date >> /root/getting-to-the-bottom-of-this)
Dec 23 22:59:01 imran-plug /USR/SBIN/CROND[24604]: (root) CMD (/bin/date >> /root/getting-to-the-bottom-of-this)
Dec 23 23:00:01 imran-plug /USR/SBIN/CROND[24613]: (root) CMD (/bin/date >> /root/getting-to-the-bottom-of-this)
Dec 23 23:01:01 imran-plug /USR/SBIN/CROND[24689]: (root) CMD (/bin/date >> /root/getting-to-the-bottom-of-this)
Dec 24 00:00:02 imran-plug /USR/SBIN/CROND[25488]: (root) CMD (/bin/date >> /root/getting-to-the-bottom-of-this)

# cat /root/getting-to-the-bottom-of-this
Fri Dec 23 22:00:01 GMT 2011
Fri Dec 23 22:59:01 GMT 2011
Fri Dec 23 23:00:02 GMT 2011
Fri Dec 23 23:01:01 GMT 2011
Sat Dec 24 00:00:02 GMT 2011

# date
Sat Dec 24 09:50:37 GMT 2011

Do you realize that this info contradicts that you posted on Friday, 16 December 2011, 10:09 GMT+1?
So I don't know what's wrong on your computer but unless you can make the issue reproducible yourself there's no way I'm going to be able to debug this.

Hi Gaetan,

Thanks for your time, basically I removed those entries from the cron which were running ntpdate which I previously thought might be causing the problem but even after removing those ntpupdate entries the problem still persists.

I'll look into the source of cronie and will try see what's wrong.

Once again thanks for looking into this problem, you may close this defect.

Cheers

Alright. If you find that this is actually a packaging problem, do not hesitate to create a new ticket with your findings. Good luck.