Informationen und Bekanntmachungen

Devblog von CCP Goliath in Kooperation mit CCP Masterplan.

Dieser Devblog ist ein Bericht darüber, was hinter den Kulissen geschah, als EVE Online am 15. Juli 2015 eine seiner längsten Downtimes seit Jahren hatte. Wir teilen ihn mit euch, weil wir wissen, dass viele Spieler im IT-Bereich arbeiten und die Kriegsgeschichten zu schätzen wissen, und weil wir euch dadurch einen guten Einblick in das Innenleben eines recht einzigartigen Spieleclusters geben können. Wenn euch diese Dinge interessieren, dann lest weiter für einen Bericht über die Ereignisse am 15. Juli. Falls ihr diese Details lieber auslassen wollt, empfehlen wir die oberflächlichere Zusammenfassung, die wir hier kurz nach dem Vorfall veröffentlicht haben.

Hintergrund

Diejenigen unter euch, die bereits seit einer langer Zeit bei uns sind, erinnern sich bestimmt an eine Zeit, in der die Downtime mehrere Tage statt Stunden betrug. In den letzten Jahren haben wir es geschafft, diese furchtbar langen Downtimes - größtenteils - zu eliminieren. Am 15. Juli waren wir 699 Minuten lang für Spieler unerreichbar. Das ist etwas länger als die Downtimes, die am 2. und 3. Juni 2013 auftauchten, direkt vor der Veröffentlichung von Odyssey (das selbst aufgrund von über einen großen Zeitraum laufenden Tiercide-Skripten eine 342-minütige Downtime nach sich zog). Davor waren wir 2011 mit Incarna 963 Minuten unerreichbar, was aber die letzte der sehr langen Veröffentlichungen darstellte, die unserem 6-monatigen Releasezyklus folgten. Wenn wir momentan einfach automatisch neu starten, ohne etwas zu veröffentlichen, können wir sicher sein, dass dies ungefähr 7 Minuten dauert. Wenn wir etwas veröffentlichen, rechnen wir normalerweise damit, dass innerhalb der 30-minütigen Downtime alles wieder läuft.

Das Hochfahren

Der Tranquility-Cluster besteht aus ungefähr 250 Serverknoten. Um den Cluster hochzufahren, müssen alle Knoten eine koordinierte Funktionsabfolge ausführen. Dies beinhaltet die Zuweisung von IDs zu jedem Knoten, die Herstellung von Netzwerkverbindungen zwischen jedem Knotenpaar, die Zuweisung welches Sonnensystem auf welchem Knoten läuft, sowie das Laden der notwendigen Daten, um es jedem Knoten zu ermöglichen, seine Aufgabe auszuführen (ein Knoten ist beispielsweise für die Region eines Markts zuständig, oder eine Reihe von Corporations/Allianzen, oder dem Skilltraining für eine Reihe an Charakteren).

Während der Startsequenz bewegt sich der Cluster durch mehrere Phasen. Der Cluster wird nicht in die nächste Phase übergehen, bis alle Knoten berichten, dass sie die Aufgaben der aktuellen Phase abgeschlossen haben. Er beginnt bei Phase -4 und läuft bis Phase 0 weiter. Sobald sich alle Knoten in Phase 0 melden, ist der Cluster bereit. Ein Hauptknoten wird gewählt, um diese Sequenz zu organisieren. Diesen nennen wir Polaris. Der Polaris-Knoten ist dafür verantwortlich, die Phasen aller anderen Knoten zu überprüfen und Anweisungen zum Übergang in die nächste Phase auszusenden, sobald die erforderlichen Bedingungen erfüllt wurden.

-4: Der Knoten ist aktiv und wir haben eine Verbindung zur Datenbank
-3: Der Knoten hat erfolgreich eine Netzwerkverbindungen zu jedem anderen Knoten geöffnet
-2: Der Adressen-Cache wurde vorbereitet. Das ist im Prinzip die Routingtabelle, so dass jeder Knoten weiß, was die Aufgabe jedes anderen Knotens ist
-1: Alle Hochfahrdienste haben ihre Initialisierung abgeschlossen und das Vorausladen einiger Daten (Markt, Sonnensysteme, usw.) hat begonnen
0: Dem Knoten wurde mitgeteilt, dass der Cluster bereit ist. Alle Hochfahrdaten sind geladen und Dienste sind bereit, Anfragen anzunehmen

Der Vorfall

Als wir den Server am 15. Juli vom Netz nahmen um den ersten Folgepatch für Souveränität in Aegis aufzuspielen, haben wir keinen Störfall erwartet. Die Testserver, auf die wir das Update zuvor aufgespielt hatten, wurden korrekt hochgefahren und verhielten sich normal, so dass wir erwarteten, dass es sich um eine standardmäßige 15-20 minütige Veröffentlichung handeln wird. Das erste Hindernis war, dass unser Veröffentlichungstool sehr lange brauchte, um das Serverpaket zu installieren, irgendwann eine Fehlermeldung ausspuckte und kurz vor 11:30 Uhr neu gestartet wurde. Zu diesem Zeitpunkt haben wir die Verzögerung beim Hochfahren bekannt gegeben, rechneten aber immer noch nicht mit etwas Ungewöhnlichem - Programme versagen manchmal einfach, Zeitüberschreitungen passieren und wir haben die Inhalte einfach neu installiert, dieses Mal erfolgreich. Der erste Versuch zum Hochfahren des Servers war um 11:42, um 11:46 berichteten 12 Knoten (von ca. 250), dass sie feststecken und verhinderten somit ein erfolgreiches Hochfahren. Das schreckte uns nicht ab: Unser erster Anlaufpunkt war der älteste Trick im IT-Buch - "aus- und wieder einschalten".

[img]http://content.eveonline.com/www/newssystem/media/67449/1/have-you-triedsmall.jpg[/img]

Das Hochfahren ging dieses Mal schneller, allerdings sahen wir uns immer noch mit 41 Knoten konfrontiert, die im "-1"-Status feststeckten. Wir entschieden uns dafür, den Server auf VIP-Zugriff zu setzen, so dass nur Accounts mit besonderen Entwicklerrollen Zugriff auf den Server haben, sobald er online ist, und die Veröffentlichung nochmal komplett von vorne vorzunehmen, um mögliche Sperrungen, Konflikte oder menschliches Versagen nach dem ersten Versuch auszuschließen. All unsere Vermutungen konzentrierten sich diesmal auf die Umgebung als mögliche Ursache, da der Code auf dem Testserver funktionierte und keine der Daten für rote Flaggen sorgte.

Leider waren wir 2 Hochfahrversuche später immer noch keinen Schritt näher an einem funktionierendem Server, also war es an der Zeit, die Kavallerie zu rufen. EVE-Programmierer taten sich mit der Serverbetriebsabteilung (Live Ops) für weitere Recherchen des...

Folgendes passierte:

Zuerst hatten wir zwei Protokollkanäle - einen allgemeinen Kanal, sowie den speziellen Kanal, der zum Erfassen der Kampagnenaktivität im Souveränitätssystem benutzt wurde. Wir konnten bestätigen, dass beide Kanäle funktionierten, indem wir den folgenden Code auf einem einzelnen Knoten ausführten.

1. # generic_logger ist eine Referenz zu einem allgemeinen Protokollkanal
2. # campaign_logger ist eine Referenz zum Protokollkanal, der von Souveränitätskampagnen benutzt wird
4. # Schritt 1a: Sicherstellen, dass die Ausgabe zum allgemeinen Protokoll korrekt funktioniert
5. generic_logger.warn('The quick brown fox jumps over the lazy dog')
7. # Schritt 1a: Sicherstellen, dass die Ausgabe zum Kampagnenprotokoll korrekt funktioniert
8. campaign_logger.warn('The quick brown fox jumps over the lazy dog')

Während dieser Code arbeitete, haben wir zudem die Protokollausgabe in Echtzeit über Splunk im Auge behalten. Tatsächlich tauchte jede Zeile einmal auf.

Als nächstes führten wir Schritt 1a gleichzeitig auf allen 250 Knoten aus. Sofort tauchten 250 Einträge auf der Splunk-Anzeige auf. Dann wiederholten wir das gleiche für Schritt 1b und erhielten das gleiche Ergebnis - jeder Knoten protokolliert eine Instanz der Zeile und jede Zeile zeigte an, dass sie vom Kampagnenkanal kam.

So weit, so gut. Jetzt wollten wir mehr Daten protokollieren, aber nichts, das irgendwelche Probleme verursachen sollte, richtig? Richtig? Hmm...

1. # Schritt 2a: Die selbe Zeile 500 Mal pro Knoten im allgemeinen Kanal protokollieren
2. [generic_logger.warn('The quick brown fox jumps over the lazy dog') for i in range(500)]
4. # Schritt 2a: Die selbe Zeile 500 Mal pro Knoten im Kampagnenkanal protokollieren
5. [campaign_logger.warn('The quick brown fox jumps over the lazy dog') for i in range(500)]

Für diejenigen unter euch, die sich nicht mit Python auskennen: Die zweite Zeile wird 500 Mal wiederholt und gibt die Warnmeldung einmal pro Wiederholung im allgemeinen Protokollkanal aus. Die fünfte Zeile macht das gleiche, aber im Kampagnenprotokollkanal.

Zuerst haben wir Schritt 2a parallel auf allen Knoten ausgeführt. Der Befehl wurde sofort ausgeführt und wir sahen eine Spitze mit 125.000 Zeilen (250*500) auf dem Splunk-Diagramm. Das hört sich nach einer Menge Protokollen an, aber es handelt sich hierbei um nichts, was das System nicht verarbeiten kann, besonders wenn sie in kleinen Spitzen wie hier auftauchten. Dann führten wir das gleiche mit Schritt 2b aus. Hier passierte etwas Merkwürdiges. Die korrekte Anzahl an Protokollzeilen tauchte in Splunk auf (die Protokolle zeigen also tatsächlich etwas an!), doch der Befehl schien nicht so unverzüglich zurückzukommen wie bei Schritt 2a. Tatsächlich dauerte es ein paar Minuten, bis die Konsole wieder reagierte und die zurückerhaltenden Daten deuteten darauf hin, dass einige Knoten nicht rechtzeitig antworteten. Als wir uns den Status des Clusters ansahen, wurden diese Knoten als ausgefallen angezeigt. Irgendwie hat es diese unschuldige Protokollzeile geschafft, eine Zeitabschaltung bei diesen Knoten hervorzurufen und sie aus den Cluster geworfen.

Das war einfacher, als wir dachten! Wir mussten nicht mal etwas mit den Kampagnen oder der Datenbank anstellen, um den ausgefallenen Cluster zu reproduzieren. Wenn ein Entwickler sich nicht darauf verlassen kann, dass eine einfache Protokollaktion nicht den Produktionserver vernichtet, hat er einen schlechten Tag. So wie wir am Mittwoch, den 15. Juli. Jetzt wo wir das Problem weiter abgegrenzt hatten, starteten wir Tranquility neu und gaben dann die Anweisung, den VIP-Modus abzuschalten und den Server wie gewohnt zu öffnen.

Wie bereits ein paar Mal in der Zeitachse weiter oben beschrieben, passierte dies nie zuvor oder seitdem auf einem anderen Testserver. Die Art, wie Tranquility funktioniert (oder konfiguriert ist) ist irgendwie einzigartig. Die Untersuchung, warum dieses Protokollverhalten nur auf Tranquility und nur in bestimmten Protokollkanälen auftaucht, wird fortgesetzt. Wir wissen, dass Tranquility mit Sicherheit auf einer anderen Skala arbeitet, was die Menge an Hardware angeht, bis jetzt legen andere Versuche jedoch nahe, dass es es sich hierbei nicht nur um eine Frage der Anzahl an Knoten handelt. Die Untersuchung wird fortgesetzt...

[img]http://content.eveonline.com/www/newssystem/media/67449/1/RaidersWarehouse.jpg[/img]

wow


ich bin beeindruckt, ich bin kein Fachmann und ich konnte dem ganzen folgen und es verstehen

Ich möchte an dieser Stelle mal ganz **** DANKE sagen. So einen Einblick bekommt man wirklich selten und ich finde es klasse sowas lesen zu dürfen. Ich kann keinen Tipp geben, aber das was Baby Leonie geschrieben hat, das die Performance vielleicht zu schnell verarbeitet und es damit zu "Staus" kommt klingt nachvollziehbar.


Mein Fazit: Macht weiter so

Wirklich ätzend solche Fehler. Und da natürlich wirkt sich der Fehler nur auf dem System aus, an dem es den meisten Schaden anrichtet.

Murphy is strong in this one

Und vielen Dank für die ausführlichen Informationen. Für mich ist das tatsächlich ein Grund immer wieder zu diesem Spiel zurück zu kehren. Die tiefen Einblicke in eure Arbeit und der Aufwand, den ihr betreibt um es wirklich ausführlich und strukturiert zu erklären sind bewundernswert. Selbst wenn der Account mal ruht, werden die Devblogs regelmäßig durchstöbert :)

Bitte macht weiter so und ich drücke euch die Daumen! Ihr packt das schon.