[GELÖST] Bind9-DNS-Server startet nach Backup nicht mehr

[Njuguna]

Hallo,

ich habe hier einen funktionierenden Bind9-Nameserver (Debian 12) als Proxmox-VM. Leider ist die Festplatte nach 24 Stunden immer nur noch lesbar, dadurch fällt der Name-Service aus. Das Proxmox-Backup des Images hilft leider nur bedingt.
Ich habe jetzt eine neue VM für den Name-Server aufgesetzt und alle Einstellungen aus einem aktuellen Backup auf die neue VM übernommen. Wenn ich mit diesen Einstellungen und der IP-Adresse des bisherigen Nameservers (in diesem Fall ist dieser abgeschaltet) den Named-Service starten will, geht das nicht:

Code: Alles auswählen

systemctl start named.service
Job for named.service failed because the control process exited with error code.
See "systemctl status named.service" and "journalctl -xeu named.service" for details

Code: Alles auswählen

systemctl status named.service
× named.service - BIND Domain Name Server
     Loaded: loaded (/lib/systemd/system/named.service; enabled; preset: enabled)
     Active: failed (Result: exit-code) since Wed 2023-12-06 17:49:03 CET; 30s ago
       Docs: man:named(8)
    Process: 1405 ExecStart=/usr/sbin/named -f $OPTIONS (code=exited, status=1/FAILURE)
   Main PID: 1405 (code=exited, status=1/FAILURE)
        CPU: 31ms

Dez 06 17:49:03 ns1 systemd[1]: named.service: Scheduled restart job, restart counter is at 5.
Dez 06 17:49:03 ns1 systemd[1]: Stopped named.service - BIND Domain Name Server.
Dez 06 17:49:03 ns1 systemd[1]: named.service: Start request repeated too quickly.
Dez 06 17:49:03 ns1 systemd[1]: named.service: Failed with result 'exit-code'.
Dez 06 17:49:03 ns1 systemd[1]: Failed to start named.service - BIND Domain Name Server.

Code: Alles auswählen

# journalctl -xeu named.service
Dez 06 17:49:03 ns1 systemd[1]: named.service: Failed with result 'exit-code'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ The unit named.service has entered the 'failed' state with result 'exit-code'.
Dez 06 17:49:03 ns1 named[1405]: loading configuration: file not found
Dez 06 17:49:03 ns1 named[1405]: exiting (due to fatal error)
Dez 06 17:49:03 ns1 systemd[1]: Failed to start named.service - BIND Domain Name Server.
░░ Subject: A start job for unit named.service has failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ A start job for unit named.service has finished with a failure.
░░ 
░░ The job identifier is 1534 and the job result is failed.
Dez 06 17:49:03 ns1 systemd[1]: named.service: Scheduled restart job, restart counter is at 5.
░░ Subject: Automatic restarting of a unit has been scheduled
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ Automatic restarting of the unit named.service has been scheduled, as the result for
░░ the configured Restart= setting for the unit.
Dez 06 17:49:03 ns1 systemd[1]: Stopped named.service - BIND Domain Name Server.
░░ Subject: A stop job for unit named.service has finished
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ A stop job for unit named.service has finished.
░░ 
░░ The job identifier is 1607 and the job result is done.
Dez 06 17:49:03 ns1 systemd[1]: named.service: Start request repeated too quickly.
Dez 06 17:49:03 ns1 systemd[1]: named.service: Failed with result 'exit-code'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ The unit named.service has entered the 'failed' state with result 'exit-code'.
Dez 06 17:49:03 ns1 systemd[1]: Failed to start named.service - BIND Domain Name Server.
░░ Subject: A start job for unit named.service has failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ A start job for unit named.service has finished with a failure.
░░ 
░░ The job identifier is 1607 and the job result is failed.

Ich benutze exakt dieselben Konfigurationsdateien wie auf dem bisherigen Server, der sich auch starten lässt - eben mit dem Problem der Image-Platte. Dann müsste sich doch der neue Server starten lassen. Ich suche vor allem nach einer Möglichkeit den Server zu debuggen.

Grüße
Njuguna

[heisenberg]

Zeig mal die Ausgabe dieses Kommandos:

Code: Alles auswählen

journalctl -u named --lines=1000 --no-pager

Am besten im NoPaste.

Das hier ...

Code: Alles auswählen

Dez 06 17:49:03 ns1 named[1405]: loading configuration: file not found

... ist doch schon mal eine heisse Spur. Wenn man jetzt noch die Logzeilen davor hat, dann kann man vielleicht sehen, welche Datei denn nun fehlt.

---

Wenn ich den Bind im Vordergrund so starte ...

Code: Alles auswählen

/usr/sbin/named -f -u bind

... dann bekomme ich eine Logausgabe im System-Journal, die ich so auslesen kann ...

Code: Alles auswählen

# journalctl --lines=1000 | grep named | tail -n 20

Dez 06 18:30:44 heisenbergdesk named[56272]: compiled with zlib version: 1.2.13
Dez 06 18:30:44 heisenbergdesk named[56272]: linked to zlib version: 1.2.13
Dez 06 18:30:44 heisenbergdesk named[56272]: ----------------------------------------------------
Dez 06 18:30:44 heisenbergdesk named[56272]: BIND 9 is maintained by Internet Systems Consortium,
Dez 06 18:30:44 heisenbergdesk named[56272]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
Dez 06 18:30:44 heisenbergdesk named[56272]: corporation.  Support and training for BIND 9 are
Dez 06 18:30:44 heisenbergdesk named[56272]: available at https://www.isc.org/support
Dez 06 18:30:44 heisenbergdesk named[56272]: ----------------------------------------------------
Dez 06 18:30:44 heisenbergdesk named[56272]: found 8 CPUs, using 8 worker threads
Dez 06 18:30:44 heisenbergdesk named[56272]: using 8 UDP listeners per interface
Dez 06 18:30:44 heisenbergdesk named[56272]: DNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
Dez 06 18:30:44 heisenbergdesk named[56272]: DS algorithms: SHA-1 SHA-256 SHA-384
Dez 06 18:30:44 heisenbergdesk named[56272]: HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
Dez 06 18:30:44 heisenbergdesk named[56272]: TKEY mode 2 support (Diffie-Hellman): yes
Dez 06 18:30:44 heisenbergdesk named[56272]: TKEY mode 3 support (GSS-API): yes
Dez 06 18:30:44 heisenbergdesk named[56272]: config.c: option 'trust-anchor-telemetry' is experimental and subject to change in the future
Dez 06 18:30:44 heisenbergdesk named[56272]: loading configuration from '/etc/bind/named.conf'
Dez 06 18:30:44 heisenbergdesk named[56272]: /etc/bind/named.conf:10: parsing failed: file not found
Dez 06 18:30:44 heisenbergdesk named[56272]: loading configuration: file not found
Dez 06 18:30:44 heisenbergdesk named[56272]: exiting (due to fatal error)

Interessanterweise ist die Message nicht im named-Service-log, sondern im allgemeinen Journal. Beim Aufruf über die Kommandozeile ja noch verständlich, beim Aufruf als Service aber eher nicht. Aber vielleicht landen die Fehlermeldungen des Dienstes ja trotzdem irgendwie im allgemeinen Systemjournal.

Nochmal als klare Darstellung:

Service-Journal/Log von named.service:

Code: Alles auswählen

journalctl -u named --lines=100

System-Journal/Log:

Code: Alles auswählen

journalctl --lines=1000 | grep named

Ja. Das Logging vom named scheint schon komisch zu sein. Ich hätte auch erwartet, dass es da eine Option gibt, um direkt auf stdout zu loggen. Das macht der aber so überhaupt nicht.

[Njuguna]

Hallo Heisenberg,

Danke für die Tips. Ich konnte das Problem bereits eingrenzen. Das Verzeichnis "/var/log/bind/" und die die Datei "/var/log/bind/bind.log" fehlten. Mittlerweile habe ich sie angelegt und wie auf dem alten System mit den Rechten/Benutzer versehen

Code: Alles auswählen

-rw-r--r-- 1 bind bind 0  6. Dez 18:50 /var/log/bind/bind.log
drwxr-xr-x 2 bind bind 4096  6. Dez 18:50 /var/log/bind/

Jetzt hat sich die Fehlermeldung in eine Permission-Denied-Meldung gewandelt:

Code: Alles auswählen

root@ns1 /etc/bind # /usr/sbin/named -f -u bind
root@ns1 /etc/bind #  journalctl --lines=1000 | grep named | tail -n 20
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 254.169.IN-ADDR.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 2.0.192.IN-ADDR.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 100.51.198.IN-ADDR.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 113.0.203.IN-ADDR.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 255.255.255.255.IN-ADDR.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: D.F.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 8.E.F.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 9.E.F.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: A.E.F.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: B.E.F.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: 8.B.D.0.1.0.0.2.IP6.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: EMPTY.AS112.ARPA
Dez 06 19:02:27 ns1 named[3061]: automatic empty zone: HOME.ARPA
Dez 06 19:02:27 ns1 named[3061]: command channel listening on 127.0.0.1#953
Dez 06 19:02:27 ns1 named[3061]: isc_stdio_open '/var/log/bind/bind.log' failed: permission denied
Dez 06 19:02:27 ns1 named[3061]: configuring logging: permission denied
Dez 06 19:02:27 ns1 named[3061]: loading configuration: permission denied
Dez 06 19:02:27 ns1 named[3061]: exiting (due to fatal error)

Die Rechte sind jetzt dieselben wie auf dem alten System.

[Njuguna]

Auch ja, diese Abfrage

Code: Alles auswählen

journalctl --lines=1000 | grep named

liefert u.A.

Code: Alles auswählen

Dez 06 19:04:53 ns1 named[3165]: isc_stdio_open '/var/log/bind/bind.log' failed: permission denied
Dez 06 19:04:53 ns1 named[3165]: configuring logging: permission denied
Dez 06 19:04:53 ns1 named[3165]: loading configuration: permission denied
Dez 06 19:04:53 ns1 named[3165]: exiting (due to fatal error)
Dez 06 19:04:53 ns1 kernel: audit: type=1400 audit(1701885893.232:23): apparmor="DENIED" operation="open" profile="named" name="/var/log/bind/bind.log" pid=3165 comm="isc-net-0000" requested_mask="ac" denied_mask="ac" fsuid=103 ouid=103
Dez 06 19:04:53 ns1 systemd[1]: named.service: Main process exited, code=exited, status=1/FAILURE

Kann das ein Problem mit Apparmor sein?

[heisenberg]

Kann das ein Problem mit Apparmor sein?

Liest sich so.

Kannst ja mal ins Apparmor-Profil reinschauen: (dpkg -L bind9|grep -i apparmor)

[Njuguna]

Ja, das war es! Auf dem Neuen ist die Datei "/etc/apparmor.d/local/usr.sbin.named" leer, während die aus dem Backup mit
/var/lib/bind/** rw,
/var/lib/bind/ rw,
/var/log/bind/** rw,
/var/log/bind/ rw,
gefüllt ist.
So lässt sich der Named-Service wieder starten.
Vielen Dank für den Einblick in journalctl !

Grüße

Njuguna

[heisenberg]

Mit folgendem Eintrag in /etc/bind/named.conf.local kann man named übrigens dazu bringen, auf die Konsole zu loggen, wenn man named zum Debuggen im Vordergrund ausführt:

Code: Alles auswählen

     channel debug_log {
          stderr;
          severity debug;
     };
     category default { debug_log; };

Das funktioniert aber wohl erst, wenn zumindest die Konfigurationsdateien korrekt sind. Sonst greift das noch nicht und Fehler diesbezüglich landen wieder im System-Journal.

[Njuguna]

Gut zu wissen!