Sonos Player disappeared

[mumpitzstuff]

Eine Ursache die ich gesehen habe ist das die ControlPoint gewisse ips/ports belegt und bei Problemen versucht SONOS die selben Verbindungen erneut aufzubauen. Das schlägt fehl und dann schaltet SONOS quasi ab und macht schlicht nichts mehr. Dadurch timen die Verbindungen irgendwann aus und ein DOIF kann das dann neu starten, da nach einem Timeout die Ports wieder frei sind. Vermutlich wird man aber dem DOIF etwas Zeit geben müssen, bis die Verbindungen ausgetimed sind. Das könnte auch das Geheimnis sein, weshalb man das mit diesem besonderen DOIF machen musste...
Jetzt sage ich im Falle eines Fehlers, das nicht gewartet werden soll bis die Verbindung richtig abgebaut wurde, sondern das sie sofort freigegeben werden sollen. Danach schließe ich die Sockets explizit noch einmal und versuche erst danach den ControlPoint komplett neu zu starten. In der letzten Version habe ich auch versucht abzusichern, das die dafür verantwortliche Funktion möglichst nicht mehrfach getriggert werden kann. Ich hatte den Eindruck, das es dazu kommen kann, das ein Prozess den ControlPoint versucht neu zu starten und währenddessen ein zweiter Prozess eventuell versucht den ControlPoint ebenfalls zu schließen. Dabei könnte dann was durcheinander kommen und Fehler entstehen. Ich habe da ein paar Dinge auf Verdacht eingebaut. Außderdem wird es jetzt mehrfach versucht, was die Fehlerwahrscheinlichkeit reduziert. Hier gibt es vermutlich noch Raum für Verbesserungen, da ich momentan z.B. keine Wartezeit zwischen den retrys eingebaut habe.
Das Modul hat es an der Stelle nur 1x probiert, soweit ich das in der Kürze der Zeit sehen konnte. Danach wurde aufgehört und das Gerät war bis zum Neustart des Moduls tot.
Ich gucke mal noch ein wenig rum, ob ich irgendwo noch weitere Logs mit Informationen finde, ansonsten müssen wir abwarten was bei euch raus kommt.

PS: Ziemlich weit vorn hat der Maintainer was von wechselnden Ports erwähnt. Das ist meiner Meinung nach mit dem reuseAddr und reusePort nicht notwendig.

[hoppel118]

Bevor ich irgendwas gemacht habe, hatte ich zufällig gerade wieder ein paar Modul-Neustarts durch das DOIF. Anscheinend haben meine beiden Symfonisk im Schlafzimmer WLAN-Probleme. Die stehen tatsächlich stark an der Grenze der WLAN-Funkzellen.

Code Auswählen Erweitern

Unsubscription request failed with error: 500 Can't connect to 10.11.11.56:1400 (Connection timed out) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 10.11.11.55:1400 (Connection timed out) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.

Hier das verbose log (level 1): https://pastebin.com/uP8AYw0r

Vielleicht siehst du da ja noch etwas mehr. Errors gibt es dort trotz log level 1 einige.

Das Logfile für den Subprozess werde ich wie folgt erstellen. Die Datei wurde bereits angelegt.

Code Auswählen Erweitern

attr Sonos SubProcessLogfileName /opt/fhem/log/Sonos_SubProcess.log

Kann ich auch irgendwie alle Logs für das Sonos Modul in eine eigene Datei umbiegen?

Ansonsten habe ich nun deine beiden Dateien "installiert" und FHEM neugestartet. FHEM startet noch.

Eine Sache fällt mir direkt auf beim Starten von FHEM. Bisher sah ich immer die Meldung zu line 6098:

Code Auswählen Erweitern

Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6098 thread 1.

Mit deiner angepassten Modul-Version sehe ich nun eine Meldung zu line 6116:

Code Auswählen Erweitern

Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6116 thread 1.

Vielleicht bringt uns das irgendwie weiter...

Nun habe ich noch das at/DOIF deaktiviert und verbose Level 5 am Sonos Modul aktiviert, anschließend FHEM nochmal neugestartet. Wenn du keine weitere Anpassung am Code vornimmst, lasse ich das erstmal so laufen.


Kennt jemand eine Möglichkeit den Fehler zu provozieren (bspw. eine einzelne Sonos Box vom Strom trennen -> Sollte das funktionieren?)?

EDIT: Achso, die Player laufen noch!


Danke bis hierhin und viele Grüße Hoppel

[hoppel118]

Kann das Problem durch das schlechte WLAN dieser beiden Sonos Lautsprecher im Schlafzimmer verursacht werden? Wenn ja, sollte deswegen doch eigentlich nicht gleich gar nichts mehr gehen...

[mumpitzstuff]

Den Fehler habe ich nicht behoben, der hat auch nichts mit dem disappeared zu tun. Die Zeile ist gezwungermaßen anders, da ich ja auch Code eingefügt habe.
Logfile muss ich mir ansehen, da ist aber schon mächtig was los.

Das Problem kann durchaus dadurch verursacht werden, da unter Umständen der Upnp Server abgeschossen und neu gestartet wird, wenn die Verbindung zu einem Client abkackt. Dein DOIF verursacht wahrscheinlich ähnliches. Wenn dabei irgendwas schief läuft, funktioniert wahrscheinlich nicht mehr viel.

Triggern kannst du das Problem wahrscheinlich eher mit einem Stück Alufolie. Die Box auf eine Alufolie stellen und dann einen kleinen Kasten aus Alufolie basteln, den du für ein paar Sekunden drüber stülpst. Dann ist die Box für ein paar Sekunden abgeschirmt.

[Otto123]

oder Stecker ziehen? 

[hoppel118]

Ich habe einen Unifi Netzwerk Controller laufen. Damit habe ich die Möglichkeit IP-Adressen zu blocken. Das habe ich gerade mal für den Lautsprecher im Büro gemacht. Das müsste doch den gleichen Effekt bringen. Das Gerät kann jetzt nichts mehr machen. Wenn das Modul morgen früh noch läuft, also nicht im Status disappeared ist, müsste ich eigentlich nochmal eine Rolle rückwärts machen, das ursprüngliche Modul installieren, und testen ob das Problem damit provoziert werden kann.

Gruß Hoppel

[hoppel118]

oder Stecker ziehen? 

Kann man das Problem damit sicher provozieren?

[hoppel118]

Obwohl die IP vom Lautsprecher im Büro nicht mehr erreichbar ist, sehe ich im umgeleiteten SubProcessLogfileName "Sonos_SubProcess.log" immer noch folgendes:

Code Auswählen Erweitern

2020.05.30 00:26:10 4: SONOS3: SONOS_Client_Data_Retreive(RINCON_7828CAF292F801400_MR, reading, location, ) -> http://10.11.11.50:1400/xml/device_description.xml
2020.05.30 00:26:10 5: SONOS3: Location: http://10.11.11.50:1400/xml/device_description.xml
2020.05.30 00:26:10 5: SONOS3: PingType: syn
2020.05.30 00:26:10 4: SONOS3: 10.11.11.50 is alive

Ich warte mal bis morgen früh. Dann wird der Stecker gezogen.

Gruß Hoppel

[Otto123]

Kann man das Problem damit sicher provozieren?

Das weiß ich nicht.
Aber ist Stecker ziehen nicht der gleiche Effekt im Netzwerk wie Alukasten bauen = WLAN abschirmen ?

[hoppel118]

Das weiß ich nicht.
Aber ist Stecker ziehen nicht der gleiche Effekt im Netzwerk wie Alukasten bauen = WLAN abschirmen ?

Das weiß ich nicht (auch wenn ich davon ausgehe). Dann müsste es aber auch der gleiche Effekt sein, die IP zu blocken.

Wenn es morgen noch läuft, ziehe ich den Stecker.

Mein geblocktes Device "Büro" befindet sich in FHEM weiterhin im Status "appeared", obwohl es jetzt schon fast eine halbe Stunde geblockt ist, siehe Screenshot.

Gruß Hoppel

[mumpitzstuff]

Ich habe mal ein wenig in dem Log gestöbert, aber das gibt nicht viel her. Erstens sieht man nur wenige Punkte an denen der Process vorbei kommt. Zweitens scheinen die Ausgaben eher durch das laufende DOIF bedingt zu sein. Das was ich da sehe sieht so aus, als wenn man disable gesetzt und wieder weg genommen hätte, was vermutlich aus dem DOIF kommt.

Man braucht hier wirklich ein Verbose 5 Log ohne das ein automatischer Restart durch irgendwas passiert, damit man den ganzen Ablauf genau ein Mal sieht und man Anfang und Ende genau bestimmen kann.

[hoppel118]

Jo, danke erstmal, dass du dir die ganze Mühe machst und das Thema mit uns gemeinsam auseinander nimmst.

Du hast Recht mit deinen Erkenntnissen

1. Mein Logfile war verbose Level 1. Das Sonos Modul ist per Default für meinen Geschmack einfach zu gesprächig. Irgendwo wird im Wiki auch geschrieben, dass man das verbose Level heruntersetzen soll.
2. Mein DOIF greift da immer wieder, disabled und startet das Sonos Modul neu.

Mein Player im Büro ist weiterhin im Status ,,appeared". Das Sonos Modul selbst ist heute Nacht nicht abgestürzt, trotz IP Block. Ich hatte mir extra ein neues DOIF gebaut, welches mich per WhatsApp informiert, wenn das Sonos Modul den Status ,,disabled" bekommt.

Ich werde nun das Gerät im Büro vom Netz trennen. Mal sehen, ob das dann etwas bewirkt.

Gruß Hoppel

[mumpitzstuff]

Die Reaktion das es jetzt immer da ist, obwohl nicht am Netz, ist aber auch nicht richtig. Irgendwann sollte es schon offline gehen und auch so angezeigt werden. Wenn es dann wieder da ist, sollte es wieder als anwesend angezeigt werden.

[hoppel118]

Jo, sehe ich auch so. Mein Büro Player ist nun seit heute Morgen stromlos und immer noch im Status appeared. Als nächstes würde ich nochmal testen, ob der Fehler mit der originalen Modul-Version provozierbar ist, indem ein Player vom Strom getrennt wird.

Wenn das der Fall ist, wäre das eigentliche disappeared Problem evtl. schon behoben.

Oder kann das jemand sicher sagen?

Gruß Hoppel

[87insane]

Bin begeistert. Bei mir läuft auch noch alles...
Kann dem also aktuell nichts schlechtes abgewinnen. Sehr sehr nice. Danke erstmal. Bin gespannt was wir noch so finden.

Teste wenn die Sonne weg ist auch mal einen absichtlichen offline Fall ....

Gesendet von meinem LM-G810 mit Tapatalk