www.fabiankeil.de/blog-surrogat/2021/03/14/website-ausfall-durch-mbuf-cluster-limit.html

Website-Ausfall durch mbuf-cluster-Limit

Gestern war der Server, der diese Website hostet, für etwas mehr als eine Stunde nicht über das Netzwerk ansprechbar. Auf dem Server läuft ElectroBSD 11.4-STABLE.

Zuerst aufgefallen ist mir das Problem, weil Privoxy einen Fehler meldete als eine Anfrage per Socks5 über OpenSSH weitergeleitet werden sollte. Die ssh-Session war getrennt worden und ließ sich nicht neu aufbauen. ping-Pakete wurden nicht beantwortet.

Als das System nach über vierzig Minuten weiterhin nicht ansprechbar war habe ich es über einen Power-Cycle neu gestartet. Leider habe ich derzeit keinen direkten Zugriff auf die System-Konsole.

kernel: [zone: mbuf_cluster] kern.ipc.nmbclusters limit reached

Die letzten dmesg-Meldungen des Systems gefolgt von den ersten Meldungen nach dem Neustart:

Mar 13 14:15:54 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (197 occurrences)
Mar 13 14:16:40 elektrobier kernel: Limiting open port RST response from 211 to 200 packets/sec
Mar 13 14:16:41 elektrobier kernel: Limiting open port RST response from 270 to 200 packets/sec
Mar 13 14:16:42 elektrobier kernel: Limiting open port RST response from 335 to 200 packets/sec
Mar 13 14:16:43 elektrobier kernel: Limiting open port RST response from 392 to 200 packets/sec
Mar 13 14:16:43 elektrobier kernel: Limiting open port RST response from 384 to 200 packets/sec
Mar 13 14:16:44 elektrobier kernel: Limiting open port RST response from 404 to 200 packets/sec
Mar 13 14:16:45 elektrobier kernel: Limiting open port RST response from 281 to 200 packets/sec
Mar 13 14:16:54 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (973 occurrences)
Mar 13 14:17:55 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (175 occurrences)
Mar 13 14:18:55 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (229 occurrences)
Mar 13 14:19:55 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (188 occurrences)
Mar 13 14:20:14 elektrobier kernel: [zone: mbuf_cluster] kern.ipc.nmbclusters limit reached
Mar 13 14:22:47 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (68 occurrences)
Mar 13 14:25:14 elektrobier kernel: [zone: mbuf_cluster] kern.ipc.nmbclusters limit reached
Mar 13 14:30:14 elektrobier syslogd: last message repeated 1 times
Mar 13 14:35:14 elektrobier syslogd: last message repeated 1 times
Mar 13 14:39:51 elektrobier kernel: sonewconn: pcb 0xfffff8010d0a8000: Listen queue overflow: 193 already in queue awaiting acceptance (1 occurrences)
Mar 13 14:39:53 elektrobier kernel: Limiting open port RST response from 207 to 200 packets/sec
Mar 13 14:39:54 elektrobier kernel: Limiting open port RST response from 250 to 200 packets/sec
Mar 13 14:40:14 elektrobier kernel: [zone: mbuf_cluster] kern.ipc.nmbclusters limit reached
Mar 13 14:45:14 elektrobier syslogd: last message repeated 1 times
Mar 13 14:50:14 elektrobier syslogd: last message repeated 1 times
Mar 13 15:00:14 elektrobier syslogd: last message repeated 2 times
Mar 13 15:10:14 elektrobier syslogd: last message repeated 2 times
Mar 13 15:20:15 elektrobier syslogd: last message repeated 2 times
Mar 13 15:30:15 elektrobier syslogd: last message repeated 2 times
Mar 13 15:37:50 elektrobier syslogd: kernel boot file is /boot/kernel/kernel
Mar 13 15:37:50 elektrobier kernel: Copyright (c) 2010-2020 Fabian Keil - IT-Beratung und Polizei-Erziehung
Mar 13 15:37:50 elektrobier kernel: Copyright (c) 1992-2020 The FreeBSD Project.

Die mbuf_cluster-Meldungen kamen mir bekannt vor, in der September-Mitte 2020 gab es einen ähnlichen Ausfall. Damals habe ich nur das Betriebssystem aktualisiert und mir vorgenommen, das Problem im Auge zu behalten ...

Nach Durchsicht meiner Server-Notizen ist mir allerdings aufgefallen, dass das Problem auch im Oktober 2017 schon mal auftrat. Auch 2017 habe ich die Software aktualisiert und das Problem dann vergessen – offensichtlich eine optimierbare Strategie.

Swappender Tor-Process

Auf dem System laufen zwei Tor-Relays in Jails, im Log des Relays polizeierziehung fällt auf, dass bereits einige Zeit vor dem Ausfall keine Verbindungen auf dem Control-Port gemeldet wurden:

Mar 13 13:40:15.836 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 13:40:16.037 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 13:45:15.829 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 13:45:16.015 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 13:50:15.887 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 13:50:16.078 [notice] {CONTROL} New control connection opened from 127.0.1.5.
Mar 13 15:40:54.270 [notice] Tor 0.4.5.2-alpha opening log file.

Die Verbindungen werden normalerweise von einem Munin-Plugin ausgelöst. Wenig überraschend gab es im Munin-Log zu den fehlenden Verbindungen passende Fehlermeldungen:

2021/03/13-13:57:27 [75547] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-13:58:29 [75547] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:01:42 [34922] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:02:44 [34922] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:06:28 [64477] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:07:30 [64477] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:12:05 [85185] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:13:07 [85185] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:17:26 [37961] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.
2021/03/13-14:18:28 [37961] Service 'tor-bandwidth-usage-polizei-erziehung' timed out.

Bevor die Netzwerk-Verbindungen abbrachen fing das System an, stärker als üblich zu swappen:

Munin-Graph vom Plugin swap-day.png Munin-Graph vom Plugin memory-day.png

Laut PF ging die Anzahl der eingehenden Pakete nach unten aber wahrscheinlich wurden die Pakete einfach nicht mehr an PF weiter geleitet:

Munin-Graph vom Plugin pf_ipv4_ipv6_packets-day.png Munin-Graph vom Plugin pf-day.png

Die Anzahl der verwendeten File-Descriptors hat sich laut Munin nicht merklich verändert:

Munin-Graph vom Plugin procstat_file_descriptor_count_tor_polizei_erziehung-day.png Munin-Graph vom Plugin open_files-day.png

Die Last ging nach unten aber die Munin-Processing-Zeit ging nach oben, mutmaßlich wegen der fehlschlagenden Verbindungen:

Munin-Graph vom Plugin cpu-day.png Munin-Graph vom Plugin load-day.png Munin-Graph vom Plugin munin_stats-day.png

Spekulation über die Problem-Ursache

Ich vermute, dass das Tor-Relay polizeierziehung wegen dem Swappen nicht mehr mit der Verarbeitung der eingehenden Pakete hinterherkam und der Kernel daher immer mehr mbuf-Cluster benötigte bis das Limit erreicht war.

Als erste Stellschraube habe ich daher die Tor-Konfigurations-Direktive MaxMemInQueues auf 300 MB gesetzt, da das automatische Tuning offensichtlich einen für das System zu hohen Wert wählt. Das Tor-Relay elektrobier1 hatte bereits ein Limit gesetzt.

Der Speicherbedarf ging wie erwartet deutlich nach unten:

Munin-Graph vom Plugin ps_memory_usage_tor_polizei_erziehung-day.png

Es sieht so aus, als hätte das Limit keinen deutlichen Einfluss auf die verwendete Bandbreite:

Munin-Graph vom Plugin if_bge0-day.png Munin-Graph vom Plugin if_packets_bge0-day.png Munin-Graph vom Plugin tor_bandwidth_usage_polizei_erziehung-day.png

Zusätzlich habe ich ein Munin-Plugin installiert, um die mbuf-Werte im Auge zu behalten:

Munin-Graph vom Plugin netmem_clusters-day.png

Vorerst werde ich das automatisch von Kernel gesetzte kern.ipc.nmbclusters-Limit von 247424 nicht verändern.

Wegen der Listen queue overflow-Meldungen habe ich die kern.ipc.soacceptqueue-sysctl von 128 auf 4096 gesetzt, gehe aber davon aus, dass die Meldungen unabhängig von dem eigentlichen Problem aufgetreten sind.

Suboptimales System-Verhalten

Ich finde es fragwürdig, dass das System nach dem Erreichen des nmbclusters-Limit nicht mehr über das Netzwerk erreichbar war. Soviel zur von FreeBSD geerbten Power to serve.

Wenn ich den Code richtig lese, soll der uma-Slab-Allocator beim Erreichen des Limits mb_reclaim() aufrufen. Die Funktion ruft dann ein paar Protokoll-Spezifische Drain-Routinen auf, die das Problem aber offensichtlich nicht in den Griff bekamen.

Es wäre außerdem schön, wenn man für wichtige Verbindungen ein anderes Limit setzen könnte. Zum Beispiel würde ich gerne für alle Jails ein niedrigeres Limit als für den Host setzen, damit ssh-Verbindungen zum Host weiterhin möglich sind.

Falls das Problem nicht erneut auftreten sollte werde ich den Code aber wohl nicht anpassen.