SIGSEGV um 03:14 - wenn forbid(unsafe_code) dich nicht rettet

Die erste Seite kam an einem Dienstag herein. 03:14 Uhr Ortszeit. Nicht 03:00, nicht 03:30. 03:14 Uhr, in vier aufeinander folgenden Nächten.

Der Tagebucheintrag, der mich geweckt hat:

[2026-04-22T03:14:07.882Z] worker[7]: received signal: SIGSEGV (11)
[2026-04-22T03:14:07.882Z] worker[7]: fault address: 0x7f9c1afc0000 (not mapped)
[2026-04-22T03:14:07.882Z] worker[7]: dumping core to /var/crash/inventory-7.core.gz
[2026-04-22T03:14:08.014Z] worker[7]: exit code 139
[2026-04-22T03:14:08.014Z] systemd[1]: inventory-svc.service: Main process exited
[2026-04-22T03:14:08.015Z] systemd[1]: inventory-svc.service: Scheduling restart in 5s.

Der Dienst ist in Rust. Siebzehn Kisten im Arbeitsbereich, jede mit #![forbid(unsafe_code)] an der Spitze. Rust-Dienste stürzen ab, aber sie stürzen so selten ab, dass dieser Dienst das gesamte Team innerhalb einer Stunde aufweckte. In der dritten Nacht hatten wir einen Kriegsraum.

Was wir am Mittwoch wussten

Vier Fakten, zusammengetragen in drei Nächten des Ausrufens:

1. Das Problem trat nur in der Produktion auf. Im Staging lief dasselbe Binary, dieselbe Konfiguration, derselbe Postgres-Dump, dieselben Kafka-Themen. Nichts. 2. Es passierte immer um 03:14 Uhr. Nicht um 14:00 Uhr unter unserer synthetischen Last. Nicht um 02:50 Uhr. Niemals innerhalb von 90 Sekunden beiderseits von 03:14 Uhr. 3. Der abstürzende Arbeiter rotierte. Derjenige der acht Arbeiter, der zufällig um 03:14 Uhr die Anfrage aufnahm, starb. 4. Die Arbeit hatte immer die gleiche Form: BatchReconcile vom Lageradapter.

Diese vier Fakten enthielten die gesamte Antwort. Wir sahen sie erst nach 48 Stunden.

Das Offensichtliche passiert

Wir haben zuerst die dummen Dinge getan. Wir haben den Log-Level auf trace für den relevanten Code-Pfad erhöht, das Programm gestartet und bis 03:14 gewartet. Der Worker stürzte ab und die Trace-Logs endeten eine Zeile vor dem SIGSEGV. Wir erfuhren, dass der Absturz innerhalb eines Bereichs auftritt, in dem die strukturierte Protokollierung gepuffert wird, was bedeutet, dass wir nichts Nützliches gelernt haben.

Wir haben versucht, die Situation zu reproduzieren, indem wir das Kafka-Produktionsprotokoll von 03:13:00 bis 03:15:00 Uhr mit einem neuen Staging Worker abspielten. Der Staging Worker bewältigte das Problem ohne Beanstandung. Wir versuchten es erneut, wobei die Partitionsreihenfolge geändert wurde. Das Gleiche. Ein dritter Versuch, nachdem der lokale Status des Workers gelöscht wurde. Das Gleiche.

Wir haben gdb um 03:13:50 Uhr an einen laufenden Produktions-Worker im Non-Stop-Modus angeschlossen, in der Hoffnung, in dem Moment einzubrechen, in dem der Absturz erfolgt. Der Absturz trat nicht ein. Als wir gdb abschalteten und den Worker unbeeinflusst weiterlaufen ließen, stürzte er um 03:14:08 Uhr in der nächsten Nacht ab. Der Debugger verlangsamte den Worker so sehr, dass die betreffende Anfrage außerhalb des Absturzfensters beendet wurde.

Die Kerndatei

Donnerstagmorgen, endlich eine brauchbare Kerndatei. Unser Infra-Team hatte einen automatischen Upload in einen S3-Bucket bei jedem Absturz eingerichtet. Wenn Sie das nicht haben, richten Sie es heute Abend ein; es zahlt sich aus, wenn sich etwas nicht lokal reproduzieren lässt.

$ gdb ./inventory-svc /tmp/inventory-7.core
[New LWP 18341]
[New LWP 18342]
...
Reading symbols from ./inventory-svc...
Core was generated by `./inventory-svc --config=/etc/inventory.toml'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f9c1a8b2e10 in core::ptr::read_unaligned<inventory::reconcile::Request> ()
    at /rustc/.../library/core/src/ptr/mod.rs:1284
1284    pub const unsafe fn read_unaligned<T>(src: *const T) -> T {
(gdb) bt
#0  core::ptr::read_unaligned<inventory::reconcile::Request> at ptr/mod.rs:1284
#1  warehouse_rpc_codec::codec::decode_batch at src/codec.rs:142
#2  inventory::worker::handle_batch_reconcile at src/worker.rs:412
#3  inventory::worker::dispatch_loop at src/worker.rs:312
#4  tokio::runtime::task::raw::poll<...>
...

read_unaligned. In warehouse_rpc_codec. Innerhalb einer externen Kiste.

Die Versandschleife, auf die wir seit zwei Tagen gestarrt hatten, war ein Ablenkungsmanöver:

struct DispatchQueue {
    inbox: VecDeque<RawFrame>,
    deadline: Option<Instant>,
}

impl DispatchQueue {
    async fn run(&mut self) {
        loop {
            tokio::select! {
                frame = recv_from_kafka() => self.inbox.push_back(frame),
                _ = sleep_until(self.deadline) => {
                    if let Some(frame) = self.inbox.pop_front() {
                        spawn(handle_request(frame));
                    }
                }
            }
        }
    }
}

&mut self überall. Der Borrow-Checker lässt nicht zu, dass zwei Aufgaben gleichzeitig die Warteschlange berühren. Wir haben anderthalb Tage damit verbracht, uns zu fragen, wie die Warteschlange beschädigt werden konnte, obwohl die Warteschlange eigentlich in Ordnung war. Das Bild kam unversehrt aus der Warteschlange und wurde an handle_request übergeben, das den Codec aufrief, der daraufhin abstürzte.

Den Brotkrumen folgen

An diesem Abend, unter Cargo.lock:

[[package]]
name = "warehouse-rpc-codec"
version = "0.4.2"
source = "git+https://example.invalid/warehouse-rpc-codec.git#9a14bb7c"

Eine Git-Abhängigkeit. Nicht an ein Release-Tag angeheftet. Commit 9a14bb7c lag 11 Wochen hinter dem Master-Zweig des Codec-Teams.

$ git -C ~/src/warehouse-rpc-codec log --oneline 9a14bb7c..HEAD
b822c91  Fix: BatchReconcile decoder mis-aligns on 32+ requests
4a3f1ad  Use Vec::with_capacity to avoid re-allocs
2dd1e92  Decode in place via unsafe pointer math   <-- !!
1a2b3c4  Bump tokio
...

2dd1e92 hatte die rohe Zeigerarithmetik in den Decoder eingeführt. Drei Wochen später hatte b822c91 den dadurch verursachten Ausrichtungsfehler behoben. Wir befanden uns an einem Punkt in der Geschichte, der den unsicheren Fehler enthielt, aber nicht die Korrektur.

Die entsprechende Funktion in 0.4.2:

// warehouse-rpc-codec v0.4.2
pub unsafe fn decode_batch(buf: &[u8]) -> Vec<Request> {
    let count = u32::from_le_bytes(buf[0..4].try_into().unwrap()) as usize;

    // Slow path: simple, correct, untouched by 2dd1e92.
    if count <= 31 {
        return decode_slow(buf);
    }

    // sizeof(Request) is 40 bytes after #[repr(C)] padding; the wire format
    // packs items at 36 bytes each. Walking the pointer by sizeof(Request)
    // drifts 4 bytes per item. By item 32 the read straddles the end of buf
    // and starts pulling from whatever follows it in memory.
    let mut out = Vec::with_capacity(count);
    let ptr = buf.as_ptr().add(4) as *const Request;
    for i in 0..count {
        out.push(std::ptr::read_unaligned(ptr.add(i)));
    }
    out
}

Bei count = 32 beginnt der letzte Lesevorgang 128 Byte nach dem Ende von buf. Meistens liegt das innerhalb der nächsten Zuweisung auf derselben Arena. Sie erhalten eine beschädigte Request, der vorgelagerte Aufrufer weist sie mit InvalidArgument zurück, und die einzige sichtbare Auswirkung ist eine sporadische Warnung in den Protokollen. (Wir haben genau diese Warnungen seit Wochen gesehen, die auf einen verrauschten Upstream zurückgeführt wurden.) Gelegentlich ist buf die letzte Live-Allokation auf seiner Seite, der Drift trägt den Zeiger in eine nicht gemappte Seite, und man erhält einen SIGSEGV.

#![forbid(unsafe_code)] gilt für die Kiste, in der sie sich befindet. Abhängigkeiten machen, was sie wollen.

Warum 03:14

Bleibt noch die Zeitfrage. Warum genau 03:14 Uhr?

Der schnelle Pfad läuft nur unter count > 31. Also: Woher kommt die Arbeitsbelastung?

BatchReconcile ist der Rollup, der ausgelöst wird, nachdem die Kommissionierer in der europäischen Region ihre Terminals für den Tag geschlossen haben. Sie gehen um 03:00 Uhr UTC offline, und der Rollup wartet ein 14-minütiges Ablassfenster ab, damit sich die Scans während des Fluges setzen können. Auf der ersten BatchReconcile nach dem Abfluss werden alle anstehenden Sendungen gesammelt, in der Regel 32 bis 60.

Alle anderen BatchReconcile bleiben im Laufe des Tages auf count ≤ 31, weil der Echtzeit-Pickerverkehr die Warteschlange kurz hält. Nur der Post-Drain-Rollup überschritt jemals 32. Einmal am Tag. Um 03:14 Uhr.

Bei Staging war das Rollup nicht konfiguriert. Lokal auch nicht. Der einzige Ort, an dem die Eingabeform, die den schnellen Pfad auslöste, jemals existierte, war prod, und zwar genau in dieser Minute.

Die Lösung

Zehn Minuten:

[dependencies]
warehouse-rpc-codec = { git = "https://example.invalid/warehouse-rpc-codec.git", tag = "v0.5.1" }

Eine Version, bei der die Ausrichtung korrigiert wurde. Wir bauten neu auf, setzten sie ein und warteten. 03:14 kam und ging ohne eine Seite, drei Nächte hintereinander.

Die Metafixierung

Das hat länger gedauert.

cargo deny verweigert jetzt nicht angeheftete Git-Abhängigkeiten in CI. Die erlaubten Formen sind tag = "..." oder branch = ... + rev = ...; alles andere führt zum Fehlschlag des Builds. Der erste Durchlauf, nachdem wir diese Regel eingeführt hatten, schlug bei vier Kisten fehl, die andere Teams importiert hatten. Wir haben sie behoben.

Beim nächtlichen Staging werden jetzt die letzten 24 Stunden der Kafka-Produktion mit realistischem Traffic-Shaping (Replay-Rate, Partition Fanout, Lücken) wiedergegeben. Dieser Fehler wäre in der zweiten Nacht aufgetreten, wenn wir ihn damals gehabt hätten.

cargo geiger wird bei jedem Abhängigkeitssprung ausgeführt und meldet neue unsafe, die in transitive deps eingeführt wurden. Es ist lauter als mir lieb ist. Das Signal-Rausch-Verhältnis ist immer noch deutlich besser als ein weiterer Vorfall in vier Nächten.

Und es gibt eine weiche Regel: Jeder, der warehouse-rpc-codec (oder eine andere Kiste, deren Geigerbericht nicht leer ist) stößt, streicht die Differenz seit dem letzten Pin. Wir haben das seit April dreimal gemacht. Wir haben eine Regression entdeckt, die es wert ist, entdeckt zu werden, und zwei Änderungen ohne Zeremonie genehmigt.

Dinge, die sich zu tragen lohnen

• forbid(unsafe_code) ist eine Eigenschaft Ihrer Kiste, nicht Ihrer Binärdatei. Ihr Abhängigkeitsgraph ist Teil Ihrer vertrauenswürdigen Datenbasis, ob Sie ihn nun so behandeln oder nicht. - Setzen Sie alles fest. Schwebende Versionen, insbesondere Git-Deps ohne tag oder rev, sind ein Ausfall mit einer verzögerten Sicherung. - Crashdumps sind keine optionale Infrastruktur. Wenn Sie kein Corefile aus prod bekommen können, können Sie nicht debuggen, was nur in prod passiert. - Ein zeitlich festgelegter Fehler hat fast immer einen deterministischen Treiber dahinter. Finden Sie heraus, was bei dieser Uhr feuert, und Sie haben den Fehler gefunden. Cron-Jobs, Öffnen/Schließen von Märkten, Batch-Fenster, Log-Rotation, GC-Pausen; taktgebundene Dinge. - Wenn gdb -p das Symptom verschwinden lässt, ist der Fehler zeitgebunden. Wenden Sie sich als nächstes an rr oder valgrind.

Die fünfzeilige Regel cargo deny, die dies verhindert hätte, ist jetzt unter deny.toml zu finden, wobei ein Kommentar auf diesen Beitrag verweist.

Greg Law

Wenn Sie eine echte Tour durch das Post-Mortem-Debugging unter Linux wollen, finden Sie Greg Laws CppCon-Vorträge. Gib mir 15 Minuten und ich ändere deine Sicht auf GDB (CppCon 2015) ist die Kurzversion. GDB - A Lot More Than You Knew (CppCon 2016) ist diejenige, die Sie sich an einem Samstag mit geöffnetem Notizblock ansehen. Beide sind auf dem CppCon YouTube-Kanal zu finden