SONOS blockiert FHEM für Minuten

[FrankOverIP]

Hallo,

seit heute blockiert augenscheinlich das Sonos-Modul meine FHEM Installation. Die Verarbeitung bleibt jeweils für ziemlich exakt 3 Minuten hängen, ohne dass ich dafür einen Grund finden kann. Wie das so ist, behaupte ich standhaft in der letzten Zeit keine Veränderungen vorgenommen zu haben - in der letzten Zeit lief FHEM einfach rund und ich war mit anderen Dingen beschäftigt.

Um überhaupt auf Sonos als Übeltäter zu kommen, habe ich für global verbose auf 5 gestellt. Im Log finde ich dann z.B. folgende Einträge - man achte auf die Zeitstempel:

Code Auswählen Erweitern


2019.05.05 13:48:58 5: End notify loop for global
2019.05.05 13:48:58 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s99172</id><title>WDR 2 Münsterland</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g3</genreId><genre>Adult Hits</genre><twitterId>wdr2</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>128</bitrate><reliability>94</reliability><logo>http://cdn-radiotime-logos.tunein.com/s99172q.png</logo><title>94.1 FM</title><subtitle>Köln, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 13:51:58 5: Starting notify loop for Sonos_Schlafzimmer, 6 event(s), first is currentTrackURI: http://http://dg-wdr-http-dus-dtag-cdn.cast.addradio.de/wdr/wdr2/muensterland/mp3/128/stream.mp3?ar-distributor=f0a1
2019.05.05 13:51:58 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo:


Code Auswählen Erweitern


2019.05.05 15:15:45 5: Starting notify loop for Sonos, 1 event(s), first is LastProcessAnswer: 1557062145.66123
2019.05.05 15:15:45 5: End notify loop for Sonos
2019.05.05 15:15:46 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s99172</id><title>WDR 2 Münsterland</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g3</genreId><genre>Adult Hits</genre><twitterId>wdr2</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>128</bitrate><reliability>90</reliability><logo>http://cdn-radiotime-logos.tunein.com/s99172q.png</logo><title>94.1 FM</title><subtitle>Köln, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 15:18:46 5: Starting notify loop for Sonos, 1 event(s), first is LastProcessAnswer: 1557062326.99233
2019.05.05 15:18:47 5: End notify loop for Sonos
2019.05.05 15:18:47 5: Starting notify loop for Sonos_Schlafzimmer, 2 event(s), first is currentTrackPositionSimulated: 0:03:29


Wenn ich Sonos per disable abschalte, läuft alles wieder rund.

Im Rahmen der Fehlersuche habe ich ein update / shutdown restart gemacht, was aber keine Veränderung brachte. Die Sonos-Boxen haben die aktuelle Systemversion.

Hat vielleicht jemand einen Hinweis für mich, was die Ursache für die Blockade sein kann, oder was ich noch zur Ursachenforschung tun kann?

Viele Grüße
Frank

[FrankOverIP]

Ich ergänze mal eine neue Erkenntnis zu meinem eigenen Beitrag: es liegt offenbar an TuneIn. Ich hatte die ganze Zeit unseren üblichen Radiosender laufen, der die Sonos über TuneIn erreicht. Wenn ich eine andere Quelle verwende - Spotify, lokales NAS - gibt es offenbar keine Probleme. Wenn ich bei einem laufenden Stream von Spotify auf TuneIn umschalte, hängt FHEM unmittelbar für die nächsten drei Minuten. Schalte ich in dieser Zeit wieder zurück auf Spotify, geht es nach der Zwangspause problemlos weiter.

Kann es sein, dass das Sonos-Modul über den Anbieter des Streams weitere Informationen bezieht und an dieser Stelle dann im Zweifel zu einer Blockade führt?

[networker]

Vielleicht ein Problem  mit der Namensauflösung?

Networker

[FrankOverIP]

Vielleicht ein Problem  mit der Namensauflösung?
Networker

Wenn es an der Namensauflösung liegen würde, hätte ich das Thema vermutlich auch bei Spotify. Zur Sicherheit habe ich aber mal einen Ping auf cdn-radiotime-logos.tunein.com gemacht - der wurde problemlos aufgelöst.

Viele Grüße
Frank

[juemuc]

Hallo zusammen,

ich spiele ausschließlich Sender von Tunein über Sonos ab. Bisher keine Probleme.

Viele Grüße
Jürgen

[RalfP]

Hallo,

das Problem kann ich bestätigen. Hat gestern Abend begonnen. Höre TuneIn Sender wie "Radio Leipzig" oder "The Wave". Konnte es so weit eingrenzen, das sobald eine neue Titelinformation eines Radiosenders gesendet wurde, Fhem für etliche Minuten eingefroren ist.

Code Auswählen Erweitern


2019.05.05 20:32:22 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s140647</id><title>The Wave - relaxing radio</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g10</genreId><genre>Easy Listening</genre><twitterId>the_wave_radio</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>192</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s140647q.png</logo><title> Stream</title><subtitle>Berlin, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 20:32:22 5: SONOSPLAYER0: Notify-CoverTitle: transportState: PLAYING
2019.05.05 20:32:22 5: SONOSPLAYER0: Notify-TransportState: transportState: PLAYING
2019.05.05 20:32:22 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo: Verbindung herstellen...
2019.05.05 20:32:22 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []
2019.05.05 20:32:23 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s140647</id><title>The Wave - relaxing radio</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g10</genreId><genre>Easy Listening</genre><twitterId>the_wave_radio</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>192</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s140647q.png</logo><title> Stream</title><subtitle>Berlin, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 20:35:23 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo: Wird gestartet...
2019.05.05 20:35:23 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []

2019.05.05 20:35:24 1: [Freezemon] Freezemonitor: possible freeze starting at 20:32:23, delay is 181.747

2019.05.05 20:35:31 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s140647</id><title>The Wave - relaxing radio</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g10</genreId><genre>Easy Listening</genre><twitterId>the_wave_radio</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>192</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s140647q.png</logo><title> Stream</title><subtitle>Berlin, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 20:38:31 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo: EARTH, WIND & FIRE - AFTER THE LOVE HAS GONE
2019.05.05 20:38:31 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []
2019.05.05 20:38:32 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s140647</id><title>The Wave - relaxing radio</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g10</genreId><genre>Easy Listening</genre><twitterId>the_wave_radio</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>192</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s140647q.png</logo><title> Stream</title><subtitle>Berlin, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 20:38:32 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo: CHARLIE PUTH - SOME TYPE OF LOVE
2019.05.05 20:38:32 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []
2019.05.05 20:38:32 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s140647</id><title>The Wave - relaxing radio</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g10</genreId><genre>Easy Listening</genre><twitterId>the_wave_radio</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>192</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s140647q.png</logo><title> Stream</title><subtitle>Berlin, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.05 20:38:33 5: SONOSPLAYER0: Notify-CoverTitle: transportState: STOPPED
2019.05.05 20:38:33 5: SONOSPLAYER0: Notify-TransportState: transportState: STOPPED
2019.05.05 20:38:33 5: SONOSPLAYER0: Notify-CoverTitle: currentSenderInfo:
2019.05.05 20:38:33 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []

2019.05.05 20:38:35 1: [Freezemon] Freezemonitor: possible freeze starting at 20:35:25, delay is 190.976
 

In der Hoffnung, das dies eher an TuneIn liegt, könnte morgen vielleicht ja wieder alles OK sein. Trotzdem wäre hie evtl. ein Timeout angebracht, oder?

Für weitere Tipps wäre ich sehr Dankbar. Schlecht wenn meine Frau das Licht minutenlang nicht mehr einschalten kann.

vielen Dank
Ralf

[RalfP]

Hallo,

heute morgen leider nich besser. Hier noch ein Schnipsel aus dem Log:

Code Auswählen Erweitern


2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: transportState: PLAYING
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-TransportState: transportState: PLAYING
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: numberOfTracks: 1
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: currentTrackProviderIconRoundURL:
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: currentTitle: x-rincon-buzzer:0
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: currentAlbumArtURL: /fhem/sonos/cover/empty.jpg
2019.05.06 05:15:02 5: SONOSPLAYER0: Notify-CoverTitle: currentSender:
2019.05.06 05:15:04 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []

2019.05.06 05:18:13 5: SONOS0: Radioservice-Metadata: read timeout at /usr/share/perl5/Net/HTTP/Methods.pm line 268.

2019.05.06 05:18:13 5: SONOSPLAYER0: Notify-CoverTitle: transportState: STOPPED
2019.05.06 05:18:13 5: SONOSPLAYER0: Notify-TransportState: transportState: STOPPED
2019.05.06 05:18:13 5: SONOSPLAYER0: Notify-CoverTitle: currentTitle: The Wave - relaxing radio
2019.05.06 05:18:13 5: SONOSPLAYER0: Notify-CoverTitle: currentAlbumArtURL: /fhem/sonos/proxy/aa?url=http%3A%2F%2F192.168.2.69%3A1400%2Fgetaa%3Fs%3D1%26u%3Dx-sonosapi-stream%253as140647%253fsid%253d254%2526flags%253d8224%2526sn%253d0
2019.05.06 05:18:14 5: SONOS0: Player: WG.sz.Sonos ~ Slaves: []

2019.05.06 05:18:14 1: [Freezemon] Freezemonitor: possible freeze starting at 05:15:14, delay is 180.027


Hab mich vom Sonoswecker wecken lassen. Danach sollten einige Dinge passieren, wie auch das ein Radiosender abgespieltes werden soll, was leider in die Hose ging. SONOS ging diesmal sogar von allein in disable. Hab es nun notgedrungen nun erst einmal selbst auch auf disable 1 gestellt.

PS: Auffällig ist, das meist die Unterbrechung fast immer rund 180s dauert, bei Titelwechsel 

einen schönen Tag wünsche ich
Gruß
Ralf

[CQuadrat]

Das mit den genau(!) 180 Sekunden kann ich auch bestätigen.
Gefühlt immer dann, wenn ich relativ viel Sonos manuell per Frontend schalte.
Das ganze tritt bei mir allerdings schon seit mehreren Monaten auf.

Ich nutze aber kein Spotify; nur TuneIn-Sender, Musik vom NAS, Amazon-Prime und Sprachdurchsagen.

[Wuehler]

Moin,

ich hatte heute morgen erstmals unten beschriebene Probleme. Auch mit TuneIn-Sendern. Playlists funktionieren. In der SonosApp ging TuneIn ebenfalls nicht sauber. Beim fhem restart ist mir im Log noch die Meldung aufgefallen, dass $logo im Sonos-Modul nicht initialized sei. Der Restart (service fhem stop/start) hat leider auch nicht funktioniert, da ich die 3 Minuten vermutlich nicht abgewartet habe. FHEM ist (noch) nicht sauber runtergefahren, so dass der Port von FhemWeb nicht frei war. 
Tiefer analysieren kann ich leider erst wieder heute Abend.

Gruß,
Dirk

[Phiolin]

Kann dazu nicht viel mehr beitragen als: Hier auch - genau das gleiche Problem.

Stehe gerne zur Verfügung, wenn irgendwas debug'ed werden soll.

Hatte fhem mal mit -d im Debug Modus laufen. Das ist jeweils das letzte, was ausgegeben wird, bevor sich alles aufhängt, nach genau 3 Minuten geht es dann weiter... aber ohne große Fehlermeldungen o.ä.:

Code Auswählen Erweitern

2019.05.06 09:37:47 5: SONOS0: Player: Sonos_Schlafzimmer ~ Slaves: []
2019.05.06 09:37:47 5: SONOS0: Radioservice-Metadata: <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><getMediaMetadataResponse xmlns="http://www.sonos.com/Services/1.1"><getMediaMetadataResult><id>s99166</id><title>WDR 2 Ruhrgebiet</title><itemType>stream</itemType><language>de</language><country>DEU</country><genreId>g3</genreId><genre>Adult Hits</genre><twitterId>wdr2</twitterId><liveNow>true</liveNow><onDemand>false</onDemand><streamMetadata><bitrate>128</bitrate><reliability>95</reliability><logo>http://cdn-radiotime-logos.tunein.com/s99166q.png</logo><title>87.8 FM</title><subtitle>Köln, Germany</subtitle><secondsRemaining>43200</secondsRemaining><secondsToNextShow>0</secondsToNextShow><nextShowSeconds>0</nextShowSeconds></streamMetadata></getMediaMetadataResult></getMediaMetadataResponse></soap:Body></soap:Envelope>
2019.05.06 09:40:47 5: SONOS0: Player: Sonos_Wohnzimmer ~ Slaves: []
2019.05.06 09:40:47 5: PRESENCE (xyz_phone) - received data: absence;room=;rooms=;rssi=;


Kurz danach hängt es sich dann direkt wieder an der gleichen Stelle auf, für wieder 3 Minuten...

[Nobby1805]

Welche Software-Version läuft den auf euren Sonos-Boxen ... da ist in der letzten Woche ein Update erfolgt (10.1.2)

[Phiolin]

Das Update habe ich erst heute morgen eingespielt, in der Hoffnung, dass es das Problem irgendwie löst. Bei mir bestand das Problem also heute morgen schon vor dem letzten Sonos-Firmware Update.

Zumindest für meine Installation kann ich sagen, dass das Problem praktisch über Nacht aufgetaucht ist. Gestern schien tagsüber noch alles problemlos zu laufen, heute morgen ging dann mein auf Sonos basierender FHEM-Wecker nicht. Im Zuge der Problemsuche habe ich dann unter anderem das Sonos Update eingespielt. Das Update scheint aber bei mir zumindest nicht der Auslöser gewesen zu sein, außer die Boxen haben über Nacht irgendein anderes Update gezogen. Da bei mir Auto-Update aber deaktiviert ist, sollte das eigentlich nicht passieren - da die App mir das Update heute morgen auch noch angeboten hat, kann es zu dem Zeitpunkt dann auch noch nicht installiert gewesen sein.

Fhem-seitig ist die Installation auf dem aktuellen Stand, sprich FHEM Updates wurden zuletzt heute morgen eingespielt, allerdings auch erst nachdem das Problem schon bestand. Dabei wurden auch keine SONOS Module aktualisiert, hier kann es also auch keinen Zusammenhang geben. Reboots, Neustarts und ähnliches der FHEM Installation oder der darunter liegenden Hardware machen auch keinen Unterschied.

[FrankOverIP]

Eigentlich wollte ich mir das Problem gerade nochmal ansehen, kann es aber nicht mehr reproduzieren. Kann das jemand, der auch mit den Timeouts zu kämpfen hatte, bestätigen?

[Phiolin]

Nö, scheint weg zu sein. Da möchte man doch gar nicht wissen, woher das kam und wie abhängig man da von Sonos (als "Provider") ist...
Wäre aber natürlich trotzdem schön, wenn Reiner vielleicht gucken könnte, ob man dieses Problem durch entsprechende Timeout-Behandlung im Modul abfangen kann.

Edit: Kurze Verzögerungen gibt es scheinbar immer noch, aber nicht mehr 3 Minuten. Gerade einen Hänger von 25 Sekunden gesehen. Allerdings auch nur 1 Mal, generell scheint es also deutlich besser zu sein.

[FrankOverIP]

Es ist etwas schade, dass aus den bisherigen Posts nicht ersichtlich wird, an welcher Stelle genau es zu dem Timeout gekommen ist. Ich hatte zunächst einen Webservice im Verdacht (http://legato.radiotime.com/Radio.asmx), allerdings steht in meinem Log ja noch eine Antwort von diesem Service. Der Timeout scheint also eher danach aufzutreten, nicht direkt bei diesem Service.

Wie auch immer, ich würde mich auch besser dabei fühlen, wenn solche Timeouts unterbunden würden. Leider ist es mit meinem Perl Know-how nicht weit her. Ich sehe in der Doku, dass das verwendete Objekt LWP::UserAgent einen Timeout unterstützt ($ua->timeout( $secs ). Ob ich aber mit meinem gefährlichen Halbwissen an diesem nicht ganz trivialen Modul rumfingern will... Das sollte wohl jemand machen, der sich damit auskennt.