Investigating slow DNS resolution in container

Some time ago, I had a curious case of very slow DNS resolution in a container on OpenShift. The symptoms were as follows:

  • In the PHP application in the container, DNS resolution was very slow with a 5 second delay before the lookup was resolved
  • In the container itself, DNS resolution for curl was very slow, with a 5 second timeout before the lookup was resolved
  • However, using dig in the container itself, DNS resolution was instant
  • Also, on the worker node, the DNS resolution was instant (using both dig and curl)

TL;DR: Since glibc 2.10, glibc performs IPv4 and IPv6 lookups in parallel. When IPv6 fails, there is a 5 second timeout in many cases before the lookup is returned. Disable IPv6 DNS lookups by setting “single-request” in “resolv.conf” or disable the IPv6 stack completely.

To debug the issue, I started curl in the container and used the --write-out option to show me where time was lost:

curl -vvv --header --write-out '\nlookup:        %{time_namelookup}\nconnect:       %{time_connect}\nappconnect:    %{time_appconnect}\npretransfer:   %{time_pretransfer}\nredirect:      %{time_redirect}\nstarttransfer: %{time_starttransfer}\ntotal:         %{time_total}\n' https://myapp.something.ch/something
[..]
lookup:        5.517
connect:       5.522
appconnect:    5.869
pretransfer:   5.873
redirect:      0.000
starttransfer: 7.187
total:         7.193

So clearly, the DNS lookup is taking too much time. Seeing that the lookup always takes around 5 seconds, we quickly suspected some kind of timeout. However, dig in the container was always instant in looking up DNS. That was strange. So we started to actually strace the process to see what happens:

strace -e trace=network -r -f curl -vvv --write-out '\nlookup:        %{time_namelookup}\nconnect:       %{time_connect}\nappconnect:    %{time_appconnect}\npretransfer:   %{time_pretransfer}\nredirect:      %{time_redirect}\nstarttransfer: %{time_starttransfer}\ntotal:         %{time_total}\n' https://myapp.something.ch/something
[..]
     0.000000 socket(AF_INET6, SOCK_DGRAM, IPPROTO_IP) = 3
strace: Process 45 attached
[pid    45]      0.001007 socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid    45]      0.000153 connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid    45]      0.000804 socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid    45]      0.000156 connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid    45]      0.006068 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 3
[pid    45]      0.000143 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.140.10.217")}, 16) = 0
[pid    45]      0.000252 sendmmsg(3, {{{msg_name(0)=NULL, msg_iov(1)=[{"~\352\1\0\0\1\0\0\0\0\0\0\10myapp\tsomething\2"..., 63}], msg_controllen=0, msg_flags=MSG_OOB|MSG_DONTROUTE}, 63}, {{msg_name(0)=NULL, msg_iov(1)=[{"\0022\1\0\0\1\0\0\0\0\0\0\10myapp\tsomething\2"..., 63}], msg_controllen=0, msg_flags=0}, 63}}, 2, MSG_NOSIGNAL) = 2
[pid    45]      0.001548 recvfrom(3, "\0022\201\203\0\1\0\0\0\1\0\0\10myapp\tsomething\2"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.140.10.217")}, [16]) = 156

[pid    45]      5.003512 sendto(3, "~\352\1\0\0\1\0\0\0\0\0\0\10myapp\tsomething\2"..., 63, MSG_NOSIGNAL, NULL, 0) = 63
[pid    45]      0.001415 recvfrom(3, "~\352\201\203\0\1\0\0\0\1\0\0\10myapp\tsomething\2"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.140.10.217")}, [16]) = 156
[pid    45]      0.000486 sendto(3, "\0022\1\0\0\1\0\0\0\0\0\0\10myapp\tsomething\2"..., 63, MSG_NOSIGNAL, NULL, 0) = 63
[..]

So it looks like our DNS was responding pretty quickly, but our client would not continue until the 5 seconds have passed. Our containers were not using IPv6, so when I saw AF_INET6 in the log above, we quickly suspected something was going on with IPv6.

In the resolv.conf man page, we just CTRL-F’d for “timeout” and quickly came across the section mentioning:

By default, glibc performs IPv4 and IPv6 lookups in parallel since version 2.9. Some appliance DNS servers cannot handle these queries properly and make the requests time out. This option disables the behavior and makes glibc perform the IPv6 and IPv4 requests sequentially (at the cost of some slowdown of the resolving process).

So it turns out that our worker node had an older version of “glibc” installed and was therefore not affected by this change. However, our container had a current version of “glibc”, which is why it showed the behaviour above. Also, as far as I can tell, dig is not using “glibc” to resolve addresses, which is why we did not see the behaviour there.

So by setting single-request in our resolv.conf, we were able to resolve the issue of DNS resolution timeouts.

Comments

Oh no, new comments are currently disabled.
If you want to get in touch with me, please do so via e-mail: