Netzwerkausfall kurz nach Reboot mit Debian Buster

Kürzlich habe ich eine existierende virtuelle Maschine mit Debian (die unter KVM läuft) auf Debian Buster (das neueste Stable Release zur Zeit des Entstehens dieses Blog-Eintrags) hochgezogen.

Nach dem Reboot schien alles OK zu sein, aber kurz nach dem Reboot (etwa nach 10 Minuten) war die Maschine nicht mehr erreichbar. Nach einem weiteren Reboot passierte das selbe wieder.

Ich habe dann VNC eingeschaltet (die Host-Maschine auf der die VM läuft ist in einer gehosteten Infrastruktur die ich nur über Netzwerk erreichen kann, daher musste ich den VNC-Port auf meine lokale Maschine zum Testen bringen) und stellte fest, dass die Maschine lief – aber ohne Netzwerkverbindung. Das Netzwerk-Interface war oben aber hatte keine IPv4 Adresse.

Weitere Untersuchungen zeigten, dass die Maschine mit einer falschen Zeit hochkam (eine Stunde nach der aktuellen Zeit, also die Uhr war in der Zukunft) und dass die Zeit von ntp um eine Stunde zurückgestellt wurde sobald dieser hochkam. Aus dem Log:

Jan 22 19:19:35 tux4 dhclient[351]: DHCPOFFER of 10.33.33.4 from 10.33.33.254
...
Jan 22 19:19:36 tux4 ntpd[391]: ntpd 4.2.8p12@1.3728-o (1): Starting

Jan 22 19:19:36 tux4 ntpd[420]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jan 22 18:19:47 tux4 ntpd[420]: receive: Unexpected origin timestamp 0xe1d310c2.72d51f2c does not match aorg 0000000000.00000000 from server@XX.XXX.XXX.XXX xmt 0xe1d302b3.0dae523c

Im letzten Log-Eintrag ist die Zeit um eine Stunde früher als bei dem Log-Eintrag davor!

Daher war mein nächster Schritt, die dhcp leases Datei in /var/lib/dhcp/dhclient.eth0.leases zu checken:

renew 3 2020/01/22 18:39:54;
rebind 3 2020/01/22 18:44:51;
expire 3 2020/01/22 18:46:06;

Aha, das Lease war ausgelaufen. Offensichtlich konnte der ISC dhcp Server dem Interface die IP Adresse entziehen sobald das Lease ausgelaufen war, aber konnte dieses nicht rechtzeitig erneuern (vermutlich wäre das dann eine Stunde später passiert wenn die Uhr wieder die Zeit erreicht hätte die sie vor dem Zurückstellen hatte). Es sieht so aus als ob der ISC dhcp Server zwei unterschiedliche Mechanismen verwendet um die beiden Events zu timen: Für den einen Event der beim Auslaufen des Lease passiert funktioniert der Mechanismus auch wenn die Zeit zurückgestellt wird (vgl. den obigen Auszug aus dem leases file, die Zeiten dort sind richtig, nicht eine Stunde in der Zukunft). Für den anderen Mechanismus beim Lease-Erneuern nicht. Ich habe mir den Code nicht angesehen um rauszufinden, warum das so ist.

Was war nun die Ursache der falschen Zeit? Es stellte sich heraus dass ich diese Maschine schon immer so konfiguriert hatte dass sie in localtime (CET ist eine Stunde weiter als UTC) lief. Also war dieser Fehler schon immer drin. Das oben beschriebene Problme trat aber erst mit Debian Buster auf.

Inzwischen starte ich diese Maschine in UTC und alles funktioniert wie erwartet. Ich verwende direkt KVM, die korrekte Option ist:

-rtc base=utc