I updated the ntp config to write out a log file to /psp/ntp.log, and herein it gets interesting:
21 May 09:02:05 ntpd[19050]: logging to file /psp/ntp.log
21 May 09:02:05 ntpd[19050]: precision = 30.000 usec
21 May 09:02:05 ntpd[19050]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
21 May 09:02:05 ntpd[19050]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
21 May 09:02:05 ntpd[19050]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
21 May 09:02:05 ntpd[19050]: Listening on interface #2 rausb0, 192.168.1.187#123 Enabled
21 May 09:02:05 ntpd[19050]: kernel time sync status 0040
21 May 09:02:05 ntpd[19050]: frequency initialized 0.000 PPM from /psp/ntp.drift
21 May 09:02:05 ntpd[19050]: frequency initialized 0.000 PPM from /psp/ntp.drift
21 May 13:07:01 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 13:08:10 ntpd[19050]: synchronized to 204.2.134.164, stratum 2
21 May 13:13:29 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 13:13:29 ntpd[19050]: frequency error 1048 PPM exceeds tolerance 500 PPM
21 May 13:16:15 ntpd[19050]: synchronized to 204.2.134.164, stratum 2
21 May 13:16:15 ntpd[19050]: frequency error 1552 PPM exceeds tolerance 500 PPM
21 May 13:18:52 ntpd[19050]: no servers reachable
21 May 14:35:16 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 14:35:16 ntpd[19050]: frequency error 1754 PPM exceeds tolerance 500 PPM
21 May 14:40:14 ntpd[19050]: no servers reachable
21 May 14:58:35 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 14:58:35 ntpd[19050]: frequency error 1784 PPM exceeds tolerance 500 PPM
21 May 14:59:55 ntpd[19050]: no servers reachable
21 May 15:20:05 ntpd[19050]: synchronized to 129.250.35.251, stratum 2
21 May 15:20:05 ntpd[19050]: frequency error 1842 PPM exceeds tolerance 500 PPM
21 May 15:21:09 ntpd[19050]: frequency error 1844 PPM exceeds tolerance 500 PPM
21 May 15:22:14 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 15:23:36 ntpd[19050]: frequency error 879 PPM exceeds tolerance 500 PPM
21 May 15:24:42 ntpd[19050]: no servers reachable
21 May 17:05:47 ntpd[19050]: synchronized to 209.118.204.201, stratum 2
21 May 17:05:47 ntpd[19050]: frequency error 2141 PPM exceeds tolerance 500 PPM
21 May 17:09:03 ntpd[19050]: synchronized to 204.2.134.164, stratum 2
21 May 17:09:03 ntpd[19050]: frequency error 1782 PPM exceeds tolerance 500 PPM
21 May 17:10:44 ntpd[19050]: frequency error 2144 PPM exceeds tolerance 500 PPM
21 May 17:11:57 ntpd[19050]: synchronized to 198.60.22.240, stratum 1
21 May 17:11:57 ntpd[19050]: frequency error 2146 PPM exceeds tolerance 500 PPM
21 May 17:15:07 ntpd[19050]: no servers reachable
Note the timestamps! ntpd starts up, reads ntp.drift and then four hours later finally decides that it's found a clock to sync with, by which time the system clock has drifted so far that it's not actually willing to make the adjustment. Bizarre.
So let's run in debug mode?
chumby:/psp# ntpd -g -f /psp/ntp.drift -x -l /psp/ntp.log -d
ntpd 4.2.4p5@1.1541 Wed Feb 10 00:25:11 UTC 2010 (1)
addto_syslog: logging to file /psp/ntp.log
addto_syslog: logging to file /psp/ntp.log
addto_syslog: precision = 30.000 usec
addto_syslog: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
addto_syslog: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
addto_syslog: no IPv6 interfaces found
addto_syslog: no IPv6 interfaces found
addto_syslog: Listening on interface #1 lo, 127.0.0.1#123 Enabled
addto_syslog: Listening on interface #2 rausb0, 192.168.1.187#123 Enabled
local_clock: time 0 offset 0.000000 freq 0.000 state 0
addto_syslog: kernel time sync status 0040
addto_syslog: frequency initialized 500.000 PPM from /psp/ntp.drift
addto_syslog: frequency initialized 500.000 PPM from /psp/ntp.drift
peer_crypto_clear: at 0 next 0 assoc ID 41161
peer_clear: at 0 next 1 assoc ID 41161 refid INIT
newpeer: 192.168.1.187->204.235.61.9 mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
peer_crypto_clear: at 0 next 0 assoc ID 41162
peer_clear: at 0 next 2 assoc ID 41162 refid INIT
newpeer: 192.168.1.187->206.209.110.2 mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
peer_crypto_clear: at 0 next 0 assoc ID 41163
peer_clear: at 0 next 3 assoc ID 41163 refid INIT
newpeer: 192.168.1.187->198.55.111.5 mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
peer_crypto_clear: at 0 next 0 assoc ID 41164
peer_clear: at 0 next 4 assoc ID 41164 refid INIT
newpeer: 192.168.1.187->204.2.134.163 mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
local_clock: time 0 offset 0.000000 freq 500.000 state 1
report_event: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
transmit: at 1 192.168.1.187->204.235.61.9 mode 3
auth_agekeys: at 1 keys 1 expired 0
timer: interface update
addto_syslog: no IPv6 interfaces found
addto_syslog: no IPv6 interfaces found
receive: at 1 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
peer 204.235.61.9 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
clock_filter: n 1 off 5.118948 del 0.067689 dsp 7.937516 jit 0.000031, age 0
transmit: at 2 192.168.1.187->206.209.110.2 mode 3
receive: at 2 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
peer 206.209.110.2 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
clock_filter: n 1 off 5.148208 del 0.057118 dsp 7.937517 jit 0.000031, age 0
transmit: at 3 192.168.1.187->198.55.111.5 mode 3
receive: at 3 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
peer 198.55.111.5 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
clock_filter: n 1 off 5.170437 del 0.112604 dsp 7.937516 jit 0.000031, age 0
transmit: at 4 192.168.1.187->204.2.134.163 mode 3
receive: at 4 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
peer 204.2.134.163 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
clock_filter: n 1 off 5.204724 del 0.123038 dsp 7.937517 jit 0.000031, age 0
auth_agekeys: at 60 keys 1 expired 0
transmit: at 66 192.168.1.187->206.209.110.2 mode 3
receive: at 66 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
clock_filter: n 2 off 6.632560 del 0.044467 dsp 3.937765 jit 1.484352, age 0
transmit: at 67 192.168.1.187->204.235.61.9 mode 3
receive: at 67 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
clock_filter: n 2 off 6.649085 del 0.056454 dsp 3.937772 jit 1.530137, age 0
transmit: at 69 192.168.1.187->198.55.111.5 mode 3
receive: at 69 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
clock_filter: n 2 off 6.687666 del 0.107122 dsp 3.937772 jit 1.517229, age 0
transmit: at 70 192.168.1.187->204.2.134.163 mode 3
receive: at 70 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
clock_filter: n 2 off 6.734952 del 0.106801 dsp 3.937772 jit 1.530228, age 0
auth_agekeys: at 120 keys 1 expired 0
transmit: at 129 192.168.1.187->206.209.110.2 mode 3
receive: at 129 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
clock_filter: n 3 off 8.009031 del 0.077609 dsp 1.938004 jit 2.244881, age 0
transmit: at 132 192.168.1.187->204.235.61.9 mode 3
receive: at 132 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
clock_filter: n 3 off 8.082046 del 0.056280 dsp 1.938018 jit 2.327373, age 0
transmit: at 133 192.168.1.187->198.55.111.5 mode 3
transmit: at 133 192.168.1.187->204.2.134.163 mode 3
receive: at 133 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
clock_filter: n 3 off 8.119555 del 0.118584 dsp 1.938012 jit 2.318146, age 0
receive: at 133 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
clock_filter: n 3 off 8.120716 del 0.137090 dsp 1.938007 jit 2.282909, age 0
transmit: at 194 192.168.1.187->206.209.110.2 mode 3
receive: at 194 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
clock_filter: n 4 off 9.660483 del 0.087679 dsp 0.938195 jit 3.279037, age 0
transmit: at 197 192.168.1.187->204.2.134.163 mode 3
receive: at 197 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
clock_filter: n 4 off 9.770656 del 0.107652 dsp 0.938190 jit 3.305830, age 0
transmit: at 198 192.168.1.187->204.235.61.9 mode 3
receive: at 198 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
clock_filter: n 4 off 9.774090 del 0.038323 dsp 0.938208 jit 3.381273, age 0
transmit: at 199 192.168.1.187->198.55.111.5 mode 3
receive: at 199 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
clock_filter: n 4 off 9.801782 del 0.088111 dsp 0.938205 jit 3.365361, age 0
auth_agekeys: at 240 keys 1 expired 0
transmit: at 259 192.168.1.187->206.209.110.2 mode 3
receive: at 259 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
clock_filter: n 5 off 11.331488 del 0.067640 dsp 0.438321 jit 4.305341, age 0
transmit: at 262 192.168.1.187->204.2.134.163 mode 3
receive: at 262 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
clock_filter: n 5 off 11.426539 del 0.105108 dsp 0.438319 jit 4.312551, age 0
transmit: at 263 192.168.1.187->204.235.61.9 mode 3
receive: at 263 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
clock_filter: n 5 off 11.421503 del 0.063630 dsp 0.438327 jit 4.369329, age 0
transmit: at 265 192.168.1.187->198.55.111.5 mode 3
receive: at 265 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
clock_filter: n 5 off 11.492415 del 0.110222 dsp 0.438333 jit 4.395664, age 0
auth_agekeys: at 300 keys 1 expired 0
timer: interface update
addto_syslog: no IPv6 interfaces found
addto_syslog: no IPv6 interfaces found
transmit: at 324 192.168.1.187->206.209.110.2 mode 3
receive: at 324 192.168.1.187<-206.209.110.2 mode 4 code 1 auth 0
clock_filter: n 6 off 13.087355 del 0.055836 dsp 0.188400 jit 5.390925, age 0
transmit: at 327 192.168.1.187->204.235.61.9 mode 3
transmit: at 327 192.168.1.187->204.2.134.163 mode 3
receive: at 327 192.168.1.187<-204.235.61.9 mode 4 code 1 auth 0
clock_filter: n 6 off 13.121146 del 0.043954 dsp 0.188395 jit 5.392715, age 0
receive: at 327 192.168.1.187<-204.2.134.163 mode 4 code 1 auth 0
clock_filter: n 6 off 13.130597 del 0.101628 dsp 0.188398 jit 5.348189, age 0
transmit: at 328 192.168.1.187->198.55.111.5 mode 3
receive: at 328 192.168.1.187<-198.55.111.5 mode 4 code 1 auth 0
clock_filter: n 6 off 13.154256 del 0.084444 dsp 0.188390 jit 5.383440, age 0
Curiouser and curiouser! As I speculated, it sees some clocks but it doesn't actually sync with them and it keeps falling further and further behind. Why doesn't it sync? Well, here I'm kind of at the edge of my ntpd experience -- maybe we could send David Mills a few free Chumbys and see if he gets inspired?