Eine Coredump-Geschichte über NGINX ctx und error_page

Coredumps in der Produktionsumgebung sind für Ingenieure erschreckend, insbesondere wenn die Abstürze mitten in der Nacht auftreten. Ich selbst habe dies vor mehr als einem Jahrzehnt erlebt. Um diesen „Geister“-Bug zu finden, der nur nachts auftrat, ging das gesamte Team nach Hause, um am Nachmittag zu schlafen, und kam um Mitternacht zurück ins Unternehmen, um auf den Absturz zu warten und jeden Dienst einzeln zu überprüfen. Stellen Sie sich eine dunkle Nacht und ein Bürogebäude vor, in dem nur wenige Arbeitsplätze beleuchtet sind, während man den ständig blinkenden Monitor beobachtet, um Daten und Protokolle zu überprüfen – eine intensive und aufregende Erfahrung. Wir blieben drei Nächte lang, bevor wir den Bug lokalisierten und behoben, was eine unvergessliche Erfahrung war.

Wir wussten nicht, dass wir dies noch einmal erleben würden. Nur war es diesmal nicht unser eigener Dienst, sondern der Online-Dienst des Kunden, der einen Coredump hatte. Dies war schwieriger als unsere eigene kontrollierbare Umgebung:

• Der Fehler trat nur in der Produktionsumgebung des Benutzers auf, und der Benutzer konnte den Fehler nicht einmal in seiner eigenen Pre-Production- und Testumgebung reproduzieren.
• Der Benutzer hatte benutzerdefinierten Code auf der Open-Source-Version von Apache APISIX, der erst nach Unterzeichnung einer separaten NDA sichtbar war.
• Es konnten keine Debug-Protokolle hinzugefügt werden.
• Der Fehler trat nur um 3 Uhr morgens auf, was zusätzliche Ressourcen des Kunden erforderte, um ihn sofort zu beheben.

Kurz gesagt, dieses Problem war nicht reproduzierbar, es gab keinen vollständigen Quellcode und keine Umgebung zum Testen. Dennoch mussten wir den Fehler lokalisieren, einen Weg finden, ihn zu reproduzieren und schließlich eine Lösung finden. Während dieses Prozesses hatten wir viele Herausforderungen und haben viel daraus gelernt. Hier teilen wir einige interessante Punkte, die während des Debugging-Prozesses aufgetreten sind. Ich hoffe, sie werden eine Anleitung bieten, wenn Leute NGINX und APISIX debuggen.

Problembeschreibung

Nachdem der Benutzer APISIX von Version 2.4.1 auf Version 2.13.1 aktualisiert hatte, traten zyklisch Coredumps mit der folgenden Fehlermeldung auf:

Aus der Coredump-Meldung konnten wir sehen, dass der Segmentierungsfehler im lua-var-nginx-module auftrat. Und hier sind die entsprechenden Daten (teilweise) im Speicher:

#0  0x00000000005714d4 in ngx_http_lua_var_ffi_scheme (r=0x570d700, scheme=0x7fd2c241a760)
    at /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c:152
152        /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c: No such file or directory.
(gdb) print *r
$1 = {signature = 0, connection = 0x0, ctx = 0x15, main_conf = 0x5adf690, srv_conf = 0x0, loc_conf = 0x0, read_event_handler = 0xe, write_event_handler = 0x5adf697,
  cache = 0x2, upstream = 0x589c15, upstream_states = 0x0, pool = 0x0, header_in = 0xffffffffffffffff}

Wir können sehen, dass die Daten im Speicher ein Problem haben.

Einige Gedanken vor der Analyse

Segmentierungsfehler treten normalerweise in zwei Szenarien auf:

1. Lesen/Schreiben einer ungültigen Adresse im Speicher, z.B. Zugriff auf einen Array-Index außerhalb der Grenzen, der sofort einen Segmentierungsfehler verursacht.
2. Ein ungültiger Schreibvorgang, der jedoch eine gültige Adresse modifiziert, sodass er nicht sofort einen Segmentierungsfehler verursacht. Während des Programmlaufs wird versucht, auf Daten in der fehlerhaften Adresse zuzugreifen, was einen Segmentierungsfehler auslöst. Zum Beispiel, wenn der Wert eines Zeigers versehentlich geändert wird, kann dies später, wenn auf diesen Zeiger zugegriffen wird, einen Segmentierungsfehler auslösen.

Für das erste Szenario kann das Problem leicht lokalisiert werden, wenn wir die Aufrufliste überprüfen.

Für das zweite Szenario ist es unklar, wo der Fehler ursprünglich auftritt, sodass der Code, der den Fehler verursacht hat, und der Code, der den Segmentierungsfehler auslöst, möglicherweise nicht am selben Ort liegen, sogar völlig unabhängig voneinander sind, was die Lokalisierung erschwert. Wir konnten nur mehr Kontextinformationen sammeln, die den Absturz betreffen, wie:

• Aktuelle APISIX-Konfigurationsdetails.
• Die Verarbeitungsphase der aktuellen Anfrage.
• Die Details der aktuellen Anfrage.
• Die Anzahl der gleichzeitigen Verbindungen.
• Das Fehlerprotokoll.

Durch diese Informationen würden wir versuchen, den Bug durch Überprüfung des Codes zu finden und einen Weg zu finden, das Problem zu reproduzieren.

Analyse

1. Kontextüberprüfung der Fehler

Nach sorgfältiger Analyse stellten wir fest, dass der Fehler normalerweise zwischen 3 und 4 Uhr morgens auftrat, mit der folgenden Coredump-Fehlermeldung:

Schließlich erkannten wir, dass das Fehlerprotokoll mit Benutzeraktionen verbunden war. Aus bestimmten Gründen würden alle Upstream-Nachrichten zu diesem Zeitpunkt gelöscht. Daher vermuteten wir, dass das Problem mit Upstream-Clear/Reset-Operationen zusammenhängt und der Coredump möglicherweise durch das Betreten eines Ausnahmezweigs nach der Fehlerrückgabe verursacht wurde.

2. Lua-Aufrufliste erhalten

Da GDB die Lua-Aufrufliste nicht verfolgen kann, konnten wir nicht feststellen, welcher Aufruf den Fehler verursacht hat. Daher war das erste, was wir tun mussten, die Lua-Aufrufliste zu erhalten; wir hatten zwei Methoden, um die Aufruflisten zu erhalten:

1. Im lua-var-nginx-module Code hinzufügen, um die Aufrufliste auszugeben (print(debug.traceback(...)). Der Nachteil ist, dass dies viele Fehlerprotokolle generiert, was sich negativ auf die Produktionsumgebung auswirkt.
2. Verwenden Sie openresty-gdb-utils, das von API7.ai gepflegt wird. Dieses Toolkit verwendet GDBs DSL und Python-Erweiterung, um die Fähigkeit von GDB zur Analyse der Lua-Aufrufliste zu verbessern. Beachten Sie, dass Sie das Debug-Symbol zur Kompilierzeit aktivieren müssen. Es ist standardmäßig in APISIX enthalten.

Dann erhielten wir die folgende Aufrufliste.

Durch die Kombination der Lua- und C-Aufrufliste konnten wir feststellen, dass der Coredump auftrat, weil der Benutzer ngx.ctx.api_ctx.var.scheme im Prometheus-Plugin aufrief. Der Grund für den Absturz war jedoch immer noch unklar, wir mussten ihn weiter analysieren.

3. Cache verursachte das Problem

Der Fehler trat auf, wenn auf eine Variable aus ngx.ctx.api_ctx.var zugegriffen wurde, was einen Aufruf im oben beschriebenen lua-var-nginx-module ausführte. Um die Effizienz zu steigern, wurde die aktuelle Anfrage zwischengespeichert. Wir erinnerten uns, dass der Fehler auftrat, wenn der Wert des Anfragekörpers eine Ausnahme hatte, sodass die Gültigkeit der zwischengespeicherten Anfrage ebenfalls fraglich war. Um diesen Gedanken zu überprüfen, stoppten wir das Programm, den zwischengespeicherten Speicher zu verwenden, sondern holten die Anfrage jedes Mal neu ab.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request change to nil
end

Der Benutzer testete diese modifizierte Version eine ganze Nacht lang, und der Fehler trat nicht erneut auf; wir bestätigten, dass der Anfragekörper ein Problem hatte.

4. Der Fehler in ngx.ctx

Der zwischengespeicherte Anfragekörper wurde in ngx.ctx gespeichert, und der einzige Ort, der ngx.ctx änderte, war in apisix/init.lua.

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- prevent for the table leak
        local stash_ctx = fetch_ctx()

        -- internal redirect, so we should apply the ctx
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= HERE
        end
    end

    core.response.set_header("Server", ver_header)

    local up_status = get_var("upstream_status")
    if up_status then
        set_resp_upstream_status(up_status)
    end

Warum mussten wir ngx.ctx hier wiederherstellen? Weil ngx.ctx im Lua-Register gespeichert ist, kann das entsprechende ngx.ctx über den Registerindex gefunden werden. Und der Index wurde im ctx-Mitglied der NGINX-Anfragestruktur gespeichert. Jedes Mal, wenn eine interne Umleitung durchgeführt wurde, löschte NGINX ctx, und somit konnte der Index nicht gefunden werden.

Um dieses Problem zu lösen, erstellte APISIX eine Tabelle, die den aktuellen ngx.ctx vor der Umleitung speicherte, und verwendete dann ngx.var, um den Index von ngx.ctx in dieser Tabelle zu speichern. Wann immer es wiederhergestellt werden musste, konnten wir ngx.ctx direkt aus der Tabelle abrufen.

Der Code in der obigen Abbildung wurde nur ausgelöst, wenn der Benutzer error_page-Anweisungen konfiguriert hatte und nach einem Fehler nach internen Umleitungen auftrat.

Und wir wussten genau, dass der Benutzer die error_page-Anweisung nach der Versionsaktualisierung aktiviert hatte, kombiniert mit dem Fehler, der durch die oben beschriebene Upstream-Änderung auftrat. Alles schien zusammenzuhängen. War es tatsächlich ngx.ctx, das den Bug während des Fehlerbehandlungsprozesses verursachte?

5. Warum hat ngx.ctx einen Bug?

Mit dieser Frage überprüften wir den Code, der mit der Sicherung von ngx.ctx zusammenhängt, und fanden noch seltsamere Probleme. Nach einem Fehler bei set_upstream würde es nie den Schritt zur Wiederherstellung von ngx.ctx durchführen, weil es frühzeitig beendet wurde, es würde ngx.ctx nicht sichern und auch nicht den Wiederherstellungsprozess durchlaufen.

Dies war offensichtlich ein Bug! Nun, dies liegt daran, dass ngx.ctx nach der Umleitung wiederhergestellt werden musste. Und wie wurde dieser Prozess wiederhergestellt? Wo ging ngx.ctx ursprünglich schief? Jetzt gab es zu viele Ungewissheiten, wir mussten mehr Daten sammeln.

Nach Diskussionen fügten wir ein zweites Protokoll in der Produktion hinzu und entdeckten, dass, wenn der Fehler nach einer internen Umleitung auftrat, ngx.ctx nicht den Wiederherstellungsprozess durchlief, sondern direkt einen Coredump verursachte!

Dies war ein verwirrendes Phänomen, denn wenn ngx.ctx nach der Umleitung nicht wiederhergestellt wurde, wäre ngx.ctx leer/null. Und es gab Code, der auf leere Werte prüft; er sollte den Coredump-Code im Plugin nicht auslösen.

local function common_phase(phase_name)
    local api_ctx = ngx.ctx.api_ctx
    if not api_ctx then              <============ HERE
        return
    end

    plugin.run_global_rules(api_ctx, api_ctx.global_rules, phase_name)

War es also diese error_page-interne Umleitung, die ngx.ctx dazu veranlasste, ein Problem zu haben?

6. Vorläufige Schlussfolgerung

Nach Analyse und Überprüfung hatten wir ein grundlegendes Verständnis des fehlerhaften Prozesses.

set_upstream schlug fehl und leitete zur error_page-Fehlerbehandlungsphase um, und der erwartete leere ngx.ctx hatte einen unerwarteten Wert. Und aufgrund eines APISIX-Bugs wurde ngx.ctx vor der Umleitung nicht wiederhergestellt, was dazu führte, dass ngx.ctx beim Zugriff schmutzige Daten hatte und somit einen Coredump verursachte. Um dieses Problem zu lösen, mussten wir nur ngx.ctx nach der Umleitung wiederherstellen; die detaillierte Implementierung dieses Commits wird am Ende des Artikels zur Referenz bereitgestellt.

Obwohl wir eine Lösung für den Bug bereitstellten, konnten wir die vollständige Logik des Bugs immer noch nicht verstehen. Da der Benutzer die Logik von ngx.ctx nicht geändert hatte, sollte die Open-Source-Version reproduzierbar sein. Um die Produktionsumgebung und den Bereitstellungsprozess des Benutzers nicht weiter zu beeinträchtigen, beschlossen wir, die Ursache weiter zu untersuchen.

7. Erfolgreiche Reproduktion

Von dem, was wir wussten, konnten wir das Problem nicht reproduzieren. Nach der Analyse beschlossen wir, zwei der folgenden Punkte zu überprüfen:

• Hatte die interne Umleitung spezielle Verarbeitungszweige?
• Hatte ngx.ctx spezielle Verarbeitungszweige?

Für den ersten Punkt könnte es während der Verarbeitung jedes Filtermoduls von NGINX einige Ausnahmezweige geben, die die ctx-Mitglieder des Anfragekörpers beeinflussen und somit ngx.ctx beeinträchtigen. Wir überprüften die Module des Benutzers, die in NGINX kompiliert wurden, auf potenzielle Ausnahmezweige, fanden jedoch keine ähnlichen Probleme.

Für den zweiten Punkt fanden wir nach Untersuchungen heraus, dass während des SSL-Handshakes ngx.ctx ein Problem durch Wiederverwendung hat. Wenn die HTTP-Phase ngx.ctx nicht erhalten konnte, würde sie versuchen, es aus der SSL-Phase zu erhalten. Die SSL-Phase hat ihr eigenes ngx.ctx, und das könnte Probleme für ngx.ctx verursachen.

Basierend auf den oben genannten Entdeckungen entwarfen wir die folgenden Bedingungen und konnten das Problem erfolgreich reproduzieren:

1. Gleiche APISIX-Version wie die des Benutzers
2. SSL-Zertifikat aktivieren
3. Einen internen Fehler erzeugen, der error_page auslöst (z.B. Anfrage an Upstream, wenn keiner vorhanden ist)
4. Lange Verbindung
5. Prometheus-Plugin (der Coredump trat im Plugin des Benutzers auf)

Wir haben schließlich aus dem Nichts etwas geschaffen. Durch Vermutungen und Überprüfungen haben wir schließlich den vollständigen Prozess dieses Bugs herausgefunden. Sobald es eine vollständige Reproduktion gibt, ist es nicht mehr schwierig, das Problem zu lösen, und der endgültige Prozess wird hier nicht im Detail beschrieben. Ich glaube, dass jeder reichlich Erfahrung mit Problemen hat, die genau reproduziert werden können.

Zusammenfassung

Die Ursache dieses Problems: weil ngx.ctx nach dem Betreten der error_page nicht wiederhergestellt wurde, verwenden alle Anfragen auf der langen Verbindung dasselbe ngx.ctx in der SSL-Phase. Schließlich verursacht dies, dass ngx.ctx schmutzige Daten hat und ein Coredump erzeugt wird.

Im Nachgang haben wir auch eine entsprechende Lösung für dieses Problem vorgeschlagen: sicherzustellen, dass ngx.ctx nach der internen Umleitung normal wiederhergestellt wird. Bitte beziehen Sie sich auf den spezifischen PR.

Wenn Ihr APISIX Funktionen verwendet, die interne Umleitungen wie error_page beinhalten, aktualisieren Sie bitte so schnell wie möglich auf die neueste Version.

Das Schreiben von Programmen und das Debuggen sind wissenschaftlich strenge Aufgaben und lassen keinen Raum für Unklarheiten. Um ein Problem zu lösen, müssen wir Informationen sammeln, alle potenziellen Hinweise verfolgen, die Aufrufliste analysieren und dann den Kontext herausfinden, um den Fehler zu reproduzieren. Schließlich wird das Problem gelöst.