[ntp:questions] recvfrom(0.0.0.0) fd=51: Connection refused

Luc Pardon xntp at skopos.be
Sat Sep 9 20:25:42 UTC 2006


Well, I'm about to give up.

My logs are getting flooded with "Connection refused" messages and I 
can't find why, much less how to stop them.

This is a rather oldish RH Linux box with two network cards. One is 
connected to the bad world outside via an ADSL router, the other to the 
internal network (192.168.x.x). It gets its time from stratum 2 servers 
and provides time to the internal network.

I've been running ntp on that box since 2001. In June 2005, I upgraded 
to ntp 4.2.0.

Life was beautiful for more than a year until, last week, I suddenly 
started getting "Connection refused" messages in syslog.

 > Sep  3 04:06:32 gida ntpd[4796]: recvfrom(193.190.230.65) fd=9: 
Connection refused
 > Sep  3 04:06:32 gida ntpd[4796]: recvfrom(193.190.230.65) fd=9: 
Connection refused
 > Sep  3 04:07:36 gida ntpd[4796]: recvfrom(193.190.230.65) fd=9: 
Connection refused
 > Sep  3 04:07:36 gida ntpd[4796]: recvfrom(193.190.230.65) fd=9: 
Connection refused
 > Sep  3 04:08:40 gida ntpd[4796]: recvfrom(192.168.1.3) fd=9: 
Connection refused
 > Sep  3 04:08:40 gida ntpd[4796]: recvfrom(192.168.1.3) fd=9: 
Connection refused
 > Sep  3 04:09:44 gida ntpd[4796]: recvfrom(192.168.1.3) fd=9: 
Connection refused
 > Sep  3 04:09:44 gida ntpd[4796]: recvfrom(192.168.1.3) fd=9: 
Connection refused

I've been getting "Connection refused" before (which is why I upped to 
4.2.0 because that shows the failing IP). At the time it turned out that 
our friendly ISP had blocked port 123 in the ADSL router. Phoned them to 
complain and they opened it again.

This is not the case now, ntpd can reach the outside servers and syncs 
and serves the internal network just fine. Also, 'ntpq -p' showed 'reach 
377' for all servers, including 193.190.230.65. Besides, fd 9 is the 
socket on the ADSL-facing card (192.168.254.2), so packets to/from the 
internal 192.168.1.3 have no business going there.

Firewall rules haven't changed in over a month, and in any case, any 
rejected UDP/123 packets are supposed to be logged and there is nothing 
to be seen.

After 8 hours or so, the critters went away. I hate problems going away 
just like that. Fortunately (not!), they came back two days later, on 
Sep  5 08:01:15. They left again at 10:58:19, only to reappear the next 
day at 08:01:17 and leave again at 11:44:13. Back again next day, Sep 7 
00:01:18 and lasted until 09:23 when I stopped ntpd.

This is because I checked the mailing list and decided to upgrade to 
4.2.2p3. Almost as soon as I started the new version, the "connection 
refused" was back, but different now:

 > Sep  7 09:24:25 gida ntpd[26405]: ntpd 4.2.2p3 at 1.1577-o Thu Sep  7 
07:05:22 UTC
 > 2006 (1)
 > Sep  7 09:24:25 gida ntpd[26406]: precision = 1.000 usec
 > Sep  7 09:24:25 gida ntpd: ntpd startup succeeded
 > Sep  7 09:24:26 gida ntpd[26406]: Listening on interface wildcard, 
0.0.0.0#123 Disabled
 > Sep  7 09:24:26 gida ntpd[26406]: Listening on interface lo, 
127.0.0.1#123 Enabled
 > Sep  7 09:24:26 gida ntpd[26406]: Listening on interface eth0, 
192.168.1.23#123
 > Enabled
 > Sep  7 09:24:26 gida ntpd[26406]: Listening on interface eth1, 
192.168.254.2#123 Enabled
 > Sep  7 09:24:26 gida ntpd[26406]: kernel time sync status 0040
 > Sep  7 09:24:32 gida ntpd[26406]: frequency initialized 128.381 PPM 
from /etc/ntp/drift
 > Sep  7 09:24:32 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:24:32 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:25:34 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:25:34 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:26:38 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:26:38 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:27:42 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:27:42 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused
 > Sep  7 09:27:50 gida ntpd[26406]: synchronized to 193.190.230.66, 
stratum 1
 > Sep  7 09:27:50 gida ntpd[26406]: kernel time sync enabled 0001
 > Sep  7 09:28:46 gida ntpd[26406]: recvfrom(0.0.0.0) fd=51: Connection 
refused

   Note that, at startup, it says "Listening on interface wildcard, 
0.0.0.0#123 Disabled" but that seems a blatant lie since lsof shows that 
it does have a socket open there.

   The 'refused' messages come two at a time and in 64 second intervals.

   I tried adding a line 'manycastclient 224.1.1.1' to ntp.conf. The 
messages stopped and came back. So it doesn't make a difference.

   I tried removing the 'restrict' lines from ntp.conf but it doesn't 
make a difference.

   I then pulled 4.2.3p39 from dev and tried again. Same thing, the only 
difference is that it doesn't mention the wildcard IF at startup.

   I noticed that 193.190.230.66 is a stratum 1 server and not a 2 like 
the others. Either I missed that when I added it to ntp.conf in May 2005 
or they changed from 2 to 1 since then. In any case I removed it but it 
doesn't make any difference.

   I tried the debug output but it doesn't tell me anything. All I can 
make of it is that there is only one 'refused' in the debug output and 
two in the syslog. Also, the 'refused' comes after several seconds of 
silence in the debug output. It doesn't tell me why it thinks it should 
call recvfrom.

   Needless to say, "tcpdump -i eth1 port ntp" (eth1 being fd 51) 
doesn't show activity that might be related to the refusals.

   One thing that I should add is that I can't ntpq locally on that 
machine. It  says "Name or service not known". From what I can see with 
strace it seems to be looking in /etc/services from something. But I 
wouldn't know what, "ntp" is definitely in there. In any case, this 
started happening one year ago so it should have nothing to do with the 
"refused" messages (but maybe with the ntp 4.1.x to 4.2.x transition). I 
can query the box remotely, from another Linux, without problems.

   Below are the relevant syslog lines, the ntpd debug output between 
two 'refused's and the content of ntp.conf.

   I"d appreciate if somebody could tell me what to do to make this 
stop. I'd also like to know what's going on.

   TIA,

    Luc Pardon


#--------------------------
$ tail -f /var/log/messages | grep ntp

Sep  8 11:24:54 gida ntpd[8768]: ntpd 4.2.3p39 at 1.1395-o Fri Sep  8 
08:57:05 UTC 2006 (3)
Sep  8 11:24:54 gida ntpd[8769]: precision = 1.000 usec
Sep  8 11:24:54 gida ntpd: ntpd startup succeeded
Sep  8 11:24:54 gida ntpd[8769]: Listening on interface #1 lo, 
127.0.0.1#123 Enabled
Sep  8 11:24:54 gida ntpd[8769]: Listening on interface #2 eth0, 
192.168.1.23#123 Enabled
Sep  8 11:24:54 gida ntpd[8769]: Listening on interface #3 eth1, 
192.168.254.2#123 Enabled
Sep  8 11:24:54 gida ntpd[8769]: kernel time sync status 0040
Sep  8 11:24:54 gida ntpd[8769]: frequency initialized 129.083 PPM from 
/etc/ntp/drift
Sep  8 11:25:04 gida ntpd[8769]: recvfrom(0.0.0.0) fd=51: Connection refused
Sep  8 11:25:04 gida ntpd[8769]: recvfrom(0.0.0.0) fd=51: Connection refused


#--------------------------
$ lsof -i -n | grep ntp

ntpd       8769        root   48u  IPv4 92307937       UDP *:ntp
ntpd       8769        root   49u  IPv4 92307973       UDP 127.0.0.1:ntp
ntpd       8769        root   50u  IPv4 92307975       UDP 192.168.1.23:ntp
ntpd       8769        root   51u  IPv4 92307977       UDP 192.168.254.2:ntp

#-------------------------------------------------
# partial output of ntpd -q -d -d -d -d -d
# (between two 'connection refused')
#-------------------------------------------------

auth_agekeys: at 420 keys 1 expired 0
sendpkt(fd=51 dst=145.238.110.68, src=192.168.254.2, ttl=0, len=48)
transmit: at 452 192.168.254.2->145.238.110.68 mode 3
poll_update: at 452 145.238.110.68 flags 0041 poll 6 burst 0 last 452 
next 516
read_network_packet: fd=51 length 48 from 91ee6e44 145.238.110.68
receive: at 452 192.168.254.2<-145.238.110.68 flags 19 restrict 1c0
receive: at 452 192.168.254.2<-145.238.110.68 mode 4 code 1 auth 0
poll_update: at 452 145.238.110.68 flags 0041 poll 6 burst 0 last 452 
next 518
clock_filter: discard 0
sendpkt(fd=51 dst=130.159.196.118, src=192.168.254.2, ttl=0, len=48)
transmit: at 455 192.168.254.2->130.159.196.118 mode 3
poll_update: at 455 130.159.196.118 flags 0001 poll 6 burst 0 last 455 
next 521
read_network_packet: fd=51 length 48 from 829fc476 130.159.196.118
receive: at 455 192.168.254.2<-130.159.196.118 flags 19 restrict 1c0
receive: at 455 192.168.254.2<-130.159.196.118 mode 4 code 1 auth 0
poll_update: at 455 130.159.196.118 flags 0001 poll 6 burst 0 last 455 
next 518
clock_filter: discard 0
sendpkt(fd=51 dst=129.240.64.3, src=192.168.254.2, ttl=0, len=48)
transmit: at 456 192.168.254.2->129.240.64.3 mode 3
poll_update: at 456 129.240.64.3 flags 0001 poll 6 burst 0 last 456 next 520
read_network_packet: fd=51 length 48 from 81f04003 129.240.64.3
receive: at 456 192.168.254.2<-129.240.64.3 flags 19 restrict 1c0
receive: at 456 192.168.254.2<-129.240.64.3 mode 4 code 1 auth 0
poll_update: at 456 129.240.64.3 flags 0001 poll 6 burst 0 last 456 next 520
clock_filter: n 8 off 0.001595 del 0.053788 dsp 0.001001 jit 0.002848, age 0
select: endpoint -1 -0.176856
select: endpoint -1 -0.155725
select: endpoint -1 -0.114353
select: endpoint -1 -0.105808
select: endpoint -1 -0.073520
select: endpoint  0 -0.016682
select: endpoint  0 -0.004989
select: endpoint  0 -0.004133
select: endpoint  0 -0.001493
select: endpoint  0 0.001595
select: endpoint  1 0.070534
select: endpoint  1 0.106086
select: endpoint  1 0.108998
select: endpoint  1 0.143492
select: endpoint  1 0.145747
select: drop 195.13.1.153 select 0.014654 jitter 0.002537
select: drop 129.240.64.3 select 0.005345 jitter 0.002848
cluster: survivor 145.238.110.68 metric 2.072027
cluster: survivor 130.159.196.118 metric 2.107403
cluster: survivor 138.195.130.71 metric 2.110219
select: combine offset -0.003086
poll_update: at 456 145.238.110.68 flags 0041 poll 6 burst 0 last 452 
next 516
sendpkt(fd=51 dst=138.195.130.71, src=192.168.254.2, ttl=0, len=48)
transmit: at 457 192.168.254.2->138.195.130.71 mode 3
poll_update: at 457 138.195.130.71 flags 0001 poll 6 burst 0 last 457 
next 521
read_network_packet: fd=51 length 48 from 8ac38247 138.195.130.71
receive: at 457 192.168.254.2<-138.195.130.71 flags 19 restrict 1c0
receive: at 457 192.168.254.2<-138.195.130.71 mode 4 code 1 auth 0
poll_update: at 457 138.195.130.71 flags 0001 poll 6 burst 0 last 457 
next 521
clock_filter: discard 0
sendpkt(fd=51 dst=195.13.1.153, src=192.168.254.2, ttl=0, len=48)
transmit: at 458 192.168.254.2->195.13.1.153 mode 3
poll_update: at 458 195.13.1.153 flags 0001 poll 6 burst 0 last 458 next 522
read_network_packet: fd=51 length 48 from c30d0199 195.13.1.153
receive: at 458 192.168.254.2<-195.13.1.153 flags 19 restrict 1c0
receive: at 458 192.168.254.2<-195.13.1.153 mode 4 code 1 auth 0
poll_update: at 458 195.13.1.153 flags 0001 poll 6 burst 0 last 458 next 524
clock_filter: n 8 off -0.017358 del 0.018838 dsp 0.001999 jit 0.002931, 
age 0
select: endpoint -1 -0.114383
select: endpoint -1 -0.105838
select: endpoint -1 -0.097190
select: endpoint -1 -0.093209
select: endpoint -1 -0.073550
select: endpoint  0 -0.017358
select: endpoint  0 -0.004989
select: endpoint  0 -0.004133
select: endpoint  0 -0.001493
select: endpoint  0 0.001595
select: endpoint  1 0.062475
select: endpoint  1 0.070564
select: endpoint  1 0.083232
select: endpoint  1 0.106116
select: endpoint  1 0.109028
select: drop 195.13.1.153 select 0.015320 jitter 0.002848
select: drop 129.240.64.3 select 0.005345 jitter 0.002848
cluster: survivor 145.238.110.68 metric 2.072057
cluster: survivor 138.195.130.71 metric 2.079832
cluster: survivor 130.159.196.118 metric 2.088221
select: combine offset -0.003347
poll_update: at 458 145.238.110.68 flags 0041 poll 6 burst 0 last 452 
next 516
addto_syslog: recvfrom(0.0.0.0) fd=51: Connection refused
read_network_packet: fd=51 dropped (bad recvfrom)


#------------------------------------------
# ntp.conf (minus the comment lines)
#------------------------------------------

restrict default ignore
restrict 127.0.0.1
restrict 192.168.0.0 mask 255.255.0.0 nomodify notrap

server ntp.obspm.fr
restrict ntp.obspm.fr mask 255.255.255.255 nomodify notrap noquery

server ntp.via.ecp.fr
restrict ntp.via.ecp.fr mask 255.255.255.255 nomodify notrap noquery

server ntp.cs.strath.ac.uk
restrict ntp.cs.strath.ac.uk mask 255.255.255.255 nomodify notrap noquery

server ntp2.belbone.be
restrict ntp2.belbone.be mask 255.255.255.255 nomodify notrap noquery

driftfile /etc/ntp/drift



More information about the questions mailing list