Despite ntpd and hourly `hwclock --adjust`, I had to `ntpdate` to fix 5 minute drift?

GrapefruiTgirl · 06-07-2008, 11:42 PM

Wow, I pretty much got the whole problem right into the thread title..

So yes, A long while back (in another thread somewhere) I set up ntpd and configured it using bits and pieces of ntp.conf files I gathered from the net (because the originally included .conf file produced nothing but errors and the man page didn't get me anywhere) and I have had perfect time ever since.
I set ntpd to use 3 of the ca.pool.ntp servers, and it allegedly checks in & tracks/adjusts the drift about once per hour.
I have a cron run hourly that runs `hwclock --debug --adjust` and concatenates the output to a log file.

Periodically I visit the WorldTimeServer.com site and see that my clock matches their time, give or take a second or so.

Earlier tonight, I noticed that my KDE desktop time, the `date` command, and `hwclock --show` all were off by about 5 minutes. (I detected this when I noticed that my posts on LQ were time-stamped at five minutes into the future)

I tried --adjusting the hwclock manually, played with `hwclock --systohc` and `hwclock --hctosys` a few times, checked my firewall was allowing the NTP traffic, killed & restarted ntpd several times and waited for the hourly adjustment (which didn't happen, though the log claimed that the difference was less than a second so it was not going to adjust the clock), I ran `netstat` to verify that ntpd was indeed running on a port (123), and finally I started Wireshark and watched the NTP traffic when it happened.
All the above pointed to everything "working" but still the clocks were not getting corrected (and indeed had somehow gotten 5 minutes off already).

Finally, another thread on LQ about an unrelated clock situation led me to discover the `ntpdate` command, which I executed after killing ntpd.
I ran `ntpdate` with one of the same server-names that I use in my ntp.conf file, and it WORKED; the clocks became correct instantly.

The question is WHY? Why did I need to resort to using `ntpdate`, and why did that work just as the ntpd daemon did not? And am I to resort to having to periodically run `ntpdate` to correct the time now?

Thanks for any thoughts on this; if you want log files or the ntp.conf file, just ask

Sasha

Tinkster · 06-08-2008, 12:13 AM

Do the logs suggest anything regarding problems with ntpd? If
the internal clock has too much of a drift from the servers
the daemon may give up, I'm not sure how high exactly the
threshold for this is, though. Go through your logs, grep
for ntpd.

Cheers,
Tink

GrapefruiTgirl · 06-08-2008, 01:02 AM

Hi Tinkster,

Nope, the logs don't indicate anything specifically identifiable as a problem.
The rather cryptic messages do look like "errors" at times, at a glance, but they are the same messages that have always been there while this all has been working.

Here's a clip of the ntp.log, which is also where the cron gets logged (I added some comments):

Code:

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212872460 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/07 22:01:02
Hw clock time : 2008/06/07 22:01:02 = 1212876062 seconds since 1969
Time since last adjustment is 3602 seconds
Need to insert -2 seconds and refer time back 0.729529 seconds ago
Time elapsed since reference time has been 0.729755 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 22:01:01 = 1212876061 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# still off by 5 minutes

 7 Jun 19:54:53 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212876060 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/07 23:01:02
Hw clock time : 2008/06/07 23:01:02 = 1212879662 seconds since 1969
Time since last adjustment is 3602 seconds
Need to insert -2 seconds and refer time back 0.729529 seconds ago
Time elapsed since reference time has been 0.729740 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 23:01:01 = 1212879661 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# still off by 5 minutes

 7 Jun 20:54:53 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212879660 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 00:01:01
Hw clock time : 2008/06/08 00:01:01 = 1212883261 seconds since 1969
Time since last adjustment is 3601 seconds
Need to insert -2 seconds and refer time back 0.729882 seconds ago
Time elapsed since reference time has been 0.730082 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 00:01:00 = 1212883260 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# still off by 5 minutes

 7 Jun 21:54:53 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212883259 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 01:01:01
Hw clock time : 2008/06/08 01:01:01 = 1212886861 seconds since 1969
Time since last adjustment is 3602 seconds
Need to insert -2 seconds and refer time back 0.729529 seconds ago
Time elapsed since reference time has been 0.729744 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 01:01:00 = 1212886860 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# still off by 5 minutes

 7 Jun 22:54:53 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212886859 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 02:01:01
Hw clock time : 2008/06/08 02:01:01 = 1212890461 seconds since 1969
Time since last adjustment is 3602 seconds
Need to insert -2 seconds and refer time back 0.729529 seconds ago
Time elapsed since reference time has been 0.729748 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 02:01:00 = 1212890460 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# and still, off by 5 minutes

 7 Jun 23:54:53 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212890459 seconds after 1969
Last calibration done at 1212850649 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 03:01:01
Hw clock time : 2008/06/08 03:01:01 = 1212894061 seconds since 1969
Time since last adjustment is 3602 seconds
Need to insert -2 seconds and refer time back 0.729529 seconds ago
Time elapsed since reference time has been 0.729745 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 03:01:00 = 1212894060 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****

# still off by 5 minutes. Next, I kill ntpd and restart it.
# The STATUS messages are as they have always been (weird looking)..

 8 Jun 00:27:57 ntpd[2132]: ntpd exiting on signal 15
 8 Jun 00:27:57 ntpd[2132]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 00:28:02 ntpd[29284]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 00:28:02 ntpd[29284]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 00:28:03 ntpd[29284]: peer 72.1.194.82 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:28:04 ntpd[29284]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:28:05 ntpd[29284]: peer 64.201.62.2 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)

# time still wrong. I kill it again and restart:

 8 Jun 00:33:42 ntpd[29284]: ntpd exiting on signal 15
 8 Jun 00:33:42 ntpd[29284]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 00:33:46 ntpd[30419]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 00:33:46 ntpd[30419]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 00:33:47 ntpd[30419]: peer 72.0.206.121 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:33:48 ntpd[30419]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:33:49 ntpd[30419]: peer 64.201.62.2 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)

# and kill again and again, but somewhere below here between kills and restarts is where
# I did the `ntpdate` thing; it isn't logged because I did it from a console
# and didn't log it.. Silly me...

 8 Jun 00:35:04 ntpd[30419]: ntpd exiting on signal 15
 8 Jun 00:35:04 ntpd[30419]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 00:35:07 ntpd[30688]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 00:35:07 ntpd[30688]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 00:35:07 ntpd[30688]: peer 72.1.194.82 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:35:08 ntpd[30688]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:35:09 ntpd[30688]: peer 64.201.62.2 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:51:13 ntpd[30688]: ntpd exiting on signal 15
 8 Jun 00:51:13 ntpd[30688]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 00:51:46 ntpd[2505]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 00:51:46 ntpd[2505]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 00:51:48 ntpd[2505]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:51:48 ntpd[2505]: peer 208.97.105.139 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:54:55 ntpd[2505]: ntpd exiting on signal 15
 8 Jun 00:54:55 ntpd[2505]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 00:54:57 ntpd[3186]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 00:54:57 ntpd[3186]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 00:54:59 ntpd[3186]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 00:54:59 ntpd[3186]: peer 208.97.105.139 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212895282 seconds after 1969
Last calibration done at 1212895282 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 04:01:03
Hw clock time : 2008/06/08 04:01:03 = 1212897663 seconds since 1969
Time since last adjustment is 2381 seconds
Need to insert -1 seconds and refer time back 0.160191 seconds ago
Needed adjustment is less than one second, so not setting clock.
****End of hwclock data****
 8 Jun 01:02:21 ntpd[3186]: ntpd exiting on signal 15
 8 Jun 01:02:21 ntpd[3186]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6
 8 Jun 01:15:03 ntpd[6134]: frequency initialized 0.000 PPM from /etc/ntp/drift
 8 Jun 01:15:03 ntpd[6134]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
 8 Jun 01:15:03 ntpd[6134]: peer 208.97.105.139 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 01:15:04 ntpd[6134]: peer 192.135.48.21 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
 8 Jun 01:15:05 ntpd[6134]: peer 72.1.194.82 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)

****HWCLOCK adjust debug by daily cron:
hwclock from util-linux-2.12r
Using /dev/rtc interface to clock.
Last drift adjustment done at 1212895282 seconds after 1969
Last calibration done at 1212895282 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2008/06/08 04:55:51
Hw clock time : 2008/06/08 04:55:51 = 1212900951 seconds since 1969
Time since last adjustment is 5669 seconds
Need to insert -2 seconds and refer time back 0.000472 seconds ago
Time elapsed since reference time has been 0.000664 seconds.
Delaying further to reach the next full second.
Setting Hardware Clock to 04:55:50 = 1212900950 seconds since 1969
ioctl(RTC_SET_TIME) was successful.
****End of hwclock data****
 8 Jun 02:15:02 ntpd[6134]: offset 0.000000 sec freq 0.000 ppm error 0.000001 poll 6

Here's everything from /var/log/messages which is nice and clean because I rebooted earlier after cleaning the inside of my case:

Code:

Jun  7 23:14:36 darkstarssi -- MARK --
Jun  7 23:34:36 darkstarssi -- MARK --
Jun  7 23:54:36 darkstarssi -- MARK --
Jun  8 00:14:36 darkstarssi -- MARK --
Jun  8 00:28:01 darkstarssi ntpd[29283]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 00:28:01 darkstarssi ntpd[29284]: precision = 1.000 usec
Jun  8 00:28:01 darkstarssi ntpd[29284]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 00:28:01 darkstarssi ntpd[29284]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 00:28:01 darkstarssi ntpd[29284]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 00:28:01 darkstarssi ntpd[29284]: kernel time sync status 0040
Jun  8 00:33:45 darkstarssi ntpd[30418]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 00:33:45 darkstarssi ntpd[30419]: precision = 1.000 usec
Jun  8 00:33:45 darkstarssi ntpd[30419]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 00:33:45 darkstarssi ntpd[30419]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 00:33:45 darkstarssi ntpd[30419]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 00:33:45 darkstarssi ntpd[30419]: kernel time sync status 0040
Jun  8 00:35:06 darkstarssi ntpd[30687]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 00:35:06 darkstarssi ntpd[30688]: precision = 1.000 usec
Jun  8 00:35:06 darkstarssi ntpd[30688]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 00:35:06 darkstarssi ntpd[30688]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 00:35:06 darkstarssi ntpd[30688]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 00:35:06 darkstarssi ntpd[30688]: kernel time sync status 0040
Jun  8 00:51:38 darkstarssi kernel: device eth0 entered promiscuous mode
Jun  8 00:51:45 darkstarssi ntpd[2504]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 00:51:45 darkstarssi ntpd[2505]: precision = 1.000 usec
Jun  8 00:51:45 darkstarssi ntpd[2505]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 00:51:45 darkstarssi ntpd[2505]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 00:51:45 darkstarssi ntpd[2505]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 00:51:45 darkstarssi ntpd[2505]: kernel time sync status 0040
Jun  8 00:54:57 darkstarssi ntpd[3185]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 00:54:57 darkstarssi ntpd[3186]: precision = 1.000 usec
Jun  8 00:54:57 darkstarssi ntpd[3186]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 00:54:57 darkstarssi ntpd[3186]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 00:54:57 darkstarssi ntpd[3186]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 00:54:57 darkstarssi ntpd[3186]: kernel time sync status 0040
Jun  8 01:15:02 darkstarssi ntpd[6133]: ntpd 4.2.2p3@1.1577-o Tue Aug  8 04:20:31 UTC 2006 (1)
Jun  8 01:15:02 darkstarssi ntpd[6134]: precision = 1.000 usec
Jun  8 01:15:02 darkstarssi ntpd[6134]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jun  8 01:15:02 darkstarssi ntpd[6134]: Listening on interface lo, 127.0.0.1#123 Enabled
Jun  8 01:15:02 darkstarssi ntpd[6134]: Listening on interface eth0, 192.168.123.188#123 Enabled
Jun  8 01:15:02 darkstarssi ntpd[6134]: kernel time sync status 0040
Jun  8 01:39:48 darkstarssi -- MARK --
Jun  8 01:42:21 darkstarssi kernel: device eth0 left promiscuous mode
Jun  8 01:59:48 darkstarssi -- MARK --
Jun  8 02:19:48 darkstarssi -- MARK --
Jun  8 02:39:48 darkstarssi -- MARK --

..and that is about all the ntp-related stuff I have in the logs.
Lines like:

Quote:

8 Jun 01:15:03 ntpd[6134]: peer 208.97.105.139 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)

are normal (I guess) as they have always read like this.

Cheers

Sasha

landonmkelsey · 06-14-2008, 11:44 AM

I dual boot XP Prof XP and Fedora 9 on my Dell desktop workstation.

Recently, both started giving bad times. I had always taken these for granted!

If I manually update using the dialog, sometimes I get an error!

I had even suspected that maybe there was a problem with the

motherboard facility I am told is actually contains a capacitor.