<html><head><style type="text/css"><!-- DIV {margin:0px;} --></style></head><body><div style="font-family:lucida console,sans-serif;font-size:10pt"><div>Subject: Race condition between ntp and NetworkManager at entry to runlevel 2<br>Package: ntp<br>Version: 1:4.2.4p4+dfsg-8lenny3<br>Severity: important<br><br>*** Please type your report below this line ***<br>Related bug: 535049<br>Symptom: On some startups ntpq -p reports "No association ID's...".<br> On other startups ntpq -p reports servers & status normally.<br> I.E., problem is intermittent.<br>Cause: When ntpq -p reports "No association ID's..." it is because<br> NetworkManager has not yet brought up the network interface<br> (eth0 for me) when ntpd is trying to resolve server IP<br> addresses. If ntpd gives up on resolving addresses at<br> this point it will never try again
later.<br>Effect: ntpd does not provide time unless restarted manually.<br>Scope: The symptom I see is a problem with ntp. The underlying<br> cause could affect other network services as well.<br>Non-solution: Reorder startup scripts in /etc/rc2.d.<br>Correct solution: ??<br><br>Workaround: Use modified version of etch's /etc/network/if-up.d/ntp<br> script as follows:<br>----------<br>#!/bin/sh<br><br># 12/18/09 Carl Mascott adapt script from etch to work around<br># ntpd/NetworkManager race condition upon<br># entering runlevel 2<br><br># remove (or comment out) the next line if your network addresses change<br>#exit 0<br><br>case $ADDRFAM in<br> NetworkManager)<br> if [ -x
"/etc/init.d/ntp" ]; then<br> if [ -x "`which invoke-rc.d 2>/dev/null`" ]; then<br> invoke-rc.d ntp restart || exit $?<br> else<br> /etc/init.d/ntp restart || exit $?<br> fi<br> fi<br> ;;<br>esac<br>----------<br><br>Excerpt from syslog showing ntp giving up on name resolution 5 seconds<br>(in this particular example) before NetworkManager brings up eth0:<br>----------<br>Dec 18 09:26:08 ganymede ntpd[2732]: ntpd 4.2.4p4@1.1520-o Sun Nov 22 16:14:34 UTC 2009 (1)<br>Dec 18 09:26:08 ganymede ntpd[2733]: precision = 1.000 usec<br>Dec 18 09:26:08 ganymede ntpd[2733]:
Listening on interface #0 wildcard, 0.0.0.0#123 Disabled<br>Dec 18 09:26:08 ganymede ntpd[2733]: Listening on interface #1 wildcard, ::#123 Disabled<br>Dec 18 09:26:08 ganymede ntpd[2733]: Listening on interface #2 lo, ::1#123 Enabled<br>Dec 18 09:26:08 ganymede ntpd[2733]: bind() fd 19, family 10, port 123, scope 2, addr fe80::216:17ff:fe6c:7baa, in6_is_addr_multicast=0 flags=0x11 fails: Cannot assign requested address<br>Dec 18 09:26:08 ganymede ntpd[2733]: unable to create socket on eth0 (3) for fe80::216:17ff:fe6c:7baa#123<br>Dec 18 09:26:08 ganymede ntpd[2733]: failed to initialize interface for address fe80::216:17ff:fe6c:7baa<br>Dec 18 09:26:08 ganymede ntpd[2733]: Listening on interface #4 lo, 127.0.0.1#123 Enabled<br>Dec 18 09:26:08 ganymede ntpd[2733]: kernel time sync status 0040<br>Dec 18 09:26:08 ganymede ntpd[2733]: frequency initialized -109.140 PPM from /var/lib/ntp/ntp.drift<br>Dec 18 09:26:08 ganymede kernel: [ 23.369025]
warning: `ntpd' uses 32-bit capabilities (legacy support in use)<br>Dec 18 09:26:08 ganymede ntpd[2741]: signal_no_reset: signal 17 had flags 4000000<br>Dec 18 09:26:08 ganymede avahi-daemon[2352]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::216:17ff:fe6c:7baa.<br>Dec 18 09:26:08 ganymede avahi-daemon[2352]: New relevant interface eth0.IPv6 for mDNS.<br>Dec 18 09:26:08 ganymede avahi-daemon[2352]: Registering new address record for fe80::216:17ff:fe6c:7baa on eth0.*.<br>Dec 18 09:26:08 ganymede dhcdbd: Started up.<br>Dec 18 09:26:09 ganymede ntpd[2733]: Listening on interface #5 eth0, fe80::216:17ff:fe6c:7baa#123 Enabled<br>Dec 18 09:26:09 ganymede acpid: client connected from 2781[105:113]<br>Dec 18 09:26:10 ganymede NetworkManager: <info> starting...<br>Dec 18 09:26:10 ganymede NetworkManager: <info> eth0: Device is fully-supported using driver 'uli526x'.<br>Dec 18 09:26:10 ganymede NetworkManager:
<info> nm_device_init(): waiting for device's worker thread to start<br>Dec 18 09:26:10 ganymede NetworkManager: <info> nm_device_init(): device's worker thread started, continuing.<br>Dec 18 09:26:10 ganymede NetworkManager: <info> Now managing wired Ethernet (802.3) device 'eth0'.<br>Dec 18 09:26:10 ganymede NetworkManager: <info> Deactivating device eth0.<br>Dec 18 09:26:10 ganymede avahi-daemon[2352]: Withdrawing address record for fe80::216:17ff:fe6c:7baa on eth0.<br>Dec 18 09:26:10 ganymede avahi-daemon[2352]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::216:17ff:fe6c:7baa.<br>Dec 18 09:26:10 ganymede avahi-daemon[2352]: Interface eth0.IPv6 no longer relevant for mDNS.<br>Dec 18 09:26:10 ganymede NetworkManager: <info> Will activate wired connection 'eth0' because it now has a link.<br>Dec 18 09:26:10 ganymede NetworkManager: <info> SWITCH: no current
connection, found better connection 'eth0'.<br>Dec 18 09:26:10 ganymede anacron[2821]: Anacron 2.3 started on 2009-12-18<br>Dec 18 09:26:10 ganymede anacron[2821]: Will run job `cron.daily' in 5 min.<br>Dec 18 09:26:10 ganymede anacron[2821]: Jobs will be executed sequentially<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: host name not found: 0.debian.pool.ntp.org<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: couldn't resolve `0.debian.pool.ntp.org', giving up on it<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: host name not found: 1.debian.pool.ntp.org<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: couldn't resolve `1.debian.pool.ntp.org', giving up on it<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: host name not found: 2.debian.pool.ntp.org<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: couldn't resolve `2.debian.pool.ntp.org', giving up on it<br>Dec 18 09:26:10 ganymede ntpd_initres[2741]: host name not found: 3.debian.pool.ntp.org<br>Dec
18 09:26:10 ganymede ntpd_initres[2741]: couldn't resolve `3.debian.pool.ntp.org', giving up on it<br>Dec 18 09:26:10 ganymede /usr/sbin/cron[2848]: (CRON) INFO (pidfile fd = 3)<br>Dec 18 09:26:10 ganymede /usr/sbin/cron[2849]: (CRON) STARTUP (fork ok)<br>Dec 18 09:26:10 ganymede /usr/sbin/cron[2849]: (CRON) INFO (Running @reboot jobs)<br>Dec 18 09:26:11 ganymede dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.reason<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Will activate connection 'eth0'.<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Device eth0 activation scheduled...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) started...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation
(eth0) Stage 1 of 5 (Device Prepare) started...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.<br>Dec 18 09:26:11 ganymede NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...<br>Dec 18 09:26:11 ganymede acpid: client
connected from 2871[0:0]<br>Dec 18 09:26:12 ganymede NetworkManager: <info> Activation (eth0) Beginning DHCP transaction.<br>Dec 18 09:26:12 ganymede NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.<br>Dec 18 09:26:12 ganymede NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface eth0<br>Dec 18 09:26:13 ganymede kernel: [ 28.139223] nvidia: module license 'NVIDIA' taints kernel.<br>Dec 18 09:26:13 ganymede kernel: [ 28.403588] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 25 (level, low) -> IRQ 25<br>Dec 18 09:26:13 ganymede kernel: [ 28.403597] PCI: Setting latency timer of device 0000:01:00.0 to 64<br>Dec 18 09:26:13 ganymede kernel: [ 28.403725] NVRM: loading NVIDIA UNIX x86_64 Kernel Module 173.14.09 Wed Jun 4 23:40:50 PDT 2008<br>Dec 18 09:26:14 ganymede NetworkManager:
<info> DHCP daemon state is now 1 (starting) for interface eth0<br>Dec 18 09:26:14 ganymede dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5<br>Dec 18 09:26:14 ganymede dhclient: DHCPOFFER from 192.168.1.1<br>Dec 18 09:26:14 ganymede dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67<br>Dec 18 09:26:14 ganymede dhclient: DHCPACK from 192.168.1.1<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.128.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: New relevant interface eth0.IPv4 for mDNS.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Registering new address record for 192.168.1.128 on eth0.IPv4.<br>Dec 18 09:26:14 ganymede NetworkManager: <info> DHCP daemon state is now 2 (bound) for interface eth0<br>Dec 18 09:26:14 ganymede NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) scheduled...<br>Dec
18 09:26:14 ganymede NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) started...<br>Dec 18 09:26:14 ganymede dhclient: bound to 192.168.1.128 -- renewal in 40863 seconds.<br>Dec 18 09:26:14 ganymede dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.domain_search<br>Dec 18 09:26:14 ganymede dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.nis_domain<br>Dec 18 09:26:14 ganymede dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.nis_servers<br>Dec 18 09:26:14 ganymede NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:<br>Dec 18 09:26:14 ganymede NetworkManager: <info> address 192.168.1.128<br>Dec 18 09:26:14 ganymede NetworkManager: <info> netmask
255.255.255.0<br>Dec 18 09:26:14 ganymede NetworkManager: <info> broadcast 192.168.1.255<br>Dec 18 09:26:14 ganymede NetworkManager: <info> gateway 192.168.1.1<br>Dec 18 09:26:14 ganymede NetworkManager: <info> nameserver 192.168.1.1<br>Dec 18 09:26:14 ganymede NetworkManager: <info> hostname 'ganymede'<br>Dec 18 09:26:14 ganymede NetworkManager: <info> domain name 'local'<br>Dec 18 09:26:14 ganymede dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.interface_mtu<br>Dec 18 09:26:14 ganymede NetworkManager: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...<br>Dec 18 09:26:14 ganymede NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) complete.<br>Dec 18 09:26:14 ganymede NetworkManager: <info>
Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Withdrawing address record for 192.168.1.128 on eth0.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.128.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Interface eth0.IPv4 no longer relevant for mDNS.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.128.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: New relevant interface eth0.IPv4 for mDNS.<br>Dec 18 09:26:14 ganymede avahi-daemon[2352]: Registering new address record for 192.168.1.128 on eth0.IPv4.<br>Dec 18 09:26:15 ganymede dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12<br>Dec 18 09:26:15 ganymede dhclient: DHCPOFFER from 192.168.1.1<br>Dec 18 09:26:15 ganymede dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port
67<br>Dec 18 09:26:15 ganymede dhclient: DHCPACK from 192.168.1.1<br>Dec 18 09:26:15 ganymede dhclient: bound to 192.168.1.128 -- renewal in 35149 seconds.<br>Dec 18 09:26:15 ganymede acpid: client connected from 2871[0:0]<br>Dec 18 09:26:15 ganymede NetworkManager: <WARN> nm_system_device_set_ip4_route(): Failed to set IPv4 default route on 'eth0': File exists<br>Dec 18 09:26:15 ganymede NetworkManager: <info> Activation (eth0) Finish handler scheduled.<br>Dec 18 09:26:15 ganymede NetworkManager: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.<br>Dec 18 09:26:15 ganymede NetworkManager: <info> Activation (eth0) successful, device activated.<br>---------<br><br><br>-- System Information:<br>Debian Release: 5.0.3<br> APT prefers stable<br> APT policy: (990, 'stable')<br>Architecture: amd64 (x86_64)<br><br>Kernel: Linux 2.6.26-2-amd64 (SMP w/2 CPU cores)<br>Locale: LANG=C,
LC_CTYPE=C (charmap=ANSI_X3.4-1968)<br>Shell: /bin/sh linked to /bin/bash<br><br>Versions of packages ntp depends on:<br>ii adduser 3.110 add and remove users and groups<br>ii libc6 2.7-18 GNU C Library: Shared libraries<br>ii libcap1 1:1.10-14 support for getting/setting POSIX.<br>ii libedit2 2.11~20080614-1 BSD editline and history libraries<br>ii
libncurses5 5.7+20081213-1 shared libraries for terminal hand<br>ii libssl0.9.8 0.9.8g-15+lenny5 SSL shared libraries<br>ii lsb-base 3.2-20 Linux Standard Base 3.2 init scrip<br>ii netbase 4.34 Basic TCP/IP networking system<br><br>Versions of packages ntp recommends:<br>ii perl 5.10.0-19lenny2 Larry Wall's Practical Extraction <br><br>Versions of
packages ntp suggests:<br>ii ntp-doc 1:4.2.4p4+dfsg-8lenny3 Network Time Protocol documentatio<br><br>-- no debconf information<br><br></div>
<!-- cg12.c3.mail.sp2.yahoo.com compressed/chunked Tue Dec 1 20:05:44 PST 2009 -->
</div><br>
</body></html>