Hello all,

I have a problem using ntpd as client.
I am using ntpd-4.2.4p4, cross-compiled for PPC and running on linux kernel 2.6.26.

The ntpd program is started through an init.d script with parameters:
/usr/bin/ntpd -- -g -l /var/log/ntpd.log -p /var/run/ntpd.pid -c /tmp/ntp.conf

/tmp/ntp.conf contains:
server x.x.x.x iburst
driftfile /tmp/ntp.drift

where x.x.x.x is the IP address of the NTP server.


The problem I have is the following:
On startup, ntpd communicates with the server and sets the system clock to the time, given by the ntp server.
From then on, ntpd periodically communicates with the ntp server, but it does not adjust the system clock any more.

When I execute "ntpq -p", I only see the offset going up (starting from 0), while ntpd still communicates with the ntp server.
Ntpd is processing the result, by it doesn't take action. (NTP communication is verified with wireshark and is present)

What could be the cause of this problem? The clock drift is about 1s every 94s meaning the clock is running about 15min late after only 1 day. I found on some forums you can get an error when the PPM exceeds the tolerance of 500 (something like: ntpd[3611]: frequency error -512 PPM exceeds tolerance 500 PPM), but I don't get this error: not in the logs, not in the console output when starting ntpd manually with debug logging.

I also tried to add the options
"tinker panic 0 huffpuff 7200" to /tmp/ntp.conf, but it had no effect.


If you need additional info, please ask.


kind regards,
Peter






The console output looks like:
------------------------------

$ /usr/bin/ntpd -g -l /var/log/ntpd.log -p /var/run/ntpd.pid -c /tmp/ntp.conf -ddd
ntpd 4.2.4p4@1.1520 Tue Jan 6 13:42:43 UTC 2009 (1)
addto_syslog: logging to file /var/log/ntpd.log
addto_syslog: logging to file /var/log/ntpd.log

addto_syslog: set_process_priority: Leave priority alone: priority_done is <2>

addto_syslog: precision = 1.594 usec

create_sockets(123)
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

update_interfaces(123)
addto_syslog: no IPv6 interfaces found

addto_syslog: no IPv6 interfaces found

create_interface(127.0.0.1#123)
addto_syslog: Listening on interface #1 lo, 127.0.0.1#123 Enabled

created interface #1: fd=17, bfd=-1, name=lo, flags=0x5, scope=0, ifindex=0, sin=127.0.0.1, mask=255.0.0.0, Enabled:
updating interface #1: fd=17, bfd=-1, name=lo, flags=0x5, scope=0, ifindex=0, sin=127.0.0.1, mask=255.0.0.0, Enabled: new - created
create_interface(10.2.7.107#123)
addto_syslog: Listening on interface #2 bond0, 10.2.7.107#123 Enabled

created interface #2: fd=18, bfd=-1, name=bond0, flags=0x19, scope=0, ifindex=0, sin=10.2.7.107, bcast=10.255.255.255,, mask=255.0.0.0, Enabled:
updating interface #2: fd=18, bfd=-1, name=bond0, flags=0x19, scope=0, ifindex=0, sin=10.2.7.107, bcast=10.255.255.255,, mask=255.0.0.0, Enabled: new - created
create_sockets: Total interfaces = 3
init_io: maxactivefd 18
local_clock: time 0 offset 0.000000 freq 0.000 state 0
addto_syslog: kernel time sync status 0040

getnetnum given 150.158.252.51, got 150.158.252.51 (t_UNK/0)
newpeer: cast flags: 0x1 for address: 150.158.252.51
newpeer: using fd 18 and our addr 10.2.7.107
peer_crypto_clear: at 0 next 0 assoc ID 44998
peer_clear: at 0 next 1 assoc ID 44998 refid INIT
newpeer: 10.2.7.107->150.158.252.51 mode 3 vers 4 poll 6 10 flags 0x201 0x1 ttl 0 key 00000000
addto_syslog: frequency initialized 0.000 PPM from /tmp/ntp.drift

authtrust: keyid 0000ffff life 1
local_clock: time 0 offset 0.000000 freq 0.000 state 1
report_event: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 1 10.2.7.107->150.158.252.51 mode 3
poll_update: at 1 150.158.252.51 flags 0201 poll 6 burst 8 last 1 next 3
auth_agekeys: at 1 keys 1 expired 0
timer: interface update
update_interfaces(123)
addto_syslog: no IPv6 interfaces found

addto_syslog: no IPv6 interfaces found

read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 1 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 1 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
peer 150.158.252.51 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
clock_filter: n 1 off 0.558707 del 0.019843 dsp 7.945314 jit 0.000002, age 0
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 3 10.2.7.107->150.158.252.51 mode 3
poll_update: at 3 150.158.252.51 flags 0201 poll 6 burst 7 last 1 next 5
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 3 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 3 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
clock_filter: n 2 off 0.591149 del 0.017631 dsp 3.949228 jit 0.032442, age 0
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 5 10.2.7.107->150.158.252.51 mode 3
poll_update: at 5 150.158.252.51 flags 0201 poll 6 burst 6 last 1 next 7
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 5 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 5 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
clock_filter: n 3 off 0.588471 del 0.023052 dsp 1.951189 jit 0.021131, age 0
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 7 10.2.7.107->150.158.252.51 mode 3
poll_update: at 7 150.158.252.51 flags 0201 poll 6 burst 5 last 1 next 9
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 7 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 7 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
clock_filter: n 4 off 0.630746 del 0.001045 dsp 0.952171 jit 0.053369, age 0
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 9 10.2.7.107->150.158.252.51 mode 3
poll_update: at 9 150.158.252.51 flags 0201 poll 6 burst 4 last 1 next 11
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 9 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 9 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
clock_filter: n 5 off 0.645035 del 0.003762 dsp 0.452663 jit 0.058651, age 0
select: endpoint -1 -0.107899
select: endpoint 0 0.645035
select: endpoint 1 1.397968
cluster: survivor 150.158.252.51 metric 2.752934
select: combine offset 0.645035
report_event: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_ntp, 2 events, event_restart' (0xc621)
addto_syslog: synchronized to 150.158.252.51, stratum 2

clock_update: at 9 assoc 1
local_clock: assocID 44998 offset 0.645034806 freq 0.000 state 1
step_systime: step 0.645035 residual 0.000000
In ntp_set_tod
ntp_set_tod: clock_settime: 0: Success
ntp_set_tod: Final result: clock_settime: 0: Success
addto_syslog: time reset +0.645035 s

local_clock: time 9 offset 0.000000 freq 0.000 state 4
addto_syslog: kernel time sync status change 0001

local_clock: mu 9 jitr 0.000002 freq 0.000 stab 0.000000 poll 4 count 4
peer_crypto_clear: at 9 next 11 assoc ID 44998
peer_clear: at 9 next 10 assoc ID 44998 refid STEP
clear_all: at 9
report_event: system event 'event_clock_reset' (0x05) status 'sync_alarm, sync_unspec, 3 events, event_peer/strat_chg' (0xc034)
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 10 10.2.7.107->150.158.252.51 mode 3
poll_update: at 10 150.158.252.51 flags 0241 poll 6 burst 0 last 10 next 75
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 10 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 10 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
peer 150.158.252.51 event 'event_reach' (0x84) status 'unreach, conf, 2 events, event_reach' (0x8024)
poll_update: at 10 150.158.252.51 flags 0241 poll 6 burst 0 last 10 next 75
clock_filter: n 1 off 0.009529 del 0.016091 dsp 7.945314 jit 0.000002, age 0
read_network_packet: fd=17 length 12 from 7f000001 127.0.0.1
receive: at 31 127.0.0.1<-127.0.0.1 flags 5 restrict 000
in process_control()
opcode 1, found command handler
read_status: ID 0
sendpkt(fd=17 dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=16)
read_network_packet: fd=17 length 12 from 7f000001 127.0.0.1
receive: at 31 127.0.0.1<-127.0.0.1 flags 5 restrict 000
in process_control()
opcode 2, found command handler
sendpkt(fd=17 dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=440)
sendpkt(fd=17 dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=200)
auth_agekeys: at 60 keys 1 expired 0
sendpkt(fd=18 dst=150.158.252.51, src=10.2.7.107, ttl=0, len=48)
transmit: at 75 10.2.7.107->150.158.252.51 mode 3
poll_update: at 75 150.158.252.51 flags 0201 poll 6 burst 0 last 75 next 138
read_network_packet: fd=18 length 48 from 969efc33 150.158.252.51
receive: at 75 10.2.7.107<-150.158.252.51 flags 19 restrict 000
receive: at 75 10.2.7.107<-150.158.252.51 mode 4 code 1 auth 0
poll_update: at 75 150.158.252.51 flags 0201 poll 6 burst 0 last 75 next 139
clock_filter: discard 0
auth_agekeys: at 120 keys 1 expired 0


the log file contain:
---------------------

$ cat /tmp/ntpd.log
1 Jan 03:01:35 ntpd[360]: logging to file /var/log/ntpd.log
1 Jan 03:01:35 ntpd[360]: precision = 1.526 usec
1 Jan 03:01:35 ntpd[360]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
1 Jan 03:01:35 ntpd[360]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
1 Jan 03:01:35 ntpd[360]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
1 Jan 03:01:35 ntpd[360]: Listening on interface #2 bond0, 10.2.7.107#123 Enabled
1 Jan 03:01:35 ntpd[360]: kernel time sync status 0040
1 Jan 03:01:35 ntpd[360]: getconfig: Couldn't open </tmp/ntp.conf>
1 Jan 03:01:38 ntpd[360]: ntpd exiting on signal 15
1 Jan 03:01:38 ntpd[454]: logging to file /var/log/ntpd.log
1 Jan 03:01:38 ntpd[454]: precision = 1.560 usec
1 Jan 03:01:38 ntpd[454]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
1 Jan 03:01:38 ntpd[454]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
1 Jan 03:01:38 ntpd[454]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
1 Jan 03:01:38 ntpd[454]: Listening on interface #2 bond0, 10.2.7.107#123 Enabled
1 Jan 03:01:38 ntpd[454]: kernel time sync status 0040
1 Jan 03:01:47 ntpd[454]: synchronized to 150.158.252.51, stratum 2
6 Jan 16:10:14 ntpd[454]: time reset +1231247306.334839 s
7 Jan 08:29:00 ntpd[454]: ntpd exiting on signal 15
7 Jan 08:29:20 ntpd[4265]: logging to file /var/log/ntpd.log
7 Jan 08:29:20 ntpd[4265]: precision = 1.560 usec
7 Jan 08:29:20 ntpd[4265]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
7 Jan 08:29:20 ntpd[4265]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
7 Jan 08:29:20 ntpd[4265]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
7 Jan 08:29:20 ntpd[4265]: Listening on interface #2 bond0, 10.2.7.107#123 Enabled
7 Jan 08:29:20 ntpd[4265]: kernel time sync status 0040
7 Jan 08:29:20 ntpd[4265]: frequency initialized 0.000 PPM from /tmp/ntp.drift
7 Jan 08:29:29 ntpd[4265]: synchronized to 150.158.252.51, stratum 2
7 Jan 08:39:22 ntpd[4265]: time reset +593.323346 s
7 Jan 08:39:22 ntpd[4265]: kernel time sync status change 0001
7 Jan 08:39:26 ntpd[4265]: ntpd exiting on signal 15
7 Jan 08:39:30 ntpd[4287]: logging to file /var/log/ntpd.log
7 Jan 08:39:30 ntpd[4287]: precision = 1.594 usec
7 Jan 08:39:30 ntpd[4287]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
7 Jan 08:39:30 ntpd[4287]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
7 Jan 08:39:30 ntpd[4287]: no IPv6 interfaces found
7 Jan 08:39:30 ntpd[4287]: no IPv6 interfaces found
7 Jan 08:39:30 ntpd[4287]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
7 Jan 08:39:30 ntpd[4287]: Listening on interface #2 bond0, 10.2.7.107#123 Enabled
7 Jan 08:39:30 ntpd[4287]: kernel time sync status 0040
7 Jan 08:39:30 ntpd[4287]: frequency initialized 0.000 PPM from /tmp/ntp.drift
7 Jan 08:39:31 ntpd[4287]: no IPv6 interfaces found
7 Jan 08:39:31 ntpd[4287]: no IPv6 interfaces found
7 Jan 08:39:35 ntpd[4287]: ntpd exiting on signal 2
7 Jan 08:39:47 ntpd[4305]: logging to file /var/log/ntpd.log
7 Jan 08:39:47 ntpd[4305]: set_process_priority: Leave priority alone: priority_done is <2>
7 Jan 08:39:47 ntpd[4305]: precision = 1.560 usec
7 Jan 08:39:47 ntpd[4305]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
7 Jan 08:39:47 ntpd[4305]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
7 Jan 08:39:47 ntpd[4305]: no IPv6 interfaces found
7 Jan 08:39:47 ntpd[4305]: no IPv6 interfaces found
7 Jan 08:39:47 ntpd[4305]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
7 Jan 08:39:47 ntpd[4305]: Listening on interface #2 bond0, 10.2.7.107#123 Enabled
7 Jan 08:39:47 ntpd[4305]: kernel time sync status 0040
7 Jan 08:39:47 ntpd[4305]: frequency initialized 0.000 PPM from /tmp/ntp.drift
7 Jan 08:39:48 ntpd[4305]: no IPv6 interfaces found
7 Jan 08:39:48 ntpd[4305]: no IPv6 interfaces found

NOTE: the "ntpd exiting on signal 15" msg is due the fact that at startup, no config file is present, when the file is created (from saved settings in flash), the ntpd is restarted by "/etc/init.d/ntp restart"


the config file contains:
-------------------------

# cat /tmp/ntp.conf
server 150.158.252.51 iburst
driftfile /tmp/ntp.drift


the output of ntpq:
-------------------

# ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
150.158.252.51 192.43.244.18 2 u 22 64 1 16.091 9.529 0.002

Hello all,

Updating u-boot to a newer version solved the problem :-)


kind regards,
Peter