Hängende Threads / IPS verreckt plötzlich ab 0 Uhr

Slummi · 27. Dezember 2021 um 00:30

Hi,

seit Weihnachten spinnt mein IPS plötzlich und ich habe keine Ahnung, warum.
Am 2. Weihnachtstag werde ich morgens wach und stelle fest, dass im Haus nichts mehr funktioniert, was über IPS läuft. Das WebFront war per Connect nicht erreichbar, Alexa verweigerte ihren Dienst, Automationen liefen nicht… Über LAN kam ich noch aufs WebFront, aber sehr zögerlich und es funktionierte auch dort nicht viel.

Also habe ich die Konsole aufgemacht und wurde direkt mit ein paar hunderttausend Fehlern begrüßt: Zu viele Skripte, die gleichzeitig ausgeführt werden. Also noch die PHP-Threads angesehen und alle verfügbaren Threads waren voll und rot. Ich habe dann versucht remote auf den Server (Windows) zu kommen, um den Dienst zu beenden, was wegen 100 % CPU-Auslastung durch den IPS-Dienst nicht ging. Dann habe ich versucht den Dienst remote zu beenden. Das Absetzen des Befehls hat auch funktioniert und IPS hat mit dem Beenden des Dienstes begonnen, aber wurde damit nicht fertig. Nach einer halben Stunde warten, habe ich den Dienst dann hart gekillt. Ich habe mir danach die Logs angesehen und festgestellt, dass das Drama genau um 0 Uhr anfing. Allerdings konnte ich keinen wirklichen Übeltäter ausfindig machen. Es wurden halt alle möglichen Skripte ausgeführt, die sonst auch (ohne Probleme) laufen. Nur liefen wohl immer mehr parallel und wurden nicht fertig, sodass es kurz nach 0 Uhr zu den Fehlermeldungen kam.

Ich habe den Server dann wieder neu gestartet und direkt einen Blick in die Threads geworfen. Auffällig war, dass ein Skript, welches seit Jahren unverändert minütlich ausgeführt wird, direkt jede Minute rot einen neuen Thread belegte. Ich habe dann den Timer für das Skript deaktiviert und gewartet. Zunächst blieben die paar Threads weiter rot belegt, andere Threads liefen normal weiter. Dann kamen alle neuen Threads plötzlich direkt von Beginn an rot rein, verschwanden aber auch sofort wieder. Skripte, die ich in der Konsole manuell ausgeführt habe, liefen zwar, wurden aber in den Threads gar nicht angezeigt. Ich habe dann weiter abgewartet und beobachtet und irgendwann normalisierte sich alles und das System lief wieder ganz normal. Alle Threads wurden direkt abgearbeitet und auch die paar hängen gebliebenen Threads vom Anfang waren plötzlich weg. Der Server schnurtte dann den Rest des Tages vor sich hin als wäre nichts gewesen.

Irgendwie traute ich dem Frieden aber nicht und habe mich eben um 0 Uhr wieder auf die Lauer gelegt. Pünktlich fing das Theater wieder an. Das WebFront reagierte zwar noch, wurde aber merklich langsamer. Also wieder die Konsole auf und die Threads angeschaut. Hier waren noch viele frei, aber es hingen auch schon wieder eine ganze Reihe 0 Uhr Threads. Das System wurde immer langsamer, die CPU war wieder bei 100 % und nichts funktionierte mehr so richtig. Neue Threads wurden mit vielen Minuten Verspätung (Startzeitpunkt) angezeigt. Meldungen trudelten ebenfalls mit ewig Verspätung ein, obowhl immer noch Threads frei waren. Ich habe wieder versucht den Dienst remote zu beenden. Gleiches Spiel wie gestern. Der Server fängt an runter zu fahren, führt auch die Shutdown-Skripte aus, wird aber nicht fertig, weil er vermutlich noch auf das ganze hängende Zeugs wartet. Also wieder alles hart gekillt und den Server neu gestartet.

Hat von euch jemand eine Idee, wo ich mit der Fehlersuche beginnen soll? Wenn ich irgendwas geändert hätte, würde ich es ja verstehen. Aber ich habe das System die letzte Zeit nicht angefasst und ich kann auch kein bestimmtes Skript identifizieren, was Probleme macht. Mal hängt das eine, mal das andere und es ist eigentlich auch nichts dabei, was datumsabhängig seit Weihnachten etwas anders machen würde also zuvor. Und warum geht der Spuk immer um 0 Uhr los? Klar gibt es auch ein paar Skripte, die um 0 Uhr oder kurz danach einmalig ausgeführt werden. Aber auch daran hat sich seit Ewigkeiten nichts geändert und es läuft seit Jahren.
Ich dachte auch erst, dass der Server vielleicht irgendeine Macke hat. Aber dann würde ich bei anderen Diensten auch Probleme erwarten. Aber es ist immer nur der IPS-Dienst, der um 0 Uhr plötzlich die CPU komplett mit 100 % für sich beansprucht.

Ich bin gerade etwas ratlos, was die Ursache sein könnte. Ich nutze übrigens IPS 6.0 (die letzte Stable) unter Windows Server 2008. Und auch das schon seit Wochen…

Gruß
Slummi

HarmonyFan · 27. Dezember 2021 um 08:06

Hi,
wenn der Zauber anfängt sollte der Verantwortliche zu dieser Zeit im Log erscheinen. Ich hatte so ein ähnliches Problem es war aber selbst gemacht. Zu einer gewissen Zeit startete bei mir ein Script das alle Variablen des Archivs nach Unstimmigkeiten durchsucht, sie behebt und neu aggregiert. Ich hatte einen Timer von 10 Sekunden zwischen den Variablen. Wenn die Ausführung aber länger als 10 Sekunden dauert schaukelt es sich auf. Ob/wann es auftritt hing davon ab wie sauber die Werte im Archive sind. Ich kam auch nur mit einem Neustart von IPS raus.

Vielleicht hilft das bei der Suche.

Ralf

Slummi · 27. Dezember 2021 um 09:08

Hi Ralf,

danke schon mal für deinen Tipp. Wie genau erkenne ich denn den Verantwortlichen im Log? Dass er dort auftaucht, davon bin ich überzeugt, aber was hast du als Indikator herangezogen, um zu beurteilen, dass genau das eine Skript der Verursacher ist. Ich habe ja eine Vielzahl an Skripten im Log.

Heute Nacht hatte ich ein wenig Zweifel, ob nicht doch der Server selbst irgendein Problem hatte. Nachdem ich den IPS-Dienst schon längerere Zeit gekillt hatte und das System wieder stabil lief, habe ich vorsichtshalber den Server noch neu gestartet. Interessanterweise kam genau in dem Moment des Neustarts plötzlich eine Flut an (alten) IPS-Push-Nachrichten auf meinem Handy an und das, obwohl der Dienst ja schon längst nicht mehr lief. Als ob da auf dem Server irgendwas in Richtung Netzwerk steckengeblieben wäre…

Ich suche gleich mal weiter. Im Moment schnurtt wieder alles zuverlässig vor sich hin. Mal sehen, was heute Nacht zur Geisterstunde passiert.

Gruß
Slummi

HarmonyFan · 27. Dezember 2021 um 10:16

Hi,
ich habe mir jeweils den Script angeschaut was er macht. Meistens ist das eine Sache die wird ausgeführt und dann ist einfach Ende. Ich hatte ein Script das einen Timer 10sec anlegte in der Hoffnung das der vorhergehende Durchlauf weniger als 10 Sekunden braucht. Dauert es jetzt länger wird dieser Script wieder und wieder aufgerufen und irgendwann ist schluss. Ich habe auch ein Script laufen das mir laufende Scripte anzeigt wenn > 20 Threads laufen. Das script kann aber auch behindert werden so das es keine 100% Hilfe ist.

Hier das Script:

<?
$scriptName = IPS_GetName($_IPS['SELF']);

$now = time();

$threadList = IPS_GetScriptThreadList();

$s = '';
$threadCount = 0;

foreach ($threadList as $t => $i) {
    $thread = IPS_GetScriptThread ($i);

    $ScriptID = $thread['ScriptID'];
    if ($ScriptID == 0) {
        continue;
    }

    if ($ScriptID != $_IPS['SELF']) {
        $threadCount++;
    }
    $ScriptName = IPS_GetName($ScriptID);
    
    $ThreadId = $thread['ThreadID'];

    $StartTime = $thread['StartTime'];
    $sec = $now - $StartTime;
    $warn = $sec > 10 ? '!!!' : '';
    $duration = '';
    if ($sec > 3600) {
        $duration .= sprintf('%dh', floor($sec / 3600));
        $sec = $sec % 3600;
    }
    if ($sec > 60) {
        $duration .= sprintf('%dm', floor($sec / 60));
        $sec = $sec % 60;
    }
    if ($sec > 0 || $duration == '') {
        $duration .= sprintf('%ds', $sec);
        $sec = floor($sec);
    }

    $Sender = $thread['Sender'];
    
    $s .= "\nthread=$ThreadId, script=$ScriptName($ScriptID), sender=$Sender, duration=$duration $warn";
}

if ($threadCount > 20) {
    IPS_LogMessage($scriptName . '(' . $_IPS['SELF'] . ')', $s);
} 
?>

ist nicht von mir hatte ich hier mal gefunden.

Ralf

Slummi · 27. Dezember 2021 um 11:07

Cool, danke! Werde ich mal testen. Die undokumentierten Funktionen zu den Threads kannte ich noch gar nicht.
Weiß zufällig jemand, was die Werte von ExecutionMin, ExecutionAvg, ExecutionMax der Funktion IPS_GetScriptThread() für eine Einheit haben? Ich vermute mal Milisekunden?!

Noch eine allgemeine Frage zur Threadliste. Ist das nicht ein untypisches Verhalten, wenn neue Threads verspätet eintrudeln und direkt rot in der Liste markiert werden, obwohl an sich noch freie Threads verfügbar sind? Ich dachte, dass die erst gepuffert werden, wenn alle verfügbaren Threads belegt sind. Das Verhalten habe ich im Fehlerfall mehrfach beobachtet.

Gruß
Slummi

paresy · 27. Dezember 2021 um 12:28

Öffnet dir sonst kurz vor 0 Uhr mal die PHP Informationen. Dann siehst du definitiv wer alle „Slots“ belegt.

paresy

KaiS · 27. Dezember 2021 um 12:31

Könnt hier nicht auch Prometheus Exporter Modul, Dashboard für Grafana, Config für Prometheus helfen?

Grüße,
Kai

paresy · 27. Dezember 2021 um 12:48

Dort würdest du nur sehen, dass die PHP Threads ausgelastet sind und genau ab wann, aber die Ursache weniger, da die aktuell laufenden Skripte nicht angezeigt werden.

paresy

Slummi · 27. Dezember 2021 um 13:19

Mhh… Ich hätte erwartet, dass ich das auch im Nachgang sehe, also wenn das Problem schon besteht. Da sind dann zwar alle Slots voll, aber da ist komischerweise nicht alles von einem Skript belegt, sondern von vielen verschiedenen. So als ob einfach jedes Skript plötzlich Probleme macht.

Ich lege mich heute Abend rechtzeitig auf die Lauer und habe vorsichtshalber „den Finger am Abzug“, um den Prozess notfalls frühzeitig zu killen. Aber wie das auf Geisterjagd so ist, könnte ich wetten, dass sich das Gespenst ausgerechnet dann nicht zeigt. Vielleicht war es ja auch nur ein Weihnachtsgeist.

Slummi · 27. Dezember 2021 um 23:13

Hach das war so klar. Natürlich passiert heute um 0 Uhr nichts, wo ich alles überwache. Alles läuft ganz normal, wie sonst auch immer.

Das Einzige, was sich seit den letzten beiden Tagen geändert hat, ist dass ich den Server einmal komplett neu gestartet habe und dass ich heute ein Update des Shelly-Moduls gemacht habe. Letzteres würde ich aber als Ursache mal ausschließen. Vielleicht hatte doch einfach der Server ein Problem… Die gesammelten Push-Nachrichten, die beim Herunterfahren des Betriebssystems kamen, obwohl der IPS-Dienst lange beendet war, machen mich immer noch stutzig.

Samoht · 27. Dezember 2021 um 23:21

Völlig ins Blaue rein:

Wenn es nur vorgestern und gestern auftrat - könnte es vielleicht was mit den (Weihnachts-)Feiertagen zu tun haben? Irgendein „Check“?

Slummi · 27. Dezember 2021 um 23:51

Danke für den Tipp. Die Idee ist gut. Da hatte ich auch schon dran gedacht. Aber ich habe bisher nichts gefunden. In einem Script berechne ich zwar die Feiertage, aber das war unauffällig.

Vielleicht sollte ich mal mit einer Kopie des ganzen Systems eine Simulation unter geändertem Datum fahren. Aber das ist auch irgendwie etwas Overkill.

Irgendwie nervt mich sowas ja. Auf der einen Seite schön, wenn ein Problem nicht mehr auftritt, auf der anderen Seite aber auch total unbefriedigend, wenn man die Ursache nicht kennt und nicht weiß, ob und wann es vielleicht wieder passiert.

Slummi · 3. Januar 2022 um 09:35

Heute Nacht war es wieder soweit und das Schreckgespenst hat zugeschlagen. Das Positive: Damit kann ich Weihnachten als Ursache schon mal ausschließen.

Da jetzt eine Woche Ruhe war, habe ich das System natürlich nicht um 0 Uhr beobachtet. Ich habe das Problem aber heute Nacht bemerkt und dann eine unfreiwillige Nachtschicht eingelegt, um den Server wieder ans Laufen zu kriegen. Ich habe jetzt erst mal die CPU-Ressourcen und die Anzahl der Kerne für den IPS-Dienst reduziert, damit beim nächsten Mal hoffentlich nicht der ganze Server platt ist, weil IPS die CPU für sich alleine beansprucht.

Was ich heute Nacht in der Konsole beobachten konnte:
Ab 00:06 Uhr kamen im Status-Fenster viele Meldungen „KernelMT - Nachricht VM_Update für ID … dauerte (zwischen 90 ms und 3223 ms) (Modul: InstanceManager)“. Die Variable war fast immer dieselbe. Die Windgeschwinidigkeit, die bei Sturm (wie es gestern der Fall war) durchaus mehrmals pro Sekunde aktualisiert wird. Das scheint aber nicht die Ursache des Problems zu sein. Diese Konstellation besteht so schon seit Jahren und hat nie Probleme gemacht. Außerdem sehe ich deartige Meldungen immer mal wieder auch für andere Variablen (warum auch immer). Vielmehr scheinen mir das die ersten Auswirkungen der hängenden Threads von 0 Uhr zu sein, die das System zunehmend verlangsamen.

Ab 00:30 Uhr kommen dann auch immer mal wieder Meldungen „Server Socket - Fehler beim Lesen/Schreiben: Das angegebene Dateihandle ist ungültig.“ hinzu. Worauf sich das genau bezieht, kann ich noch nicht sagen. Da muss ich noch mal in den Logs schauen. Aber auch hierbei handelt es sich wohl eher um die Auswirkungen des langsam werdenden Systems.

Um 00:49 Uhr kommt es dann erstmalig zu dem Fehler „ScriptEngine - Zu viele gleichzeitige Skripe. Verwerfe Ausführung…“. Das zieht sich dann bist zum Killen des Dienstens durch.

Beim Blick in die PHP-Threads (um 02:15 Uhr) dann wieder das gleiche Bild, wie bei den letzten Malen:
Alle Slots sind belegt und rot. Dabei gibt es ein Skript, welches ich bei den letzten Malen auch gesehen habe, was genau einmal mit Startzeit 00:00:00 einen Slot belegt (also mehrere Stunden nach der Startzeit noch läuft). Die anderen Slots werden von anderen Skripten belegt. Dabei liegen die Startzeiten alle um 01:50 Uhr rum (+/- ein paar Minuten), also etwa 25 Minuten Verzug.

Damit würde ich erst mal das Skript von 0 Uhr in die Liste der engeren Verdächtigen packen und dieses vorübergehend deaktivieren.

Falls es dieses Skript sein sollte (welches minütlich ausgeführt wird), stelle ich mir aber drei Fragen:

Warum sehe ich das Skript nur einmal in den Threads mit Ausführungszeit 0 Uhr und dann erst wieder ab 01:50 Uhr, wenn es doch minütlich ausgeführt wird. Daraus schließe ich, dass es um 0 Uhr einmal hängen bleibt und dann die weiteren Male normal ausgeführt wird, bis es mit den anderen Skripten irgendwann in der vollen Thread-Queue stecken bleibt und 25 Minuten hinterher hängt.
Wenn das eine Mal um 0 Uhr der Auslöser ist, kann denn ein einzelner Thread das ganze System zum Erliegen bringen, obwohl zunächst noch zig freie Slots verfügbar sind? Also kann ein Thread exklusiv alle CPU-Ressourcen für sich beanspruchen, sodass alle anderen nix mehr abbekommen oder zumindest nur noch so wenig, dass sich die ganze Queue nach und nach füllt und alles hochschaukelt, bis nichts mehr geht?
Wenn 2. zutreffen sollte: Habe ich irgendeine Möglichkeit, die Ressourcen für einen einzelnen Thread zu limitieren? Früher hätte ich ja zumindest über die maximale Ausführungszeit noch ein Sicherheitsnetz einbauen können, aber die Möglichkeit fällt ja inzwischen leider weg.

Gruß
Slummi

Edit: Die Meldungen zum Server Socket bezogen sich alle auf den MQTT-Server. Habe mir das gerade noch mal aus den Logs raus gesucht.

remote-it · 7. Januar 2022 um 07:32

Moin Männers,

ich habe nun auch zum zweiten Mal das Problem, das ich
‚Zu viele gleichzeitige Skripte.‘ hatte und mir das System auf den Bauch fiel.

Beide Male war es jeweils die gleiche Ursache:
ein Fibaro Wall Plug war ausgesteckt worden …

Dieser Effekt ist in den letzten Jahren NIE passiert - was hat sich geändert bzw. wie kann ich das abfangen ?

Ach ja: Version 6.0 vom 28.08.21 auf WIN10 Pro

LG Tom

HarmonyFan · 7. Januar 2022 um 07:59

Hi,
schon mal die Abhängigkeiten angesehen wer alles etwas vom Wall-Plug will?

Ralf