Fedora: nfs-utils 2.5.4 nicht funktional

Posted on by

Einen Fall von Load 200 bei einem Idlefaktor von 96% sieht man nicht alle Tage, also schauen wir uns den mal an wie das mit NFS zusammenhängt 😉

Fedora: nfs-utils 2.5.4 nicht funktional

Schreck in der Morgenstunde: „Email vom Server : Load 100+“ Da hatte ich schon eine böse Vorahnung, daß ich per SSH nicht mehr in diesen Server reinkomme und den Hart rebooten muß. Ihr könnt Euch vorstellen, daß ich sehr überrascht war, als der Login flott und ohne Probleme ablief. Ein Blick in TOP und die Load zeigte tatsächlich 111 an. Etwas später waren es 150, dann 180 und irgendwann wurde die 200 durchbrochen (vermutlich), aber da habe ich nicht mehr hingesehen 😉

Jetzt ist das ein sehr bizarres Bild, wenn man eine Load von 180 im Top sieht, aber nur einen Prozess mit 10% CPU Last überhaupt arbeiten will. Die Load beschreibt das Verhältnis von cpuwollenden Prozessen zur Anzahl der Kerne einer CPU, was voraussetzt, daß es Prozesse mit CPU Verbrauch gibt, gab es aber nicht 😀

Also schauen wir uns pstree an, jede Menge Prozesse, aber nichts steht, alles arbeitet „normal“. Und dann stehst Du da als Admin und verstehst die Welt nicht mehr:  Load 180+, die CPU langweilt sich zu Tode, und alle CronJobs und Services ( Web, FTP, Mail etc. ) laufen wie am Schnürchen.

Bevor ich das auflöse, gebe ich den erfahrenen Admins Gelegenheit das nochmal zu durchdenken 🙂

5

4

3

2

1

Auflösung

NFS

Ok, ich kann Eure Gesichter jetzt förmlich sehen 🙂 Ich habe es auch nur durch Zufall gefunden, weil … Trommelwirbel … es im /var/log/messages einen Hinweis gab, daß gegen 6 Uhr morgens ein NFS Server nicht reagiert hat. Es war also nicht einmal der Server mit der Load der das Problem hatte, sondern der Fileserver 😉

Der NFS Mount funktionierte nicht mehr, wurde aber via Webserver Repository regelmäßig von allen Servern im Cluster mit Anfragen bombardiert, ob es neue Pakete gibt. Jede dieser Anfragen erzeugte einen „httpd“ Prozess, der aber keine Leistung ziehen konnte, es aber wollte, weil die IO zum Fileserver stillstand. Jetzt fallen ein paar mehr httpd Prozesse auf einem Webserver nicht wirklich auf.

So, damit war geklärt wieso wir eine Load von knapp 200 hatten, aber wieso ging der Mount nicht mehr?

Kurz ein paar Grafiken und Zahlen für Euch:

Die einzige reale CPU-Last war das nächtliche Backup 😉Der Graph wird nur alle 5 Minuten erzeugt, daher die leicht abgeflachte Spitze

und so sah das in Zahlen aus, minütlich ab 07:07:2021-08:02:01:

LOAD: 128.25 112.19 107.39 12/1536 3283086
LOAD: 162.90 124.62 111.94 12/1597 3283496
LOAD: 182.58 137.25 117.08 13/1608 3283850
LOAD: 190.78 147.84 121.98 16/1598 3284211
LOAD: 194.96 156.89 126.72 9/1582 3284999
LOAD: 195.70 164.04 131.06 14/1661 3285411
LOAD: 195.92 169.87 135.14 11/1649 3285732
LOAD: 196.50 174.77 139.00 10/1659 3286091
LOAD: 180.98 175.53 141.56 23/899 3286449
LOAD: 67.34 143.85 132.80 12/846 3287234
LOAD: 25.92 117.98 124.59 14/859 3287613
LOAD: 11.42 97.05 116.97 11/856 3287959

Das NFS UPDATE

Vor ein paar Tagen gab es ein NFS Update:

2021-07-07T04:01:45+0200 SUBDEBUG Upgrade: libnfsidmap-1:2.5.4-0.fc33.x86_64
2021-07-07T04:01:45+0200 SUBDEBUG Upgrade: nfs-utils-1:2.5.4-0.fc33.x86_64
2021-07-07T04:01:46+0200 SUBDEBUG Upgraded: nfs-utils-1:2.5.3-2.fc33.x86_64
2021-07-07T04:01:46+0200 SUBDEBUG Upgraded: libnfsidmap-1:2.5.3-2.fc33.x86_64

was zu diesem Resultat führte:

# systemctl status nfs-mountd
● nfs-mountd.service – NFS Mount Daemon
Loaded: loaded (/usr/lib/systemd/system/nfs-mountd.service; static)
Active: failed (Result: exit-code) since Wed 2021-07-07 09:20:22 CEST; 9s ago
Process: 4925 ExecStart=/usr/sbin/rpc.mountd (code=exited, status=0/SUCCESS)
Main PID: 4928 (code=exited, status=1/FAILURE)
CPU: 43ms

Jul 07 09:20:22 XXX systemd[1]: Starting NFS Mount Daemon…
Jul 07 09:20:22 XXX rpc.mountd[4928]: Unable to watch /proc/fs/nfsd/clients: No such file or directory
Jul 07 09:20:22 XXX systemd[1]: Started NFS Mount Daemon.
Jul 07 09:20:22 XXX systemd[1]: nfs-mountd.service: Main process exited, code=exited, status=1/FAILURE
Jul 07 09:20:22 XXX systemd[1]: nfs-mountd.service: Failed with result ‚exit-code‘.

Es blieb nur das Downgrade übrig:

dnf downgrade https://kojipkgs.fedoraproject.org//packages/nfs-utils/2.5.3/2.fc33/x86_64/libnfsidmap-2.5.3-2.fc33.x86_64.rpm https://kojipkgs.fedoraproject.org//packages/nfs-utils/2.5.3/2.fc33/x86_64/nfs-utils-2.5.3-2.fc33.x86_64.rpm

Aber danach, lief der NFS Server wieder normal und die Probleme verschwanden.

Emergency Bugreport ist erstellt, ich fürchte Test-Driven-Development gibt es nicht überall 🙁

Linux am Dienstag – Programm 6.7. ab 19 Uhr

Posted on by

Da Deutschlandspiele nicht mehr im Weg sind, geht es wieder pünktlich um 19 Uhr los 🙂

Linux am Dienstag – Programm 6.7. ab 20 Uhr

Mit dabei sind folgende Linux Themen:

  • Security – Kaseya: Coop schliesst 700 Filialen in Schweden wegen Hacks des Bezahlsoftware
    Blender Einführung – Teil 4/6 – Wolken – Duplizieren
    Systemd – Wie man Dienste startet
    Wine – Dicker Fehler in Wine Staging64 6.12
    Dovecot – Update 2.3.15 kickt Teile von Windows und Android raus

Linux am Dienstag kann man wie immer über unsere öffentliche Videokonferenz unter https://cloud-foo.de/Linux oder Ihr klickt auf https://Linux-am-Dienstag.de auf den VideoChat Button erreichen.

Hinweis: Nein, wir nehmen das nicht auf, Ihr müsstet Euch selbst hin bemühen 😉

Wine-Staging64 6.12 erschienen – Heftiger Bug im TCP/IP Stack

Posted on by

Am eigenen Leibe habe ich gerade erfahren müssen, daß das Wine-Staging64 Update auf 6.12 einen schweren Fehler im TCP/IP Stack enthält.

Wine-Staging64 6.12 erschienen – Heftiger Bug im TCP/IP Stack

Man sollte annehmen, daß es sofort beim Testen einer neuen Version auffällt, wenn man mit dem Internet keine Verbindung aufbauen kann. Tja.

Nach dem heute morgen durchgeführten Update von 6.11-5 auf 6.12-1 der experimentellen Staging Version, die zugegebenermaßen per Definition eine Entwicklerversion ist, kam es aus Sicht der Anwendung zum Ausfall des Internets, weil keine Server mehr erreicht werden können.

Das sieht dann so aus:

dropped privs to tcpdump
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on enp7s0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
15:08:05.773227 IP 192.168.0.34.57894 > 194.187.19.180.80: Flags [S], seq 2759647570, win 64240, options [mss 1460,sackOK,TS val 831085749 ecr 0,nop,wscale 7], length 0
E..<2.@.@.p....".....&.P.|.R.........h.........
1.\.........
15:08:05.773984 IP 192.168.0.34.57896 > 194.187.19.180.80: Flags [S], seq 2488347596, win 64240, options [mss 1460,sackOK,TS val 831085750 ecr 0,nop,wscale 7], length 0
E..<.y@.@..	...".....(.P.Q+..........h.........
1.\.........
15:08:05.774671 IP 192.168.0.34.57898 > 194.187.19.180.80: Flags [S], seq 3242501228, win 64240, options [mss 1460,sackOK,TS val 831085751 ecr 0,nop,wscale 7], length 0
E..<&.@.@.}....".....*.P.D.l.........h.........
1.\.........
15:08:05.794930 IP 194.187.19.180.80 > 192.168.0.34.57894: Flags [S.], seq 114763427, ack 2759647571, win 8192, options [mss 1380,nop,wscale 8,sackOK,TS val 97248822 ecr 831085749], length 0
E..<?.@.y.*........".P.&..&..|.S.. ........d.......
...61.\.
15:08:05.794945 IP 192.168.0.34.57894 > 194.187.19.180.80: Flags [R], seq 2759647571, win 0, length 0
E..(..@.@......".....&.P.|.S....P...._..
15:08:05.795624 IP 194.187.19.180.80 > 192.168.0.34.57896: Flags [S.], seq 1794556337, ack 2488347597, win 8192, options [mss 1380,nop,wscale 8,sackOK,TS val 97249931 ecr 831085750], length 0
E..<F.@.y.#........".P.(j....Q+... .C/.....d.......
....1.\.
15:08:05.795628 IP 192.168.0.34.57896 > 194.187.19.180.80: Flags [R], seq 2488347597, win 0, length 0
E..(..@.@......".....(.P.Q+.....P...v...
15:08:05.796216 IP 194.187.19.180.80 > 192.168.0.34.57898: Flags [S.], seq 2891142575, ack 3242501229, win 8192, options [mss 1380,nop,wscale 8,sackOK,TS val 97248822 ecr 831085751], length 0
E..<?.@.y.*........".P.*.SU..D.m.. ........d.......
...61.\.
15:08:05.796218 IP 192.168.0.34.57898 > 194.187.19.180.80: Flags [R], seq 3242501229, win 0, length 0
E..(..@.@......".....*.P.D.m....P....y..

Wer das nicht lesen und verstehen kann, dem sei es kurz erklärt:

Normalerweise…

Normalerweise sendet ein TCP/IP Stack zum Aufbau einer Verbindung 1 SYN Paket zum Server, der bestätigt das mit einem SYN-ACK und dann kann der Client mit einem Push Paket Daten schicken.

Im obigen Fehlerfall sendet der Wine-Stack  sofort parallel 3 SYN Pakete mit 3 verschiedenen SessionIDs los.
Der Server schickt für alle 3 SYN jeweils den passenden SYN-ACK. jetzt hat aber der Stack als letztes die 3. SessionID benutzt, es kommt aber zuerst ein SYN-ACK für die 1.SessionID rein. Die Folge: die SessionIDs passen nicht zusammen, der Wine-Stack schickt korrekterweise ein RESET zum Server und legt auf.

Das mit den 3 SYN Paketen ist zwar vorgesehen, aber nicht parallel, sondern nach einander. Es ist nämlich der Versuch auf ein nicht beantwortetes 1. oder 2. SYN doch noch ein ACK vom Server zu bekommen, wenn z.b. durch Stau über Überlastung im Netz SYN Pakete verloren gegangen sind.  Natürlich wartet ein Stack zwischen diesen Versuchen eine Zeit lang, was aber bei 6.12. nicht der Fall ist und das ist hier der Fehler.

In den Commits für 6.12 kann man auch erahnen, wo das das Problem eingebaut wurde. Bugreport ist raus 🙂

Lösung:

Downgrade auf 6.11-5 und alles ist wieder gut 🙂

Warum schreibt man jetzt deswegen einen Blogartikel?

Weil man die Stagingversion für einige Spiele braucht um z.b. Vulkantreiber zu benutzen oder andere Anpassungen an Wine braucht, damit Spiele funktionieren. Es ist eben doch nicht eine reine Entwicklerversion 😉