[Bug 1429427] [NEW] Unexplainable time jumps in CRON

Mon Jun 8 19:41:41 UTC 2015

Hi,

On 2015-03-07 18:16, sgofferj wrote:
> On my main server I see unexplainable time jumps backwards in the syslog. Those jumps affect CRON.
> Example:
> 
> Feb 10 06:48:01 nostromo CRON[20351]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
> Feb 10 06:49:01 nostromo CRON[20364]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
> Feb 10 06:50:01 nostromo CRON[20386]: (root) CMD (    /storage/exec/status-nostromo.sh >/dev/null 2>&1)
> Feb  7 05:40:01 nostromo CRON[20389]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
> Feb 10 06:50:01 nostromo CRON[20390]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
> Feb 10 06:50:01 nostromo CRON[20391]: (root) CMD (    /storage/exec/checkip.sh 2>/dev/null 1>/dev/null)

I'm afraid this is not a cron bug. The cron daemon does not write any
logs itself: as it is customary, it uses the syslog(3) facilities to log
all its messages. Therefore, the timestamp you are seeing is not
generated by cron, but by your syslog daemon.

Note that the PIDs of the individual cron processes are close together
(20386, 20389, 20390, 20391), which usually indicates that they were
started in close succession. So, despite the bogus timestamp, your cron
execution schedule appears to be fine.

I'd say this is either a bug in your syslog implementation, or a
hardware issue affecting syslog. By reassigning this bug to your syslog
implementation, the respective maintainers might be able to help you in
tracking down this issue.

Regards,
Christian

> For debugging I did the following:
> Start xclock and watch xclock and tail -f /var/log/syslog in parallel. When CRON logged a wrong time, xclock did NOT show any time jump but seemed to freeze for a fraction of a second.
> Open a screen and start a script that will once per second read the time (in unix seconds) and compare the read time with the time read a second ago. If the current time was smaller, the script would send an email with a process list from before and after the jump. The script also never detected any time jump.
> 
> In summary, my current impression is that there might be a bug in CRON because no other programm seems to be able to see the "wrong" time. The server in question is syslog server for 4 servers and 3 network devices. The time jumps exclusively show in syslog entries from the local CRON instance. Not in any remote syslog entry and not in any other local syslog entry, e.g. from DHCPD, bind, tftpd, etc. etc.
> Also, after a reboot, things work ok for several days upto about 2 or 3 weeks. Then the "time jumps" start to occur with increasing frequency.
> 
> I don't use user crontabs but maintain all jobs in /etc/crontab. I have
> number of jobs which are triggered every minute and another number of
> jobs which are triggered every 5 minutes (maybe some CRON internal
> counter overflow problem?).

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to cron in Ubuntu.
https://bugs.launchpad.net/bugs/1429427

Title:
  Unexplainable time jumps in CRON

Status in cron package in Ubuntu:
  Confirmed

Bug description:
  On my main server I see unexplainable time jumps backwards in the syslog. Those jumps affect CRON.
  Example:

  Feb 10 06:48:01 nostromo CRON[20351]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
  Feb 10 06:49:01 nostromo CRON[20364]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
  Feb 10 06:50:01 nostromo CRON[20386]: (root) CMD (    /storage/exec/status-nostromo.sh >/dev/null 2>&1)
  Feb  7 05:40:01 nostromo CRON[20389]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
  Feb 10 06:50:01 nostromo CRON[20390]: (root) CMD (    /storage/exec/checkinternet.sh 2>/dev/null 1>/dev/null)
  Feb 10 06:50:01 nostromo CRON[20391]: (root) CMD (    /storage/exec/checkip.sh 2>/dev/null 1>/dev/null)

  For debugging I did the following:
  Start xclock and watch xclock and tail -f /var/log/syslog in parallel. When CRON logged a wrong time, xclock did NOT show any time jump but seemed to freeze for a fraction of a second.
  Open a screen and start a script that will once per second read the time (in unix seconds) and compare the read time with the time read a second ago. If the current time was smaller, the script would send an email with a process list from before and after the jump. The script also never detected any time jump.

  In summary, my current impression is that there might be a bug in CRON because no other programm seems to be able to see the "wrong" time. The server in question is syslog server for 4 servers and 3 network devices. The time jumps exclusively show in syslog entries from the local CRON instance. Not in any remote syslog entry and not in any other local syslog entry, e.g. from DHCPD, bind, tftpd, etc. etc.
  Also, after a reboot, things work ok for several days upto about 2 or 3 weeks. Then the "time jumps" start to occur with increasing frequency.

  I don't use user crontabs but maintain all jobs in /etc/crontab. I
  have number of jobs which are triggered every minute and another
  number of jobs which are triggered every 5 minutes (maybe some CRON
  internal counter overflow problem?).

  Hardware:
  Asus P9D-V
  Intel Xeon E3-1240L V3
  16GB ECC RAM
  128GB SSD System
  3x3TB ZFS RaidZ2 storage
  1x3TB Misc. data

  CMOS battery already changed and board inspected.

  nostromo:~ # lsb_release -rd
  Description:    Ubuntu 14.04.2 LTS
  Release:        14.04

  nostromo:~ # apt-cache policy cron
  cron:
    Installed: 3.0pl1-124ubuntu2
    Candidate: 3.0pl1-124ubuntu2
    Version table:
   *** 3.0pl1-124ubuntu2 0
          500 http://us.archive.ubuntu.com/ubuntu/ trusty/main amd64 Packages
          100 /var/lib/dpkg/status

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/cron/+bug/1429427/+subscriptions