Aus der Kategorie „Bugs, die Linux schrieb“ heute für Euch der nicht auszumerzende Fehler mit den MAX OPEN FILES.

Bug: schließe Dateien, die Du gar nicht offen hast

Wer von Euch schon ein Programm geschrieben hat, wird evtl. mal über den dezenten Hinweis des Programmierlehrers gestolpert sein, alle Ressourcen die man öffnet, auch wieder zu schließen. Obwohl es heute Garbage-Kollektoren gibt, die so etwas aufräumen, ist es nicht nur schlechter Stil, wenn man das nicht macht, sondern kann massive Probleme wie Memory Leaks verursachen.

Das Spiel geht aber auch anders herum, nämlich Ressourcen zu schließen, die gar nicht offen sind 😉 Und das hat unter Linux ganz massive Probleme zur Folge.

Hier ein Mitschnitt auf einem PC heute morgen:

[pid 25178] dup2(48, 0) = 0
[pid 25178] pipe([51, 52]) = 0
[pid 25178] close(51) = 0
[pid 25178] dup2(52, 1) = 1
[pid 25178] close(52) = 0
[pid 25178] dup2(1, 2) = 2
[pid 25178] getrlimit(RLIMIT_NOFILE, {rlim_cur=8*1024, rlim_max=8*1024}) = 0
[pid 25178] close(8191) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8190) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8189) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8188) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8187) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8186) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8185) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8184) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8183) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8182) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8181) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8180) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8179) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8178) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8177) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8176) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8175) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8174) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8173) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8172) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8171) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8170) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8169) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8168) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8167) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8166) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8165) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8164) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8163) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8162) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8161) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8160) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8159) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8158) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8157) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8156) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8155) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8154) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8153) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8152) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8151) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8150) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8149) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8148) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8147) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8146) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8145) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8144) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8143) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8142) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8141) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8140) = -1 EBADF (Bad file descriptor)
[pid 25178] close(8139) = -1 EBADF (Bad file descriptor)
… ja, das geht so bis 50, dann …
[pid 25178] close(19) = 0
[pid 25178] close(18) = 0
[pid 25178] close(17) = 0
[pid 25178] close(16) = 0
[pid 25178] close(15) = 0
[pid 25178] close(14) = 0
[pid 25178] close(13) = 0
[pid 25178] close(12) = 0
[pid 25178] close(11) = 0
[pid 25178] close(10) = 0
[pid 25178] close(9) = 0
[pid 25178] close(8) = 0
[pid 25178] close(7) = 0
[pid 25178] close(6) = 0
[pid 25178] close(5) = 0
[pid 25178] close(4) = 0
[pid 25178] close(3) = 0
[pid 25178] geteuid() = 110
[pid 25178] execve(„/sbin/unix_chkpwd“, [„/sbin/unix_chkpwd“, „XXXXXXXXXXXX“, „nonull“], [/* 0 vars */]) = 0
[pid 25178] brk(NULL) = 0x5574dbb77000
[pid 25178] fcntl(0, F_GETFD) = 0
[pid 25178] fcntl(1, F_GETFD) = 0
[pid 25178] fcntl(2, F_GETFD) = 0
[pid 25178] access(„/etc/suid-debug“, F_OK) = -1 ENOENT (No such file or directory)
[pid 25178] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfc6241000
[pid 25178] access(„/etc/ld.so.preload“, R_OK) = -1 ENOENT (No such file or directory)
[pid 25178] open(„/etc/ld.so.cache“, O_RDONLY|O_CLOEXEC) = 3
[pid 25178] fstat(3, {st_mode=S_IFREG|0644, st_size=43265, …}) = 0
[pid 25178] mmap(NULL, 43265, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fcfc6236000
[pid 25178] close(3) = 0
…

Wie man an dem Mitschnitt ( strace ) sehen kann, versucht der Prozess alle offenen Dateihandles, und Sockets gehören da auch dazu, von 8191 bis 3 zu beenden, und bekommt dabei einen Fehler. Die relevante Stelle:

[pid 25178] getrlimit(RLIMIT_NOFILE, {rlim_cur=8*1024, rlim_max=8*1024}) = 0
[pid 25178] close(8191) = -1 EBADF (Bad file descriptor)

8*1024 ist 8192, also 8191+1 bzw. 0…8191 => 8192 Handles . RLIMIT_NOFILE ist die maximale Anzahl an offenen Dateien, die ein Prozess auf diesem System haben darf. Je nach Systemeinstellungen können das auch mal mehr oder weniger sein.

Wie man also leicht erkennen kann, werden alle 8141 Filehandles mit einem Fehler geschlossen: „-1 EBADF (Bad file descriptor)„, weil sie nicht offen waren. Schrieb ich 8141? ja, weil ab Filehandle 50 tatsächlich offene Filehandles geschlossen werden. Es wurden also von dem Prozess genau 51 Dateien (0..50) dauerhaft offen gehalten.

Das Schließen von Dateien die nicht offen sind, verursacht eine ungeheure Last, weil natürlich von einem Fehler ausgegangen wird. Die genutzten Systembibliotheken tun alles um diesen Fehler auszumerzen und verbrauchen dabei richtig viel Last. Das wiederum ist kein Fehler des Programms selbst, sondern der benutzten „Lib“ ( englische Kurzform von Bibliothek ).

Die Folge

Die Folge der Aktion war, daß der Prozess bei 156% CPU Verbrauch lag, was auf einem 8 Kerner an sich kein Problem ist, aber leider dabei soooooviel Behinderung der Lib( s.u. ) erzeugte, daß „top -c“ über 6 Sekunden brauchte zu starten.

Wenn Top das schon so behindert, könnt Ihr Euch denken, was das mit einem Fileserver macht: „System geht nur noch eingeschränkt zu nutzen.“

Mehr Infos

Wer sich den Bug aus der Nähe ansehen möchte, findet hier eine Version des Fehlers bei ClamAV und Fedora:

https://bugzilla.redhat.com/show_bug.cgi?id=1852460

Wie Ihr am Datum des Bugreports sehen könnt, gibt es diese Bugs nicht erst seit gestern. Allerdings sind sie in aktuellen Distros, die kein LTS sind (so wie das System von dem der obige strace stammt), bereits ausgemerzt worden.

Falls Euch aber mal so ein Fehler über den Weg laufen sollte, dann könnt Ihr den so temporär beheben:

1. mit „strace -f -p PID“ den Prozess belauschen lassen.
2. bei der close() Orgie darauf achten, ab welchem Filehandle ( oben war es „50“ ) die Orgie aufhört.
3. mit „ulimit -n {ermittelte Zahl+30}; /pfad/zum/programm {optionen}“ den Prozess neustarten.

Den Schritt 3 kann man auch anders organisieren, je nach dem ob es ein Systemd Start ist, könnte man das neue FilesOpenLimit im Unitfile setzen und so dafür sorgen, daß der Bug nicht so starke Auswirkungen hat. In dem Punkt müßt Ihr etwas flexibel sein, wie das bei Euch konkret am Besten geht.