Verbindung zwischen Fhem und Sonos bricht ab

[Reinerlein]

Hi Nobby,

bei der Adressierung nicht Hardware-Adresse zur Identifikation (das ist diese Rincon-MAC-Adresse, statisch ab Sonos-Werk) mit der IP-Adresse, also der Adresse, wo alle Steuersignale hin müssen (und natürlich auch der Datenverkehr herkommt) verwechseln.

Die Matrix sieht für dein Wohnzimmer halt gelb aus.
Das SonosNet versucht erstmal immer eine direkte Verbindung zur Brücke (egal, ob das nun eine Bridge oder ein normaler Player ist) aufzubauen.
Problematisch wird es halt, wenn diese Verbindung mal klappt, und dann mal wieder nicht... Sonos probiert es immer wieder von neuem, sobald die sich mal sehen.
Das wird dann das Routing, oder das, was man als MeshUp-Network bezeichnet, immer wieder durch die Direktverbindung ersetzt, da diese eher gewünscht ist...

Kannst du was über Stellung der Player ändern (z.B. ein Stück drehen oder so), bzw. auf WLAN umstellen, oder einen anderen Player ans Netz hängen?
Das mit der fehlenden Verbindung (incoming subscription) zwischen Wohnzimmer und Fhem ist schon komisch...

Grüße
Reiner

[Nobby1805]

Die Matrix sieht für dein Wohnzimmer halt gelb aus.

das ist mir aber unverständlich ... wenn ich mal vermute, dass grün besser als gelb ist

Die Bridge ist am LAN und von der Bridge zum Wohnzimmer-Player sind es ca. 4 m mit direktem Sichtkontakt, der Schlafzimmer-Player ist ein Stockwerk höher mit einer Stahlbetondecke dazwischen. Wenn ich das normale WLAN konfigurieren würde sind beide Player eher in schlechteren Positionen 

Gibt es irgendwo eine Beschreibung was mit NoiseFloor, OFDM, ANI usw. gemeint ist ?


Edit:
Die IP-Adresse des Wohnzimmer-Players hat sich übrigens seit längerem nicht verändert
und ich habe noch etwas im Log gefunden

2385 2017.01.13 17:53:25.362 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
2386 2017.01.13 18:06:39.612 3: SONOS1: ProxyObject does not exists
2387 2017.01.13 18:06:49.612 3: SONOS1: ProxyObject does not exists
2388 2017.01.13 18:35:43.174 3: SONOS1: ZoneGroupTopology-Subscription for ZonePlayer "RINCON_000E58E3988A01400_MR" has expired and is now renewed.

[Nobby1805]

Hallo Reiner,

ich habe da mal ein dumme Frage ...

Mir war bei meinem umgebauten Logging aufgefallen, dass ab und zu die Logs der 4 Threads durcheinander kamen ... ist ja einige Jahre her, dass ich mit Perl gearbeitet habe, im IT-Management ist das Selbstprogrammieren ja eher selten der Fall ... aber ich habe das jetzt mit shared-Variablen so hinbekommen wie ich das wollte

Jetzt zu der Frage, du verwendest ja auch shared-Variablen ... aber ich habe nirgendwo gefunden, dass die Thread-safe gelocked werden ... kann das der Auslöser für die Probleme sein ?

Viele Grüße und schönen (Schnee-)Sonntag noch
Nobby

[Reinerlein]

Hallo Nobby,

dumme Fragen gibt es nicht Und da Perl bei weitem weder meine beliebteste noch meine beherrschteste Sprache ist, kann auch ich immer nur dazulernen...

Zu den shared-Variablen:
Ich dachte immer, dass die sowas wie "volatile" abbilden, also immer ein direkten Zugriff auf das "Original" der Variablen durchgeführt wird, und somit jeder Thread den aktuellen Zustand der Variablen "sieht".

Ich weiß jetzt nicht genau, was du mit "Thread-Safe geblockt" meinst, aber durch obigen Mechanismus sollte da eigentlich kein Problem auftreten...

Das Problem mit dem Logging kommt meiner Meinung nach daher, dass Std-Out in die Fhem-Logdatei umgelenkt wird, und dadurch irgendwas mit den Threads, die Ihre Logausgaben auf Std-Out schreiben, in der Reihenfolge oder dem Filepositionmarker durcheinanderkommt.
Wenn die Ausgabe nicht umgelenkt wird (so wie früher mal), dann ging bei mir zumindest noch nie etwas verloren...

Ich verwende diese Variablen eigentlich sowie durch andere Prozesswege (wie Signale oder so) synchronisiert. Es gibt noch Queues, die ich verwende, da gehe ich aber von einer Thread-Safe Implementierung aus

Grüße
Reiner

[Nobby1805]

Ich dachte immer, dass die sowas wie "volatile" abbilden, also immer ein direkten Zugriff auf das "Original" der Variablen durchgeführt wird, und somit jeder Thread den aktuellen Zustand der Variablen "sieht".

Ich weiß jetzt nicht genau, was du mit "Thread-Safe geblockt" meinst, aber durch obigen Mechanismus sollte da eigentlich kein Problem auftreten...

DAs klassische Thread-Problem mit shared Variablen entsteht ja wenn eine davon z.B. ein Index oder ein Pointer ist und dieser nach dem Lesen, aber vor der Verwendung durch einen anderen Thread verändert wird ... siehe z.B. hier https://www.techfak.uni-bielefeld.de/ags/pi/lehre/NetProg12/Threads.pdf ab Folie 15

Das Problem mit dem Logging kommt meiner Meinung nach daher, dass Std-Out in die Fhem-Logdatei umgelenkt wird, und dadurch irgendwas mit den Threads, die Ihre Logausgaben auf Std-Out schreiben, in der Reihenfolge oder dem Filepositionmarker durcheinanderkommt.
Wenn die Ausgabe nicht umgelenkt wird (so wie früher mal), dann ging bei mir zumindest noch nie etwas verloren...

Es ging ja auch nichts verloren ... nur die Reihenfolge wurde verändert, vermutlich weil jeder Thread einen eigenen IO-Buffer hat und der erst bei Füllung zur Platet geschrieben wird ... jedes Mal open und Close hätte vermutlich auch gereicht, aber aus Performancegründen wollte ich das nicht und habe das jetzt mit geshareten Variablen gut gelöst

Ich habe jetzt sowohl für den Endlosloop als auch für das "Tut nicht"-Problem einige Logs eingebaut und sehe auch im aktuellen Log wie es aussieht wenn alles OK ist ... warten wir also ab, wann es das nächste Mal passiert

Gruß Nobby

[Nobby1805]

Hallo Reiner,

so, es ist wieder so weit ... die Verbindung zwischen FHEM und dem Sonos ist unterbrochen ... kannst du im Logging irgendetwas erkennen?

Logging von Gestern, als es noch klappte

333919 2017.01.23 10:25:58.209 3: SONOS0: foreach-loop GLOB(0x199b2bc) GLOB(0x198057c)
  333920 2017.01.23 10:25:58.209 1: SONOS0: Received: 'DoWork:RINCON_000E58A376D201400_MR:play:'
  333921 2017.01.23 10:25:58.209 1: SONOS0: DoWork: 'RINCON_000E58A376D201400_MR' 'play'
  333922 2017.01.23 10:25:58.209 1: SONOS0: vor ComObjectTransportQueue
    1604 2017.01.23 10:25:58.380 0: SONOS1: nach peek play
    1605 2017.01.23 10:25:58.380 3: SONOS1: play bearbeiten RINCON_000E58A376D201400_MR
    1606 2017.01.23 10:25:58.380 3: SONOS1: CheckProxyObject
  333923 2017.01.23 10:25:59.208 3: SONOS0: nach can_read
  333924 2017.01.23 10:25:59.209 3: SONOS0: vor foreach-loop
    1607 2017.01.23 10:25:59.333 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
    1608 2017.01.23 10:25:59.750 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
    1609 2017.01.23 10:25:59.849 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
    1610 2017.01.23 10:26:00.131 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
    1611 2017.01.23 10:26:00.192 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
  333925 2017.01.23 10:26:00.208 3: SONOS0: nach can_read
    1612 2017.01.23 10:26:00.195 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
  333926 2017.01.23 10:26:00.227 3: SONOS0: vor foreach-loop

Logging von Heute:

557608 2017.01.24 12:25:07.828 3: SONOS0: vor foreach-loop
  557609 2017.01.24 12:25:07.828 3: SONOS0: foreach-loop GLOB(0x199b2bc) GLOB(0x198057c)
  557610 2017.01.24 12:25:07.828 1: SONOS0: Received: 'DoWork:RINCON_000E58A376D201400_MR:play:'
  557611 2017.01.24 12:25:07.828 1: SONOS0: DoWork: 'RINCON_000E58A376D201400_MR' 'play'
  557612 2017.01.24 12:25:07.828 1: SONOS0: vor ComObjectTransportQueue
  557613 2017.01.24 12:25:08.827 3: SONOS0: nach can_read
  557614 2017.01.24 12:25:08.828 3: SONOS0: vor foreach-loop

nach dem ComObjectTransportQueue peekt er das Play-Kommando nicht aus der Queue ...

Ich habe dann mal gesucht welches die letzten Loggings des Thread 1 vor diesem Problem waren ... und das war heute

526029 2017.01.24 08:45:00.015 3: SONOS0: foreach-loop GLOB(0x199b2bc) GLOB(0x198057c)
  526030 2017.01.24 08:45:00.022 1: SONOS0: Received: 'DoWork:RINCON_000E58C1DE0A01400_MR:playURITemp:\\Homeserver\Musik\xx.mp3£@£~50'
  526031 2017.01.24 08:45:00.118 1: SONOS0: DoWork: 'RINCON_000E58C1DE0A01400_MR' 'playURITemp'
  526032 2017.01.24 08:45:00.118 1: SONOS0: vor ComObjectTransportQueue
  526033 2017.01.24 08:45:00.326 3: SONOS0: nach can_read GLOB(0x198057c)
  526034 2017.01.24 08:45:00.327 3: SONOS0: vor foreach-loop
  526035 2017.01.24 08:45:00.327 3: SONOS0: foreach-loop GLOB(0x198057c) GLOB(0x198057c)
  526036 2017.01.24 08:45:00.328 3: SONOS0: Connection accepted from HomeServer:2269
  526037 2017.01.24 08:45:00.329 3: SONOS0: nach can_read GLOB(0x1c533fc)
  526038 2017.01.24 08:45:00.329 3: SONOS0: vor foreach-loop
  526039 2017.01.24 08:45:00.329 3: SONOS0: foreach-loop GLOB(0x1c533fc) GLOB(0x198057c)
  526040 2017.01.24 08:45:00.329 1: SONOS0: Received: 'hello'
  526041 2017.01.24 08:45:00.330 3: SONOS0: nach can_read GLOB(0x1c533fc)
  526042 2017.01.24 08:45:00.330 3: SONOS0: vor foreach-loop
  526043 2017.01.24 08:45:00.330 3: SONOS0: foreach-loop GLOB(0x1c533fc) GLOB(0x198057c)
  526044 2017.01.24 08:45:00.330 1: SONOS0: Received: 'goaway'
    2363 2017.01.24 08:45:00.859 0: SONOS1: nach peek playURITemp
    2364 2017.01.24 08:45:00.984 3: SONOS1: Temporary playing of "\\Homeserver\Musik\xx.mp3" must wait, because another playing is in work...
  526045 2017.01.24 08:45:01.327 3: SONOS0: nach can_read

Das ist schon komisch ... jeden Tag um 8:45 spiele ich als Wecker einen Sound ab (aber auf einem anderen Player) ... warum endet das ganze mit dem "... must wait ..."
Wie sah das denn gestern aus?

319414 2017.01.23 08:45:00.017 1: SONOS0: Received: 'DoWork:RINCON_000E58C1DE0A01400_MR:playURITemp:\\Homeserver\Musik\xx.mp3£@£~50'
  319415 2017.01.23 08:45:00.122 1: SONOS0: DoWork: 'RINCON_000E58C1DE0A01400_MR' 'playURITemp'
  319416 2017.01.23 08:45:00.123 1: SONOS0: vor ComObjectTransportQueue
    1554 2017.01.23 08:45:01.005 0: SONOS1: nach peek playURITemp
    1555 2017.01.23 08:45:01.099 3: SONOS1: Start temporary playing of "\\Homeserver\Musik\xx.mp3"
    1556 2017.01.23 08:45:01.099 3: SONOS1: ProxyObject does not exists
  319417 2017.01.23 08:45:01.130 3: SONOS0: nach can_read

ProxyObject does not exist ?
Vorgestern sah es so aus

112542 2017.01.22 08:45:00.008 1: SONOS0: Received: 'DoWork:RINCON_000E58C1DE0A01400_MR:playURITemp:\\Homeserver\Musik\xx.mp3£@£~50'
  112543 2017.01.22 08:45:00.008 1: SONOS0: DoWork: 'RINCON_000E58C1DE0A01400_MR' 'playURITemp'
  112544 2017.01.22 08:45:00.008 1: SONOS0: vor ComObjectTransportQueue
     749 2017.01.22 08:45:00.144 0: SONOS1: nach peek playURITemp
     750 2017.01.22 08:45:00.144 3: SONOS1: Start temporary playing of "\\Homeserver\Musik\xx.mp3"
  112545 2017.01.22 08:45:01.003 3: SONOS0: nach can_read
  112546 2017.01.22 08:45:01.004 3: SONOS0: vor foreach-loop
  112547 2017.01.22 08:45:02.003 3: SONOS0: nach can_read
  112548 2017.01.22 08:45:02.003 3: SONOS0: vor foreach-loop
     751 2017.01.22 08:45:02.816 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Schlafzimmer".
  112549 2017.01.22 08:45:03.003 3: SONOS0: nach can_read
  112550 2017.01.22 08:45:03.004 3: SONOS0: vor foreach-loop
     752 2017.01.22 08:45:03.134 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
     753 2017.01.22 08:45:03.236 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     754 2017.01.22 08:45:03.237 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     755 2017.01.22 08:45:03.378 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     756 2017.01.22 08:45:03.380 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     757 2017.01.22 08:45:03.481 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Schlafzimmer".
     758 2017.01.22 08:45:03.492 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Schlafzimmer".
     759 2017.01.22 08:45:03.602 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Schlafzimmer".
     760 2017.01.22 08:45:03.763 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
     761 2017.01.22 08:45:03.894 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     762 2017.01.22 08:45:03.897 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
  112551 2017.01.22 08:45:04.003 3: SONOS0: nach can_read

Wenn dich sonst noch etwas im Logging interessiert ... ich habe noch alle Logs gespeichert, es sind z.Zt. ca. 12 MB pro Tag
Soll ich irgendwo zusätzliches Logging einbauen?

Viele Grüße
Nobby

[Reinerlein]

Hallo Nobby,

etwas an der Log-Ausgabe ist komisch: Ich verwende einen eigenen Trenner für die Parameter eines Befehls (damit in den Parametern auch Doppelpunkte u.ä. vorkommen können). Dieser Trenner lautet eigentlich £@£~, in deiner Log-Ausgabe ist vor dem Pfund-Zeichen noch ein Sonderzeichen.

Ich weiß jetzt nicht, ob das nur ein Problem der Logausgabe ist, oder wirklich bei der Übertragung verändert wird, aber vielleicht kannst du diesen Trenner einfach mal testweise umändern (es kommt zweimal im Code vor), z.B. in ~~@@~~?

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

was ist denn ~~@@~~

Ich finde die Sequenz mit dem Pfund genau 2x
Zeile 2114

Code Auswählen Erweitern

DevIo_SimpleWrite($hash, 'DoWork:'.$udn.':'.$method.':'.encode_utf8(join('£@£~', @params))."\r\n", 0);
Zeile 8940

Code Auswählen Erweitern

my @params = split(/£@£~/, decode_utf8($3));
Die Zeilennummern haben sich natürlich durch meine Einbauten verändert ... aber ich glaube das meinst du

Ich ändere das jetzt mal in §&§°

Viele Sonntagsgrüße
Nobby

[Reinerlein]

Hi Nobby,

Die Sequenz darf nur sicher nicht in den Parametern selbst vorkommen, und sollte für den Test aus reinen ASCII-Zeichen bestehen...
Du siehst ja jetzt direkt in der Logausgabe, ob irgendwelche Sonderzeichen zwischengerutscht sind

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

jetzt kommt

playURITemp:\\Homeserver\Musik\xx.mp3§&§°50'

wieder etwas "dazwischen" gerutscht ... ich untersuche das mal genauer, ob das an Windows, meiner Perl-Version oder wo auch immer liegt

Gruß Nobby

Edit: ja neee ... is klar

encode_utf8 ... und weder dein £ noch mein § oder ° gehören zu den 7-Bit Standard-ASCII und werden daher mit C2 escaped ...

Also kein Problem, daran kann mein Problem nicht liegen

[Nobby1805]

So es ist wieder passiert ...
das Play-/Pause-Kommando kommt im Thread an und kann dann nicht zum Player geschickt werden, weil

1760 2017.01.31 11:44:57.785 3: SONOS1: play bearbeiten RINCON_000E58A376D201400_MR
    1761 2017.01.31 11:44:57.785 3: SONOS1: ProxyObject does not exists

und der Log, den ich eingebaut habe weil ich vermutete, dass dort der Proxy gelöscht wird ist nicht gekommen ...also wird der Proxy woanders ohne Log gelöscht
Ich baue jetzt weitere Logs ein und überlege, den Proxy-Zustand zyklisch zu loggen

Wenn du noch weitere Ideen hast ... immer raus damit

Gruß Nobby

[Reinerlein]

Hi Nobby,

die Proxies werden eigentlich ausschließlich beim isAlive-Check gelöscht. Das würde aber vorher im Log stehen (kommt auf Level 3)...

Kam denn da was in der Richtung?

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

Nein, das wundert mich ja gerade... also noch weiteres Logging rein ...

Gruß Nobby

[Nobby1805]

Hallo Reiner,

es ist was passiert ...

Code Auswählen Erweitern

     233 2017.01.31 20:31:57.696 0: SONOS1: nach peek renewSubscription
     234 2017.01.31 20:31:57.696 3: SONOS1: AVTprox 2 RINCON_000E58A376D201400_MR RINCON_000E58C1DE0A01400_MR
     215 2017.01.31 20:32:17.232 1: SONOS2: IsAlive-Thread
     235 2017.01.31 20:32:17.716 3: SONOS1: Error! Transport-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 500 Can't connect to 192.168.1.50:1400 at ./FHEM/00_SONOS.pm line 3505 thread 1.
     236 2017.01.31 20:32:17.716 0: SONOS1: Delete ProxyObjects and SubscriptionObjects for 'RINCON_000E58C1DE0A01400_MR'
     237 2017.01.31 20:32:17.719 0: SONOS1: nach peek renewSubscription
     238 2017.01.31 20:32:17.719 3: SONOS1: AVTprox 1 RINCON_000E58A376D201400_MR

Vor dem Fehler gab es noch 2 Proxy-Einträge ... danach nur noch einen
Interessant ist auch, dass unmittelbar vor dem Fehler der IsLive-Thread "dazwischen" gekommen ist

Zeilennummer 3505 weist bei mir hier hin:

Code Auswählen Erweitern

3502 } elsif ($workType eq 'renewSubscription') {
3503 if (defined($SONOS_TransportSubscriptions{$udn}) && (Time::HiRes::time() - $SONOS_TransportSubscriptions{$udn}->{_startTime} > $SONOS_SUBSCRIPTIONSRENEWAL)) {
3504 eval {
3505 $SONOS_TransportSubscriptions{$udn}->renew();
3506 SONOS_Log $udn, 3, 'Transport-Subscription for ZonePlayer "'.$udn.'" has expired and is now renewed.';
3507 };
3508 if ($@) {
3509 SONOS_Log $udn, 3, 'Error! Transport-Subscription for ZonePlayer "'.$udn.'" has expired and could not be renewed: '.$@;
3510
3511 # Wenn der Player nicht erreichbar war, dann entsprechend entfernen...
3512 # Hier aber nur eine kleine Lösung, da es nur ein Notbehelf sein soll...
3513 if ($@ =~ m/Can.t connect to/) {
3514 SONOS_DeleteProxyObjects($udn);
3515 }
3516 }
3517 }

Mich wundert, dass der Log aus Zeile 3506 nicht erscheint ... ich muss allerdings zugeben, dass ich den Sinn von "eval" noch nicht verstanden habe

Interessant ist auch, dass das Problem jetzt erstmals am anderen Player aufgetreten ist 

Gruß Nobby

[Reinerlein]

Hi Nobby,

das Konstrukt mit dem "eval{};" und dem folgenden Prüfen auf "$@" ist sozusagen mit einem try...catch aus Hochsprachen vergleichbar.
Wenn ein Fehler innerhalb des eval-Blocks auftritt, wird dieser sofort beendet (aber eben nur der Block, und nicht das gesamte Skript), und es geht hinter dem Block weiter. Dort wird dann mit dem "if" die Fehlervariable von Perl auf Inhalt überprüft, und wenn etwas enthalten ist, der Fehler ausgegeben, und passend reagiert.

Das bedeutet, du hast einen Fehler beim Auffrischen der Subscription, und dabei lösche ich sofort den Proxy... das ist irgendwie übertrieben, da ich auch dort so etwas wie eine Gnadenfrist einräumen müsste (hat der isAlive-Checker ja auch). Zumal sich das auch nicht selbst korrigiert (heißt, der Proxy wird nicht neu verbunden), weil der Player ja gar kein Problem hat, und fortan vom Sonos-Modul einfach nicht angesprochen wird...

Ok, das ist auf jeden Fall ein Problem, welches ich beheben/umbauen muss... Ich schaue mir das an, danke für diese Suche... Hoffentlich bekommen wir das Problem damit dann in den Griff...

Grüße
Reiner