Proxmox: Fedora 40 zerstört Filesystem wegen uraltem SCSI Bug

Posted on by

Es läuft nicht gut für neue Fedora Versionen. Erst diese Gnome 47 Bugs auf dem Tablet bei Fedora 41, dann die Sache mit dem Wayland & Cinnamon und jetzt hat es uns bei Fedora 40 fast einen Server gekostet 🙁

Proxmox: Fedora 40 zerstört Filesystem wegen uraltem SCSI Bug

Jetzt muß ich ein bisschen ausholen:

Anfang des Jahres haben wir einen neuen Server mit Proxmox als Virtualisierungsgrundlage installiert. Wenn man der Hilfe zur Einrichtung von VMs und der besten Auswahl des Festplattentreiber glaubt, dann ist SCSI die beste Wahl: Beste Performance, abgehangenes System, seit 1995 im Einsatz, simuliert jede Menge Platten gleichzeitig usw.

Also wurden, ohne groß darüber nachzudenken, die VMs im Standardmodus mit SCSI angelegt. Dann zogen die Daten auf den Server und er lief genauso gut, wie wir das von der Hardware erwartet hatten. Bis letzten Mittwoch  22 Uhr 🙁

Gut das so etwas um 22 Uhr gemacht wird!

Um 22 Uhr am Mittwoch wurde das System von Fedora 39 auf Fedora 40 aktualisiert, da Fedora 39 EOL hatte. Da man das nicht simulieren kann, wie ein System reagiert, legt man davor einen Snapshot an. Dann kann man nach dem Update mit geringen Verlusten zurück zu einem funktionierenden System, wenn man denn merkt, daß es nicht geht 🙁

Eine halbe Stunde nach dem Update fiel mir auf, daß ich vergessen hatte das Datenbankupgradescipt laufen zu lassen, was per se nicht weiter schlimm war, da man das jederzeit nachholen kann. Das Mysql Upgradescript behebt bekannte Fehler der Vorgängerversionen an den Datenbeständen und optimiert das alles. Jetzt hatten wir da 8 GB in 400 Datenbanken drin, so daß Mysql ein bisschen was zu tun hatte und dann passierte es: Das System blieb stehen!

Load von 600, 100% iowait auf allen Kernen, keine Programmneustarts mehr und keine ersichtliche Ursache, was das ausgelöst hat auf einer 7 GB/s NVME.. und dann… puff.. löste sich der Stillstand von alleine nach einigen Minuten auf. Da dachte ich noch, daß Upgradescript wäre Schuld, was es im Prinzip auch war, aber es war nicht die Ursache, sondern nur der Auslöser. Die wahre Ursache zeigte sich erst, nachdem sich das mehrfach wiederholt hatte, ohne das das Script lief.

Der Kernel loggte es zum Glück

hier ein kleiner Auszug was passierte:

[ +4,915102] sd 2:0:0:0: ABORT operation timed-out.
[ +0,009657] scsi target2:0:0: TARGET RESET operation started
[Nov15 00:20] scsi target2:0:0: TARGET RESET operation timed-out.
[ +0,000006] scsi target2:0:1: TARGET RESET operation started
[Nov15 00:21] scsi target2:0:1: TARGET RESET operation timed-out.
[ +9,830340] sd 2:0:0:0: [sda] tag#389 ABORT operation started
[ +0,002342] sym0: SCSI BUS reset detected.
[ +0,007025] sym0: SCSI BUS has been reset.
[ +0,000016] sd 2:0:0:0: ABORT operation complete.
[ +3,193349] sd 2:0:1:0: Power-on or device reset occurred
[ +0,000056] sd 2:0:0:0: [sda] tag#389 BUS RESET operation started
[ +0,002306] sym0: SCSI BUS reset detected.
[ +0,007090] sym0: SCSI BUS has been reset.
[ +0,000010] sd 2:0:0:0: BUS RESET operation complete.
[ +10,058980] sd 2:0:0:0: Power-on or device reset occurred
[ +0,016222] sd 2:0:1:0: [sdb] tag#393 timing out command, waited 180s
[ +0,000005] sd 2:0:1:0: [sdb] tag#393 FAILED Result: hostbyte=DID_REQUEUE driverbyte=DRIVER_OK cmd_age=279s
[ +0,000002] sd 2:0:1:0: [sdb] tag#393 CDB: Write(10) 2a 00 00 00 a6 40 00 02 00 00
[ +0,000001] I/O error, dev sdb, sector 42560 op 0x1WRITE) flags 0x8800 phys_seg 64 prio class 2
[ +0,000003] I/O error, dev sdb, sector 42560 op 0x1WRITE) flags 0x8800 phys_seg 64 prio class 2
[ +0,000002] sd 2:0:1:0: [sdb] tag#394 timing out command, waited 180s
[ +0,000002] sd 2:0:1:0: [sdb] tag#394 FAILED Result: hostbyte=DID_REQUEUE driverbyte=DRIVER_OK cmd_age=279s
[ +0,000001] sd 2:0:1:0: [sdb] tag#394 CDB: Write(10) 2a 00 00 00 a3 40 00 03 00 00
[ +0,000000] I/O error, dev sdb, sector 41792 op 0x1WRITE) flags 0xc800 phys_seg 96 prio class 2
[ +0,000001] I/O error, dev sdb, sector 41792 op 0x1WRITE) flags 0xc800 phys_seg 96 prio class 2
[ +0,000002] sd 2:0:1:0: [sdb] tag#395 timing out command, waited 180s
[ +0,000001] sd 2:0:1:0: [sdb] tag#395 FAILED Result: hostbyte=DID_REQUEUE driverbyte=DRIVER_OK cmd_age=279s
[ +0,000001] sd 2:0:1:0: [sdb] tag#395 CDB: Write(10) 2a 00 00 00 a0 40 00 03 00 00
[ +0,000000] I/O error, dev sdb, sector 41024 op 0x1WRITE) flags 0xc800 phys_seg 96 prio class 2
[ +0,000001] I/O error, dev sdb, sector 41024 op 0x1WRITE) flags 0xc800 phys_seg 96 prio class 2
[ +0,000013] sd 2:0:1:0: [sdb] tag#396 timing out command, waited 180s
[ +0,000002] sd 2:0:1:0: [sdb] tag#396 FAILED Result: hostbyte=DID_REQUEUE driverbyte=DRIVER_OK cmd_age=279s
[ +0,000000] sd 2:0:1:0: [sdb] tag#396 CDB: Write(10) 2a 00 00 00 9e 40 00 02 00 00
[ +0,000001] I/O error, dev sdb, sector 40512 op 0x1WRITE) flags 0x8800 phys_seg 64 prio class 2
[ +0,000000] I/O error, dev sdb, sector 40512 op 0x1WRITE) flags 0x8800 phys_seg 64 prio class 2

Wie man sehen kann, sprang die simulierte Festplatte vom simulierten Bus runter. Wer bitte baut so eine Scheiße in ein Virtualisierungssystem ein?????? Stellt sich raus, niemand. Die Ursache liegt im Gastkernel, denn im RingBuffer vom Kernel von Proxmox war gar nichts zu sehen. Es handelte sich also um eine interne Angelegenheit der VM.

Aber wie beheben wir das?

Überlegung: „Der SCSI Treiber ist ein Sub-System vom Kernel, da wird wohl der aktuelle Kernel buggy sein.“

Also rebootet das System mit dem Kernel der vorher wunderbar lief. Das Systeme bootete und lief… denkste! Das ganze ging dermaßen in die Hose, daß der Kernel gecrasht ist!

Am Anfang lief es gut, aber das hat es mit dem Fedora 40 Kernel auch, bis es dann nicht mehr lief.

[ +26,879827] watchdog: BUG: soft lockup – CPU#1 stuck for 118s! [kworker/1:3:120797]
[ +0,000015] Modules linked in: xt_owner ipt_REJECT nf_reject_ipv4 xt_connlimit nf_conncount nf_conntrack nf_defrag_ipv6 nf_defrag_ip
v4 ip6table_filter ip6_tables xt_multiport iptable_filter ip_tables cfg80211 rfkill sunrpc intel_rapl_msr intel_rapl_common intel_unco
re_frequency_common nfit libnvdimm kvm_intel kvm irqbypass i2c_piix4 rapl virtio_balloon joydev fuse loop nfnetlink crct10dif_pclmul c
rc32_pclmul crc32c_intel polyval_clmulni bochs polyval_generic ghash_clmulni_intel sha512_ssse3 drm_vram_helper sha256_ssse3 drm_ttm_h
elper virtio_net ttm sym53c8xx sha1_ssse3 net_failover scsi_transport_spi failover serio_raw ata_generic pata_acpi qemu_fw_cfg
[ +0,000024] CPU: 1 PID: 120797 Comm: kworker/1:3 Tainted: G L 6.8.11-200.fc39.x86_64 #1
[ +0,000002] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
[ +0,000001] Workqueue: events netstamp_clear
[ +0,000006] RIP: 0010:smp_call_function_many_cond+0x12e/0x560
[ +0,000004] Code: 73 35 48 63 e8 49 8b 1f 48 81 fd 00 20 00 00 0f 83 f6 03 00 00 48 03 1c ed a0 4c c0 bb 8b 53 08 48 89 de 83 e2 01
74 0a f3 90 <8b> 4e 08 83 e1 01 75 f6 83 c0 01 eb b1 48 83 c4 40 5b 5d 41 5c 41
[ +0,000001] RSP: 0018:ff36e8b984593d60 EFLAGS: 00000202
[ +0,000001] RAX: 0000000000000000 RBX: ff26fb3f2483ce00 RCX: 0000000000000001
[ +0,000001] RDX: 0000000000000001 RSI: ff26fb3f2483ce00 RDI: ff26fb3940156b98
[ +0,000000] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000006
[ +0,000001] R10: 0000000000000002 R11: 0000000000000000 R12: ff26fb3f248b5ac0
[ +0,000000] R13: 0000000000000001 R14: 0000000000000001 R15: ff26fb3f248b5ac0
[ +0,000001] FS: 0000000000000000(0000) GS:ff26fb3f24880000(0000) knlGS:0000000000000000
[ +0,000001] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ +0,000001] CR2: 000014bce6b69d60 CR3: 000000010d428003 CR4: 0000000000771ef0
[ +0,000002] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ +0,000001] DR3: 0000000000000000 DR6: 00000000fffe07f0 DR7: 0000000000000400
[ +0,000000] PKRU: 55555554
[ +0,000001] Call Trace:
[ +0,000002] <IRQ>
[ +0,000002] ? watchdog_timer_fn+0x1e6/0x270
[ +0,000003] ? __pfx_watchdog_timer_fn+0x10/0x10
[ +0,000002] ? __hrtimer_run_queues+0x113/0x280
[ +0,000001] ? ktime_get_update_offsets_now+0x49/0x110
[ +0,000004] ? hrtimer_interrupt+0xf8/0x230
[ +0,000001] ? __sysvec_apic_timer_interrupt+0x4d/0x140
[ +0,000003] ? sysvec_apic_timer_interrupt+0x6d/0x90
[ +0,000002] </IRQ>
[ +0,000001] <TASK>
[ +0,000000] ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
[ +0,000004] ? smp_call_function_many_cond+0x12e/0x560
[ +0,000001] ? __pfx_do_sync_core+0x10/0x10
[ +0,000003] on_each_cpu_cond_mask+0x24/0x40
[ +0,000001] text_poke_bp_batch+0xbe/0x300
[ +0,000001] ? arch_jump_label_transform_queue+0x57/0x80
[ +0,000003] text_poke_finish+0x1f/0x30
[ +0,000002] arch_jump_label_transform_apply+0x1a/0x30
[ +0,000002] static_key_enable_cpuslocked+0x63/0x90
[ +0,000003] static_key_enable+0x1a/0x20
[ +0,000001] process_one_work+0x173/0x340
[ +0,000004] worker_thread+0x27b/0x3a0
[ +0,000002] ? __pfx_worker_thread+0x10/0x10
[ +0,000001] kthread+0xe5/0x120
[ +0,000002] ? __pfx_kthread+0x10/0x10
[ +0,000001] ret_from_fork+0x31/0x50
[ +0,000002] ? __pfx_kthread+0x10/0x10

Ihr könnt Euch sicher denken, daß derartige IO Fehler nicht gut für das Filesystem und den Datenbestand sind, wenn man auch noch hart reseten muß, um die VM wieder zu starten.  Datenverlust vorprogrammiert.

Nächster Versuch

Überlegung: „Das ist SCSI, aber Proxmox kann auch SATA.“

Also biss ich um 2:30 Uhr in den sauren Apfel und wir hatten Glück, das noch genug Platz auf der Storage war, wir reden hier nämlich von TBweise Platz:

  1. VM gestoppt
  2. neue Festplatten exakt gleicher Größe angelegt, aber als SATA Gerät.
  3. VM mit Fedora 38 LiveDisk gestartet
  4. Alte Platten 1:1 auf die neuen Platten kopiert:
    dd if=/dev/sdalt of=/dev/sdneu bs=128M status=progress
  5. VM umkonfiguriert, so daß SATA zuerst bootet
  6. VM gestartet
  7. gebannt auf den RingBuffer vom Kerne gestarrt

Da die Maschine beim nächtlichen Backup abgestürzt war, muß das eh nachgeholt werden und wenn dieser Stresstest durchgehen würde, dann wäre das Problem bestimmt gelöst. Also startete das Backup durch und siehe da, nicht ein aufmucken, keine Einträge im Kernel. Geschafft!

Gegen 5 war ich dann endlich im Bett, weil wir natürlich im jugendlichen Leichtsinn mehr als einen Server auf dem Proxmox aktualisiert hatten und die brauchten die gleiche Prozedur 🙁

Die Geister von 2015 holen einen immer wieder ein

Ihr lest richtig: 2015. 2015 wurde ein Fehler im Linux Kernel SCSI Subsystem behoben, der genau diese Auswirkungen hatte. Und welche waren das? Das SCSI Subsystem hat auf die Steuersignale vom Controller nicht richtig reagiert und dann eine Art Deadlock erschaffen, wenn da zuviele IO Requests durchgingen, der erst nach 5-10 MInuten aufgelöst wurde, also genau das, was wir jetzt auch hatten: Lahmarsch IO => läuft / High Performance Kleinteil IO => Deadlock / 5-10Minuten bis Auflösung.

Das nennt man eine Übersättigung des Treibers mit IO-Requests, passiert, wenn z.b. zig tausende Request jeweils nur einen Block haben wollen, statt in weniger Requests einfach größere Blöcke zu transportieren. Darf natürlich trotzdem nicht passieren, sondern der Treiber muß die Prozesse blockieren, bis wieder genug Reserven frei sind, was beim SATA Driver offensichtlich der Fall ist, beim SCSI Treiber gabs wohl vermutlich irgendwann zwischen 2015 und heute eine REGRESSION, die den alten Bug wieder eingebaut hat. Das letzte mal, daß ich so einen Fehler gesehen habe, da hatte die Jahreszahl noch 2 Nullen drin 😉

Jetzt ist es aber viel zu leicht, nur dem Kernel die Schuld zu geben, denn wir hatten mit Fedora 39 den gleichen Kernel ( Version ) laufen, wie mit Fedora 40 und der zeigte das Problem ja auch erst zusammen mit dem Rest von Fedora 40 und nicht schon mit Fedora 39. Da muß also etwas in der Distro sein, daß das ausgelöst hat!

Reaktionen

Nicht so gut gelaufen. Wir haben Montag und ich habe bei Proxmox und beim Fedora im Kernelteam ( weil ist am Ende halt doch ein Kernelbug ) noch in der Nacht vom Mittwoch auf Donnerstag letzter Woche einen Bugreport bzw. einen Foreneintrag eröffnet.

Keine der beiden Parteien äußerte sich, wobei ich das bei Proxmox verstehen kann, ist ja nur das Forum und ohne Subscription gibt es keinen Support. Das auch niemand aus der Community geantwortet hat, das ist dann doch bedenklich, weil das Forum von Proxmox ist genau der Ort, wo das schon 2015 gefunden wurde!

Das das Kernelteam jetzt erstmal vor einem fetten Haufen Mist steht und nicht weiß, wo es da anfangen soll mit rumstochern, kann ich auch verstehen, zumal das Fedora Maintainerteam ja nicht die Kernelentwickler sind. Aber gar nicht zu reagieren auf so einen Fatalen Fehler, der ein Produktionssystem zu einem Datenverlust geleitet hat, das geht nun mal auch nicht.

Zum Glück habe ich einen von denen nächsten Donnerstag zu meiner privaten Verfügbarkeit, da werde ich ihn mal drauf ansprechen, wieso da nichts passiert 😀