Debian 10 auf Debian 11 Update

[MockZ]

Hallo,

nach dem holprigen Upgrade (siehe einige Beiträge vorher) läuft der Server stabil – lediglich Einstellungen an der Firewall kann ich nicht machen. Ich lande immer auf einer weißen Browserseite. Da meine Änderungen übersichtlich waren, könnte ich auch alle Einstellungen zurücksetzen. Nur: wie fange ich das an?

Gruß
Mock

[Alexander]

Was sagt das Log unter /var/log/keyhelp/php-error.log in dem Moment, wenn du auf die Firewall-Seite klickst?

[MockZ]

Unter Firewall ist der Button neben Status: „Firewall ist aktiviert”. Nach dem Klick wieder weiße Seite und im /var/log/keyhelp/php-error.log folgende neue Zeilen:

Code: Select all

[06-Oct-2021 17:04:07 Europe/Berlin] PHP Warning:  unlink(/etc/keyhelp/iptables/startup_rules_ipv4): No such file or directory in /home/keyhelp/www/keyhelp/core/Firewall/Iptables.php on line 267
[06-Oct-2021 17:04:07 Europe/Berlin] PHP Warning:  unlink(/etc/keyhelp/iptables/startup_rules_ipv6): No such file or directory in /home/keyhelp/www/keyhelp/core/Firewall/Iptables.php on line 267
[06-Oct-2021 17:04:07 Europe/Berlin] PHP Warning:  file_put_contents(/etc/fail2ban/jail.d/keyhelp.local): failed to open stream: Permission denied in /home/keyhelp/www/keyhelp/core/pending/File.php on line 341
[06-Oct-2021 17:04:07 Europe/Berlin] PHP Warning:  chown(): Operation not permitted in /home/keyhelp/www/keyhelp/core/pending/File.php on line 358
[06-Oct-2021 17:04:07 Europe/Berlin] PHP Warning:  chgrp(): Operation not permitted in /home/keyhelp/www/keyhelp/core/pending/File.php on line 359
[06-Oct-2021 17:04:07 Europe/Berlin] PHP Fatal error:  Could not save file "/etc/fail2ban/jail.d/keyhelp.local" in /home/keyhelp/www/keyhelp/core/Firewall/Iptables.php on line 694

[MockZ]

Ich antworte gleich mal selbst:

/etc/fail2ban/jail.d/keyhelp.local auf User/Group keyhelp/keyhelp gesetzt. Schon gehts.

Gruß
Mock

[Alexander]

Sehr schön.

Die Änderung der Dateirechte kam eigentlich mit Einführung der neuen Firewall-Verwaltung Ende 2020. Warum die Datei bei dir immer noch auf root:root steht ist komisch , aber funktioniert ja jetzt bei dir.

[TiDschay]

Hier wurde scheinbar noch nicht alles bzgl. der geänderten PHP-Version entfernt. Zum Beispiel wird an der WARNING-verursachenden-Stelle "phpenmod" ausgeführt. Dieser ist bei dir noch mit php 8.0 verknüpft.

Ich habe noch verschiedenes Versucht, hat aber alles nichts mehr gebracht. Das Ende von Lied war, dass ich Deb.11 installiert habe und alles von neu eingegeben habe. War auch nicht so schlimm, denn der Server steht hier neben mir und hat nur Domains drauf, mit denen ich arbeite. Also nach der Neuinstallation das Backup der Seiten drüber und fertig .

Danke für die Hilfe und noch einen schönen Tag zusammen...

[tab-kh]

So, habe gestern am späten Abend auch meinen Testserver auf Debian 11 gebracht. Hat prima funktioniert mit dem Skript, es scheint erst einmal alles normal zu funktionieren. Ok, logwatch hat mich heute Morgen geschockt, weil Kernel Errors angezeigt wurden. Da das apparmor betraf, habe ich halt kurz in die Logdateien geschaut und festgestellt, dass das wie erwartet nur während des Upgrades vorkam und habe erst einmal beschlossen das zu ignorieren. Ich schaue mir aber jetzt erst einmal eine Weile die Logdateien dieses Servers genauer an als sonst. Dabei bin ich auf eine Meldung gestossen, die ich bisher noch nie hatte - oder jedenfalls noch nie bemerkt habe .

Code: Select all

Oct  7 14:25:01 fanny CRON[45921]: (root) CMD (nice -n 5 php /home/keyhelp/www/keyhelp/cronjob/mastercronjob.php)
Oct  7 14:25:14 fanny mariadbd[967]: 2021-10-07 14:25:14 1338 [Warning] Aborted connection 1338 to db: 'keyhelp' user: 'keyhelp' host: 'localhost' (Got timeout reading communication packets)
Oct  7 14:26:01 fanny CRON[45961]: (root) CMD (nice -n 5 php /home/keyhelp/www/keyhelp/cronjob/mastercronjob.php)

Ist aber bisher nur dieses eine Mal aufgetreten. Naja, so furchtbar lang läuft er ja auch noch nicht mit Debian 11 . Dass der Server so fürchterlich überlastet gewesen sein soll zu der Zeit, dass er die Datenbankkommunikation nicht mehr hinbekommt, ist eigentlich schwer vorstellbar. Und was macht er zu der Zeit überhaupt mit der Datenbank? Ich war auch nicht im Keyhelp Panel angemeldet. Der dürfte zu der Zeit eigentlich mehr oder weniger nur Däumchen gedreht haben. Da kann er sich mit seinen vier dedizierten Cores eigentlich höchstens einen Knoten in die Daumen gemacht haben. Ich kann jedenfalls zu der Zeit in den sonstigen Logdateien außer eben der syslog auch nichts dazu finden. Auch keine PHP-Errors.

Was könnte so etwas verursachen? Mir fällt jedenfalls momentan keine schlüssige Erklärung ein.

[Alexander]

Der zuvor ausgeführte Befehl...

"php /home/keyhelp/www/keyhelp/cronjob/mastercronjob.php"

...startet die Wartungsjobs. Je nachdem welcher Job gerade ansteht werden hier verschiedene Wartungsaufgaben ausgeführt. Welcher das war, steht im mastercronjob.log (Im KeyHelp unter Protokolle) zum Zeitpunkt "Oct 7 14:25:01"

Der DB-Verbindungsaufbau erfolgt aber direkt im mastercronjob.php - sollte es hierbei zu Problemen gekommen sein (die er nicht selbst lösen konnte) müsste das auch im Log vermerkt sein.

[tab-kh]

Da hatte ich natürlich schon relativ intensiv gesucht.
Die master.log.1 sagt

Code: Select all

[PID-45922] [07-Oct-2021 14:25:01] INFO  --> jobs to run: update.php
[PID-45922] [07-Oct-2021 14:25:01] INFO  --> >>> trying to run "update"
[PID-45922] [07-Oct-2021 14:25:01] INFO  --> lock "update" acquired
[PID-45922] [07-Oct-2021 14:25:01] INFO  --> processing the job ...
[PID-45922] [07-Oct-2021 14:25:01] INFO  --> <<< job done, releasing lock "update"

Und update.log

Code: Select all

[07-Oct-2021 14:25:01] INFO  --> load tasks... nothing to do

Ist halt für mich im Moment unklar, was da passiert ist bzw warum. Die beiden obigen Logs interpretiere ich so, dass der/die Cronjobs für 14:25 zum Zeitpunkt der Warnung um 14:25:14 bereits komplett abgearbeitet waren. Kann es sein, dass der MariaDB-Server aus irgendeinem Grund 13 Sekunden nicht antwortet, ohne dass das zu weiteren Logeinträgen führt?
Wie gesagt, ist auch nur einmal aufgetreten und seitdem nicht mehr. Wäre das auf einem der Server mit Debian 10 passiert, die seit Monaten laufen, hätte ich das wahrscheinlich nicht so intensiv verfolgt. Aber bei einem frisch auf Debian 11 upgegradeten Server bleibt halt immer der Verdacht, dass es mit dem Upgrade zu tun haben könnte. Ich warte mal bis heute 14:25 ... Ich sehe da zwar keine Aufgaben, die um diese Uhrzeit täglich abgearbeitet werden müssten aber wer weiss, vielleicht passiert es ja wieder. Vielleicht muss ich auch einfach mal den Datenbankserver ordentlich stressen um zu sehen ob da eventuell was faul ist. Die MariaDB-Version hat sich ja auch ziemlich verändert. Bei den Konfigurationsdateien habe ich immer die bestehenden übernommen und nicht die mitgelieferten, müsste da eventuell irgendwas für die neue MariaDB-Version geändert/angepasst werden?

Aber gut, wenn weiterhin nichts passiert hake ich es halt als einmaliges, unerklärliches Ereignis ab, bzw kontrolliere noch eine Weile täglich, ob es nochmal aufgetreten ist Es war eh mehr oder weniger Zufall, dass ich die Meldung überhaupt gesehen habe.

[Alexander]

Der Eintrag muss auch noch nicht mal von KeyHelp direkt kommen:
Der KeyHelp-Datenbank-Account ist zum Beispiel auch im Postfix / Dovecot / Amavis / ProFTPd hinterlegt, damit diese Tools auf die Datenbank und die dort angelegten Accounts zugreifen können. Vielleicht kam also der Zugriff um 14:25:14 von einen dieser Dienste.

Ich würde das nicht überbewerten. Ich kann zwar nur für meine Software sprechen, aber da ist die DB Verbindung entsprechend so robust, dass er bei so einem einem kleinen Datenbank-Schluckauf sich einfach neu verbindet und gut ist. Ggf. machen das die Anderen auch so. Wenn mit der DB wirklich was im argen wäre, dann würde sich das wahrscheinlich deutlich stärker bemerkbar machen. Solltest du aber noch etwas herausfinden, dann gern melden .

(Also auch nicht verwundern lassen, wenn im /var/log/keyhelp/php-error.log einmal ein paar Verbindungsabbrüche protokolliert werden, das ist i.d.R. kein Problem.)

[tab-kh]

Es wird immer mysteriöser. Also mit dem Debian Upgrade hat es wohl nichts zu tun, soweit die gute Nachricht. Aber heute, pünktlich einige Sekunden nach 14:25 war die Meldung wieder da. Ich habe dann einfach mal in die mysql error.log reingeschaut, das war eine der wenigen Logdateien in die ich bisher blöderweise noch gar nicht reingeschaut hatte. Da sah ich dann zunächst eine Reihe solche Meldungen während des Upgrades. Und auch noch eine Meldung vom Nachmittag vor dem Upgrade. Selbe Uhrzeit 14:25 + einige Sekunden. Es ist also schon vorher dagewesen! Ich habe dann mal in die älteste error.log.7 reingeschaut. Auch darin, ein Eintrag 14:25 + einige Sekunden am 29.09. Hmm. Also außer am Tag des Upgrades, immer nur ein Eintrag jeden Tag kurz nach 14:25.

Nachdem das offenbar regelmäßig auftritt, habe ich mir die mysql Logs der beiden anderen Server angeschaut. Und Bingo , fast jeden Tag um 14:25 und ein paar Zerquetschte steht da der Eintrag drin, teilweise noch einer so um die 13:30 bis 13:40. Alles KVM vServer bei netcup, zwei RS und ein VPS, könnte das irgendein Einfluss aus dem Hostsystem sein? Weil auf den Servern selbst finde ich einfach nichts was um die Zeit läuft. Muss mich wohl für morgen mal besser vorbereiten und überlegen wie ich an die Ursache rankomme.

[nikko]

Ich prüfe mal für dich meine ganzen Server ab. Dann können wir sehen, ob das ein Problem der Hosts sein könnte.

[nikko]

Ich habe diese Meldungen auch, gleich ob dedizierte Maschine oder V-Host - je kleiner die Maschine (speziell RAM), und umso mehr belegt diese ist, desto häufiger ist diese Meldung abgelegt.
Nur in einem Server erscheint diese Meldung nicht - der prüft aber auch keine eingehenden Mails auf Viren. Dieser machte aber vor Wochen zu ähnlichen Uhrzeiten Probleme - daher kann ich den "Fehler" womöglich eingrenzen:

Vermutlich macht clamav zu dieser Zeit ein Datenbankupdate (doppelte RAM Last), das würde die Regelmäßgkeit erklären. Bevor aber irgendetwas schief geht bitte ich dich, beobachte mal zu dieser fraglichen Zeit mit "top" oder "htop" den Serverload.

Auf der betreffenden Maschine habe ich in die etc/clamav/clamd.conf als letzte Zeile folgenden Code hinzugefügt, Restart nicht vergessen:

Code: Select all

ConcurrentDatabaseReload no

Quelle: https://blog.clamav.net/2020/09/clamav- ... eased.html

Aber primär gilt Alexs Aussage: "Ich würde das nicht überbewerten."

[tab-kh]

Klar, ich will das auch nicht überbewerten. Aber es interessiert mich einfach wo das herkommt. Das sind drei recht unterschiedliche Server bei mir. Ein VPS mit 6 vCores, ein RS mit zwei dedizierten Intel Cores (Xeon Gold), ein RS mit vier dedizierten AMD Epyc 7702 Cores. Den letzteren habe ich kürzlich auf Debian 11 gehoben. Auf dem läuft außer Keyhelp momentan so gut wie nichts, eigentlich nichts, keine eigenen Cronjobs, keine E-Mail Adressen oder Postfächer. Der kleine RS fungiert hauptsächlich als Mailserver und macht das klaglos ohne dabei warm zu werden. Der prüft alle Mails zu 100% auf Viren, kein Problem. Und der hat auch nicht mehr solche Fehler als der deutlich stärkere Server, der außer Keyhelps Cronjobs und ein paar russische und chinesische Spielkinder abzubügeln nichts zu tun hat. Zudem hat er die Fehler zur gleichen Uhrzeit, wenn auch um ein paar Sekunden verschoben. Deswegen kann ich nicht an eine Überlastung als Ursache glauben, schon gar nicht beim stärkeren Server. Zumal hier zu der Zeit ClamAV kein Update gemacht hat, das würde ich ja in den Logs sehen, z.B. syslog. Das startet ca um 13:40 und 14:40, weit weg von 14:25. Was Keyhelp betrifft, hat der Server zu dieser Zeit (14:25:14) eigentlich überhaupt nichts gemacht. Natürlich hat er trotzdem immer eine gewisse Grundlast mit Firewall, fail2ban und ein paar Bots, die versuchen Seiten aufzurufen die es größtenteils nicht gibt, aber die ist vernachlässigbar. Gerade mal ca 10 M OP/s verteilt auf 4 Cores.

Wenn das nicht immer fast exakt zur selben Zeit wäre auf allen drei Servern, dann hätte ich das auch bei 10 oder 20 solchen Vorkommnissen pro Tag mittlerweile längst ad acta gelegt. Ein Vorkommnis pro Tag immer zur selben Zeit macht mir da mehr Sorgen. Und vor allem macht es mich neugierig
Aber ich werde natürlich morgen die Load beobachten zu der Zeit, die wird wohl eher sehr niedrig sein. Aber vielleicht werde ich da ja schon wieder überrascht.

[tab-kh]

Gerade eben ist es wieder passiert, 14:25:06. Load average zu der Zeit und die letzten 10 Minuten davor: 0.00, 0.00, 0.00
Der Server langweilt sich einigermaßen
Als es auftrat war mariadbd der Prozess mit dem höchsten CPU-Anteil, ist ja auch halbwegs einleuchtend. Aber %CPU deutlich unter 1 (0.3).

Ab 14:48:01 wurde dann freshclam gestartet, um 14:48:24 wurde die neue DB dann bereits von clamd geladen und aktiviert. Load in diesem Zeitraum immerhin bis zu 0.22. Ich muss mir wohl was besseres einfallen lassen um die Ursache zu finden.