- Am 8. Juli 2023 verschwanden auf der Mastodon-Instanz von Vivaldi Social ältere Benutzerkonten, und schließlich kam es zu einem Vorfall, bei dem 198 Konten in ein einziges Remote-Konto zusammengeführt wurden.
- Die Ursache war weder eine direkte Löschung noch ein Angriff, sondern ein Zusammenspiel aus dem Account-Merging-Verhalten von Mastodon und der Makara-basierten PostgreSQL-Replikationskonfiguration von Vivaldi Social, wodurch die Reihenfolge der Vorgänge durcheinandergeriet.
- Die Konten wirkten zwar wie gelöscht, doch die Benutzernamen wurden erneut vergeben und auch Avatar- und Header-Bilder verschwanden, wodurch sich das Problem auf ein internes Verhalten der Mastodon-Anwendung eingrenzen ließ.
- Das Betriebsteam bereitete einen vollständigen DB-Rollback vor und arbeitete parallel an selektiven Wiederherstellungsskripten, um Konten, Beiträge, Followings, Follower und Beziehungsdaten zurückzusetzen.
- Mastodon v4.1.5 enthält eine Sperre für die Nutzung von Makara in Sidekiq-Workern sowie eine Korrektur der Reihenfolge beim Account-Merging; Betreiber von Servern mit Replikations-DB sollten daher den Lesepfad der Worker prüfen.
Das Wochenendproblem, bei dem 198 Konten verschwanden
- Am Samstag, dem 8. Juli 2023, gegen 17:25 CEST verlangte der Vivaldi-Social-Tab erneut eine Anmeldung; nach dem Login zeigte sich, dass die Home-Timeline leer war.
- Dasselbe Symptom trat auch bei anderen Systemadministrator-Konten auf. Eine Prüfung der Datenbank ergab, dass betroffene Konten nach ihrer Löschung beim nächsten Login des Nutzers wie neue Konten erneut erstellt wurden.
- Für Vivaldi Social gab es ein nächtliches Backup von Freitag 23:00 UTC, und das Betriebsteam begann mit dem Kopieren der Backup-Datei, um die Wiederherstellbarkeit zu prüfen.
- Bei einer normalen Mastodon-Kontolöschung wird der Benutzername dauerhaft reserviert und nicht erneut verwendet. In diesem Vorfall wurde derselbe Benutzername jedoch wieder zugewiesen, was zeigte, dass es sich nicht um eine normale Löschung handelte.
Die Löschungen liefen weiter
- Anfangs waren ältere Konten mit einer ID unter 142 verschwunden; um 19:10 waren bereits Konten mit einer ID unter 217 betroffen, was zeigte, dass die Löschung noch im Gange war.
- Um 19:18 wurde Mastodon-Entwickler um Hilfe gebeten; nach der Antwort von Renaud beteiligten sich auch Claire und Eugen an der Untersuchung.
- Als um 19:20 die Mastodon-Docker-Instanzen neu gestartet wurden, stoppten die Löschungen, und die niedrigste Konto-ID in der Datenbank war nun 236.
- Insgesamt wurden während des Vorfalls 198 Konten gelöscht oder zusammengeführt.
Eingegrenzt auf Anwendungsverhalten statt Angriff
- Das Betriebsteam und die Mastodon-Entwickler prüften, ob
UserCleanupSchedulermöglicherweise „unconfirmed“-Konten gelöscht hatte, schlossen dies aber aus, da die gelöschten Nutzer die Bedingungen der betreffenden Abfrage nicht erfüllen konnten. - Da 48 Stunden vor dem Vorfall auf Mastodon 4.1.3 aktualisiert worden war, wurden die Änderungen zwischen v4.1.2 und v4.1.3 sowie die von Vivaldi veröffentlichten Änderungen überprüft, ohne eine passende Ursache zu finden.
- Auch die Avatar- und Header-Bilder der gelöschten Konten waren im Dateisystem verschwunden, was bestätigte, dass nicht einfach direkt in der DB gelöscht worden war, sondern dass die Mastodon-Anwendung selbst den Löschvorgang ausgeführt hatte.
- In Logs und Dateisystem wurde nach Spuren eines Einbruchs oder Angriffs gesucht, doch es fanden sich keine Belege; auch eine mögliche Ausnutzung im Zusammenhang mit den Sicherheitsfixes in Mastodon v4.1.3 ließ sich nicht bestätigen.
- In der Nacht zum Samstag wurde ein Patch ausgerollt, der zusätzliche Logs für das Kontolöschverhalten hinzufügte; nachdem die gepatchte Version um 00:29 CEST ausgerollt worden war, legte das Team eine Pause ein.
Der entscheidende Hinweis: Beiträge, die auf ein Remote-Konto konzentriert waren
- Am Sonntag um 13:56 wurde gemeldet, dass die Profilseite des Vivaldi-Sicherheitsexperten Yngve einen HTTP-500-Fehler ausgab; dieses Konto gehörte nicht zu den 198 gelöschten Konten.
- In den Logs tauchte immer wieder dasselbe Konto auf derselben Remote-Mastodon-Instanz auf; im Text wird es dafür unter dem Pseudonym
social.example.comgeführt. - Eine Abfrage der Status dieses Remote-Kontos lieferte 17.600 Zeilen zurück.
- Um 14:43 bestätigte der Vergleich mit dem Backup, dass alle Status aller gelöschten Konten einem einzigen Nutzer auf
social.example.comneu zugewiesen worden waren. - Ab 15:00 verdichtete sich durch
AccountMergingWorker-Logs, die Rails-Konsole und zusätzliche DB-Abfragen die Hypothese, dass der Account-Merging-Worker alle Konten in ein einziges Remote-Konto zusammengeführt hatte.
Grundursache: Account-Merging und PostgreSQL-Replikationsverzögerung
- Vivaldi Social nutzte eine PostgreSQL-Replikationskonfiguration mit 2 Servern, und Worker-Prozesse konnten über Makara Datenbanklesezugriffe auf den Standby-Server ausführen.
- Das von Claire um 17:28 dargestellte Unfallszenario war wie folgt:
- Vivaldi Social empfängt von
social.example.comeine Benachrichtigung über eine Änderung des Kontonamens. - Beim Erstellen des neuen Kontos wird das Feld
URIzunächst mitnullin die Datenbank geschrieben. - Danach wird die
URIdes neuen Kontos auf den korrekten Wert des Remote-Kontos gesetzt. - Über Redis wird die Ausführung von
AccountMergingWorkereingeplant, um Daten vom alten Konto in das neue Konto zusammenzuführen. - Aufgrund einer Verzögerung in der Datenbankreplikation gerät die Reihenfolge zwischen dem Setzen der
URIund dem Einplanen der Worker-Ausführung aus Sicht des tatsächlichen Lesezeitpunkts durcheinander.
- Vivaldi Social empfängt von
- Da bei allen lokalen Konten einer Mastodon-Instanz der
URI-Wertnullist, ordnete der Worker beim Zusammenführen von Konten mit gleicherURIalle lokalen Konten dem neuen Remote-Konto zu. - Die Entwickler gingen davon aus, dass so etwas eher auftreten kann, wenn die Datenbanklast steigt und sich dadurch die Replikationsverzögerung verlängert.
- Das Betriebsteam und die Mastodon-Entwickler hielten diese Konfiguration mit sehr hoher Wahrscheinlichkeit für die eigentliche Ursache.
Patch und Konfigurationsänderung
- Nachdem die Ursache eingegrenzt war, konzentrierte sich das Betriebsteam auf die Datenwiederherstellung, während Claire einen Patch zur Verhinderung einer Wiederholung schreiben wollte.
- Hlini übernahm das Einspielen des Patches und die Umstellung der nicht mehr empfohlenen Replikationskonfiguration.
- Um 17:58 trat während des Deployments ein Problem auf, was zum einzigen kompletten Ausfall des Wochenendes führte; um 18:18 war Vivaldi Social wieder erreichbar.
- Um 18:44 waren Patch und Konfigurationsänderung erfolgreich ausgerollt, sodass derselbe Vorfall voraussichtlich nicht erneut auftreten würde.
Wiederherstellung: selektives Restore statt vollständigem Rollback
- Anfangs wurde ein vollständiger Datenbank-Rollback in Betracht gezogen, doch wegen bekannter Performance-Probleme wäre dafür ein komplizierter Ablauf nötig gewesen, bei dem das Backup
.dumpin.sqlumgewandelt und eine 54-GB-Textdatei bearbeitet werden musste. - Das Betriebsteam verfolgte parallel den vollständigen Wiederherstellungsprozess und die selektive Wiederherstellung.
- Hlini bearbeitete die 54-GB-
.sql-Datei und bereitete die vollständige Wiederherstellung vor. - Thomas schrieb ein Skript zur Wiederherstellung gelöschter Konten und der dazugehörigen Daten.
- Hlini bearbeitete die 54-GB-
- Beim Schreiben des Skripts gab es einen Fehler, bei dem PDO-Abfrageparameter per Referenz gebunden wurden; Ísak fand diesen Fehler.
- Um 23:04 war der erste Teil fertig, der die
user-,account- undidentity-Datensätze der 198 betroffenen Nutzer korrigierte. - Um 23:55 war das selektive Wiederherstellungsskript fertig, um Status-, Follow-, Follower- und Beziehungsdaten auf den Stand vor dem Vorfall zurückzusetzen.
Selektive Wiederherstellung abgeschlossen und nachträgliche Korrekturen
- Wegen Datenbank-Beziehungs-Constraints erfolgte die Wiederherstellung in zwei Schritten.
- Zuerst wurden die
user-,account- undidentity-Datensätze aller 198 Personen wiederhergestellt. - Danach wurden die übrigen Beziehungsdaten wiederhergestellt.
- Zuerst wurden die
- Wenn sich manche Nutzer nach dem Vorfall erneut eingeloggt und Follows gesetzt hatten, traten Duplicate-Key-Fehler auf; das Skript wurde daher so angepasst, dass nicht wiederherstellbare bestehende Datensätze gelöscht und neuere Datensätze beibehalten wurden.
- Um 01:27 CEST am Montag war der letzte Arbeitsschritt des Skripts abgeschlossen, und um 01:40 war die Neuindizierung des Home-Feeds beendet.
- Im Ergebnis wurden die Home-Feeds von 198 Konten wiederhergestellt, und ein vollständiger Rollback war nicht mehr nötig.
- Am Montag und Dienstag wurden weitere Folgeprobleme behoben.
- Login-Probleme bei 6 Konten mit Symbolen im Benutzernamen
- Verlust von Web-Einstellungsdaten bei den 198 Konten
- Fehler bei Profilzählern wie Follower-Zahl und Beitragsanzahl
- 4 Konten mit fehlerhaften Daten
Offizieller Fix in Mastodon
- Die Mastodon-Entwickler informierten andere Serverbetreiber über die Risiken beim Einsatz von Mastodon mit einer Makara-basierten Replikationskonfiguration.
- Es wurde festgehalten, dass eine solche Konfiguration selten ist und eher nur bei großen Instanzen wie Vivaldi Social in Betracht kommt.
- Mastodon v4.1.5 enthält zwei Fixes im Zusammenhang mit diesem Vorfall.
Zeitleiste des Vorfalls in UTC
- Samstag 15:15: Eine Nachricht zur Änderung des Kontonamens von einer externen Instanz wird an Vivaldi Social zugestellt, und der fehlerhafte Account-Merging-Job startet.
- Samstag 15:25: Die ersten Anzeichen des Vorfalls werden beobachtet.
- Samstag 17:20: Nach dem Neustart der Docker-Container stoppt der Account-Merging-Job; zwischen 15:15 und 17:20 wurden insgesamt 198 Konten gelöscht oder zusammengeführt.
- Sonntag 13:00: Eine mögliche Grundursache wird identifiziert.
- Sonntag 14:25: Die Grundursache wird bestätigt.
- Sonntag 21:55: Die Datenwiederherstellung beginnt.
- Sonntag 23:27: Die Datenwiederherstellung wird abgeschlossen.
- Montag 10:40: 6 Konten mit Symbolen im Benutzernamen werden korrigiert.
- Montag 11:05: Verlorene Web-Einstellungsdaten werden wiederhergestellt.
- Dienstag 15:31: Falsche Zählerwerte werden korrigiert.
- Dienstag 16:01: 4 Konten mit fehlerhaften Daten werden korrigiert.
1 Kommentare
Meinungen auf Hacker News
Das war eine hervorragende Retrospektive, und sie hat besonders gut eingefangen, wie stark menschliche Kosten wie Schlafmangel die Behebung komplexer Ausfälle beeinflussen können.
Am meisten stach für mich die Stelle hervor: „Ein neues Konto wurde in der Datenbank mit einem null-Wert im URI-Feld angelegt.“
Immer wenn ich Postmortems mit Datenbankbezug lese, lauert NULL fast immer irgendwo in der Nähe des Tatorts. Selbst wenn NULL nicht der Täter ist, sollte es immer zu den Verdächtigen gehören.
Mein Rat wäre: Verlasst euch nicht auf NULL als Sentinel-Wert, und lasst es in der Datenbank nach Möglichkeit gar nicht erst zu. Auch wenn es Vorteile zu haben scheint, werden diese Jahre später oft durch schwer auffindbare Bugs aufgewogen, wenn sich die Bedeutung des Datenmodells ändert und irgendeine harmlos wirkende Anweisung NULL oder NOT NULL erwartet, dann aber unerwartete Ergebnisse liefert.
In diesem Fall war es eine Race Condition, aber wenn lokale und entfernte Konten über Typen klar unterschieden worden wären, hätte die Reihenfolge der Operationen möglicherweise keine Rolle gespielt, und der Code zum Zusammenführen von Konten hätte auf einen engeren Bereich begrenzt werden können.
Null ist ein vollkommen gültiger Wert für Daten und sollte auch so behandelt werden. Standardwerte wie -1 für Booleans oder leere Werte für Strings können ein System scheinbar funktionieren lassen, bei dem NULL zur Laufzeit einen Fehler ausgelöst hätte; das bedeutet aber nicht, dass das System wie erwartet funktioniert, sondern nur, dass es still bleibt.
Ich verstehe die Versuchung, NULL unter den Teppich zu kehren, aber „nicht vorhanden“ ist ein ebenso gültiger Zustand von Daten wie „vorhanden“, und Systeme sollten im Allgemeinen so geschrieben sein, dass sie damit umgehen können.
In diesem Fall sehe ich das Problem nicht bei NULL in der Datenbank, sondern bei NULL in der Anwendungsschicht.
Wenn NULL ein Wert wäre, der wie eine Art Maybe-Monade zwingend behandelt werden muss, würde man ihn am Ende auch behandeln und darüber nachdenken. Ob es nun ein leerer String ist, ein null-String der verwendeten Sprache oder ein selbst gebauter spezieller Markerwert, macht keinen großen Unterschied.
In vielen Fällen sollten Implementierende zuerst an die Bedenken und Interaktionsanforderungen denken, die Git-artige Merge-Konflikte mit sich bringen, und von diesem Ausgangspunkt aus vereinfachende Annahmen für den jeweiligen Problembereich treffen.
Wenn man sich den Mastodon-Quellcode https://github.com/mastodon/mastodon/blob/main/app/workers/a... ansieht, scheint es nicht einmal eine explizite Liste der „IDs, aus denen zusammengeführt werden soll“ zu geben, die von der Seite, die die Merge-Anfrage startet, an den asynchronen Merge-Executor übergeben wird. Dass so etwas passiert, war daher wohl nur eine Frage der Zeit.
Das ist keine Kritik an Mastodon. Ich habe selbst Merge-Logik mit deutlich schlimmeren Race Conditions geschrieben und die Folgen zu spüren bekommen. Eigentlich ist es erstaunlich, dass es eine solche Funktion überhaupt in einem Freiwilligenprojekt wie https://opencollective.com/mastodon gibt. Trotzdem ist es ein warnendes Beispiel.
Noch grundlegender: Die Realität ist unordentlich, und Datenbanken können die Verarbeitung nicht verweigern, nur weil die Realität unordentlich ist; deshalb ist NULL unvermeidlich. Nehmen wir etwa an, man modelliert Anrede, vorangestellten Titel und nachgestellten Titel und möchte aus diesen Daten eine vollständige Begrüßung erstellen: Es gibt mindestens Menschen ohne nachgestellten Titel. Selbst wenn man NULL nicht speichert, erhält man durch den JOIN, der zur Erstellung der Begrüßung verwendet wird, NULL.
Einzelne NULL-Werte kann man entfernen, aber nicht die Tatsache, dass „nicht zutreffend“ oder „unbekannt“ in der Realität häufig gültige Werte sind und Datenbanken damit umgehen müssen.
Der hier nachvollziehbare Ablauf ist: Man beginnt mit „Wir haben ein vollständiges Datenbank-Backup, also stellen wir alles wieder her“, gelangt dann zu „Eine vollständige Wiederherstellung ist schwierig und bringt Downtime und Nebenwirkungen mit sich“, dann wieder zu „Vielleicht können wir clever nur die fehlenden Daten teilweise wiederherstellen“, macht das manuell, stößt auf merkwürdige Fehler, deployed schließlich eine provisorisch gebaute selektive Wiederherstellung und räumt zum Schluss die fünf verbliebenen fehlenden Datensätze auf. In der Hoffnung, den sechsten nicht übersehen zu haben.
Egal wer Backup/Restore übt, es läuft jedes Mal ungefähr so ab. Am Ende muss die Entscheidung, welche Daten aus einem Backup-Image zurückgeholt werden, immer auf Anwendungsebene getroffen werden.
Allerdings ist mir in diesem Fall nicht ganz klar, was das Problem war. Alles aus dem letzten guten Backup wiederherzustellen hätte zwar bedeutet, dass einige danach veröffentlichte Beiträge verschwinden, was schade ist, aber es wäre eine sofortige Lösung gewesen, statt Handarbeit und Unsicherheit.
Beeindruckend fand ich die Stelle, dass Renaud, Claire und Eugen aus dem Mastodon-Entwicklungsteam mehr geholfen haben, als man erwarten konnte.
Ich weiß nicht, ob Vivaldi Mastodon finanziell unterstützt, und auf der Sponsorenseite konnte ich den Namen nicht finden. Falls nicht, hoffe ich, dass Vivaldi oder andere Unternehmen, die Mastodon nutzen, diesen Vorfall zum Anlass nehmen, Sponsoring oder einen Supportvertrag zu prüfen.
Sponsoring ist möglich und hat tatsächlich großen Einfluss. Dass es Vollzeitkräfte im Projekt gibt, ist extrem wichtig, aber aktuell gibt es auf technischer Seite neben dem Gründer Eugen nur einen Vollzeitentwickler und eine Person für DevOps.
Das war eines der besseren Postmortems, die ich seit Langem gelesen habe.
Dass Punkt 2 und 3 nicht atomar verarbeitet werden, fühlt sich wie ein Problem an. Natürlich gibt es vermutlich Gründe, warum das nicht trivial ist, aber ich habe mir den Code noch nicht angesehen und sollte das irgendwann tun.
Es sieht so aus, als sei es trivial gewesen, das atomar zu machen.
Vorher war es nur nicht nötig. Ich meine: Dass es nicht atomar war, war kein Problem, solange niemand die schlechte Konfiguration vornimmt, sidekiq mit einem veralteten Datenbankserver zu verbinden, also mit einer Replik. Genau diese Konfiguration scheint hier das Hauptproblem gewesen zu sein.
Als ich zum ersten Mal einen riesigen SQL-Dump wiederherstellen musste, werde ich nie vergessen, wie vim beim Lesen tatsächlich mit einem Segmentation Fault abgestürzt ist.
Damals entdeckte ich die Magie von split(1), also Dateien in Stücke aufzuteilen. Ich habe den großen Dump in je eine Datei pro Tabelle zerlegt.
Natürlich kann auch eine einzelne Tabelle riesig sein, aber zumindest werden die Dateien dadurch gleichmäßiger, sodass sich Abfragen mit anderen Tools wie sed oder awk leichter umschreiben lassen.
Wenn man allerdings einen Dump bearbeiten muss, um Daten wiederherzustellen, ist mit dem Wiederherstellungsprozess etwas gründlich schiefgelaufen. Natürlich hilft einem dieses Wissen wenig, wenn man tatsächlich in der Situation steckt.
Der Workaround bestand darin, ein Python-Skript zu schreiben, das alles schrittweise verarbeitet und die Dateien anhand gemeinsamer Präfixe in Unterverzeichnisse verschiebt.
Bei der Stelle „Claire bat um den vollständigen Stacktrace des Log-Eintrags, und auch der ließ sich aus den Logs extrahieren“ habe ich die Augenbrauen hochgezogen.
Entweder ist das tiefste Voodoo-Magie, oder Code bzw. Konfiguration verwandeln einen Xeon in etwas auf 286er-Niveau. Sind das nicht Megabytes pro Request?
Das ist das Standardverhalten von Ruby on Rails. Bei einem 500er oder einem unbekannten Fehler gibt es einen Stacktrace aus; der Inhalt besteht im Wesentlichen aus Zeilennummern und Dateipfaden.
Ich betreibe eine ziemlich schlecht designte Rails-App und habe gerade nachgesehen: Der Stacktrace eines einzelnen 500ers war 5 KiB groß. Da ein 500er-Fehler ungefähr nur einmal pro Stunde auftritt, sind das nicht einmal 1 MiB pro Tag.
Den Call Stack griffbereit zu halten, ist tatsächlich ziemlich unproblematisch für die Performance. Auch das Standardverhalten von Java-Exceptions ist, bei jeder Exception einen Stacktrace mitzuführen, selbst wenn er nicht ausgegeben wird; Java-Anwendungen laufen trotzdem gut. Man muss ohnehin wissen, wie man zurückkehrt, also hat man den Call Stack, und zusätzlich braucht man nur Debug-Symbole für Dateinamen und Zeilennummern. Ruby braucht diese Informationen wegen seiner Spracheigenschaften ohnehin.
Wie kann es sein, dass „alle lokalen Accounts der Mastodon-Instanz übereinstimmten, weil das URI-Feld null war“?
NULL = NULL wird zu FALSE ausgewertet. SQL verwendet dreiwertige Logik, genauer Kleenes schwache dreiwertige Logik, und die Anwendung eines Operators auf NULL ergibt NULL.
Ich verstehe nicht, wie Accounts mit NULL-Werten in der URI-Spalte von der Query gematcht wurden. NULL wird nicht als gleich NULL verglichen. Ist das irgendeine schreckliche Rails-Magie?
Bei der Passage, dass sich 6 Nutzer mit Sonderzeichen im Benutzernamen nicht anmelden konnten und das wegen eines Fehlers im Wiederherstellungsskript leicht behoben wurde, fühlt es sich so an, als hätte UTF-8 wieder einmal zugeschlagen.