Sonos Player disappeared

hoppel118 · 30 Mai 2020, 19:53:08

@mimpitzstuff

Ich habe gerade die beiden ursprünglichen Dateien wieder hergestellt, die fhem-log und sonos-subprocess-log geleert, FHEM neu gestartet, ein paar Minuten gewartet und den Stecker meiner Sonos Box im Büro gezogen.

Bisher läuft alles weiter. Mal sehen, ob sich da im Laufe des Abends etwas tut.

Was ist dir denn am Liebsten:

a.) Ich lasse die Version von Rainerlein installiert und warte bis der Fehler wieder auftritt.
b.) Ich installiere die von dir angepasste Version und mache damit einen Langzeittest.

By the way... Der Büro Player war bis vorhin noch im Status ,,appeared".

Viele Grüße Hoppel

mumpitzstuff · 30 Mai 2020, 22:46:21

Okay wenn das grundlegende Verhalten gleich ist, dann wäre ein längerer Test mit meiner Version und Verbose 5 wünschenswert (+abgeschaltetem DOIF).

Das reine Abschalten eines Gerätes scheint dann nämlich nicht die eigentliche Ursache zu sein.

Alternativ könntest du mit Verbose 5 auch mal ins Logfile gucken, ob da irgendwas auffälliges passiert, wenn du eine Box für 35 Minuten (30 Minuten ist ein interner Timeout Wert) abschaltest und dann wieder einschaltest. Am besten auch mit meiner Version.

87insane · 30 Mai 2020, 22:53:26

Ich hatte die erste Version getestet. An sich gut aber Player gehen dann gar nicht offline. Hinzu, wenn man den stecker zieht, wärend ein Internet Stream läuft, denkt fhem der läuft weiter und weiter. Hab eine sonos im bad die auch für draußen ist. Die steht aus Faulheit aktuell unangeschlossen im Flur. Aber der Player läuft und läuft...

Das als Info. Lade mir morgen die aktuelle Version von dir rein.

Gesendet von meinem LM-G810 mit Tapatalk

mumpitzstuff · 30 Mai 2020, 23:30:41

Hoppel118 hatte geschrieben, dass das auch mit der originalen Version passiert. Wenn ich das richtig verstanden habe, liegt das also nicht an meinen Änderungen (das kann man sich ja mal ansehen, wenn das eigentliche Problem behoben worden ist). Der Fehler der dazu führt das die Player auf disappeared stehen, scheint also nicht durch simples Ausschalten reproduzierbar zu sein.
Aus meiner Sicht ist damit der Fakt, dass die Geräte gar nicht offline angezeigt werden, erst einmal unschön aber eigentlich unkritisch.

Ihr solltet auf jeden Fall die letzte Version von mir verwenden, da diese noch einige Erweiterungen zur ersten Version enthält.

PS: Habt ihr schon mal versucht die abgeschaltete Box über FHEM anzusprechen? Ändert sich vielleicht erst dann etwas am Status der Box?

87insane · 30 Mai 2020, 23:35:06

Habe ich probiert...passiert nix dabei. Ich teste es nochmal mit der original Version. Zu 99% bin ich sicher das die Boxen alle aussteigen wenn eine auf Zeit x offline ist. Hatte das mehrfach.

Gesendet von meinem LM-G810 mit Tapatalk

87insane · 31 Mai 2020, 00:48:54

Hab die Box wieder eingesteckt. Danach habe ich über eine benachbarte alexa einen Radio sender eingeschaltet. Nun sind wieder alle disapper. Hab noch die erste Version drin und glaube es auch reproduzieren zu können. Teste morgen deine aktuelle.

Edit: die benachbarte alexa ist auch eine Sonos box. Nur als Zusatz Info.

In dem Moment wo ich die Box einsteckte, die lange vom Strom war ist der prozess abgekackt oder wo ich den Stream aufrief. Teste ich morgen im Detail.

Danke für deine Mühen!

Gesendet von meinem LM-G810 mit Tapatalk

mumpitzstuff · 31 Mai 2020, 01:07:23

Ich bräuchte ein Verbose 5 vom Log. Ich kann sonst nur raten was passiert. Im besten Fall sogar eins vom original Modul und eins von der letzten Version das ich gebastelt habe.

hoppel118 · 31 Mai 2020, 01:32:31

Zitat von: 87insane am 31 Mai 2020, 00:48:54
Hab die Box wieder eingesteckt. Danach habe ich über eine benachbarte alexa einen Radio sender eingeschaltet. Nun sind wieder alle disapper. Hab noch die erste Version drin und glaube es auch reproduzieren zu können. Teste morgen deine aktuelle.

Edit: die benachbarte alexa ist auch eine Sonos box. Nur als Zusatz Info.

In dem Moment wo ich die Box einsteckte, die lange vom Strom war ist der prozess abgekackt oder wo ich den Stream aufrief. Teste ich morgen im Detail.

Das habe ich gerade mit der Originalversion des Moduls nachgestellt. Das Verhalten habe ich bei mir nicht. Ich hatte die Sonos im Büro jetzt für einige Stunden vom Strom getrennt. Diese habe ich nun wieder eingesteckt, bin in die Küche gegangen (dort steht auch eine Sonos), habe Alexa gebeten einen Radiosender abzuspielen und der Blick auf FHEM zeigt mir, dass weiterhin alles in Ordnung ist. Dann habe ich die Sonos im Büro gestartet. Alles läuft ganz normal.

(Auch mit der originalen Modulversion bleibt die Sonos im Büro im Status ,,appeared", obwohl sie mehrere Stunden vom Strom getrennt war. @87insane Wie ist das bei dir? Wie dem auch sei, das hat nichts mit dem eigentlichen Problem zu tun. Wie @mumpitzstuff schon gesagt hat, kümmern wir uns später nochmal drum, ist unkritisch.)

Zitat von: mumpitzstuff am 31 Mai 2020, 01:07:23
Ich bräuchte ein Verbose 5 vom Log. Ich kann sonst nur raten was passiert. Im besten Fall sogar eins vom original Modul und eins von der letzten Version das ich gebastelt habe.

Uff, jetzt habe ich es wegen deiner letzten Aussage gerade wieder umgebaut auf deine Version.

Dann baue ich es jetzt nochmal zurück auf die originale Modul Version (ist ja nicht der große Aufwand) und lasse das verbose level 5 so lange laufen, bis der Fehler wieder auftritt. Dann haben wir auch das sauber erfasst. Das kann schnell gehen, kann aber auch mal einen Monat dauern.

@87insane Du testest dann am besten die neue Version mit verbose level 5.

Ich bin die nächsten Wochen mit meinem Wohnmobil unterwegs. Solche bzw. irgendwelche Tests mit Stecker ziehen, werden dann schwierig.

Logfile ziehen und hier kommunizieren geht aber trotzdem noch. Ich komme per VPN an alles ran.

Ich hoffe, dass hier noch weitere Personen aus der Deckung kommen, die dieses Problem auch haben, und unterstützen beim Testen.

Viele Grüße Hoppel

87insane · 31 Mai 2020, 11:16:40

Guten Morgen,

hab die aktuellen Datein eingehangen und im sonos auf verbose 5 gestellt. Hab ich das überlesen oder kann ich den Verbose5 kram separat auslagern? Ungern möchte ich meine normale LOG Datei danach durchsuchen. Aktuell lasse ich es aber erstmal los laufen...
Teste auch später nochmal die ganzen "Phänomene".

87insane · 31 Mai 2020, 13:53:58

Sooooo... ich kann es reproduzieren, habe geloggt usw...(das ganze habe ich mit dem aktuellen TEST MODUL so gemacht)

Ich habe eine von drei Sonos abgesteckt. Diese eine blieb auch die ganze Zeit online obwohl aus.
Nach einiger Zeit habe ich die Sonos wieder eingesteckt. Nun wurde sie ganz kurz disapper angezeigt.
Nachdem ich dann dieser Sonos Box einen Stream mitteilte, den sie abspielen sollte sind wenige Sekunden danach alle Sonos offline gegangen.

Also kurz:
1) Eine Sonos abklemmen
2) ein wenig warten und wieder anklemmen
3) Sonos Box Musik spielen lassen über FHEM (es kommt keine Musik und alles "kackt" ab)

Anbei das LOG (13:16 war kurz nachdem nichts mehr ging) / Ich hoffe ich habe nichts anderes drin gelassen im LOG....

Nobby1805 · 31 Mai 2020, 14:50:38

Ich sehe Ähnlichkeiten zu dem von mir untersuchten Problem

Folgender Log-Block kommt regelmäßig alle 60 Sekunden

Code Auswählen

2020.05.31 13:02:46 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:02:46 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'
2020.05.31 13:02:46 4: SONOS1: SONOS_Client_Notifier(rePing:undef::)
2020.05.31 13:02:47 5: SONOS0: Received from UPnP-Server: 'rePing:undef::'

...

Code Auswählen

2020.05.31 13:12:41 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:12:41 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'
2020.05.31 13:12:41 4: SONOS1: SONOS_Client_Notifier(rePing:undef::)
2020.05.31 13:12:41 5: SONOS0: Received from UPnP-Server: 'rePing:undef::'

um 13:13 fehlt dann der Logeintrag, aber es kommt

Code Auswählen

2020.05.31 13:14:17 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:14:17 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'

... nach meiner Interpretation kommt die Message nicht an

Code Auswählen

2020.05.31 13:14:47 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:14:47 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'

Code Auswählen

2020.05.31 13:15:17 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:15:17 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'

und dann zum Abschluss

Code Auswählen

2020.05.31 13:15:47 5: SW: DoWork:undef:refreshProcessAnswer:
2020.05.31 13:15:47 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'
2020.05.31 13:15:47 2: SONOS0: LastProcessAnswer way too old (Lastanswer: 1590923597 ~ 2020-05-31 13:13:17)... try to restart the process and connection...

87insane · 31 Mai 2020, 15:18:42

Mich würde auch der Keepalive check interessieren. Es wird immer online angezeigt. Das dann ein Player bei Rückkehr nicht den alten Thread nutzt, ist in meinen Augen zusammenhängen.
Meine ausgeklemmte Box war die ganze Zeit munter weiter online...

Otto123 · 01 Juni 2020, 12:37:47

Heute Morgen:

nur mal so zur Info:
Heute morgen, scheinbar ohne weitere Aktion

Code Auswählen

2020.06.01 08:22:59 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...
Danach sind alle Player weg disappeared.
Interessanterweise steht diese Zeile noch im Log von vorigem Monat (gestern)

Gruß Otto

87insane · 01 Juni 2020, 13:03:04

Wie geht es denn überhaupt weiter. Hat noch einer Ideen oder basteln wir sonos2mqqt einfach auf und nehmen dann das? Würde den Programmierer tatsächlich auch mal anschreiben um mehr Infos zu bekommen.

Gesendet von meinem LM-G810 mit Tapatalk

mumpitzstuff · 01 Juni 2020, 22:48:32

Sry ich habe etwas gebraucht mich da durchzuwühlen...

Nachdem was ich gesehen habe verstehe ich nicht, weshalb sich das Original SONOS Modul anders verhalten soll als meine veränderte Version. Ich finde nämlich im Log keine Informationen dazu, das meine veränderten Funktionen überhaupt aufgerufen wurden. Wenn ich nichts übersehen habe, dann müsste aber ein Logeintrag existieren, denn alle von mir veränderten Funktionen schreiben ins Logfile. Okay aber lassen wir das mal beiseite und schauen uns das eigentliche Problem näher an (ich glaube was gefunden zu haben).

1.) Einer der Clients kann zeitwelig nicht erreicht werden. Dadurch wird 4x ein "SW: DoWork:undef:refreshProcessAnswer:" ausgelöst.
2.) Wenn das 4x nicht erfolgreich war, dann wird innerhalb der Funktion SONOS_IsSubprocessAliveChecker() zuerst SONOS_StopSubProcess() aufgerufen und 30s später SONOS_DelayStart().
3.) SONOS_StopSubProcess() löst nun einen kompletten shutdown aus und killt quasi alles. Das sieht man hier:

Code Auswählen

2020.05.31 13:15:48 5: SONOS0: Received: 'shutdown'
2020.05.31 13:15:48 3: SONOS0: Disconnecting client and shutdown server...
2020.05.31 13:15:48 3: SONOS0: Trying to kill Sonos_Thread...
2020.05.31 13:15:48 3: SONOS0: Trying to kill LongJobs_Thread...
2020.05.31 13:15:48 3: SONOS0: Trying to kill IsAlive_Thread...
2020.05.31 13:15:48 3: SONOS0: Trying to kill PlayerRestore_Thread...
2020.05.31 13:15:48 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...

4.) Jetzt wird SONOS_DelayStart() aufgerufen und innerhalb der Funktion SONOS_StartClientProcessIfNeccessary(). Und jetzt kommt meine Vermutung:

Code Auswählen

my $socket = new IO::Socket::INET(PeerAddr => $upnplistener, Proto => 'tcp');
if (!$socket) {

Die Funktion versucht ein Socket zu öffnen und wenn das nicht möglich wäre, dann wäre alles super. Ein neuer Process würde gestartet werden und alles würde wunderbar laufen. Das Problem ist aber hier (meiner Meinung nach), das hier erkannt wird, dass der Socket noch vorhanden ist, dann wird dieser gekillt und dann ist alles vorbei. Keine retrys, kein gar nix mehr. Klinisch tot.

Code Auswählen

		# Hiermit wird eine etwaig bestehende Thread-Struktur beendet und diese Verbindung selbst geschlossen...
		eval{
			$socket->shutdown(2);
			$socket->close();
		};

Die Frage ist jetzt, warum gibts den Socket noch, wenn unter 3. alles gekillt wird? Entweder wird der socket nicht sauber abgebaut oder das Timeout ist schlicht zu kurz. Ein Socket braucht nämlich normalereise etliche Sekunden bis Minuten, bis dieser wieder frei ist.

Jetzt gibt es verschiedene Optionen:

a) Ich erhöhe mal die Zeit zwischen SONOS_StopSubProcess und SONOS_DelayStart, so das der Socket Zeit zum austimen bekommt, falls dieser überhaupt irgendwo abgebaut wird.

b) Ich versuche das killen des Sockets in der Funktion SONOS_StartClientProcessIfNeccessary irgendwie zu verhindern. Das wird allerdings schwierig werden, denn an anderer Stelle wird das benötigt.

c) Ich versuche die Funktion SONOS_StartClientProcessIfNeccessary 2x auf, wobei ich auch hier sicherstellen muss, dass das an anderer Stelle nicht zu Problemen führt.

Ich würde mal mit a) starten, da das die einfachste Variante ist. Wenn das nichts bringt, dann schaue ich mir c) an. Gebt mir noch 1 Tag Zeit, um das etwas sacken zu lassen, dann stelle ich euch eine neue Version zur Verfügung.