Non existent host causes 100% cpu utilization by systemd-resolved and dnsmasq

[Fodder]

May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] googletagservices.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded googletagservices.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1
May 04 13:32:07 cannon-fodder dnsmasq[8101]: forwarded cf.shareasimage.com to 127.0.0.53
May 04 13:32:07 cannon-fodder dnsmasq[8101]: query[A] cf.shareasimage.com from 127.0.0.1

[Fodder (aaroncosand)]

affects 17.04 - worked fine on 16.10 and 16.04

[Christian Ehrhardt  (paelzer)]

Hi Aaron (I didn't want to call someone fodder :-) )
Thank you for taking the time to report this bug and helping to make Ubuntu better.
I'm interested in the regression you might have found.

The log looks like a forwarding loop on a ?cloudflare server?. I haven't seen the issue myself in all my virt work where dnsmasq is mostly around, I'm afraid you'll have to share a bit more details on your setup.
- How did you install/setup/configure dnsmasq/systemd-resolved
- Which host isn't existing the one you are resolving or one that you manage with dnsmasq?
- What are the commands to trigger this?

So far there isn't really enough information here for a developer to confirm this issue is a bug, or to begin working on it, so I am marking this bug Incomplete for now.

If you can provide exact steps so that a developer can reproduce the original problem, then please add them to this bug and change the status back to New.

[Fodder (aaroncosand)]

This is a workstation, not a virtual

dnsmasq and systemd are installed from the ubuntu repos (I'm on 17.04)

I've done a full uninstall of dnsmasq (apt-get remove --auto-remove --purge dnsmasq, manually deleting /etc/dnsamsq.d, apt list --installed *dnsmasq* to confirm everything was removed and then apt-get install dnsmasq

I have a cron script that generates a config file for dnsmasq that directs a number of ad server domains to 127.0.0.1. The file has a series of address= entries and is copied into /etc/dnsmasq.d

Upon further investigation it isn't an invalid host that seems to be causing the problem, but if I go to the following page in firefox (again normal install from repos), it generates the error consistently: http://science.howstuffworks.com/reverse-osmosis.htm

[Fodder (aaroncosand)]

I uncommented dns-loop-detect in /etc/dnsmasq.conf, but this didn't change anything.

[Fodder (aaroncosand)]

In the page source, the error seems to occur when there are dns-prefetch entries on a web page, as this is the only reference to the host that was being repeated in my log (<link rel="dns-prefetch" href="//cf.shareasimage.com">), and with dnsmasq turned off (so it should just use the dns servers from my ISP) cf.shareasimage.com can't be resolved

$ nslookup cf.shareasimage.com
Server: 127.0.0.53
Address: 127.0.0.53#53

Non-authoritative answer:
*** Can't find cf.shareasimage.com: No answer

The parent domain can be found though:
nslookup shareasimage.com
Server: 127.0.0.53
Address: 127.0.0.53#53

Non-authoritative answer:
Name: shareasimage.com
Address: 52.32.185.55
Name: shareasimage.com
Address: 54.191.249.219

[Christian Ehrhardt  (paelzer)]

Thanks for all the details,
I tried to reproduce on 17.04 as that is the release it shows up for you.

In a new zesty container first without dnsmasq installed I see the follwing base config in /etc/resolve.conf:
- 10.0.4.1 is my local dns which forwards to my provider
- 127.0.0.53 of systemd-resolv on second place.
Neither of those can resolve the host as expected.
$ nslookup cf.shareasimage.com
$ nslookup cf.shareasimage.com 127.0.0.53
[...]
both don't find it.

Installing dnsmasq changes resolv conf to:
- 127.0.0.1 which s dnsmasq
In turn dnsmasq has the old two dns servers in its /run/dnsmasq/resolv.conf
Still none of the tries to resolve work - as expected - but also none fall into a loop.

I placed the adblock config you had, but still no loop.

I enabled log-queries as you had and here is what I get to compare:
dnsmasq[1217]: query[A] cf.shareasimage.com from 127.0.0.1
dnsmasq[1217]: forwarded cf.shareasimage.com to 10.0.4.1
dnsmasq[1217]: forwarded cf.shareasimage.com to 127.0.0.53
dnsmasq[1217]: query[A] cf.shareasimage.com from 127.0.0.1
dnsmasq[1217]: forwarded cf.shareasimage.com to 10.0.4.1

If I re-lookup very fast it only ahs one forward end replies the not-found.
If I wait a while it asks both again.

Now compared to your setup mine asks systemd-resolvd on 127.0.0.53 AND my provider via the router on 10.0.4.1. In you initial log I never saw this.
Maybe there is the issue, what had your /etc/resolv.conf before installing?
And in turn what has you /run/dnsmasq/resolv.conf?

Trying to force that with an intentionally broken /run/dnsmasq/resolv.conf taking out the uplink DNS and only leaving systemd-resolvd there and then reloading the service recreates your case I think.

After a while nslookup and such give up with:
$ nslookup cf.shareasimage.com
;; connection timed out; no servers could be reached

But the log has about 20 forwarding entries, it seems that systemd-resolvd gives an answer causing this - we know it can't resolve the dns already.
But it is not looping forever, once the client gives up it stops - or vice versa I assume once dnsmasq gives up on trying it returns the timeout.

Now for case I'd almost consider that a broken DNS config, pelase check your /run/dnsmasq/resolv.conf and why it might miss the uplink DNS.

[Fodder (aaroncosand)]

Just a note: nslookup doesn't produce the error, accessing http://science.howstuffworks.com/reverse-osmosis.htm through firefox or chromium does.

/etc/resolv.conf is symlinked to ../run/resolvconf/resolv.conf
I assume that this is the default option (and dnsmasq issues a warning if it isn't symlinked to this file)

***with dnsmasq stopped***

/etc/resolv.conf
nameserver 127.0.0.53

/run/systemd/resolve/resolv.conf
nameserver 192.168.2.1

***after starting dnsmasq***

/etc/resolv.conf
nameserver 127.0.0.1

/run/systemd/resolve/resolv.conf
nameserver 192.168.2.1

/run/dnsmasq/resolv.conf
nameserver 127.0.0.53

[Christian Ehrhardt  (paelzer)]

Yeah the link is fine.

But more interesting is that dnsmasq only seems to "care" about reading from /etc/resolv.conf, but ignored your setup in /run/systemd/resolve/resolv.conf.

In my working case I had the provider DNS in /etc/resolv.conf but you only had it in /run/systemd/resolve/resolv.conf (I have it there as well, but as I said -also- in /etc/resolv.conf).

Due to that your dnsmasq doesn't know about the "uplink-dns" and fail-loops on the systemd-resolvd.
In that sense it doesn't do it wrong, it reads /etc/resolv.conf (as is its default in /etc/dnsmasq.conf and thereby only picks up the systemd-resolved ip, but not the uplink).

We have to understand how/why your /etc/resolv.conf is the way it is (without the uplink dns).

[Christian Ehrhardt  (paelzer)]

Since this might be as much about "resolvconf" than it is about dnsmasq I add a bug task.
In some sense this is both:
a) dnsmasq not picking up info of systemd-resolve
b) resolvconf not adding uplink-dns in /etc/resolv.conf

We have to understand b) to know if a) is a bug

[Christian Ehrhardt  (paelzer)]

Could you report the output of your systems call to this?:
$ /usr/share/resolvconf/dump-debug-info

You can see that in my case resolvconf gets the uplink info via /run/resolvconf/interface/eth0.dhclient, how does your system get its config - dhcp as well?
If so are you having a comparable file?

Here mine from a more or less default zesty container.
###### Start of debugging information for resolvconf ######
### ls -l /etc/resolvconf
total 12
-rw-r--r-- 1 root root 511 Apr 1 2016 interface-order
drwxr-xr-x 2 root root 4096 Apr 25 01:15 resolv.conf.d
drwxr-xr-x 2 root root 4096 May 8 11:18 update.d
### cat /etc/resolvconf/interface-order
# interface-order(5)
lo.inet6
lo.inet
lo.@(dnsmasq|pdnsd)
lo.!(pdns|pdns-recursor)
lo
tun*
tap*
hso*
em+([0-9])?(_+([0-9]))*
p+([0-9])p+([0-9])?(_+([0-9]))*
@(br|eth)*([^.]).inet6
@(br|eth)*([^.]).ip6.@(dhclient|dhcpcd|pump|udhcpc)
@(br|eth)*([^.]).inet
@(br|eth)*([^.]).@(dhclient|dhcpcd|pump|udhcpc)
@(br|eth)*
@(ath|wifi|wlan)*([^.]).inet6
@(ath|wifi|wlan)*([^.]).ip6.@(dhclient|dhcpcd|pump|udhcpc)
@(ath|wifi|wlan)*([^.]).inet
@(ath|wifi|wlan)*([^.]).@(dhclient|dhcpcd|pump|udhcpc)
@(ath|wifi|wlan)*
ppp*
*
### ls -l /etc/resolvconf/resolv.conf.d
total 4
-rw-r--r-- 1 root root 0 Apr 1 2016 base
-rw-r--r-- 1 root root 282 Nov 28 23:37 head
### cat /etc/resolvconf/resolv.conf.d/base
### cat /etc/resolvconf/resolv.conf.d/head
# 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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

### ls -l /run/resolvconf
### ls -l /run/resolvconf
total 4
-rw-r--r-- 1 root root 0 Apr 27 15:54 enable-updates
drwxr-xr-x 2 root root 80 May 8 11:18 interface
-rw-r--r-- 1 root root 335 May 8 11:18 resolv.conf
### cat /run/resolvconf/enable-updates
### cat /run/resolvconf/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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

nameserver 10.0.4.1
nameserver 127.0.0.53
search lxd
### ls -l /run/resolvconf/interface
total 8
-rw-r--r-- 1 root root 31 Apr 27 15:54 eth0.dhclient
-rw-r--r-- 1 root root 22 Apr 27 15:54 systemd-resolved
### cat /run/resolvconf/interface/eth0.dhclient
domain lxd
nameserver 10.0.4.1
### cat /run/resolvconf/interface/systemd-resolved
nameserver 127.0.0.53
### ls -l /etc/resolv.conf
lrwxrwxrwx 1 root root 29 Apr 25 09:54 /etc/resolv.conf -> ../run/resolvconf/resolv.conf
### lsattr /etc/resolv.conf
lsattr: Operation not supported While reading flags on /etc/resolv.conf
### 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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

nameserver 10.0.4.1
nameserver 127.0.0.53
search lxd
### cat /etc/NetworkManag...

[Fodder (aaroncosand)]

###### Start of debugging information for resolvconf ######
### ls -l /etc/resolvconf
total 16
-rw-r--r-- 1 root root 511 May 4 2015 interface-order
drwxr-xr-x 2 root root 4096 Apr 21 10:52 resolv.conf.d
drwxr-xr-x 2 root root 4096 Apr 21 10:11 update.d
drwxr-xr-x 2 root root 4096 Apr 14 10:59 update-libc.d
### cat /etc/resolvconf/interface-order
# interface-order(5)
lo.inet6
lo.inet
lo.@(dnsmasq|pdnsd)
lo.!(pdns|pdns-recursor)
lo
tun*
tap*
hso*
em+([0-9])?(_+([0-9]))*
p+([0-9])p+([0-9])?(_+([0-9]))*
@(br|eth)*([^.]).inet6
@(br|eth)*([^.]).ip6.@(dhclient|dhcpcd|pump|udhcpc)
@(br|eth)*([^.]).inet
@(br|eth)*([^.]).@(dhclient|dhcpcd|pump|udhcpc)
@(br|eth)*
@(ath|wifi|wlan)*([^.]).inet6
@(ath|wifi|wlan)*([^.]).ip6.@(dhclient|dhcpcd|pump|udhcpc)
@(ath|wifi|wlan)*([^.]).inet
@(ath|wifi|wlan)*([^.]).@(dhclient|dhcpcd|pump|udhcpc)
@(ath|wifi|wlan)*
ppp*
*
### ls -l /etc/resolvconf/resolv.conf.d
total 4
-rw-r--r-- 1 root root 0 Oct 10 2014 base
-rw-r--r-- 1 root root 282 Nov 28 18:37 head
### cat /etc/resolvconf/resolv.conf.d/base
### cat /etc/resolvconf/resolv.conf.d/head
# 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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

### ls -l /run/resolvconf
### ls -l /run/resolvconf
total 4
-rw-r--r-- 1 root root 0 May 8 04:17 enable-updates
drwxr-xr-x 2 root root 80 May 8 05:32 interface
-rw-r--r-- 1 root root 303 May 8 05:32 resolv.conf
### cat /run/resolvconf/enable-updates
### cat /run/resolvconf/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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

nameserver 127.0.0.1
### ls -l /run/resolvconf/interface
total 8
-rw-r--r-- 1 root root 21 May 8 05:32 lo.dnsmasq
-rw-r--r-- 1 root root 22 May 8 04:17 systemd-resolved
### cat /run/resolvconf/interface/lo.dnsmasq
nameserver 127.0.0.1
### cat /run/resolvconf/interface/systemd-resolved
nameserver 127.0.0.53
### ls -l /etc/resolv.conf
lrwxrwxrwx 1 root root 29 Jun 11 2015 /etc/resolv.conf -> ../run/resolvconf/resolv.conf
### lsattr /etc/resolv.conf
lsattr: Operation not supported While reading flags on /etc/resolv.conf
### 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
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

nameserver 127.0.0.1
### cat /etc/NetworkManager/NetworkManager.conf
[main]
plugins=ifupdown,keyfile

[ifupdown]
managed=false
###### End of debugging information for resolvconf ######

[Christian Ehrhardt  (paelzer)]

Hi,
ok so you don't have an <interface>.dhclient that provides your dns resolution as provided by dhcp.
Furthermore I see you have a networkmanager config while I have none.

Networkmanager is not in use on Ubuntu Server, but on Desktop. So I assume you are running a [ULK..]Ubuntu Desktop edition while running into this issue?

Also just to confirm your system gets its IP and DNS infos via dhcp is that correct?
I assume that in your case somehow network manager is soaking that up which leads to the issue of dnsmasq not being able to find the info when starting up.

This more and more leaves my area of expertise :-/
Adding a networkmanager task as well for now.

[Christian Ehrhardt  (paelzer)]

As a temporary workaround until this gets proper handling/fix you might (depending on preference and on how static or not your config is):
a) switch back from resolved to dnsmasq as described in [1], you need to follow both answers since you are also running Network Manager
b) set your DNS address in a file in /etc/resolvconf/resolv.conf.d/
c) we understand why/how NetworkManager is stopping/avoiding dhclient to place the info as it had doen for me in /run/resolvconf/interface/eth0.dhclient and fix that. The update hook should be /etc/dhcp/dhclient-enter-hooks.d/resolvconf

[1]: https://askubuntu.com/questions/898605/how-to-disable-systemd-resolved-and-resolve-dns-with-dnsmasq

[Fodder (aaroncosand)]

you are correct:
I am running desktop not server
I am running Network Manager
IP and DNS come from DHCP

I'll try the workaround and let you know.
I'll also fiddle with Network Manager and see if I can sort out what is going wrong

[Fodder (aaroncosand)]

I found this workaround (lets you use dnsmasq with NetworkManager instead of reloved and dnsmasq together

https://askubuntu.com/questions/898605/how-to-disable-systemd-resolved-and-resolve-dns-with-dnsmasq/899338

[Fodder (aaroncosand)]

make sure you add --dns-loop-detect to the command line in /etc/init.d/dnsmasq (I added a line with 'DNSMASQ_OPTS="$DNSMASQ_OPTS --dns-loop-detect"') or you still get cycling after a non-existent host is queried, just not 100% cpu utilization like when both dnsmasq and resolved are running at the same time. In this case, loop detect actually works though.

[Fodder (aaroncosand)]

correction - needed to disable dnsmasq service as network manager starts it instead.

[Steve Langasek (vorlon)]

> correction - needed to disable dnsmasq service as network manager
> starts it instead.

network-manager in 17.04 and later is not expected to start dnsmasq, it integrates with resolved instead. Have you overridden the default network-manager config?

Is it possible your issue is related to LP: #1694156?

[Launchpad Janitor (janitor)]

[Expired for resolvconf (Ubuntu) because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for dnsmasq (Ubuntu) because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for network-manager (Ubuntu) because there has been no activity for 60 days.]