Unerklärliches Phänomen bei einer gewissen Abfolge von Befehlen

[Hannes Schellnast]

Ich schreibe schon längere Zeit an einer Art Plugin für den MS4Lox.
Bei meinen Dauertests über die letzten Monate bin ich immer wieder über ein Phänomen gestolpert, dass ich mir nicht erklären kann.

Hier mein Setup:
Intel Nuc mit 2 Logilink Soundkarten.
6Stk. Stereozonen eingerichtet.
Software auf aktuellstem Stand.

Folgende Abfolge von Befehlen führt zeitweise zu dem Verhalten (siehe Auszug aus Logfile):

Zuerst die Zusammenfassung d. zeitl. Ablaufs:
1. Zone 4 auf Play ...ok
2. Sender/Stream in Zone 6 wird über TCP-Kommando aktiviert ...ok
3. Overlaytext wird mit einer Verzögerung von 500ms ausgegeben ...ok
4. Zone 6 geht ohne eine Anweisung vom Plugin od. Miniserver auf Standby ...nicht ok

Hier detailiert der Auszug aus dem Logfile des Plugins (inkl. Erklärungen)
Ausgangszustand zum Logfile: Player in Zone4 (Buero) aktiviert, alle anderen Zonen stehen auf Standby

2018-08-25 12:40:25.638 INFO [32455] [UDPServer::makeServerStuff@139] ...RECEIVER: BUTTON;WC;ON Trigger aus WC, um Zone Buero (Zone6) zu starten
2018-08-25 12:40:25.638 INFO [32455] [MsgProcessing::checkButtonMsg@126] Received message BUTTON with Arg#2: WC Arg#3: ON Plugin empfängt UDP Message zum Starten des Players
2018-08-25 12:40:25.638 INFO [32455] [MsgProcessing::switchOnZone@686] BUTTON message successfully processed interne Plugin Meldung
2018-08-25 12:40:25.639 INFO [31375] [LMSClient::sequenceAlgo@58] Delay: 0ms interne Plugin Meldung
2018-08-25 12:40:25.639 INFO [31375] [LMSClient::sequenceAlgo@68] TCP: aa:bb:cc:dd:ee:06 playlist play
http%3A%2F%2Fopml%2Eradiotime%2Ecom%2FTune%2Eashx% 3Fid%3Ds149491%26formats%3Daac%2Cogg%2Cmp3%26partn erId%3D16%26serial%3D6959a862fdf6ce89ee7020446536c a3a diese TCP Meldung wird an den Squeezeserver abgesetzt. Der Player beginnt zu spielen
2018-08-25 12:40:25.665 INFO [31375] [LMSClient::sequenceAlgo@58] Delay: 500ms
2018-08-25 12:40:26.166 INFO [31375] [LMSClient::sequenceAlgo@78] HTTP: /event/event.php?type=tts&text=Radio%2E%20Welle%201&zone= 6 mit einer Verzögerung von 500ms wird über das Overlay ein entsprechender Text ausgegeben, der den Stream/Sender beschreibt.
2018-08-25 12:40:29.579 INFO [367] [LMSPoll::sequenceAlgo@117] Recognized player state change of zone Buero to 0 Plugin bekommt mit, dass der Player in der Zone 4 gestoppt wurde. Diese Anweisung geht aber definitiv nicht vom Plugin raus.

Dieses Verhalten ist leider nicht 100% reproduzierbar, sondern tritt nur zeitweise auf. Ich nehme an, dass es sich deshalb um einen Timingeffekt handelt.
Kann es sein, dass diese Abschaltung durch eines der Skripte während des Overlays aufgerufen wird?

Ich habe gesehen, dass das Logging der Player seit einigen MS2Lox-Versionen ausgeschaltet ist. Werde dieses Logging wieder aktivieren, um ev. detailliertere Informationen zur Abschaltung d. Players zu bekommen. Gibt es einen bestimmten Grund, warum das Logging der Player abgeschaltet wurde?


MfG
Hannes

[hismastersvoice]

Zonen werden nur abgeschaltet wenn sie auf Pause oder Stop stehen. Dann auch nur nach Ablauf der eingestellten Zeit.
Diese Aufgabe übernimmt der PowerManager.
Es wird bei den Events nur geschaut ob die benötigte Zone aktiv ist, wenn nicht wird sie eingeschaltet. Ausschalten übernimmt wieder der PowerManager wenn Stop oder Pause anliegt.

Log wurde abgeschaltet da dieser immer wieder zum Absturz des Squeezelite Player geführt hat.

[Hannes Schellnast]

Danke für die Info. Das Problem scheint wirklich nicht einfach zum Finden. Werde zu Testzwecken zwischendurch das Logging der Player aktivieren. Da werde ich wohl hoffentlich mehr Infos rausbekommen, warum der Player aus dem Zustand Play raus springt.

[Christian Fenzl]

Was mir beim Squeezelite Player Plugin (Gateway) implementieren aufgefallen ist, dass beim Laden von Playlists, beim Skippen usw. der LMS erst ein Stop und dann wieder ein Play für den neuen Titel sendet.
Mein Gateway handhabt das speziell, aber es könnte da (im MS4L) durchaus ein Timing-Issue geben.

[hismastersvoice]

Hannes Schellnast
Schau mal ob der Player auf Pause oder Stop geht.
Den nur so erklärt sich das er danach auf aus geht.

Ich habe keine derartigen Probleme, bei mir laufen die Zonen ohne Power Off.
Ohne deinen Code gesehen zu haben kann ich natürlich wenig dazu sagen.


Christian Fenzl
Er nutzt Overlay, dort wird keine Playlist geladen.
Das einzige was gemacht wird ist das die Lautstärke der Zonen verringert wird.

Mein Gateway handhabt das speziell, aber es könnte da (im MS4L) durchaus ein Timing-Issue geben.

Somit ist ein Timing Problem ausgeschlossen.
Selbst wenn er nicht das Overlay verwenden würde wird der Player gestoppt, Playlist geladen und wieder auf play gesetzt.

[hismastersvoice]

Hannes Schellnast
Was mir gerade auffällt...

/event/event.php?type=tts&text=Radio%2E%20Welle%201&zone= 6
Bei deiner URL ist ein Leerzeichen zwischen zone= und 6 drin, keine Ahnung ob das eine Auswirkung hat aber evtl. liegt es daran.

[Hannes Schellnast]

Was das Leerzeichen ist mir beim Editieren des Beitrags passiert. Im realen Logging ist kein Leerzeichen enthalten.

[Hannes Schellnast]

Hannes Schellnast
Schau mal ob der Player auf Pause oder Stop geht.
Den nur so erklärt sich das er danach auf aus geht.

Dazu werde ich temporär das Logging der Player aktivieren, und hoffen dass der Fehler sobald wie möglich wieder auftritt.

[Hannes Schellnast]

Habe nun wieder einen Fehlerfall gehabt.
Folgendes ist passiert:
Zone 1 (Esszimmer) war schon einige Minuten aktiv
Zone 4 (Büro) war schon einige Minuten aktiv (Büro)
Zone 6 (WC) wurde aktiviert
----> aktivieren der Zone 6 hat folgendes bewirkt:
Zone 1 (Esszimmer) wurde auf Standby gesetzt
Zone 4 (Büro) läuft ordnungsgemäß weiter
Zone 6 (WC) startet ordnungsgemäß

Hier die Details aus meinem Logging:
2018-08-26 10:09:31.542 INFO [3486] [UDPServer::makeServerStuff@139] ...RECEIVER: BUTTON;WC;ON
2018-08-26 10:09:31.542 INFO [3486] [MsgProcessing::checkButtonMsg@126] Received message BUTTON with Arg#2: WC Arg#3: ON
2018-08-26 10:09:31.543 INFO [3486] [MsgProcessing::switchOnZone@686] BUTTON message successfully processed
2018-08-26 10:09:31.543 INFO [30792] [LMSClient::sequenceAlgo@58] Delay: 0ms
2018-08-26 10:09:31.543 INFO [30792] [LMSClient::sequenceAlgo@68] TCP: aa:bb:cc:dd:ee:06 playlist play http%3A%2F%2Fopml%2Eradiotime%2Ecom%2FTune%2Eashx% 3Fid%3Ds149491%26formats%3Daac%2Cogg%2Cmp3%26partn erId%3D16%26serial%3D6959a862fdf6ce89ee7020446536c a3a starten des Players für Zone 6 (WC)
2018-08-26 10:09:31.561 INFO [30792] [LMSClient::sequenceAlgo@58] Delay: 500ms
2018-08-26 10:09:32.061 INFO [30792] [LMSClient::sequenceAlgo@78] HTTP: /event/event.php?type=tts&text=Radio%2E%20Welle%201&zone= 6 Durchsage des Streams/Sender für Zone 6 (WC)
2018-08-26 10:09:35.943 INFO [3861] [LMSPoll::sequenceAlgo@117] Recognized player state change of zone Esszimmer to 0 Plugin erkennt, dass sich Zone 1 (Esszimmer) nicht mehr auf Zustand Play befindet.

Hier das Logging von Squeezelite für das Esszimmer (Loglevel = info)
[10:01:41.751701] _output_frames:149 track start sample rate: 44100 replay_gain: 0
[10:09:35.395667] decode_flush:229 decode flush
[10:09:35.395744] output_flush:427 flush output buffer
[10:09:49.465734] output_thread:804 disabling output

Hier sieht man zwar das der Ausgang der Zone 1 disabled wird, jedoch ist der Grund nicht ersichtlich.
Ich kann mal versuchen den Debuglevel von info auf debug zu wechseln.
Was meint ihr dazu?


MfG
Hannes