0

I need to see accurate timestamps for the cron logs of a CentOS 7 VM using an OpenVZ-based image. The machine also has SCL enabled because Red Hat supplies antique software out-of-the box. Users like us have to do something special to get into a good state.

Currently the log entries have some random time timestamps and skew more as time goes in a log rotation period. In the log sample below, today is December 21, 2018 but the tail log entries are being stamped December 16. In between the first and last entry are entries with random timestamps.

Here is an earlier problem we had to solve, and I'm not sure if it is contributing to this problem. I've already installed an NTP client and it is sync'ing with NIST time servers every four hours.

What is the problem and how do I fix it?

Here is a sample of the logs. It is a monotonically increasing sampling. I just picked pieces out where the machinery decided to start randomizing entries.

# cat /var/log/cron-20181216
# <first two entries below this line>
Dec 11 17:40:02 ftpit CROND[330]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 11 17:50:01 ftpit CROND[536]: (root) CMD (/usr/lib64/sa/sa1 1 1)
...
Dec 12 00:00:01 ftpit CROND[5589]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 12 00:10:01 ftpit CROND[5703]: (root) CMD (/usr/lib64/sa/sa1 1 1)
...
Dec 12 10:20:04 ftpit CROND[14133]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 12 10:21:43 ftpit crond[182]: (CRON) INFO (Shutting down)
...
Dec 12 10:22:10 ftpit crond[182]: (CRON) INFO (running with inotify support)
Apr 17 00:00:01 ftpit CROND[10377]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Aug 19 14:40:01 ftpit CROND[22522]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Feb 21 11:30:01 ftpit CROND[20076]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 28 23:50:02 ftpit CROND[23797]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jun  8 04:50:06 ftpit CROND[5513]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 28 23:53:01 ftpit CROND[23816]: (root) CMD (/usr/lib64/sa/sa2 -A)
Feb 21 11:40:04 ftpit CROND[20398]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 29 00:00:07 ftpit CROND[23863]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Apr 17 00:12:01 ftpit CROND[10645]: (root) CMD (run-parts /etc/cron.hourly)
Apr 17 00:12:01 ftpit run-parts(/etc/cron.hourly)[10645]: starting 0yum-hourly.cron
Jun  8 05:00:01 ftpit CROND[5638]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 29 00:10:04 ftpit CROND[23913]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Feb 21 11:50:13 ftpit CROND[20790]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jun  8 05:10:01 ftpit CROND[5754]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jun  8 05:12:01 ftpit CROND[5834]: (root) CMD (run-parts /etc/cron.hourly)
Jun  8 05:12:01 ftpit run-parts(/etc/cron.hourly)[5834]: starting 0yum-hourly.cron
...
Dec 16 04:30:01 ftpit CROND[30820]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 16 04:40:03 ftpit CROND[30981]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 16 04:50:03 ftpit CROND[31096]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 16 05:00:01 ftpit CROND[31252]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Dec 16 05:00:14 ftpit run-parts(/etc/cron.daily)[31270]: finished 0yum-daily.cron
Dec 16 05:00:14 ftpit run-parts(/etc/cron.daily)[30614]: starting certwatch
Dec 16 05:00:15 ftpit run-parts(/etc/cron.daily)[31287]: finished certwatch
Dec 16 05:00:15 ftpit run-parts(/etc/cron.daily)[30614]: starting gdrive-backup
Dec 16 05:00:18 ftpit run-parts(/etc/cron.daily)[31303]: finished gdrive-backup
Dec 16 05:00:18 ftpit run-parts(/etc/cron.daily)[30614]: starting logrotate
# <last 10 entries are above this line>
  • 1
    I'm a little curious why you're only syncing every 4 hours; if your system's clock is drifting, you may end up syncing less often or more often! Is there a reason you can't run NTP as a continuous daemon? – Jeff Schaller Dec 22 '18 at 02:19
  • @JeffSchaller - I think mostly old habit. In the early 2000's I was a Windows sysadmin. We sync'd once a day and things went well. AD with 13 DC's around the world did not have any problems. NIST does not like their servers hammered, so I limited it to every 4 hours for this problem. (The problem has been around for years. I've kind of hit my limits with the BS I am willing to take from this OS, so I'm now doing something about it). –  Dec 22 '18 at 02:35
  • NTP will query the servers a few times initially, then dials back to a slower rate; if you have an environment of reasonable size, it's common to set up a couple internal NTP servers (who will be stratum "NIST - 1"), against which the rest of your environment can sync. Then you're not querying NIST with "N" clients but only 2. Just mentioning NTP in case your time is drifting badly in that 4-hour window. – Jeff Schaller Dec 22 '18 at 02:38
  • Thanks Jeff. You know, I can't help but laugh at this. [Prehistoric man](https://www.egardwatches.com/blogs/news/how-did-people-tell-time-before-clocks) had a better sense of time and timekeeping than a CentOS server in 2018. A 2000 BC sundial is more accurate than a CentOS server in 2018. If I was Red Hat I would be embarrassed. –  Dec 22 '18 at 05:12
  • It's a VM. Unless it's synced to the host clock you will always get drift because the vCPU gets dialed back in a way that is hard for the guest to notice. Clock ticks can get dropped unexpectedly, etc. You should either run NTP in the way it was designed (not SNTP as was common on Windows 2003/2008 servers) or sync to host time and ensure that that is accurate. – roaima Dec 25 '18 at 17:22
  • Is each line an standalone sample? I'm trying to understand what timing problem you're illustrating here. Or is that 17 line block in the middle a continuous segment? If so, that's characteristic of filesystem corruption. – roaima Dec 25 '18 at 17:25
  • If it's actually OpenVZ, then time sync must be done in the host OS, not in a container. – Michael Hampton Dec 25 '18 at 19:20

0 Answers0