Wege durch die NAT-Hölle - Teil 2
Nachdem der erste Fehler in CGN eingegrenzt und behoben werden konnte, treten weiter Abstürze auf. Natürlich in anderen Ausprägungen. Und so geht die Fehlersuche weiter.
unknownDebugging ist wie Zwiebeln schälen: Man entfernt vorsichtig Schicht um Schicht, um am Ende mit leeren Händen dazustehen.
Hyperoptimiert
Diese neuen Abstürze sind eher seltsam. So meldete ein Server einen Panic in einer Funktion laut Stacktrace, die diesen Code gar nicht enthält.
KDB: enter: panic libalias/alias_db.c:850 IncrementalCleanup: la (0xffffff80012f3000) != lnk->la (0xffffff8001327000) panic() at panic+0x187 HouseKeeping() at HouseKeeping+0x161 LibAliasOutLocked() at LibAliasOutLocked+0x62 LibAliasOut() at LibAliasOut+0x54
Es handelt sich um eine Compiler-Optimierung, die Code verschiebt und umsortiert. Diese wird aber nur bei höheren Optimierungsstufen aktiviert. Doch nicht im Kernel, oder? Schließlich ist eine höhere Optimierung nicht empfohlen.
# $FreeBSD: releng/8.3/sys/conf/kern.pre.mk
. if ${MACHINE_ARCH} == "amd64"
COPTFLAGS?=-O2 -frename-registers -pipe
. else
COPTFLAGS?=${_MINUS_O} -pipe
. endifAlso doch! Aber das müßte den gesamten Kernel betreffen.
Die Suche fördert die Abstürze zu Tage, die immer nur dann auftreten, während Streit um ein Mutex herrscht. Und das Mutex muß nicht in libalias liegen:
/var/crash# tar xOf textdump.tar.15 | fgrep -2 address_hook db:0:kdb.enter.default> bt Tracing pid 2437 tid 100255 td 0xffffff001df85460 ng_address_hook() at ng_address_hook+0x8e ng_ppp_link_xmit() at ng_ppp_link_xmit+0x108 ng_apply_item() at ng_apply_item+0x220 -- Tracing command mpd5 pid 2437 tid 100255 td 0xffffff001df85460 ng_address_hook() at ng_address_hook+0x8e ng_ppp_link_xmit() at ng_ppp_link_xmit+0x108 ng_apply_item() at ng_apply_item+0x220 -- _mtx_lock_sleep() at _mtx_lock_sleep+0xb0 _mtx_lock_flags() at _mtx_lock_flags+0x43 ng_address_hook() at ng_address_hook+0x42 ng_ksocket_incoming2() at ng_ksocket_incoming2+0x18e ng_apply_item() at ng_apply_item+0x320 -- _mtx_lock_sleep() at _mtx_lock_sleep+0xb0 _mtx_lock_flags() at _mtx_lock_flags+0x43 ng_address_hook() at ng_address_hook+0x42 ng_ksocket_incoming2() at ng_ksocket_incoming2+0x18e ng_apply_item() at ng_apply_item+0x320 -- _mtx_lock_sleep() at _mtx_lock_sleep+0xb0 _mtx_lock_flags() at _mtx_lock_flags+0x43 ng_address_hook() at ng_address_hook+0x42 ng_ksocket_incoming2() at ng_ksocket_incoming2+0x18e ng_apply_item() at ng_apply_item+0x320 -- _mtx_lock_sleep() at _mtx_lock_sleep+0xb0 _mtx_lock_flags() at _mtx_lock_flags+0x43 ng_address_hook() at ng_address_hook+0x42 ng_ksocket_incoming2() at ng_ksocket_incoming2+0x18e ng_apply_item() at ng_apply_item+0x320 -- _mtx_lock_sleep() at _mtx_lock_sleep+0xd7 _mtx_lock_flags() at _mtx_lock_flags+0x43 ng_address_hook() at ng_address_hook+0x42 ng_iface_send() at ng_iface_send+0xc5 ng_iface_output() at ng_iface_output+0x1b3
Ich habe probeweise auf eingen Servern die Optimierung für den libalias-Code deaktiviert und so ein neues Modul geschaffen.
Damit kann ein Fehler, der durch den optimierenden Compiler verursacht wurde, ausgeschlossen werden. Er könnte die Mutexe unter Last, auf verschiedenen CPU, ggf. im Interrupt-Handler, durch Instruction-Scheduling einer Racecondition ausgesetzt haben.
Um zumindest den Interrupt-Anteil zu minimieren, habe ich net.isr.direct=0 gesetzt. So wird NAT nicht mehr direkt im Interface-Interrupt ausgeführt. Den CPUs tut es gut. Die Last verteilt sich mehr.
Um Schwierigkeiten mit Mutexen und CPU-Switching zu vermeiden, ist zusätzlich net.isr.bindthreads=1 gesetzt.
Aber da ist ja auch noch der Compiler-Optimierer einzubremsen, und zwar im kompletten Kernel. Bisher war ja nur das Modul ohne Optimierung kompiliert.
$ env CFLAGS='-O -pipe' COPTFLAGS='-O -pipe' \
MAKEOBJDIRPREFIX=~/mykernel NO_KERNELCLEAN=yes \
KERNCONF=LNS make buildkernelWenn man Glück hat, kracht es nun an anderen Stellen. Dies bedeutet dann, daß man ein weitere Schicht der Zwiebel abgetragen hat.
Fatal trap 12: page fault while in kernel mode cpuid = 5; apic id = 13 fault virtual address = 0x58 fault code = supervisor read data, page not present instruction pointer = 0x20:0xffffffff8069c912 stack pointer = 0x28:0xffffff835f8c3800 frame pointer = 0x28:0xffffff835f8c3820 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 12913 (mpd5) rtfree() at rtfree+0x72 in_ifadownkill() at in_ifadownkill+0xb0 rn_walktree() at rn_walktree+0x7c in_ifadown() at in_ifadown+0x8b in_control() at in_control+0x956 ifioctl() at ifioctl+0x75e kern_ioctl() at kern_ioctl+0xfe ioctl() at ioctl+0xfd amd64_syscall() at amd64_syscall+0xf9 Xfast_syscall() at Xfast_syscall+0xfc <4>if_rtdel: error 3 <6>in_scrubprefix: err=65, prefix delete failed
Out of area Einsätze
Aber es sind auch alte Bekannte dabei:
KDB: enter: panic libalias/alias_db.c:850 IncrementalCleanup: la (0xffffff8001288000) != lnk->la (0x2000000008)
KDB: enter: panic libalias/alias_db.c:850 IncrementalCleanup: la (0xffffff80014aa000) != lnk->la (0x2000000008)
Dieser Fehler ist wirklich interessant. Er deutet darauf hin, daß der Kernel – anderwo – den Speicher überschreibt.
Darüberhinaus ist es bedenkenswert, in diesem Fall aufzuräumen anstatt abzustürzen. Die Gefahr, ein Memory-Leak zu produzieren, ist groß, allerdings tritt der Fehler nur alle paar Tage einmal auf. Beim Absturz gegen die aktuellen NAT-Tabellen sowieso verloren, vom Wegwerfen wird der Schaden also nicht größer.
Es besteht natürlich die Gefahr, daß kein kleiner Fehler vorliegt, sondern ganze RAM-Bereiche vernichtet worden. In diesem Fall wäre der erste Fehler nur der Anfang einer heftigen Kaskade. Es ist also sinnvoll, den Fehler nur begrenzt oft zu ignorieren.
#define VALID_PTR_MASK 0xff00000000000000lu
#define VALID_PTR(p) ((((uint64_t)p)&VALID_PTR_MASK) == VALID_PTR_MASK)
#define CHECK_LNK(la, lnk, i, abortcmd) do { \
if(!VALID_PTR(lnk)) { \
_broken_lnk(la, lnk, i, "lnk", __FILE__, __LINE__, __FUNCTION__); \
lnk = NULL; \
abortcmd; \
} \
if(!VALID_PTR(lnk->la)) { \
_broken_lnk(la, lnk->la, i, "lnk->la", __FILE__, __LINE__, __FUNCTION__);\
lnk = NULL; \
abortcmd; \
} \
KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p) @%d\n", \
__FILE__, __LINE__, __FUNCTION__, la, lnk->la, i)); \
} while(0)
static void _broken_lnk(struct libalias *la, void * p, int i, char const * prt, char const * file, int line, char const * func);
static int _broken_retry_count = 0;
static void _broken_lnk(struct libalias *la, void * p, int i, char const * ptr, char const * file, int line, char const * func) {
if(_broken_retry_count >= 10) /* No mercy */
panic("%s:%d %s: %s=%p is invalid @%d\n", file, line, func, ptr, p, i);
printf("%s:%d %s: %s=%p is invalid @%d\n", file, line, func, ptr, p, i);
printf("%d. retry to throw away broken NAT tables (will leak memory)\n", ++_broken_retry_count);
LIBALIAS_LOCK_ASSERT(la);
for (i = 0; i < LINK_TABLE_OUT_SIZE; i++)
LIST_INIT(&la->linkTableOut[i]);
for (i = 0; i < LINK_TABLE_IN_SIZE; i++)
LIST_INIT(&la->linkTableIn[i]);
}Und dann im Code überall die struct alias_link Zeiger vor jeder Verwendung an CHECK_LNK verfüttern.
Ja, der Code ist häßlich. Besonders die Prüfung mit einer Maskierung. Aber alle Abstürze in _FindLinkOut haben inzwischen Adressen, die nicht mehr dem Testmuster entsprechen. Man müßte eigentlich mit mincore den Zeiger prüfen, aber diese Funktion ist ein richtiger Performancekiller.
Es dauert nun wieder einige Tage, bis diese neue Version durch die zufälligen Reboots ausgerollt ist. Erst wenn diese Versionen wieder abstürzen, gibt es weitere Ergebnisse.
KDB: enter: panic libalias/alias_db.c:850 IncrementalCleanup: la (0xffffff800133e000) != lnk->la (0x4800000008) @3545
KDB: enter: panic libalias/alias_db.c:850 IncrementalCleanup: la (0xffffff80013da000) != lnk->la (0x200000002) @918
Oh, damit ist eine weitere Vermutung widerlegt: Die Hashfunktion ist in Ordnung. Es bestand eine gewisse Chance, daß ein negativer Wert als Ergebnis der Hashberechnung entsteht. Ebenfalls möglich wäre ein Off-by-one Error an den Grenzen des Wertebreichs gewesen. Aber dies liegt ganz offensichtlich nicht vor.
Einige Tage später hat die Methode nun tatsächlich Wirkung gezeigt: Zumindest ein Absturz wurde verhindert.
Plötzlich (fast) stabil
Nachdem ein Kunde vom Netz genommen wurde, der selbst CGN machte, treten die Abstürze in der libalias nicht mehr auf. Aktuell ist es nur eine Korrelation, aber man darf hoffen.
Es ist gut möglich, daß die Fehler von einer überproportional hohen Anzahl von Verbindungen mit dem gleichen Quellport und der gleichen Quelladresse verursacht wurden. Die Libalias könnte also in der Hinsicht nicht streßfest sein.
Weitersuchen
Achja, um das auch auszuschließen: Die Systeme haben ECC-RAM. Speicherfehler als Ursache waren eigentlich schon dadurch praktisch unmöglich, weil immer an der gleichen Stelle auf unterschiedlichsten Systemen das Problem auftritt. Es hat nur nach wie vor keine erkennbare Ursache. Andererseits hat die detailierte und geduldige Untersuchung schon einen Fehler in den Firewallregeln aufgedeckt. Es ist also nicht hoffnungslos.
Die ganz gemeine Methode ist radikal upzudaten. Das ist aber ein anderes Thema. Dennoch ist die Überlegung interessant, da es unter den FreeBSD Entwicklern Hinweise darauf gibt, daß es beim schnellen Löschen von Interfaces zum use-after-free im Kernelspeicher kommen kann.
Da ich nicht einfach upgraden kann, variiere ich die Geschwindigkeiten von 20ms bis 120ms in gleichmäßigen Schritten. Jeder LNS hat nun eine andere Verarbeitungsgeschwindigkeit für Ereignisse. Mal sehen, wie sich das auswirkt, wenn nachts die Massen wieder "die Zwansgtrennung vorziehen.
Die Ergebnisse sind sparsam: Die Kiste mit 20ms hat zwei Abstürze mehr als die Kiste mit 120ms. Nun laufen alle Kiste auf 100ms Delay.
Auffällig ist, daß inzwischen immer der gleiche Wert als falscher Pointer auftritt. Möglicherweise läßt sich der überschreibende Prozeß anhand des überschriebenden Umfeldes eingrenzen. Dazu wird der Code abgeändert, um einen Hexdump der struct alias_link zu erhalten.
#define CHECK_LNK(la, lnk, i, abortcmd) do { \
if(!VALID_PTR(lnk)) { \
_broken_lnk(la, lnk, i, "lnk", __FILE__, __LINE__, __FUNCTION__); \
lnk = NULL; \
abortcmd; \
} \
if(!VALID_PTR(lnk->la)) { \
hexdump(lnk, sizeof(*lnk), "lnk", 0); \
_broken_lnk(la, lnk->la, i, "lnk->la", __FILE__, __LINE__, __FUNCTION__);\
lnk = NULL; \
abortcmd; \
} \
KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p) @%d\n", \
__FILE__, __LINE__, __FUNCTION__, la, lnk->la, i)); \
} while(0)Und das gibt tatsächlich Ergebnisse. Ein Absturz der mit querverlinkten Einträgen:
[... kein Dump ...] libalias/alias_db.c:884 IncrementalCleanup: la (0xffffff80014d6000) != lnk->la (0xffffff800136a000) @2061
Ein Absturz der mit falschen Zeiger und Aufräumcode, der aber nicht hilft:
lnk0000 01 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0050 00 00 00 00 00 00 00 00 ff ff ff ff 00 00 00 00 |................| lnk0060 00 00 00 00 00 00 00 00 |........ | alias_db.c:886 IncrementalCleanup: lnk->la=0x100000001 is invalid @3064 1. retry to throw away broken NAT tables (will leak memory) Fatal trap 12: page fault while in kernel mode cpuid = 4; apic id = 12 fault virtual address = 0x34 fault code = supervisor read data, page not present instruction pointer = 0x20:0xffffffff80f6e0d8 stack pointer = 0x28:0xffffff835f81f360 frame pointer = 0x28:0xffffff835f81f3c0 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 12 (swi1: netisr 4)
Ein Absturz der mit falschen Zeiger und Aufräumcode, der diesmal hilft:
lnk0000 08 00 00 00 20 00 00 00 04 00 00 00 01 00 00 00 |.... ...........| lnk0010 ec ca 4a 01 03 f6 14 38 63 6d 64 34 00 00 00 00 |..J....8cmd4....| lnk0020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0030 00 00 00 00 00 00 00 00 6f 01 00 00 fb 24 00 00 |........o....$..| lnk0040 6a 01 00 00 dc 24 00 00 00 00 00 00 00 00 00 00 |j....$..........| lnk0050 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| lnk0060 00 00 00 00 00 00 00 00 |........ | alias_db.c:1260 _FindLinkIn: lnk->la=0x2000000008 is invalid @2910 1. retry to throw away broken NAT tables (will leak memory) [... läuft noch stundenlang weiter ...]
Insgesamt wird beim Aufräumen tatsächlich die Betriebsfähigkeit des Systems erhalten. Drei bis vier Aufräumversuche überlebt eine Maschine, bevor sie entgültig rebootet. Und die Vorfälle liegen immer noch bei ca. ein Vorfall pro Tag bei einem LNS statt der gesamten Plattform.
Die Fehler treten vorzugsweise an Maschinen auf, die nicht nur CGN und PPP/ADSL und dafür machen, sondern auch CGN für DHCP/VDSL. Es ist also möglich, daß ein Fehler mit hohen Verbindungsanzahlen pro Souce-IP und Port bedingt wird.
Welches CMD?
Mittlerweile ist der letzte Hexdump das absolut vorherrschende Phänomen der noch korrigierbaren Fehler geworden.
Aber was zu Hölle sucht ein "cmd" Text mitten in einem NAT-Eintrag? Welcher Prozess konnte es sein, der diesen String hinterlies? Welcher Prozess könnte einen Datensatz generiert, der diesen Text enthält? Könnte das geschehen nachdem ein Interface nicht mehr existiert, so daß ein "use-after-free" tatsächlich zur Wirkung kommt?
Die Suche im Kernelcode findet diesen String ausschließlich im Parser von NetGraph Nachrichten. Und NetGraph Nachrichten werden vom MPD generiert. Und die sollen zu spät kommen? Ich hatte doch die Eventverarbeitung extra verlangsamt, um die Abstürze in den Griff zu bekommen! Na dann setze ich die doch mal wieder ganz runter: Von 0 bis 10ms.
Das Beschleunigen der Eventverarbeitung hat das Problem nur verschärft: Es sind wieder 100ms aktiv. Das war's also auch nicht.
Aber der Memorydump stammt tatsächlich von einer NetGraph Nachricht:
struct ng_mesg {
struct ng_msghdr {
u_char version; /* 08 ... NGM_VERSION */
u_char spare; /* 00 ... pad */
u_int16_t spare2; /* 00 00 ... pad */
u_int32_t arglen; /* 0x00000020 ... length of data */
u_int32_t cmd; /* 0x00000004 ... NGM_NAME */
u_int32_t flags; /* 0x00000001 ... NGF_RESP */
u_int32_t token; /* ec ca 4a 01 ... Token für den MPD */
u_int32_t typecookie; /* 03 f6 14 38 ... NGM_PPP_COOKIE */
u_char cmdstr[NG_CMDSTRSIZ]; /* "com4" */
} header;
char data[]; /* 6f 01 00 ... */
};Speicher, mein Speicher
Es ist für die Stabilität des Systems zwingend notwendig, die Abstürze durch Memory-Corruption zu verhindern. Das ist aber ein anderes Thema.
Nachtrag
Mit dem Verzicht auf das Löschen von Interface-Knoten konnten die Fehler bisher vollständig beseitigt werden.