Ich hatte im März meine Netzwerkverwaltung auf Systemd umgestellt und habe dabei auch den lokalen Dienst für die Pufferung von DNS-Anfragen gegen systemd-resolved ausgewechselt. Dabei fiel mir damals auf, dass der DNS-Server auf dem Freifunk-Router kein DNSSEC unterstützte, weshalb ich mir verschiedene freie DNS-Server im Internet ausgewählt habe. Jedoch kam es seitdem immer wieder dazu, dass der resolved irgendwann keine Anfragen mehr beantwortet hat und Seiten im Browser nicht mehr geladen wurden.

Ganz klassisch habe ich dann also erst mal ins Log geschaut, was dort steht (j ist bei mir ein Alias für journalctl -r --no-hostname):

# j -u systemd-resolved
Apr 08 12:57:21 systemd-resolved[20368]: DNSSEC validation failed for question d2tpbry8f62bv9.cloudfront.net IN AAAA: incompatible-server
Apr 08 12:56:48 systemd-resolved[20368]: DNSSEC validation failed for question video-stats.l.google.com IN A: incompatible-server
Apr 08 12:56:21 systemd-resolved[20368]: DNSSEC validation failed for question d2tpbry8f62bv9.cloudfront.net IN AAAA: incompatible-server
Apr 08 12:56:21 systemd-resolved[20368]: DNSSEC validation failed for question d2tpbry8f62bv9.cloudfront.net IN A: incompatible-server
Apr 08 12:56:21 systemd-resolved[20368]: DNSSEC validation failed for question detectportal.firefox.com IN A: incompatible-server
Apr 08 12:56:21 systemd-resolved[20368]: DNSSEC validation failed for question detectportal.firefox.com IN AAAA: incompatible-server

Also einen ersten Anhaltspunkt gab es, aber die Angabe, welcher der incompatible-server ist, wäre doch noch hilfreich gewesen. Systemd verfolgt eine etwas andere Strategie beim Logging: Sonst bestimmt man den Inhalt der Protokolle in einer Konfigurationsdatei des Dienstes, aber bei Systemd steuert man es über eine Umgebungsvariable -- meine Meinung dazu habe ich in einem eigenen Artikel dargelegt.

Um also resolved zu mehr Ausgaben im Protokoll zu bewegen, muss man die Variable SYSTEMD_LOG_LEVEL vorm Start des Dienstes auf debug. Leicht lässt sich dies mit systemctl edit systemd-resolved.service erreichen. Dort ergänzt man dann (in die unter Umständen leere Datei):

[Service]
Environment=SYSTEMD_LOG_LEVEL=debug

Das Endergebnis kann man noch mal mit systemctl (bei mir der Alias s) kontrollieren:

# s cat systemd-resolved
# /lib/systemd/system/systemd-resolved.service
#  This file is part of systemd.
...
[Service]
ExecStart=/lib/systemd/systemd-resolved
...
# /etc/systemd/system/systemd-resolved.service.d/override.conf
[Service]
Environment=SYSTEMD_LOG_LEVEL=debug

Mit s edit wurde also die override.conf angelegt und das Skript um die Environment-Variable SYSTEMD_LOG_LEVEL ergänzt. Danach den Dienst neu starten (s restart systemd-resolved.service) und abwarten, bis es wieder Probleme gibt.

Als der resolved wieder mal nicht keine Antworten mehr abgab, hatte ich dann im Log wesentlich mehr Meldungen und konnte so auch den Server erkennen, der die Probleme verursacht:

# j -u systemd-resolved
Apr 12 00:51:53 systemd-resolved[25490]: Transaction 15731 for <www.gravatar.com IN A> on scope dns on wlp59s0/* now complete with <dnssec-failed> from network (unsigned).
Apr 12 00:51:53 systemd-resolved[25490]: DNSSEC validation failed for question www.gravatar.com IN A: incompatible-server
Apr 12 00:51:53 systemd-resolved[25490]: Not validating response for 15731, used server feature level does not support DNSSEC.
Apr 12 00:51:53 systemd-resolved[25490]: Processing incoming packet on transaction 15731.
Apr 12 00:51:53 systemd-resolved[25490]: Sending query packet with id 15731.
Apr 12 00:51:53 systemd-resolved[25490]: Using DNS server 10.17.64.1 for transaction 15731.
Apr 12 00:51:53 systemd-resolved[25490]: Using feature level UDP for transaction 15731.
Apr 12 00:51:53 systemd-resolved[25490]: Transaction 15731 for <www.gravatar.com IN A> scope dns on wlp59s0/*.
Apr 12 00:51:53 systemd-resolved[25490]: Cache miss for www.gravatar.com IN A

Der resolved griff also noch weiterhin auf den DNS-Server vom Freifunk-Router zu, obwohl dieser kein DNSSEC unterstützt. Dies lies sich dann mit der Einstellung

[DHCP]
UseDNS=false

[IPv6AcceptRA]
UseDNS=false

in der Konfiguration /etc/systemd/network/20-dhcp.network unterbinden.

Meine Anpassung des Startskripts für resolved konnte ich danach recht einfach mit s revert systemd-resolved.service rückgängig machen.

Genauere Ausgaben mit journalctl

Bei journalctl kann man die Ausgabe auf bestimmte Dringlichkeiten reduzieren. Wenn man also den Dienst so konfiguriert hat, dass er auch Debug-Meldungen ausgibt, kann man mit journalctl -p notice die Info- und Debug-Meldungen entfernen. Oder man kann auch nur einen Bereich von Dringlichkeiten auswählen und somit zum Beispiel nur die Debug-Meldungen ausgeben: journalctl -p debug..debug.

Von journald werden aber noch mehr Informationen gespeichert, als die die bei einfachem Aufruf ausgegeben werden. Mit journalctl -o verbose kann man sich die Felder anzeigen lassen.

Bei meiner Suche oben vielen mir die Attribute CODE_LINE und CODE_FUNCTION auf. Mit diesen kann man gezielt Meldungen aus einer bestimmten Codezeile abfragen und somit leicht eine Statistik der häufigsten DNS-Anfragen erstellen:

# journalctl -u systemd-resolved -o cat CODE_FUNCTION=dns_transaction_go CODE_LINE=1496 |sed 's/>.*//; s/.*<//' |sort |uniq -c |sort -nr |head 
    654 forums.dotnetfoundation.org IN A
    648 forums.dotnetfoundation.org IN AAAA
    531 hosted-vh1.discourse.org IN A
    506 hosted-vh1.discourse.org IN AAAA
    219 d2tpbry8f62bv9.cloudfront.net IN AAAA
    214 d2tpbry8f62bv9.cloudfront.net IN A
    198 hosted-vh1.discourse.org IN SOA
    197 hosted-vh1.discourse.org IN DS
    145 detectportal.firefox.com IN A
    144 detectportal.firefox.com IN AAAA

Zusätzliche Felder im JSON-Format

In der JSON-Ausgabe von journalctl habe ich entdeckt, dass noch mehr Felder enthalten sind:

{
  "__CURSOR": "s=f05618816fcd47d3b0484d94b234634b;i=7d245;b=8f4e6562de7d48b28d69b2b8c1ee20aa;m=14f70ad247;t=58129cc80ada0;x=7fa26ed0c169134b",
  "DNS_SERVER": "fd00::ca0e:14ff:febf:fcd0",
  "CODE_FILE": "../src/resolve/resolved-dns-transaction.c",
  "_SYSTEMD_CGROUP": "/system.slice/systemd-resolved.service",
  "_SYSTEMD_INVOCATION_ID": "1540b279508444aa8ae5277443dceaf1",
  "_MACHINE_ID": "523cb54753234ed08c13ec497d0d3b64",
  "_EXE": "/lib/systemd/systemd-resolved",
  "_PID": "711",
  "_SYSTEMD_UNIT": "systemd-resolved.service",
  "DNS_SERVER_FEATURE_LEVEL": "UDP+EDNS0",
  "__REALTIME_TIMESTAMP": "1549391408180640",
  "__MONOTONIC_TIMESTAMP": "90044027463",
  "CODE_LINE": "319",
  "_UID": "102",
  "_SYSTEMD_SLICE": "system.slice",
  "MESSAGE_ID": "1675d7f172174098b1108bf8c7dc8f5d",
  "_SOURCE_REALTIME_TIMESTAMP": "1549391408180612",
  "_CAP_EFFECTIVE": "0",
  "_SELINUX_CONTEXT": "unconfined\n",
  "MESSAGE": "DNSSEC validation failed for question incoming.telemetry.mozilla.org IN A: incompatible-server",
  "_HOSTNAME": "zenbook",
  "_TRANSPORT": "journal",
  "SYSLOG_FACILITY": "3",
  "DNS_TRANSACTION": "59597",
  "_GID": "105",
  "_BOOT_ID": "8f4e6562de7d48b28d69b2b8c1ee20aa",
  "DNSSEC_RESULT": "incompatible-server",
  "_COMM": "systemd-resolve",
  "SYSLOG_IDENTIFIER": "systemd-resolved",
  "PRIORITY": "5",
  "DNS_QUESTION": "incoming.telemetry.mozilla.org IN A",
  "_CMDLINE": "/lib/systemd/systemd-resolved",
  "CODE_FUNC": "dns_transaction_complete"
}

Mit jq kann man sehr gut die Logmeldungen filtern und auswerten, um ein Vielfaches leichter als es mit den reinen Textdateien von Syslog der Fall war.

% journalctl --since=-1d --output=json-pretty -u systemd-resolved.service |jq -r 'select(.DNSSEC_RESULT == "incompatible-server") | .DNS_SERVER' |sort -u
fd00::ca0e:14ff:febf:fcd0