Bug 440264

I think you've selected the wrong component. NNTPGrab is a download program. I
think this bugreport needs to be against the 'ntp' component. Re-assigning to ntp

Is NetworkManager enabled? Has the machine a local DNS server running, like bind
or dnsmasq?

Yes, NetworkManager is up and running (I have a router attached to the
machine & to the Internet) and the connection is always on.

bind is not listed in the Service Configuration program's Background
Services list and nor is dnsmasq. I think I rely on the ISP (or the
router?) to do DNS for me.

Basically I just have a vanilla Fedora 8 KDE spin. (My laptop has
Kubuntu and that is connected to the same router & gets the time fine.)

There is a bug in ntpd with delayed DNS resolution, but it should affect only
machines with local DNS.

Is 127.0.0.1 listed in /etc/resolv.conf? Do the server specifications in
/etc/ntp.conf have dynamic keyword? If the config was generated by
system-config-date, it's probably missing them. It should be:

server 0.fedora.pool.ntp.org dynamic
server 1.fedora.pool.ntp.org dynamic
server 2.fedora.pool.ntp.org dynamic

Here's my /etc/resolv.conf file (excluding blank lines):

    # generated by NetworkManager, do not edit!
    search home
    nameserver 192.168.1.1

My /etc/ntp.conf does not have the dynamic keyword. I've added it to the
server lines as you said:

    server 0.fedora.pool.ntp.org dynamic
    server 1.fedora.pool.ntp.org dynamic
    server 2.fedora.pool.ntp.org dynamic

I used the Network Configuration program and added 127.0.0.1 as the
Secondary DNS, leaving the Primary DNS as 192.168.1.1 (which is my
router's address). I saved this configuration and did a cat on
/etc/resolv.conf and saw that the extra line was added... but when I
rebooted and did another cat I discovered that the 127.0.0.1 entry had
gone! (I tried this twice.)

So I cannot see how to add 127.0.0.1 to /etc/resolv.conf, so even with
the addition of dynamic, I still get the same errors in
/var/log/messages:

Apr  4 15:07:46 marmaduke ntpd[1914]: getaddrinfo: "0.fedora.pool.ntp.org"
invalid host address, ignored
Apr  4 15:07:46 marmaduke ntpd[1914]: getaddrinfo: "1.fedora.pool.ntp.org"
invalid host address, ignored
Apr  4 15:07:46 marmaduke ntpd[1914]: getaddrinfo: "2.fedora.pool.ntp.org"
invalid host address, ignored

(As you can tell I am no sysadmin, so I really am stuck.)

127.0.0.1 shouldn't be in the file, I was just asking to be sure there isn't a
local DNS running.

Can you please verify that there are no such errors and the clock is
synchronized after ntpd service is restarted (service ntpd restart)? If
restarting ntpd doesn't help it won't be related to NetworkManager.

Also, please attach here one complete ntpd output from "grep ntpd var/log/messages".

Restart seemed fine:

[root@marmaduke mark]# /sbin/service ntpd restart
Shutting down ntpd:                                        [  OK  ]
Starting ntpd:                                             [  OK  ]

Here's grep ntpd /var/log/messages:

Apr  5 07:49:41 marmaduke ntpd[1916]: ntpd 4.2.4p2 Mon Sep 24 14:40:07
UTC 2007 (1)
Apr  5 07:49:41 marmaduke ntpd[1917]: precision = 1.000 usec
Apr  5 07:49:41 marmaduke ntpd[1917]: Listening on interface #0 wildcard,
0.0.0.0#123 Disabled
Apr  5 07:49:41 marmaduke ntpd[1917]: Listening on interface #1 wildcard, ::#123
Disabled
Apr  5 07:49:41 marmaduke ntpd[1917]: Listening on interface #2 lo, ::1#123 Enabled
Apr  5 07:49:41 marmaduke ntpd[1917]: Listening on interface #3 lo,
127.0.0.1#123 Enabled
Apr  5 07:49:41 marmaduke ntpd[1917]: kernel time sync status 0040
Apr  5 07:49:41 marmaduke ntpd[1917]: frequency initialized 0.000 PPM from
/var/lib/ntp/drift
Apr  5 07:49:42 marmaduke ntpd[1917]: getaddrinfo: "0.fedora.pool.ntp.org"
invalid host address, ignored
Apr  5 07:49:42 marmaduke ntpd[1917]: getaddrinfo: "1.fedora.pool.ntp.org"
invalid host address, ignored
Apr  5 07:49:42 marmaduke ntpd[1917]: getaddrinfo: "2.fedora.pool.ntp.org"
invalid host address, ignored
Apr  5 07:54:42 marmaduke ntpd[1917]: Listening on interface #4 eth0,
fe80::216:76ff:fe28:80e3#123 Enabled
Apr  5 07:54:42 marmaduke ntpd[1917]: Listening on interface #5 eth0,
192.168.1.2#123 Enabled
Apr  5 08:03:00 marmaduke ntpd[1917]: ntpd exiting on signal 15
Apr  5 08:03:00 marmaduke ntpd[2906]: ntpd 4.2.4p2 Mon Sep 24 14:40:07
UTC 2007 (1)
Apr  5 08:03:00 marmaduke ntpd[2907]: precision = 1.000 usec
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #0 wildcard,
0.0.0.0#123 Disabled
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #1 wildcard, ::#123
Disabled
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #2 lo, ::1#123 Enabled
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #3 eth0,
fe80::216:76ff:fe28:80e3#123 Enabled
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #4 lo,
127.0.0.1#123 Enabled
Apr  5 08:03:00 marmaduke ntpd[2907]: Listening on interface #5 eth0,
192.168.1.2#123 Enabled
Apr  5 08:03:00 marmaduke ntpd[2907]: kernel time sync status 0040
Apr  5 08:03:00 marmaduke ntpd[2907]: frequency initialized 0.000 PPM from
/var/lib/ntp/drift


Maybe it is working now (presumably after adding the dynamic keyword you suggested?)

Looks like the error messages are caused by "restrict *.fedora.pool.ntp.org"
lines in /etc/ntp.conf. They should be harmless though.

Can you please verify that ntpd is working correctly by using ntpstat after the
machine is rebooted and the user has been logged in for at least 20 minutes?

Does removing the restrict lines remove the error messages from log?

The results of ntpstat prior to rebooting (and about 20 mins after rebooting):

unsynchronised
  time server re-starting
   polling server every 64 s

Here is the grep of ntpd for today's first boot, and then a second boot having
commented out the restrict lines as you said:

Apr 10 06:56:39 marmaduke ntpd[1913]: ntpd 4.2.4p2 Mon Sep 24 14:40:07
UTC 2007 (1)
Apr 10 06:56:39 marmaduke ntpd[1914]: precision = 1.000 usec
Apr 10 06:56:39 marmaduke ntpd[1914]: Listening on interface #0 wildcard,
0.0.0.0#123 Disabled
Apr 10 06:56:39 marmaduke ntpd[1914]: Listening on interface #1 wildcard, ::#123
Disabled
Apr 10 06:56:39 marmaduke ntpd[1914]: Listening on interface #2 lo, ::1#123 Enabled
Apr 10 06:56:39 marmaduke ntpd[1914]: Listening on interface #3 lo,
127.0.0.1#123 Enabled
Apr 10 06:56:39 marmaduke ntpd[1914]: kernel time sync status 0040
Apr 10 06:56:39 marmaduke ntpd[1914]: frequency initialized 0.000 PPM from
/var/lib/ntp/drift
Apr 10 06:56:40 marmaduke ntpd[1914]: getaddrinfo: "0.fedora.pool.ntp.org"
invalid host address, ignored
Apr 10 06:56:40 marmaduke ntpd[1914]: getaddrinfo: "1.fedora.pool.ntp.org"
invalid host address, ignored
Apr 10 06:56:40 marmaduke ntpd[1914]: getaddrinfo: "2.fedora.pool.ntp.org"
invalid host address, ignored
Apr 10 07:01:40 marmaduke ntpd[1914]: Listening on interface #4 eth0,
fe80::216:76ff:fe28:80e3#123 Enabled
Apr 10 07:01:40 marmaduke ntpd[1914]: Listening on interface #5 eth0,
192.168.1.2#123 Enabled
Apr 10 14:35:17 marmaduke ntpd[1914]: ntpd exiting on signal 15
Apr 10 14:36:08 marmaduke ntpd[1913]: ntpd 4.2.4p2 Mon Sep 24 14:40:07
UTC 2007 (1)
Apr 10 14:36:08 marmaduke ntpd[1914]: precision = 1.000 usec
Apr 10 14:36:08 marmaduke ntpd[1914]: Listening on interface #0 wildcard,
0.0.0.0#123 Disabled
Apr 10 14:36:08 marmaduke ntpd[1914]: Listening on interface #1 wildcard, ::#123
Disabled
Apr 10 14:36:08 marmaduke ntpd[1914]: Listening on interface #2 lo, ::1#123 Enabled
Apr 10 14:36:08 marmaduke ntpd[1914]: Listening on interface #3 lo,
127.0.0.1#123 Enabled
Apr 10 14:36:08 marmaduke ntpd[1914]: kernel time sync status 0040
Apr 10 14:36:08 marmaduke ntpd[1914]: frequency initialized 0.000 PPM from
/var/lib/ntp/drift

I'm not sure, but it looks like your suggestion has fixed the problem since
there are no invalid host address errors after the reboot.

Do you think you'll be able to fix Fedora so that this problem doesn't arise
again, or is it just an unfortunate quirk of my machine that I'll have to fix
each time I upgrade Fedora?

Thanks!

Well, I'm still not sure what exactly is wrong.

The error messages are harmless, but the ntpstat output indicates that something
is wrong. It should said something like this:

synchronised to NTP server (10.20.30.40) at stratum 3

Please leave it running for one hour and post here output from "/usr/sbin/ntpq -pn".

After just over 1 hour I got this:
# ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 217.147.223.78  .INIT.          16 u    - 1024    0    0.000    0.000   0.000
 192.33.96.102   .INIT.          16 u    - 1024    0    0.000    0.000   0.000
 147.231.100.5   .INIT.          16 u    - 1024    0    0.000    0.000   0.000

Thanks!

0 in the reach column means the ntpd is not getting answers from the servers,
it's definitely not working correctly.

Maybe a firewall setting on the router?

The router is just an off the shelf box that works with my broadband connection.
I don't know if it has a firewall or not---everything else works, e.g., ftp,
ssh, web browsing, email...
I don't know enough about sysadmin stuff to even know where to look:-(

It could be also your ISP who is dropping the packets, maybe they provide a
local NTP server.

To verify that NTP packets are getting through you can use:

/usr/sbin/ntpdate -p 1 -q 0.pool.ntp.org

The output should look like:

server 84.242.66.126, stratum 3, offset 0.004387, delay 0.05209
server 147.251.48.140, stratum 2, offset -0.000032, delay 0.03996
server 212.96.160.147, stratum 2, offset 0.002721, delay 0.07861
11 Apr 12:11:35 ntpdate[18185]: adjust time server 147.251.48.140 offset -0.0000

Here's the output I get:

# ntpdate -p 1 -q 0.pool.ntp.org
server 204.9.53.11, stratum 2, offset 74.362266, delay 0.06839
server 153.109.180.3, stratum 4, offset 74.358443, delay 0.09424
server 78.47.89.89, stratum 2, offset 74.364430, delay 0.09233
server 81.169.180.21, stratum 2, offset 74.349360, delay 0.10170
server 81.171.44.131, stratum 2, offset 74.364917, delay 0.06232
11 Apr 12:20:10 ntpdate[13804]: step time server 81.171.44.131 offset 74.364917 sec

I got similar for 0.fedora.pool.ntp.org

Hm, so it is a ntpd problem after all.

Can you attach here /etc/ntp.conf file?

Created attachment 302115 [details]
This is the original Fedora 8 one with the modifications you suggested and is the one in use

The config is ok. Now it would be good to see ntpd debug output.

As root:
# /etc/init.d/ntpd stop
# /usr/sbin/ntpd -D 4 &> log

Keep it running for few minutes and attach here the log file. Thanks.

Created attachment 302118 [details]
log of ntpd -D 4 &>/tmp/ntp.log

Packets are sent, but no answer is coming back. That's odd.

Can you attach here output of "tcpdump -n -i any port ntp" running when the
ntpdate command is executed and when ntpd is started?

Created attachment 302345 [details]
tcpdump output as requested

Here's the output for the following:

# tcpdump -v -n -i any port ntp > /tmp/ntp.txt &
[1] 31589
tcpdump: WARNING: Promiscuous mode not supported on the "any" device
# tcpdump: listening on any, link-type LINUX_SLL (Linux cooked), capture size
96 bytes

# ntpdate
14 Apr 15:42:00 ntpdate[31590]: no servers can be used, exiting

# service ntpd stop
Shutting down ntpd:					   [  OK  ]

# service ntpd start
Starting ntpd:						   [  OK  ]

Hope that's what you needed?

Please use "ntpdate -p 1 -q 0.pool.ntp.org" and keep tcpdump running for few
minutes after ntpd is restarted. Thanks.

Created attachment 302409 [details]
tcpdump as requested

Here's what I did at the console (with an interval of several minutes):

# tcpdump -v -n -i any port ntp > /tmp/ntp.txt &
[1] 3021
# tcpdump: WARNING: Promiscuous mode not supported on the "any" device
tcpdump: listening on any, link-type LINUX_SLL (Linux cooked), capture size 96
bytes

# ntpdate -p 1 -q 0.pool.ntp.org
server 192.108.114.23, stratum 1, offset 81.695382, delay 0.14781
server 193.2.111.2, stratum 3, offset 81.699360, delay 0.09581
server 212.235.187.82, stratum 3, offset 81.698475, delay 0.09634
server 213.239.154.12, stratum 2, offset 81.695442, delay 0.05714
server 141.13.16.222, stratum 3, offset 81.694043, delay 0.08278
15 Apr 07:16:48 ntpdate[3022]: step time server 192.108.114.23 offset 81.695382
sec
# service ntpd stop
Shutting down ntpd:					   [  OK  ]
# service ntpd start
Starting ntpd:						   [  OK  ]
ntpdate -p 1 -q 0.pool.ntp.org
server 192.108.114.23, stratum 1, offset 81.702680, delay 0.14639
server 193.2.111.2, stratum 3, offset 81.706548, delay 0.09552
server 212.235.187.82, stratum 3, offset 81.705719, delay 0.09599
server 213.239.154.12, stratum 2, offset 81.702511, delay 0.05751
server 141.13.16.222, stratum 3, offset 81.701205, delay 0.08299
15 Apr 07:17:20 ntpdate[3060]: step time server 192.108.114.23 offset 81.702680
sec
# # several minutes pass...
# ntpdate -p 1 -q 0.pool.ntp.org
server 192.108.114.23, stratum 1, offset 81.798563, delay 0.14755
server 193.2.111.2, stratum 3, offset 81.801476, delay 0.09578
server 212.235.187.82, stratum 3, offset 81.800946, delay 0.09563
server 213.239.154.12, stratum 2, offset 81.799607, delay 0.05931
server 141.13.16.222, stratum 3, offset 81.796617, delay 0.08139
15 Apr 07:24:19 ntpdate[3183]: step time server 192.108.114.23 offset 81.798563
sec
fg
tcpdump -v -n -i any port ntp > /tmp/ntp.txt
51 packets captured
51 packets received by filter
0 packets dropped by kernel

Thanks. Probably the last thing I'd like you to try is:

service ntpd stop
ntpdate -p 1 0.pool.ntp.org
ntpdate -u -p 1 0.pool.ntp.org

# service ntpd stop
Shutting down ntpd:                                        [  OK  ]
# ntpdate -p 1 0.pool.ntp.org
15 Apr 13:06:36 ntpdate[31287]: no server suitable for synchronization found
# ntpdate -u -p 1 0.pool.ntp.org
15 Apr 13:06:46 ntpdate[31288]: step time server 88.191.22.72 offset 86.542400 sec

Hope that helps. I really appreciate the effort you've made to solve this!

The -u option causes ntpdate to use an unprivileged port for outgoing packets
(normally is used the NTP port 123). ntpd always uses 123.

This means that something is dropping either outgoing packets that have source
port 123 or incoming packets that have destination port 123. It could be the
router or an ISP firewall.

A bit more information is at:
http://support.ntp.org/bin/view/Support/TroubleshootingNTP#Section_9.8.

You have mentioned that a laptop running Kubuntu doesn't have this problem, is
it really using ntpd?

I ran ntpdate on Kubuntu and got the same kind of output, so clearly that isn't
working either. (I guess the laptop clock is just better than the desktop
machine's clock.)

My router is a Voyater 2110 and it is providing DHCP. I can't find any setting
that has switched off port 123 (or anything else).

I looked at the troubleshooting page, but it seems to me that somewhere I am
blocking port 123, but I just don't know where.

I don't know if it is relevant but /etc/protocols has the line:
ptp	123	PTP		# Performance Transparency Protocol

Unfortunately I don't know enough about networking or firewalls to know where to
look.

My guess would be the internet provider. As a last resort to have some
timekeeping, you can put

#!/bin/bash
sleep $[$RANDOM % 100].$[$RANDOM % 100]
/usr/sbin/ntpdate -p 1 -U ntp -u 0.pool.ntp.org > /dev/null

in a file in /etc/cron.hourly and make it executable.

As this turned out to be a networking issue, I'm closing this as NOTABUG.

Thank you ever so much for you terrific help:-)
I've put the above into /etc/cron.hourly/runntp.sh and done chmod +x on it (on
both machines:-)
I've also raised the issue with my ISP.

Thanks!