Der Fluch der Stabilität

Die Software der PPP Plattform steht inzwischen stabil. Die L2TP Verbindungen bleiben nun tag- ja wochenlang stehen. Und nun treten seltsame Ausfälle auf. Einer der Gründe der Auslöser einer ganzen fatalen Folge von Ereignissen.

Spontanes Versterben

Quer über alle Technik versterben spontan mal L2TP Verbindungen. Die äußert sich in Meldungen wie:

mpd: [0x807aa9f10] L2TP: XMIT stalled, queueing ...
mpd: L2TP: acknowledgement timeout
mpd: L2TP: reply timeout in session state wait-connect 

Was ist die Ursache von solchen Meldungen?

Offenbar steht die Verbindung zwischen LNS und LAC. Es gehen Pakete verloren und werden immer wieder neu gesendet, ohne daß es zu einer Verarbeitung oder Bestätigung der Nachrichten kommt.

Irgendwann greift dann der Timeout. Der L2TP Tunnel wird für tot erklärt. Alle Nutzer dieses Tunnels fliegen raus und müssen sich neu anmelden.

Beide Seiten haben in Ihren Logfiles die gleiche Ursache aufgeschrieben: Gegenstelle antwortet nicht mehr.

Als Konsequenz aus einem solchen Tunnelzusammenbruch kann es zu einer Überlastung anderer Teile der Infrastruktur kommen. Dann werden andere Tunnel nicht mehr schnell genug bedient und die Probleme verschärfen sich massiv.

Ursachenforschung

Das große Problem dieses Ereignisses ist, daß es selten und unvorhergesehen passiert.

Deswegen wurde der komplette L2TP Control Traffic mitgeschnitten, in der Hoffnung irgendwo eine Auffälligkeit zu erkennen. Sei es Paketverlust, -vertauschung oder -verdopplung. Da Daten und Steuerkanal von L2TP gemischt werden, ist der Ausdruck für den tcpdump etwas komplexer:

udp and port 1701 and udp[8:2] & 0x80ff == 0x8002

Als nächstes müssen mehrere solche Ereignisse eintreten, um diese auf Gemeinsamkeiten zu untersuchen.

17:11:49 l2tp:[TLS](24004/9105)Ns=32766,Nr=44927 *MSGTYPE(ICRP)
17:11:49 l2tp:[TLS](34489/0)Ns=44927,Nr=32767 ZLB
17:11:49 l2tp:[TLS](34489/64208)Ns=44927,Nr=32767 *MSGTYPE(ICCN)
17:11:49 l2tp:[TLS](24004/0)Ns=32767,Nr=44928 ZLB
17:13:19 l2tp:[TLS](34489/56748)Ns=44928,Nr=32767 *MSGTYPE(CDN)
17:13:19 l2tp:[TLS](24004/0)Ns=32767,Nr=44929 ZLB
17:13:24 l2tp:[TLS](34489/0)Ns=44929,Nr=32767 *MSGTYPE(ICRQ)
17:13:24 l2tp:[TLS](24004/9109)Ns=32767,Nr=44930 *MSGTYPE(ICRP)
17:13:24 l2tp:[TLS](34489/0)Ns=44930,Nr=32768 ZLB
17:13:24 l2tp:[TLS](34489/59827)Ns=44930,Nr=32768 *MSGTYPE(ICCN)
17:13:24 l2tp:[TLS](24004/0)Ns=32768,Nr=44931 ZLB
17:13:25 l2tp:[TLS](24004/9109)Ns=32767,Nr=44931 *MSGTYPE(ICRP)
17:13:25 l2tp:[TLS](34489/0)Ns=44931,Nr=32768 ZLB
17:13:27 l2tp:[TLS](24004/9109)Ns=32767,Nr=44931 *MSGTYPE(ICRP)
17:13:27 l2tp:[TLS](34489/0)Ns=44931,Nr=32768 ZLB
17:13:31 l2tp:[TLS](24004/9109)Ns=32767,Nr=44931 *MSGTYPE(ICRP)
17:13:31 l2tp:[TLS](34489/0)Ns=44931,Nr=32768 ZLB
17:13:39 l2tp:[TLS](24004/9109)Ns=32767,Nr=44931 *MSGTYPE(ICRP)
17:13:39 l2tp:[TLS](34489/0)Ns=44931,Nr=32768 ZLB

Was auffällt, ist daß die Sequenznummer, an der es stehen bleibt genau der Übergang von 15 zu 16 bit darstellt.

An dieser Grenze bricht jeder Tunnel ab. Wenn also der MPD 32767 L2TP-Nachrichten versand hat, glaubt er keine mehr loswerden zu können.

Es steht zu vermuten, daß dieses Problem im Netgraph Knoten für L2TP begraben liegt. Ganz offensichtlich ist es aber nicht.

Die Zähler haben den richten Typ (uint16_t) und die Rechnung schaut korrekt aus.

Böse Bitfehler

Da eigentlich alles richtig erscheint, muß der Compiler beweisen, daß es tatsächlich auch richtig abläuft. Im Kernel-Code (ng_l2tp.c) steht die folgende Rechnung:

#define L2TP_SEQ_DIFF(x, y)     ((int)((int16_t)(x) - (int16_t)(y)))

Ich bin mir bei der nicht sicher bin, ob da nicht ein falsches Ergebnis raus kommt. Also muß ein Testprogramm beweisen, daß es an allen interessanten Übergängen die richtigen Ergebnisse zeigt.

#include <stdio.h>
#include <stdint.h>

#define L2TP_SEQ_DIFF(x, y)     ((int)((int16_t)(x) - (int16_t)(y)))
#define L2TP_SEQ_DIFF1(x, y)    ((int16_t)((int16_t)(x) - (int16_t)(y)))

void test(uint16_t b) {
   uint16_t a,c;
   a=b-1;
   c=b+1;
   printf("%5d %6d %6d %6d %6d\n", b,
          L2TP_SEQ_DIFF(a,b), L2TP_SEQ_DIFF(c,b),
          L2TP_SEQ_DIFF1(a,b), L2TP_SEQ_DIFF1(c,b)
          );
}

void main(void) {
   uint16_t b;
   for(b=32765; b!=32770; b++) test(b);
   for(b=65530; b!=    5; b++) test(b);
}

Das Ergebnis überrascht:

32765     -1      1     -1      1
32766     -1      1     -1      1
32767     -1 -65535     -1      1
32768  65535      1     -1      1
32769     -1      1     -1      1
65530     -1      1     -1      1
65531     -1      1     -1      1
65532     -1      1     -1      1
65533     -1      1     -1      1
65534     -1      1     -1      1
65535     -1      1     -1      1
    0     -1      1     -1      1
    1     -1      1     -1      1
    2     -1      1     -1      1
    3     -1      1     -1      1
    4     -1      1     -1      1

Ich hatte nicht erwartet, so tief im Kernel einen solch elementaren Fehler zu finden.

Die Lösung ist offenkundig: Man muß die Rechnung auf 16 bit begrenzen. Mein Testcode steht ja dabei.

Und nun heißt es warten:

  • Zum einen erstmal auf eine Gelegenheit den Kernel zu patchen.
  • Zum zweiten auf eine Gelegenheit alle betroffenen Maschinen zu rebooten.
  • Und zum dritten auf Sequenz-Zählerstände größer 32767.

Und das Ergebnis überzeugt.

Avatar
Mark 08.07.2014 16:08
I see the patch made it in however which releases of FreeBSD did it make it into? I am seeing similar issues to all of your blog posts and so we have had to use FreeBSD 8(it was unstable but much faster on 9 and 10 ) - do you know if the patch made its way into 8.4 code?
Avatar
glebius 03.01.2014 13:13
Thanks, Lutz!

http://svnweb.freebsd.org/base?view=revision&revision=260225
Avatar
Rainer S. 27.12.2013 09:34
Nicht daß ich irgendeine Ahnung hätte, aber das riecht doch streng nach einem off-by-one-error?

3 Kommentare

Post a comment

Verwandter Inhalt