Und täglich grüßt der SMB-ReMount
Ein Kunde beschwerte sich über Netzwerkprobleme. Zwischen zwei seiner Server würde immer wieder ein SMB/CIFS-Mount weg brechen. Nicht, dass es irgendwelche bemerkbaren Störungen gegeben hätte, aber es gäbe halt immer wieder diese Fehlermeldungen im Log.
Aufbau
Der Kunde hat in seinem Layer2-Segment eine ganze Latte Server stehen. Einer davon spielt Windows-Fileserver für eine Gruppe von Windows Rechnern. Ein anderer ist das Linux-Monitoring-System, das u.a. regelmäßig versucht auf die Freigabe zuzugreifen.
Das Ganze hat eine längere Vorgeschichte, die vor einem halben Jahr zur Empfehlung führte, doch konsequent auf SMB1 zu verzichten. Dieser Teil ist nicht von Belang, sondern das, was der Empfehlung folgte.
Denn seit der Umstellung hat das Monitoring-Linux seltsame Einträge im Kernellog stehen:
Feb 12 19:07:02 kernel: CIFS VFS: Server a.b.c.d has not responded in 120 seconds. Reconnecting...
Woher kommen die 120 Sekunden? Das Handbuch hilft weiter:
echo_interval=n sets the interval at which echo requests are sent to the server on an idling connection. This setting also affects the time required for a connection to an unresponsive server to timeout. Here n is the echo interval in seconds. The reconnection happens at twice the value of the echo_interval set for an unresponsive server. If this option is not given then the default value of 60 seconds is used.
Das erklärt schon mal die 120 Sekunden: Alle Minute wird ein SMB Echo versendet und wenn zweimal kein Echo beantwortet wird, nimmt man an die Verbindung sei tot. Deswegen wird seitens des Kunden (verständlicherweise) vermutet, dass es Paketverlust im Netzwerk gäbe.
Allein diese Vermutung zu widerlegen, dauert Wochen. Dazu wird auf beiden Seiten der Datenverkehr mitgeschnitten und Paket für Paket nebeneinander gelegt.
Dem eigentlichen Problem ist man damit aber leider immer noch nicht näher gekommen.
Analyse
Immer wieder wird so ein Mitschnitt angeschaut, um irgendeine Auffälligkeit zu entdecken.
Es ist sehr schön zu sehen, wie jede Minute das Keep-Alive Request-Response Spiel passiert. Anschließend werden Daten übertragen.
Kurz darauf kommt die Kommunikation zum Erliegen und der im Log erwähnte Timeout schlägt zu. Zwischen 19:05:01.99... und 19:07:02.25... liegen etwas mehr als 120 Sekunden. Das passt so weit.
Auffällig ist der Übertragungsfehler (der mit dem TCP-Keepalive), der direkt vor dem Abbruch der Verbindung rein schlägt. Das muss untersucht werden!
Warum ist die Zeile schwarz? Weil der Keepalive genau ein Byte nochmal sendet, dass schon lange geackt wurde. Es ist eine sehr ungewöhnliche Kommunikation. Wireshark markiert solche Sequenzfehler mit schwarzer Farbe.
- Um 19:05:01.949511 werden 128 Byte empfangen.
- Um 19:05:01.997203 wird der Empfang dieser 128 Bytes bestätigt.
- Um 19:07:01.999481 wird das letzte der 128 Bytes nochmal übertragen (zusammen mit dem Keepalive-Flag)
Wenn die Bestätigung des Datenempfangs (ACK) nicht angekommen wäre, würden die gesamten 128 Byte nochmal gesendet. Werden sie aber nicht.
Hat irgend eine Firewall unterwegs an den Sequenznummern gespielt? Es ist aber gar keine Firewall dazwischen, beide Server stehen im gleichen LAN und sehen sich direkt. Der Mitschitt auf der anderen Seite bestätigt, dass die Bestätigung komplett angekommen ist.
Warum sollte der Kernel also ein einzelnes Byte nochmal senden? Es stellt sich heraus, dass die Windows-Implementation des TCP-Keepalives genau ein Byte nochmal sendet, während die Linux-Implementation das Keepalive ohne Payload auskommt. Es handelt sich offenbar um eine Anpassung von Windows an kaputte Middleware, die TCP-Pakete ohne Payload verwirft.
Der Teil ist also in Ordnung. Aber was ist es dann?
Vielleicht hat es irgendwo Verzögerungen gegeben? Also schauen wir mal auf die Round-Trip-Zeiten. Vielleicht gibt es Ausreißer.
Von der remote Stelle gibt es keine besonderen Auffälligkeiten. Alles schön.
Auch die lokale Verarbeitung ist völlig unauffällig: Das der Kernel direkt bearbeiten kann, ist nahezu in Nullzeit erledigt. Wenn die Anwendungssoftware involviert ist, dauert's länger. Man sieht sehr schön, wie regelmäßig die Messungen vorgenommen werden.
Auch hier ist nichts auffällig. Aber was ist es dann?
Beim genaueren Hinsehen fällt auf, dass um 19:06:00 ein Echo-Request hätte versendet werden sollen. Der fehlt aber!
Kernel Archäologie
Im Linux-Kernel ist für das Versenden der Echo-Requests die Funktion cifs_echo_request zuständig. Dort steht:
static void
cifs_echo_request(struct work_struct *work)
{
int rc;
struct TCP_Server_Info *server = container_of(work,
struct TCP_Server_Info, echo.work);
unsigned long echo_interval;
/*
* If we need to renegotiate, set echo interval to zero to
* immediately call echo service where we can renegotiate.
*/
if (server->tcpStatus == CifsNeedNegotiate)
echo_interval = 0;
else
echo_interval = server->echo_interval;
/*
* We cannot send an echo if it is disabled.
* Also, no need to ping if we got a response recently.
*/
if (server->tcpStatus == CifsNeedReconnect ||
server->tcpStatus == CifsExiting ||
server->tcpStatus == CifsNew ||
(server->ops->can_echo && !server->ops->can_echo(server)) ||
time_before(jiffies, server->lstrp + echo_interval - HZ))
goto requeue_echo;
rc = server->ops->echo ? server->ops->echo(server) : -ENOSYS;
if (rc)
cifs_dbg(FYI, "Unable to send echo request to server: %s\n",
server->hostname);
requeue_echo:
queue_delayed_work(cifsiod_wq, &server->echo, server->echo_interval);
}Der Code ist in mehrfacher Hinsicht interessant:
- Zum Einen wird ein Echo nur gesendet, wenn dafür eine echte Notwendigkeit besteht.
- Zum Anderen handelt es sich um ein Daisy-Chain Scheduling: Erst nach getaner Arbeit wird die nächste Aktion geplant.
Was die Notwendigkeit betrifft, so werden keine Echos ausgesendet, solange die letzte Response kürzer als eine Echo-Abstand einging.
Aber was ist eine Response? Im Code wird der server-›lstrp immer dann auf die aktuelle Zeit gesetzt, wenn ein Paket empfangen wird. Unabhängig davon ob es ein Echo-Response oder normale Daten sind.
Das Abziehen von HZ (eine Sekunde) ist eine Maßnahme dagegen, dass die Echo-Response auf die eigene Anfrage schon als interessanter Traffic interpretiert wird. Dieser hartkodierte Wert gilt also unter der Annahme, dass die Antwort der Gegenstelle immer schneller da ist als in einer Sekunde.
Betreibt man einen solchen SMB Zugriff über eine längere Strecke oder gegen einen langsameren Server, so wird jeder zweite Echo-Request unterdrückt, wenn kein weiterer Traffic auftritt. Das führt direkt dazu, dass SMB nur im LAN wirklich funktioniert.
Aufgrund der Protokollarchitektur werden alle Anfragen sequentiell bearbeitet. Wenn also ein Echo-Request gesendet wird, während noch eine andere Abfrage an den Server läuft, so wird die Verarbeitung des Echo-Requests erst dann erfolgen, wenn der vorherige Request bearbeitet wurde. Eine asynchrone Bearbeitung wurde mit dem Wechsel von SMB1 zu SMB2 aufgegeben. Stattdessen soll der Server den Client mitteilen, dass die Bearbeitung einer aufwändigeren Anfrage noch andauert.
In diesem Fall war um 19:05:01.91... eine Antwort vom Server eingegangen. Das Echo-Paket hätte gegen 19:06:00 gesendet werden sollen. Das ist haarscharf daneben!
Die zweite Auffälligkeit ist das Scheduling. Erst, wenn alle Arbeiten (Echo-Paket versenden) erledigt sind, wird der nächste Echo-Versand geplant und zwar 60 Sekunden später. Die gesamte Verarbeitungszeit fehlt in der Planung. Das führt dazu, dass die Echo-Pakete nicht genau nach 60 Sekunden versendet werden, sondern immer ein Stück später.
Man sieht das im Mitschnitt sehr schön: 19:01:55.05, 19:02:56.49, 19:03:57.94, 19:04:59.37, 19:06:00.90, 19:07:02.27. Die Abstände betragen etwa 61,5 Sekunden. Also 1,5 Sekunden mehr als geplant. Im letzten Schritt ist das Intervall kürzer, weil das Echo-Paket ja nicht versendet werden musste.
Racecondition
Was wirklich passiert ist schnell erklärt: Das Unterdrücken des geplanten Echo-Requests ist fehlerhaft.
Im Detail:
- Durch das Daisy-Chaining-Schedulung entsteht eine Lücke.
- Kommt Traffic unglücklich kurz nach dem letzten Echo, so wird das geplante Echo unterdrückt.
- Durch die Lücke verzögert sich der nächste Echo-Versand bis nach dem Timeout, das hart auf das doppelte Echo-Intervall gesetzt wird.
Besonderen Charme hat die Erkenntnis, dass der finale Echo-Request erst versendet wird und danach der Timeout zuschlägt, weil die erste Aktion beim Empfangen des Echo-Response ist, auf einen Timeout zu prüfen und abzubrechen. Ironischerweise hat also das erfolgreiche Echo den Abbruch getriggert.
Stellt sich nun die Frage, seit wann das Problem auftritt und wer dafür verantwortlich ist:
- Im Patch c740 werden fest alle 60 Sekunden Echo-Requests versendet, wenn kein anderer Traffic auftrat. (Jan 11, 2011)
- Im Patch fda3 werden diese Echos genutzt um nach dem fünffachen Intervall (konfigurierbar) ohne Traffic den Timeout auszulösen. (Jan 20, 2011)
- Im Patch 6dae wird die Konfigurierbarkeit von 60s x variabel(5) zu variabel(60s) x zwei umgestellt. (Feb 21, 2012)
Die Lücke und das Unterdrücken wurde also am 11. Januar 2011 eingeführt. Allerdings hat diese keine Auswirkung, da der Timeout erst beim fünffachen Intervall eintritt.
Mit der Umstellung vom 21. Februar 2012 wirkt sich die Lücke nun aus, da man den Timeout hart auf das doppelte Intervall setzte.
Lösungen
Es gibt drei Möglichkeiten.
Zum einen kann man die Lücke beseitigen, indem man das Scheduling zu festen Zeiten macht (immer 60 Sekunden zum letzten Schedule-Zeitpunkt addieren). Es genügt übrigends nicht, das Rescheduling an den Anfang der Routine zu stellen. Damit wird die Lücke nur kürzer, bleibt aber bestehen.
Eine andere Möglichkeit wäre, den Echo-Request unabhängig von anderem Traffic in jedem Fall zu versenden. Motto: Wenn eh schon Traffic läuft, stört der zusätzliche Request auch nicht mehr. Es besteht dabei die potentielle Gefahr, dass sich ein Server an einem Echo zwischen anderen Requests verschluckt.
Und dann wäre es noch denkbar, dass man dem gesamten Problem aus dem Weg geht, indem man minimal die dreifache Intervall-Länge wartet.
Für einen Quick-Fix sollte man den dritten Weg beschreiten: Aus einer 2 eine 3 im Code machen:
static bool
server_unresponsive(struct TCP_Server_Info *server)
{
/*
* We need to wait 2 echo intervals to make sure we handle such
* situations right:
* 1s client sends a normal SMB request
* 2s client gets a response
* 30s echo workqueue job pops, and decides we got a response recently
* and don't need to send another
* ...
* 65s kernel_recvmsg times out, and we see that we haven't gotten
* a response in >60s.
*/
if ((server->tcpStatus == CifsGood ||
server->tcpStatus == CifsNeedNegotiate) &&
time_after(jiffies, server->lstrp + 2 * server->echo_interval)) {
cifs_dbg(VFS, "Server %s has not responded in %lu seconds. Reconnecting...\n",
server->hostname, (2 * server->echo_interval) / HZ);
cifs_reconnect(server);
wake_up(&server->response_q);
return true;
}
return false;
}Bleibt nur noch die Frage nach dem TCP-Keepalive. Windows hat exakt 120s bis es auf einer TCP Session einen Keepalive schickt. Man sieht sehr schön, dass zuerst der Windows-Server den TCP-Keepalive schickt, weil er das letzte Paket eher abgesendet hat als es beim Linux ankam.
Danksagung
Die gesamte Analyse wurde von meinem Kollegen Jens durchgeführt, der mich nur bat, die Dinge zusammen zu schreiben. Was ich hier mit getan habe.
jetzt muss nur noch ein Bugreport an die richtige Stelle geschickt werden.
5 Kommentare