Sonos Player disappeared

[aski71]

@mumpitzstuff:
Ich habe jetzt mit Deinem Modul ein völlig neues Fehlverhalten.
Nach einer gewissen Laufzeit funktioniert meine Script-basierte Zuschaltung von Lautsprechern nicht mehr.
Das Script, getriggert durch einen Bewegungsmelder, macht einen simplen AddMember

Spannend dabei ist: Es funktioniert nicht, obwohl alle Lautsprecher auf ,,appeared" stehen.
Nach disable und Neustart des Sonos-Moduls geht es wieder.

[mumpitzstuff]

@aski71: Versuch lieber das Modul von Reinerlein. Dort sind Teile meiner Änderungen mit drin. Meine Version zu nehmen macht keinen Sinn mehr.

@Reinerlein: Wenn aber der Socket noch so halblebig da ist (wait Zustand), dann kommst du in den Zweig rein und versuchst zu lesen und es könnte da dann endlos weiter versucht werden. Ich würde da zur Sicherheit was einbauen, um 100% sicher zu sein. Das sind aber nur so Dinge die mir auf die Schnelle eingefallen sind. Und noch mal drüber nachdenken ist nie verkehrt. Ich schau aber noch mal rein.

[aski71]

@aski71: Versuch lieber das Modul von Reinerlein. Dort sind Teile meiner Änderungen mit drin. Meine Version zu nehmen macht keinen Sinn mehr.

@Reinerlein: Wenn aber der Socket noch so halblebig da ist (wait Zustand), dann kommst du in den Zweig rein und versuchst zu lesen und es könnte da dann endlos weiter versucht werden. Ich würde da zur Sicherheit was einbauen, um 100% sicher zu sein. Das sind aber nur so Dinge die mir auf die Schnelle eingefallen sind. Und noch mal drüber nachdenken ist nie verkehrt. Ich schau aber noch mal rein.

@Reinerlein: Ist das die Version von Antwort 345?

[Reinerlein]

Hi aski71,

yup, die alten habe ich gelöscht, und mal in einen neuen Artikel gepackt

Grüße
Reiner

[Nobby1805]

Bei mir ist heute mit den erweitertem bzw. geänderten Modulen mal wieder der Fehler aufgetreten, der alle paar Wochen auftritt. Da jetzt der Fehlercode richtig bearbeitet wird, kommt jetzt auch eine Meldung

2020.06.21 17:02:30.423 2: SONOS1: Rendering-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed: (Renewal of subscription failed with error: 500 Can't connect to 192.168.1.55:1400 at ./FHEM/00_SONOS.pm line 4189 thread 1.
)

Zeile 4189 ist bei der bei mir laufenden Version

Code Auswählen Erweitern

4183 sub SONOS_ProcessRenew($$$) {
4184  my ($udn, $subscriptionName, $subscriptionHash) = @_;
4185 
4186  if (defined($subscriptionHash->{$udn}) && (Time::HiRes::time() - $subscriptionHash->{$udn}->{_startTime} > $SONOS_SUBSCRIPTIONSRENEWAL)) {
4187    $SIG{__WARN__} = sub { $@ = shift; };
4188
4189    $subscriptionHash->{$udn}->renew();
4190    SONOS_Log $udn, 3, $subscriptionName.'-Subscription for ZonePlayer "'.$udn.'" has expired and is now renewed.';
4191
4192      ###
4193      ### Nobby 20-06-07
4194      ###
4195 SONOS_Log $udn, 2, $subscriptionName.'-Subscription for ZonePlayer "'.$udn.'" has expired and is now renewed: ('.$@.')';
4196      ###


[Reinerlein]

Hi Nobby,

ist denn die IP-Adresse korrekt?
500er-Fehler sind für "internal server error" reserviert. Also sagt dein Sonosplayer (so er es denn ist), dass er kein renew machen kann/will...

Grüße
Reinerlein

[cortmen]

  Hat sich geklärt @reinerlein  Danke

@reinerlein,

magst Du bitte kurz in den Thread schauen.

https://forum.fhem.de/index.php/topic,112486.0.html

Ich habe Deine "Zwischenversion" hier auf dem Thread eingesetzt.
Und kurz vorher auf die neuen S1 Firmware der Sonos player gewechselt.

Aber auch mit den "alten" Sonos Modul aus 2019 gibt den den Fehler in Zusammenhang  mit S1 Firmware und configdb  Speicherung.
Danke für prüfen.

Hinweis : Sonos_Wohnzimmer ist eine Beam und 2 x Play One Speaker.

[Nobby1805]

Hi Reinerlein,

ist denn die IP-Adresse korrekt?
500er-Fehler sind für "internal server error" reserviert. Also sagt dein Sonosplayer (so er es denn ist), dass er kein renew machen kann/will...

IP-Adresse ist korrekt und der Player war über die Sonos-App, sowohl Handy als auch PC, ansprechbar und hat einwandfrei Musik abgespielt  ... irgendwann ist mir dann aufgefallen, dass das Cover in der Fhem-Umgebung nicht stimmte

Asche auf mein Haupt 

Da habe ich die falsche Fehlermeldung erwischt, hier hatte ich bei einem Lied, das einen Hidden-Track hatte und dazwischen  fast 25 Minuten Stille, den Player abgeschaltet, weil ich dachte, er hat sich aufgehängt ... also 500 ist dann ganz OK

Die richtige Fehlermeldung ist

2020.06.26 03:20:30.558 2: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58A376D201400_MR" has expired and is now renewed: (Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4189 thread 1.
)

und diese Meldung ist zig-mal gekommen für alle unterschiedlichen Subscriptions und alle 30 Minuten wieder

[juemuc]

Hallo zusammen,

bei mir wurde auch das Logfile "geflutet" 

Code Auswählen Erweitern

2020.06.27 10:20:56 1: SONOS1: ZoneGroupTopology-Event: device 'Sonos_Kueche' is marked as disappeared. Restarting discovery-process!
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.
Unsubscription request failed with error: 500 Can't connect to 192.168.70.55:1400 (No route to host) at FHEM/lib/UPnP/ControlPoint.pm line 1153 thread 1.

und

Code Auswählen Erweitern

2020.06.27 13:59:05 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 13:59:36 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:01:17 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:01:27 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:02:23 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:02:40 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:02:48 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:02:55 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:03:50 1: SONOS1: Da keine Endzeit ermittelt werden konnte, wird kein Restoring durchgeführt werden!
2020.06.27 14:04:30 1: SONOS1: Error! Transport-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! Rendering-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! GroupRendering-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! ContentDirectory-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! Alarm-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! ZoneGroupTopology-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! DeviceProperties-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:04:30 1: SONOS1: Error! MusicServices-Subscription for ZonePlayer "RINCON_949F3E08E98201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:06:43 1: SONOS1: Couldn't load data from URL(https://api.classicalarchives.com/smapi/presentationmap.xml): 500 Status read failed:
2020.06.27 14:06:52 1: SONOS1: Error! Transport-Subscription for ZonePlayer "RINCON_B8E937E1619401400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:06:52 1: SONOS1: Error! Rendering-Subscription for ZonePlayer "RINCON_B8E937E1619401400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:06:52 1: SONOS1: Error! GroupRendering-Subscription for ZonePlayer "RINCON_B8E937E1619401400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 14:06:52 1: SONOS1: Error! ContentDirectory-Subscription for ZonePlayer "RINCON_B8E937E1619401400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 412 Precondition Failed at ./FHEM/00_SONOS.pm line 4212 thread 1.

oder auch diese Meldungen

Code Auswählen Erweitern

Thread 4 terminated abnormally: 500 Can't connect to 192.168.70.54:1400 (Connection timed out) at FHEM/lib/UPnP/ControlPoint.pm line 937 thread 4.
2020.06.27 14:09:06 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...
2020.06.27 14:09:37 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2020.06.27 14:09:38 1: SONOS0: ./FHEM/00_SONOS.pm is started by fhem...
2020.06.27 14:09:38 1: SONOS0: ./FHEM/00_SONOS.pm is listening to Port 4711
2020.06.27 14:09:46 1: SONOS1: UPnP-Thread gestartet.
2020.06.27 14:09:46 1: SONOS2: LongJobs-Thread gestartet. Prüfe auf LongJobs...
2020.06.27 14:09:46 1: SONOS3: IsAlive-Thread gestartet. Warte 120 Sekunden und pruefe dann alle 45 Sekunden...
2020.06.27 14:09:46 1: SONOS4: Restore-Thread gestartet. Warte auf Arbeit...
2020.06.27 14:10:15 1: SONOS1: Couldn't load data from URL(https://api.classicalarchives.com/smapi/presentationmap.xml): 500 Status read failed:
2020.06.27 14:21:21 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 14:21:22 1: SONOS1: Service-subscribing not possible due to missing TransportService
Loading device description failed with error: 500 read timeout (Location: http://192.168.70.28:5200/Printer.xml) at ./FHEM/00_SONOS.pm line 2463 thread 1.
Loading device description failed with error: 500 Can't connect to 192.168.70.28:5200 (Connection timed out) (Location: http://192.168.70.28:5200/Printer.xml) at ./FHEM/00_SONOS.pm line 2463 thread 1.
2020.06.27 15:43:41 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 15:43:42 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 15:44:11 1: SONOS1: Couldn't load data from URL(https://api.classicalarchives.com/smapi/presentationmap.xml): 500 Status read failed:
2020.06.27 15:53:54 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 15:53:55 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 15:54:36 1: SONOS1: Couldn't load data from URL(https://api.classicalarchives.com/smapi/presentationmap.xml): 500 Status read failed:
2020.06.27 16:25:08 1: SONOS1: Error! Transport-Subscription for ZonePlayer "RINCON_B8E937E1618C01400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 500 Can't connect to 192.168.70.53:1400 (No route to host) at ./FHEM/00_SONOS.pm line 4212 thread 1.

2020.06.27 16:25:09 1: SONOS1: Service-subscribing not possible due to missing TransportService
2020.06.27 16:39:14 1: SONOS1: Service-subscribing not possible due to missing TransportService
webei die IP-Adresse ...28 wirklich ein Drucker ist.

Zusätzlich habe ich in global folgenden Eintrag gefunden, der sehr ärgerlich ist, da autosave deaktiviert wird.

Code Auswählen Erweitern

Messages collected while initializing FHEM:./log/fhem.save: Reading Sonos_Wohnzimmer_TV->LastSubscriptionsRenew is now unused and is ignored for the future for all Zoneplayer-Types.

Autosave deactivated

Ich hoffe dies hilft bei der Fehlersuche. Zur Erläuterung: Ich habe zwei Raspberrys parallel laufen, die beide auf die Sonos-Boxen zugreifen.



Viele Grüße
Jürgen

[Reinerlein]

Hi Nobby,

ich habe bei mir jetzt den 412er Fehler auf Ignorieren umgestellt. Angeblich regeneriert sich der Player sowieso irgendwann selbst, und man kann nichts weiter machen... mal beobachten, ob das wirklich so ist...

@Jürgen: Sorry, da ist mir ein Fehler unterlaufen, als ich das Reading "LastSubscriptionsRenew" reaktiviert habe. Ich habe das nun von der unused-Liste runtergenommen...
Und du solltest dir mal die Ausschluss-Attribute anschauen. Damit wirst du deine Nicht-Sonos-Player mal los, die immer dazwischenfunken...

Grüße
Reinerlein

[Nobby1805]

Hi Reinerlein,
ich habe irgendwann mal mit der 1400-er Debug Schnittstelle von einem Player eine Liste aller aktiven Subscriptions bekommen ... weiß aber leider nicht mehr, wie ich das gemacht habe 🙁

Btw. wieso findet der Renew der Subscriptions eigentlich alle 30 Minuten statt? Und wenn ich mich richtig erinnere, dann wird dabei doch eine ,,Laufzeit" von 86.000 Sekunden angegeben

Gruß Nobby

[Reinerlein]

Hi Nobby,

es wird alle 5 Minuten nachgesehen, ob die 1800 Sekunden (30 Minuten) für ein Player-Renew abgelaufen sind. Die 1800 Sekunden werden vom Player angegeben...

Grüße
Reinerlein

[sTaN]

Also ich bekomme meine Sonos Player aktuell nicht mer zufriedenstellend zum Laufen.  Auch das komplette Löschen der Player und Neuanlage brachte keinen Erfolg.
Aktuell scheint wirklich ein Gerät im Netzwerk (meine Vermutung die Nanoleaf Canvas Beleuchtung) das Modul nach Anlage des Sonos device so zu blocken, dass das FHEM Webinterface mehrere Minuten nicht erreichbar ist und sich diverse Geräte auch nicht schalten lassen. Dadurch kann ich natürlich auch die ignoredIP's oder weitere Attribute wie reusedPort 1 etc. nicht setzen. Mir würde hier nur das Anlegen des Devices direkt in der Fhem.cfg einfallen inkl. der Attribute, aber hiervon wird ja immer wieder abgeraten.

Wenn das Webinterface dann irgendwann mal wieder erreichbar bleibt mein Sonos Player in der Küche leider disappeared...
Ich wünschte mein Kabelanschluss wäre nicht umgestellt und die FritzBox abgetauscht. Seitdem habe ich die Themen. Zuvor zwar auch, aber ich hatte wirklich 2 Monate Ruhe und die Bedienung über TabletUI lief erstklassig.

Habe seit meinen letzten Versuchen am Freitag die Sonos Module umbenannt und deaktiviert, da das FHEM Web regelmäßig blockiert wurde und nicht erreichbar war.

Schaue ich heute in die FHEM Logs habe ich auch keine Probleme mehr mit meiner harmony Fernbedienung (hier gab es ab und an auch sporadisch die Fehlermeldung harmony: disconnected im Logfile). Seit Freitag sehe ich die Meldung gar nicht mehr. Das Sonos Modul scheint wohl noch mehr negative Auswirkungen zu haben als ich dachte.

Ich hoffe, dass ihr hier noch weiteres Fehlerhandling verbaut bekommt, da meine Frau ohne Bedienung der Sonos Player über TabletUI glaube die Krise bekommt. 
Falls ich irgendwie testen/unterstützen kann, stehe ich gern zur Verfügung.

sTaN

[Reinerlein]

Hi sTaN,

du brauchst doch nur dein Fhem herunterfahren, die fhem.cfg editieren, und Fhem wieder hochfahren.

Und dort trägst du dann direkt ein "usedonlyIPs"-Attribut mit ein.
fhem.cfg:

Code Auswählen Erweitern


define Sonos SONOS
attr Sonos usedonlyIPs 192.168.0.20
Natürlich musst du die IP anpassen. Nimm ruhig erstmal nur eine bekannte...
Keine Player-Devices selber anlegen... Das kann das Modul selber viel besser

Interressant wäre auch mit was das Laden der Devicedescription abbricht, also die komplette Fehlermeldung zu "Loading device description failed with error:"...

Wenn im Log nichts Aussagekräftiges steht, dann kannst du mal verbose hochstellen, aber das erzeugt große Logs...

Code Auswählen Erweitern

attr Sonos verbose 5

Grüße
Reinerlein

[sTaN]

Hallo Rainerlein,

die Player habe ich nie selbst angelegt, sondern immer dem SubProcess überlassen.

Habe es jetzt noch mal in Angriff genommen und zuvor alle Player Devices gelöscht und zum Schluss das Sonos device (zuvor Sonos auf disable = 1 gesetzt, damit der SubProcess beendet wird).

Nach Neuanlage mit dem Wissen, dass es nach Anlage des Sonos device etwas dauern kann, habe ich mich erst mal arrangiert und gewartet bis FHEM wieder reagiert und alle Player da waren.
Jetzt bin ich wieder soweit, dass alle Player durch den SubProcess neu angelegt wurden und Status appeared haben. Aber interessanterweise lassen sich die Player nicht mehr über FHEM steuern. Das Cover, von dem Track der auf einem Sonos Player läuft wird noch angezeigt, aber bei Trackwechsel auch nicht mehr aktualisiert. Steuerung geht weder über das Webinterface, noch über TabletUI (letzteres logisch, wenn ersteres nicht funktioniert).

Player gehen dann wieder nach kurzer Zeit auf disappeared, aber der SuProcess wird scheinbar anschließend automatisch neugestartet:

Code Auswählen Erweitern

2020.06.28 16:10:01 2 : SONOS0: LastProcessAnswer way too old (Lastanswer: 1593353251 ~ 2020-06-28 16:07:31)... try to restart the process and connection...
2020-06-28 16:10:01 SONOS Sonos LastProcessRestart: 2020-06-28 16:10:01
2020-06-28 16:10:01 SONOS Sonos LastProcessRestartCount: 3
2020-06-28 16:10:01 SONOSPLAYER Sonos_Bad presence: disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Bad disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Kueche presence: disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Kueche disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Schlafzimmer presence: disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Schlafzimmer disappeared
2020-06-28 16:10:01 SONOSPLAYER Sonos_Wohnzimmer presence: disappeared
2020.06.28 16:10:31 1 : SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2020-06-28 16:10:39 SONOS Sonos CONNECTED

Soweit so gut. Nun heißt es wieder ca. 6 Minuten warten, da nach dem Neustart des UPnP Servers Fhem wieder hängt. In dieser Zeit geht auch mein harmonyhub kurz auf disconnect!

Und dann geht das Spielchen von vorne los:

Code Auswählen Erweitern

2020.06.28 16:16:22 2 : SONOS0: LastProcessAnswer way too old (Lastanswer: 1593353632 ~ 2020-06-28 16:13:52)... try to restart the process and connection...
2020-06-28 16:16:22 SONOS Sonos LastProcessRestart: 2020-06-28 16:16:22
2020-06-28 16:16:22 SONOS Sonos LastProcessRestartCount: 4
2020-06-28 16:16:22 SONOSPLAYER Sonos_Bad presence: disappeared
2020-06-28 16:16:22 SONOSPLAYER Sonos_Bad disappeared
2020-06-28 16:16:22 SONOSPLAYER Sonos_Schlafzimmer presence: disappeared
2020-06-28 16:16:22 SONOSPLAYER Sonos_Schlafzimmer disappeared
2020-06-28 16:16:22 SONOSPLAYER Sonos_Wohnzimmer presence: disappeared
2020-06-28 16:16:22 SONOSPLAYER Sonos_Wohnzimmer disappeared
2020.06.28 16:16:52 1 : SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...

Mittlerweile bin ich echt mit dem Latein am Ende...Man kann bei der Anlage ja nun wirklich nicht so viel falsch machen und ich bekomme sie nicht mal mehr für einen Tag zum Laufen.

Gruß
sTaN