chr.istoph, der Blog

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

Nach dem der Cisco Switch beim Letzten Stromausfall nicht überlebt hat. Ist jetzt auch einer meiner ältesten Server nicht mehr da.
Bei einer Uptime von 2847 Tagen habe ich das Letzte Screenshot gemacht:

Neben der Uptime habe ich auch mittels dumpe2fs /dev/sda1 den Zeitpunkt anzeigen lassen wann das Filesystem das letzte mal ein gehangen wurde. Das war am 08.02.2009.

Da heutzutage Server Quasi täglich mit Sicherheitsupdates versorgt werden müssen und es mittlerweile stabile Livemigration von VMs gibt. Wird es bei mir nicht mehr vorkommen, dass ein Server eine derart hohe Uptime erreichen wird.