5 second delay on any resolving

Message

Skinkie · Post by **Skinkie** » Sat Dec 10, 2011 2:21 pm

Using wget 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.

The strace output of this is:

Code: Select all

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

The tcpdump output is:

Code: Select all

 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)

The problem isn't wget related it also happens on anything else like curl, httplib2, etc.

Post by Hu » Sat Dec 10, 2011 5:55 pm

What is the output of emerge --info ; cat -n /etc/resolv.conf?

Skinkie · Post by **Skinkie** » Sat Dec 10, 2011 8:26 pm

Hu wrote:What is the output of emerge --info ; cat -n /etc/resolv.conf?

Code: Select all

emerge --info ; cat -n /etc/resolv.conf
Portage 2.1.10.39 (default/linux/amd64/10.0/no-multilib, gcc-4.5.3, glibc-2.14.1-r1, 3.1.4-gentoo x86_64)
=================================================================
System uname: Linux-3.1.4-gentoo-x86_64-Intel-R-_Pentium-R-_Dual_CPU_E2220_@_2.40GHz-with-gentoo-2.1
Timestamp of tree: Fri, 09 Dec 2011 15:15:01 +0000
app-shells/bash:          4.2_p20
dev-java/java-config:     2.1.11-r3
dev-lang/python:          2.6.7-r2, 2.7.2-r3
dev-util/cmake:           2.8.1-r2
dev-util/pkgconfig:       0.26
sys-apps/baselayout:      2.1
sys-apps/openrc:          0.9.4
sys-apps/sandbox:         2.5
sys-devel/autoconf:       2.68
sys-devel/automake:       1.10.3, 1.11.1-r1
sys-devel/binutils:       2.22
sys-devel/gcc:            4.3.4, 4.4.5, 4.5.3-r1
sys-devel/gcc-config:     1.5-r2
sys-devel/libtool:        2.4.2
sys-devel/make:           3.82-r3
sys-kernel/linux-headers: 2.6.39 (virtual/os-headers)
sys-libs/glibc:           2.14.1-r1
Repositories: gentoo
ACCEPT_KEYWORDS="amd64 ~amd64"
ACCEPT_LICENSE="*"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -pipe -march=nocona"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/env.d/java/ /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo"
CXXFLAGS="-O2 -pipe -march=nocona"
DISTDIR="/usr/portage/distfiles"
FEATURES="assume-digests binpkg-logs distlocks ebuild-locks fixlafiles news parallel-fetch protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch"
FFLAGS=""
GENTOO_MIRRORS="http://distfiles.gentoo.org"
LC_ALL="nl_NL.utf8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
LINGUAS="nl en"
PKGDIR="/usr/portage/packages"
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_EXTRA_OPTS="--exclude-from=/etc/portage/rsync_excludes"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages"
PORTAGE_TMPDIR="/var/tmp"
PORTDIR="/usr/portage"
PORTDIR_OVERLAY=""

SYNC="rsync://rsync.nl.gentoo.org/gentoo-portage"
USE="acl amd64 berkdb bzip2 cli cracklib crypt cups cxx dri fontconfig gdbm geoip gpm iconv ipv6 jpeg lzma mmx modules ncurses nptl nptlonly odbc openmp openssl pcre png pppd python2 readline session sqlite sse sse2 ssl sysfs tcpd threads truetype unicode xorg zlib" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="kexi words flow plan stage tables krita karbon braindump" CAMERAS="ptp2" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ubx" INPUT_DEVICES="keyboard mouse evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="nl en" PHP_TARGETS="php5-3" RUBY_TARGETS="ruby18" USERLAND="GNU" VIDEO_CARDS="fbdev glint intel mach64 mga neomagic nouveau nv r128 radeon savage sis tdfx trident vesa via vmware dummy v4l" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account"
Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, INSTALL_MASK, LANG, MAKEOPTS, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS

     1  #nameserver 2001:4018:3:12::202
     2  #nameserver 2001:4018:1:64::202
     3  nameserver 212.83.206.202
     4  #nameserver 213.207.64.202
     5  #nameserver 8.8.8.8
     6  #nameserver 8.8.4.4

Thanks in advance for helping me to trace down the debug. Reading various forums mdns was said to be the bugger, but I do not have mdns enabled at all.

When adding "options timeout:2" to /etc/resolv.conf the length does reduce to 2 seconds delay.

Using "option single-request" in /etc/resolv.conf I can workaround the issue... now need to figure out what causes this.

whig · Post by **whig** » Sun Dec 11, 2011 12:36 am

Sniff the traffic with wireshark.