Wine: Appcrashe führen zu Datenverlusten

Wine 6.9-1 für Fedora hat hier im exessiven Test zu Datenverlusten auf der Festplatte geführt, einer war so schwer, daß das System nur durch Zufall gerettet werden konnte.

Wine: Appcrashe führen zu Datenverlusten

Eigentlich wollte ich Euch ja die gute Nachricht mitteilen, daß einige Spiele, die eine Weile nicht mehr funktioniert haben, jetzt wieder laufen so z.B. Runes of Magic. Leider gab es schwere Kernel-Crashe mit Wine 6.9 wenn Runes of Magic lief, was zu mehreren Datenverlusten führte. Der jüngste Crash zerstörte Daten in der librpmio.so die von RPM benötigt wird und ohne die, kann man sein System weder updaten noch durch Reinstall retten. Da hier SSH noch lief, konnte die defekte Lib von einem anderen Fedora System kopiert werden, was den Fehler dann behoben hat.

Hier ein Beispiel:

Jun 6 14:23:58 eve kernel: general protection fault, probably for non-canonical address 0xdfff920ad662d0c8: 0000 [#1] SMP NOPTI
Jun 6 14:23:58 eve kernel: CPU: 1 PID: 12432 Comm: Client.exe Tainted: P OE 5.12.8-200.fc33.x86_64 #1
Jun 6 14:23:58 eve kernel: Hardware name: To be filled by O.E.M. To be filled by O.E.M./M5A97 R2.0, BIOS 2201 12/10/2013
Jun 6 14:23:58 eve kernel: RIP: 0010:__vma_unlink_list+0x1b/0x30
Jun 6 14:23:58 eve kernel: Code: 70 18 c3 48 8b 07 48 89 37 eb ea 0f 1f 40 00 0f 1f 44 00 00 48 8b 56 18 48 8b 46 10 48 85 d2 74 0e 48 89 42 10 48 85 c0 74 04 <48> 89 50 18 c3 48 89 07 eb f1 66 66 2e 0f 1f 84 00 00 00 00 00 0f
Jun 6 14:23:58 eve kernel: RSP: 0018:ffff9dff070b3ce0 EFLAGS: 00010282
Jun 6 14:23:58 eve kernel: RAX: dfff920ad662d0c8 RBX: 0000000000000000 RCX: 0000000000000000
Jun 6 14:23:58 eve kernel: RDX: ffff920aeb7a30c8 RSI: ffff920ad673e320 RDI: ffff920ac0a450c0
Jun 6 14:23:58 eve kernel: RBP: ffff920ad673e320 R08: ffff920ac0a450c8 R09: 0000000010099000
Jun 6 14:23:58 eve kernel: R10: 0000000000100000 R11: 0000000000000000 R12: ffff920aeb7a30c8
Jun 6 14:23:58 eve kernel: R13: 0000000000000000 R14: ffff920ac0a450c0 R15: 0000000000200070
Jun 6 14:23:58 eve kernel: FS: 00000000003e2000(0063) GS:ffff920deec40000(006b) knlGS:00000000f7fc7880
Jun 6 14:23:58 eve kernel: CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
Jun 6 14:23:58 eve kernel: CR2: 0000000025c7a004 CR3: 00000000264a0000 CR4: 00000000000406e0
Jun 6 14:23:58 eve kernel: Call Trace:
Jun 6 14:23:58 eve kernel: __vma_adjust+0x283/0xbf0
Jun 6 14:23:58 eve kernel: vma_merge+0x370/0x3c0
Jun 6 14:23:58 eve kernel: ? __do_munmap+0x319/0x510
Jun 6 14:23:58 eve kernel: mmap_region+0x171/0x720
Jun 6 14:23:58 eve kernel: do_mmap+0x433/0x540
Jun 6 14:23:58 eve kernel: ? security_mmap_file+0x81/0xd0
Jun 6 14:23:58 eve kernel: vm_mmap_pgoff+0xb8/0x160
Jun 6 14:23:58 eve kernel: ? __set_current_blocked+0x36/0x50
Jun 6 14:23:58 eve kernel: __do_fast_syscall_32+0x5c/0x90
Jun 6 14:23:58 eve kernel: do_fast_syscall_32+0x2f/0x70
Jun 6 14:23:58 eve kernel: entry_SYSCALL_compat_after_hwframe+0x45/0x4d
Jun 6 14:23:58 eve kernel: RIP: 0023:0xf7fcc559
Jun 6 14:23:58 eve kernel: Code: 10 05 03 74 b8 01 10 06 03 74 b4 01 10 07 03 74 b0 01 10 08 03 74 d8 01 00 00 00 00 00 00 00 00 00 51 52 55 89 cd 0f 05 cd 80 <5d> 5a 59 c3 90 90 90 90 8d b4 26 00 00 00 00 8d b4 26 00 00 00 00
Jun 6 14:23:58 eve kernel: RSP: 002b:0000000000c4d200 EFLAGS: 00000256 ORIG_RAX: 00000000000000c0
Jun 6 14:23:58 eve kernel: RAX: ffffffffffffffda RBX: 000000001ae90000 RCX: 000000000000e000
Jun 6 14:23:58 eve kernel: RDX: 0000000000000000 RSI: 0000000000004032 RDI: 00000000ffffffff
Jun 6 14:23:58 eve kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jun 6 14:23:58 eve kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
Jun 6 14:23:58 eve kernel: R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Jun 6 14:23:58 eve kernel: Modules linked in: xt_multiport twofish_generic twofish_avx_x86_64 twofish_x86_64_3way twofish_x86_64 twofish_common xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 ip6table_mangle ip6table_nat iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter tun bridge stp llc vboxnetadp(OE) vboxnetflt(OE) vboxdrv(OE) it87 hwmon_vid nvidia_drm(POE) nvidia_modeset(POE) nvidia_uvm(POE) uvcvideo videobuf2_vmalloc videobuf2_memops snd_usb_audio videobuf2_v4l2 videobuf2_common videodev snd_usbmidi_lib snd_rawmidi mc snd_hda_codec_realtek edac_mce_amd snd_hda_codec_hdmi snd_hda_codec_generic ledtrig_audio kvm_amd ccp snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec nvidia(POE) kvm snd_hda_core snd_hwdep eeepc_wmi asus_wmi irqbypass sparse_keymap snd_seq rfkill snd_seq_device wmi_bmof snd_pcm video k10temp fam15h_power snd_timer drm_kms_helper sp5100_tco snd i2c_piix4 cec
Jun 6 14:23:58 eve kernel: soundcore acpi_cpufreq binfmt_misc drm fuse zram ip_tables dm_crypt trusted mxm_wmi crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel serio_raw r8169 wmi
Jun 6 14:23:58 eve kernel: —[ end trace dfa7f7887fe5aab0 ]—
Jun 6 14:23:58 eve kernel: RIP: 0010:__vma_unlink_list+0x1b/0x30
Jun 6 14:23:58 eve kernel: Code: 70 18 c3 48 8b 07 48 89 37 eb ea 0f 1f 40 00 0f 1f 44 00 00 48 8b 56 18 48 8b 46 10 48 85 d2 74 0e 48 89 42 10 48 85 c0 74 04 <48> 89 50 18 c3 48 89 07 eb f1 66 66 2e 0f 1f 84 00 00 00 00 00 0f
Jun 6 14:23:58 eve kernel: RSP: 0018:ffff9dff070b3ce0 EFLAGS: 00010282
Jun 6 14:23:58 eve kernel: RAX: dfff920ad662d0c8 RBX: 0000000000000000 RCX: 0000000000000000
Jun 6 14:23:58 eve kernel: RDX: ffff920aeb7a30c8 RSI: ffff920ad673e320 RDI: ffff920ac0a450c0
Jun 6 14:23:58 eve kernel: RBP: ffff920ad673e320 R08: ffff920ac0a450c8 R09: 0000000010099000
Jun 6 14:23:58 eve kernel: R10: 0000000000100000 R11: 0000000000000000 R12: ffff920aeb7a30c8
Jun 6 14:23:58 eve kernel: R13: 0000000000000000 R14: ffff920ac0a450c0 R15: 0000000000200070
Jun 6 14:23:58 eve kernel: FS: 00000000003e2000(0063) GS:ffff920deec40000(006b) knlGS:00000000f7fc7880
Jun 6 14:23:58 eve kernel: CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
Jun 6 14:23:58 eve kernel: CR2: 0000000025c7a004 CR3: 00000000264a0000 CR4: 00000000000406e0
Jun 6 14:23:59 eve abrt-dump-journal-oops[1733]: abrt-dump-journal-oops: Found oopses: 1
Jun 6 14:23:59 eve abrt-dump-journal-oops[1733]: abrt-dump-journal-oops: Creating problem directories
Jun 6 14:24:00 eve abrt-dump-journal-oops[1733]: Reported 1 kernel oopses to Abrt

Das ist ein Crash, der glimpflich für das System abgelaufen ist, oder?

Leider nicht:

Jun 06 23:57:47 eve.resellerdesktop.de systemd-cryptsetup[11292]: Device luks-ffbd61f2-4c1e-4dc8-b12b-c89e9f69c9fa is still in use.
Jun 06 23:57:47 eve.resellerdesktop.de systemd-cryptsetup[11292]: Failed to deactivate: Device or resource busy

Die Luks-Partition konnte also beim Shutdown nicht geschlossen werden, weil da noch ein Prozess drauf zugriff, was Ihr im Log nicht sehen werdet, aber beim Runterfahren des PCs am Ende zum Umstand führt, daß der Rechner nicht, oder nur nach einer sehr langen Zeit abschaltet. Wer dann den Plymouth Schleier hebt und sich die Meldungen vom Systemd-Shutdown ansieht, der wird feststellen, daß ein Prozess nicht beendet werden kann.

Welcher war das wohl? Dreimal dürft Ihr raten.

Der Crash stört also den Datenzugriff auf die Platte, weil dabei der Kernel crasht kann es zum unkontrollierten Schreibzugriff auf den Datenträger kommen und der kann dann Dateien zerstören.

Natürlich ist hier nicht nur Wine Schuld, der Kernel darf auch nicht gleich mitcrashen. Ergo gibt es jetrzt einen Bugreport an Fedora und hoffenlich fixt das bald einer, weil mir langsam die gesunden Daten ausgehen 🙁

 

 

Nvidia: Fehlercodes

Seit einigen Wochen nervt meine GTX 1050, eine schöne Gelegenheit Euch mal das Nvidia Fehlersystem näher zu bringen.

Nvidia: Fehlercodes

Zuerst müssen wir natürlich erstmal wissen, welcher Fehler überhaupt aufgetreten ist. Dazu braucht es nur dmesg:

$ dmesg |grep Xid
[ 5552.987812] NVRM: Xid (PCI:0000:01:00): 32, pid=1550, Channel ID 00000033 intr 00040000
[ 5731.173383] NVRM: Xid (PCI:0000:01:00): 32, pid=11658, Channel ID 00000033 intr 00040000
[ 5731.173633] NVRM: Xid (PCI:0000:01:00): 32, pid=11658, Channel ID 00000033 intr 00040000
[ 6326.298292] NVRM: Xid (PCI:0000:01:00): 32, pid=11982, Channel ID 00000033 intr 00040000
[ 6326.298525] NVRM: Xid (PCI:0000:01:00): 32, pid=11982, Channel ID 00000033 intr 00040000

Wie bei allen Kernelmeldungen steht am Anfang die Kernelzeit in Sekunden seit dem Boot. Danach kommt als erstes die PCI ID des Gerätes, aber da selten jemand zwei oder mehr Grafikkarten im PC hat, ist das für die meisten uninteressant. Der Fehlercode selbst ist die unscheinbare Zahl nach der PCI ID, hier „32“.

Auf der Webseite von Nvidia: xid errors findet sich dann die Beschreibung für den Fehler und erste Hinweise zur Ursache:

XIDFailureCauses
HW ErrorDriver ErrorUser App ErrorSystem Memory CorruptionBus ErrorThermal IssueFB Corruption

31

GPU memory page fault

X

X

32

Invalid or corrupted push buffer stream

X

X

X

X

X

Xid 32 meint also, daß der Datenstrom zu Grafikkarte unterbrochen wurde. Mögliche Ursachen: Der Graka-Speicher ist defekt, der PCI Bus hat ne Macke oder irgendwas ist überhitzt. (FB Corruption meint FRAMEBUFFER kaputt, das sind die Strukturen im OS/Programm welche die Grafik handhaben. )

Wie man vorn sehen kann, handelt sich nicht um einen HW Fehler, sondern am wahrscheinlichsten um einen Grafikkartentreiberbug.

Ab jetzt kann man nur noch spekulieren, weil das ja alles mögliche meinen kann. Es geht sogar soweit, daß Xid 32 Probleme bei der Stromzuführung in die Grafikkarte meinen kann, also wenn das Netzteil schwächelt. Da aber der Bildschirm nicht ausgeht, hat die Graka noch genug Saft, das kann es also eigentlich nicht sein.

Jetzt können wir noch etwas ausschließen: Thermalprobleme

55 Grad sind völlig normal. Im Bild oben sind zwar die Lüfter aus, aber die funktionieren nachweislich, denn man hört sie bei der Arbeit 😉

Das Nvidia Settingstool (oben im Bild) kann man beim Gamen auf dem zweiten Monitor mitlaufen lassen und so die Anzeige im Auge behalten.

Vielleicht doch nur ein Treiberproblem?

Jetzt bringt uns das nicht weiter. Wir haben zwar 2 Sachen ausschließen können, aber es blieben immer noch FB Problem, Memoryproblem. Keins davon kann man prüfen.

Was man jetzt noch prüfen könnte, steht im /var/log/messages sofern man das noch hat. ( Habt Ihr nicht mehr, nur noch Systemd? Ihr tut mir so leid .. ehrlich 🙁 )

$ grep NVRM /var/log/messages

Jul 23 00:43:18 eve kernel: NVRM: Xid (PCI:0000:01:00): 31, pid=1923, Ch 00000020, intr 10000000. MMU Fault: ENGINE GRAPHICS GPCCLIENT_PE_0 faulted @ 0x1_0ca39000. Fault is of type FAULT_PTE ACCESS_TYPE_READ

Andere Fehlernummer.. interessant. Ist ein reiner Anwendungsbug. In diesem Fall in WINE. Wine hat in den letzten Wochen unheimlich viele Updates rausgehauen. Es wäre also wirklich im Bereich des Möglichen, daß Wine bzw. der 3D Treiber in Wine ( DXVK ) hier die eigentliche Ursache sind.

Wine hat allerdings noch ganz andere Probleme, die die Entwickler aber leider nicht wahr haben wollen, weil Bugreports ignoriert werden. Ab Wine-Staging 5.5+ kommt es zu einem wahrlich irren Bug:

Es kommt in Verbindung mit dem Grakafehler zu einem IO-Fehler mit dem DVD-ROM, welches aber gar nicht benutzt wird noch eine DVD drin hat. Das sieht dann so aus:

[22163.062313] sr 1:0:0:0: [sr0] tag#26 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
[22163.062316] sr 1:0:0:0: [sr0] tag#26 Sense Key : Not Ready [current]
[22163.062319] sr 1:0:0:0: [sr0] tag#26 Add. Sense: Medium not present – tray closed
[22163.062321] sr 1:0:0:0: [sr0] tag#26 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
[22163.062323] blk_update_request: I/O error, dev sr0, sector 0 op 0x0:(READ) flags 0x80700 phys_seg 2 prio class 0
[22163.062366] sr 1:0:0:0: [sr0] tag#3 unaligned transfer
[22163.062368] blk_update_request: I/O error, dev sr0, sector 0 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062370] Buffer I/O error on dev sr0, logical block 0, async page read
[22163.062382] sr 1:0:0:0: [sr0] tag#4 unaligned transfer
[22163.062383] blk_update_request: I/O error, dev sr0, sector 1 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062384] Buffer I/O error on dev sr0, logical block 1, async page read
[22163.062393] sr 1:0:0:0: [sr0] tag#5 unaligned transfer
[22163.062394] blk_update_request: I/O error, dev sr0, sector 2 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062395] Buffer I/O error on dev sr0, logical block 2, async page read
[22163.062404] sr 1:0:0:0: [sr0] tag#6 unaligned transfer
[22163.062405] blk_update_request: I/O error, dev sr0, sector 3 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062406] Buffer I/O error on dev sr0, logical block 3, async page read
[22163.062415] sr 1:0:0:0: [sr0] tag#7 unaligned transfer
[22163.062416] blk_update_request: I/O error, dev sr0, sector 4 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062417] Buffer I/O error on dev sr0, logical block 4, async page read
[22163.062425] sr 1:0:0:0: [sr0] tag#8 unaligned transfer
[22163.062427] blk_update_request: I/O error, dev sr0, sector 5 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062427] Buffer I/O error on dev sr0, logical block 5, async page read
[22163.062436] sr 1:0:0:0: [sr0] tag#9 unaligned transfer
[22163.062437] blk_update_request: I/O error, dev sr0, sector 6 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062438] Buffer I/O error on dev sr0, logical block 6, async page read
[22163.062446] sr 1:0:0:0: [sr0] tag#10 unaligned transfer
[22163.062448] blk_update_request: I/O error, dev sr0, sector 7 op 0x0:(READ) flags 0x0 phys_seg 2 prio class 0
[22163.062448] Buffer I/O error on dev sr0, logical block 7, async page read

und das ist nur beim Starten von Wine, da ist noch nicht mal eine GFX Operation gelaufen. Mit WIne 5.13 geht nicht mal ein Fenster auf, das ist derzeit komplett im *****.

Das bestärkt mich in der Annahme, daß es sich um reine Driverbugs handelt, die von WINE getriggert werden. Rein zur Vorsicht, habe ich das .nv/GLCache geleert, vielleicht lag da ja noch was defektes drin.

Mehr ist zu dem Zeitpunkt leider nicht feststellbar. Jetzt hilft nur Testen, updaten, Testen und weiter Testen.

 

Wine: Die SSD schonen

Ihr wollt mit Wine Spiele spielen, aber Eure SSD nicht unnötig belasten? Da könnte man was machen.

Wine: Die SSD schonen

Wer auf Linux Windows Spiele zocken möchte, der kommt um Wine nicht herum. Egal in welcher Form, es ist immer irgendwie beteiligt. Leider bedeutet das auch, daß Eure SSD alleine durchs Loggen von Debuginfos belastet wird. So eine Runde WOW kann da die Lebenszeit der SSD richtig dezimieren:

# grep fixme /var/log/messages |grep „Jun 28“ | grep -c fixme
711541

meint, am 28.Juni wurden ins Logfile 711.541 Zeilen von Wine geschrieben, fast alle mit dem gleichen, leeren Inhalt:

Jun 28 10:08:21 xxx /usr/libexec/gdm-x-session[2227]: 009e:fixme:rawinput:GetRawInputBuffer data (nil), data_size 0x22f7b0, header_size 24 stub!

Von den 711k Logzeilen macht die obige Zeile 708k aus, ohne Mehrwert für den User. Rechnet Euch mal aus, wieviele das übers Jahr sind!

Wie bekommt man das jetzt weg?

Zum Glück ist das einfach in der .desktop Datei vom jeweiligen Wine-Spiel zu lösen(hier WOW):

Ändert die Exec Zeile von so:

Exec=env WINEPREFIX=“/home/<username>/.wine“ /opt/wine-staging/bin/wine64 C:\\\\windows\\\\command\\\\start.exe /Unix /home/<username>/.wine/dosdevices/c:/Program\\ Files\\ (x86)/World\\ of\\ Warcraft/_retail_/Wow.exe

in so um:

Exec=env WINEPREFIX=“/home/<username>/.wine“ WINEDEBUG=-all /opt/wine-staging/bin/wine64 C:\\\\windows\\\\command\\\\start.exe /Unix /home/<username>/.wine/dosdevices/c:/Program\\ Files\\ (x86)/World\\ of\\ Warcraft/_retail_/Wow.exe

Danach ist Ruhe im Logfile und rsyslogd bzw. journald werden Euch danken, denn:

Jun 28 16:38:51 XXXXXXX rsyslogd[1506]: imjournal: 180769 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Jun 28 16:48:52 XXXXXXX rsyslogd[1506]: imjournal: 180635 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Jun 28 16:58:58 XXXXXXX rsyslogd[1506]: imjournal: 103949 messages lost due to rate-limiting (20000 allowed within 600 seconds)

das, was grep da gezählt hat, ist nur das, was im Logfile auch angekommen ist. In Wirklichkeit sind da tonnenweise Logzeilen weg gefiltert worden und trotz dessen waren es am Ende noch 711k ! Das müssen mehrere Millionen Zeilen gewesen sein, an nur einem einzigen Tag!

„Warum ist das nicht die Defaulteinstellung?“ würde man zurecht fragen, aber solange nur beim Start mal kurz was wichtiges geloggt wird, ok, aber 708.010x das eine 3D-Routine gefixt werde müßte?? Also da könnte man auch mal über sinnvolleres Loggen nachdenken, oder?