Unstable systemd-resolved with multiple DNS servers

[strboul]

trafficstars

Describe the bug

I realized that my DNS was unstable from my machine for a while when I was connected to my home network where my router advertised multiple DNS servers. I found out that my current DNS server was constantly switching due to the systemd-resolved rules defined in OpenSnitch.

Include the following information:

• OpenSnitch version: 1.6.3-1
• OS: Arch Linux
• Version:
• Window Manager: KDE
• Kernel version: echo $(uname -a) Linux personal 6.4.12-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 24 Aug 2023 00:38:14 +0000 x86_64 GNU/Linux

To Reproduce

First, I enabled the debug logs of systemd-resolved,

[Service]
Environment=SYSTEMD_LOG_LEVEL=debug

ends up in the override.conf via sudo systemctl edit systemd-resolved.

I observed that the DNS resolver was timing out, then it was forever switching to the alternative in the circular buffer. After I saw the host detectportal.firefox.com in the logs, I realized that OpenSnitch causes it.

journalctl -u systemd-resolved -f

Sep 08 10:25:15 personal systemd-resolved[23197]: Firing regular transaction 54198 for <detectportal.firefox.com IN A> scope dns on wlan0/* (validate=yes).
Sep 08 10:25:15 personal systemd-resolved[23197]: Using feature level UDP+EDNS0 for transaction 54198.
Sep 08 10:25:15 personal systemd-resolved[23197]: Using DNS server 192.168.1.12 for transaction 54198.
Sep 08 10:25:15 personal systemd-resolved[23197]: Announcing packet size 1472 in egress EDNS(0) packet.
Sep 08 10:25:15 personal systemd-resolved[23197]: Emitting UDP, link MTU is 1500, socket MTU is 0, minimal MTU is 40
Sep 08 10:25:15 personal systemd-resolved[23197]: Sending query packet with id 54198 of size 53.
Sep 08 10:25:15 personal systemd-resolved[23197]: Emitting UDP, link MTU is 1500, socket MTU is 0, minimal MTU is 40
Sep 08 10:25:15 personal systemd-resolved[23197]: Sending query packet with id 54198 of size 53.
Sep 08 10:25:15 personal systemd-resolved[23197]: Timeout reached on transaction 42439.
Sep 08 10:25:15 personal systemd-resolved[23197]: Retrying transaction 42439.
Sep 08 10:25:15 personal systemd-resolved[23197]: Regular transaction 42439 for <personal.local IN ANY> on scope mdns on wlan0/INET6 now complete with <attempts-max-reached> from none (unsigned; non-confidential).
Sep 08 10:25:15 personal systemd-resolved[23197]: Record personal.local IN AAAA fe80::6f7b:6165:5812:1ee1 successfully probed.
Sep 08 10:25:15 personal systemd-resolved[23197]: Sending response packet with id 0 on interface 3/AF_INET6 of size 140.
Sep 08 10:25:15 personal systemd-resolved[23197]: Freeing transaction 42439.
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1166 path=n/a interface=n/a member=n/a  cookie=19 reply_cookie=23 signature=n/a error-name=n/a error-message=n/a
Sep 08 10:25:15 personal systemd-resolved[23197]: Match type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0=':1.1167' successfully installed.
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1168 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=2 reply_cookie=0 signature=s error-name=n/a e>
Sep 08 10:25:15 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1168 path=n/a interface=n/a member=n/a cookie=25 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1168 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_32 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=3 reply_cookie=0 signature=s error-n>
Sep 08 10:25:15 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1168 path=n/a interface=n/a member=n/a cookie=26 reply_cookie=3 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1168 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_33 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=4 reply_cookie=0 signature=s error-n>
Sep 08 10:25:15 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1168 path=n/a interface=n/a member=n/a cookie=27 reply_cookie=4 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1168 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_34 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=5 reply_cookie=0 signature=s error-n>
Sep 08 10:25:15 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1168 path=n/a interface=n/a member=n/a cookie=28 reply_cookie=5 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:15 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1168 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_35 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=6 reply_cookie=0 signature=s error-n>
Sep 08 10:25:15 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1168 path=n/a interface=n/a member=n/a cookie=29 reply_cookie=6 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:16 personal systemd-resolved[23197]: Sending response packet with id 0 on interface 3/AF_INET of size 82.
Sep 08 10:25:16 personal systemd-resolved[23197]: Sending response packet with id 0 on interface 3/AF_INET6 of size 140.
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink: New incoming connection.
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink-29: Setting state idle-server
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink-29: New incoming message: {"method":"io.systemd.Resolve.Monitor.SubscribeQueryResults","parameters":{},"more":true}
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink-29: Changing state idle-server → processing-method-more
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink-29: Sending message: {"parameters":{"ready":true},"continues":true}
Sep 08 10:25:17 personal systemd-resolved[23197]: 1 clients now attached for varlink notifications
Sep 08 10:25:17 personal systemd-resolved[23197]: varlink-29: Changing state processing-method-more → pending-method-more
Sep 08 10:25:17 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1169 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=2 reply_cookie=0 signature=s error-name=n/a e>
Sep 08 10:25:17 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1169 path=n/a interface=n/a member=n/a cookie=30 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:17 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1169 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_32 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=3 reply_cookie=0 signature=s error-n>
Sep 08 10:25:17 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1169 path=n/a interface=n/a member=n/a cookie=31 reply_cookie=3 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:17 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1169 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_33 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=4 reply_cookie=0 signature=s error-n>
Sep 08 10:25:17 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1169 path=n/a interface=n/a member=n/a cookie=32 reply_cookie=4 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:17 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1169 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_34 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=5 reply_cookie=0 signature=s error-n>
Sep 08 10:25:17 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1169 path=n/a interface=n/a member=n/a cookie=33 reply_cookie=5 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:17 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1169 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_35 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=6 reply_cookie=0 signature=s error-n>
Sep 08 10:25:17 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1169 path=n/a interface=n/a member=n/a cookie=34 reply_cookie=6 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:19 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1171 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=2 reply_cookie=0 signature=s error-name=n/a e>
Sep 08 10:25:19 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1171 path=n/a interface=n/a member=n/a cookie=35 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:19 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1171 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_32 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=3 reply_cookie=0 signature=s error-n>
Sep 08 10:25:19 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1171 path=n/a interface=n/a member=n/a cookie=36 reply_cookie=3 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:19 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1171 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_33 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=4 reply_cookie=0 signature=s error-n>
Sep 08 10:25:19 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1171 path=n/a interface=n/a member=n/a cookie=37 reply_cookie=4 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:19 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1171 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_34 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=5 reply_cookie=0 signature=s error-n>
Sep 08 10:25:19 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1171 path=n/a interface=n/a member=n/a cookie=38 reply_cookie=5 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:19 personal systemd-resolved[23197]: Got message type=method_call sender=:1.1171 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1/link/_35 interface=org.freedesktop.DBus.Properties member=GetAll  cookie=6 reply_cookie=0 signature=s error-n>
Sep 08 10:25:19 personal systemd-resolved[23197]: Sent message type=method_return sender=n/a destination=:1.1171 path=n/a interface=n/a member=n/a cookie=39 reply_cookie=6 signature=a{sv} error-name=n/a error-message=n/a
Sep 08 10:25:20 personal systemd-resolved[23197]: Timeout reached on transaction 54198.
Sep 08 10:25:20 personal systemd-resolved[23197]: Retrying transaction 54198, after switching servers.
Sep 08 10:25:20 personal systemd-resolved[23197]: wlan0: Switching to DNS server 1.1.1.1.

Screenshots

Additional context

Solutions I've found to remediate:

• Disable OpenSnitch (duh!!!)

• Disable any rules touching systemd-resolved (duh!!)

• In the systemd-resolved, hard-code the current the DNS server (duh!)

I'm not sure if this can be considered a bug in the end, because that's how systemd-resolved works(?); however, it caused some trouble to me so I'd be happy if there's a better way to fix it.

[izar3]

Im not sure where @gustavo-iniguez-goya is but ill try to help.

From what I can tell its trying to resolve your main DNS server then using 1.1.1.1 when it fails or there could be malware logging your DNS requests to that localhost IP

Either way this isnt a opensnitch problem

And for securitys sake, please configure your router properly and use wireshark to insure your traffic isnt being leaked

[TriMoon]

Looks to me like you are blocking some connections that systemd-resolved needs. It's alternating between your DNS-servers cause it can't reach them... This is a configuration problem of your firewall rules in opensnitch, so it could be handy to post them...

PS: Why do you have both a LAN and external DNS? (If they supply conflicting answers you will have other problems also later.)

• 192.168.1.12 is a DNS server on your LAN
• 1.1.1.1 is the external DNS server (cloudflare)

TIP: You can try https://gitlab.com/TriMoon/dnsdig to check your DNS responses...

[gustavo-iniguez-goya]

Hi all,

wlan0: Switching to DNS server 1.1.1.1wlan0: Switching to DNS server 1.1.1.1

I had never seen this error before, but reviewing the logs I've realized that I have some. I usually allow systemd-resolved connect to a port, how did you create the rule for systemd-resolved?

Do you also see any delay or error with nslookup or dig? They will query directly to the DNS servers without using systemd-resolved. Also set the LogLevel to DEBUG (Preferences -> Nodes) and see if there's any clue that could explain that behaviour.