chr.istoph, der Blog

Wir haben das Problem, dass wir Server haben die einfach Abstürzen ohne einem Meldung im /var/log/kernel.log zu hinterlassen. Wir haben nun das Kernel Loggin Modul „netconsole“ verwendet, um die Logzeilen direkt vom Kernel via UDP verschicken zu können.

Dafür würde auf Empfänger und Sender Seite folgendes eingerichtet.

Empfänger:
Möchte man das ganze nicht Reboot fest machen und für mehrere Ports/Server einrichten kann man auch einfach den socat Befehl von Hand ausführen. Hier wird nun beschreiben wie wir einen dynamischer Systemd Service verwenden.

/etc/systemd/system/netconsole@.service

[Unit]
Description=netconsole
After=network.target remote-fs.target nss-lookup.target
PartOf=netconsole.service

[Service]
Type=simple
Environment="LANG=C"
ExecStart=/usr/bin/socat OPEN:/var/log/netconsole-%i,append udp4-listen:%i,reuseaddr,fork

Restart=always

[Install]
WantedBy=multi-user.target

/etc/systemd/system/netconsole.service

[Unit]
Description=netconsole
Wants=netconsole@10001.service netconsole@10002.service

[Service]
RemainAfterExit=yes
ExecStart=/bin/true

[Install]
WantedBy=multi-user.target

An dieser Stelle kann das der Punkt „Wants“ beliebig anpassen werden. Der Zahlen wert hinter dem @xxxx ist der übergebene Port.

Abschließend müssen das systemd noch aktiviert werden:

systemctl enable netconsole.service
systemctl start netconsole.service
systemctl status netconsole.service
● netconsole.service - netconsole
   Loaded: loaded (/etc/systemd/system/netconsole.service; enabled; vendor preset: enabled)
   Active: active (exited) since Mo 2017-05-08 10:54:23 CEST; 4s ago
  Process: 11124 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
 Main PID: 11124 (code=exited, status=0/SUCCESS)

Mai 08 10:54:23 server systemd[1]: Started netconsole.

Sender:
/etc/modprobe.d/netconsole.conf

options netconsole netconsole=10000@192.168.0.1/br0,10001@192.168.0.9/00:00:00:00:00

Dann kann das Kernel Modul geladen werden:

modprobe netconsole

Möchte man das ganze reboot fest machen, muss das Modul in /etc/modules eingetragen werden:

echo "netconsole" >> /etc/modules

Zum Testen erzeugt folgender Befehl einen Eintrag im Kernel log, als auch auf dem Empfänger Server:

echo h > /proc/sysrq-trigger

Update 17.05.2017: für die Verwendung von CentOS7 wurde das Script von nc auf socat umgebaut.

Nach dem neu starten unserer VServer Plattform mit dem Kernel 3.10.0-514, traten nach sofort nach dem Booten folgende schwerwiegenden Fehler im Log auf:

kernel: Buffer I/O error on dev dm-15, logical block 8892681, lost async page write
kernel: sd 4:0:0:0: [sdc] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
kernel: sd 4:0:0:0: [sdc] Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdc] Add. Sense: Logical unit communication failure
kernel: sd 4:0:0:0: [sdc] CDB: Write(16) 8a 00 00 00 00 00 37 7d 48 00 00 00 40 00 00 00
kernel: blk_update_request: I/O error, dev sdc, sector 930957312
kernel: sd 4:0:0:0: [sdc] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE


Aber auch folgende syslog events traten auf, nachdem mittels:

lvmcreate -L 10G -n lv_snapshot -S vg/lv

ein snapshot erzeugt wurde.

kernel: EXT4-fs (dm-28): INFO: recovery required on readonly filesystem
kernel: EXT4-fs (dm-28): write access will be enabled during recovery
kernel: EXT4-fs warning (device dm-28): ext4_clear_journal_err:4718: Filesystem error recorded from previous mount: IO fail
ure
kernel: EXT4-fs warning (device dm-28): ext4_clear_journal_err:4719: Marking fs in need of filesystem check.
kernel: EXT4-fs (dm-28): recovery complete
kernel: EXT4-fs (dm-28): mounted filesystem with ordered data mode. Opts: (null)
kernel: EXT4-fs (dm-28): INFO: recovery required on readonly filesystem
kernel: EXT4-fs (dm-28): write access will be enabled during recovery
kernel: EXT4-fs (dm-28): orphan cleanup on readonly fs
kernel: EXT4-fs (dm-28): 6 orphan inodes deleted
kernel: EXT4-fs (dm-28): recovery complete

Schlimmer noch, die VMs wechselten nach kurzer Zeit in den read only Modus. Und konnten ohne erweitertes Filesystem Check nicht wieder gestart werden.

Zugglück sind wir schnell auf den Kernel Parameter gekommen, der das Problem verursacht hat.

cat /sys/block/sda/queue/max_sectors_kb
32767

Dieser Wert war bei älteren Servern noch auf 512 eingestellt. Bei den von dem Bug betroffenen Server durfte er nicht über 4096 eingestellt sein, stand aber immer wieder auf 8192.

Der CentOS Bug Report 12725, in dem das selbe verhalten mittels:

parted -s /dev/sda unit s print

beschrieben wurdet, half uns den Fehler weiter auf den Kernel einzuschränken. Immer wenn eine Partitionsabfrage, oder eine Änderung am LVM Stattgefunden hat, änderte sich der Wert plötzlich wieder auf 8192.

Folgende udev Regel, die wir unter /etc/udev/rules.d/99-san.rules eingefügt haben, verhinderte das umstellen des wertes:

ACTION=="add|change", ENV{ID_FS_USAGE}!="filesystem", ENV{ID_PATH}=="*-iscsi-*", RUN+="/bin/sh -c 'echo 4096 > /sys$DEVPATH/queue/max_sectors_kb'"

Fazit:
Ein so schwerwiegenden Kernel Bug ist mit schon lange nicht mehr untergekommen. Er hatte für uns zufolge das wir bei einzelnen VMs nur noch teile retten konnten und komplett aus dem Backup wiederhergestellt werden mussten. Auch das Rechercheiren des Bugs ist bei CentOS kaum möglich. Da es zu RedHat binär kompatibel kann man nicht einfach durch ein git repository zu scrolen und sich die Änderungen und Kommentare anschauen. Wo bei mir die Überlegung offen ist, zukünftig auf einen Vanilla-Kernel zu wechseln und/oder CentOS zu vermeiden.

Unser Kernel: 3.10.0-514.6.1.el7.x86_64
Quelle Burgreport: https://bugs.centos.org/view.php?id=12725