Metadata CRC error detected at xfs_sb_read_verify


mgutt

Recommended Posts

Ich konnte gestern Abend meinen Server nicht mehr erreichen, wobei ein Docker noch erreichbar war, alle anderen, sowie die Unraid WebGUI und der Unraid SMB Server aber komplett tot waren.

 

Ich habe dann die Ausgabe per HDMI geprüft und folgende Fehlermeldung wurde angezeigt:

Metadata CRC error detected at xfs_sb_read_verify
XFS (md11) Unmount and run xfs_repair
XFS (md11) First 128 bytes of corrupted metadata buffer:
...
Hex Code
...
JMicron_Tech

1895811922_2021-03-3111_22_53.png.89fb1564020875beca29f69cff5bd5f5.png

 

"md11" sagt ja eigentlich aus, dass Disk11 das Problem sein müsste. Aber witzigerweise ist Disk11 morgens erst frisch formatiert worden, komplett leer und müsste zu dem Zeitpunkt des Absturzes sogar geschlafen haben.

 

Im Hex-Code steht außerdem "Jmicron_Tech". Das wäre wiederum eines der beiden USB-Laufwerke, die ich per Unassigend Devices gemountet habe und die gerade wie folgt einen sync durchführen:

rsync -av --stats --checksum /mnt/disks/JMicron_Tech3/ /mnt/disk6
rsync -av --stats --checksum /mnt/disks/JMicron_Tech4/ /mnt/disk6

 

Jedenfalls habe ich die USB Laufwerke abgesteckt und jeweils kurz gewartet. Erst als ich das zweite abgesteckt habe, kam der Login-Bildschirm im Terminal. Keine Ahnung ob das Zufall war, aber ich werde diese Disk natürlich zuerst untersuchen.

 

Dann habe ich mich angemeldet und gleich versucht rsync zu killen, weil das ja der einzige Prozess war, der auf die USB Laufwerke zugegriffen hat:

pkill -x rsync -c

 

Der Befehl wollte aber nicht zum Ende kommen. Ich habe dann mit "top" die Prozesse gesichtet und nichts lief. Also 0,1% CPU Last und kein rsync Prozess zu sehen. Entweder waren sie schon weg oder sie wurden doch gekillt. Ich habe den Befehl wiederholt, blieb aber trotzdem erneut hängen.

 

Also habe ich versucht die WebGUI neuzustarten:

/etc/rc.d/rc.nginx restart

 

 

Es wurde aber nur angezeigt, dass Nginx noch läuft. Also habe ich den Server mit "reboot" versucht neu zu starten, aber auch das wollte kein Ende finden. Also muss ich ihn hart abschalten.

 

Nach einem Neustart habe ich das Array im Wartungsmodus gestartet und für jede Disk eine Reparatur durchgeführt (sollte man immer machen, wenn man hart abschaltet) und er machte auch einiges auf den Disks:

xfs_repair -vL /dev/md1
xfs_repair -vL /dev/md2
xfs_repair -vL /dev/md3
...

 

 

Erstaunlich ist, dass auf allen Disks Reparaturen durchgeführt wurden. Sogar auf Disk11, die ich gestern erst frisch formatiert habe und auf der wie gesagt keinerlei Dateien liegen:

xfs_repair -vL /dev/md11
Phase 1 - find and verify superblock...
        - block cache size set to 2951880 entries
Phase 2 - using internal log
        - zero log...
zero_log: head block 859 tail block 855
ALERT: The filesystem has valuable metadata changes in a log which is being
destroyed because the -L option was used.
        - scan filesystem freespace and inode maps...
sb_fdblocks 4363244241, counted 4394060165
        - found root inode chunk
...
Phase 7 - verify and correct link counts...
Maximum metadata LSN (1:857) is ahead of log (1:2).
Format log to cycle 4.

        XFS_REPAIR Summary    Wed Mar 31 11:16:01 2021

Phase           Start           End             Duration
Phase 1:        03/31 11:15:34  03/31 11:15:34
Phase 2:        03/31 11:15:34  03/31 11:15:43  9 seconds
Phase 3:        03/31 11:15:43  03/31 11:15:43
Phase 4:        03/31 11:15:43  03/31 11:15:43
Phase 5:        03/31 11:15:43  03/31 11:15:43
Phase 6:        03/31 11:15:43  03/31 11:15:43
Phase 7:        03/31 11:15:43  03/31 11:15:43

Total run time: 9 seconds
done

 

Ich habe dann die USB-Laufwerke wieder verbunden. Sie werden nun wie erwartet nicht als "mdX" angezeigt, sondern nur als "sdX" bzw "/mnt/disks/X":

lsblk
NAME   MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
...
sdj      8:144  0 931.5G  0 disk 
└─sdj1   8:145  0 931.5G  0 part /mnt/cache
sdk      8:160  0  16.4T  0 disk 
└─sdk1   8:161  0  16.4T  0 part 
sdl      8:176  0  10.9T  0 disk 
└─sdl1   8:177  0  10.9T  0 part 
sdm      8:192  0  10.9T  0 disk 
└─sdm1   8:193  0  10.9T  0 part /mnt/disks/JMicron_Tech3
sdn      8:208  0  10.9T  0 disk 
└─sdn1   8:209  0  10.9T  0 part /mnt/disks/JMicron_Tech4
md1      9:1    0  10.9T  0 md   /mnt/disk1
md2      9:2    0  10.9T  0 md   /mnt/disk2
md3      9:3    0  10.9T  0 md   /mnt/disk3
md4      9:4    0  10.9T  0 md   /mnt/disk4
md5      9:5    0  10.9T  0 md   /mnt/disk5
md6      9:6    0  16.4T  0 md   /mnt/disk6
md8      9:8    0  16.4T  0 md   /mnt/disk8
md9      9:9    0  10.9T  0 md   /mnt/disk9
md10     9:10   0  16.4T  0 md   /mnt/disk10
md11     9:11   0  16.4T  0 md   /mnt/disk11

 

Keines der USB-Laufwerke zeigt SMART-Fehler an. Der kurze SMART-Check ist auch fehlerfrei durchgelaufen. Was lernen wir daraus? Vermutlich liegt es am USB-Adapter. Der ist nach der langen Belastung vermutlich ausgestiegen. Aber warum zeigte der mir dann einen Fehler auf md11 an und warum zieht das gleich den ganzen Server in Mitleidenschaft? Finde ich echt nervig.

 

Ich hätte ja gerne SATA für die Übertragung der Daten genommen, aber ich wollte nicht extra eine größere Unraid-Lizenz kaufen, weil ich ja schlussendlich weniger und nicht mehr Disks im Array haben will. Meine Lösung wird daher denke ich jetzt sein, dass ich die Parität abklemme und über SATA die Daten kopiere bzw ich muss mal schauen ob ich Hot Swap zum Laufen bringe. Dann könnte ich das Lizenz-Problem umgehen. War auf jeden Fall wieder ein kleines Abenteuer.

Link to comment
5 hours ago, mgutt said:

er machte auch einiges auf den Disks

 

Das muss nichts heissen. Aktuelle Dateisysteme besitzen wie Datenbanken einen Transaktions-Puffer (transaction log). Alle Änderungen wandern da durch und der Transaktions-Manager arbeitet diese ab. Sobald abgeschlossen werden die Änderungen als "abgeschlossen" markiert (commit). Bei einem ordentlichen Shutdown werden alle hängenden Änderungen, inkl. das Log selbst, noch synchronisiert. Bei einem harten Shutdown geht das naturgemäß nicht. Das geschieht dann nach dem mounten oder bei einem repair.

 

Wie bei Datenbanken können mehrere Änderungen (Metadaten, Daten, ...) in einer Transaktion stecken. Erst wenn alle Änderungen einer Transaktion erfolgreich abgeschlossen wurden, wird die Transaktion als solche markiert.

 

5 hours ago, mgutt said:

sollte man immer machen, wenn man hart abschaltet

 

Also das habe ich noch nie gemacht. Wo hast Du das her?

 

Meiner bescheidenen Meinung nach ist das nicht notwendig. Der Transaktion-Manager wird beim mount ohnehin das transaction-log prüfen und unvollständige Transaktion bearbeiten. Erst danach startet der Parity-Sync.

 

Mag mich aber irren und bin bereit neu zu lernen.

 

  • Thanks 1
Link to comment

Ich habe nach xfs_repair auf einer Platte Lost+Found Dateien gehabt. Waren unwichtig, aber durch einen normalen Mount wären die nicht aufgetaucht. Bei einer weiteren Disk wurde nicht nur bei "Phase 2" etwas repariert, sondern in 4 verschiedenen Phasen:

2021-03-31_10-52-20_02-00_916_667_1600747_1.jpg.2585c8c76dc337b53ab83e8d5990ee01.jpg

 

Das war meine ich Disk8 des Arrays, welche zum Zeitpunkt des Absturzes auch nicht in Verwendung war. 

 

Da ist also etwas mehr passiert als nur Logs abzuarbeiten, würde ich sagen.

Link to comment

Mittlerweile habe ich alle Platten über SATA verbunden. Dann habe ich wieder den Sync angestoßen und gestern Abend hatte ich erneut einen Fehler. Die WebGUI war nicht erreichbar. SMB war ebenfalls tot. Später am Abend lief der Server dann ohne mein Zutun wieder. In den System Logs war zum Zeitpunkt des Fehlers nur das geloggt worden:

Apr  2 20:34:21 Thoth emhttpd: cmd: /usr/local/emhttp/plugins/user.scripts/showLog.php rsync2
Apr  2 21:17:43 Thoth nginx: 2021/04/02 21:17:43 [error] 6418#6418: *349331 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.178.30, server: , request: "GET /Dashboard HTTP/1.1", subrequest: "/auth_request.php", upstream: "fastcgi://unix:/var/run/php5-fpm.sock", host: "thoth"
Apr  2 21:17:43 Thoth nginx: 2021/04/02 21:17:43 [error] 6418#6418: *349331 auth request unexpected status: 504 while sending to client, client: 192.168.178.30, server: , request: "GET /Dashboard HTTP/1.1", host: "thoth"
Apr  2 21:59:54 Thoth emhttpd: cmd: /usr/local/emhttp/plugins/dynamix/scripts/disk_log sde
Apr  3 00:00:07 Thoth crond[1901]: exit status 1 from user root /usr/local/sbin/mover &> /dev/null

 

Der Server war nach 20:34 irgendwann nicht erreichbar. Ich tippe auf den Eintrag um 21:17 Uhr, wo ich versucht habe die WebGUI zu öffnen.

 

Da ich wieder zwei rsyncs laufen hatte, kann ich nun keine Platte eingrenzen. SMART sieht bei allen Platten nach wie vor in Ordnung aus.

 

Eventuell gibt es auch ein Problem mit den Logs, die rsync produziert. Ich sehe nämlich gerade, dass die Log-Datei des Scripts 13GB groß ist. Die RAM Auslastung ist für meine Verhältnisse hoch, aber noch weit von überlastet:

417384646_2021-04-0314_02_29.png.c412d972613f1bc092a72ebd0d6c40fe.png

 

Leider gibt rsync in den Logs keinen Timestamp aus. Vielleicht hatte ja ein Script zu dem Zeitpunkt seine Arbeit erledigt?! EDIT: Nein, das Änderungsdatum deutet nicht darauf hin. Die eine rsync Log-Datei wurde um 01:30 Uhr das letzte mal beschrieben und die andere um 01:20 Uhr. Wirklich komisch. Ich werde jetzt mal die Log-Dateien beide löschen und die rsync Skripte diesmal nacheinander laufen lassen. Außerdem habe ich das Kommando angepasst, so dass rsync hoffentlich auch einen Zeitstempel ausgibt. Dann kann ich hoffentlich wenigstens den Zeitraum eingrenzen.

 

EDIT: Der Server muss auf jeden Fall total überlastet gewesen sein, denn ich lasse ein Skript alle 15 Minuten ausführen und um 21:15 sollte ein Skript ausgeführt werden, das erst um 21:18 gestartet wurde:

1715798876_2021-04-0315_32_26.thumb.png.0784240aba95912af5d1e839bcad6319.png

 

Ein anderes Script läuft alle 5 Minuten und auch da gab es Verzögerungen:

803339752_2021-04-0315_36_45.thumb.png.010c4aaed4d7cee0b48e2d120900acbc.png

 

Es muss also schon um 21:10 ein Problem mit dem Server gegeben haben, wo dieses Script hätte ausgeführt werden müssen.

 

Leider habe ich mir die Zeit nicht notiert, aber um diese Zeit herum hatte ich mit Sonos versucht Musik über SMB abzuspielen. Die Musik liegt auf der SSD. Die SSD sieht auch in Ordnung aus, aber ich mache zur Sicherheit mal einen Screenshot von den SMART Werten für den späteren Vergleich:

725826122_2021-04-0315_34_13.thumb.png.e4618af935df08547b2550e0b153833f.png

 

Vielleicht hatte sich auch einfach nur der SMB Service böse aufgehangen, aber komisch, dass es keine Logs zu dem Zeitpunkt gibt.

 

Ich warte jetzt mal die beiden syncs ab und schaue ob sich der Fehler wiederholt. Außerdem habe ich das Script, das alle 5 Minuten ausgeführt wird, um folgende Zeile ergänzt, damit in den Logs auch die Prozesse und Auslastungen zu sehen sind:

top -b -c -n1 -d1 | head -n20

 

Link to comment

Bisher gab es keine weiteren Auffälligkeiten. Ich habe nun mein rsync Script wie folgt angepasst, damit ich in den Logs auch die Uhrzeit sehen kann:

#!/bin/bash
rsync -av --stats --delete --out-format="%t %n%L" --hard-links /mnt/user/Movie/09 /mnt/disks/WDC_WD180EDFZ
rsync -av --stats --delete --out-format="%t %n%L" --hard-links /mnt/user/Movie/AB /mnt/disks/WDC_WD180EDFZ
rsync -av --stats --delete --out-format="%t %n%L" --hard-links /mnt/user/Movie/CD /mnt/disks/WDC_WD180EDFZ
rsync -av --stats --delete --out-format="%t %n%L" --hard-links /mnt/user/Movie/YZ /mnt/disks/WDC_WD180EDFZ

 

Beispiel:

sending incremental file list
2021/04/04 22:28:35 09/
2021/04/04 22:28:35 09/10 Cloverfield Lane (2016)/
2021/04/04 22:28:35 09/10 Cloverfield Lane (2016)/10 Cloverfield Lane (2016) FSK16 DE EN IMDB7.2.mkv

 

 

 

Damit ist nun auch besser nachvollziehbar ob ein eventueller rsync Fehler damit in Verbindung steht.

 

 

Link to comment

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Reply to this topic...

×   Pasted as rich text.   Restore formatting

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.