Libnetwork: The number of max concurrent queries for the dns resolver is 100

[axblum]

I am curious to understand why the number is capped at 100, and why its not something that is currently configurable

https://github.com/docker/libnetwork/blob/7e5ff9e9cb4b91cee895cdfa7a7786b3886c366f/resolver.go#L70

Docker info:
```Containers: 6
Running: 3
Paused: 0
Stopped: 3
Images: 3
Server Version: 17.12.0-ce
Storage Driver: overlay2
Backing Filesystem: xfs
Supports d_type: true
Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: active
NodeID: zlxybspzhlzlk1wf4z9zdyni3
Is Manager: true
ClusterID: 3medqkdj1yp2mv891g7wpw0xt
Managers: 3
Nodes: 3
Orchestration:
Task History Retention Limit: 5
Raft:
Snapshot Interval: 10000
Number of Old Snapshots to Retain: 0
Heartbeat Tick: 1
Election Tick: 3
Dispatcher:
Heartbeat Period: 5 seconds
CA Configuration:
Expiry Duration: 3 months
Force Rotate: 0
Autolock Managers: false
Root Rotation In Progress: false
Node Address: 10.232.7.251
Manager Addresses:
10.232.5.189:2377
10.232.6.4:2377
10.232.7.251:2377
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 89623f28b87a6004d4b785663257362d1658a729
runc version: b2567b37d7b75eb4cf325b77297b140ea686ce8f
init version: 949e6fa
Security Options:
seccomp
Profile: default
Kernel Version: 4.4.112-1.el7.elrepo.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 3.624GiB
Name: node001.sre.exelator.net
ID: 4MNB:2H6T:7FV4:MTR2:O7V7:SXIQ:TPYG:GON4:57PZ:K74K:QOGU:QPI5
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
aws.az=us-east-1e
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false

Supporting Error Messages: 

Feb 21 13:26:40 node001.sre.exelator.net dockerd[1158]: time="2018-02-21T13:26:40.143437780-05:00" level=error msg="[resolver] more than 100 concurrent queries from 172.18.0.5:59382"
Feb 21 13:26:57 node001.sre.exelator.net dockerd[1158]: time="2018-02-21T13:26:57.180634044-05:00" level=error msg="[resolver] more than 100 concurrent queries from 172.18.0.5:44649"
Feb 21 13:27:31 node001.sre.exelator.net dockerd[1158]: time="2018-02-21T13:27:31.655002339-05:00" level=error msg="[resolver] more than 100 concurrent queries from 172.18.0.5:50674"
```

[ddebroy]

@axblum we can look into making the limit configurable on a per-host basis. Can you share some details about your use case where you are running into the limit?

[hhsnow]

I work w/ @axblum. We're running into it when running zabbix-proxy container (https://github.com/zabbix/zabbix-docker) on a swarm cluster. The zabbix-proxy will connect to agents running on target hosts outside the docker swarm cluster and acquire metrics. If monitoring several dozen remote servers & collecting several dozen metrics from each per time interval, you can end up with a lot of simultaneous dns lookups.

[j-haj]

@ddebroy Is there a preferred approach to making this configurable? I have a fix that simply changes maxConcurrent to a variable and creates a public setter.

[rdxmb]

@ddebroy Here are some details:

• 2 workers
• 1 manager
• Containerized infrastructure with a reverseproxy running as a docker container
• 9 docker stacks
• 33 docker services
• a monitoring container running telegraf to monitor http-content on websites

worker1.rdx-dev.com:/mnt/docker/stacks/base/reverseproxy/sites# grep -c 'more than 100 concurrent queries from' /var/log/syslog
3629
worker1.rdx-dev.com:/mnt/docker/stacks/base/reverseproxy/sites# grep -c 'more than 100 concurrent queries from' /var/log/syslog.1
14890

I cannot believe that docker - which is designed for largest server farms - has a hard limit like that ...

[euanh]

@rdxmb, @hhsnow: Can you please tell us a bit more about your DNS configuration?

• How many upstream DNS resolvers are configured?
• How many DNS search domains are configured?
• Have you overridden the ndots configuration option? (This says that queries containing fewer than this number of dots should be tried against every entry in the search list)

These settings come from the host's /etc/resolv.conf by default, but they can be overridden by command line parameters: https://docs.docker.com/v17.09/engine/userguide/networking/configure-dns/

Also, do you have any data on the general performance of the upstream DNS service?

• Roughly how many new DNS queries are being made each second?
• What proportion of upstream queries are searched against the search domain list (i.e. have fewer than ndots)? You won't be able to see this from outside the cluster, only from the requests being made by the applications running inside your containers.
• What proportion of queries result in errors, timeouts or NXDOMAIN from the upstream resolvers? If you have debug logging turned on, look for [resolver] send to DNS server failed and [resolver] read from DNS server failed in the logs.
• How long on average do the upstream resolvers take to respond to queries?

Don't worry if you don't have information for all these questions. I'm trying to figure out whether a combination of high request rate combined with slow responses could be causing you to hit the 100 concurrent query limit.

[NirBenor]

@euanh We also stepped into this issue.
Our use case is an app which resolves many async reverse-dns lookups using getnameinfo

Regarding our DNS configuration:
The container runs inside an Azure machine, and we do not override ndots or any other resolv.conf params. These errors occur using both Azure's internal DNS (168.63.129.16 as seen in the logs: https://blogs.msdn.microsoft.com/mast/2015/05/18/what-is-the-ip-address-168-63-129-16/
) and google DNS (8.8.8.8 and 8.8.4.4).

We ran the docker daemon in debug for a while, and copied the relevant logs of that time period.
It appears that some (~4%) of the queries result in i/o timeout errors.
We have lots of concurrent queries (we might get a few thousands per second), so a small percent of timed out queries may indeed reach that hardcoded value.

We would also be happy to see this being configurable.

root@<host> /d/l/# cat /tmp/messages.log | grep "IP To resolve" | wc -l
11304
root@<host> /d/l/# cat /tmp/messages.log | grep "read from DNS server failed" | wc -l
436

Example logs:

Jun  3 14:33:40 <host> dockerd: time="2018-06-03T14:33:40.445877950Z" level=error msg="[resolver] more than 100 concurrent queries from 172.18.0.5:60717"
Jun  3 14:34:54 <host> dockerd: time="2018-06-03T14:34:54.287485609Z" level=error msg="[resolver] more than 100 concurrent queries from 172.18.0.5:45515"

Jun  3 13:02:43M <host> dockerd: time="2018-06-03T13:02:43.488327639Z" level=debug msg="[resolver] read from DNS server failed, read udp 172.18.0.2:38747->168.63.129.16:53: i/o timeout"
Jun  3 13:02:43 <host> dockerd: time="2018-06-03T13:02:43.531057926Z" level=debug msg="[resolver] read from DNS server failed, read udp 172.18.0.2:46057->168.63.129.16:53: i/o timeout"

[rdxmb]

worker1.rdx-dev.com:~# grep dns-nameservers /etc/network/interfaces
        dns-nameservers 10.139.0.110
        dns-nameservers 8.8.8.8
worker1.rdx-dev.com:~# grep dns-search /etc/network/interfaces
        dns-search dc1.rdx-dev.com

10.139.0.110 -> virtual IP of the workers, which contain a running dnsmasq-container

Also, do you have any data on the general performance of the upstream DNS service?

Not by now, but I will implement a monitoring-check for that.

I'm trying to figure out whether a combination of high request rate combined with slow responses could be causing you to hit the 100 concurrent query limit.

The errors here only occured in our staging-environment. The traffic there is almost zero. I don't have the errors or logs in our production environment.

---

Is there a way to get logs about the dns-queries at the docker-engine/containerd ? So I could have a look from which service/container the requests are coming.

[euanh]

@rdxmb If you can run Docker in debug mode, the resolver will log queries, responses, connection and backend failures. The interesting log lines will be prefixed with [resolver].

Please note that this will turn on debug mode globally so you will get a lot more logging output.

[rdxmb]

@euanh Thanks.

Just seems that I have 2000005 debug entries within about 2 hours. Time to debug, what's going on here ...

[euanh]

@rdxmb Are those all just from the resolver, or in total? Turning on debug mode will make every component print debug logs, not just the resolver.

[rdxmb]

just the resolver. File-upload will follow ...

[rdxmb]

@euanh Here are the logs of the resolver in syslog:
https://github.com/rdxmb/docker_dns

Questions:

1. is it "normal" that dockerd tries to resolve IPv6 addresses when IPv6 is not explicitly enabled?
   -> https://docs.docker.com/config/daemon/ipv6/

{
worker1.rdx-dev.com:/tmp/docker_dns# cat /etc/docker/daemon.json
    "log-driver": "json-file",
      "log-opts": {"max-size": "10m", "max-file": "3"},
      "log-level": "error",
      "debug": true
}

1. Is it "normal" that internal "names" (like service-hashes) are tried to resolve externally?
   Jun 4 14:19:24 worker1 dockerd[25497]: time="2018-06-04T14:19:24.843388137+02:00" level=debug msg="[resolver] query b715b3bdb53a.dc1.rdx-dev.com. (A) from 172.18.0.24:52620, forwarding to udp:10.139.0.110"

2. Is it "normal" that docker-hashes like 32f19f76803d are suffixed with the dns-search dc1.rdx-dev.com defined in /etc/network/interfaces ?

Just for your information: The nameserver 8.8.8.8 was removed on my host before writing those debug logs, so actually this is:

worker1.rdx-dev.com:/tmp/docker_dns# cat /etc/resolv.conf 
# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver 10.139.0.110
search dc1.rdx-dev.com

[euanh]

@rdxmb Thanks for the logs, those are very useful. It's going to take me a bit of time to sift through them... :)

[euanh]

@rdxmb Regarding your questions:

1. Yes, this is normal, but the IPv6 queries are coming from the libc resolver in your containers, not dockerd. In these cases dockerd is just proxying requests, it does not make IPv6 lookups on its own.
   You can see the difference by watching the logs and running dig www.docker.com and then curl www.docker.com:

   • dig doesn't use libc's resolver and just makes the query you ask; on my machine I only see an A query.
   • curl uses libc's resolver; on my machine I see an A query and an AAAA query, even though my container doesn't have any IPv6 addresses configured. curl picks one of the returned IPv4 addresses to connect to www.docker.com.

2. Yes, this happens when the internal name does not match a container in the same stack as the container making the query. dockerd's resolver first tries to find a matching container and, if it can't, it forwards the query to the upstream DNS server. If the upstream server replies, dockerd's resolver passes the reply back to the requesting container. If the upstream server returns an error or sends no response at all, dockerd retries the search on the next upstream server, if configured.

3. Yes, this is normal, but again this is being done by the resolver running in the container, not by dockerd. You can demonstrate this by changing the search list in /etc/resolv.conf in the container and searching for an external, unqualified name (such as www):

   • First you will see a search for www.
   • If the search for www. fails, the requesting resolver retries the query, appending the first search entry
   • If that search fails, the requesting resolver will work its way through any other configured search paths
     Again, dig behaves differently because it doesn't use the libc resolver; it will only search for www. in this case.

Looking at your logs I still see lots of searches being forwarded to 8.8.8.8. Changes to /etc/resolv.conf on the host will only be picked up by containers created after the change - they won't apply retrospectively to existing containers.

[euanh]

@rdxmb I've had a look through the logs you sent. As you pointed out there are lots of queries for what look like container IDs. dockerd's resolver will try to find a container with a matching name before forwarding the query upstream, but it will only look in the same stack and user-defined network as the requesting container.

Could you please check:

1. that the names being requested correspond to running containers; and
2. if so, that those containers are in the same stack and on the same user-defined network as the container requesting them?

[rdxmb]

Looking at your logs I still see lots of searches being forwarded to 8.8.8.8. Changes to /etc/resolv.conf on the host will only be picked up by containers created after the change - they won't apply retrospectively to existing containers.

Ok, just cleaning up everything and starting just one stack after another.

Just to get it right:

Jun  5 17:36:30 worker1 dockerd[25497]: time="2018-06-05T17:36:30.309978748+02:00" level=debug msg="[resolver] external DNS udp:10.139.0.110 did not return any AAAA records for \"vip.dc1.rdx-dev.com.\""
Jun  5 17:36:31 worker1 dockerd[25497]: time="2018-06-05T17:36:31.082801740+02:00" level=debug msg="[resolver] external DNS udp:10.139.0.110 did not return any AAAA records for \"ciss.rdx-dev.com.\""
Jun  5 17:36:40 worker1 dockerd[25497]: time="2018-06-05T17:36:40.307157022+02:00" level=debug msg="[resolver] query vip.dc1.rdx-dev.com. (A) from 172.18.0.6:41111, forwarding to udp:10.139.0.110"
Jun  5 17:36:40 worker1 dockerd[25497]: time="2018-06-05T17:36:40.308085639+02:00" level=debug msg="[resolver] query vip.dc1.rdx-dev.com. (AAAA) from 172.18.0.6:60326, forwarding to udp:10.139.0.110"
Jun  5 17:36:40 worker1 dockerd[25497]: time="2018-06-05T17:36:40.308199859+02:00" level=debug msg="[resolver] received A record \"10.139.0.110\" for \"vip.dc1.rdx-dev.com.\" from udp:10.139.0.110"
Jun  5 17:36:40 worker1 dockerd[25497]: time="2018-06-05T17:36:40.309690905+02:00" level=debug msg="[resolver] external DNS udp:10.139.0.110 did not return any AAAA records for \"vip.dc1.rdx-dev.com.\""
Jun  5 17:36:50 worker1 dockerd[25497]: time="2018-06-05T17:36:50.307877918+02:00" level=debug msg="[resolver] query vip.dc1.rdx-dev.com. (AAAA) from 172.18.0.6:55719, forwarding to udp:10.139.0.110"
Jun  5 17:36:50 worker1 dockerd[25497]: time="2018-06-05T17:36:50.308483427+02:00" level=debug msg="[resolver] query vip.dc1.rdx-dev.com. (A) from 172.18.0.6:50127, forwarding to udp:10.139.0.110"
Jun  5 17:36:50 worker1 dockerd[25497]: time="2018-06-05T17:36:50.309005547+02:00" level=debug msg="[resolver] external DNS udp:10.139.0.110 did not return any AAAA records for \"vip.dc1.rdx-dev.com.\""
Jun  5 17:36:50 worker1 dockerd[25497]: time="2018-06-05T17:36:50.310229573+02:00" level=debug msg="[resolver] received A record \"10.139.0.110\" for \"vip.dc1.rdx-dev.com.\" from udp:10.139.0.110"

is one query-line in the log really one query within dockerd - so we could count them per time unit?

[euanh]

is one query-line in the log really one query within dockerd - so we could count them per time unit?

Yes. We log query <query> (<type>) from... just before each attempt to forward a query.

The next log line will depend on the outcome of the query:

• more than 100 concurrent queries...: hit the limiter; retry with the next upstream server (if any)
• send to DNS server failed: most likely a TCP failure; retry with the next upstream server
• read from DNS server failed: most likely a time out; retry with the next upstream server
• external DNS <server> responded with ServFail: server error; retry with the next upstream server
• received <type> record...: success, results found; return to client
• external DNS <server> did not return any <type> records...: success, no results found; return to client
• external DNS <server> returned empty response...: success, no results found; return to client

[rdxmb]

@euanh

Could you please check:

that the names being requested correspond to running containers; and

There are no containers with that ids, checked with docker ps | grep <ID> and even with docker ps -qa | grep <ID>

[euanh]

@rdxmb If you are running in a multi-node swarm, remember to check on other nodes.

It looks like your application is making thousands of DNS lookups for non-existent containers. dockerd's resolver fail to find addresses for these container IDs and will forward all these queries to your upstream DNS server. From time to time this extra lookup load is causing you to hit the concurrent lookup limiter.

Probably the next thing to investigate is why your application is looking up non-existent containers - is there a cache or stale data somewhere which needs to be flushed?

[rdxmb]

If you are running in a multi-node swarm, remember to check on other nodes.

I already did.

Just removed all stacks except one and run the syslog-logrotate -> The syslog does not contain any IDs for dns-queries.

Deployed another stack -> the syslog is "full" with queries for different unique ids:

cat /var/log/syslog | grep query | cut -f11 -d' ' | grep -v 'rdx-dev.com' | sort | uniq | wc -l
261

This does not look like a cache, for the services have just started.

Actually, one service is restarting in a loop because of a configuration error. However, this is not a reason for so many enquired ids/containers.

[euanh]

@rdxmb The question is: _why_ is your application looking up these IDs, and so often? If we are right in assuming that they are container IDs, perhaps they existed at some point, your application logged their existence and is now trying to find them again.

Since these hashes don't correspond to existing containers, it looks like dockerd's resolver is working as designed by passing them to the upstream DNS server.

[rdxmb]

The question is: why is your application looking up these IDs, and so often?

I don't know. This also is not "my application" running here. All these are official images of the TICK Stack.

# grep image docker-stack.yml 
    image: chronograf:1.4.3
    image: kapacitor:1.4.1
    image: "influxdb:1.4"
    image: "grafana/grafana:5.1.3"

I will try to reproduce this with other stacks. If it is not possible, it's time to debug the application. If it is possible, we have to go on here ...

[rdxmb]

seems like my influxdb-instance is running out of control - with making ten-thousands of requests to not-existing IDs. When running a new influxdb-instance, the problem is not reproducable.

If you hear nothing different the next days, my problems above can be ignored for this case.

@euanh Have many thanks for your help!

[euanh]

@rdxmb You're welcome!

[rdxmb]

problem solved. Issue can be closed for my case.

[vladimir-avinkin]

Greetings. To me it seems that the original question was not answered.

I am curious to understand why the number is capped at 100, and why its not something that is currently configurable

This limit can be quite easily reached with legitimate concurrent network code, and there are no easy workarounds.

@euanh @fcrisciani

[hhsnow]

Hi @euanh and @fcrisciani, I also concur that this should not have been closed. Take the example that Andrew and I opened this issue with -- monitoring software that creates a dns request per metric per monitored server. You can very easily exceed this 100 qps threshold monitoring 36 metrics on 50 servers with a monitoring interval of 30 seconds.

[vladimir-avinkin]

Initial commit also lack any rationale behind the introduction of this constant
https://github.com/docker/libnetwork/commit/f9b23d3a3b8794ffa88dc7a0d9b252a2ac1fedfc

[thaJeztah]

Initial commit also lack any rationale behind the introduction of this constant

Slightly more details can be found in https://github.com/moby/moby/issues/22185. If you're using a public DNS, also be sure to check if they have a rate limit. For example, Google's DNS servers also have a rate limit of 100 QPS (but can be raised on request); if you hit that rate limit, DNS responses will fail/stall, which would result in the queue /failures in docker's embedded DNS to grow as well