Heute morgen um 6:33 Uhr hat sich MariaDB auf unserem Host longmore verabschiedet. Die an sich automatisch laufende Recovery verlief dabei nicht wie geplant - am Ende war Einiges an Handarbeit nötig. Die Arbeiten konnten nun aber erfolgreich abgeschlossen werden und mögliche Datenverluste dürften unserer Einschätzung nach minimal sein.

Unser Monitoring alarmierte zunächst den einen, kurz darauf via Eskalation auch noch den zweiten Bereitschaftstechniker, und teilte mit, dass MariaDB auf longmore nicht mehr verfügbar sei. Ein erster Blick ins Journal verriet einen Crash:

Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: 191031  6:33:56 [ERROR] mysqld got signal 11 ;
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: This could be because you hit a bug. It is also possible that this binary
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: or one of the libraries it was linked against is corrupt, improperly built,
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: or misconfigured. This error can also be caused by malfunctioning hardware.
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: We will try our best to scrape up some info that will hopefully help
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: diagnose the problem, but since we have already crashed,
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: something is definitely wrong and this may fail.
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: Server version: 10.3.18-MariaDB
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: key_buffer_size=134217728
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: read_buffer_size=131072
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: max_used_connections=92
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: max_threads=402
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: thread_count=98
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: It is possible that mysqld could use up to
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1014852 K  bytes of memory
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: Hope that's ok; if not, decrease some variables in the equation.
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: Thread pointer: 0x7fd77c0009a8
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: Attempting backtrace. You can use the following information to find out
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: where mysqld died. If you see no messages after this, something went
Oct 31 06:33:56 longmore.uberspace.de mysqld[31247]: terribly wrong...
Oct 31 06:33:57 longmore.uberspace.de mysqld[31247]: stack_bottom = 0x7fd7cd19cd30 thread_stack 0x49000
Oct 31 06:33:58 longmore.uberspace.de mysqld[31247]: *** buffer overflow detected ***: /usr/sbin/mysqld terminated
[...]
Oct 31 06:33:59 longmore.uberspace.de systemd[1]: mariadb.service: main process exited, code=killed, status=6/ABRT
Oct 31 06:33:59 longmore.uberspace.de systemd[1]: Unit mariadb.service entered failed state.
Oct 31 06:33:59 longmore.uberspace.de systemd[1]: mariadb.service failed.
Oct 31 06:34:04 longmore.uberspace.de systemd[1]: mariadb.service holdoff time over, scheduling restart.
Oct 31 06:34:04 longmore.uberspace.de systemd[1]: Stopped MariaDB 10.3.18 database server.

So weit, so unschön. Wer schon länger mit MySQL oder dem von uns eingesetzten MySQL-Fork MariaDB zu tun hat, weiß, dass das jetzt nicht sooo selten ist, wie es wünschenswert wäre, und die Ansage “This could be because you hit a bug” in der Fehlermeldung häufig schlicht und einfach stimmt. Da wir bei MariaDB auf die offiziellen Pakete von MariaDB selbst zurückgreifen (und nicht auf ältere, separat gepflegte des Linux-Distributors), bekommen wir hier dann auch entsprechend jedes Minor-Release und damit jeden Bugfix zügig mit auf unsere Systeme. Unabhängig davon fummeln wir grundsätzlich nicht per Hand an den Dateien unterhalb von /var/lib/mysql herum - außer heute, wo es zwecks Problembehebung nicht anders ging.

Mit etwas Glück war so ein Crash eine einmalige Sache, die einfach nie wieder auftritt, insbesondere weil mit dem nächsten Update vielleicht der fragliche Bug gefixt wurde. Manchmal ist auch tatsächlich eine spezielle Tabelle - in der Regel eine InnoDB-Tabelle - korrupt und der Fehler beim Zugriff auf diese eine Tabelle reproduzierbar. Das ist so gesehen schön, dann kann man diese Tabelle zumindest isolieren, falls möglich im Recovery-Modus noch mit dem was da ist, dumpen, oder aus einem der täglichen Backups zurückspielen und damit hat es sich.

Für einen automatischen Restart von MariaDB sorgt systemd. Für eine automatische InnoDB-Wiederherstellung sorgt MariaDB selbst. So sah das dann im Log aus:

Oct 31 06:34:04 longmore.uberspace.de systemd[1]: Starting MariaDB 10.3.18 database server...
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] /usr/sbin/mysqld (mysqld 10.3.18-MariaDB) starting as process 25628 ...
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Using Linux native AIO
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Uses event mutexes
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Number of pools: 1
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Using SSE2 crc32 instructions
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: Completed initialization of buffer pool
Oct 31 06:34:08 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:08 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Oct 31 06:34:10 longmore.uberspace.de mysqld[25628]: 2019-10-31  6:34:10 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=313002307663

Das dauert zwar in der Regel eine Weile - bewegt sich aber bei uns meistens im Bereich weniger Minuten, denn durch die begrenzte Anzahl der User auf einem Host und die begrenzte Größe der Datenbanken bleibt hier eigentlich alles schön im Rahmen. Heute war das anders: Der Recovery-Prozess ist nämlich während des Zeitfensters von 10 Minuten, das wir via systemd hier einräumen, schlicht nicht fertig geworden:

Oct 31 06:44:05 longmore.uberspace.de systemd[1]: mariadb.service start operation timed out. Terminating.
Oct 31 06:45:35 longmore.uberspace.de systemd[1]: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
Oct 31 06:45:35 longmore.uberspace.de systemd[1]: Failed to start MariaDB 10.3.18 database server.
Oct 31 06:45:35 longmore.uberspace.de systemd[1]: Unit mariadb.service entered failed state.
Oct 31 06:45:35 longmore.uberspace.de systemd[1]: mariadb.service failed.

Wir haben daraufhin zunächst das 10-Minuten-Limit entfernt, in der Annahme, die Recovery würde eben etwas länger Zeit brauchen. Es gibt hier leider keinerlei Anzeichen, was gerade genau passiert oder sowas wie einen prozentualen Fortschritt. Einfluss auf die Recovery-Geschwindigkeit hat man insofern nicht und kann auch keine Vorab-Aussage über die Dauer treffen. Das ist unbefriedigend, aber ist eben so.

Nach dem Entfernen des Limits lief die Recovery dann fröhlich weiter - vielleicht ein bisschen zu fröhlich: So richtig passiert ist nämlich nichts. Hm. Merkwürdig. Sehr merkwürdig.

Da wir innodb_file_per_table einsetzen, befinden sich die eigentlichen Daten der jeweiligen Tabelle in jeweils einer einzelnen, nach der Tabelle benannten Datei, nicht in der zentralen ibdata1, die insofern eigentlich nur Systemdaten von InnoDB vorhält:

InnoDB uses the system tablespace to store the data dictionary, change buffer, and undo logs.

Dementsprechend ist sie in der Regel klein. Oder besser gesagt: Sie sollte es sein. Auf dem Host longmore war sie nämlich auf rund 40 GB Volumen angewachsen, während sie auf anderen Hosts weit unter 1 GB bleibt.

Klemmt man sich mit strace an den mysqld-Prozess, so kann man normalerweise während der Recovery gut sehen, wie MariaDB nacheinander jede InnoDB-Tabelle einmal kurz anfasst. In diesem Fall nicht: Die ibdata1 war die einzige Datei, die offengehalten wurde und aus der konstant gelesen wurde. Schreibzugriffe auf einzelne InnoDB-Tabellen, die darauf hätten hindeuten können, dass gerade etwas zurückgerollt oder aus dem Redo-Log ausgeführt wird, gab es hingegen nicht.

Als auch nach einer Stunde jedoch keinerlei Fortschritt bei der Recovery ersichtlich war, haben wir während des Wartens Plan B geschmiedet und zunächst eine 1:1-Kopie des gesamten Datenverzeichnisses gemacht, was sowieso immer eine gute Idee ist, bevor man irgendwelche eigenständigen, manuellen und potentiell frickeligen Reparaturversuche unternimmt:

rsync -avP /var/lib/mysql/ /var/lib/mysql.backup/

Dem Recovery-Prozess haben wir ja noch etwas Zeit gegeben, denn er hatte bisher ja keinerlei Fehler gezeigt und auch keinen weiteren Absturz provoziert.

Irgendwann ging uns aber die Geduld aus: Selbst die größten MariaDB-Instanzen, die wir bei uns einsetzen, die mehrere 100 GB an Daten halten, sind mit einer Recovery nach rund 20-30 Minuten fertig. Nicht so longmore.

Da wir nun eine komplette Kopie des Datenbestands gesichert hatten, gingen wir Plan B an: Wir haben den Recovery-Prozess abgebrochen und /var/lib/mysql/{ibdata1,ib_logfile0,ib_logfile1,ibtmp1} gelöscht, also faktisch InnoDB plattgemacht. In diesem Zustand konnte MariaDB erstmal wieder starten und ab diesem Zeitpunkt dann zumindest alles servieren, was nicht auf InnoDB-Tabellen basierte (sondern z.B. auf MyISAM-Tabellen).

Unser erster Gedanke ist: MariaDB ermöglicht es, dass man den InnoDB-Tablespace einer Tabelle mit ALTER TABLE <table> DISCARD TABLESPACE verwirft, anschließend eine .ibd-Datei aus dem Backup und idealerweise noch eine zugehörige .cfg-Datei ins Datenverzeichnis schreibt und diese Dateien dann mit ALTER TABLE <table> IMPORT TABLESPACE in den produktiven Betrieb lädt. Das Problem ist aber, dass man die .cfg-Datei nur bekommt, in dem man FLUSH TABLES <table> FOR EXPORT ausführt. Solange man auf der MySQL-Shell bleibt, gibt es dann eine konsistente .ibd-Datei sowie eine zugehörige .cfg-Datei, während vorübergehend ein Read Lock auf der Tabelle liegt. Nur: So hatten wir ja keine Exporte gemacht (unsere Backups basieren auf Dumps). Wir hatten also nur die .ibd-Dateien und dazu noch die .frm-Dateien, die traditionell die Struktur einer Tabelle vorhalten - wobei InnoDB die Struktur inzwischen mit in der .ibd-Datei abbildet. Nun ist also das Problem: Ein SHOW CREATE TABLE <table> funktioniert nicht mehr, weil wir InnoDB ja bereits geplättet hatten (was wir - zur Erinnerung - tun mussten, damit MariaDB überhaupt wieder startete). Diverse Dokumentation besagt nun, dass man die fragliche Tabelle zunächst als Dummy wieder anlegen möge (CREATE TABLE <table> (id INT) Engine=InnoDB), dann den Tablespace discarden soll, dann die .idb-Datei reinkopieren soll und dann den Tablespace importieren soll. Das hat im Prinzip auch geklappt - hat aber nur die Daten, nicht die Struktur (mangels .cfg-Datei…) importiert, so dass hinterher zwar die Daten “irgendwie” wieder da waren, aber ohne die Tabellenstruktur nicht sinnvoll nutzbar. Es wäre also schon zumindest nötig gewesen, die korrekte Struktur der Tabelle erneut anzulegen - dann hätte der Import der .ibd-Datei wohl funktioniert (bzw. hat es bei einem Test per Hand auch). Die korrekte Struktur der Tabelle konnten wir in diesem Fall aus dem letzten sauberen Dump des Backups entnehmen. Dennoch funktionierte das nicht so wirklich schön im großen Stil: Die Dumps liegen als Dump pro Datenbank vor, nicht pro Tabelle, und die Dumps enthalten Struktur und Daten. Wir hätten insofern wenn dann jeweils eine komplette Datenbank restoren müssen, was im Hinblick darauf, dass neben den InnoDB-Tabellen vielleicht aber auch völlig intakte und aktuelle MyISAM-Tabellen vorliegen, nicht so schön gewesen wäre, denn wir wollen ja keine aktuellen Tabellen ohne Not mit einem älteren Backup überbügeln. Eine Möglichkeit wäre gewesen, die Restores nicht in die produktiven Datenbanken, sondern in separate Restore-Datenbanken vorzunehmen und dann von dort jeweils einen Dump nur von der Struktur zu machen, und anschließend die jeweilige .ibd-Dateien von unmittelbar vor dem Crash zu importieren. Unschönheit 1: Das funktioniert natürlich nur, wenn sich die Struktur nicht seit dem letzten Backup geändert hat. Unschönheit 2: Wenn seit dem Backup Tabellen weggefallen oder dazugekommen sind, haben wir ein Problem. Der Fall ist nicht unbedingt wahrscheinlich, aber durchaus möglich.

Unsere Gedanken gingen daher dann in die Richtung, irgendwie zu versuchen, die Tabellenstrukturen nicht aus den Dump-Backups zu beziehen, sondern irgendwie aus der zu Lesezwecken gesicherten Kopie des Datenverzeichnisses. Wir haben dabei diese spannende Methode gefunden, die in etwa so funktioniert (ich habe das etwas verkürzt und vereinfacht und die Reihenfolge etwas angepasst, um die Theorie zu zeigen; es ist ohnehin nicht der Weg, den wir letztlich gegangen sind):

1. Lege eine Tabelle mit CREATE TABLE <table> (id INT) Engine=InnoDB als Dummy an, damit es überhaupt .frm-Dateien und einen InnoDB-Tablespace gibt.
2. Stoppe MySQL und kopiere dann die .frm-Dateien aus dem Backup über die Dummies.
3. Starte MySQL wieder und sorge mit FLUSH TABLES dafür, dass die Tabellenstrukturen aus den .frm-Dateien eingelesen werden. Jetzt sollten die Strukturen wieder da sein.
4. Benutze ALTER TABLE <table> DISCARD TABLESPACE, um die Tabelle explizit als “hat keinen Tablespace mehr” zu markieren.
5. Kopiere die .ibd-Dateien aus dem Backup zurück.
6. Benutze ALTER TABLE <table> IMPORT TABLESPACE, um den zurückkopierten Tablespace wieder in die zuvor schon wieder angelegte Struktur zu importieren.

Das könnte mit etwas Glück klappen, wobei der verlinkte Blogpost von 2014 ist und sich möglicherweise auch etwas am Vorgehen geändert haben könnte. Dennoch könnte dieser Ansatz vielleicht auch heute noch jemandem helfen.

Während der Recherche ist uns dann allerdings ein anderer Weg eingefallen, der sich dann auch als funktionierend herausgestellt hat.

Wir haben eine MariaDB-Konfiguration angelegt, die auf Basis des kopierten Datenbestands eine Readonly-Instanz von MariaDB hochfährt. Wir haben dazu in einer separaten Config einen anderen port, ein anderes datadir und einen anderen socket angegeben - und wir haben innodb_force_recovery gesetzt. Diese Einstellung ist dafür da, einzelne Recovery-Komponenten, die möglicherweise zu erneuten Crashes führen, abzustellen, je nach gewähltem Level. Nun haben wir aber ja keinen Crash mehr verzeichnet, sondern eben eine Recovery, die einfach nicht zum Ende kommt. Wir mussten uns hocharbeiten bis zum Level 6, bei dem dann faktisch gar keine Recovery mehr versucht wird. Damit hatten wir mit einem separaten Socket eine Restore-Instanz, die “so gut wie möglich” den letzten Stand vor dem Crash servieren konnte. So gut wie möglich heißt: Ohne einen sauberen Recovery-Prozess (und der war hier eben nach zwei Stunden aus unserer Perspektive wirklich nicht mehr zu erwarten) gibt es weder einen Rollback noch ein Redo von unfertigen Transaktionen. Das ist - da braucht man nicht drumherumzureden - schlecht. Es ist schlicht unter allen schlechten Optionen, die wir hatten, aber immer noch die beste - prominenteste Alternative wäre sonst gewesen, stattdessen die Dumps aus den Backups wieder einzuspielen, die wir täglich anfertigen. Hier ist schlicht das Problem, dass der Crash während des heutigen Backups stattfand und insofern nur für einem Teil der Datenbanken Backups vorlagen, die lediglich 1-2 Stunden alt waren, und für den größeren Teil aber nur Backups, die vom Vortag stammten, also bereits 25-26 Stunden alt waren. Wem das im Zweifelsfall die liebere Option gewesen wäre, der hat diese Möglichkeit ja auch jetzt noch.

Auf Basis des Readonly-Restore-mysqld haben wir dann Tabelle für Tabelle (mit einem zu diesem Zweck entworfenen Script) wiederhergestellt, also im Prinzip pro InnoDB-Tabelle diesen Schritt durchgeführt:

mysqldump --socket /var/lib/mysql.backup/restore.sock <database> <table> | mysql <database>

Der mysqldump-Befehl liest aufgrund der socket-Angabe vom Restore-mysqld; der mysql-Befehl schreibt aufgrund der nicht existierenden socket-Angabe in den Standard-MariaDB-Server, also in die Produktion (wo die betreffende Tabelle zu diesem Zeitpunkt bisher noch komplett fehlt).

Während der ersten manuellen Tests machten wir zudem die interessante Beobachtung, dass ein mysqldump --socket /var/lib/mysql.backup/restore.sock <database> einer gesamten Datenbank in einem Aufwasch in zwei Fällen den Restore-mysqld reproduzierbar zum Absturz brachte. Bezogen wir allerdings zunächst mit mysql --socket /var/lib/mysql.backup/restore.sock <database> -e "SHOW TABLES" eine Liste aller Tabellen jener beiden Problem-Datenbanken und ließen diese einzeln dumpen, so funktionierte dies ohne Probleme. Für dieses Verhalten konnten wir bislang keine Erklärung finden.

Mit etwas manueller Nacharbeit (hier fallen einem dann so Dinge auf die Füße, dass MariaDB im Dateisystem manche Sonderzeichen maskiert, also eine Datenbank aaa-bbb im Dateisystem aaa@002dbbb heißt…) konnten wir so bis auf wenige Ausnahmen alle InnoDB-Tabellen vom letzten Stand vor dem Crash wiederherstellen - wie beschrieben ohne saubere Recovery, die schlicht nicht durchführbar war. SQL-Queries, die während des Crashs aktiv waren, können insofern unter Umständen nur partiell ausgeführt worden sein.

• ← Previous Post
• Next Post →