ntpd -d output for clock problem

JP Vossen vossenjp at netaxs.com
Mon Jan 6 18:59:00 CST 2003


Hi,

I've posted a couple of messages about my PE500SC clock going nuts every
Monday AM during/after my backup job.  I finally remembered to run ntpd -d to
see if that gives anything useful.  Perhaps I'm dense (actually, many would
argue that's a proven fact :-) but I don't see anything all that illuminating
here.

The pertinent (as far as I can tell) part of the log is below.  Sorry about
the length-and this is with almost 6K lines deleted.  Likewise, my ntp.conf is
excerpted at bottom.

The backup job itself is afio (with a gzip -9 in there) with a bunch of really
ugly shell script wrapped around it
(http://www.jpsdomain.org/linux/OnStream_DI-30-RedHat_Backup_mini-HOWTO.html
site is out-of-date a bit).  It's running on an IDE OnStream DI-30 drive on
hdd.  hdc is an IDE CD-ROM.  The IDE interface is the generic built-in one on
the PE500SC.  The crontab is "30 4 * * Mon /opt/jpbackup/jpbackup" and nothing
else interesting runs at that time, for obvious reasons.


Any thoughts or help are much appreciated,
JP



Add -d flag to /etc/sysconfig/ntpd and /etc/rc.d/init.d/ntpd restart.  Restart
process "hangs" as discussed in this list a couple of weeks ago.  I just left
it.  "Myserver" is the server name xxx.xxx.xxx.11 is the IP address (OK, so
I'm paranoid-I'm a security guy, I'm supposed to be).

Not that it matters, but TZ is EST5EDT.

Jan 5 18:16:10 myserver ntpd[17117]: ntpd exiting on signal 15
Jan 5 18:16:10 myserver ntpd: ntpd shutdown succeeded
Jan 5 18:16:37 myserver ntpdate[28210]: step time server 192.5.41.41 offset
-0.005583 sec
Jan 5 18:16:37 myserver ntpd:  succeeded
Jan 5 18:16:37 myserver ntpd[28213]: ntpd 4.1.1a at 1.791 Sat Aug 31 18:27:29 EDT
2002 (1)
Jan 5 18:16:37 myserver ntpd[28213]: precision = 9 usec
Jan 5 18:16:37 myserver ntpd: create_sockets(123)
Jan 5 18:16:37 myserver ntpd[28213]: kernel time discipline status 0040
Jan 5 18:16:37 myserver ntpd[28213]: frequency initialized -18.689 from
/etc/ntp/drift
Jan 5 18:16:37 myserver ntpd: interface <lo> OK
Jan 5 18:16:37 myserver ntpd: interface <eth0> OK
Jan 5 18:16:37 myserver ntpd: bind() fd 4, family 2, port 123, addr 0.0.0.0,
flags=1
Jan 5 18:16:37 myserver ntpd: bind() fd 5, family 2, port 123, addr 127.0.0.1,
flags=0
Jan 5 18:16:37 myserver ntpd: bind() fd 6, family 2, port 123, addr
xxx.xxx.xxx.11, flags=1
Jan 5 18:16:37 myserver ntpd: init_io: maxactivefd 6
Jan 5 18:16:38 myserver ntpd: peer_clear: at 0 assoc ID 0
Jan 5 18:16:38 myserver ntpd: newpeer: xxx.xxx.xxx.11->192.5.41.40 mode 3 vers
4 poll 6 10 flags 1 1 ttl 0 key 00000000
Jan 5 18:16:38 myserver ntpd: peer_clear: at 0 assoc ID 0
Jan 5 18:16:38 myserver ntpd: newpeer: xxx.xxx.xxx.11->192.5.41.41 mode 3 vers
4 poll 6 10 flags 1 1 ttl 0 key 00000000
Jan 5 18:16:38 myserver ntpd: peer_clear: at 0 assoc ID 0
Jan 5 18:16:38 myserver ntpd: newpeer: xxx.xxx.xxx.11->128.118.25.3 mode 3
vers 4 poll 6 10 flags 1 1 ttl 0 key 00000000
Jan 5 18:16:38 myserver ntpd: peer_clear: at 0 assoc ID 0
Jan 5 18:16:38 myserver ntpd: newpeer: 127.0.0.1->127.127.1.0 mode 3 vers 4
poll 6 6 flags 21 1 ttl 0 key 00000000
Jan 5 18:16:38 myserver ntpd: report_event: system event 'event_restart'
(0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
Jan 5 18:16:38 myserver ntpd: auth_agekeys: at 1 keys 1 expired 0
Jan 5 18:16:45 myserver ntpd: transmit: at 8 xxx.xxx.xxx.11->128.118.25.3 mode
3
Jan 5 18:16:45 myserver ntpd: receive: at 8 xxx.xxx.xxx.11<-128.118.25.3 mode
4 code 1
Jan 5 18:16:45 myserver ntpd: peer 128.118.25.3 event 'event_reach' (0x84)
status 'unreach, conf, 1 event, event_reach' (0x8014)
Jan 5 18:16:45 myserver ntpd: clock_filter: n 1 off 0.015650 del 0.031959 dsp
7.937511 jit 0.000008, age 0
Jan 5 18:16:49 myserver ntpd: transmit: at 12 xxx.xxx.xxx.11->192.5.41.41 mode
3
Jan 5 18:16:49 myserver ntpd: receive: at 12 xxx.xxx.xxx.11<-192.5.41.41 mode
4 code 1
Jan 5 18:16:49 myserver ntpd: peer 192.5.41.41 event 'event_reach' (0x84)
status 'unreach, conf, 1 event, event_reach' (0x8014)
Jan 5 18:16:49 myserver ntpd: clock_filter: n 1 off 0.000515 del 0.057903 dsp
7.937508 jit 0.000008, age 0
Jan 5 18:16:50 myserver ntpd: refclock_transmit: at 13 127.127.1.0
Jan 5 18:16:50 myserver ntpd: refclock_receive: at 13 127.127.1.0
Jan 5 18:16:50 myserver ntpd: peer LOCAL(0) event 'event_reach' (0x84) status
'unreach, conf, 1 event, event_reach' (0x8014)
Jan 5 18:16:50 myserver ntpd: refclock_sample: n 1 offset 0.000000 disp
0.010000 jitter 0.000000
Jan 5 18:16:50 myserver ntpd: clock_filter: n 1 off 0.000000 del 0.000000 dsp
7.937508 jit 0.000008, age 0
Jan 5 18:16:52 myserver ntpd: transmit: at 15 xxx.xxx.xxx.11->192.5.41.40 mode
3
Jan 5 18:16:52 myserver ntpd: receive: at 15 xxx.xxx.xxx.11<-192.5.41.40 mode
4 code 1
Jan 5 18:16:52 myserver ntpd: peer 192.5.41.40 event 'event_reach' (0x84)
status 'unreach, conf, 1 event, event_reach' (0x8014)
Jan 5 18:16:52 myserver ntpd: clock_filter: n 1 off -0.000269 del 0.057509 dsp
7.937508 jit 0.000008, age 0
Jan 5 18:17:37 myserver ntpd: auth_agekeys: at 60 keys 1 expired 0
Jan 5 18:17:50 myserver ntpd: transmit: at 73 xxx.xxx.xxx.11->128.118.25.3
mode 3
Jan 5 18:17:50 myserver ntpd: receive: at 73 xxx.xxx.xxx.11<-128.118.25.3 mode
4 code 1
Jan 5 18:17:50 myserver ntpd: clock_filter: n 2 off 0.015231 del 0.031680 dsp
3.937761 jit 0.000419, age 0

<snip 5702 lines of debug logs>

Jan 6 06:59:43 myserver ntpd: clock_update: at 45788 assoc 4
Jan 6 06:59:43 myserver ntpd: local_clock: assocID 4663 off 0.000000 jit
0.000011 sta 4
Jan 6 06:59:43 myserver ntpd: local_clock: mu 66 noi 18.448 stb 0.000 pol 6
cnt 30
Jan 6 06:59:43 myserver ntpd: transmit: at 45788 xxx.xxx.xxx.11->128.118.25.3
mode 3
Jan 6 06:59:43 myserver ntpd: receive: at 45788 xxx.xxx.xxx.11<-128.118.25.3
mode 4 code 1
Jan 6 06:59:43 myserver ntpd: clock_filter: n 2 off 2048.718065 del 0.033943
dsp 0.000963 jit 16.248850, age 0
Jan 6 06:59:53 myserver ntpd: transmit: at 45798 xxx.xxx.xxx.11->192.5.41.41
mode 3
Jan 6 06:59:53 myserver ntpd: receive: at 45798 xxx.xxx.xxx.11<-192.5.41.41
mode 4 code 1
Jan 6 06:59:53 myserver ntpd: clock_filter: n 2 off 2048.696811 del 0.056495
dsp 0.000954 jit 12.552438, age 0
Jan 6 07:00:13 myserver ntpd: transmit: at 45818 xxx.xxx.xxx.11->192.5.41.40
mode 3
Jan 6 07:00:13 myserver ntpd: receive: at 45818 xxx.xxx.xxx.11<-192.5.41.40
mode 4 code 1
Jan 6 07:00:13 myserver ntpd: clock_filter: n 2 off 2048.697788 del 0.056675
dsp 0.000950 jit 4.701204, age 0
Jan 6 07:00:35 myserver ntpd: auth_agekeys: at 45840 keys 1 expired 0
Jan 6 07:00:47 myserver ntpd: transmit: at 45852 xxx.xxx.xxx.11->128.118.25.3
mode 3

OK, and we're dead now...  Log files for backup time stamped as:
	Jan  6 06:59 	catalog
	Jan  6 07:00	afio log
	Jan  6 07:09	my log

Jan 6 07:00:47 myserver ntpd[28213]: time correction of 2049 seconds exceeds
sanity limit (1000); set clock manually to the correct UTC time.
Jan 6 07:00:47 myserver ntpd: receive: at 45852 xxx.xxx.xxx.11<-128.118.25.3
mode 4 code 1
Jan 6 07:00:47 myserver ntpd: clock_filter: n 2 off 2048.716344 del 0.031148
dsp 0.000956 jit 0.001720, age 0
Jan 6 07:00:47 myserver ntpd: clock_update: at 45852 assoc 4
Jan 6 07:00:47 myserver ntpd: local_clock: assocID 4662 off 2048.716344 jit
0.001721 sta 4
Jan 6 07:00:47 myserver ntpd: report_event: system event 'event_fault' (0x02)
status 'leap_none, sync_ntp, 15 events, event_peer/strat_chg' (0x6f4)
Jan 6 07:00:47 myserver ntpd: ntpd startup failed

At this point, I removed the -d flag from /etc/sysconfig/ntpd and
/etc/rc.d/init.d/ntpd restart

Jan 6 11:30:44 myserver ntpdate[11375]: step time server 192.5.41.40 offset
2048.638265 sec
Jan 6 11:30:44 myserver ntpd:  succeeded
Jan 6 11:30:44 myserver ntpd[11379]: ntpd 4.1.1a at 1.791 Sat Aug 31 18:27:29 EDT
2002 (1)
Jan 6 11:30:44 myserver ntpd: ntpd startup succeeded
Jan 6 11:30:44 myserver ntpd[11379]: precision = 8 usec
Jan 6 11:30:44 myserver ntpd[11379]: kernel time discipline status 0040
Jan 6 11:30:44 myserver ntpd[11379]: frequency initialized -14.871 from
/etc/ntp/drift
Jan 6 11:33:56 myserver ntpd[11379]: kernel time discipline status change 41




Excerpts from /etc/ntp.conf

# Prohibit general access to this service.
restrict default ignore

# Permit all access over the loopback interface.
restrict 127.0.0.1


# -- CLIENT NETWORK -------
restrict xxx.xxx.xxx.0 mask 255.255.255.0 notrust nomodify notrap


# --- OUR TIMESERVERS -----

# tick.usno.navy.mil
restrict 192.5.41.40  mask 255.255.255.255 nomodify notrap noquery
server 192.5.41.40

# tock.usno.navy.mil
restrict 192.5.41.41  mask 255.255.255.255 nomodify notrap noquery
server 192.5.41.41

# clock.psu.edu
restrict 128.118.25.3 mask 255.255.255.255 nomodify notrap noquery
server 128.118.25.3


# --- GENERAL CONFIGURATION ---
#
# Undisciplined Local Clock. This is a fake driver intended for backup...
server	127.127.1.0	# local clock
fudge	127.127.1.0 stratum 10

driftfile /etc/ntp/drift
broadcastdelay	0.008

authenticate no


------------------------------|:::======|--------------------------------
JP Vossen, CISSP              |:::======|                jp at jpsdomain.org
My Account, My Opinions       |=========|       http://www.jpsdomain.org/
------------------------------|=========|--------------------------------
"The software said it requires Windows 98 or better, so I installed
Linux..."




More information about the Linux-PowerEdge mailing list