Wie GitHub eine seltene Race Condition in der Session-Verarbeitung fand und behob

Am 8. März wurden aufgrund einer Sicherheitslücke alle Nutzer von GitHub.com abgemeldet.

• Am 2. März ging ein Bericht eines Nutzers ein, der sich eingeloggt hatte, aber als ein anderer Nutzer authentifiziert wurde. Der Nutzer meldete sich sofort ab, meldete das Problem jedoch, und die Untersuchung begann umgehend. Einige Stunden später meldete ein weiterer Nutzer ein ähnliches Problem.

• Die ersten Untersuchungsergebnisse zeigten, dass die Session eines Nutzers zum Zeitpunkt des Berichts von zwei IP-Adressen aus gemeinsam genutzt wurde.

• Bei der Untersuchung jüngster Infrastrukturänderungen stellte sich heraus, dass kürzlich der Load Balancer und das Routing aktualisiert worden waren und dabei HTTP keepalives geändert wurden. Das wirkte zunächst relevant, erwies sich bei weiterer Untersuchung jedoch als nicht ursächlich.

• Dennoch zeigte die Untersuchung der Infrastruktur, dass die Requests, die eine falsche Session erhalten hatten, exakt auf derselben Maschine und in demselben Prozess verarbeitet wurden.

• Die Logs zeigten, dass der Response-Body korrekt war und nur das Cookie falsch gesendet wurde; dabei wurde fälschlicherweise das Cookie eines anderen Nutzers ausgeliefert, dessen Request im selben Prozess verarbeitet worden war. In einem der gemeldeten Fälle waren es zwei aufeinanderfolgende Requests, im anderen lagen zwei weitere Requests dazwischen.

• Daraus entstand die Hypothese, dass zwischen Requests, die im selben Ruby-Prozess verarbeitet wurden, Zustand auslief, und man fragte sich, wie das möglich sein konnte.

• Die Überprüfung der jüngsten Änderungen zeigte, dass Logik zur Prüfung aktivierter Funktionen für Nutzer aus Performance-Gründen nicht mehr während der Request-Verarbeitung lief, sondern in einen Background-Thread verlagert worden war, der sie in festen Abständen aktualisierte. Die Untersuchung konzentrierte sich daher auf das Thread-Safety-Verhalten.

• Die Hauptanwendung von GitHub.com basiert auf Ruby on Rails und enthält viele Komponenten, die nicht für den Betrieb mit mehreren Threads geschrieben wurden.

• Zwar wurden in der Anwendung bereits Threads verwendet, doch der neue Background-Thread führte in der Exception-Handling-Routine zu unerwartetem Verhalten.

• Wenn im Background-Thread eine Exception auftrat, enthielten die Error-Logs sowohl Informationen zum Background-Thread als auch zum gerade laufenden Request.

• Zunächst hielt man die Tatsache, dass Daten eines nicht zusammenhängenden Requests im Log des Background-Threads auftauchten, lediglich für eine Inkonsistenz im internen Reporting.

• Man ging davon aus, dass Rails sicher sei, weil für jeden Request ein neues Controller-Objekt erzeugt werde.

• Deshalb blieb weiterhin unklar, warum dieses Problem auftrat.

• Ein Durchbruch zeichnete sich ab, als man entdeckte, dass Unicorn, das in der Rails-Anwendung als Rack-HTTP-Server verwendet wird, nicht für jeden Request ein neues separates env-Objekt erzeugt.

• Stattdessen allokiert Unicorn für jeden Request einen Ruby-Hash und leert ihn anschließend mit clear.

• Dadurch wurde klar, dass die Logs des Background-Threads keine Reporting-Inkonsistenz waren, sondern dass Request-Daten tatsächlich geteilt wurden.

• Man versuchte, diese Race Condition in der Entwicklungsumgebung zu reproduzieren, und stellte fest, dass die Situation mit einem anonymen Request beginnen musste.

1. Ein anonymer Request (Request #1) trifft ein, und in der Exception-Reporting-Bibliothek wird ein Callback registriert. Dieser Callback enthält eine Referenz auf ein Rails-Controller-Objekt, das auf das von Unicorn bereitgestellte Rack-Request-Umgebungsobjekt zugreift.

2. Im Background-Prozess tritt eine Exception auf. Um sie zu melden, wird der gesamte Kontext kopiert, einschließlich des Callbacks.

3. Im Haupt-Thread beginnt ein neuer eingeloggter Request. (Request #2)

4. Im Background-Thread verarbeitet das Exception-Reporting den Kontext-Callback. Es versucht, den Session-Identifier des Nutzers zu lesen, findet aber keinen und schickt daher über den Rails-Controller von Request #1 eine Anfrage an das Authentifizierungssystem. Da Rack für alle Requests dasselbe Objekt verwendet, findet der Controller das Session-Cookie von Request #2.

5. Im Haupt-Thread endet Request #2.

6. Ein weiterer eingeloggter Request trifft ein. (Request #3) Die Authentifizierung ist bereits abgeschlossen.

7. Im Background-Thread schreibt der Controller das Session-Cookie in das Cookie-Jar im Rack-Environment und schließt damit die Authentifizierung ab. Zu diesem Zeitpunkt ist es jedoch das Cookie-Jar für Request #3.

8. Der Nutzer erhält die Response für Request #3, aber weil im Cookie-Jar das Session-Cookie von Request #2 geschrieben wurde, wird er als der Nutzer von Request #2 authentifiziert.

Zusammengefasst: Wenn eine Exception auftritt und die Stadien der Request-Verarbeitung in genau dieser Reihenfolge ablaufen, wird die Session einer Response durch die einer vorherigen Response ersetzt. Das geschah nur im Cookie-Header; Responses wie HTML enthielten weiterhin Daten des ursprünglich authentifizierten Nutzers.

Dieser Bug trat nur auf, wenn all diese komplexen Bedingungen gleichzeitig erfüllt waren.

• Um das Problem zu beheben, entfernte GitHub den neu eingeführten Background-Thread und spielte die Änderung am 5. März in die Produktion aus.

• Anschließend wurde ein Patch für Unicorn erstellt, damit das Environment nicht mehr gemeinsam genutzt wird; dieser wurde am 8. März ausgerollt.

• Nach der Log-Analyse stellte sich heraus, dass das Problem nur selten aufgetreten war, aber um das potenzielle Risiko vollständig zu beseitigen, wurden die Sessions aller Nutzer ungültig gemacht.

• Nach der Behebung arbeitete GitHub mit den Unicorn-Maintainern zusammen, damit der Fix auch Upstream übernommen wurde.

[kunggom]

Parallele Verarbeitung ist wirklich kompliziert. Ich habe mich am Wochenende auch eine ganze Weile damit herumgeschlagen, einen Code, den ich kürzlich zum persönlichen Lernen geschrieben hatte, parallel entsprechend der Anzahl der CPU-Threads auszuführen. Es hat zwar funktioniert, aber ich bin mir immer noch nicht ganz sicher, ob es wirklich sauber umgesetzt ist.