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.
http://svnweb.freebsd.org/base?view=revision&revision=260225
3 Kommentare