Sonos Player disappeared

[87insane]

Um 5 sollte keiner bei mir klingeln und deswegen da auch der Neustart wenn nötig. Wenn das so eingestellt wird, hast du kein disapper mehr.
https://fhem.de/commandref_DE.html#DOIF_Zeitintervalle_Readings_und_Status_ohne_Trigger

[aski71]

Um 5 sollte keiner bei mir klingeln und deswegen da auch der Neustart wenn nötig. Wenn das so eingestellt wird, hast du kein disapper mehr.
https://fhem.de/commandref_DE.html#DOIF_Zeitintervalle_Readings_und_Status_ohne_Trigger

Again what learned. Danke.
Aber was ist, wenn das Modul tagsüber die Grätsche macht?
Oder passiert das nicht?

[87insane]

Das passiert max alle 24 h.. deswegen passt das so. Probier es aus klappt mit dem originalem.

Ich weiß leider noch immer nicht den aktuellen Status, der gefunden wurde? Ist das nicht eh schon obsolet?

[aski71]

Das passiert max alle 24 h.. deswegen passt das so. Probier es aus klappt mit dem originalem.

Ich weiß leider noch immer nicht den aktuellen Status, der gefunden wurde? Ist das nicht eh schon obsolet?

Scheinbar nicht.

[mumpitzstuff]

So. Logs.

Das hier ist das einzige, was ich heute gefunden habe: Scheinbar ein selbständiger Neustart?!
Ansonsten nichts auffälliges passiert heute. Außer, dass morgens meine bewegungsgesteuerte Einschaltautomatik nicht hingehauen hat.

Code Auswählen Erweitern

2020.06.18 15:10:11 2: SONOS0: LastProcessAnswer way too old (Lastanswer: 1592485689 ~ 2020-06-18 15:08:09)... try to restart the process and connection...
2020.06.18 15:10:49 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 1 Sekunde(n) darauf...
2020.06.18 15:10:50 3: Opening Sonos device localhost:9091
2020.06.18 15:10:50 1: Sonos: Can't connect to localhost:9091: Connection refused
2020.06.18 15:10:51 1: SONOS0: ./FHEM/00_SONOS.pm is started by fhem...
2020.06.18 15:10:51 1: SONOS0: ./FHEM/00_SONOS.pm is listening to Port 9091
2020.06.18 15:11:50 3: SONOS0: Connection accepted from localhost:58936
2020.06.18 15:11:50 1: localhost:9091 reappeared (Sonos)
Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6098 thread 1.
Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6098 thread 1.
Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6098 thread 1.
Subscription request failed with error: 503 Service Unavailable at ./FHEM/00_SONOS.pm line 6098 thread 1.

Welche ControlPoint und welche SONOS Version verwendest du? Zeile 6098 verwirrt mich. Das ist sowohl im Originalmodul als auch meiner angepassten Version eine Leerzeile.

[87insane]

Aktuell nutze ich komplett FHEM original SVN.
Hatte die letzten Tage wenig Zeit daher musste ich umstellen. Ich kann gerne nochmal testen nur habe ich aktuell sehr wenig Zeit und das kommt dann sehr gebündelt oder in gewissen Blöcken.

[mumpitzstuff]

Okay kein Problem. Ich meinte aber vor allem aski71, von dem der Ausschnitt aus dem Logfile ist.

[aski71]

Welche ControlPoint und welche SONOS Version verwendest du? Zeile 6098 verwirrt mich. Das ist sowohl im Originalmodul als auch meiner angepassten Version eine Leerzeile.

Ich habe das Originalmodul vor weiß nicht wann installiert. Da kam schon seit ewiger Zeit kein Update mehr.
Und ich habe keine Ahnung, was Du mit ControlPoint meinst und wo ich die Versionsnummern finde. 
Bitte hilf mir auf die Sprünge. Dann liefere ich das nach.

[mumpitzstuff]

Ich kann nur etwas mit Logfiles anfangen, die von den beiden von mir geänderten Modulen ausgespuckt werden:

https://github.com/mumpitzstuff/fhem-SONOS

Hier findest du die direkten Links:

https://forum.fhem.de/index.php/topic,46058.msg1062441.html#msg1062441

[87insane]

Aber es war so das es lief oder nicht?
Teste es ( wenn alles klappt) am we auch nochmal. Kann ja nicht sein das Hilfe nicht angenommen wird :-/

@mumpitzstuff: kannst du grob den aktuellen Status zusammen fassen?

[mumpitzstuff]

Ich hatte jetzt seit einigen Tagen nichts mehr geändert, weil mir dazu weitere Fehlermeldungen fehlen bzw. Logfiles von eventuell auftretenden Fehlern. Den Author des Moduls habe ich informiert und er wollte sich das mal ansehen, ich habe aber keine Ahnung ob da schon was raus gekommen ist. Gefragt hat er mich jedenfalls nichts, obwohl ich ihm das angeboten hatte. Vielleicht hat er aktuell auch viel um die Ohren...

[Reinerlein]

Hi mumpitzstuff,

ich habe mir erstmal die ControlPoint vorgenommen, und habe deine Anpassungen erstmal eingefügt und einen Test laufen. Da meiner Meinung nach reuseport aber nicht von Debian berücksichtigt wird, erwarte ich da keine Änderung...

Zu deinen Änderungen an der Sonos.pm bin ich etwas skeptisch... ich habe ein Problem beim Wiederanstarten des SubProzesses entdeckt (hängt mit dem immer noch belegten Port zusammen), bin mir aber noch nicht sicher, wie ich das löse... bin aber der Meinung, dass deine Lösung auch nicht die richtige ist... da habe ich gerade aber auch einen Test laufen...

Also, erstmal müssen die Fehler wieder auftreten, und dann sehe ich hoffentlich was im Log...

Grüße
Reinerlein

[mumpitzstuff]

Die Änderungen in der ControlPoint führen aber auf jeden Fall dazu, das bei einem Shutdown restart von FHEM kein Port already in use bei mir kommt und sofort alles hochgefahren wird anstatt erst beim xten Versuch. Das wurde auch von einem anderen User bestätigt.

Den Ping Bugfix konntest du hoffentlich übernehmen.
Auf welche anderen Änderungen beziehst du dich denn?

Beim shutdown/restart war meines Erachtens die Logik nicht richtig. Dort hattest du immer nur den Prozess abgeschossen und nicht restartet. Das habe ich umgedreht, so das der Prozess erst abgeschossen werden sollte und dann restartet.
Dann hatte ich beim restart der ControlPoint noch eingefügt, das die Sockets geschlossen werden vorher und zwar ohne wait. Das sollte dazu führen das beim Restart die Ports nicht mehr belegt sind und dann der restart nicht funktioniert.
Zu guter Letzt habe ich das abfangen der Warnings der ControlPoint noch angepasst, das hatte vorher eindeutig nicht funktioniert. Da gibts aber vermutlich mehrere Wege. Einen anderen hast du am Anfang des Moduls auskommentiert. Dort biegst du warnings zu errors um. Damit würde dein eval und catch ebenfalls funktionieren. Eval fängt aber eben keine Warnings, weshalb das zu Problemen geführt hat.

Ich glaube das waren alle Änderungen an die ich mich erinnere. Aber ich mache dann erst mal nichts weiter und warte ab.

[Reinerlein]

Hi mumpitzstuff,

aber die Ports der ControlPoint beziehen sich auf die Kommunikation zwischen SubProzess und SonosPlayer., bzw. den UPnP-Broadcast-Listener Die haben überhaupt nichts mit der Kommunikation zwischen dem Fhem-Modulteil und dem SubProzess zu tun...

Und natürlich lasse ich den SubProzess erstmal nur absterben. Um den Neustart kümmert sich dann Zeitversetzt ein anderer Teil:

Code Auswählen Erweitern


.
.
# Stoppen...
InternalTimer(gettimeofday() + 1, 'SONOS_StopSubProcess', $hash, 0);

# Starten...
InternalTimer(gettimeofday() + 30, 'SONOS_DelayStart', $hash, 0);
.
.
Das ist das, was ausgeführt wird, wenn die letzte SubProzess-Antwort zu lange her ist... Beides wird Zeitversetzt ausgeführt, damit Fhem nicht blockiert wird...

Das Problem dabei ist, dass die spätere Prüfung in "SONOS_StartClientProcessIfNeccessary()" ahand der Belegung des Ports (4711) prüft, ob ein SubProzess läuft... Und wenn der belegt ist, dann gibt es wohl einen SubProzess, weswegen kein neuer angestartet wird.
Das dieser belegte Port erst später freigegeben wird, und nicht mehr an einem SubProzess hängt, ist hier das Problem...

Bei dem Ping habe ich die Änderung irgendwie nicht sehen können. Ich hatte aber auch ein paar Probleme alle Änderungen zu finden, da ja alle Zeilen mit Leerzeichen anfingen und auch die Umlaute irgendwie nicht gepasst hatten. Das muss ich nochmal auf anderem Wege vergleichen...

Was ich noch gesehen hatte waren Änderungen an Eval-Strukturen. Du hast, wenn ich das richtig verstanden habe, den Warn-Handler deaktiviert und die Eval-Fehlervariable $@ umgebogen?
Das finde ich eher unglücklich... Aber wir sehen mal, was wir so finden...
Ich verwende Eval an diesen Stellen als eine Art Try-Catch-Block. Warnings und carp-Aufrufe innerhalb von Eval brechen den Eval ab, und setzen die Variable $@. Das funktioniert hervorragend... lediglich croak-Aufrufe wird nicht gefangen, sondern nur carp-Aufrufe... Aber die croak-Aufrufe in der ControlPoint sind eigentlich an Stellen, wo ich anders drauf reagiere (z.B. beim Aufbau des SSDP-Listeners)...

Das mit dem SubProzess-Restart ist ja auch gar nicht der eigentliche Fehler... der betrifft den SubProzess, da er irgendwann einfach nicht mehr auf die Ping-Anforderung reagiert (bzw. natürlich auch andere Dinge nicht mehr tut)...
Da bin ich auch auf der Suche... bei mir tritt das Problem aber sehr selten bis gar nicht auf...

Grüße
Reinerlein

[Nobby1805]

Was ich noch gesehen hatte waren Änderungen an Eval-Strukturen. Du hast, wenn ich das richtig verstanden habe, den Warn-Handler deaktiviert und die Eval-Fehlervariable $@ umgebogen?
Das finde ich eher unglücklich... Aber wir sehen mal, was wir so finden...
Ich verwende Eval an diesen Stellen als eine Art Try-Catch-Block. Warnings und carp-Aufrufe innerhalb von Eval brechen den Eval ab, und setzen die Variable $@. Das funktioniert hervorragend... lediglich croak-Aufrufe wird nicht gefangen, sondern nur carp-Aufrufe... Aber die croak-Aufrufe in der ControlPoint sind eigentlich an Stellen, wo ich anders drauf reagiere (z.B. beim Aufbau des SSDP-Listeners)...

Hallo Reinerlein,

und genau das hat im Original ControlPoint nicht funktioniert ... $@ war immer leer und deshalb kam es pro nicht erreichbarem SONOS-Devices bis zu 9 mal zum 20 Sekunden Timeout und danach trat immer mal wieder ein "way too old" auf. Da dann der restart bei mir NIE funktioniert hat hing dann der komplette SONOS-Teil im Fhem. Mit der Änderung von mumpitzstuff klappt das jetzt wunderbar: 1 mal Timeout, danach richtiger Fehler im $@ und das Device wird auf disappeared gesetzt.

Grüße Nobby

PS @mumpitzstuff

Aus über 40-jähriger Programmierpraxis, die viele Jahre auch mit der Pflege von Legacyprogrammen zu tun hatte ...

Ich hatte aber auch ein paar Probleme alle Änderungen zu finden, da ja alle Zeilen mit Leerzeichen anfingen

guter Programmierstil kommentiert jede, aber wirklich jede, durchgeführte Änderung: Wer, was, warum