PHPSonos und HM frieren Dashboard und Webfront ein

Archiv Allgemeine Diskussion (2.x/3.x)
1

Guten Tag zusammen

Letzte Woche hatten wir einen Stromausfall und seit da Verhält sich mein IPS etwas seltsam.
Und zwar erhalte ich sehr oft beim Ansteuern von Sonos oder beim Schreiben/Lesen von HM-Systemvariablen einen „Maximum execution time of 30 seconds exceeded“ Fehler, was mir das Dashboard und Webfront für 2-3 Minuten einfrieren lässt. Dies passiert sehr oft, jedoch nicht immer. Eine Regelmässigkeit oder ein Muster konnte ich nicht erkennen.

Ich habe mal alles so umprogrammiert, dass die Sonos-Ansteuerung in einem eigenen Thread läuft. Auch die „maxumum execution time“ habe ich mal auf 2 Sekunden herunter gesetzt. Leider alles ohne Erfolg.

Ich verwende IPS 3.3 #3645 und habe zum testen mal bis auf 40 Threads erhöht. Das ganze läuft auf einem HP ProLiant N54L mit 8GB RAM. Sonos und die CCU sind ebenfalls auf dem neusten Stand.

Hier nun mal am Beispiel von heute Morgen von Sonos, was genau passiert. HM verhält sich ganz ähnlich.

Über das Dashboard setze ich eine Boolean-Variable, dass ich nun wach bin:

07.04.2015 05:28:54.383 | 32876 | DEBUG   | ExecuteThreadID #19  | Skriptausführung: dashboardAction.ips.php ~ Absender: RunScript
07.04.2015 05:28:54.430 | 45301 | MESSAGE | VariableManager      | [OG\Zimmer3\Taster\isMarcoSchlafen] = False

Von hier an ist sowohl das Dashboard als auch das Webfront (Browser und Android-App) blockiert, das heisst reagiert nicht mehr auf Eingaben. Im Hintergrund laufen ein paar Ereignisse, unter anderem natürlich die Sonos-Ansteuerung:

07.04.2015 05:28:54.430 | 55335 | DEBUG   | ExecuteThreadID #8   | Skriptausführung: wohnungChangeHandler.ips.php ~ Absender: Ereignis #18063, Variable #45301, Auslöser: OnChange
07.04.2015 05:28:54.430 | 21692 | DEBUG   | ExecuteThreadID #25  | Skriptausführung: raumChangeHandlerZimmer3.ips.php ~ Absender: Ereignis #25725, Variable #45301, Auslöser: OnUpdate
07.04.2015 05:28:54.477 | 33262 | MESSAGE | VariableManager      | [Allgemein\szeneWohnung] = 6
07.04.2015 05:28:54.477 | 25213 | MESSAGE | VariableManager      | [OG\Zimmer4\szeneZimmer4] = 6
07.04.2015 05:28:54.477 | 49102 | MESSAGE | VariableManager      | [OG\Terrasse\szeneTerrasse] = 6
07.04.2015 05:28:54.477 | 47174 | MESSAGE | VariableManager      | [OG\Wohnzimmer\szeneWohnzimmer] = 6
07.04.2015 05:28:54.477 | 40642 | MESSAGE | VariableManager      | [OG\Bad\szeneBad] = 6
07.04.2015 05:28:54.477 | 37581 | MESSAGE | VariableManager      | [OG\Flur\szeneFlur] = 6
07.04.2015 05:28:54.477 | 42953 | MESSAGE | VariableManager      | [OG\Kueche\szeneKueche] = 6
07.04.2015 05:28:54.477 | 50320 | MESSAGE | VariableManager      | [UG\Fitness\szeneFitness] = 6
07.04.2015 05:28:54.602 | 14902 | MESSAGE | VariableManager      | [_system\Libraries\SonosThreading\sonosWohnzimmer] = 3
07.04.2015 05:28:54.617 | 14902 | DEBUG   | VariableManager      | [_system\Libraries\SonosThreading\sonosWohnzimmer] = 3
07.04.2015 05:28:54.680 | 54325 | DEBUG   | ExecuteThreadID #39  | Skriptausführung: sonosThreading.ips.php ~ Absender: Ereignis #46380, Variable #14902, Auslöser: OnUpdate
07.04.2015 05:29:50.216 | 32457 | DEBUG   | ExecuteThreadID #8   | Skriptausführung: dashboardVisibility.ips.php ~ Absender: Ereignis #57686, Zeit Ereignis
07.04.2015 05:29:50.263 | 32457 | DEBUG   | ExecuteThreadID #8   | Ausgeführt, Resultat: 1, Erfolgreich: True, Zeit: 51 ms

Durch setzten der Variable ‚sonosWohnzimmer‘ wird das Script ‚sonosThreading.ips.php‘ im Thread #39 aufgerufen, welches einen Internetstream auf Sonos starten soll.
Auch zu erkennen, dass mit dem Script ‚dashboardVisibility.ips.php‘ die Anzeige auf dem Dashboard verändert wird. Dies funktioniert auch, obwohl das Dashboard ansonsten auf keine Eingaben reagiert.

Nach rund 2.5 Minuten steht dann folgendes im Log:

07.04.2015 05:31:19.916 | 54325 | ERROR   | ExecuteThreadID #39  | [_system\Libraries\SonosThreading] = 
Fatal error:  Maximum execution time of 2 seconds exceeded in [_system\Bindings\Sonos\PHPSonos] on line 2298
PHP-Error-Error: Maximum execution time of 2 seconds exceeded
   Error in Script C:\IP-Symcon\scripts\PHPSonos.ips.php on Line 2298Abort Processing during Fatal-Error: Maximum execution time of 2 seconds exceeded
   Error in Script C:\IP-Symcon\scripts\PHPSonos.ips.php on Line 2298
07.04.2015 05:31:19.916 | 54325 | DEBUG   | ExecuteThreadID #39  | Ausgeführt, Resultat: 0, Erfolgreich: False, Zeit: 145242 ms

Also obwohl die ‚Maximum execution time‘ auf 2 Sekunden gesetzt ist, dauert es über 2 Minuten bis der Fehler im Log erscheint und Dashboard/Webfront wieder auf Eingaben reagieren.
In dieser Zeit kann ich Sonos übrigens problemlos über die Sonos-Android-App steuern.

Wie bereits geschrieben, funktioniert das ganze in vielleicht 2 von 3 Fällen problemlos. Da dauert die Ausführung des Scripts ‚sonosThreading.ips.php‘ ein paar wenige Millisekunden.

Hat jemand eine Idee, was hier passiert? Warum sind Dashboard und Webfront 2-3 Minuten lang eingefroren? Was kann ich noch tun, um dieses Problem zu beheben?

Liebe Grüsse
Marco

2

Da mir scheinbar niemand weiter helfen kann, versuche ich mal, die Frage etwas anders zu stellen.

Bei mir friert das Dashboard immer wieder mal für 2-3 Minuten ein (reagiert nicht mehr). Im Logfile steht dann folgender Fehler:

Fatal error:  Maximum execution time of 5 seconds exceeded in [.../.../...] on line xx

Der Fehler taucht in unterschiedlichen Scripts auf, jedoch immer beim Aufruf von fsockopen oder cURL.

Die 5 Sekunden kommen daher, dass ich das Limit in den Scripts entsprechend gesetzt habe:

set_time_limit(5);

Jedoch habe ich bei den Aufrufen von fsockopen und cURL explizit ein kürzeres Timeout gesetzt und das ganze auch noch in einen Try-Catch-Block verpackt:

try {
         $fp = fsockopen($this->address, 1400 /* Port */, $errno, $errstr, 2 /* Timeout */);
}catch (Exception $e){
         echo 'SONOS ERROR: ',  $e->getMessage(), "
";
		}

1. Warum wird das Timeout von 2s scheinbar ignoriert?
2. Warum wird keine Exception abgefangen sondern ein Fatal Error ausgegeben?

Wenn nun also die maxmimum execution time auf 5s gesetzt ist, warum friert dann das Dashboard für 2-3 Minuten ein? Ich habe mal geloggt, wann den der Befehl fsockopen aufgerufen und wann der Fatal Error ausgegeben werden:

11.04.2015 [b]06:40:19[/b].921 | 54325 | ERROR   | ExecuteThreadID #33  | [_system\Libraries\SonosThreading] = 
PHPSonos fsockopen at [b]06:37:59[/b]
Fatal error:  Maximum execution time of 5 seconds exceeded in [_system\Bindings\Sonos\PHPSonos] on line 2301
PHP-Error-Error: Maximum execution time of 5 seconds exceeded

3. Warum wird der Fatal Error erst 2.5 Minuten nach Aufruf von fsockopen ausgegeben?

Ich hoffe, nun kann mir bald jemand helfen. Ich verzweifle hier noch mit dem Zeugs :confused:

Liebe Grüsse
Marco