5

Using wget (curl, httplib2) I always get a 5 second resolving timeout. This issue doesn't arrive when I do wget -4 or wget -6. Resolving also works using dig or host. Delay can be lowered using "options timeout:2" in /etc/resolv.conf

The strace output of this is: 

15:19:09.908234 uname({sys="Linux", node="openkvk", ...}) = 0 
15:19:09.908413 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3 
15:19:09.908482 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, 16) = 0 
15:19:09.908569 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}]) 
15:19:09.908637 sendto(3, "F\347\1\0\0\1\0\0\0\0\0\0\10slashdot\3org\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30 
15:19:09.908735 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=3, revents=POLLOUT}])
15:19:09.908804 sendto(3, "F\331\1\0\0\1\0\0\0\0\0\0\10slashdot\3org\0\0\34\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30 
15:19:09.908884 poll([{fd=3, events=POLLIN}], 1, 4999) = 1 ([{fd=3, revents=POLLIN}]) 
15:19:09.911230 ioctl(3, FIONREAD, [46]) = 0 
15:19:09.911308 recvfrom(3, "F\347\201\200\0\1\0\1\0\0\0\0\10slashdot\3org\0\0\1\0\1\300\f"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 46 
15:19:09.911445 poll([{fd=3, events=POLLIN}], 1, 4997) = 0 (Timeout) 
15:19:14.909096 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}]) 
15:19:14.909189 sendto(3, "F\347\1\0\0\1\0\0\0\0\0\0\10slashdot\3org\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30 
15:19:14.909292 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}]) 
15:19:14.911569 ioctl(3, FIONREAD, [46]) = 0 
15:19:14.911644 recvfrom(3, "F\347\201\200\0\1\0\1\0\0\0\0\10slashdot\3org\0\0\1\0\1\300\f"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 46 
15:19:14.911772 poll([{fd=3, events=POLLOUT}], 1, 4997) = 1 ([{fd=3, revents=POLLOUT}]) 
15:19:14.911837 sendto(3, "F\331\1\0\0\1\0\0\0\0\0\0\10slashdot\3org\0\0\34\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30 
15:19:14.912051 poll([{fd=3, events=POLLIN}], 1, 4997) = 1 ([{fd=3, revents=POLLIN}]) 
15:19:14.914034 ioctl(3, FIONREAD, [106]) = 0

Tcpdump output:

tcpdump -vvv  port 53 
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes 
15:19:09.908687 IP (tos 0x0, ttl 64, id 37830, offset 0, flags [DF], proto UDP (17), length 58) 
    93.157.136.242.38551 > 212.83.206.202.domain: [bad udp cksum 3576!] 18151+ A? slashdot.org. (30) 
15:19:09.908852 IP (tos 0x0, ttl 64, id 37831, offset 0, flags [DF], proto UDP (17), length 58) 
    93.157.136.242.38551 > 212.83.206.202.domain: [bad udp cksum 2876!] 18137+ AAAA? slashdot.org. (30) 
15:19:09.911081 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 74) 
    212.83.206.202.domain > 93.157.136.242.38551: [udp sum ok] 18151 q: A? slashdot.org. 1/0/0 slashdot.org. [22m21s] A 216.34.181.45 (46) 
15:19:14.909246 IP (tos 0x0, ttl 64, id 37832, offset 0, flags [DF], proto UDP (17), length 58) 
    93.157.136.242.38551 > 212.83.206.202.domain: [bad udp cksum 3576!] 18151+ A? slashdot.org. (30) 
15:19:14.911442 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 74) 
    212.83.206.202.domain > 93.157.136.242.38551: [udp sum ok] 18151 q: A? slashdot.org. 1/0/0 slashdot.org. [22m16s] A 216.34.181.45 (46) 
15:19:14.911882 IP (tos 0x0, ttl 64, id 37833, offset 0, flags [DF], proto UDP (17), length 58) 
    93.157.136.242.38551 > 212.83.206.202.domain: [bad udp cksum 2876!] 18137+ AAAA? slashdot.org. (30) 
15:19:14.913906 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 134) 
    212.83.206.202.domain > 93.157.136.242.38551: [udp sum ok] 18137 q: AAAA? slashdot.org. 0/1/0 ns: slashdot.org. [3m39s] SOA ns-1.ch3.sourceforge.com. hostmaster.corp.sourceforge.com. 2011101300 14400 1800 604800 3600 (106)

Tools like dig/host perform similar to using wget -4 or wget -6, instant, without any problem.

I have tried each of the following servers individually.

nameserver 2001:4018:3:12::202
nameserver 2001:4018:1:64::202
nameserver 212.83.206.202
nameserver 213.207.64.202
nameserver 8.8.8.8
nameserver 8.8.4.4

What could cause this delay?

Requested output: wget -4 (works)

23:41:10.428217 IP (tos 0x0, ttl 64, id 11790, offset 0, flags [DF], proto UDP (17), length 55)
    93.157.136.242.51379 > 212.83.206.202.domain: [bad udp cksum e070!] 65414+ A? vircon.nl. (27)
23:41:10.430442 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 71)
    212.83.206.202.domain > 93.157.136.242.51379: [udp sum ok] 65414 q: A? vircon.nl. 1/0/0 vircon.nl. [15h59m29s] A 31.193.104.52 (43)

23:41:10.427920 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
23:41:10.427982 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, 16) = 0
23:41:10.428095 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
23:41:10.428166 sendto(3, "\377\206\1\0\0\1\0\0\0\0\0\0\6vircon\2nl\0\0\1\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
23:41:10.428262 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
23:41:10.430572 ioctl(3, FIONREAD, [43]) = 0
23:41:10.430651 recvfrom(3, "\377\206\201\200\0\1\0\1\0\0\0\0\6vircon\2nl\0\0\1\0\1\300\f\0\1\0"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 43
23:41:10.430774 close(3)

wget (broken)

23:40:13.577621 IP (tos 0x0, ttl 64, id 20475, offset 0, flags [DF], proto UDP (17), length 55)
    93.157.136.242.55276 > 212.83.206.202.domain: [bad udp cksum 16c!] 62764+ A? vircon.nl. (27)
23:40:13.577786 IP (tos 0x0, ttl 64, id 20476, offset 0, flags [DF], proto UDP (17), length 55)
    93.157.136.242.55276 > 212.83.206.202.domain: [bad udp cksum 9654!] 61847+ AAAA? vircon.nl. (27)
23:40:13.579879 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 71)
    212.83.206.202.domain > 93.157.136.242.55276: [udp sum ok] 62764 q: A? vircon.nl. 1/0/0 vircon.nl. [22h20m8s] A 31.193.104.52 (43)
23:40:18.582490 IP (tos 0x0, ttl 64, id 20477, offset 0, flags [DF], proto UDP (17), length 55)
    93.157.136.242.55276 > 212.83.206.202.domain: [bad udp cksum 16c!] 62764+ A? vircon.nl. (27)
23:40:18.584709 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 71)
    212.83.206.202.domain > 93.157.136.242.55276: [udp sum ok] 62764 q: A? vircon.nl. 1/0/0 vircon.nl. [16h21s] A 31.193.104.52 (43)
23:40:18.585163 IP (tos 0x0, ttl 64, id 20478, offset 0, flags [DF], proto UDP (17), length 55)
    93.157.136.242.55276 > 212.83.206.202.domain: [bad udp cksum 9654!] 61847+ AAAA? vircon.nl. (27)
23:40:18.587212 IP (tos 0x0, ttl 59, id 0, offset 0, flags [DF], proto UDP (17), length 106)
    212.83.206.202.domain > 93.157.136.242.55276: [udp sum ok] 61847 q: AAAA? vircon.nl. 0/1/0 ns: vircon.nl. [56m25s] SOA ns1.vircon.nl. hostmaster.vircon.nl. 2011120602 10800 3600 604800 86400 (78)

23:40:13.577353 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
23:40:13.577417 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, 16) = 0
23:40:13.577502 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
23:40:13.577572 sendto(3, "\365,\1\0\0\1\0\0\0\0\0\0\6vircon\2nl\0\0\1\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
23:40:13.577667 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=3, revents=POLLOUT}])
23:40:13.577737 sendto(3, "\361\227\1\0\0\1\0\0\0\0\0\0\6vircon\2nl\0\0\34\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
23:40:13.577892 poll([{fd=3, events=POLLIN}], 1, 4999) = 1 ([{fd=3, revents=POLLIN}])
23:40:13.580007 ioctl(3, FIONREAD, [43]) = 0
23:40:13.580105 recvfrom(3, "\365,\201\200\0\1\0\1\0\0\0\0\6vircon\2nl\0\0\1\0\1\300\f\0\1\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 43
23:40:13.580229 poll([{fd=3, events=POLLIN}], 1, 4997) = 0 (Timeout)
23:40:18.582338 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
23:40:18.582433 sendto(3, "\365,\1\0\0\1\0\0\0\0\0\0\6vircon\2nl\0\0\1\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
23:40:18.582535 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
23:40:18.584835 ioctl(3, FIONREAD, [43]) = 0
23:40:18.584912 recvfrom(3, "\365,\201\200\0\1\0\1\0\0\0\0\6vircon\2nl\0\0\1\0\1\300\f\0\1\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 43
23:40:18.585048 poll([{fd=3, events=POLLOUT}], 1, 4997) = 1 ([{fd=3, revents=POLLOUT}])
23:40:18.585117 sendto(3, "\361\227\1\0\0\1\0\0\0\0\0\0\6vircon\2nl\0\0\34\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
23:40:18.585300 poll([{fd=3, events=POLLIN}], 1, 4997) = 1 ([{fd=3, revents=POLLIN}])
23:40:18.587325 ioctl(3, FIONREAD, [78]) = 0
23:40:18.587394 recvfrom(3, "\361\227\201\200\0\1\0\0\0\1\0\0\6vircon\2nl\0\0\34\0\1\300\f\0\6\0"..., 2005, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("212.83.206.202")}, [16]) = 78
23:40:18.587513 close(3)
Stefan de Konink
  • 61
  • 1
  • 4
  • So what is the question? Beside having a really really bad DNS setup. – mailq Dec 10 '11 at 22:16
  • Can you experiment with different nameservers to see if it only occurs with a particular nameserver? – growse Dec 10 '11 at 22:17
  • I have already tried 6 dns servers. Given that there is an instant reply on wget -4, wget -6, dig, host. I doubt it is DNS. It is the resolver itself. (Or something that the resolver executes...) – Stefan de Konink Dec 10 '11 at 22:25
  • 1
    Can you compare and contrast the `strace` / `tcpdump` output between the `wget` that's causing issues and a more successful `wget -4` or `dig`? – growse Dec 10 '11 at 22:32
  • I am currently trying to reproduce the issue again using strace; but like this afternoon using strace as wrapper the resolving works, but without it, resolving fails. – Stefan de Konink Dec 10 '11 at 22:39
  • I think it is all about the 'Timeout', but what exactly times out there? – Stefan de Konink Dec 10 '11 at 22:50
  • 1
    I must admit I'm not sure what's going on here. The only insight I can offer is that `wget` is making both `A` and `AAAA` requests and could be waiting for both to return before returning the resolution result. Specifying `-4` narrows it down to a single request which goes through instantly. Why this happens, don't know :( – growse Dec 10 '11 at 22:59
  • We have just figured out that: "options single-request" works around the issue... I'll follow up. – Stefan de Konink Dec 10 '11 at 23:05

2 Answers2

11

Your problem is described on http://udrepper.livejournal.com/20948.html, and is caused by a parallel lookup on both IPv4 and IPv6 which doesn't work together with some DNS servers and firewalls.

It can be fixed by adding "single-request" to the options in /etc/resolv.conf as the link above mentions.

Maarten Bremer
  • 126
  • 1
  • 2
1

If you prefer NetworkManager service, then using nmtui/nmcli is better. (the following cmds tested on centos7)

change setting (for those who suffering from 5s DNS delay problem)

nmcli con modify YourConnName ipv4.dns-options "single-request-reopen timeout:2"

you can find YourConnName by executing : nmcli con show

apply setting

nmcli con down YourConnName ; nmcli con up YourConnName

P.S. change the setting to default, which is empty

nmcli c m YourConnName ipv4.dns-options ''

Hosi Golden
  • 111
  • 4