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.

Debugging ist wie Zwiebeln schälen: Man entfernt vorsichtig Schicht um Schicht, um am Ende mit leeren Händen dazustehen.

unknown

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
. endif

Also 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 buildkernel

Wenn 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.

Post a comment

Verwandter Inhalt