Wie ein bisschen Rate-Limiting uns schleichend ruiniert hat, und jetzt nicht mehr

Posted by jonas on Thursday, July 11, 2024

Issue #510

Dezember 2021.

“Hey, wir sollten im Rahmen der Spambekämpfung mal etwas mehr Rate-Limiting machen. So maximal 60 Verbindungen pro Stunde sollten erstmal passen, das sollte normale User nicht beeinträchtigen, aber Spammer etwas besser ausbremsen.” - Allgemeine Zustimmung im Team.

Gesagt, getan - und unsere /etc/haraka/outbound/limits.ini nach einigen Tests um (unter anderem) ein Rate-Limiting für SMTP-Verbindungen ergänzt, gemäß der Dokumentation:

[rate_conn]
enabled=true
default=60/60m

Funktioniert prima und tut was es soll.

Schnellvorlauf.

2022 - “Irgendwie seh ich öfter mal Haraka ziemlich weit oben in der Prozessliste, sowohl was CPU als auch was RAM angeht… ist das so ineffizient oder wie? Das macht doch nur ein bisschen Relaying…” - eine Runde relativ ergebnisloses Debugging. “Sooo schlimm ist es jetzt auch nicht, ist vielleicht einfach so.”

2023 - “Boah, Leute, also auf Dauer kann das echt nicht so bleiben, unsere Postfix-Instanzen anderswo machen praktisch null Last, aber was geht denn hier ab?” - eine Runde relativ ergebnisloses Debugging. “Mit U8 wechseln wir eh auf Postfix. Da sollten wir nicht mehr so viel Zeit reinstecken.”

Anfang 2024.

“LEUTE, wir haben ein PROBLEM! Was macht Haraka denn da, irgendwie ist das im htop jetzt konstant ganz oben zu sehen, selbst nach einem Reboot ist das direkt von Beginn an wieder so!”, und auch “Haraka braucht durchschnittlich pro Host einen CPU Kern und 4GB RAM, da sparen wir zukünftig also gut was, wenn wir bei U8 auf Postfix wechseln”.

Der Unmut wächst

Was sich innerhalb des Teams langsam auch zu häufen beginnt:

“Boah, diese Uberspace-OnCall-Schicht hatte echt wieder so einige Load- und CPU-Alerts. Was ist denn da bloß los? Wir haben keinen dramatischen User-Anstieg, wir haben nichts gravierend Neues ausgerollt. Ich verstehe das einfach nicht.”

“Boah, diese Operations-OnCall-Schicht war echt wieder super nervig. Ich schaue schon extrem penibel darauf, die VMs so gleichmäßig wie möglich auf die Nodes zu verteilen, und wir haben doch erst vor wenigen Wochen noch drei neue Nodes in den Cluster eingebaut, wieso merkt man davon einfach nichts?”

Es mangelte all die Zeit über nie an Versuchen, dem Problem irgendwie debugtechnisch näherzukommen. Wir sind ihm nur nicht auf die Spur gekommen.

In der letzten Woche schließlich begann das Debugging-Projekt, von dem wir zu diesem Zeitpunkt noch nicht ahnten, mit welchem Tusch es diesem Thema ein Ende setzen wird.

Last, die völlig unlogisch erscheint

Es beginnt damit, dass ich mir einen unserer internen Hosts vornehme, der mailtechnisch praktisch überhaupt nicht benutzt wird. Dort finde ich diese Prozessliste vor:

[...]
root      2799  0.2  0.4 831780 51292 ?        Ssl  Jun18  66:43 Haraka (master) cn=113146 cc=3 cps=0/0.08/5 rcpts=3601/1.01 rps=0/0/
haraka    3008  0.0  0.4 967348 56292 ?        Sl   Jun18  23:30  \_ Haraka (worker) cn=14146 cc=1 cps=0/0.01/1 rcpts=437/1.01 rps=0/0/1 msgs=433/0.03 mps=0/0/1
haraka    3009  0.0  0.5 975540 66592 ?        Rl   Jun18  23:24  \_ Haraka (worker) cn=14145 cc=1 cps=0/0.01/1 rcpts=445/1.01 rps=0/0/1 msgs=439/0.03 mps=0/0/1
haraka    3010  0.1  0.5 975140 66008 ?        Sl   Jun18  24:41  \_ Haraka (worker) cn=14143 cc=0 cps=0/0.01/1 rcpts=465/1.01 rps=0/0/1 msgs=462/0.03 mps=0/0/1
haraka    3011  0.0  0.4 967348 58068 ?        Sl   Jun18  23:40  \_ Haraka (worker) cn=14142 cc=0 cps=0/0.01/1 rcpts=462/1.01 rps=0/0/1 msgs=456/0.03 mps=0/0/1
[...]
root      2865  0.2  0.4 832292 50616 ?        Ssl  Jun18  66:59 Haraka (master) cn=274666 cc=0 cps=0/0.19/12 rcpts=6/1 rps=0/0/2 msgs
haraka    3067 10.7  3.3 1188748 404840 ?      Sl   Jun18 2638:44  \_ Haraka (worker) cn=34342 cc=0 cps=0/0.02/2 rcpts=1/1 rps=0/0/1 msgs=1/0 mps=0/0/1 out=0/0/0
haraka    3068 10.5  1.7 1024444 209600 ?      Sl   Jun18 2589:06  \_ Haraka (worker) cn=34340 cc=0 cps=0/0.02/2 rcpts=0/0 rps=0/0/0 msgs=0/0 mps=0/0/0 out=0/0/0
haraka    3070 10.4  2.7 1118992 336028 ?      Sl   Jun18 2575:16  \_ Haraka (worker) cn=34334 cc=0 cps=0/0.02/2 rcpts=0/0 rps=0/0/0 msgs=0/0 mps=0/0/0 out=0/0/0
haraka    3078 10.8  2.2 1097276 269528 ?      Sl   Jun18 2674:11  \_ Haraka (worker) cn=34329 cc=0 cps=0/0.02/2 rcpts=1/1 rps=0/0/1 msgs=1/0 mps=0/0/1 out=0/0/0
[...]

Der obere Block ist das Haraka für eingehende Mails, der untere für ausgehende Mails. Beide Prozessgruppen sind am 18. Juni gestartet worden. Man sieht, dass die zweite Instanz mehr als doppelt soviele Connections verarbeitet hat (cn=274666) als die erste (cn=113146), was aber auch dazu passt, dass die erste nur einen Port bereitstellt (25), die zweite für’s Relaying aber zwei (465 und 587), und da wir alle Ports regelmäßig monitoren, bekommt die zweite Instanz rund doppelt so viele Verbindungen ab. Was aber auffällt, ist die Spalte der kumulierten CPU-Zeit (die direkt hinter “Jun18”): Hier haben wir Werte, die eher so beim Hundertfachen der CPU-Zeit der eingehenden Prozesse liegen. Das… kann doch nicht sein.

Sperren wir doch mal das Monitoring aus…

Davon ausgehend, dass nahezu alle Verbindungen von unserem Monitoring stammen (was nichts anderes tut als ein EHLO zu senden, auf Port 587 noch ein STARTTLS, und dann ein QUIT), habe ich mal ins Blaue hinein getestet, was passiert, wenn ich einen Teil unserer Monitoring-IPs kurzerhand via iptables aussperre (vorher eine Silence gesetzt, damit nichts alarmiert). Der Graph spricht für sich:

Graph des RAM-Verbrauchs von Haraka, massiv abfallend

Auch die CPU-Last ging nennenswert nach unten. B…bitte was?! Nur weil unser Monitoring nicht mehr lumpige 8 SMTP-Sessions pro Minute aufmacht (wir testen minütlich, aber von 2 Standorten aus, über IPv4 und IPv6 separat, und eben die Ports 465 und Port 587, daher 8 Sessions pro Minute auf der gleichen Haraka-Instanz), sinkt die Last so dramatisch? Wie kann denn das sein?

Ich habe dann auf einem Test-Host den relevanten Teil unseres Monitoring-Setups nachgebaut, um besser herumspielen zu können. Wir nutzen für die SMTP-Checks den blackbox_exporter mit dieser Config, hier exemplarisch für TLS via STARTTLS (für Port 587) als auch mit direkt aktiviertem TLS (für Port 465):

modules:

  smtp_c2s_starttls_v4:
    prober: tcp
    tcp:
      query_response:
        - expect: "^220 ([^ ]+) ESMTP (.+)$"
        - send: "EHLO moni.toring.host\r"
        - expect: '^250.+ \[\d+\.\d+\.\d+\.\d+\]Haraka is at your service\.$'
        - send: "STARTTLS\r"
        - expect: "^220"
        - starttls: true
        - send: "EHLO moni.toring.host\r"
        - expect: '^250(.+) (\[\d+\.\d+\.\d+\.\d+\])Haraka is at your service\.$'
        - expect: "^250 AUTH"
        - send: "QUIT\r"
      preferred_ip_protocol: "ip4"
      ip_protocol_fallback: false

  smtp_c2s_tls_v4:
    prober: tcp
    tcp:
      query_response:
        - expect: "^220 ([^ ]+) ESMTP (.+)$"
        - send: "EHLO moni.toring.host\r"
        - expect: '^250.+ \[\d+\.\d+\.\d+\.\d+\]Haraka is at your service\.$'
        - expect: "^250 AUTH"
        - send: "QUIT\r"
      preferred_ip_protocol: "ip4"
      ip_protocol_fallback: false
      tls: true

Sobald der blackbox_exporter läuft, ließen sich die Verbindungen so testen:

$ curl "http://localhost:9115/probe?target=<testhost>.uberspace.de:587&module=smtp_c2s_starttls_v4"
$ curl "http://localhost:9115/probe?target=<testhost>.uberspace.de:465&module=smtp_c2s_tls_v4"

Jetzt gab es nur ein Problem: Diese Tests funktionierten nicht nur einwandfrei - sie generierten auch praktisch überhaupt keine CPU-Last und belegten praktisch überhaupt keinen zusätzlichen RAM. Okay, bestimmt teste ich nicht aggro genug - gleich erstmal eine for-Schleife drum herum gebaut und mal hundert SMTP-Sessions nacheinander aufgebaut ohne Pausen dazwischen, also viel viel mehr als unser Monitoring macht. Es zeigt sich: Nichts. Alle Graphen bleiben vollkommen ruhig.

Verzweiflungstat

8. Juli 2024, 15:11 Uhr. Ich werfe eine ungewöhnliche Nachricht in unseren Teamchat, nämlich dass ich gerne einmal für definiert 1 Stunde lang unser Monitoring der SMTP-Relay-Ports deaktivieren möchte, um mir anzuschauen, was passiert. Ich habe zu diesem Zeitpunkt noch keine Idee, wieso Verbindungen unseres Monitorings grundsätzlich anders behandelt werden sollten als jede andere - vor allem nicht, weil ich auf meinem Testhost ja mit dem blackbox_exporter exakt das nachgebildet habe, was unser Monitoring auch tut. Es gab insofern nur ein diffuses Bauchgefühl.

8. Juli 2024, 15:50 Uhr. Das Monitoring ist aus. Wir starren gebannt auf Graphen. Mein Kollege Noah lässt sich zu einem “holy sh…” hinreißen. Mein Kollege luto kommentiert trocken: “erstmal 370 GB RAM frei”.

Natürlich ist interessant, wie sich das Deaktivieren des Monitorings der zwei SMTP-Ports konkret auf Haraka auswirkt, aber ich wollte vor allem auch gerne sehen, wie sich das in der Gesamtbelastung des Clusters bemerkbar macht. Lassen wir einfach mal ein Bild sprechen (die Graphen zeigen den durchschnittlichen Load über 15 Minuten, das heißt, niedrige Werte sind besser).

Zwei Load-15-Graphen mit abrupt rund halbierter Last

Das Deaktivieren des Monitorings der SMTP-Relay-Ports hat unsere gesamte Cluster-Last grob gesagt halbiert. Und das hat positive Auswirkungen auf alles, also z.B. auch auf die dramatisch verbesserte Commit-Latency unseres Ceph-Storage-Clusters.

Wir entschieden spontan, die geplante 1 Stunde für das Deaktivieren des Monitorings der SMTP-Relay-Ports erstmal auszuweiten, bis wir mehr wissen - immerhin wussten wir nun, dass wir etwas Großem auf der Spur sind.

Wie bitte kann das sein?

Ausgehend von der Beobachtung, dass die Last-Effekte selbst bei identischen SMTP-Sessions nur dann auftreten, wenn unsere Monitoring-Hosts sie ausführen, aber bei anderen irgendwie so gar nicht, haben wir überlegt, wo denn IP-bezogene Last überhaupt herkommen könnte. An das Rate-Limiting von ganz am Anfang haben wir dabei offen gesagt im ersten Moment gar nicht gedacht - klar muss das Rate-Limiting für “Verbindungen pro Stunde” irgendwie notieren, wenn Verbindungen durchgeführt werden, aber das Ganze ist ja dann ein Moving Window von einer Stunde, so dass ältere Einträge dann ja wieder verworfen werden können und sollten. Oder?

ODER?

An dieser Stelle waren wir neugierig darauf, wie genau das limit-Plugin von Haraka die benötigten Informationen speichert. Wir wussten, die Daten landen in einer Redis-Instanz, die wir extra dafür bereitgestellt haben. Also sind wir hier mal etwas eingetaucht (keine Sorge, eine weniger technische Erklärung dessen, was man hier sieht, folgt im Anschluss).

Redis ist ein Key-Value-Store, speichert also unter frei gewählten Identifier-Bezeichnungen irgendwelche Werte. Also haben wir uns erstmal mit dem Befehl KEYS angeschaut, wie die betreffenden Keys heißen:

[root@fairydust ~]# redis-cli -s /run/redis-haraka-out/haraka-out.socket -n 4
redis /run/redis-haraka-out/haraka-out.socket[4]> KEYS *
1) "rate_conn:192.0.2.132"
2) "rate_conn:198.51.100.234"
3) "rate_conn:203.0.113.65"

Aha, es gibt also offenbar pro IP-Adresse einen Key mit dem Präfix “rate_conn:” gefolgt von der IP-Adresse. Wir wissen schon, dass die zugehörigen Werte nicht unbedingt eine einfache Datenstruktur wie eine Zeichenkette sein müssen, sondern auch komplexere Strukturen sein können. Mit dem Befehl TYPE finden wir das raus:

redis /run/redis-haraka-out/haraka-out.socket[4]> TYPE rate_conn:192.0.2.132
hash

Aha, ein Hash. Also schauen wir mal, welche Keys und Werte dieser Hash hat. Dazu dient der Befehl HKEYS, der den Namen eines Keys als Argument bekommt und dann die Hash-Keys des darunter gespeicherten Hashes ausgibt:

redis /run/redis-haraka-out/haraka-out.socket[4]> HKEYS rate_conn:192.0.2.132
1) "1720515650760"

Mhm, mhm. Sieht wie ein Timestamp aus, von der Anzahl der Ziffern vermutlich Mikrosekunden. Und welchen Wert hat er? Das finden wir mit dem Befehl HGET heraus:

redis /run/redis-haraka-out/haraka-out.socket[4]> HGET rate_conn:192.0.2.132 1720515650760
"1"

Aha, eine Eins. Vermutlich ein Counter. Es erscheint sinnvoll, sich nun auch mal den Code des limit-Plugins anzuschauen. Dort gibt es die Funktion rate_conn_incr, die im Wesentlichen das hier tut:

    try {
        await this.db.hIncrBy(`rate_conn:${key}`, (+ new Date()).toString(), 1)
        // extend key expiration on every new connection
        await this.db.expire(`rate_conn:${key}`, getTTL(value) * 2)
    }

Aha, so kann das sein!

Langsam setzen sich die Puzzleteile zusammen, und was bisher nur so eine dumpfe Ahnung war, verfestigt sich mit dem Lesen des Plugin-Codes:

Pro IP wird in Redis unter dem Key “rate_conn:” ein Hash gespeichert, bei dem die Hash-Keys Timestamps sind und die Hash-Values Counter für diesen Timestamp, in der Regel also einfach “1”, bei mehreren Verbindungen von der gleichen IP zur exakt gleichen Zeit aber ggf. auch mal höher. Und der Key für “rate_conn:” bekommt eine TTL von 60m * 2, also 7200 Sekunden, dann läuft er automatisch ab.

Jetzt kommt aber der Haken: Die Hash-Keys mit den Timestamps, die dann unter diesem Key für die IP gespeichert sind, haben keine TTL. Redis kennt für Hash-Keys unseres Wissens nach auch keine - ist einfach nicht vorgesehen. Wenn man möchte, dass diese Hash-Keys ebenso ablaufen, müsste man dafür eine eigene Ablauf-Logik bauen, die diese Hash-Keys nach Ablauf verwirft.

Eine Ablauf-Logik, die das limit-Plugin nicht hat.

Alles für die Ewigkeit

Das bedeutet entsprechend: Solange von einer IP innerhalb der Dauer von 7200 Sekunden weitere Verbindungen reinkommen, bleibt der Key mitsamt aller (!!!) seiner Hash-Keys in Redis enthalten. Die Connection-History bleibt insofern ewig.

Eine von unserem Monitoring ausgeführte SMTP-Verbindung pro Minute bedeutet 1.440 Verbindungen pro Tag. 43.200 Verbindungen pro Monat. 525.600 Verbindungen pro Jahr - und in den rund 2,5 Jahren seit Einführung des Rate-Limitings ergo rund 1.314.000 Verbindungen insgesamt - die allesamt in einem einzigen Hash in Redis stecken. Und wie oben schon angemerkt: Das Ganze mal 2 Ports, mal 2 IP-Protokolle, mal 2 Monitoring-Standorte. Von diesen Trümmern im Redis haben wir also acht - und sie laufen niemals ab. Ein Haraka-Restart tut nichts zur Sache, weil die Daten im Redis stecken; ein Redis-Restart tut nichts zur Sache, weil Redis die Daten periodisch auf die Platte dumpt und bei einem Neustart auch zur Initialisierung einliest.

Plötzlich erscheint sowohl die CPU- als auch die RAM-Belastung total plausibel: Wenn bei einer eingehenden Verbindung Haraka ein Hash mit 1,3 Millionen Keys aus Redis lesen muss (RAM) und für jeden Hash-Key eine Berechnung durchführen muss, ob jener im Beobachtungszeitraum von 60m liegt (CPU) und danach vermutlich auch die Garbage Collection relativ aufwendig sein dürfte (wir konnten jedenfalls reproduzieren, dass der RAM-Bedarf eines Haraka-Prozesses erst ca. 10 Sekunden nach dem Ende der SMTP-Verbindung wieder sank), dann passt plötzlich alles ganz wunderbar zusammen.

Was tun?

Wir überlegen uns jetzt im nächsten Schritt, was wir tun werden. Die naheliegendste Möglichkeit wäre, die IPs unserer Monitoring-Hosts in der Config des limit-Plugins ausnehmen - aber das löst ja nicht das Problem, dass im Grunde auch jede andere IP-Adresse uns konstant (und in weit höherer Frequenz) mit SMTP-Requests fluten könnte und damit exakt das gleiche Problem triggern könnte. Es wäre also nur eine Teillösung, die nicht das zugrundeliegende Problem angeht. Was bleibt:

Wir könnten das Limit-Plugin entsprechend umbauen. Da Redis wie gesagt keine TTL für Hash-Keys kennt, könnte das bedeuten, die Datenstruktur ganz umzubauen, oder man müsste eine Ablauf-Logik für Hash-Keys zu implementieren.
- Entweder wir machen das selbst, wobei angesichts dessen, dass wir ja ohnehin auf Postfix wechseln werden, ein bisschen nach verschenkter Zeit aussieht
- Oder wir legen zumindest einen Bugreport beim Haraka-limit-Plugin an, um auf dieses Problem hinzuweisen, und schauen nach einer anderen Lösung:
Wir könnten das Rate-Limiting durch Haraka einfach bleiben lassen und
- auf anderem Weg realisieren, z.B. mit iptables
- oder… wir haben dann einfach keins mehr (das Rate-Limiting von Verbindungen ist schließlich nur eine Stellschraube, mit dem wir den Missbrauch unserer Ressourcen begrenzen wollen)
???

Darüber werden wir in den nächsten Tagen entscheiden. Für den Moment freuen wir uns erstmal, dass wir eine Tonne an freien Ressourcen zurückgewonnen haben, von denen uns nicht bewusst war, wofür genau wir sie “verloren” hatten - denn dafür war der Anstieg des Verbrauchs so langsam, dass wir ihn kaum mit einem konkreten Config-Setting, das zudem völlig unkritisch wirkt, in Verbindung hätten bringen können.

Foto von Ray Harrington auf Unsplash