1

Try as I might, I can't figure out why this server randomly timestamps syslog entries with bad time.

Here's a 5-minute stretch of syslog from a few minutes ago. You'll notice there are two places where the time is logged wrong. Once where it logs it as January 10th (off by ~4 days) and another where it logs it as November 16th (either ~2 months behind or ~10 months ahead--can't tell since syslog doesn't log the year):

Jan 14 18:25:01 tetrad CRON[15482]: (root) CMD (zfs-auto-snapshot -q -g --label=frequent --keep=12  //)
Jan 14 18:25:01 tetrad CRON[15483]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then munin-run apt update 7200 12 >/dev/null; fi)
Jan 14 18:25:03 tetrad zfs-auto-snap: @zfs-auto-snap_frequent-2015-01-15-0225, 1 created, 1 destroyed, 0 warnings.
Jan 14 18:26:54 tetrad puppet-master[31196]: message repeated 2 times: [ Could not find default node or by name with 'kvm4.virt.pne.local, kvm4.virt.pne, kvm4.virt, kvm4' on node kvm4.virt.pne.local]
>> Jan 10 00:00:01 tetrad CRON[18094]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then munin-run apt update 7200 12 >/dev/null; fi)
Jan 14 18:27:01 tetrad CRON[18094]: (root) CMD (/usr/local/bin/lockrun --lockfile=/root/updatecw.lock -- /root/sqlworkbench/updatecw.sh > /dev/null)
Jan 14 18:28:02 tetrad fetchmail[7149]: message repeated 51 times: [ Warning: the connection is insecure, continuing anyways. (Better use --sslcertck!)]
>> Nov 16 23:45:01 tetrad CRON[20554]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then munin-run apt update 7200 12 >/dev/null; fi)
Jan 14 18:29:04 tetrad fetchmail[7149]: Warning: the connection is insecure, continuing anyways. (Better use --sslcertck!)
Jan 14 18:29:58 tetrad kernel: [7713426.484590] ip_set: protocol 6

I have verified the timezone settings are correct on the box, and I've completely stopped rsyslogd and started it again. I can even leave a loop running on the box for hours without an error:

while true; do date; sleep 1; done

...so it doesn't appear to be an issue with the clock. Reviewing 10,000+ lines of 'date' output in the console sucks! ;)

I should point out that I've only ever seen it when logging a CRON action. The cron jobs are not long running, and I've even tested by commenting out all the jobs in cron for a day. No false time entries.

Any thoughts?

Aaron C. de Bruyn
  • 578
  • 10
  • 28
  • 1
    Very likely the same issue as http://serverfault.com/questions/636901/random-ssh-entries-in-auth-log-out-of-date-order/655076 – Craig Miskell Jan 15 '15 at 05:05

0 Answers0