Sudden High CPU Usage With Tailscale VPN and systemd-resolved when dbus restarts

[PythonCoderAS]

What is the issue?

I was running the tailscale VPN daemon (no devices were logged in). Out of nowhere, I heard the fans spin up, and saw that both the tailscale daemon and systemd-resolved were using 100% CPU. I restarted the systemd-resolved service and both processes dropped to near-0 cpu usage.

Steps to reproduce

No response

Are there any recent changes that introduced the issue?

No response

OS

Linux

OS version

Ubuntu 22.04

Tailscale version

1.24.2

Bug report

BUG-ec1aaed5a0ab790bcc95321a028585ebe4ac88a7ebe5dbe6e169105b186c328e-20220508232821Z-057aacabef55d99d

[PythonCoderAS]

Some investigation with the grafana agent led to the discovery of a bunch of log entries that say:

dns: error: context deadline exceeded

[DentonGentry]

tailscaled died with a SIGSEGV, then restarted:

2022-05-08 23:01:06.106216702 +0000 UTC: netcheck: report: udp=true v6=true mapvarydest=false hair=false portmap= v4a=67.250.154.47:41641 v6a=[2603:7000:e43f:9867:7ae3:b5ff:fe6c:9d14]:41641 derp=1 derpdist=1v4:23ms,1v6:23ms,9v4:56ms,12v4:38ms,12v6:38ms
2022-05-08 23:06:42.129198744 +0000 UTC: panic: runtime error: invalid memory address or nil pointer dereference
2022-05-08 23:06:42.129198744 +0000 UTC: [signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x951af8]
2022-05-08 23:06:42.129198744 +0000 UTC: goroutine 51 [running]:
2022-05-08 23:06:42.129198744 +0000 UTC: tailscale.com/net/dns.(*resolvedManager).resync(0xc00009e400, {0xe734b0, 0xc00009a540}, 0xc0000a0660)
2022-05-08 23:06:42.129198744 +0000 UTC:        tailscale.com@v1.24.2/net/dns/resolved.go:141 +0x118
2022-05-08 23:06:42.129198744 +0000 UTC: created by tailscale.com/net/dns.newResolvedManager
2022-05-08 23:06:42.129198744 +0000 UTC:        tailscale.com@v1.24.2/net/dns/resolved.go:111 +0x24f
2022-05-08 23:06:38.084208322 +0000 UTC: logtail started
2022-05-08 23:06:38.088198942 +0000 UTC: Program starting: v1.24.2-t9d6867fb0-g2d0f7ddc3, Go 1.18.1-ts710a0d8610: []string{"/usr/sbin/tailscaled", "--cleanup"}

When it restarted, it decided to use a direct DNS manager (writing to /etc/resolv.conf) not systemd-resolved:

2022-05-08 23:06:43.959922344 +0000 UTC: Program starting: v1.24.2-t9d6867fb0-g2d0f7ddc3, Go 1.18.1-ts710a0d8610: []string{"/usr/sbin/tailscaled", "--state=/var/lib/tailscale/tailscaled.state", "--socket=/run/tailscale/tailscaled.sock", "--port", "41641"}
2022-05-08 23:06:43.959961777 +0000 UTC: LogID: ec1aaed5a0ab790bcc95321a028585ebe4ac88a7ebe5dbe6e169105b186c328e
2022-05-08 23:06:43.968614062 +0000 UTC: logpolicy: using $STATE_DIRECTORY, "/var/lib/tailscale"
2022-05-08 23:06:43.969902153 +0000 UTC: wgengine.NewUserspaceEngine(tun "tailscale0") ...
2022-05-08 23:06:44.068384161 +0000 UTC: router: kernel supports IPv6 policy routing (found 6 rules)
2022-05-08 23:06:44.068496093 +0000 UTC: router: v6nat = true
2022-05-08 23:06:44.077623787 +0000 UTC: router: policy routing available; found 7 rules
2022-05-08 23:06:45.079953691 +0000 UTC: dns: [rc=resolved resolved=no ret=direct]
2022-05-08 23:06:45.080416452 +0000 UTC: dns: using *dns.directManager
2022-05-08 23:06:45.080850561 +0000 UTC: link state: interfaces.State{defaultRoute=enp3s0 ifs={docker0:[172.17.0.1/16] enp3s0:[192.168.1.144/24 2603:7000:e43f:9867:7ae3:b5ff:fe6c:9d14/64]} v4=true v6=true}

At that point we start seeing the DNS context deadline exceeded:

2022-05-08 23:06:52.002295677 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:06:52.014808437 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:06:52.030178202 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:06:52.040463304 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:06:52.056969833 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:06:52.057098467 +0000 UTC: [RATELIMIT] format("dns: error: %v")
2022-05-08 23:07:10.651257898 +0000 UTC: [RATELIMIT] format("dns: error: %v") (5 dropped)
2022-05-08 23:07:10.651525849 +0000 UTC: dns: error: context deadline exceeded
2022-05-08 23:07:10.651602264 +0000 UTC: dns: error: context deadline exceeded

My guess would be that the two processes were using 100% CPU because they were sending DNS packets in a loop back and forth to each other as rapidly as they could.

Could you:

• attach or paste the content of /etc/resolv.conf
• is /etc/resolv.conf a softlink to somewhere in /run with a name that looks like systemd-resolved?

[PythonCoderAS]

Contents of /etc/resolv.conf:

# This is /run/systemd/resolve/stub-resolv.conf managed by man:systemd-resolved(8).
# Do not edit.
#
# This file might be symlinked as /etc/resolv.conf. If you're looking at
# /etc/resolv.conf and seeing this text, you have followed the symlink.
#
# This is a dynamic resolv.conf file for connecting local clients to the
# internal DNS stub resolver of systemd-resolved. This file lists all
# configured search domains.
#
# Run "resolvectl status" to see details about the uplink DNS servers
# currently in use.
#
# Third party programs should typically not access this file directly, but only
# through the symlink at /etc/resolv.conf. To manage man:resolv.conf(5) in a
# different way, replace this symlink by a static file or a different symlink.
#
# See man:systemd-resolved.service(8) for details about the supported modes of
# operation for /etc/resolv.conf.

nameserver 127.0.0.53
options edns0 trust-ad
search nyc.rr.com <myemail>.gmail.com.beta.tailscale.net

ls -l /etc/resolv.conf:

lrwxrwxrwx 1 root root 39 Apr 21 01:00 /etc/resolv.conf -> ../run/systemd/resolve/stub-resolv.conf

[PythonCoderAS]

I also decided to restart the tailscale daemon and that stopped it for now, I'll see if it lasts.

[DentonGentry]

tailscale.com@v1.24.2/net/dns/resolved.go:141 resync() is:

tailscale/net/dns/resolved.go

Line 141 in 741ae99

if signal.Path != dbusPath || signal.Name != dbusInterface+"."+dbusOwnerSignal {

[PythonCoderAS]

tailscale.com@v1.24.2/net/dns/resolved.go:141 resync() is:

tailscale/net/dns/resolved.go

Line 141 in 741ae99

if signal.Path != dbusPath || signal.Name != dbusInterface+"."+dbusOwnerSignal {

dbus? I think I understand the root of the problem. When updating some packages, ubuntu 22.04 prompted me to restart the dbus service and so I did. I'd say the upgrade happened right around the time the problem started.

[bradfitz]

Yeah, that dbus-reading goroutine spins forever when dbus restarts.

Repro:

package main

import (
        "log"

        "github.com/godbus/dbus/v5"
)

func main() {
        conn, err := dbus.SystemBus()
        if err != nil {
                log.Fatal(err)
        }
        signals := make(chan *dbus.Signal, 16)
        conn.Signal(signals)
        for sig := range signals {
                log.Println(sig)
        }
        log.Println("DONE")
}

Run that and then systemctl restart dbus and watch it say DONE. That channel gets closed, which resync doesn't handle.

/cc @danderson