Carrier Grade NAT, also NAT auf Providerseite, hat besondere Anforderungen an die Technik. Eine Lösung mit OpenSource auf Basis von FreeBSD stößt dabei schnell an erstaunliche Grenzen.
Seltsame Reboots
Nach Inbetriebnahme einer neuen LNS-Plattform, bootete sporadisch einer der Server in der LNS Farm neu. Dabei wurden die gerade auf diesem LNS angemeldeten Kunden getrennt.
Wenn das System abstürzt und nicht von allein rebootet, steht der Absturzbericht auf der Konsole. Teile davon gelangen manchmal auch ins Logfile. Typischerweise schaut das dann so aus:
Was mag das sein?
Die erste Vermutung lautet, daß irgendein Kundensystem irgend etwas "falsch" macht: Es könnte so ungewöhnliche Daten schicken, daß der Kernel die Hufe reißt. Dafür lassen sich aber keine Korrelationen finden: Die Kunden die regelmäßig zum Absturzzeitpunkt online sind, sind die, die häufig Ihre Verbindung neu aufbauen und so mit hoher Wahrscheinlichkeit auf dem betreffenden System landen.
Eine kurzer Blick in die Kernelquellen offenbart, daß dort aber auch nicht alles ganz koscher ist. Es werden Locks getestet, bevor die Zeiger auf die Locks überhaupt initialisiert sind. Ein Bugreport für diesen offenkundigen Fehler löste mir aber auch nicht das Problem.
Was kann es noch sein? Vielleicht einige der Protokolle, die die neue Plattform mehr unterstützt? Schalten wir doch auf einem Server mal VanJacobsen Compression in IPCP und IPV6CP Aushandlung komplett ab. Die anderen Server bleiben, wie sie sind.
Es ist keine signifikante Änderung zu erkennen. Das war es wohl nicht.
Es gab noch Überreste des Umbaus beim Plattformwechsel, schließlich wurden beide System einige Zeit parallel betrieben. Vielleicht kommen die Fehler aus dieser doch hinreichend umständlichen Topologie. Wieder kein Erfolg.
Etwas Systematik
Zuerst einmal müssen Fakten her. Dazu werden Crashdumps ativiert.
Alle beobachtbaren Abstürze finden im Netzkartentreiber statt. Nun werden alle Maschinen also in Zukunft primär die andere Netzkartenart benutzen (em statt igb). Außerdem ist bei em-Karten die Systemlast niedriger. Darüberhinaus lassen sich die em-Karten bei Bedarf von Interrupt in Pollingmodus versetzen. Das wäre der nächste Schritt.
Aber auch das hilft nichts. Die Fehler treten alle paar Tage wieder und wieder auf: Quer über den Maschinenpark, aber immer im libalias Code. Es steht also wieder mal die Vermutung im Raum, daß dieser Fehler von einem Datenpaket, nicht von einer PPP-Anmeldung verursacht wird.
Hier mal ein Crashdump mit Verbindung zum Sourcecode:
#6 0xffffffff80fa2829 in _FindLinkOut (la=0xffffff8001436000, src_addr=
{s_addr = 403271268}, dst_addr={s_addr = 4143199550}, src_port=17143,
dst_port=59294, link_type=17, replace_partial_links=1)
at /usr/src/sys/netinet/libalias/alias_db.c:1111
LIBALIAS_LOCK_ASSERT(la);
i = StartPointOut(src_addr, dst_addr, src_port, dst_port, link_type);
-> LIST_FOREACH(lnk, &la->linkTableOut[i], list_out) {
if (lnk->dst_addr.s_addr == dst_addr.s_addr &&
lnk->src_addr.s_addr == src_addr.s_addr &&
lnk->src_port == src_port &&
lnk->dst_port == dst_port &&
lnk->link_type == link_type &&
lnk->server == NULL) {
lnk->timestamp = la->timeStamp;
break;
}
} Sehr seltsam. Warum sollte ein solcher Code abstürzen? Das Lock ist gesetzt (und validiert). Die Datenstrukturen sind einfach und enthalten eigene Kopien der Originaldaten. Dafür gibt es keine logische Erklärung.
Abstürzende Abstürze
Wieder ist ein Server abgestürzt. Er hat aber nicht rebootet, sondern ist beim Anlegen des Absturzberichtes hängen geblieben. Remote wurde die Maschine rebootet. Der eigentliche Grund liegt an der gleichen Stelle: FindLinkOut in libalias.
Warum kein Crashdump? Stehen geblieben ist er beim Schreiben des Crashdumps auf die Platte. Die schnelle Lösung ist, per crontab nachts die Crashdumps abzuschalten. Dann bleibt nur auf das Glück zu hoffen und einen hängen bleibenden Crashdump live zu erleben.
Dumping xx out of yy MB: 1% … 11% ... 21% carp1: BACKUP -> MASTER
Was zur Hölle macht der carp Code da? Wir sind im Shutdown!
Ein Blick in den Kernelcode zeigt, daß die Interrupt-Verarbeitung und damit ein Teil des Kernelcodes aktiviert bleibt. Dies tut er, damit er überhaupt auf die Platte schreiben kann. Aber offenbar dauert das Schreiben zu lange.
Die Probleme, die beim Erstellen von Crashdumps auftreten, liegen also darin begründet, daß für die Erzeugung der Crashdumps ein Teil der Betriebssystemfunktionalität vorhanden sein muß. Diese ist aber schon zum Teil abgeschaltet. Damit kann es vorkommen, daß der Überrest des Systems einen Deadlock generiert, z.B. weil kein Kernelthread mehr da ist, der ihn auflösen kann.
Kann man schneller Dumpen? Ja, mit textdumps. Auch hier ist wieder ein neuer Kernel fällig, aber der lohnt sich wirklich. Denn nun schreibt er die Crashdumps zuverlässig und bootet auch danach korrekt.
Nach einiger Zeit bleibt wieder ein Crash hängen: Er steht im Kerneldebugger. Wieso das?
Der Kernel hatte keine panic, sondern einen Page Fault ausgelöst. Und ddb hat pro möglichem Event einen Handler, an den Scripte gebunden werden können. Defaultmäßig liefert FreeBSD eine ddb.conf aus, die nur kernel.enter.panic belegt.
# /etc/ddb.conf
script kdb.enter.default=textdump set; capture on; show pcpu; bt; ps; alltrace; capture off; call doadump; reset
Nachdem nun alle Events abgefangen werden, ist klappt das mit den Crashdumps endlich wie gewünscht. Ein ernsthaftes Debugging ist nun erstmals möglich.
Spurensuche
Immer und immer wieder treten diese Art von Fehlern auf:
#7 0xffffffff80fa0cf1 in DeleteLink (lnk=0xffffff018feab700)
at /usr/src/sys/netinet/libalias/alias_db.c:859
#8 0xffffffff80fa0f01 in HouseKeeping (la=0xffffff80011fa000)
at /usr/src/sys/netinet/libalias/alias_db.c:849
Vielleicht klappt das mit dem Locking im NAT-Code nicht richtig? Vielleicht wurde der Fehler inzwischen behoben?
Ein Vergleich des Sourcecodes des für NAT zuständigen libalias Moduls zwischen der eingesetzten Version 8.3-RELEASE und der aktuellen Entwicklerversion HEAD ergibt, daß eigentlich nur die SVN Änderung 241648 dazu gekommen ist. Diese wird eingespielt, aber bringt keine Besserung.
Der Fehler wurde offenbar auch anderswo noch nicht gefunden, i.d.R. wird darauf verwiesen, daß der RAM defekt sei. Dies ist aber inzwischen sehr unwahrscheinlich. Es können nicht alle Systeme gleichartig kaputt sein.
Ist das Locking defekt? Wenn ja, dann müßte doch LIBALIAS_LOCK_ASSERT sich melden. Wieder zeigt ein Blick in den Source, wie irregeleitet eine solche Annahme sein kann:
* $FreeBSD: releng/8.3/sys/netinet/libalias/alias_local.h
#ifdef _KERNEL
#define LIBALIAS_LOCK_INIT(l) \
mtx_init(&l->mutex, "per-instance libalias mutex", NULL, MTX_DEF)
#define LIBALIAS_LOCK_ASSERT(l) mtx_assert(&l->mutex, MA_OWNED)
#define LIBALIAS_LOCK(l) mtx_lock(&l->mutex)
#define LIBALIAS_UNLOCK(l) mtx_unlock(&l->mutex)
#define LIBALIAS_LOCK_DESTROY(l) mtx_destroy(&l->mutex)
#else
#define LIBALIAS_LOCK_INIT(l)
#define LIBALIAS_LOCK_ASSERT(l)
#define LIBALIAS_LOCK(l)
#define LIBALIAS_UNLOCK(l)
#define LIBALIAS_LOCK_DESTROY(l)
#endif
Schaut doch gut aus, oder?
* $FreeBSD: releng/8.3/sys/sys/mutex.h
/*
* The INVARIANTS-enabled mtx_assert() functionality.
*
* The constants need to be defined for INVARIANT_SUPPORT infrastructure
* support as _mtx_assert() itself uses them and the latter implies that
* _mtx_assert() must build.
*/
#if defined(INVARIANTS) || defined(INVARIANT_SUPPORT)
#define MA_OWNED LA_XLOCKED
#define MA_NOTOWNED LA_UNLOCKED
#define MA_RECURSED LA_RECURSED
#define MA_NOTRECURSED LA_NOTRECURSED
#endif
#ifdef INVARIANTS
#define mtx_assert(m, what) \
_mtx_assert((m), (what), __FILE__, __LINE__)
#define GIANT_REQUIRED mtx_assert(&Giant, MA_OWNED)
#else /* INVARIANTS */
#define mtx_assert(m, what) (void)0
#define GIANT_REQUIRED
#endif /* INVARIANTS */
Der gesamte Code wird schon vom Präprozessor entsorgt! Na zum Glück kann man das libalias-Modul separat kompilieren und einbinden.
Oh, nein! Die Basisfunktionalität "INVARIANT_SUPPORT" ist nicht im Standardkernel eingebunden. Also wieder mal einen komplett neuen Kernel!
Mit einem neuen Kernel kann man ja mal schon präventiv Polling aktivieren. Aber das war ein extra Schuß in den Ofen.
Folge dem Lock
Nun ist also im betroffenen NAT Modul der Überwachungscode für Locking aktiviert. Wenn die Abstütze mit fehlerhaftem Locking zusammen hängen, sollten sie damit gefunden werden.
Alternativ kann es sein, daß NAT aufgrund einer bestimmten Protokollbenutzung eines Kunden durcheinander kommt. Dies kann ein defekter NAT-Helper sein, der auf bestimmte Protokollverletzungen nicht korrekt reagiert und dabei die Verwaltungsdaten zerstört.
Und tatsächlich gibt starke Hinweise auf ein Lockingproblem:
KDB: enter: panic mutex per-instance libalias mutex not owned
at .../libalias/alias_db.c:861
Es ist nicht klar, ob die Lockingprobleme durch die Interruptsynchronisation auf mehreren CPUs kommt, oder durch einen NAT Helper, der die falsche Tabelle anfaßt.
Es wurde ein neues NAT-Modul erstellt, das einige Vermutungen belegen oder widerlegen soll:
- Wenn die internen Rücklinks der NAT Einträge auf die Verwaltungsstruktur nicht stimmen, wird das System mit einem panic anhalten und Details melden.
- Bevor internen Verwaltungsstrukturen entsorgt werden, werden diese mit einem wiedererkennbaren Bitmuster ECECEC... überschrieben. Damit ist eine spätere Verwendung von bereits freigegebenen Speicherbereichen erkennbar.
--- bsd-head/sys/netinet/libalias/alias_db.c 2013-05-09 14:25:35.000000000 +0200
+++ 8.3/sys/netinet/libalias/alias_db.c 2013-05-20 22:36:07.125123000 +0200
@@ -828,6 +828,8 @@
lnk = LIST_FIRST(&la->linkTableOut[i]);
while (lnk != NULL) {
struct alias_link *link_next = LIST_NEXT(lnk, list_out);
+
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
DeleteLink(lnk);
lnk = link_next;
}
@@ -845,6 +847,7 @@
LIBALIAS_LOCK_ASSERT(la);
LIST_FOREACH_SAFE(lnk, &la->linkTableOut[la->cleanupIndex++],
list_out, lnk_tmp) {
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
if (la->timeStamp - lnk->timestamp > lnk->expire_time)
DeleteLink(lnk);
}
@@ -875,6 +878,7 @@
head = curr = lnk->server;
do {
next = curr->next;
+ memset(curr, 0xEC, sizeof(*curr)); /* detect double free */
free(curr);
} while ((curr = next) != head);
}
@@ -921,6 +925,7 @@
}
/* Free memory */
+ memset(lnk, 0xEC, sizeof(*lnk)); /* detect double free */
free(lnk);
/* Write statistics, if logging enabled */
@@ -994,6 +999,7 @@
/* Determine alias port */
if (GetNewPort(la, lnk, alias_port_param) != 0) {
+ memset(lnk, 0xEC, sizeof(*lnk)); /* detect double free */
free(lnk);
return (NULL);
}
@@ -1026,6 +1032,7 @@
fprintf(stderr, "PacketAlias/AddLink: ");
fprintf(stderr, " cannot allocate auxiliary TCP data\n");
#endif
+ memset(lnk, 0xEC, sizeof(*lnk)); /* detect double free */
free(lnk);
return (NULL);
}
@@ -1135,6 +1142,7 @@
link_type, 0);
}
if (lnk != NULL) {
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
lnk = ReLink(lnk,
src_addr, dst_addr, lnk->alias_addr,
src_port, dst_port, lnk->alias_port,
@@ -1268,6 +1276,7 @@
struct in_addr src_addr;
u_short src_port;
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
if (lnk->server != NULL) { /* LSNAT link */
src_addr = lnk->server->addr;
src_port = lnk->server->port;
@@ -2097,6 +2106,9 @@
void
SetExpire(struct alias_link *lnk, int expire)
{
+ struct libalias *la = lnk->la;
+
+ LIBALIAS_LOCK_ASSERT(la);
if (expire == 0) {
lnk->flags &= ~LINK_PERMANENT;
DeleteLink(lnk);
@@ -2141,6 +2153,7 @@
LIBALIAS_LOCK_ASSERT(la);
la->deleteAllLinks = 1;
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
ReLink(lnk, lnk->src_addr, lnk->dst_addr, lnk->alias_addr,
lnk->src_port, cid, lnk->alias_port, lnk->link_type);
la->deleteAllLinks = 0;
@@ -2432,6 +2446,7 @@
LIBALIAS_LOCK(la);
la->deleteAllLinks = 1;
+ KASSERT(la == lnk->la, ("%s:%d %s: la (%p) != lnk->la (%p)\n", __FILE__, __LINE__, __FUNCTION__, la, lnk->la));
DeleteLink(lnk);
la->deleteAllLinks = 0;
LIBALIAS_UNLOCK(la);
@@ -2570,6 +2586,7 @@
LIST_REMOVE(la, instancelist);
LIBALIAS_UNLOCK(la);
LIBALIAS_LOCK_DESTROY(la);
+ memset(la, 0xEC, sizeof(*la)); /* detect double free */
free(la);
}Ungereimtheiten
Es fällt auf, daß die Abstürze einige Zeit nach dem schnellen Verlust von Sessions auf einem Server auftreten, d.h. vor allem Nachts bei den (kundenseitig initierten) Trennungen bzw. nachdem ein Teil der Sessions getrennt wurden.
So besteht die Vermutung, daß beim Entfernen von Interfaces auch IP Adressen und damit zusammenhängende Daten im Kernel entfernt werden. Ein Teil der Daten wird auch von der NAT-Funktionalität nochmal verwaltet. Es ist möglich, daß die NAT-Bibliothek nicht ordnungsgemäß über das Wegräumen von Daten informiert wird, die sie ebenfalls verwaltet. Dadurch greift die NAT-Bibliothek auf eigentlich nicht mehr existente Speicherbereiche zu, die zufällig noch eine Weile die richtigen Daten enthalten. Irgendwann werden diese Speicherbereiche aber überschrieben und spätestens dann kommt es zum Absturz.
Eine solche Vermutung ist zu prüfen. Dazu ist der Kernelcode für das Entfernen von Interfaces zu sichten. Die Hoffnung besteht darin, eine Stelle zu finden, die auf die Vermutung paßt. Dies würde eine Fehlerbehebung gestatten.
Alternative Umgehungsmöglichkeit: Da die Abstürze fast ausschließlich im NAT-Code auftreten und damit den NAT-tenden Server zum Reboot zwingen, kann der Schaden für die Endkunden eingeschränkt werden. Dazu kann man die NAT und die LNS (Terminierung der PPP Verbindungen) Funktionalität trennen. Wenn nun der NAT Server abstürzt, übernimmt die Funktion ein gleichartiger NAT-Server.
Andere Server bilden ausschließlich den LNS, also die PPP-Terminierung ab. Diese wären von den NAT-Ausfällen nicht betroffen: Die Kunden würden also online bleiben. Für dieses Setup ist es notwendig, mit weitere Maschinen zu arbeiten, die Funktionscluster bilden.
Bevor aber für einen solchen Umbau Hardware beschafft beschafft wird, ist es notwendig, Die Vermutung zu untersetzen oder zu widerlegen. Und dazu muß das mit INVARIANTS kompilierte Modul ansprechen. Und mit etwas Glück liefert es einen Beleg, ob ein Use-After-Free Fehler vorliegt.
Es dauert aber erstmal Tage, bis alle Systeme den neuen Kernel mit dem "Fehlersuch-Modul" durch die zufälligen Reboots geladen haben. Neue Erkenntnisse sind bis dahin nicht aufgetreten: Wie immer sind die Abstürze im libalias-Code.
In der Zwischenzeit hat intensives Codestudium doch einige Erkenntisse gebracht:
- An besonderen Protokollhelper im NAT sind nur GRE und SCTP einkompiliert.
- Andere Protokollhelper von NAT sind nicht geladen (Modularer Aufbau).
- Querreferenzen auf Datenstrukturen anderer Kernelbestandteile werden von der NAT-Bibliothek nicht verwaltet.
Damit entfällt die Vermutung, das es mit dem Entfernen von Interfaces zu tun hat.
Erste Ergebnisse
Die Fehlersuche schlägt an:
.../netinet/libalias/alias_db.c:853 IncrementalCleanup:
la (0xffffff8001476000) != lnk->la (0xffffff80014c4000)
la ist der Zeiger auf die NAT-Struktur (von denen es 32 gibt). lnk ist der Zeiger auf den gerade aktiven NAT-Eintrag, der selbst auf seine NAT-Struktur zurückzeigen soll.
Erwartet war, daß lnk->la den Codewert für 0xececececec enthält, was einen Use-after-Free aufgezeigt hätte. Eine andere Erwartung war, daß lnk->la komplettes Chaos enthält, was eine Fremdnutzung des Speicherbereichs angezeigt hätte.
Die unerwartete Meldung besagt nun, daß ein NAT-Eintrag, die für ihn zuständige Struktur verlassen hat und bei einer anderen Struktur aufgenommen wurde. Dies deutet auf einen Fehler im originären NAT-Code hin.
Es ist grundsätzlich möglich, daß ein einzelnes Datenpaket durch die konfigurierten Firewallregeln, die das NAT ansteuern, zweimal an unterschiedliche NAT-Instanzen übergeben wird. Dies geschieht dann, wenn ein Kunde einen anderen Kunden von NAT zu NAT ansprechen will.
Dies sollte eigentlich kein Problem darstellen, korreliert aber mit dem Regelwerk.
for i in $(seq 0 31); do
j=$(($i+128))
ipfw nat $j config ip 198.51.100.$j same_ports
ipfw add 1$j nat $j ip4 from any to 198.51.100.$j
ipfw add 2$j nat $j ipv4 from 100.64.0.$i:255.192.0.31 to any
done
Die Firewallregeln werden nun dahingehend angepaßt, daß sie ausschließlich auf dem äußeren Interface (NAT ins Internet und unNAT aus dem Internet) aktiv werden. Erst durch den Abbau der alten Plattform war es überhaupt möglich, diese Einschränkung vorzunehmen. Zuvor gab es weitere, interne Übergänge ins Internet.
Da diese Bedingung nun entfallen ist, wurde das Regelwerk entschlackt und die NAT-Bindungen nur auf das Außeninterface beschränkt.
for i in $(seq 0 31); do
j=$(($i+128))
ipfw nat $j config ip 198.51.100.$j same_ports
ipfw add 1$j nat $j ip4 from any to 198.51.100.$j recv extern in
ipfw add 2$j nat $j ipv4 from 100.64.0.$i:255.192.0.31 to any xmit extern out
done
Dabei ist zu beachten, daß FreeBSD NAT nur ausgehend ausführt. Eingehende Datenpakete werden ausschließlich "entnattet".
Die Absturzhäufigkeit sinkt drastisch!
Mit etwas Abstand kann man feststellen, daß nach diesen Änderungen an den ipfw-Regeln die beobachteten Fehler nicht mehr auftreten. Das bedeutet natürlich nicht, daß alle Probleme gelöst sind. Denn es geht weiter …
