[ntp:questions] dcf77 time synchronization problem

Wolfgang.Hennerbichler at ooe.gv.at Wolfgang.Hennerbichler at ooe.gv.at
Fri Aug 6 09:38:54 UTC 2010


Hi ntpd folk, 

This will be a long email, I hope somebody is able to help. In short: My
dcf77 doesn't work very well and I don't know exactly why. 
The long version: 
The dcf77 is connected via serial console to the HP DL380. My
ntp-configuration is as follows: 

driftfile /var/lib/ntp/ntp.drift
logconfig all
statsdir /var/log/ntpstats/
statistics loopstats peerstats clockstats
filegen loopstats file loopstats type day enable
filegen peerstats file peerstats type day enable
filegen clockstats file clockstats type day enable
server 127.127.8.0 mode 2 prefer
server tslirz01.ooe.local
server ts1.univie.ac.at
server ts2.univie.ac.at
server tt73.ripe.net
restrict -4 default kod notrap nomodify nopeer noquery
restrict -6 default kod notrap nomodify nopeer noquery
restrict 127.0.0.1
restrict ::1

so far so good, ntpd starts up, the dcf77 is the primary time source of
time:

Aug  6 09:51:36 tslilh01 ntpd[1471]: kernel time sync status 2040
Aug  6 09:51:36 tslilh01 ntpd[1471]: frequency initialized -12.758 PPM
from /var/lib/ntp/ntp.drift
Aug  6 09:51:36 tslilh01 ntpd[1471]: NTP PARSE support: Copyright (c)
1989-2006, Frank Kardel
Aug  6 09:51:36 tslilh01 ntpd[1471]: PARSE receiver #0: reference clock
"Meinberg DCF77 C51 or compatible" (I/O device /
dev/refclock-0, PPS device /dev/refclock-0) added
Aug  6 09:51:36 tslilh01 ntpd[1471]: PARSE receiver #0: Stratum 0, trust
time 00:30:00, precision -20
Aug  6 09:51:36 tslilh01 ntpd[1471]: PARSE receiver #0: rootdelay
0.000000 s, phase adjustment 0.010000 s, PPS phase adj
ustment 0.000000 s, normal IO handling
Aug  6 09:51:36 tslilh01 ntpd[1471]: PARSE receiver #0: Format
recognition: Meinberg Standard
Aug  6 09:51:36 tslilh01 ntpd[1471]: PARSE receiver #0: NO PPS support
Aug  6 09:51:36 tslilh01 ntpd[1471]: system event 'event_restart' (0x01)
status 'sync_alarm, sync_unspec, 1 event, event
_unspec' (0xc010)
Aug  6 09:51:37 tslilh01 ntpd[1471]: PARSE receiver #0: packet format
"Meinberg Standard"
Aug  6 09:51:37 tslilh01 ntpd[1471]: PARSE receiver #0: STATE CHANGE:
-> DST; TIME CODE; (LEAP INDICATION)
Aug  6 09:51:37 tslilh01 ntpd[1471]: peer GENERIC(0) event 'event_reach'
(0x84) status 'unreach, conf, 1 event, event_re
ach' (0x8014)
Aug  6 09:51:38 tslilh01 ntpd[1471]: peer 10.254.254.110 event
'event_reach' (0x84) status 'unreach, conf, 1 event, even
t_reach' (0x8014)
Aug  6 09:51:39 tslilh01 ntpd[1471]: peer 131.130.250.250 event
'event_reach' (0x84) status 'unreach, conf, 1 event, eve
nt_reach' (0x8014)
Aug  6 09:51:40 tslilh01 ntpd[1471]: system event 'event_peer/strat_chg'
(0x04) status 'sync_alarm, sync_lf_clock, 2 eve
nts, event_restart' (0xc221)
Aug  6 09:51:40 tslilh01 ntpd[1471]: synchronized to GENERIC(0), stratum
0
Aug  6 09:51:40 tslilh01 ntpd[1471]: kernel time sync status change 2001
Aug  6 09:51:40 tslilh01 ntpd[1471]: system event 'event_sync_chg'
(0x03) status 'leap_none, sync_lf_clock, 3 events, event_peer/strat_chg'
(0x234)
Aug  6 09:51:40 tslilh01 ntpd[1471]: system event 'event_peer/strat_chg'
(0x04) status 'leap_none, sync_lf_clock, 4 events, event_sync_chg'
(0x243)
Aug  6 09:51:40 tslilh01 ntpd[1471]: peer 193.171.23.164 event
'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach'
(0x8014)
Aug  6 09:51:41 tslilh01 ntpd[1471]: peer 193.171.23.106 event
'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach'
(0x8014)


After some time I can find this in the logs: 
Aug  6 09:52:01 tslilh01 ntpd[1471]: PARSE receiver #0: STATE CHANGE:
DST; TIME CODE; (LEAP INDICATION) -> TIME CODE NOT CONFIRMED; DST; TIME
CODE; (LEAP INDICATION)
Aug  6 09:52:01 tslilh01 ntpd[1471]: clock GENERIC(0) event
'clk_badsignal' (0x04)
Aug  6 09:52:01 tslilh01 ntpd[1471]: peer GENERIC(0) event
'event_peer_clock' (0x85) status 'reach, conf, sel_sys.peer, 2 events,
event_peer_clock' (0x9625)
Aug  6 09:52:01 tslilh01 ntpd[1471]: PARSE receiver #0: interval for
following error message class is at least 00:01:00
Aug  6 09:52:01 tslilh01 ntpd[1471]: PARSE receiver #0: TIMECODE NOT
CONFIRMED

so the signal is bad? which signal - the serial console signal or the
signal of the antenna of the dcf77 on the top of the building?
Nevertheless the dcf77 is still the primary time source, and ist seems
it comes back to life again:

Aug  6 09:53:01 tslilh01 ntpd[1471]: PARSE receiver #0: 59 messages
where suppressed, error condition class persists for 00:01:00
Aug  6 09:53:01 tslilh01 ntpd[1471]: PARSE receiver #0: TIMECODE NOT
CONFIRMED
Aug  6 09:54:01 tslilh01 ntpd[1471]: PARSE receiver #0: 59 messages
where suppressed, error condition class persists for 00:02:00
Aug  6 09:54:01 tslilh01 ntpd[1471]: PARSE receiver #0: TIMECODE NOT
CONFIRMED
Aug  6 09:55:00 tslilh01 ntpd[1471]: PARSE receiver #0: STATE CHANGE:
TIME CODE NOT CONFIRMED; DST; TIME CODE; (LEAP INDICATION) -> DST; TIME
CODE; (LEAP INDICATION)
Aug  6 09:55:00 tslilh01 ntpd[1471]: PARSE receiver #0: SYNCHRONIZED
Aug  6 09:55:00 tslilh01 ntpd[1471]: clock GENERIC(0) event 'clk_okay'
(0x00)
Aug  6 09:55:00 tslilh01 ntpd[1471]: peer GENERIC(0) event
'event_peer_clock' (0x85) status 'reach, conf, sel_sys.peer, 3 events,
event_peer_clock' (0x9635)

An then, 5 minutes later, ntpd switches to another time source (a
stratum 1 ntp server) - without any prior notice:
Aug  6 10:01:37 tslilh01 ntpd[1471]: synchronized to 131.130.250.250,
stratum 1

I don't get why this happens, the metric of the dcf77 is close to 0
(whereas the other network-servers are around 1) just before that
happens. In debug-mode I can really not get what's going on: 

PARSE receiver #0: refclock_process_offset(reftime=d0063cba.00000000
Fri, Aug  6 2010  9:48:10.000, rectime=d0063cba.03
bf922a  Fri, Aug  6 2010  9:48:10.014, Fudge=0.010000)
refclock_transmit: at 838 127.127.8.0
poll_update: at 838 127.127.8.0 flags 10e1 poll 6 burst 0 last 838 next
904
PARSE receiver #0: status 000004, state 10010022, time(fp)
d0063cbb.00000000, stime(fp) d0063cbb.03bfa2ab, ptime(fp) 0.00000000
PARSE receiver #0: Reftime d0063cbb.00000000  Fri, Aug  6 2010
9:48:11.000, Recvtime d0063cbb.03bfa2ab  Fri, Aug  6 2010  9:48:11.014 -
initial offset -0.014643
PARSE receiver #0: Reftime d0063cbb.00000000  Fri, Aug  6 2010
9:48:11.000, Recvtime d0063cbb.03bfa2ab  Fri, Aug  6 2010  9:48:11.014 -
final offset -0.014643
PARSE receiver #0: calculated Reftime d0063cbb.00000000  Fri, Aug  6
2010  9:48:11.000, Recvtime d0063cbb.03bfa2ab  Fri, Aug  6 2010
9:48:11.014
PARSE receiver #0: refclock_process_offset(reftime=d0063cbb.00000000
Fri, Aug  6 2010  9:48:11.000, rectime=d0063cbb.03bfa2ab  Fri, Aug  6
2010  9:48:11.014, Fudge=0.010000)
refclock_receive: at 838 127.127.8.0
refclock_sample: n 59 offset -0.004642 disp 0.000000 jitter 0.000001
clock_filter: n 8 off -0.004642 del 0.000000 dsp 0.000976 jit 0.007485,
age 0
select: endpoint -1 -0.032722
select: endpoint -1 -0.015602
select: endpoint  0 -0.004642
select: endpoint  0 -0.002582
select: endpoint -1 -0.001673
select: endpoint -1 -0.001387
select: endpoint -1 0.002832
select: endpoint  1 0.006319
select: endpoint  0 0.021580
select: endpoint  0 0.021696
select: endpoint  1 0.027559
select: endpoint  0 0.029549
select: endpoint  1 0.044779
select: endpoint  1 0.044834
select: endpoint  1 0.056267
cluster: survivor 131.130.250.250 metric 1.023083
cluster: survivor 193.171.23.164 metric 1.023254
cluster: survivor 193.171.23.106 metric 1.026718
select: combine offset 0.024031
addto_syslog: synchronized to 131.130.250.250, stratum 1

Furthermore, after some even more time I do get this in the logs: 
offset -0.032644 sec freq -11.499 ppm error 0.008115 poll 10

If I restart the ntpd, the dcf77 becomes the main time source
immediately. 
And with ntpq I see the following different outputs typing cv: 

=> broken state. 
assID=0 status=0404 clk_badsignal, last_clk_badsignal,
device="Meinberg DCF77 C51 or compatible",
timecode="\x02D:06.08.10;T:5;U:09.49.03; *S \x03", poll=14, noreply=0,
badformat=0, baddata=0, fudgetime1=10.000, stratum=0, refid=DCFa,
flags=0,

=> working state.
assID=0 status=0004 clk_okay, last_clk_badsignal,
device="Meinberg DCF77 C51 or compatible",
timecode="\x02D:06.08.10;T:5;U:09.57.48;  S \x03", poll=6, noreply=0,
badformat=0, baddata=0, fudgetime1=10.000, stratum=0, refid=DCFa,
flags=0,

I can't really figure out what my problem is, maybe somebody could shed
some light. Sorry for the excessive debug messages, but I'm really
hoping somebody can help. Thanks for any hints, 

Wolfgang



More information about the questions mailing list