Fedora hat Krita 4.1.8 bekommen und wir ein Problem

Freude, Fedora hat ein Krita Update bekommen \o/ … öhm…auf die sechs Monate alte Version 4.1.8, statt der aktuellen Version 4.2.2. Und damit einen Bug, den Linux Mint schon im Januar hatte, man kann jetzt nämlich das Fenster nicht mehr maximieren. WTF !

„Erfreut Euch an den Bugs, was anderes habt Ihr nicht!“ (Bill Gates)

Ich spare mir mal das lange Palaver über die Ursachen alte Versionen zu compilieren, wenn dann auch noch Bugs drin sind. *Kopfschüttel*  Der Fix ist jedenfalls denkbar einfach. Auf der rechten Seite sind Docker untergebracht. Auf den ersten Blick bemerkt man, daß die Seite komisch aussieht, weil jede Menge neue, völlig unnütze Docker da drin sind. Aus einem mir unverständlichen Grund, triggert das Krita dazu, das Maximize Button im Fensterrahmen abzulehnen und sonst auch alle Request an den Windowmanager das Fenster doch mal zu vergrößern zu verneinen.

Wenn man jetzt ein paar von den Dockern entfernt, braucht man vermutlich eh nicht, dann kommt zuerst die Maximize Funktion wieder und nach dem ersten Refresh des Fensterrahmens ist auch das Button wieder da.

Wer das Zitat von Bill Gates nicht kennt, kann ja mal auf den Text klicken 😉

The Revenge of Mariadb IV

Es ist mal wieder Zeit für eine MariaDB Geschichte. Keine Panik, die wird nicht wieder biblisch werden 🙂

Es war mal wieder Zeit für ein OS-Upgrade

Mittlerweile waren drei OS-Releases ins Land gegangen und eine sich anbahnende Sicherheitslücke im Exim .. PSSST! Ich habe sie Euch nicht verraten. Tut so, also wenn Ihr nächste Woche das erste mal davon gelesen habt, ja? 😉 .. zwang zu einem schnellen Update auf eine nicht betroffene Version. Fedora 29 sollte es sein 😉

Nun, glücklicherweise war auch ein anderer Testserver noch auf der gleichen alten OS Release, so daß er als Testlauf herhalten durfte. Dieser Test lief ausgesprochen positiv ab, um genau zu sein, makellos. Daher wurde kürzestfristig entschieden, auch den eigentlichen Kandidaten auf die gleiche Art zu updaten. Ein Snapshot der VM und 30 Minuten später  war das Update komplett und der Server startete wieder.

Mailserver, Webserver, IMAP-Server, diverse Dienste liefen. Was natürlich nicht lief war die MariaDB .. Ätzzz. N I C H T  S C  H O N  W I E D E R!   Auch gutes Zureden, energisches Nachtreten mit systemctl änderte nichts an diesem Status, der Datenbankserver startete nicht.

Same procedure als last year, Miss Sophie?

Leider nein. Letztes mal hatte sich bekanntlich ein Konfigfile des Systemd geändert, so daß die zum Start nötigen Limits nicht gesetzt wurden. Natürlich wurde der DIFF Test vom letzten mal auch wieder angewendet, zeigte aber keinen Unterschied an. Also mußte die gute alte Methode „Start den Dienst von Hand, dann bekommst Du Infos“ herhalten.

Wie macht man das?

Wir schauen uns mal an, was der Systemd so starten wollen würde:

cat /usr/lib/systemd/system/mariadb.service

Da findet dann das hier:

ExecStartPre=/usr/libexec/mysql-prepare-db-dir %n
# MYSQLD_OPTS here is for users to set in /etc/systemd/system/mariadb@.service.d/MY_SPECIAL.conf
# Note: we set –basedir to prevent probes that might trigger SELinux alarms,
# per bug #547485
ExecStart=/usr/libexec/mysqld –basedir=/usr $MYSQLD_OPTS $_WSREP_NEW_CLUSTER
ExecStartPost=/usr/libexec/mysql-check-upgrade

Das POST können wir ignorieren, soweit kommen wir nicht, bleiben nur Pre und der eigentliche Dienststart.

Das in den einschlägigen Envfiles  unter /etc/sysconfig/ nichts steht, reicht also ein :

/usr/libexec/mysqld –basedir=/usr

für den Test aus. Ja super.. eine Fehlermeldung:   Can’t set requested open_files (1024) to 2000 …

Das lag an dem ulimit hier:

# ulimit -a
core file size (blocks, -c) unlimited
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 32088
max locked memory (kbytes, -l) 16384
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) unlimited
cpu time (seconds, -t) unlimited
max user processes (-u) 32088
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

Damit kann nicht mal die minimale Version der Datenbank starten 😉 Ergo geben wir ein: „ulimit -n 99999“ und starten es nochmal und siehe da, es hat sich doch wieder was geändert:

2019-06-04 23:13:41 0 [ERROR] /usr/libexec/mysqld: unknown variable ‚innodb_additional_mem_pool_size=50M‘
2019-06-04 23:13:41 0 [ERROR] Aborting

Wenn man denn endlich mal in Logfile schaut, sieht man dort auch die Warnung, daß sich das ja mal ändern könnte. Wer rechnet schon mit damit, daß da jemand mal Ernst macht 😉

2019-05-26 09:18:16 b753fd80 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB’s internal memory allocator.
2019-05-26 9:18:16 3075734912 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

Merke, erst ins Datenbank Log schauen, dann Server updaten!

Drei OS-Versionen sind dann vielleicht doch etwas happig bei einem Update. Diese Option findet man, so man sie gesetzt hat, in der Datei /etc/my.cnf . Anweisung auskommentieren, diesmal Datenbank über systemctl starten und läuft wieder 🙂

Und hier dachte ich eigentlich, ist die Story zu ende… war sie aber nicht!

Der an diesem Master angeschlossene Replications Elf ( Sklave sagt man im PCSG nicht mehr 😉 ) mochte die Replikationsblöcke vom Master nicht mehr lesen, weil Checksumme unbekannt! Das lag daran, daß der Replikations Elfe eine ältere Datenbankversion laufen hatte, da LTS. Einer langen Suche kurzes Ende:

Elfen anhalten: mysql -p -e „stop slave
auf den Master connecten: mysql -p -e „set global binlog_checksum=’NONE‘; SHOW MASTER STATUS;“ ausführen.

+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000138 | 521505   |              |                  |
+------------------+----------+--------------+------------------+

Datenbank auf dem Master dumpen, auf den Elfen kopieren. Auf dem Elfen die Datenbank wipen, den SQL Dump einspielen.

Auf dem Elfen : mysql -p -e „change master to MASTER_LOG_FILE=’mysql-bin.000138′, MASTER_LOG_POS=521505;start slave

Sollte wieder gehen. Ging nicht.. Neuer Fehler! Statt:

Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Slave can not handle replication events with the checksum that master is configured to log; the first event 'mysql-bin.000136' a'

gabs jetzt :

Last_IO_Errno: 1045
Last_IO_Error: error connecting to master 'test@masterserver:3306' - retry-time: 60  retries: 86400

Er zum Geier ist „TEST“ !?

Tja, keine Ahnung wie das passieren konnte, aber der „change master to …“ Befehl hatte den Replikationsusernamen durch „test“ ersetzt! Einfach so! Passwort war ok, Servername war ok, Username weg! Wie geil ist das denn ?!?!?

Also nochmal mit dem change master an den Elfen ran:

/usr/bin/mysql -p -e „stop slave;;CHANGE MASTER TO MASTER_USER=’myreplicationusername‘,MASTER_PASSWORD=’MeinPasswort‘;start slave

Da machste was mit als Admin … Ich wollte doch nur den Exim abdichten, nicht das Rad neu erfinden! Naja, jetzt gehts ja erstmal wieder 🙂 Und bevor noch einer fragt, nein, der Server hatte extern nur Port 25 zu bieten, deswegen ja auch das Update 😉

Fedora 28 und das Upgradeaftermatch

„Hey, Fedora 27 ist Geschichte, freu Dich auf Fedora 28, User!“ Ich habe ihn nicht gehört, aber der MCP hat das bestimmt vorhin beim Upgrade gesagt oder gedacht. Leider hat es nicht funktioniert.

Keine Friends in Sicht…

Ja, heute war es soweit: das obligatorische Sechsmonatsupgrade auf Fedora 28 war dran. Auf dem Laptop läuft es seit letzter Woche, also sollte das ja jetzt kein Problem werden. Flugs den Desktop stoppen, in eine Root-Shell und DNF mit Arbeitsanweisung versorgen. Gesagt, getan. 15 Minuten später waren alle 3800 Pakete geladen und bereit. Zwei unwichtige Downgrades und 3 unwesentliche Altpaketentfernungen waren abgesegnet. Schritt 1/7550 kam in Sicht und …. hey… (nanü? Was ist mit der Absatzüberschrift los?)… ging 🙂

7550 Schritte später, wartet mein Cursor, meine Root-Shell und mein neues Fedora auf mich, also „reboot“ getippt, beide Daumen zerquetscht und gewartet. Bios .. Grub \o/ … die seit Jahren vertraute Meldung, daß die Kernel-Module vom Systemd nicht geladen werden konnten…( Anm.d.R „auch diesmal“ wieder nicht 🙁 ) .. Fedora Bootlogo… wird weiß… Login! … DESKTOP! … P.R.O.G.R.A.M.M.E !.! … was ist das denn?

„Wollen Sie die Default Ordner rename to die lokal gewählte Sprache…“

Was zum Geier… wie kommt Cinnamon darauf, daß ich bei einem Deutschen Desktop englische Verzeichnisnamen haben können wollte? Könnten die Spracheinstellungen defekt sein? Nachguck.. Nö. Deutsch/Deutsch. Sieht ok aus. „Da hat bestimmt Gnome beim Update was zerlegt.“ war der Gedanke, also ins Gnome gewechselt… was ein schwerer Fehler war, den GNOME ist nicht mehr .. DAS hat es tatsächlich beim Upgrade zerlegt, denn die Gnome-Shell kommt nicht an den Start. Die Programme schon, aber ohne Windowmanager nützt das nicht viel 😀 … Hmm.. Programme melden sich aber in Deutsch, das ja komisch.

Mit STRG+ALT+F3 ab in die Root-Shell, anmelden …. was ist das denn? „setlocale: Konnte LC_TIME nicht setzen“ (War natürlich auf english, aber zum besseren Verständnis wird es hier eingedeutscht). Wie kann das denn sein?

Kurz mal die Umgebungsvariablen checken:

# strings /proc/self/environ 
...
LANG=de_DE.UTF-8
...
_=/usr/bin/strings


# locale
LANG=de_DE.UTF-8
LC_CTYPE="de_DE.UTF-8"
LC_NUMERIC="de_DE.UTF-8"
LC_TIME="de_DE.UTF-8"
LC_COLLATE="de_DE.UTF-8"
LC_MONETARY="de_DE.UTF-8"
LC_MESSAGES="de_DE.UTF-8"
LC_PAPER="de_DE.UTF-8"
LC_NAME="de_DE.UTF-8"
LC_ADDRESS="de_DE.UTF-8"
LC_TELEPHONE="de_DE.UTF-8"
LC_MEASUREMENT="de_DE.UTF-8"
LC_IDENTIFICATION="de_DE.UTF-8"
LC_ALL=

Alles ok, Deutsch ist eingestellt. Übersetzungen gingen ja in den Programmen, aber tatsächlich war die Zeit in English mit 12H+AM/PM .. schauen wir doch mal mit strace auf welche Locale will das Programm eigentlich zugreifen: also „strace -f locale de_DE.UTF-8“ eingegeben und es würde gern diese Datei benutzen „/usr/lib/locale/de_DE.utf8/LC_TIME“ … ist ja merkwürdig, die ist gar nicht vorhanden…. hey! den ganzen Ordnerbaum gibt es gar nicht! HIER FEHLT DEUTSCH!

Und so behebt man das

Die Sachelage ist klar: Keine Deutsche Locale vorhanden, also nachinstallieren. Da wir den Pfad kennen, fragen wir dnf wer das bereitstellen könnte:

# dnf provides „/usr/lib/locale/de_DE.utf8/LC_TIME“

glibc-langpack-de-2.27-32.fc28.x86_64 : Locale data for de
….

also installieren wir das und rebooten kurz ( damit auch die Bootprozesse in Deutsch melden können, wenn Sie das wünschen):

# dnf install glibc-langpack-de

und da merkt man dann, daß das kein Witz war, weil der jetzt „j“ nicht mehr als „ja“ => „yes“ erkennt .. muß man also wirklich „y“ drücken 🙂

Nach dem Reboot war es dann in Ordnung. Warum der den Language-pack nicht installiert hat, werden wir nicht erfahren. Um GNOME werde ich mich wohl mit „rm -rf .config/gnome-session“ kümmern müssen.

Update Tag 2:

Die WetterApp geht nicht. Libmozjs crasht beim Start extrem hart, incl. Coredump. Autsch. Mal sehen was von den HinterbänklerApps noch so nicht geht.

Jitsi kann keine SIP Anrufe mehr annehmen

Wer kennt das nicht, in der Firma läuft es ruhig. Kunden melden sich nur per Email, aber das Telefon schweigt seit Tagen. Das alljährliche Sommerloch, wegen dessen wir alle in den Urlaub fahren …, oder ?

Paranoide Menschen würden jetzt per Telefon sich selbst anrufen und entsetzt feststellen, daß die Telefone nicht klingeln, weil .. ja .. scheisse, wieso klingeln die nicht ????!!!!!!

Ab jetzt herrscht Panik in der IT-Abteilung:  Was ist passiert ?

Ist der SIP Provider pleite gegangen ?
Haben Mäuse die Glasfaserkabel geknackt ?
Oder liegt es etwa an uns ?
Gab es ein Update der Telefonsoftware ?
Gab es überhaupt irgend ein Update ?

Also prüfen wir zunächst mal, ob alle betroffen sind und stellen fest : Alle Jitsi SIP Softphones sind quasi tod, aber normale Telefone für SIP nicht. Jitsi kann zwar noch raustelefonieren, sonst wäre das ja auch eher aufgefallen, aber ankommende Anrufe gehen nicht mehr. Komischerweise geht Jitsi auf den Handies noch.

Das schliesst per se ein DSL Router und Netzwerkproblem aus, außer die lokale Firewall wäre im Spiel:

TEST:
systemctl stop firewalld
Anruf => kein Klingeln
systemctl start firewalld

Das wars nicht. Hatte Jitsi ein Update ? Seit Monaten nicht mehr.  Fällt somit als Ursache auch weg.  Hmm…

2 Tage und eine systematische Suche später ..

Das Problem, das  Jitsi keine SIP Calls mehr annehmen konnte, ist behoben worden.

Es lag NICHT an Jitsi, Sipgate, den Mäusen, dem DSL Router, den Kabeln, der Firewall sondern an :  JAVA.

Die Ursache

Fedora hat vor zwei Tagen ein neues openjdk 1.8.0.141_b16 eingespielt, das hat Jitsi und vermutlich andere Apps beeinträchtigt. Das Update war als Security Update markiert, es ist also potentiell gefährlich, die App weiter zu betreiben. Ist es in dem Fall nicht, da das Update pauschal als Security Update eingestuft wurde, weil 4 Security Tests beim Build nicht liefen. Dazu noch eine Menge normaler Updates, von denen vermutlich eins die Ursache ist.

Der Workaround

Der schnellste Workaround ist natürlich, Java zu downgraden auf die letzte funktionierende Version:

java-1.8.0-openjdk-1.8.0.131-5.b12.fc25.x86_64.rpm
java-1.8.0-openjdk-devel-1.8.0.131-5.b12.fc25.x86_64.rpm
java-1.8.0-openjdk-headless-1.8.0.131-5.b12.fc25.x86_64.rpm
java-1.8.0-openjdk-javadoc-1.8.0.131-5.b12.fc25.noarch.rpm

Wenn man das jetzt mit „dnf downgrade java-*“ macht, landet man bei einer uralten Version, was Securitymäßig keine gute Idee ist. Also lädt man die Pakete hier runter:

https://kojipkgs.fedoraproject.org//packages/java-1.8.0-openjdk/1.8.0.131/5.b12.fc25/noarch/java-1.8.0-openjdk-javadoc-1.8.0.131-5.b12.fc25.noarch.rpm
https://kojipkgs.fedoraproject.org//packages/java-1.8.0-openjdk/1.8.0.131/5.b12.fc25/x86_64/java-1.8.0-openjdk-headless-1.8.0.131-5.b12.fc25.x86_64.rpm
https://kojipkgs.fedoraproject.org//packages/java-1.8.0-openjdk/1.8.0.131/5.b12.fc25/x86_64/java-1.8.0-openjdk-devel-1.8.0.131-5.b12.fc25.x86_64.rpm
https://kojipkgs.fedoraproject.org//packages/java-1.8.0-openjdk/1.8.0.131/5.b12.fc25/x86_64/java-1.8.0-openjdk-1.8.0.131-5.b12.fc25.x86_64.rpm

Aber natürlich nur passenderweise für Fedora 25, andere Versionen bitte selbst bei koji suchen.

Nicht vergessen: /etc/dnf/dnf.conf editieren und java auf die Sperrliste setzen, sonst kommt das Update gleich wieder rein.

Warum ist jetzt der Downgrade auf b12 akzeptable und der auf die Fedora Downgrade Version nicht ?

Weil Jitsi nur Verbindungen zu bestimmten, vertrauenswürdigen Servern aufnimmt. Es ist daher kaum möglich etwaige SecBugs in Java über diesen Channel auszunutzen, zumal in der ML von OpenJAVA keine Hinweise zu Securitybugs enthalten waren. 4 Tests beim Build failten, das kann alles sein. in nächster Zeit wird es sicher Updates von Jitsi geben, damit es auch mit der aktuellen Java Version läuft, denn es steht zu befürchten, daß Openjdk, den „Bug“ nicht fixt.

Linuxkernel 4.7/4.8 und der OOM-Killer

Es ist mal wieder soweit:  „mir ham a problem“ (cnr)

Leider ist es kein witziges Problem, deswegen ist der Gag oben auch echt unangebracht, aber wie das so ist, Menschen versuchen ernste Probleme mit Humor zu vereinfachen. Vermutlich geben die „Forscher“ Ihren tollen Sicherheitslücken deswegen Namen wie „Dirty COW“ oder „Poodle“.

Out-Of-Memory

Wie Ihr schon im Beitrag über das Abschalten der RAM Disk für /tmp lesen konntet, sind OOM Probleme grade meine Hauptsorge #1.  Seit Kernel 4.7.2 häufen sich die Meldungen, daß  Systeme mit exorbitant viel RAM keinen Speicher mehr haben. Das Kürzel ist OOM was für Out-Of-Memory steht und die dafür zuständige Kernelkomponente ist, na wer räts? Der OOM-Killer 🙂

Mein aktuelles Sorgenkind hat 10 GB RAM und benutzt davon im Normalfall 1.5 GB, der Rest geht für Caches drauf, was die Performance des Systems erhöht, aber auch die Ursache sein könnte, denn mit 8.5 GB freiem Speicher, kann man wohl kaum im normalen Betrieb einen OOM produzieren, wenn man einen Webserver betreibt. Es gibt nur einen Grund wieso ein OOM passieren kann : Die Anforderung an RAM ist größer als der freie Speicher + Swap .

Ursachenforschung

Bei der Analyse des Problems fiel auf, daß SWAP überhaupt nicht benutzt wird, wenn es zum OOM kommt, was nur bedeuten kann, der Algorithmus des OOM-Mechanismuses im Kernel hat einen Bug. Wie es der Zufall so will, hatte das 16 GB Laptop von Linus Torvalds im September einen OOM Vorfall, welcher Mr. Linux dazu gebracht hat, eine Email dazu rumzuschicken. In der Email findet sich der Hinweis, daß Linus vermutet, ein 1 KB Ramrequest hätte seine 16 GB Maschine zum OOM gezwungen. Ferner entnehmen wir der Email, daß im Kernel 4.7 ein neuer Patch für OOM Situationen implementiert wurde:

"I'm afraid that the oom situation is still not fixed, and the "let's
die quickly" patches are still a nasty regression." (Linus Torvalds, 18.9.2016)

Nun passiert das zum Glück nicht nur mir, weil mir ja sonst wieder Paranoia und „unsupported systemconfigurations“ vorgeworfen würden 😉 . Einer der Bugreporter bei Redhat berichtet dann auch, daß er das verhindern konnte, indem er einen Cron eingerichtet hat, der alle 2 Stunden die Caches auf die Platte geflusht hat.

Ob Cacheflushen hilft ?

sync && echo 1 > /proc/sys/vm/drop_caches

Natürlich werde ich das ausprobieren, denn wenn das funktioniert, ist die Ursache sehr wahrscheinlich Memory Fragmentation caused by Cacheallocations. Das würde nämlich passen. Der Server hat immer dann Probleme, wenn viel Cachespeicher in Gebrauch ist. Caches bauen sich nicht so auf, daß der Kernel sieht „oh jetzt habe ich 8 GB frei, laß mal 8 GB am Stück belegen, ich gebs frei, wenn einer was will“ sondern das wird Portionsweise gemacht, mal hier 100 MB, da mal 200 MB, wie die Aktivitäten des Systems das eben grade brauchen. d.b. Selbst wenn keine neuen Prozesse über die Zeit dazu kämen und Speicher bräuchten, würde der freie Speicher in Cacheblöcke aufgeteilt, die wiederum nach Benutzung ggf. freigegeben und neu alloziert werden.

1 Woche Memorystatistiken

1 Woche Memorystatistiken und solange die Caches klein waren, gab es keine OOMs.

Dies ist ein hochdynamischer Vorgang, den man sich als Laie schwer vorstellen kann. Selbst Cachblöcke werden intern über einen Poolingalgorithmus verwaltet, d.b. der Kernel nimmt mehr freien Speicher als er grade braucht in der Annahme, daß der in Zukunft schon belegt werden wird. Daher gibt es im MemoryPool Funktionen Speicher innerhalb eines Pools zu allozieren oder freizugeben : Speicherverwaltung in Speicherblöcken.

Memorypools

Das ist beileibe keine neue Erfindung, das hatte schon ein Amiga 1988 zu bieten. So ein MemoryPool ist sogar extrem sinnvoll in dynamischen Situationen, weil man damit Verwaltungslasten vom System auf einen Prozess umlagert (Stichwort Selbstorganisation). Der Kernel muß sich um weniger Speicherbereiche kümmern, was den Aufwand minimiert und die Speicherverwaltungsketten für Speicherblöcke minimiert. Das schafft quasi „Übersicht“ und ist für alle schneller, weil er bessere Entscheidungen treffen kann.

OOM im Logfile

Damit Ihr einen OOM erkennen könnt, so sieht der im Logfile aus :

Nov 16 20:28:52 {VMNAME} kernel: Out of memory: Kill process 4348 (java) score 36 or sacrifice child
 Nov 16 20:28:52 {VMNAME} kernel: Killed process 4348 (java) total-vm:1415176kB, anon-rss:411284kB, file-rss:16108kB, shmem-rss:0kB
 Nov 16 22:09:07 {VMNAME} kernel: mysqld invoked oom-killer: gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=1, oom_score_adj=0
 Nov 16 22:09:07 {VMNAME} kernel: mysqld cpuset=/ mems_allowed=0
 Nov 16 22:09:07 {VMNAME} kernel: CPU: 1 PID: 670 Comm: mysqld Not tainted 4.7.10-100.fc23.i686+PAE #1
 Nov 16 22:09:07 {VMNAME} kernel: c0e18967 cebd2808 0000020f d0fd5d30 c0753527 c6b34200 00000021 d0fd5d78
 Nov 16 22:09:07 {VMNAME} kernel: c05d8adf c0d35b0c ca15a574 027000c0 d0fd5e6c 00000001 00000000 d0fd5d58
 Nov 16 22:09:07 {VMNAME} kernel: c0b4133d d0fd5d78 c075928f ecfa6000 00000000 c0e29320 c6b34200 00000021
 Nov 16 22:09:07 {VMNAME} kernel: Call Trace:
 Nov 16 22:09:07 {VMNAME} kernel: [<c0753527>] dump_stack+0x58/0x81
 Nov 16 22:09:07 {VMNAME} kernel: [<c05d8adf>] dump_header+0x4d/0x18f
 Nov 16 22:09:07 {VMNAME} kernel: [<c0b4133d>] ? _raw_spin_unlock_irqrestore+0xd/0x10
 Nov 16 22:09:07 {VMNAME} kernel: [<c075928f>] ? ___ratelimit+0x9f/0xf0
 Nov 16 22:09:07 {VMNAME} kernel: [<c057426b>] oom_kill_process+0x1db/0x3c0
 Nov 16 22:09:07 {VMNAME} kernel: [<c047556a>] ? has_capability_noaudit+0x1a/0x30
 Nov 16 22:09:07 {VMNAME} kernel: [<c0573bdd>] ? oom_badness.part.14+0xad/0x120
 Nov 16 22:09:07 {VMNAME} kernel: [<c057463b>] out_of_memory+0x18b/0x2c0
 Nov 16 22:09:07 {VMNAME} kernel: [<c057920c>] __alloc_pages_nodemask+0xccc/0xd20
 Nov 16 22:09:07 {VMNAME} kernel: [<c05795cf>] alloc_kmem_pages_node+0x2f/0xa0
 Nov 16 22:09:07 {VMNAME} kernel: [<c04693a4>] copy_process.part.38+0xf4/0x1490
 Nov 16 22:09:07 {VMNAME} kernel: [<c0454ab1>] ? pvclock_clocksource_read+0xa1/0x160
 Nov 16 22:09:07 {VMNAME} kernel: [<c0454ab1>] ? pvclock_clocksource_read+0xa1/0x160
 Nov 16 22:09:07 {VMNAME} kernel: [<c046a904>] _do_fork+0xd4/0x370
 Nov 16 22:09:07 {VMNAME} kernel: [<c0761756>] ? _copy_to_user+0x26/0x30
 Nov 16 22:09:07 {VMNAME} kernel: [<c046ac8c>] SyS_clone+0x2c/0x30
 Nov 16 22:09:07 {VMNAME} kernel: [<c040377e>] do_int80_syscall_32+0x5e/0xc0
 Nov 16 22:09:07 {VMNAME} kernel: [<c0b41891>] entry_INT80_32+0x31/0x31
 Nov 16 22:09:07 {VMNAME} kernel: [<c0b40000>] ? rt_mutex_futex_unlock+0x30/0x40
 Nov 16 22:09:08 {VMNAME} kernel: Mem-Info:
 Nov 16 22:09:08 {VMNAME} kernel: active_anon:183856 inactive_anon:113422 isolated_anon:0#012 active_file:1090753 inactive_file:852861 isolated_file:0#012 unevictable:0 dirty:0 writeback:2 unstable:0#012 slab_reclaimable:54066 slab_unreclaimable:12950#012 mapped:32115 shmem:173 pagetables:4656 bounce:0#012 free:271310 free_pcp:0 free_cma:0
 Nov 16 22:09:08 {VMNAME} kernel: DMA free:2328kB min:16kB low:20kB high:24kB active_anon:0kB inactive_anon:0kB active_file:1256kB inactive_file:264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15996kB managed:4472kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:300kB slab_unreclaimable:212kB kernel_stack:16kB pagetables:40kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:336 all_unreclaimable? no
 Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 579 10099 10099
 Nov 16 22:09:08 {VMNAME} kernel: Normal free:4724kB min:3068kB low:3832kB high:4596kB active_anon:220kB inactive_anon:292kB active_file:161300kB inactive_file:133144kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:720888kB managed:604904kB mlocked:0kB dirty:0kB writeback:0kB mapped:240kB shmem:0kB slab_reclaimable:215964kB slab_unreclaimable:51588kB kernel_stack:4704kB pagetables:18584kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
 Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 0 76160 76160
 Nov 16 22:09:08 {VMNAME} kernel: HighMem free:1078188kB min:512kB low:13108kB high:25704kB active_anon:735204kB inactive_anon:453396kB active_file:4200456kB inactive_file:3278036kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9748488kB managed:9748488kB mlocked:0kB dirty:0kB writeback:8kB mapped:128216kB shmem:692kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
 Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 0 0 0
 Nov 16 22:09:08 {VMNAME} kernel: DMA: 18*4kB (UMEH) 16*8kB (UME) 13*16kB (UMEH) 12*32kB (UME) 14*64kB (UME) 3*128kB (UME) 1*256kB (U) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2328kB
 Nov 16 22:09:08 {VMNAME} kernel: Normal: 1100*4kB (UMEH) 3*8kB (H) 0*16kB 6*32kB (H) 2*64kB (H) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4744kB
 Nov 16 22:09:08 {VMNAME} kernel: HighMem: 10121*4kB (UM) 3475*8kB (UM) 6526*16kB (UM) 11333*32kB (UM) 4201*64kB (UM) 981*128kB (UM) 206*256kB (UM) 49*512kB (UM) 31*1024kB (UM) 9*2048kB (M) 5*4096kB (M) = 1078268kB
 Nov 16 22:09:08 {VMNAME} kernel: 1944132 total pagecache pages
 Nov 16 22:09:08 {VMNAME} kernel: 323 pages in swap cache
 Nov 16 22:09:08 {VMNAME} kernel: Swap cache stats: add 6908, delete 6585, find 321637/322832
 Nov 16 22:09:08 {VMNAME} kernel: Free swap  = 1036992kB
 Nov 16 22:09:08 {VMNAME} kernel: Total swap = 1048572kB
 Nov 16 22:09:08 {VMNAME} kernel: 2621343 pages RAM
 Nov 16 22:09:08 {VMNAME} kernel: 2437122 pages HighMem/MovableOnly
 Nov 16 22:09:08 {VMNAME} kernel: 31877 pages reserved
 Nov 16 22:09:08 {VMNAME} kernel: 0 pages hwpoisoned
 Nov 16 22:09:08 {VMNAME} kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
 Nov 16 22:09:08 {VMNAME} kernel: [  319]     0   319    17618    11423      33       4       26             0 systemd-journal
 Nov 16 22:09:08 {VMNAME} kernel: [  354]     0   354     3343      804       7       4       92         -1000 systemd-udevd
 Nov 16 22:09:08 {VMNAME} kernel: [  422]     0   422     3457      706       6       4       65         -1000 auditd
 Nov 16 22:09:08 {VMNAME} kernel: [  445]     0   445     1550       21       6       4       79             0 rpc.idmapd
 Nov 16 22:09:08 {VMNAME} kernel: [  450]    70   450     1711      902       7       4       65             0 avahi-daemon
 Nov 16 22:09:08 {VMNAME} kernel: [  453]     0   453      583      405       5       4       27             0 acpid
 Nov 16 22:09:08 {VMNAME} kernel: [  454]     0   454     9615     4806      22       4     1336             0 yum-updatesd
 Nov 16 22:09:08 {VMNAME} kernel: [  458]     0   458      989      662       5       4       23             0 systemd-logind
 Nov 16 22:09:08 {VMNAME} kernel: [  464]     0   464   128506     9331     135       4      111             0 rsyslogd
 usw. usw. usw.

Hier wird ein  Java Prozess gekillt, weil Mysql mehr Speicher brauchte 🙁

Wie man an diesen Zeilen sehen kann, war min. 4.5 GB RAM frei und der Swap wurde nicht benutzt.

 Nov 16 22:09:08 {VMNAME} kernel: Normal free:4724kB min:3068kB low:3832kB high:4596kB active_anon:220kB inactive_anon:292kB active_file:161300kB inactive_file:133144kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:720888kB managed:604904kB mlocked:0kB dirty:0kB writeback:0kB mapped:240kB shmem:0kB slab_reclaimable:215964kB slab_unreclaimable:51588kB kernel_stack:4704kB pagetables:18584kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
 Nov 16 22:09:08 {VMNAME} kernel: HighMem free:1078188kB min:512kB low:13108kB high:25704kB active_anon:735204kB inactive_anon:453396kB active_file:4200456kB inactive_file:3278036kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9748488kB managed:9748488kB mlocked:0kB dirty:0kB writeback:8kB mapped:128216kB shmem:692kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
 Nov 16 22:09:08 {VMNAME} kernel: Free swap  = 1036992kB
 Nov 16 22:09:08 {VMNAME} kernel: Total swap = 1048572kB

Wenn man sich den Thread auf der Kernel-ML weiter durchliest, kommt raus, daß erst mit Kernel 4.9 mit einer Verbesserung zu rechnen ist. Ab 4.9 wird ein anderer Algorithmus benutzt, der „härter“ versuchen soll, den OOM zu verhindern. Man wird sehen.

Update 18:00 Uhr :

Das Wegflushen der Filecache hat nichts gebracht. Aber Kernel 4.6.8 sollte noch keine oom’s produzieren. Das beinhaltet aber wieder eine Angriffsfläche für den Dirty COW Exploit.