Verbindung zwischen Fhem und Sonos bricht ab

[Nobby1805]

Ich habe seit einiger zeit das Problem, dass jeweils nach ein paar Tagen die Verbindung zwischen Fhem und Sonos unterbrochen wird ... Änderungen auf den Sonos Geräten werden im Fhem nicht mehr angezeigt und Aktionen aus dem Fhem heraus führt Sonos nicht mehr aus.

Wenn ich mir den vom Sonos Modul erzeugten Sub-Prozess ansehe, dann ist hier noch zyklischer Datenverkehr mit den Sonos-Komponenten feststellbar, ab und zu habe ich auch schon gesehen, dass dieser Prozess einen Kern der CPU zu 100% auslastet.

Wenn man den Sub-Prozess abschießt, oder wie heute Morgen passiert dieser abstürzt, dann wird er nach einiger Zeit neu gestartet und Sonos ist mit Fhem wieder voll funktionsfähig.

Interessant ist das Verhalten von heute Morgen, um 8:45 wurde auf einem Play.1 ein Sound ausgegeben, kurz danach ging der Sub-Prozess in einen Loop und ist dann um 9:13 abgestürzt ...da ich seit einiger Zeit eine Prozessmonitor mitlaufen lassen habe ich folgendes Log eingefangen:

Code Auswählen Erweitern

08:45:41,1091860 perl.exe 12464 Thread Exit SUCCESS Thread ID: 10684, User Time: 33.6406250, Kernel Time: 60.8750000
08:45:41,1101406 perl.exe 12464 Thread Exit SUCCESS Thread ID: 12480, User Time: 487.9218750, Kernel Time: 30.7500000
08:45:41,1104838 perl.exe 12464 Thread Exit SUCCESS Thread ID: 6052, User Time: 20.1093750, Kernel Time: 1.7500000
08:50:33,9592322 perl.exe 12464 Thread Exit SUCCESS Thread ID: 10612, User Time: 0.1875000, Kernel Time: 0.6406250
09:13:11,0910788 perl.exe 12464 Thread Exit SUCCESS Thread ID: 13388, User Time: 9104.4218750, Kernel Time: 1666.3281250
09:13:11,0921045 perl.exe 12464 Process Exit SUCCESS Exit Status: 9, User Time: 9646.2812500 seconds, Kernel Time: 1760.3437500 seconds, Private Bytes: 10.100.736, Peak Private Bytes: 53.518.336, Working Set: 12.644.352, Peak Working Set: 53.870.592

Ebenso habe ich beim sonos-Modul seit einiger Zeit verbose auf 4 gesetzt ... normalerweise kommt dort nur alle 30 Sekunden

Code Auswählen Erweitern

2016.12.14 08:43:32.433 4: SONOS0: Got correct Answer from Subprocess...

heute Morgen sah es etwas anders aus

Code Auswählen Erweitern

2016.12.14 08:45:25.522 0: SONOS0: No Answer from Subprocess. Restart Sonos-Subprocess...
2016.12.14 08:45:26.249 1: Perfmon: possible freeze starting at 08:45:07, delay is 19.249
2016.12.14 08:45:34.116 3: Opening Sonos device localhost:4711
2016.12.14 08:45:34.157 3: Sonos device opened
2016.12.14 08:46:35.343 4: SONOS0: Got correct Answer from Subprocess...

und die letzte Meldung weiter alle 3 Sekunden bis

Code Auswählen Erweitern

2016.12.14 09:13:12.218 4: SONOS0: Got correct Answer from Subprocess...
2016.12.14 09:13:14.211 1: SONOS0: Nothing could be read from TCP-Channel (the first level) even though the Read-Function was called.
2016.12.14 09:13:15.256 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2016.12.14 09:13:24.241 3: Opening Sonos device localhost:4711
2016.12.14 09:13:25.178 3: Can't connect to localhost:4711: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2016.12.14 09:14:25.282 1: localhost:4711 reappeared (Sonos)


Was passiert da? Wie kann ich das vermeiden?

Wenn ich weitere Loggings einschalten soll, welche?

[justme1968]

reiner konnte das problem bis jetzt nicht reproduzieren.

ich starte inzwischen jede nacht den sonos prozess neu:

Code Auswählen Erweitern

define sonosReconnect at *03:00 attr sonos disable 1;; sleep 90;; deleteattr sonos disable;; savenicht ideal, funktioniert aber. damit habe ich dem keine probleme mehr.

[Nobby1805]

Danke für den Workaround ... aber eine Lösung wäre mir lieber  ich bin auch zu jeder Art von Support bereit, bei mir tritt es ziemlich "regelmäßg" auf, auch wenn ich bisher noch keine Regel feststellen konnte

Ich habe mir den Quellcode mal angesehen ... aber da bräuchte ich erst mal einige Zeit um überhaupt zu verstehen was dort wo genau gemacht wird um zu wissen, welche Logs eingeschaltet bzw. erstmal hinzugefügt werden sollten

PS sehe ich das richtig, bei dir läuft es auf einem Raspi? Dann kann es ja nicht an meiner exotischen Windows-Server-Umgebung liegen

[justme1968]

beim mir läuft fhem auf einer intel synology diskstation mit active perl. also eigentlich ein ziemlich normales linux und auch ein ziemlich normales perl.

ich habe den verdacht das es irgendwie mit dem automatischen umschalten eines players zwischen wlan und sonos net zu tun hat wenn die dinger sich selber neu konfigurieren weil der andere weg gerade besser ist.

[Nobby1805]

Hmm ...das allgemeine WLAN  ist bei mir aber gar nicht im Sonos konfiguriert ... "damals" als ich mit Sonos anfing ging das gar nicht und ich habe die Einstellung mit der Sonos-Bridge bisher nicht verändert

[Nobby1805]

Heute Morgen wurde um 8:45 nicht der erwartete Sound ausgegeben, aber es kamen einige Meldungen im Log die ich bisher noch nicht gesehen habe

Code Auswählen Erweitern

2016.12.15 08:21:14.793 2: SONOS0: Error during MainTrigger: syntax error at (eval 873614) line 1, at EOF
- Trying to execute 'Sorry. I don't understand you - ''.'
2016.12.15 08:21:14.803 2: SONOS0: Error during MainTrigger: syntax error at (eval 873615) line 1, at EOF
- Trying to execute 'Sorry. I don't understand you - 'C:\FHEM>sendemail ...
2016.12.15 08:21:14.809 2: SONOS0: Error during MainTrigger: syntax error at (eval 873616) line 1, at EOF
- Trying to execute 'Sorry. I don't understand you - 'Dec 15 08:21:08 homeserver sendemail[10276]: Email was sent successfully!'.'

Da wurde aufgrund eines Fensterkontaktes eine E-Mail geschickt ... aber warum kommt dann eine Fehlermeldung von Sonos ?
um 8:45 dann

Code Auswählen Erweitern

2016.12.15 08:45:00.542 4: SONOS0: DoWorkAnswer arrived for Sonos_Schlafzimmer->LastActionResult: 'CheckProxyObject-ERROR: SonosPlayer disappeared?'

um 8:54 gab es dann Transport Events für diesen Player ohne weitere Fehlermeldung, aber: dieser Player lässt sich seitdem nicht über Fhem bedienen, die Änderungen am Player kommen aber im Fhem an ... der andere Player funktioniert weiterhin problemlos

[Nobby1805]

Im Moment scheint das Sonos-Modul bei mir sehr instabil zu sein ...

Code Auswählen Erweitern

Date & Time: 17.12.2016 12:43:30
Event Class: Process
Operation: Process Exit
Result: SUCCESS
Path:
TID: 10592
Duration:         0.0000000
Exit Status: 22
User Time: 5775.2968750 seconds
Kernel Time: 1103.6406250 seconds
Private Bytes: 10.313.728
Peak Private Bytes: 53.927.936
Working Set: 12.824.576
Peak Working Set: 53.202.944

Im Log ist aber um 12:43:30 kein Fehler angezeigt ...nur etwas früher war etwas und danach sieht man den neuen Start

Code Auswählen Erweitern

2016.12.17 12:25:32.145 0: SONOS0: No Answer from Subprocess. Restart Sonos-Subprocess...
2016.12.17 12:25:40.379 3: Opening Sonos device localhost:4711
2016.12.17 12:25:40.676 3: Sonos device opened
2016.12.17 12:43:38.192 1: SONOS0: Nothing could be read from TCP-Channel (the first level) even though the Read-Function was called.
2016.12.17 12:43:39.348 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2016.12.17 12:43:48.864 3: Opening Sonos device localhost:4711
2016.12.17 12:43:49.863 3: Can't connect to localhost:4711: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2016.12.17 12:44:50.405 1: localhost:4711 reappeared (Sonos)

Unter Exit Status 22 habe ich gefunden: The device does not recognize the command.
Wird da irgendwo im Sonosmodul ein Exitstatus nicht richtig abgefangen ?

[Nobby1805]

Hallo Reiner(lein),

heute habe ich festgestellt, dass der SONOS-Subprozess wieder mall geloopt hat ... da ich bisher nie dazu passende Meldungen im Log gefunden habe (gegenseitige Störung mit dem normalen Fhem-Logging), habe ich das Logging im Sonosmodul etwas umgebaut und schreibe die Meldungen des Subprozesses jetzt in einen Logfile ... und habe auch ein paar zusätzliche Meldungen eingebaut

Also war ich gespannt, was im Log zu finden ist ... der Logfile ist 735 MB groß  da musste ich erst mal ein Möglichkeit finden, das zu bearbeiten 

89 2017.01.09 10:40:40.562 3: SONOS0: foreach-loop GLOB(0x1980bac) GLOB(0x1980bac)
90 2017.01.09 10:40:40.562 3: SONOS0: Connection accepted from HomeServer:1603
91 2017.01.09 10:40:40.563 3: SONOS0: foreach-loop GLOB(0x1c53f3c) GLOB(0x1980bac)
92 2017.01.09 10:40:40.563 1: SONOS0: Received: 'hello'
93 2017.01.09 10:40:40.566 3: SONOS0: foreach-loop GLOB(0x1c53f3c) GLOB(0x1980bac)
94 2017.01.09 10:40:40.566 1: SONOS0: Received: 'goaway'

95 2017.01.09 10:41:10.578 3: SONOS0: foreach-loop GLOB(0x1980bac) GLOB(0x1980bac)
96 2017.01.09 10:41:10.578 3: SONOS0: Connection accepted from HomeServer:1624
97 2017.01.09 10:41:10.578 3: SONOS0: foreach-loop GLOB(0x1c496fc) GLOB(0x1980bac)
98 2017.01.09 10:41:10.579 1: SONOS0: Received: 'hello'
99 2017.01.09 10:41:10.581 3: SONOS0: foreach-loop GLOB(0x1c496fc) GLOB(0x1980bac)
100 2017.01.09 10:41:10.581 1: SONOS0: Received: 'goaway'

101 2017.01.09 10:41:41.140 3: SONOS0: foreach-loop GLOB(0x1980bac) GLOB(0x1980bac)
102 2017.01.09 10:41:41.140 3: SONOS0: Connection accepted from HomeServer:1701
103 2017.01.09 10:41:41.143 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
104 2017.01.09 10:41:41.143 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
105 2017.01.09 10:41:41.144 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
106 2017.01.09 10:41:41.144 3: SONOS0: foreach-loop GLOB(0x199a6ac) GLOB(0x1980bac)
107 2017.01.09 10:41:41.144 1: SONOS0: Received: 'disconnect'
108 2017.01.09 10:41:41.144 3: SONOS0: Disconnecting client...
109 2017.01.09 10:41:41.144 3: SONOS0: Trying to kill Sonos_Thread...
110 2017.01.09 10:41:41.145 3: SONOS0: Trying to kill IsAlive_Thread...
111 2017.01.09 10:41:41.145 3: SONOS0: Trying to kill PlayerRestore_Thread...
112 2017.01.09 10:41:41.145 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
113 2017.01.09 10:41:41.145 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
114 2017.01.09 10:41:41.145 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
115 2017.01.09 10:41:41.145 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
116 2017.01.09 10:41:41.146 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
117 2017.01.09 10:41:41.146 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)
118 2017.01.09 10:41:41.146 3: SONOS0: foreach-loop GLOB(0x1c498dc) GLOB(0x1980bac)

Die letzte Meldung kommt danach mehrfach pro Millisekunde bis zum Abbruch des Subprozesses

Die "foreach-loop"-Meldung habe ich hinzugefügt

Code Auswählen Erweitern

foreach my $so (@ready) {
SONOS_Log undef, 3, "foreach-loop $so $sock";
if ($so == $sock) { # New Connection read

und das Loglevel der Received-Message habe ich von 5 auf 1 geändert

Hast du eine Erklärung was da passiert? Und/oder eine Idee was noch gelogt werden sollte um mehr Infos zu bekommen  bzw. geändert werden müsste um den Loop zu vermeiden? An ein paar Stellen im Modul habe ich Waits gesehen um Loops zu vermeiden, aber hier gibt es so etwas anscheinend  nicht

Viele Grüße
Nobby

[Reinerlein]

Hi Nobby,

das ist schon sehr komisch. Es scheint so, als würde er das foreach nicht weitermachen, oder landet er immer wieder von neuem in der foreach?
Wenn das so wäre sollte doch eigentlich die 0.5 bei der can_read()-Abfrage eine 100%-Loop verhindern...

Wenn er die foreach-Schleife nicht weitermachen sollte, könntest du daraus mal eine for-Schleife bauen:

Code Auswählen Erweitern


.
.
for (my $i = 0; $i < scalar(@ready); $i++) {
my $so = $ready[$i];
.
.


Grüße
Reiner

[Nobby1805]

Hallo Reiner,

ich habe das jetzt ein bisschen umgebaut damit man beim nächsten Mal erkennen kann was dort genau passiert

Bei mir wird can_read() übrigens mit 0.1 aufgerufen ... habe ich da einen Update nicht mitbekommen ?

Jetzt müssen wir nur noch auf den nächsten Loop warten ... ich melde mich dann

Gruß Nobby

[Reinerlein]

Hi Nobby,

bei mir auch, die 5 wurde von meinem iPad reingeschummelt
Sollte trotzdem reichen, da es eigentlich nur für eine Rückgabe der Ausführungshoheit an die Signal- und Interruptverarbeitung sorgt...

Warten wir's mal ab...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

nein, leider ist der Loop noch nicht wieder aufgetreten aber: jetzt habe ich wieder die Situation, dass die Kommunikation zwischen dem Fhem und einem Sonos-Player nicht funktioniert ... Kommandos erreichen den Player nicht und Änderungen am Player, über die Sonos-App, bekommt Fhem nicht mit ...

Das letzte Kommando war ein "Pause" an den Player am Mittwoch ... heute gab es dann ein "Play", das aber den Player nicht startete

LastActionResult  ist CheckProxyObject-ERROR: SonosPlayer disappeared?

Im Log finde ich nur

683458 2017.01.13 18:06:39.292 3: SONOS0: vor foreach-loop
683459 2017.01.13 18:06:39.292 3: SONOS0: foreach-loop GLOB(0x199af34) GLOB(0x1981004)
683460 2017.01.13 18:06:39.292 1: SONOS0: Received: 'DoWork:RINCON_000E58A376D201400_MR:play:'
683461 2017.01.13 18:06:40.283 3: SONOS0: nach can_read

Kann ich sonst noch irgendwo Logs einschalten oder wo sollte ich etwas einbauen? Ich sehe auch nicht, wovon das "disappeared" abgeleitet sein könnte

Edit:
habe jetzt gerade dies hier gefunden ... kann es sein, das die "Adresse" des Players geändert wurde und der Sonos-Hauptprozess das nicht gemerkt hat ?

2343 2017.01.13 16:05:37.752 3: SONOS1: ZoneGroupTopology-Subscription for ZonePlayer "RINCON_000E58E3988A01400_MR" has expired and is now renewed.
2344 2017.01.13 16:05:37.768 3: SONOS1: DeviceProperties-Subscription for ZonePlayer "RINCON_000E58E3988A01400_MR" has expired and is now renewed.
2345 2017.01.13 16:05:37.783 3: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2346 2017.01.13 16:05:37.799 3: SONOS1: Rendering-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2347 2017.01.13 16:05:37.815 3: SONOS1: GroupRendering-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2348 2017.01.13 16:05:37.830 3: SONOS1: ContentDirectory-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2349 2017.01.13 16:05:37.867 3: SONOS1: Alarm-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2350 2017.01.13 16:05:37.896 3: SONOS1: ZoneGroupTopology-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.
2351 2017.01.13 16:05:37.925 3: SONOS1: DeviceProperties-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" has expired and is now renewed.

[Reinerlein]

Hallo Nobby,

normalerweise läuft das bei UPnP-Komponenten so ab, dass bei einer solchen Änderung eine neue Discover-Antwort vom Player gesendet wird, damit der Controller die neue Adresse kennt. Seitens des Moduls sollte das auch gehen.
Aber Sonos hat genau damit wohl ein Problem, und deshalb sollte man versuchen diese Landschaft so stabil wie möglich zu machen.

Die Empfangsqualität der Player untereinander kann man sich in einer Matrix anzeigen lassen:
x.x.x.x:1400/support/review
Dort dann unter "Network Matrix".

Der IsAlive-Prozess versucht genau die Player zu finden, die nicht mehr unter ihrer Adresse erreichbar sind. Allerdings nur mit einem Ping-Test (bzw. was man eingestellt hat). Das kann auch mal falsche Ergebnisse liefern...

Diese ganzen Prüfungen, ermöglichen natürlich immer noch zeitliche Schlupflöcher
Deswegen ein stabiles System bevorzugen

Vielleicht kannst du daran ja schon etwas erkennen...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

Danke für den Tipp ... aber das ist Interessant ... die Probleme habe ich ja z.Zt. mit dem Sonos_Wohnzimmer, laut Log RINCON_000E58A376D201400

In den Meldungen von 16:05 tauchen RINCON_000E58E3988A01400 und RINCON_000E58C1DE0A01400 auf

Die Abfrage bringt

Wohnzimmer (RINCON_000E58A376D201400)
Schlafzimmer (RINCON_000E58C1DE0A01400)
BRIDGE (RINCON_000E58E3988A01400)

also hat sich Adresse für das Wohnzimmer doch nicht geändert und ich verstehe die expires für das Schalfzimmer und die Bridge nicht

Kannst du die Network Matrix interpretieren?

[Nobby1805]

Bei incoming subscriptions sehe ich einen Unterschied ... der Player Wohnzimmer zeigt keine Verbindung zum Fhem an 

subscriptions for: AudioInput current: 0 max: 32
subscriptions for: ZoneGroupTopology current: 0 max: 32
subscriptions for: DeviceProperties current: 2 max: 32
   13   0   uuid:RINCON_000E58A376D201400_sub0000001015   http://192.168.1.50:1400/notify
   43   0   uuid:RINCON_000E58A376D201400_sub0000000010   http://192.168.1.53:1400/notify
subscriptions for: SystemProperties current: 0 max: 32
subscriptions for: ConnectionManagerServer current: 0 max: 32
subscriptions for: ContentDirectory current: 2 max: 32
   1   0   uuid:RINCON_000E58A376D201400_sub0000001051   http://192.168.1.60:3400/notify
   7   0   uuid:RINCON_000E58A376D201400_sub0000001022   http://192.168.1.59:3400/notify
subscriptions for: ConnectionManagerRenderer current: 0 max: 32
subscriptions for: RenderingControl current: 2 max: 32
   1   0   uuid:RINCON_000E58A376D201400_sub0000001050   http://192.168.1.60:3400/notify
   1   0   uuid:RINCON_000E58A376D201400_sub0000001021   http://192.168.1.59:3400/notify
subscriptions for: AVTransport current: 2 max: 32
   1   0   uuid:RINCON_000E58A376D201400_sub0000001049   http://192.168.1.60:3400/notify
   42   0   uuid:RINCON_000E58A376D201400_sub0000001020   http://192.168.1.59:3400/notify
subscriptions for: GroupRenderingControl current: 0 max: 32
subscriptions for: Queue current: 1 max: 32
   1   0   uuid:RINCON_000E58A376D201400_sub0000001048   http://192.168.1.60:3400/notify
subscriptions for: GroupManager current: 2 max: 32
   1   0   uuid:RINCON_000E58A376D201400_sub0000001016   http://192.168.1.50:1400/notify
   1   0   uuid:RINCON_000E58A376D201400_sub0000000011   http://192.168.1.53:1400/notify
subscriptions for: AlarmClock current: 0 max: 32
subscriptions for: MusicServices current: 0 max: 32

dagegen Schlafzimmer

subscriptions for: AudioInput current: 0 max: 32
subscriptions for: ZoneGroupTopology current: 3 max: 32
   15   0   uuid:RINCON_000E58C1DE0A01400_sub0000000967   http://192.168.1.59:3400/notify
   2   0   uuid:RINCON_000E58C1DE0A01400_sub0000001001   http://192.168.1.60:3400/notify
   34   0   uuid:RINCON_000E58C1DE0A01400_sub0000000894   http://192.168.1.41:1730/fhemmodule
subscriptions for: DeviceProperties current: 3 max: 32
   88   0   uuid:RINCON_000E58C1DE0A01400_sub0000000054   http://192.168.1.61:1400/notify
   96   0   uuid:RINCON_000E58C1DE0A01400_sub0000000002   http://192.168.1.53:1400/notify
   21   0   uuid:RINCON_000E58C1DE0A01400_sub0000000895   http://192.168.1.41:1730/fhemmodule
subscriptions for: SystemProperties current: 2 max: 32
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000998   http://192.168.1.60:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000964   http://192.168.1.59:3400/notify
subscriptions for: ConnectionManagerServer current: 0 max: 32
subscriptions for: ContentDirectory current: 3 max: 32
   3   0   uuid:RINCON_000E58C1DE0A01400_sub0000000969   http://192.168.1.59:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000001002   http://192.168.1.60:3400/notify
   9   0   uuid:RINCON_000E58C1DE0A01400_sub0000000892   http://192.168.1.41:1730/fhemmodule
subscriptions for: ConnectionManagerRenderer current: 0 max: 32
subscriptions for: RenderingControl current: 3 max: 32
   3   0   uuid:RINCON_000E58C1DE0A01400_sub0000000963   http://192.168.1.59:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000997   http://192.168.1.60:3400/notify
   7   0   uuid:RINCON_000E58C1DE0A01400_sub0000000890   http://192.168.1.41:1730/fhemmodule
subscriptions for: AVTransport current: 3 max: 32
   22   0   uuid:RINCON_000E58C1DE0A01400_sub0000000962   http://192.168.1.59:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000996   http://192.168.1.60:3400/notify
   57   0   uuid:RINCON_000E58C1DE0A01400_sub0000000889   http://192.168.1.41:1730/fhemmodule
subscriptions for: GroupRenderingControl current: 1 max: 32
   7   0   uuid:RINCON_000E58C1DE0A01400_sub0000000891   http://192.168.1.41:1730/fhemmodule
subscriptions for: Queue current: 1 max: 32
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000995   http://192.168.1.59:3400/notify
subscriptions for: GroupManager current: 2 max: 32
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000053   http://192.168.1.61:1400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000003   http://192.168.1.53:1400/notify
subscriptions for: AlarmClock current: 3 max: 32
   3   0   uuid:RINCON_000E58C1DE0A01400_sub0000000966   http://192.168.1.59:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000001000   http://192.168.1.60:3400/notify
   5   0   uuid:RINCON_000E58C1DE0A01400_sub0000000893   http://192.168.1.41:1730/fhemmodule
subscriptions for: MusicServices current: 2 max: 32
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000999   http://192.168.1.60:3400/notify
   1   0   uuid:RINCON_000E58C1DE0A01400_sub0000000965   http://192.168.1.59:3400/notify

[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

[Nobby1805]

Hallo Reiner,

danke für die Erläuterungen ... und dass du die Frage gestellt hast, die ich auch hatte: warum wird nach einer Störung nicht versucht, die Verbindung wieder zu erstellen?

Ich warte geduldig auf deine Umbauten 

Gruß Nobby

[Nobby1805]

Hallo Reiner,

es ist gerade wieder genau an der gleichen Stelle passiert ... ich werde da morgen mal einbauen, dass nach ein paar Sekunden Wartezeit es einfach noch einmal probiert wird

Gruß Nobby

[Reinerlein]

Hi Nobby,

das ist vielleicht zum Testen eine Lösung, allerdings wird dann der SubProzess solange  blockiert, und kann keinerlei Mitteilungen der Player empfangen, oder Befehle von Fhem senden...

Ich baue da gerade ein, dass zunächst mal der Zustand der Player auf der Oberfläche korrekt ist (disappeared), und dann der Erkennungsvorgang neu angestossen wird (rescanNetwork).
Du könntest mal bei jeder der Renew-Fehlerprüfungen folgendes ersetzen/einbauen:

Code Auswählen Erweitern


if ($@ =~ m/Can.t connect to/) {
SONOS_DeleteProxyObjects($udn);

# Player-Informationen aktualisieren...
SONOS_Client_Data_Refresh('ReadingsSingleUpdateIfChanged', $udn, 'presence', 'disappeared');
SONOS_Client_Data_Refresh('ReadingsSingleUpdateIfChanged', $udn, 'state', 'disappeared');

# Discovery neu anstarten, falls der Player irgendwie doch noch erreichbar sein sollte...
$SONOS_Search = $SONOS_Controlpoint->searchByType('urn:schemas-upnp-org:device:ZonePlayer:1', \&SONOS_Discover_Callback);
}


Falls er sofort wieder erreichbar sein sollte, dann ist der Zustand des disappeared nicht lange auf der Oberfläche, ansonsten wird spätestens bei der nächsten Aktualisierungsmeldung durch den Player (der hat seine Subscription noch einen Moment) der Player neu erkannt (dazu ist der Zustand disappeared notwendig)...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

ist mir schon klar ... aber ich will erst mal (nur) sehen, ob meine Vermutung stimmt das der Connect schon beim nächsten Versuch nach wenigen Sekunden klappt ... ich habe da einen Verdacht (der außerhalb von FHEM liegt) und der wird dann ggf. bestätigt

Gruß Nobby

Edit 7.2.: Es ist wieder passiert ... und nach 2 Sekunden Wartezeit hat der erneute Versuch dann funktioniert. Mein Verdacht, dass der Auslöser eine andere Anwendung auf dem Server ist hast sich allerdings (bisher) nicht betätigt.

Gruß Nobby

[Nobby1805]

Es ist wieder passiert ...und mein Workaround hat wieder funktioniert.

Interessanterweise war der Connect nach dem 2 Sekunden warten nicht sofort erfolgreich sondern hat 9 Sekunden gedauert ... irgendetwas, m.M.n. außerhalb von FHEM, stört da den Verbindungsversuch.

Gruß Nobby

[Xguide]

Hallo zusammen,

ich lese hier schon eine Weile, da mich ähnliche Sorgen geplagt haben. Ich betreibe fhem auf einem Raspberry Pi 3 unter Jessie. Nachdem ich Ende letzten Jahres zur bestehenden Play1, die über lange Zeit problemlos funktionierte und immer von fhem ansprechbar war, zwei weitere Play1 für einen weiteren Raum hinzugenommen habe fingen meine Probleme an. Die 3 Play1 sind alle über WiFi verbunden.
Nach einem fhem Neustart funktionierte die ganze Landschaft wieder, allerdings nur für wenige Stunden. Mein fhem ist immer sehr aktuell gehalten (max 1 Woche alt).

Mein letzter Versuch das System wieder zuverlässig ans Laufen zu bringen war:
1. update & upgrade aller Pakete auf dem Pi
2. die Sonos Landschaft komplett aus fhem entfernt und neu definiert

Seit 2 Tagen läuft es nun ohne Abbrüche, ich hoffe das bleibt auch so.
Zu 1. kann ich leider nicht genau sagen ob irgendwelche Abhängigkeiten aktualisiert wurden.

Vielleicht hilft es ja auch dem ein oder anderen.

Viel Erfolg,

Marcel

[Reinerlein]

Hallo Nobby,

ich fürchte, da wird man nur etwas mittels detaillierter Paketuntersuchung feststellen können, und das ist doch sehr aufwändig.
Ich denke, wir sollten hier den pragmatischen Weg weiterverfolgen

Ich überlege mir mal was, ob ich z.B. bei einer IsAlive-Prüfung nicht ab und zu eine Broadcast-Message einbringen kann, die die Player dazu bewegt, sich wieder zu melden.
Das löst natürlich nicht dein ursächliches Problem des verschwindenden Players, aber das Problem ist dann wenigstens selbst-korrigierend, da der Player wieder auftauchen wird, wenn das Netzproblem weg ist...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

pragmatisch ist immer gut ...

Ich habe jetzt noch andere Fehlermeldungen gefunden ... als diese vor ein paar Tagen erstmals auftraten (bzw. sie mir aufgefallen sind) dachte ich noch, sie hätten etwas mit meinen dauernden Restarts für den Einbau neuen Loggings zu tun... aber jetzt sind sie diese Nacht, als alles schlief, wieder gekommen ... irgendwelche Auswirkungen habe ich bisher nicht feststellen können

Code Auswählen Erweitern

265 2017.02.09 01:17:11.613 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.


Code Auswählen Erweitern

480 2017.02.09 03:08:10.238 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.


Code Auswählen Erweitern

787 2017.02.09 06:20:56.357 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.

Ich habe mal ein bisschen im Code gesucht und vermute das kommt von hier

Code Auswählen Erweitern

SONOS_LoadBookmarkValues();

my $error;
do {
$SONOS_RestartControlPoint = 0;

eval {
$SONOS_Controlpoint = UPnP::ControlPoint->new(SearchPort => 0, SubscriptionPort => 0, SubscriptionURL => '/fhemmodule', MaxWait => 30, UsedOnlyIP => \%usedonlyIPs, IgnoreIP => \%ignoredIPs);
$SONOS_Search = $SONOS_Controlpoint->searchByType('urn:schemas-upnp-org:device:ZonePlayer:1', \&SONOS_Discover_Callback);
$SONOS_Controlpoint->handle;
};
$error = $@;

# Nur wenn es der Fehler mit der XML-Struktur ist, dann den UPnP-Handler nochmal anstarten... 
if (($error =~ m/multiple roots, wrong element '.*?'/si) || ($error =~ m/junk '.*?' after XML element/si) || ($error =~ m/mismatched tag '.*?'/si) || ($error =~ m/no element found/si) || ($error =~ m/500 Can't connect to/si) || ($error =~ m/not properly closed tag '.*?'/si) || ($error =~ m/Bad arg length for Socket::unpack_sockaddr_in/si)) {
SONOS_Log undef, 2, "Error during UPnP-Handling, restarting handling: $error";
SONOS_StopControlPoint();
} else {
SONOS_Log undef, 2, "Error during UPnP-Handling: $error";
SONOS_StopControlPoint();

undef($error);
}
} while ($error || $SONOS_RestartControlPoint);

Fehler in der XML-Struktur??? Was passiert da zu nachtschlafender Zeit? Was ist der Auslöser? Siehst du einen Zusammenhang mit dem anderen Problem?

Gruß Nobby

[Reinerlein]

Hi Nobby,

das klingt komisch. Da scheint eine SSDP-Antwort (also eine Antwort, dass ein Player sich ab-/anmeldet) nicht vollständig korrekt anzukommen.
Das eigentliche Problem tritt ja in der ControlPoint-UPnP-Library auf, weil dort versucht wird, die IP-Adresse des Absenders herauszufinden. Mir ist nicht ganz klar, wieso das mal fehlschlagen kann...
Ich kann das aber mal anders behandeln, um nicht solche Wellen bei diesem Fehler zu erhalten, bin mir aber nicht sicher, ob das eine so gute Idee ist... Ich denke mal dran rum...

Grüße
Reiner

[Nobby1805]

Dann poste ich hier mal das Umfeld der Fehlermeldungen ... ist nicht ganz identisch

Code Auswählen Erweitern

     265 2017.02.09 01:17:11.613 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.
     266 2017.02.09 01:17:12.363 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
     267 2017.02.09 01:17:14.223 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
     268 2017.02.09 01:17:14.225 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
     269 2017.02.09 01:17:14.244 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001609
     270 2017.02.09 01:17:14.351 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001610
     271 2017.02.09 01:17:14.352 3: SONOS1: Discover: End of discover-event for "BRIDGE".
     272 2017.02.09 01:17:14.457 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
     273 2017.02.09 01:17:15.410 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
     274 2017.02.09 01:17:15.611 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
     275 2017.02.09 01:17:15.634 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000614
     276 2017.02.09 01:17:15.647 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000615
     277 2017.02.09 01:17:15.664 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000616
     278 2017.02.09 01:17:15.676 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000617
     279 2017.02.09 01:17:15.689 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000618
     280 2017.02.09 01:17:15.703 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000619
     281 2017.02.09 01:17:15.715 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000620
     282 2017.02.09 01:17:15.729 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000621
     283 2017.02.09 01:17:15.729 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
     284 2017.02.09 01:17:15.803 2: SONOS1: Discover Sonosplayer 'Schlafzimmer' (S1) Software Revision 7.1 with ID 'RINCON_000E58C1DE0A01400_MR'
     285 2017.02.09 01:17:16.817 2: SONOS1: SonosPlayer 'Schlafzimmer' (S1) with ID 'RINCON_000E58C1DE0A01400_MR' is already defined (as 'Sonos_Schlafzimmer') and will only be updated
     286 2017.02.09 01:17:16.978 2: SONOS1: SonosPlayer 'Schlafzimmer' is now updated
     287 2017.02.09 01:17:17.001 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000775
     288 2017.02.09 01:17:17.017 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000776
     289 2017.02.09 01:17:17.029 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000777
     290 2017.02.09 01:17:17.042 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000778
     291 2017.02.09 01:17:17.056 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000779
     292 2017.02.09 01:17:17.084 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000780
     293 2017.02.09 01:17:17.099 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000781
     294 2017.02.09 01:17:17.099 3: SONOS1: Discover: End of discover-event for "Schlafzimmer".
     295 2017.02.09 01:17:17.104 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     296 2017.02.09 01:17:17.111 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     297 2017.02.09 01:17:17.116 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
     298 2017.02.09 01:17:17.248 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
     299 2017.02.09 01:17:17.253 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Schlafzimmer".
     300 2017.02.09 01:17:17.461 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
     301 2017.02.09 01:17:17.470 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_BRIDGE".
     302 2017.02.09 01:17:17.473 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_BRIDGE".
     303 2017.02.09 01:17:17.479 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     304 2017.02.09 01:17:17.479 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     305 2017.02.09 01:17:17.488 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     306 2017.02.09 01:17:17.490 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     307 2017.02.09 01:17:17.504 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Wohnzimmer".
     308 2017.02.09 01:17:17.505 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Wohnzimmer".
     309 2017.02.09 01:17:17.513 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Schlafzimmer".
     310 2017.02.09 01:17:17.514 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Schlafzimmer".
     311 2017.02.09 01:17:17.523 3: SONOS1: Event: Received AudioIn-Event for Zone "Sonos_Wohnzimmer".
     312 2017.02.09 01:17:17.524 3: SONOS1: Event: End of AudioIn-Event for Zone "Sonos_Wohnzimmer".
     313 2017.02.09 01:17:17.534 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     314 2017.02.09 01:17:17.541 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     315 2017.02.09 01:17:17.548 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     316 2017.02.09 01:17:17.557 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     317 2017.02.09 01:17:17.570 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     318 2017.02.09 01:17:17.572 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     319 2017.02.09 01:17:17.585 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     320 2017.02.09 01:17:17.587 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     321 2017.02.09 01:17:17.597 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     322 2017.02.09 01:17:17.599 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     323 2017.02.09 01:17:17.608 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     324 2017.02.09 01:17:17.609 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     325 2017.02.09 01:17:17.618 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Schlafzimmer".
     326 2017.02.09 01:17:17.632 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Schlafzimmer".
     327 2017.02.09 01:17:17.639 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Wohnzimmer".
     328 2017.02.09 01:17:17.653 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Wohnzimmer".


Code Auswählen Erweitern

     480 2017.02.09 03:08:10.238 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.
     481 2017.02.09 03:08:13.645 2: SONOS1: Discover Sonosplayer 'Schlafzimmer' (S1) Software Revision 7.1 with ID 'RINCON_000E58C1DE0A01400_MR'
     482 2017.02.09 03:08:16.613 2: SONOS1: SonosPlayer 'Schlafzimmer' (S1) with ID 'RINCON_000E58C1DE0A01400_MR' is already defined (as 'Sonos_Schlafzimmer') and will only be updated
     483 2017.02.09 03:08:17.160 2: SONOS1: SonosPlayer 'Schlafzimmer' is now updated
     484 2017.02.09 03:08:17.192 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000796
     485 2017.02.09 03:08:17.255 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000797
     486 2017.02.09 03:08:17.283 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000798
     487 2017.02.09 03:08:17.318 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000799
     488 2017.02.09 03:08:17.353 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000800
     489 2017.02.09 03:08:17.373 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000801
     490 2017.02.09 03:08:17.388 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000802
     491 2017.02.09 03:08:17.389 3: SONOS1: Discover: End of discover-event for "Schlafzimmer".
     492 2017.02.09 03:08:17.442 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
     493 2017.02.09 03:08:17.723 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
     494 2017.02.09 03:08:17.734 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
     495 2017.02.09 03:08:17.750 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001611
     496 2017.02.09 03:08:17.766 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001612
     497 2017.02.09 03:08:17.766 3: SONOS1: Discover: End of discover-event for "BRIDGE".
     498 2017.02.09 03:08:17.793 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Schlafzimmer".
     499 2017.02.09 03:08:18.140 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
     500 2017.02.09 03:08:18.223 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
     501 2017.02.09 03:08:19.317 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
     502 2017.02.09 03:08:19.539 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
     503 2017.02.09 03:08:19.561 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000638
     504 2017.02.09 03:08:19.575 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000639
     505 2017.02.09 03:08:19.588 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000640
     506 2017.02.09 03:08:19.600 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000641
     507 2017.02.09 03:08:19.616 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000642
     508 2017.02.09 03:08:19.630 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000643
     509 2017.02.09 03:08:19.643 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000644
     510 2017.02.09 03:08:19.656 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000645
     511 2017.02.09 03:08:19.656 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
     512 2017.02.09 03:08:19.669 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     513 2017.02.09 03:08:19.696 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     514 2017.02.09 03:08:19.713 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     515 2017.02.09 03:08:19.726 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     516 2017.02.09 03:08:19.742 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
     517 2017.02.09 03:08:19.886 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
     518 2017.02.09 03:08:19.900 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_BRIDGE".
     519 2017.02.09 03:08:19.910 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_BRIDGE".
     520 2017.02.09 03:08:19.943 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Schlafzimmer".
     521 2017.02.09 03:08:19.944 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Schlafzimmer".
     522 2017.02.09 03:08:19.950 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     523 2017.02.09 03:08:19.950 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     524 2017.02.09 03:08:19.957 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     525 2017.02.09 03:08:19.969 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     526 2017.02.09 03:08:19.975 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Wohnzimmer".
     527 2017.02.09 03:08:19.976 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Wohnzimmer".
     528 2017.02.09 03:08:19.989 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     529 2017.02.09 03:08:20.002 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     530 2017.02.09 03:08:20.010 3: SONOS1: Event: Received AudioIn-Event for Zone "Sonos_Wohnzimmer".
     531 2017.02.09 03:08:20.011 3: SONOS1: Event: End of AudioIn-Event for Zone "Sonos_Wohnzimmer".
     532 2017.02.09 03:08:20.019 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     533 2017.02.09 03:08:20.023 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     534 2017.02.09 03:08:20.053 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Schlafzimmer".
     535 2017.02.09 03:08:20.122 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Schlafzimmer".
     536 2017.02.09 03:08:22.442 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     537 2017.02.09 03:08:22.469 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     538 2017.02.09 03:08:22.489 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     539 2017.02.09 03:08:22.492 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     540 2017.02.09 03:08:22.506 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     541 2017.02.09 03:08:22.507 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     542 2017.02.09 03:08:22.522 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Wohnzimmer".
     543 2017.02.09 03:08:22.532 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Wohnzimmer".


Code Auswählen Erweitern

    787 2017.02.09 06:20:56.357 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.

     788 2017.02.09 06:20:57.935 2: SONOS1: Discover Sonosplayer 'Schlafzimmer' (S1) Software Revision 7.1 with ID 'RINCON_000E58C1DE0A01400_MR'
     789 2017.02.09 06:20:59.467 2: SONOS1: SonosPlayer 'Schlafzimmer' (S1) with ID 'RINCON_000E58C1DE0A01400_MR' is already defined (as 'Sonos_Schlafzimmer') and will only be updated
     790 2017.02.09 06:20:59.732 2: SONOS1: SonosPlayer 'Schlafzimmer' is now updated
     791 2017.02.09 06:20:59.759 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000817
     792 2017.02.09 06:20:59.787 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000818
     793 2017.02.09 06:20:59.805 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000819
     794 2017.02.09 06:20:59.820 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000820
     795 2017.02.09 06:20:59.834 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000821
     796 2017.02.09 06:20:59.850 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000822
     797 2017.02.09 06:20:59.868 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58C1DE0A01400_sub0000000823
     798 2017.02.09 06:20:59.868 3: SONOS1: Discover: End of discover-event for "Schlafzimmer".
     799 2017.02.09 06:21:00.013 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
     800 2017.02.09 06:21:02.013 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
     801 2017.02.09 06:21:02.592 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
     802 2017.02.09 06:21:02.687 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000662
     803 2017.02.09 06:21:02.737 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000663
     804 2017.02.09 06:21:02.755 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000664
     805 2017.02.09 06:21:02.785 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000665
     806 2017.02.09 06:21:02.816 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000666
     807 2017.02.09 06:21:02.839 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000667
     808 2017.02.09 06:21:02.871 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000668
     809 2017.02.09 06:21:02.892 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000000669
     810 2017.02.09 06:21:02.892 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
     811 2017.02.09 06:21:02.900 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Schlafzimmer".
     812 2017.02.09 06:21:03.240 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
     813 2017.02.09 06:21:03.310 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
     814 2017.02.09 06:21:03.601 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
     815 2017.02.09 06:21:03.605 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
     816 2017.02.09 06:21:03.635 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001613
     817 2017.02.09 06:21:03.653 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001614
     818 2017.02.09 06:21:03.654 3: SONOS1: Discover: End of discover-event for "BRIDGE".
     819 2017.02.09 06:21:03.662 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
     820 2017.02.09 06:21:03.895 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
     821 2017.02.09 06:21:03.905 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     822 2017.02.09 06:21:03.906 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Schlafzimmer".
     823 2017.02.09 06:21:03.919 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     824 2017.02.09 06:21:03.929 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
     825 2017.02.09 06:21:03.940 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     826 2017.02.09 06:21:03.941 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Wohnzimmer".
     827 2017.02.09 06:21:03.954 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Schlafzimmer".
     828 2017.02.09 06:21:03.955 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Schlafzimmer".
     829 2017.02.09 06:21:03.968 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Wohnzimmer".
     830 2017.02.09 06:21:03.969 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Wohnzimmer".
     831 2017.02.09 06:21:03.984 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_BRIDGE".
     832 2017.02.09 06:21:03.986 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_BRIDGE".
     833 2017.02.09 06:21:03.999 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     834 2017.02.09 06:21:04.009 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Schlafzimmer".
     835 2017.02.09 06:21:04.025 3: SONOS1: Event: Received AudioIn-Event for Zone "Sonos_Wohnzimmer".
     836 2017.02.09 06:21:04.026 3: SONOS1: Event: End of AudioIn-Event for Zone "Sonos_Wohnzimmer".
     837 2017.02.09 06:21:04.043 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     838 2017.02.09 06:21:04.045 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Schlafzimmer".
     839 2017.02.09 06:21:04.056 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     840 2017.02.09 06:21:04.067 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
     841 2017.02.09 06:21:04.080 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     842 2017.02.09 06:21:04.082 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Schlafzimmer".
     843 2017.02.09 06:21:04.101 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     844 2017.02.09 06:21:04.103 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
     845 2017.02.09 06:21:04.112 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Schlafzimmer".
     846 2017.02.09 06:21:04.127 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Schlafzimmer".
     847 2017.02.09 06:21:04.138 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     848 2017.02.09 06:21:04.140 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
     849 2017.02.09 06:21:04.165 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Wohnzimmer".
     850 2017.02.09 06:21:04.206 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Wohnzimmer".


Falls du mehr Logging aus dem Umfeld dieser Meldungen möchtest ... oder ich irgendwo noch etwas einbauen soll dann melde dich

Gruß Nobby

[Nobby1805]

Hallo Reiner,

heute ist wieder der Loop (siehe #7) aufgetreten ... der Logfile ist diesmal 890 MByte groß

Ich hatte ja in den Loop weitere Logs eingebaut weil es nicht ersichtlich war, warum überhaupt ohne Pause geloopt wird

So sieht es normalerweise alle 30 Sekunden aus

Code Auswählen Erweitern

  739692 2017.02.12 13:00:24.497 3: SONOS0: vor foreach-loop
  739693 2017.02.12 13:00:24.515 3: SONOS0: nach can_read GLOB(0x198019c)
  739694 2017.02.12 13:00:24.515 3: SONOS0: vor foreach-loop
  739695 2017.02.12 13:00:24.515 3: SONOS0: foreach-loop GLOB(0x198019c) GLOB(0x198019c)
  739696 2017.02.12 13:00:24.516 3: SONOS0: Connection accepted from HomeServer:2540
  739697 2017.02.12 13:00:24.517 3: SONOS0: nach can_read GLOB(0x1c5395c)
  739698 2017.02.12 13:00:24.517 3: SONOS0: vor foreach-loop
  739699 2017.02.12 13:00:24.517 3: SONOS0: foreach-loop GLOB(0x1c5395c) GLOB(0x198019c)
  739700 2017.02.12 13:00:24.517 1: SONOS0: Received: 'hello'
  739701 2017.02.12 13:00:24.517 3: SONOS0: nach can_read GLOB(0x1c5395c)
  739702 2017.02.12 13:00:24.518 3: SONOS0: vor foreach-loop
  739703 2017.02.12 13:00:24.518 3: SONOS0: foreach-loop GLOB(0x1c5395c) GLOB(0x198019c)
  739704 2017.02.12 13:00:24.518 1: SONOS0: Received: 'goaway'
  739705 2017.02.12 13:00:25.512 3: SONOS0: nach can_read
  739706 2017.02.12 13:00:25.512 3: SONOS0: vor foreach-loop
aber um 13:02 beginnt dann der Loop

Code Auswählen Erweitern

  739832 2017.02.12 13:01:22.528 3: SONOS0: vor foreach-loop
  739833 2017.02.12 13:01:23.528 3: SONOS0: nach can_read
  739834 2017.02.12 13:01:23.528 3: SONOS0: vor foreach-loop
    5411 2017.02.12 13:01:24.200 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
  739835 2017.02.12 13:01:24.528 3: SONOS0: nach can_read
  739836 2017.02.12 13:01:24.528 3: SONOS0: vor foreach-loop
  739837 2017.02.12 13:01:24.551 3: SONOS0: nach can_read GLOB(0x198019c)
  739838 2017.02.12 13:01:24.552 3: SONOS0: vor foreach-loop
  739839 2017.02.12 13:01:24.553 3: SONOS0: foreach-loop GLOB(0x198019c) GLOB(0x198019c)
  739840 2017.02.12 13:01:24.554 3: SONOS0: Connection accepted from HomeServer:2591
  739841 2017.02.12 13:01:24.555 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739842 2017.02.12 13:01:24.555 3: SONOS0: vor foreach-loop
  739843 2017.02.12 13:01:24.555 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739844 2017.02.12 13:01:24.556 1: SONOS0: Received: 'hello'
    5412 2017.02.12 13:01:24.545 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
  739845 2017.02.12 13:01:24.558 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739846 2017.02.12 13:01:24.569 3: SONOS0: vor foreach-loop
  739847 2017.02.12 13:01:24.569 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739848 2017.02.12 13:01:24.569 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739849 2017.02.12 13:01:24.569 3: SONOS0: vor foreach-loop
  739850 2017.02.12 13:01:24.569 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739851 2017.02.12 13:01:24.570 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739852 2017.02.12 13:01:24.570 3: SONOS0: vor foreach-loop
  739853 2017.02.12 13:01:24.570 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739854 2017.02.12 13:01:24.570 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739855 2017.02.12 13:01:24.570 3: SONOS0: vor foreach-loop
  739856 2017.02.12 13:01:24.571 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739857 2017.02.12 13:01:24.571 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739858 2017.02.12 13:01:24.571 3: SONOS0: vor foreach-loop
  739859 2017.02.12 13:01:24.571 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739860 2017.02.12 13:01:24.571 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739861 2017.02.12 13:01:24.572 3: SONOS0: vor foreach-loop
  739862 2017.02.12 13:01:24.572 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739863 2017.02.12 13:01:24.572 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739864 2017.02.12 13:01:24.572 3: SONOS0: vor foreach-loop
  739865 2017.02.12 13:01:24.572 3: SONOS0: foreach-loop GLOB(0x1c4abfc) GLOB(0x198019c)
  739866 2017.02.12 13:01:24.573 3: SONOS0: nach can_read GLOB(0x1c4abfc)
  739867 2017.02.12 13:01:24.573 3: SONOS0: vor foreach-loop

Wie man sieht ist hier etwas zeitgleich von Sonos gekommen ... danach wird mit can_read immer wieder dasselbe gelesen und daher wirkt die Verzögerung (bei mir 1 Sekunde) dort nicht

Kannst du dort etwas erkennen ?

Gruß Nobby

[Nobby1805]

Hallo Reiner,

ich verstehe nicht was da passiert

Code Auswählen Erweitern

foreach my $so (@ready) {
SONOS_Log undef, 3, "foreach-loop $so $sock";                                             ####Nobby
if ($so == $sock) { # New Connection read

laut log ist $so ungleich $sock, also geht es im else-Zweig weiter

Code Auswählen Erweitern

} else { # Existing client calling
my $inp = <$so>;

if (defined($inp)) {
# Abschließende Zeilenumbrüche abschnippeln
$inp =~ s/[\r\n]*$//;

# Consume and send evt. reply
SONOS_Log undef, 1, "Received: '$inp'";        ##### Nobby
SONOS_Log undef, 5, "Received: '$inp'";
SONOS_Client_ConsumeMessage($so, $inp);
}
}

und da das Received-logging nicht kommt, kann nur $inp undefined sein ... aber ist das nicht ein Widerspruch wenn can_read meint es sind Daten da aber beim lesen dieser Daten dann nichts kommt?

Gruß Nobby

[Reinerlein]

Hi Nobby,

genau das ist mein Problem... Ich bekomme ganz oft die Mitteilung, dass Daten zum Abholen bereit wären, und es kommen dann keine... Deswegen ständig diese Prüfungen darauf, ob etwas angekommen ist...
Normalerweise wird man nur einmal falsch getriggert, und muss somit nur diesen einen Trigger überstehen (da man den Socket ja auch ausliest), hier passiert es ständig wieder (in der Loop)...

Ich weiß echt nicht, was ich da machen soll...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

Ok ... ich lese mich in die Thematik mal ein bisschen tiefer ein

Kurzfristig baue ich erst mal noch ein paar weitere Logs ein ... mal schauen was dann beim nächsten mal angezeigt wird

Gruß Nobby

[Nobby1805]

Hallo Reiner,

ich habe mal etwas geforscht, kennst du dies?

https://techblog.ralph-schuster.eu/2015/06/19/nonblocking-sockets-and-perls-netdaemon/

http://www.perlmonks.org/bare/?node_id=427056

wenn ich in den Log schaue, dann wird das "Hello" gelesen und bearbeitet, aber das folgende "goaway" führt dann zu dem Problem
und jetzt spekuliere ich mal

Code Auswählen Erweitern

$socket->send("hello\n", 0);
$socket->recv($answer, 500);

$socket->send("goaway\n", 0);

$socket->shutdown(2);
$socket->close();

Das "goaway" wird gesendet, kann aber nicht gelesen werden weil der Transport-Event im anderen Thread bearbeitet wird  ... und dann wird der Sendesocket runtergefahren und geschlossen ... und dann will der Thread lesen, bekommt dann aber eine Fehler weil der socket disconnected ist.

Wenn das so ist, dann würde das helfen was in Ralphs-Blog beschrieben ist ... was meinst du? Oder man baut etwas warten zwischen send-goaway und shutdown ein

Gruß Nobby   

[Reinerlein]

Hi Nobby,

das klingt plausibel, und mir ist noch was anderes aufgefallen: ich hole erst die can_read()-Liste, und dann prüfe (und aktualisiere) ich die Subscriptions, und danach erst lese ich die gelieferten Sockets aus.. ist vielleicht auch nicht so schlau.

Versuch mal folgendes:
In dem else-Zweig für "Existing client calling", vor dem my $inp = <$so>;

Code Auswählen Erweitern


if (!$so->opened()) {
$SONOS_Client_Selector->remove($so);
next;
}

my $inp = <$so>;
Das ist der von dir gefundene Tipp.

Und die Zeile

Code Auswählen Erweitern


my @ready = $SONOS_Client_Selector->can_read(0.1);
nach unten verschieben, direkt vor die entsprechende for-Schleife:

Code Auswählen Erweitern


.
.
# Alle Bereit-Lesenden verarbeiten
# Das ganze blockiert eine kurze Zeit, um nicht 100% CPU-Last zu erzeugen
# Das bedeutet aber auch, dass Sende-Vorgänge um maximal den Timeout-Wert verzögert werden
my @ready = $SONOS_Client_Selector->can_read(0.1);
for (my $i = 0; $i < scalar(@ready); $i++) {
my $so = $ready[$i];
.
.


In meiner Testumgebung geht das

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

ja werde ich machen ... ich kenne aber noch einen alten Spruch aus meiner aktiven Phase, wo wir uns mit Treiber-Programmierung und ähnlichen Effekten herumgeschlagen haben ... "Man kann durch testen nur die Anwesenheit von Fehlern, aber nicht deren Abwesenheit feststellen ..."

In diesem Sinne werde ich jetzt erst mal ein paar Tage warten ob das Problem mit dem wieder erweiterten Logging noch einmal auftritt

Jetzt sieht es im Normalfall so aus

Code Auswählen Erweitern

    5048 2017.02.14 00:00:10.726 3: SONOS0: vor foreach-loop
    5049 2017.02.14 00:00:10.727 3: SONOS0: nach bits/Count 0028 0000  2
     108 2017.02.14 00:00:11.554 1: SONOS2: IsAlive-Thread
    5050 2017.02.14 00:00:11.586 3: SONOS0: nach can_read GLOB(0x197fbdc)
    5051 2017.02.14 00:00:11.586 3: SONOS0: vor foreach-loop
    5052 2017.02.14 00:00:11.586 3: SONOS0: foreach GLOB(0x197fbdc) GLOB(0x197fbdc)
    5053 2017.02.14 00:00:11.586 3: SONOS0: connected
    5054 2017.02.14 00:00:11.588 3: SONOS0: Connection accepted from HomeServer:1124
    5055 2017.02.14 00:00:11.588 3: SONOS0: nach bits/Count 0028 0020  3
    5056 2017.02.14 00:00:11.589 3: SONOS0: nach can_read GLOB(0x1c49e74)
    5057 2017.02.14 00:00:11.589 3: SONOS0: vor foreach-loop
    5058 2017.02.14 00:00:11.589 3: SONOS0: foreach GLOB(0x1c49e74) GLOB(0x197fbdc)
    5059 2017.02.14 00:00:11.589 3: SONOS0: connected
    5060 2017.02.14 00:00:11.590 3: SONOS0: inp = 'hello'
    5061 2017.02.14 00:00:11.590 1: SONOS0: Received: 'hello'
    5062 2017.02.14 00:00:11.590 3: SONOS0: nach bits/Count 0028 0020  3
    5063 2017.02.14 00:00:11.591 3: SONOS0: nach can_read GLOB(0x1c49e74)
    5064 2017.02.14 00:00:11.591 3: SONOS0: vor foreach-loop
    5065 2017.02.14 00:00:11.591 3: SONOS0: foreach GLOB(0x1c49e74) GLOB(0x197fbdc)
    5066 2017.02.14 00:00:11.591 3: SONOS0: connected
    5067 2017.02.14 00:00:11.592 3: SONOS0: inp = 'goaway'
    5068 2017.02.14 00:00:11.592 1: SONOS0: Received: 'goaway'
    5069 2017.02.14 00:00:11.592 3: SONOS0: nach bits/Count 0028 0000  2
    5070 2017.02.14 00:00:12.586 3: SONOS0: nach can_read
    5071 2017.02.14 00:00:12.586 3: SONOS0: vor foreach-loop


Gruß Nobby

PS ja ich weiß, durch (zu) viel Logging kann man bei Timingproblemen auch erreichen, dass diese gar nicht mehr auftreten

[Nobby1805]

Hallo Reiner,

heute ist dann das andere Problem wieder aufgetreten (Renew) ... und mein Workaround hat wieder funktioniert

Ich habe jetzt den Workaround wieder ausgebaut und deinen Vorschlag aus #32 eingebaut

Gruß Nobby

[Nobby1805]

Hallo Reiner,

also mein Workaround hat das Problem, zumindest so wie es bei mir auftritt, schneller und effektiver behoben ... mit deiner Änderung hat es mehrere Versuche gedauert bis es dann wieder lief

Code Auswählen Erweitern

    2178 2017.02.15 15:18:58.853 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 3515 thread 1.
    2179 2017.02.15 15:18:58.870 0: SONOS1: Delete ProxyObjects and SubscriptionObjects for 'RINCON_000E58C1DE0A01400_MR'
    2180 2017.02.15 15:18:58.904 1: SONOS1: Nach Error: Reiners Vorschlag 32
    2181 2017.02.15 15:18:58.911 0: SONOS1: nach peek renewSubscription
    2182 2017.02.15 15:18:58.911 3: SONOS1: AVTprox 1 RINCON_000E58A376D201400_MR
    2183 2017.02.15 15:18:58.911 3: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58A376D201400_MR" vor dem renew-Versuch

    2184 2017.02.15 15:19:18.915 3: SONOS1: Error! Transport-Subscription for ZonePlayer "RINCON_000E58A376D201400_MR" has expired and could not be renewed: Renewal of subscription failed with error: 500 Can't connect to 192.168.1.61:1400 at ./FHEM/00_SONOS.pm line 3515 thread 1.
    2185 2017.02.15 15:19:18.915 0: SONOS1: Delete ProxyObjects and SubscriptionObjects for 'RINCON_000E58A376D201400_MR'
    2186 2017.02.15 15:19:18.933 1: SONOS1: Nach Error: Reiners Vorschlag 32
    2187 2017.02.15 15:19:19.014 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
    2188 2017.02.15 15:19:19.356 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
    2189 2017.02.15 15:19:19.371 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
    2190 2017.02.15 15:19:19.445 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001670
    2191 2017.02.15 15:19:19.479 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001671
    2192 2017.02.15 15:19:19.479 3: SONOS1: Discover: End of discover-event for "BRIDGE".
    2193 2017.02.15 15:19:19.481 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
    2194 2017.02.15 15:19:19.548 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
    2195 2017.02.15 15:19:19.551 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
    2196 2017.02.15 15:19:19.586 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001672
    2197 2017.02.15 15:19:19.611 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001673
    2198 2017.02.15 15:19:19.611 3: SONOS1: Discover: End of discover-event for "BRIDGE".
    2199 2017.02.15 15:19:19.618 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2200 2017.02.15 15:19:19.626 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2201 2017.02.15 15:19:19.660 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_BRIDGE".
    2202 2017.02.15 15:19:19.662 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_BRIDGE".
    2203 2017.02.15 15:19:19.701 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2204 2017.02.15 15:19:19.713 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2205 2017.02.15 15:22:00.587 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
    2206 2017.02.15 15:22:00.837 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
    2207 2017.02.15 15:22:01.046 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
    2208 2017.02.15 15:22:01.074 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001784
    2209 2017.02.15 15:22:01.193 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001785
    2210 2017.02.15 15:22:01.217 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001786
    2211 2017.02.15 15:22:01.233 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001787
    2212 2017.02.15 15:22:01.266 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001788
    2213 2017.02.15 15:22:01.283 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001789
    2214 2017.02.15 15:22:01.299 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001790
    2215 2017.02.15 15:22:01.337 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001791
    2216 2017.02.15 15:22:01.337 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
    2217 2017.02.15 15:22:01.339 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
    2218 2017.02.15 15:22:01.541 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
    2219 2017.02.15 15:22:01.745 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
    2220 2017.02.15 15:22:01.761 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001792
    2221 2017.02.15 15:22:01.780 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001793
    2222 2017.02.15 15:22:01.797 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001794
    2223 2017.02.15 15:22:01.815 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001795
    2224 2017.02.15 15:22:01.837 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001796
    2225 2017.02.15 15:22:01.855 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001797
    2226 2017.02.15 15:22:01.878 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001798
    2227 2017.02.15 15:22:01.898 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001799
    2228 2017.02.15 15:22:01.898 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
    2229 2017.02.15 15:22:01.902 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
    2230 2017.02.15 15:22:02.057 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
    2231 2017.02.15 15:22:02.075 3: SONOS1: Event: Received GroupRendering-Event for Zone "Sonos_Wohnzimmer".
    2232 2017.02.15 15:22:02.076 3: SONOS1: Event: End of GroupRendering-Event for Zone "Sonos_Wohnzimmer".
    2233 2017.02.15 15:22:02.117 3: SONOS1: Event: Received Alarm-Event for Zone "Sonos_Wohnzimmer".
    2234 2017.02.15 15:22:02.118 3: SONOS1: Event: End of Alarm-Event for Zone "Sonos_Wohnzimmer".
    2235 2017.02.15 15:22:02.159 3: SONOS1: Event: Received AudioIn-Event for Zone "Sonos_Wohnzimmer".
    2236 2017.02.15 15:22:02.168 3: SONOS1: Event: End of AudioIn-Event for Zone "Sonos_Wohnzimmer".
    2237 2017.02.15 15:22:02.191 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
    2238 2017.02.15 15:22:02.198 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
    2239 2017.02.15 15:22:02.220 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
    2240 2017.02.15 15:22:02.221 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_Wohnzimmer".
    2241 2017.02.15 15:22:02.244 3: SONOS1: Event: Received ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
    2242 2017.02.15 15:22:02.261 3: SONOS1: Event: End of ContentDirectory-Event for Zone "Sonos_Wohnzimmer".
    2243 2017.02.15 15:22:02.275 3: SONOS1: Event: Received Rendering-Event for Zone "Sonos_Wohnzimmer".
    2244 2017.02.15 15:22:02.324 3: SONOS1: Event: End of Rendering-Event for Zone "Sonos_Wohnzimmer".
    2245 2017.02.15 15:22:02.353 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".
    2246 2017.02.15 15:22:02.521 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Wohnzimmer".
    2247 2017.02.15 15:25:45.415 2: SONOS1: Discover Sonosplayer 'Schlafzimmer' (S1) Software Revision 7.1 with ID 'RINCON_000E58C1DE0A01400_MR'

    2248 2017.02.15 15:26:06.509 2: SONOS1: Error during UPnP-Handling, restarting handling: 500 Can't connect to 192.168.1.50:1400 at FHEM/lib/UPnP/ControlPoint.pm line 847 thread 1.
    2249 2017.02.15 15:26:27.009 2: SONOS1: Discover Sonosplayer 'BRIDGE' (ZB100) Software Revision 7.1 with ID 'RINCON_000E58E3988A01400_MR'
    2250 2017.02.15 15:26:28.071 2: SONOS1: SonosPlayer 'BRIDGE' (ZB100) with ID 'RINCON_000E58E3988A01400_MR' is already defined (as 'Sonos_BRIDGE') and will only be updated
    2251 2017.02.15 15:26:28.074 2: SONOS1: SonosPlayer 'BRIDGE' is now updated
    2252 2017.02.15 15:26:28.122 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001674
    2253 2017.02.15 15:26:28.154 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58E3988A01400_sub0000001675
    2254 2017.02.15 15:26:28.154 3: SONOS1: Discover: End of discover-event for "BRIDGE".
    2255 2017.02.15 15:26:28.165 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2256 2017.02.15 15:26:28.187 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_BRIDGE".
    2257 2017.02.15 15:26:28.223 3: SONOS1: Event: Received DeviceProperties-Event for Zone "Sonos_BRIDGE".
    2258 2017.02.15 15:26:28.225 3: SONOS1: Event: End of DeviceProperties-Event for Zone "Sonos_BRIDGE".
    2259 2017.02.15 15:27:01.400 2: SONOS1: Discover Sonosplayer 'Wohnzimmer' (ZP90) Software Revision 7.1 with ID 'RINCON_000E58A376D201400_MR'
    2260 2017.02.15 15:27:02.712 2: SONOS1: SonosPlayer 'Wohnzimmer' (ZP90) with ID 'RINCON_000E58A376D201400_MR' is already defined (as 'Sonos_Wohnzimmer') and will only be updated
    2261 2017.02.15 15:27:02.882 2: SONOS1: SonosPlayer 'Wohnzimmer' is now updated
    2262 2017.02.15 15:27:02.919 2: SONOS1: Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001800
    2263 2017.02.15 15:27:02.942 2: SONOS1: Rendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001801
    2264 2017.02.15 15:27:02.965 2: SONOS1: GroupRendering-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001802
    2265 2017.02.15 15:27:02.983 2: SONOS1: ContentDirectory-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001803
    2266 2017.02.15 15:27:03.000 2: SONOS1: Alarm-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001804
    2267 2017.02.15 15:27:03.020 2: SONOS1: ZoneGroupTopology-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001805
    2268 2017.02.15 15:27:03.042 2: SONOS1: DeviceProperties-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001806
    2269 2017.02.15 15:27:03.059 2: SONOS1: AudioIn-Service-subscribing successful with SID=uuid:RINCON_000E58A376D201400_sub0000001807
    2270 2017.02.15 15:27:03.059 3: SONOS1: Discover: End of discover-event for "Wohnzimmer".
    2271 2017.02.15 15:27:03.064 3: SONOS1: Event: Received Transport-Event for Zone "Sonos_Wohnzimmer".


[Reinerlein]

Hi Nobby,

das mit der Zeit kann aber auch Zufall sein. Der Schlafzimmer-Player schien in diesem Fall echt lange nicht erreichbar gewesen zu sein. Das Modul hatte es ja mehrfach versucht...
Mein Code aus #32 sendet einen Broadcast aus, dass sich alle Zoneplayer melden sollen, also auch die noch bekannten...
Natürlich kann auch bedingt durch die Rückmeldereihenfolge eine Verzögerung auftreten, dafür ist das der eigentlich korrekte Weg Was mir notfalls aber gar nicht so wichtig wäre... Aber dieses Vorgehen sichert auch die anderen Player neu ab, falls das Netzwerk im allgemeinen ein Problem haben sollte bzw. gehabt hatte. Sozusagen ein bißchen deine Netz-Probleme generalisieren und allgemeingültig abfangen/korrigieren...

Wichtig ist, ob der Player sicher wieder neu erkannt wird... Dein Code hätte in diesem Fall eher Probleme gehabt, da der Player ja mindestens 8 Minuten nicht erreichbar war... Dann endet ja dein Log (ohne das der Schlafzimmer-Player abschließend gefunden wurde)...

Grüße
Reiner

[Nobby1805]

Ich kann jetzt nicht behaupten, dass mit meinem Workaround es auch in diesem Fall besser funktioniert hätte ... aber: 3 mal hat es bei meiner Methode problemlos funktioniert und 2x (auch heute gab es wieder das Problem) hat deine Änderung mehrere Versuche benötigt um die Verbindung wieder herzustellen

Der Renew hat übrigens bei Wohnzimmer nicht geklappt ... .61, Schlafzimmer ist .50 ... vermutlich stand deshalb auch nichts vom Schlafzimmer im Log

Das Problem von heute war dann übrigen mit Schlafzimmer

Mal schauen wie es weiter geht ... egal welche der beiden Lösungen bin ich ja schon froh, dass ich nicht mehr so häufig wenn ich die Musik im Wohnzimmer einschalten will und er reagiert nicht ins Arbeitszimmer laufen muss um FHEM neu zu starten 

Gruß Nobby

[Reinerlein]

Hi Nobby,

in deinem Log war es aber der Player mit der Rincon-ID "000E58C1DE0A01400", das schien mir nicht das Wohnzimmer zu sein...
Die Wiederverbindung hatte dann beim Wohnzimmer nicht geklappt, da dieser nicht ansprechbar war, und deshalb der Erkennungsprozess nochmal neugestartet wurde (mehrfach).

Das deutet ja auf ein prinzipielles Netzwerk-Problem hin, wenn schon zwei Player nicht vollständig erreichbar sind (Wohnzimmer meldet sich, kann aber dann nicht angesprochen werden, Schlafzimmer meldet sich noch nicht mal mehr). Deshalb ja auch der Code für das komplette neu Erkennen...

Wir beobachten das noch eine Weile, und wenn es sicher stabil läuft, würde ich gerne diesen Codestand langsam mal einchecken...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

sowohl als auch ....

ist dir aufgefallen, in Zeile 2178 ist es .50 RINCON_000E58C1DE0A01400 also das Schlafzimmer und dann 20 Sekunden danach in Zeile 2184 ist es .61 RINCON_000E58A376D201400 also das Wohnzimmer

Wie ich schon mal schrieb, ich verwende nicht das Standard WLAN sondern (althergebracht) das Sonos-WLAN und die Bridge und der Wohnzimmerplayer stehen ca. 2-3 Meter voneinander entfernt mit Sichtkontakt

Gruß Nobby

[Nobby1805]

Hallo Reiner,

sehr komisch ....

Ich hatte gestern noch einmal weitere Logs eingebaut und im Hintergrund einen Netzwerk-Monitor gestartet um zu schauen ob man an den Datenpaketen evt. etwas sehen kann

Heute Mittag ist dann der Fehler wieder aufgetreten

Code Auswählen Erweitern

    1794 2017.02.21 13:55:08.632 0: SONOS1: nach peek renewSubscription
    1795 2017.02.21 13:55:08.632 3: SONOS1: AVTprox 2 RINCON_000E58C1DE0A01400_MR RINCON_000E58A376D201400_MR
    1796 2017.02.21 13:55:08.632 3: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58C1DE0A01400_MR" vor dem renew-Versuch

    1797 2017.02.21 13:55:28.862 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 3515 thread 1.

um 13:55:08 wird also der renew versucht und nach 20 Sekunden um 13:55:28 kommt der Fehler

Interessant ist jetzt aber, was der Netzwerkmonitor dort mitgeschnitten hat ...

Code Auswählen Erweitern

00-0A-E4-8B-C3-D5 40 (0x28) 218205 18967.6010000 13:55:02 21.02.2017 HOMESERVER  192.168.1.61 TCP TCP:Flags=...A...F, SrcPort=2618, DstPort=1400, PayloadLen=0, Seq=3589160989, Ack=3183810991, Win=65050 (scale factor 0x0) = 65050 {TCP:21610, IPv4:19}
00-0E-58-A3-76-D2 40 (0x28) 218206 18967.6010000 13:55:02 21.02.2017 192.168.1.61 HOMESERVER  TCP TCP:Flags=...A...., SrcPort=1400, DstPort=2618, PayloadLen=0, Seq=3183810991, Ack=3589160990, Win=5840 (scale factor 0x0) = 5840 {TCP:21610, IPv4:19}
0x3300 00-0A-E4-8B-C3-D5 48 (0x30) 218207 18994.0228750 13:55:28 21.02.2017 perl.exe HOMESERVER  192.168.1.61 TCP TCP:Flags=......S., SrcPort=2638, DstPort=1400, PayloadLen=0, Seq=3837985867, Ack=0, Win=65535 (  ) = 65535 {TCP:21622, IPv4:19}
0x3300 00-0E-58-A3-76-D2 48 (0x30) 218208 18994.0541250 13:55:28 21.02.2017 perl.exe 192.168.1.61 HOMESERVER  TCP TCP:Flags=...A..S., SrcPort=1400, DstPort=2638, PayloadLen=0, Seq=3214966934, Ack=3837985868, Win=5840 ( Scale factor not supported ) = 5840 {TCP:21622, IPv4:19}
0x3300 00-0A-E4-8B-C3-D5 40 (0x28) 218209 18994.0541250 13:55:28 21.02.2017 perl.exe HOMESERVER  192.168.1.61 TCP TCP:Flags=...A...., SrcPort=2638, DstPort=1400, PayloadLen=0, Seq=3837985868, Ack=3214966935, Win=65535 (scale factor 0x0) = 65535 {TCP:21622, IPv4:19}
0x3300 00-0A-E4-8B-C3-D5 247 (0xF7) 218210 18994.3197500 13:55:28 21.02.2017 perl.exe HOMESERVER  192.168.1.61 WEBDAV WEBDAV:Request, SUBSCRIBE /MediaRenderer/AVTransport/Event {SIP:21624, TCP:21622, IPv4:19}

nämlich nichts ... da ist von .50 weder etwas um 55:08 zu sehen noch um 55.28

Die Pakete um 13:55:28 mit .61 ist der renew des anderen Players der unmittelbar nach dem Fehler gestartet wird

Code Auswählen Erweitern

    1800 2017.02.21 13:55:28.947 0: SONOS1: nach peek renewSubscription
    1801 2017.02.21 13:55:28.947 3: SONOS1: AVTprox 1 RINCON_000E58A376D201400_MR
    1802 2017.02.21 13:55:28.947 3: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58A376D201400_MR" vor dem renew-Versuch
    1803 2017.02.21 13:55:29.248 3: SONOS1: Transport-Subscription for ZonePlayer "RINCON_000E58A376D201400_MR" has expired and is now renewed.


Hast du irgendeine Erklärung / Idee dazu ?

Die positive Nachricht ist, dass auch in diesem Fall nach kurzer Zeit alles wieder OK war  aus meiner Sicht kannst du deine Änderung einbauen und frei geben, auch wenn wir nicht wissen wodurch das Problem ausgelöst wird 

Gruß Nobby

Edit: das bestätigt dann meinen Verdacht, dass es sich NICHT um ein Netzwerkproblem handelt sondern ein Problem der IP/UPnP-Implementierung in Perl oder im Windows ist 

[Nobby1805]

Hallo Reiner,

interessanter/komischer Nebeneffekt ... seitdem ich die Logs eingebaut habe um dem Renew-Problem auf die Spur zu kommen häuft sich bei mir folgende Fehlermeldung

Code Auswählen Erweitern

     124 2017.02.24 00:09:12.882 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 485, <$client> line 6.

Ich habe jetzt auch dort Logging eingebaut und mit gleichzeitigem Einsatz eines Netzwerkscanners und eines Prozessmonitors folgendes festgestellt: der Auslöser scheinen UPnP-Multicastmessages eines Nicht-Sonos-Gerätes zu sein, es ist ein Panasonic TV. Interessanterweise ein ähnliches Phänomen wie bei dem Loop, die Leseroutine wird aufgerufen weil eine Message gekommen ist, aber beim Lesen der Message kommt nichts und beim Versuch den Header zu dekodieren dann der o.a. Fehler. Ignore-IP wirkt dort noch nicht weil die Prüfung erst danach auf Basis des dekodierten Headers erfolgt

Nach diesem Fehler folgen dann immer unsubscribes für alle Sonos-Geräte

Code Auswählen Erweitern

   18834 2017.02.24 10:35:11.898 1: SONOS1: unsubscripe
   18835 2017.02.24 10:35:11.899 1: SONOS1: unsubscribe http://192.168.1.61:1400/AudioIn/Event
   18836 2017.02.24 10:35:11.923 1: SONOS1: unsubscripe
   18837 2017.02.24 10:35:11.925 1: SONOS1: unsubscribe http://192.168.1.50:1400/MediaServer/ContentDirectory/Event
   18838 2017.02.24 10:35:11.955 1: SONOS1: unsubscripe
   18839 2017.02.24 10:35:11.957 1: SONOS1: unsubscribe http://192.168.1.61:1400/DeviceProperties/Event
... usw.


Ich habe dort jetzt eine Fehlerprüfung eingebaut ... vielleicht besteht ja ein Zusammenhang mit dem Renew-Problem

Code Auswählen Erweitern

                     if (!defined($peer)){                                                             ####Nobby
        UPnP::ControlPoint::NobLog undef, 1, "peer undefined -> return";              ####Nobby 
                         return;                                                                       ####Nobby
                     }                                                                                 ####Nobby

schaun wir mal ...

Gruß Nobby

[Reinerlein]

Hi Nobby,

ich habe hier jetzt auch jeweils ein return eingebaut, wenn peer oder peerdata leer ist.
Das kann auf jeden Fall nicht schaden

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

mit der Erweiterung beim Renew läuft es jetzt eigentlich recht gut ... aber ich bin immer noch der Ursache auf der Spur und baue bei jedem Auftreten des Problems weiteres Logging ein ...

Heute ist mir ein ganz anderer Fehler, aber anscheinend ähnlicher Kontext, aufgefallen ... vielleicht kannst du mir helfen, den zu interpretieren

Code Auswählen Erweitern

   29923 2017.03.11 00:12:36.038 3: Nobby1: No trackinformationen found in data:
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/">
  <InstanceID val="0">
  <TransportStatus val="ERROR_LOST_CONNECTION"/>
  <TransportErrorDescription val="7,0,Briefcase Boogie,//HOMESERVER/Musik,//HOMESERVER/Musik/Thing-Fish/26 - Zappa\, Frank - Briefcase Boogie.mp3,"/>
  <TransportErrorURI val="x-file-cifs://HOMESERVER/Musik/Thing-Fish/26%20-%20Zappa,%20Frank%20-%20Briefcase%20Boogie.mp3"/>
  </InstanceID>
</Event>

Sehe ich das richtig, dass der Player ein Problem hatte auf die MP3-Datei zuzugreifen ?

Viele Grüße
Nobby

Edit: btw. da ist außerdem ein Schreibfehler drin ... trackinformationen ... oder besser, ein deutsches Wort im englischen Satz

[Reinerlein]

Hi Nobby,

den Tippfehler habe ich korrigiert, und auch den Loglevel eine Ebene hochgesetzt.
Diese Meldung bedeutet, dass der Player die MP3-Datei wegen eines Verbindungsproblems nicht wiedergeben konnte. Im Großen und Ganzen kann das Sonos-Modul diese Meldung ignorieren, da es keine Lösung gibt, die das Modul durchführen könnte...

Das deutet aber weiter darauf hin, dass deine Player Funknetzprobleme haben, die nichts mit dem Modul zu tun haben...

Ich werde am Wochenende die neue Version einchecken. Bei mir läuft jetzt wieder alles stabil (nachdem ich diesen Freeze von Fhem veursacht hatte ). Ich habe noch ein paar neue Readings eingefüht... dazu dann aber mehr in der Releasemeldung...

Grüße
Reiner

[Nobby1805]

Hi Reiner,

danke für die schnelle Rückmeldung die meine Vermutung bestätigt ... aber der Player hat beim abspielen keine Probleme gemacht ... kein stocken oder überspringen eines Liedes

Das deutet aber weiter darauf hin, dass deine Player Funknetzprobleme haben, die nichts mit dem Modul zu tun haben...

Das schließe ich ja auch nicht aus ... aber ich wüsste es gerne noch etwas konkreter und deshalb teste ich weiter

UPnP ist bzw. war bisher nicht mein Thema ... vielleicht kannst du mir helfen ...

Nach der letzten Logerweiterung sind mir HTTP-Logs aufgefallen die mit Sonos bzw. dem FHEM gar nichts zu tun haben ... schickst du einen "Alle UPnP-Devices bitte melden" ins Netz? Kann man die Antworten irgendwo loggen? Ich vermute, dass Nicht-SONOS Antworten dann nicht weiter verwendet werden ...
Es haben sich z.B. ein devolo-Device und irgendetwas aus dem mit VPN verbundenen Netz meiner Tochter (eigentlich laufen darüber nur zyklische Backups) gemeldet

Gruß aus dem z.Zt. sonnigen Essen
Nobby

[Reinerlein]

Hi Nobby,

yupp, Eine UPnP-Suchanfrage ist eine Broadcast Message an das Netz im allgemeinen. Es antworten alle Geräte darauf, und die Antworten werden dann entsprechend gefiltert...

Die Antworten landen dann in der Prozedur "_receiveSearchResponse" in der ControlPoint.pm und werden dort gefiltert und zu Devices verarbeitet.

Du kannst auch beispielsweise mit dem Intel Device Spy nachschauen, was es so gibt, und wie die sich melden...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

der am Anfang dieses Threads, #7, diskutierete Loop ist nach langer Zeit gestern Abend wieder bei mir aufgetreten, allerdings in einer etwas anderen Variante aber im Prinzip an der selben Stelle.

Aufgefallen ist mir, dass im Log im Prinzip minütlich folgende Meldung kam

2017.03.31 01:43:14.655 1: Perfmon: possible freeze starting at 01:42:57, delay is 17.655
2017.03.31 01:44:02.656 1: Perfmon: possible freeze starting at 01:43:45, delay is 17.656

mit Appdata habe ich dann gefunden, dass diese Verzögerung von SONOS_IsSubprocessAliveChecker ausgelöst wurde und habe dann in den von mir "damals" stark erweiterten Log geschaut.

Normalerweise sieht der Log der durch die Kommunikation des SubprocessAliveCheckers im Subprocess erzeugt wird so aus

Code Auswählen Erweitern

  344501 2017.03.30 23:36:00.261 3: 17476 Nobby0: nach bits/Count 0028 0000  2
  344502 2017.03.30 23:36:00.717 3: 17476 Nobby0: nach can_read GLOB(0x1991d9c)
  344503 2017.03.30 23:36:00.717 3: 17476 Nobby0: vor foreach-loop
  344504 2017.03.30 23:36:00.717 3: 17476 Nobby0: foreach GLOB(0x1991d9c) GLOB(0x1991d9c)
  344505 2017.03.30 23:36:00.717 3: 17476 Nobby0: connected
  344506 2017.03.30 23:36:00.719 3: 17476 Nobby0: Connection accepted from HomeServer:2702
  344507 2017.03.30 23:36:00.719 3: 17476 Nobby0: nach bits/Count 0028 0020  3
  344508 2017.03.30 23:36:00.719 3: 17476 Nobby0: nach can_read GLOB(0x1c5ab0c)
  344509 2017.03.30 23:36:00.720 3: 17476 Nobby0: vor foreach-loop
  344510 2017.03.30 23:36:00.720 3: 17476 Nobby0: foreach GLOB(0x1c5ab0c) GLOB(0x1991d9c)
  344511 2017.03.30 23:36:00.720 3: 17476 Nobby0: connected
  344512 2017.03.30 23:36:00.720 3: 17476 Nobby0: inp = hello

  344513 2017.03.30 23:36:00.720 1: 17476 Nobby0: Received: 'hello'
  344514 2017.03.30 23:36:00.721 3: 17476 Nobby0: nach bits/Count 0028 0020  3
  344515 2017.03.30 23:36:00.721 3: 17476 Nobby0: nach can_read GLOB(0x1c5ab0c)
  344516 2017.03.30 23:36:00.721 3: 17476 Nobby0: vor foreach-loop
  344517 2017.03.30 23:36:00.721 3: 17476 Nobby0: foreach GLOB(0x1c5ab0c) GLOB(0x1991d9c)
  344518 2017.03.30 23:36:00.721 3: 17476 Nobby0: connected
  344519 2017.03.30 23:36:00.722 3: 17476 Nobby0: inp = goaway

  344520 2017.03.30 23:36:00.722 1: 17476 Nobby0: Received: 'goaway'
  344521 2017.03.30 23:36:00.722 3: 17476 Nobby0: nach bits/Count 0028 0000  2
  344522 2017.03.30 23:36:01.714 3: 17476 Nobby0: nach can_read
  344523 2017.03.30 23:36:01.714 3: 17476 Nobby0: vor foreach-loop
erst das hello und dann das goaway

als es dann anders wurde, und damit das Problem begann, wurde folgendes gelogged

Code Auswählen Erweitern

  344658 2017.03.30 23:36:35.011 3: 17476 Nobby0: nach bits/Count 0028 0000  2
  344659 2017.03.30 23:36:35.069 3: 17476 Nobby0: nach can_read GLOB(0x19a9bbc)
  344660 2017.03.30 23:36:35.070 3: 17476 Nobby0: vor foreach-loop
  344661 2017.03.30 23:36:35.070 3: 17476 Nobby0: foreach GLOB(0x19a9bbc) GLOB(0x1991d9c)
  344662 2017.03.30 23:36:35.070 3: 17476 Nobby0: connected
  344663 2017.03.30 23:36:35.070 3: 17476 Nobby0: inp = DoWork:RINCON_000E58C1DE0A01400_MR:getCurrentTrackPosition:


  344664 2017.03.30 23:36:35.070 1: 17476 Nobby0: Received: 'DoWork:RINCON_000E58C1DE0A01400_MR:getCurrentTrackPosition:'
  344665 2017.03.30 23:36:35.071 1: 17476 Nobby0: DoWork: 'RINCON_000E58C1DE0A01400_MR' 'getCurrentTrackPosition'
  344666 2017.03.30 23:36:35.071 1: 17476 Nobby0: vor ComObjectTransportQueue
  344667 2017.03.30 23:36:35.071 1: 17476 Nobby0: nach enqueue, pending= 2
  344668 2017.03.30 23:36:35.072 3: 17476 Nobby0: nach bits/Count 0028 0000  2
  344669 2017.03.30 23:36:35.105 3: 17476 Nobby0: nach can_read GLOB(0x1991d9c)
  344670 2017.03.30 23:36:35.106 3: 17476 Nobby0: vor foreach-loop
  344671 2017.03.30 23:36:35.106 3: 17476 Nobby0: foreach GLOB(0x1991d9c) GLOB(0x1991d9c)
  344672 2017.03.30 23:36:35.106 3: 17476 Nobby0: connected
  344673 2017.03.30 23:36:35.108 3: 17476 Nobby0: Connection accepted from HomeServer:2736
  344674 2017.03.30 23:36:35.108 3: 17476 Nobby0: nach bits/Count 0028 0040  3
  344675 2017.03.30 23:36:35.111 3: 17476 Nobby0: nach can_read GLOB(0x1c755c4)
  344676 2017.03.30 23:36:35.111 3: 17476 Nobby0: vor foreach-loop
  344677 2017.03.30 23:36:35.111 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344678 2017.03.30 23:36:35.112 3: 17476 Nobby0: connected
  344679 2017.03.30 23:36:35.112 3: 17476 Nobby0: inp = hello

  344680 2017.03.30 23:36:35.112 1: 17476 Nobby0: Received: 'hello'
  344681 2017.03.30 23:36:35.112 3: 17476 Nobby0: nach bits/Count 0028 0040  3
  344682 2017.03.30 23:36:35.209 3: 17476 Nobby0: nach can_read GLOB(0x1c755c4)
  344683 2017.03.30 23:36:35.210 3: 17476 Nobby0: nach can_write GLOB(0x19a9bbc) GLOB(0x1c755c4)
  344684 2017.03.30 23:36:35.210 3: 17476 Nobby0: vor foreach-loop
  344685 2017.03.30 23:36:35.210 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344686 2017.03.30 23:36:35.211 3: 17476 Nobby0: connected
  344687 2017.03.30 23:36:35.478 3: 17476 Nobby0: inp = 
  344688 2017.03.30 23:36:35.479 1: 17476 Nobby0: kein Received: inp ist undef
  344689 2017.03.30 23:36:37.464 3: 17476 Nobby0: nach bits/Count 0028 0040  3
  344690 2017.03.30 23:36:37.465 3: 17476 Nobby0: nach can_read GLOB(0x1c755c4)
  344691 2017.03.30 23:36:37.465 3: 17476 Nobby0: nach can_write GLOB(0x19a9bbc) GLOB(0x1c755c4)
  344692 2017.03.30 23:36:37.467 3: 17476 Nobby0: vor foreach-loop
  344693 2017.03.30 23:36:37.467 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344694 2017.03.30 23:36:37.469 3: 17476 Nobby0: connected
  344695 2017.03.30 23:36:37.470 3: 17476 Nobby0: inp = 
  344696 2017.03.30 23:36:37.470 1: 17476 Nobby0: kein Received: inp ist undef
  344697 2017.03.30 23:36:39.464 3: 17476 Nobby0: nach bits/Count 0028 0040  3
  344698 2017.03.30 23:36:39.464 3: 17476 Nobby0: nach can_read GLOB(0x1c755c4)
  344699 2017.03.30 23:36:39.464 3: 17476 Nobby0: vor foreach-loop
  344700 2017.03.30 23:36:39.464 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344701 2017.03.30 23:36:39.465 3: 17476 Nobby0: connected
  344702 2017.03.30 23:36:39.465 3: 17476 Nobby0: inp = 

unmittelbar vor dem hello kam ein DoWork ... und dann nach dem hello werden leere Strings gelesen ... goaway kam gar nicht und dann nach einiger Zeit wieder ein hello

Code Auswählen Erweitern

  344825 2017.03.30 23:37:07.464 3: 17476 Nobby0: nach bits/Count 0028 0060  4
  344826 2017.03.30 23:37:07.464 3: 17476 Nobby0: nach can_read GLOB(0x1c5af44) GLOB(0x1c755c4)
  344827 2017.03.30 23:37:07.464 3: 17476 Nobby0: vor foreach-loop
  344828 2017.03.30 23:37:07.464 3: 17476 Nobby0: foreach GLOB(0x1c5af44) GLOB(0x1991d9c)
  344829 2017.03.30 23:37:07.464 3: 17476 Nobby0: connected
  344830 2017.03.30 23:37:07.465 3: 17476 Nobby0: inp = hello

  344831 2017.03.30 23:37:07.465 1: 17476 Nobby0: Received: 'hello'
  344832 2017.03.30 23:37:07.465 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344833 2017.03.30 23:37:07.465 3: 17476 Nobby0: connected
  344834 2017.03.30 23:37:07.466 3: 17476 Nobby0: inp = 
  344835 2017.03.30 23:37:07.466 1: 17476 Nobby0: kein Received: inp ist undef
  344836 2017.03.30 23:37:09.464 3: 17476 Nobby0: nach bits/Count 0028 0060  4
  344837 2017.03.30 23:37:09.464 3: 17476 Nobby0: nach can_read GLOB(0x19a9bbc) GLOB(0x1c5af44) GLOB(0x1c755c4)
  344838 2017.03.30 23:37:09.464 3: 17476 Nobby0: vor foreach-loop
  344839 2017.03.30 23:37:09.464 3: 17476 Nobby0: foreach GLOB(0x19a9bbc) GLOB(0x1991d9c)
  344840 2017.03.30 23:37:09.464 3: 17476 Nobby0: connected
  344841 2017.03.30 23:37:09.464 3: 17476 Nobby0: inp = DoWork:RINCON_000E58C1DE0A01400_MR:getCurrentTrackPosition:


  344842 2017.03.30 23:37:09.465 1: 17476 Nobby0: Received: 'DoWork:RINCON_000E58C1DE0A01400_MR:getCurrentTrackPosition:'
  344843 2017.03.30 23:37:09.465 1: 17476 Nobby0: DoWork: 'RINCON_000E58C1DE0A01400_MR' 'getCurrentTrackPosition'
  344844 2017.03.30 23:37:09.465 1: 17476 Nobby0: vor ComObjectTransportQueue
  344845 2017.03.30 23:37:09.466 1: 17476 Nobby0: nach enqueue, pending= 1
  344846 2017.03.30 23:37:09.466 1: 17476 Nobby0: pending ist 1
  344847 2017.03.30 23:37:09.466 3: 17476 Nobby0: foreach GLOB(0x1c5af44) GLOB(0x1991d9c)
  344848 2017.03.30 23:37:09.466 3: 17476 Nobby0: connected
  344849 2017.03.30 23:37:09.466 3: 17476 Nobby0: inp = goaway

  344850 2017.03.30 23:37:09.466 1: 17476 Nobby0: Received: 'goaway'
  344851 2017.03.30 23:37:09.467 3: 17476 Nobby0: foreach GLOB(0x1c755c4) GLOB(0x1991d9c)
  344852 2017.03.30 23:37:09.467 3: 17476 Nobby0: connected
  344853 2017.03.30 23:37:09.467 3: 17476 Nobby0: inp = 
  344854 2017.03.30 23:37:09.468 1: 17476 Nobby0: kein Received: inp ist undef


Was mir jetzt auffällt ist, das im "normalen" Log in der bits/count-Zeile 0028 0020 3 steht ... wenn nichts zu tun ist 0028 0000 2.
Beim Start des Problems lautet es 0028 0040 3  ... und dann später 0028 0060 4 ... noch später gibt es dann 0028 0060 4 und 0028 00e0 5
Ich habe so das Gefühl, als ob das '40'-ger Bit nicht zurückgesetzt wird und dann die falsche Behandlung auslöst

Weist du, oder sonst jemand, was diese Bits genau bedeuten? und evt. auch was man gegen den Loop tun kann?

Der von mir eingebaute Code lautet übrigens

Code Auswählen Erweitern

        my $Nobbits = $SONOS_Client_Selector->bits();             ####Nobby
        my $Nobcnt = $SONOS_Client_Selector->count();             ####Nobby
                my $Nobfoo = ord($Nobbits);                               ####Nobby   
                my $Nobtext = sprintf ("Hex=%04x",$Nobfoo);               ####Nobby
                $Nobbits =~ s/(.)/sprintf("%04x ",ord($1))/eg;               ####Nobby
      SONOS_Log undef, 3, "nach bits/Count $Nobbits $Nobcnt";                 ###Nobby

# Das ganze blockiert eine kurze Zeit, um nicht 100% CPU-Last zu erzeugen
# Das bedeutet aber auch, dass Sende-Vorgänge um maximal den Timeout-Wert verzögert werden
# my @ready = $SONOS_Client_Selector->can_read(0.1);
my @ready = $SONOS_Client_Selector->can_read(1.0);         ####Nobby
     
      SONOS_Log undef, 3, "nach can_read @ready";      ###Nobby


Nach Restart des FHEM lief dann alles wieder normal

Gruß Nobby

[Nobby1805]

Hallo Reiner,

ich habe mich am Wochenende entschieden meien alte Sonos-Version, in die ich ja jede Menge erweiterte Logs eingebaut hatte, durch die aktuelle per update zu aktualisieren ... seit dem treten jede Menge Fehler auf, solche die schon mal da waren und auch Neue

Code Auswählen Erweitern

2017.04.11 03:08:14.276 2: SONOS1: Error during UPnP-Handling, restarting handling: Bad arg length for Socket::unpack_sockaddr_in, length is 0, should be 16 at FHEM/lib/UPnP/ControlPoint.pm line 434, <$client> line 6.
ich dachte, da hättest du einen Fix eingebaut ...


Hi Nobby,

ich habe hier jetzt auch jeweils ein return eingebaut, wenn peer oder peerdata leer ist.
Das kann auf jeden Fall nicht schaden

Grüße
Reiner

Heute Morgen wurde um 8:45 meine Weckmelodie abgespielt ... aber danach wurde der Player nicht wieder richtig auf den vorherigen Stand gesetzt ... aber dazu finde ich keinerlei Meldung

Dafür kommt:

Code Auswählen Erweitern

2017.04.11 02:55:40.885 3: SONOS1: Event: Received ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
2017.04.11 02:55:41.013 3: SONOS1: Event: End of ZoneGroupTopology-Event for Zone "Sonos_Wohnzimmer".
2017.04.11 02:55:41.013 1: SONOS1: ZoneGroupTopology-Event: device 'Sonos_Wohnzimmer' is marked as disappeared. Restarting discovery-process!
2017.04.11 02:55:41.057 3: SONOS0: Connection accepted from HomeServer:3852
2017.04.11 02:55:41.073 3: SONOS0: Disconnecting client...
2017.04.11 02:55:41.078 2: SONOS1: Error during UPnP-Handling:
2017.04.11 02:55:41.146 3: SONOS0: Trying to kill Sonos_Thread...
2017.04.11 02:55:41.157 3: SONOS0: Trying to kill IsAlive_Thread...
2017.04.11 02:55:41.157 3: SONOS0: Trying to kill PlayerRestore_Thread...
2017.04.11 02:55:41.170 3: SONOS0: Connection accepted from HomeServer:3853
2017.04.11 02:55:41.171 3: SONOS0: Disconnecting client...
2017.04.11 02:55:41.171 3: SONOS0: Sonos_Thread is already killed!
2017.04.11 02:55:41.171 3: SONOS0: IsAlive_Thread is already killed!
2017.04.11 02:55:41.172 3: SONOS0: PlayerRestore_Thread is already killed!
2017.04.11 02:55:41.186 3: SONOS1: Controlpoint-Listener wurde beendet.
2017.04.11 02:55:41.385 1: SONOS2: IsAlive-Thread wurde beendet.
2017.04.11 02:55:41.417 1: SONOS3: Restore-Thread wurde beendet.
2017.04.11 02:55:49.167 3: SONOS0: Connection accepted from HomeServer:3862
(in cleanup) Unsubscription request failed with error: 500 read timeout at FHEM/lib/UPnP/ControlPoint.pm line 1063 thread 1.
2017.04.11 02:56:07.276 2: SONOS1: Discover Sonosplayer 'Schlafzimmer' (S1) Software Revision 7.2 with ID 'RINCON_000E58C1DE0A01400_MR'
2017.04.11 02:56:09.104 2: SONOS1: SonosPlayer 'Schlafzimmer' (S1) with ID 'RINCON_000E58C1DE0A01400_MR' is already defined (as 'Sonos_Schlafzimmer') and will only be updated


Code Auswählen Erweitern

Can't call method "kill" on an undefined value at ./FHEM/00_SONOS.pm line 9120.
leider ohne Zeitstempel

Code Auswählen Erweitern

2017.04.11 11:45:07.424 0: SONOS0: No Answer from Subprocess. Restart Sonos-Subprocess...
2017.04.11 11:45:15.519 3: Opening Sonos device localhost:4711
2017.04.11 11:45:15.616 3: Sonos device opened
2017.04.11 11:53:40.226 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackURI,x-file-cifs://HOMESERVER/Musik/Music%20of%20Jethro%20Tull/01%20-%20London%20Symphony%20Orchestra%20-%20Locomotive%20Breath.mp3) missed to call readingsBeginUpdate first.
2017.04.11 11:53:40.226 1: stacktrace:
2017.04.11 11:53:40.227 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8676)
2017.04.11 11:53:40.227 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1167)
2017.04.11 11:53:40.227 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.11 11:53:40.227 1:     main::CallFn                        called by fhem.pl (685)
2017.04.11 11:53:40.229 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackProvider,) missed to call readingsBeginUpdate first.
2017.04.11 11:53:40.230 1: stacktrace:
2017.04.11 11:53:40.230 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8676)
2017.04.11 11:53:40.230 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1167)
2017.04.11 11:53:40.230 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.11 11:53:40.231 1:     main::CallFn                        called by fhem.pl (685)
2017.04.11 11:53:40.234 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackPosition,0:00:22) missed to call readingsBeginUpdate first.
2017.04.11 11:53:40.235 1: stacktrace:
2017.04.11 11:53:40.235 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8676)
2017.04.11 11:53:40.235 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1167)
2017.04.11 11:53:40.236 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.11 11:53:40.236 1:     main::CallFn                        called by fhem.pl (685)
2017.04.11 11:53:40.238 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackPositionSec,22) missed to call readingsBeginUpdate first.
2017.04.11 11:53:40.238 1: stacktrace:
2017.04.11 11:53:40.239 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8676)
2017.04.11 11:53:40.239 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1167)
2017.04.11 11:53:40.239 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.11 11:53:40.239 1:     main::CallFn                        called by fhem.pl (685)
2017.04.11 11:53:40.245 1: readingsUpdate(Sonos_Wohnzimmer,currentStreamAudio,) missed to call readingsBeginUpdate first.
2017.04.11 11:53:40.245 1: stacktrace:
2017.04.11 11:53:40.245 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8676)
2017.04.11 11:53:40.246 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1167)
2017.04.11 11:53:40.246 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.11 11:53:40.246 1:     main::CallFn                        called by fhem.pl (685)
2017.04.11 11:55:17.252 1: Perfmon: possible freeze starting at 11:54:47, delay is 30.252
2017.04.11 11:57:28.288 1: Perfmon: possible freeze starting at 11:57:16, delay is 12.288
2017.04.11 12:01:28.435 0: SONOS0: No Answer from Subprocess. Restart Sonos-Subprocess...
2017.04.11 12:01:36.461 3: Opening Sonos device localhost:4711
2017.04.11 12:01:36.477 3: Sonos device opened


Ich baue jetzt wieder Teile meines erweiterten Loggings in die aktuelle 00_SONOS ein

Gruß Nobby

[Reinerlein]

Hi Nobby,

damit es bei dir ankommen kann, muss man es auch einchecken...

Ich habe das gerade mal nachgeholt... Sorry...

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

mal wieder eine Fehlermeldung die ich noch nie hatte

Error during UPnP-Handling, restarting handling: multiple roots, wrong element 'direction'

Gruß Nobby

[Nobby1805]

Hallo Reiner,

mit der neuen Version ist alles bei mir deutlich instabiler geworden

Threads werden beendet und neu gestartet

5013 2017.04.18 13:38:02.772 3: Nobby0: inp = 'disconnect'
    5014 2017.04.18 13:38:02.772 1: Nobby0: Received: 'disconnect'
    5015 2017.04.18 13:38:02.772 3: Nobby0: Disconnecting client...
    5016 2017.04.18 13:38:02.772 3: Nobby0: Trying to kill Sonos_Thread...
    5017 2017.04.18 13:38:02.773 3: Nobby0: Trying to kill IsAlive_Thread...
    5018 2017.04.18 13:38:02.773 3: Nobby0: Trying to kill PlayerRestore_Thread...
    5019 2017.04.18 13:38:02.773 3: Nobby0: inp = ''
    5020 2017.04.18 13:38:02.773 1: Nobby0: kein Received: inp ist undef
    4768 2017.04.18 13:38:02.834 1: Nobby14: IsAlive-Thread wurde beendet.
    4775 2017.04.18 13:38:02.928 1: Nobby15: Restore-Thread wurde beendet.
   13972 2017.04.18 13:38:03.209 3: Nobby13: Controlpoint-Listener wurde beendet.

Fehlermeldungen im Log

2017.04.18 13:49:13.631 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackURI,x-file-cifs://homeserver/Musik/The%20Yellow%20Shark/09%20-%20Zappa,%20Frank%20-%20Ruth%20Is%20Sleeping.mp3) missed to call readingsBeginUpdate first.
2017.04.18 13:49:13.632 1: stacktrace:
2017.04.18 13:49:13.632 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8688)
2017.04.18 13:49:13.632 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1169)
2017.04.18 13:49:13.633 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.18 13:49:13.633 1:     main::CallFn                        called by fhem.pl (685)
2017.04.18 13:49:13.636 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackProvider,) missed to call readingsBeginUpdate first.
2017.04.18 13:49:13.636 1: stacktrace:
2017.04.18 13:49:13.636 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8688)
2017.04.18 13:49:13.636 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1169)
2017.04.18 13:49:13.637 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.18 13:49:13.637 1:     main::CallFn                        called by fhem.pl (685)
2017.04.18 13:49:13.642 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackPosition,0:00:12) missed to call readingsBeginUpdate first.
2017.04.18 13:49:13.643 1: stacktrace:
2017.04.18 13:49:13.643 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8688)
2017.04.18 13:49:13.643 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1169)
2017.04.18 13:49:13.644 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.18 13:49:13.644 1:     main::CallFn                        called by fhem.pl (685)
2017.04.18 13:49:13.647 1: readingsUpdate(Sonos_Wohnzimmer,currentTrackPositionSec,12) missed to call readingsBeginUpdate first.
2017.04.18 13:49:13.647 1: stacktrace:
2017.04.18 13:49:13.647 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (8688)
2017.04.18 13:49:13.648 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1169)
2017.04.18 13:49:13.648 1:     main::SONOS_Read                    called by fhem.pl (3379)
2017.04.18 13:49:13.648 1:     main::CallFn                        called by fhem.pl (685)

Der ZP90-Player (Connect) hat sich in den letzten Tagen mehrfach komplett aufgehängt und war auch von der Sonos-App nicht erreichbar ... Power-Off/On war notwendig

und dann noch diese Meldungen

Unsubscription request failed with error: 500 Can't connect to 192.168.1.66:1400 at FHEM/lib/UPnP/ControlPoint.pm line 1066 thread 1.
Loading device description failed with error: 500 Can't connect to 192.168.1.66:1400 (Location: http://192.168.1.66:1400/xml/device_description.xml) at ./FHEM/00_SONOS.pm line 4129 thread 1.
Error loading SCPD document: Bad file descriptor at ./FHEM/00_SONOS.pm line 5575 thread 1.
Error loading SCPD document: Bad file descriptor at ./FHEM/00_SONOS.pm line 5581 thread 1.
Error loading SCPD document: Bad file descriptor at ./FHEM/00_SONOS.pm line 5618 thread 1.
   (in cleanup) Unsubscription request failed with error: 500 Can't connect to 192.168.1.66:1400 at FHEM/lib/UPnP/ControlPoint.pm line 1066 thread 1.
Odd number of elements in hash assignment at FHEM/lib/UPnP/ControlPoint.pm line 869, <$client> line 6.
   (in cleanup) Unsubscription request failed with error: 500 read timeout at FHEM/lib/UPnP/ControlPoint.pm line 1066 thread 1.
Can't call method "kill" on an undefined value at ./FHEM/00_SONOS.pm line 9138.

Was tun?

Gruß Nobby

[Reinerlein]

Hi Nobby,

wenn schon Player neugestartet werden müssen, würde ich wirklich mal prüfen, ob du das Netz nicht stabiler gestalten kannst

Läuft das nach den Unregelmäßigkeiten denn irgendwann wieder normal? Oder musst du bei Fhem irgendwo eingreifen?
Ich denke nicht, dass das Modul stabiler als deine Sonos-Landschaft werden kann. Es wird immer empfindlicher reagieren, als der Controller selbst.
Das Problem ist ja, dass du durch das Modul jede Instabilität feststellst, auch wenn zu diesem Zeitpunkt gar keine Player laufen (meint: Musik abspielen).
Vielleicht wäre es eine Lösung, wenn du mit dem Sonos-Support die Verbindungen optimieren läßt...

Was auch ein Problem zu sein scheint, ist die TCP/IP Verbindung zwischen Fhem-Modul und SubProzess.
Es gibt im Fhem-Level eine Prozedur "SONOS_IsSubprocessAliveChecker", die periodisch prüft, ob der SubProzess korrekt antwortet. Wenn dort keine Antwort ankommt, dann wird an den Client ein Neustart gesendet (das sind deine ersten Logausgaben).
Hast du dort mal Logausgaben angesetzt?
Du solltest mal schauen, warum sogar innerhalb eines Systems soviel Netzwerkkommunikation schief geht....

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

ich musste auch FHEM neu starten und den SONSO-Subprozess musste ich auch "von Hand" totschlagen ...

Ich weiß, ehrlich gesagt, nicht was ich am Netzwerk verbessern soll ... die Bridge ist per LAN verbunden und der jetzt betroffene Player steht 3 Meter daneben.
Aber, ich hatte auch schon mal überlegt den Support von Sonos einzuschalten ... das werde ich dann mal probieren.

Gruß Nobby

[Nobby1805]

Hallo Reiner,

ich habe den Eindruck, dass das keepAlive zwischen dem Haupt-FHEM und dem Sonos-Prozess ab und zu gestört wird

Im FHEM-Log

2017.04.21 09:57:41.420 0: SONOS0: No Answer from Subprocess. Restart Sonos-Subprocess...
2017.04.21 09:57:49.524 3: Opening Sonos device localhost:4711
2017.04.21 09:57:49.578 3: Sonos device opened

Jetzt habe ich ja noch genau an dieser Stelle aus den am Anfang dieses Beitrags beschriebenen Gründen Logs eingebaut ...
FHEM-Prozess

21900 2017.04.21 09:57:11.403 9: Nobby0: recv 'This is UPnP-Server calling'
   21901 2017.04.21 09:57:11.403 9: Nobby0: send hello
   21902 2017.04.21 09:57:11.403 9: Nobby0: recv OK
   21903 2017.04.21 09:57:11.404 9: Nobby0: send goaway
   21904 2017.04.21 09:57:41.418 9: Nobby0: recv 'This is UPnP-Server calling'
   21905 2017.04.21 09:57:41.418 9: Nobby0: send hello
   21906 2017.04.21 09:57:41.419 9: Nobby0: recv DoWorkAnswer:RINCON_000E58A376D201400_MR:LastActionResult:GetCurrentTrackPosition: 0:03:18
   21907 2017.04.21 09:57:41.419 9: Nobby0: send goaway
   21908 2017.04.21 09:58:50.714 9: Nobby0: recv 'This is UPnP-Server calling'
   21909 2017.04.21 09:58:50.714 9: Nobby0: send hello
   21910 2017.04.21 09:58:50.715 9: Nobby0: recv OK
   21911 2017.04.21 09:58:50.715 9: Nobby0: send goaway

Da kommt als Antwort auf das hello nicht das OK sondern ein DoWork-Antwort ... und die Abfrage auf das OK klappt dann nicht und es wird ein Disconnect gemacht

Code Auswählen Erweitern

if (!defined($answer) || ($answer ne 'OK')) {
SONOS_Log undef, 0, 'No Answer from Subprocess. Restart Sonos-Subprocess...';

Das zugehörige Logging im Subprozess sieht so aus

7857 2017.04.21 09:57:11.407 3: Nobby0: Connection accepted from HomeServer:2548
    7858 2017.04.21 09:57:11.408 1: Nobby0: Received: 'hello'
    7859 2017.04.21 09:57:11.409 1: Nobby0: Received: 'goaway'
    7860 2017.04.21 09:57:26.008 1: Nobby0: Received: 'DoWork:RINCON_000E58A376D201400_MR:getCurrentTrackPosition:'
    7861 2017.04.21 09:57:41.008 1: Nobby0: Received: 'DoWork:RINCON_000E58A376D201400_MR:getCurrentTrackPosition:'
    7862 2017.04.21 09:57:41.411 3: Nobby0: Connection accepted from HomeServer:2576
    7863 2017.04.21 09:57:41.412 1: Nobby0: Received: 'hello'
    7864 2017.04.21 09:57:41.413 1: Nobby0: Received: 'goaway'
    7865 2017.04.21 09:57:41.436 1: Nobby0: Received: 'disconnect'
    7866 2017.04.21 09:57:41.436 3: Nobby0: Disconnecting client...
    7867 2017.04.21 09:57:41.508 3: Nobby0: Trying to kill Sonos_Thread...
    7868 2017.04.21 09:57:41.508 3: Nobby0: Trying to kill IsAlive_Thread...
    7869 2017.04.21 09:57:41.508 3: Nobby0: Trying to kill PlayerRestore_Thread...

Wenn ich es recht überlege, dann treten die beschriebenen verstärkten Probleme etwa seit dem auf, als ich die zyklische Abfrage der aktuellen Trackposition eingebaut habe

Gruß Nobby

[Reinerlein]

Hi Nobby,

OK, das bekommen wir in den Griff.

Mach mal folgende Änderungen...

Neue Test-Version des Alive Checkers:

Code Auswählen Erweitern


sub SONOS_IsSubprocessAliveChecker() {
my ($hash) = @_;

return undef if (AttrVal($hash->{NAME}, 'disable', 0));

my $answer;
# Neue Verbindung parallel zur bestehenden Kommunikationsleitung.
# Nur zum Prüfen, ob der SubProzess noch lebt und antworten kann.
my $socket = new IO::Socket::INET(PeerAddr => $hash->{DeviceName}, Proto => 'tcp');
if ($socket) {
$socket->sockopt(SO_LINGER, pack("ii", 1, 0));

$socket->recv($answer, 500);

#$socket->send("hello\n", 0);
#$socket->recv($answer, 500);

$socket->send("goaway\n", 0);

$socket->shutdown(2);
$socket->close();
}
# Ab hier keine Parallelverbindung mehr offen...

if (defined($answer)) {
$answer =~ s/[\r\n]//g;
}

if (!defined($answer) || ($answer !~ m/^This is UPnP-Server listening for commands/)) {
SONOS_Log undef, 0, 'No (or incorrect) answer from Subprocess. Restart Sonos-Subprocess...';

# Verbindung beenden, damit der SubProzess die Chance hat neu initialisiert zu werden...
RemoveInternalTimer($hash);
DevIo_SimpleWrite($hash, "disconnect\n", 0);
DevIo_CloseDev($hash);

# Neu anstarten...
SONOS_StartClientProcessIfNeccessary($hash->{DeviceName}) if ($SONOS_StartedOwnUPnPServer);
InternalTimer(gettimeofday() + $hash->{WAITTIME}, 'SONOS_DelayOpenDev', $hash, 0);
} elsif (defined($answer) && ($answer =~ m/^This is UPnP-Server listening for commands/)) {
SONOS_Log undef, 4, 'Got correct answer from Subprocess...';

InternalTimer(gettimeofday() + $hash->{INTERVAL}, 'SONOS_IsSubprocessAliveChecker', $hash, 0);
}
}


Neue Version des Antwortstrings nach dem Kommentar "# Send Welcome-Message":

Code Auswählen Erweitern


send($client, "This is UPnP-Server listening for commands\r\n", 0);


Im Wesentlichen wird das rumgelaber zwischen den beiden Prozessen verkürzt, sodass nur noch die Willkommensnachricht des Clients im Server geprüft wird. Damit ist das auch nicht mehr unterbrechbar...

Schau mal wie das bei dir läuft... Bei mir läuft das auch stabil

Grüße
Reiner

[Nobby1805]

Hallo Reiner,

das Problem ist gestern wieder aufgetreten ...

Jetzt habe ich deine Änderungen eingebaut und neu gestartet .. schau'n wir mal was in den nächsten Tagen so passiert

Gruß Nobby

[Nobby1805]

Hi Reiner,

jetzt habe ich eine ganze Zeit versucht zu verstehen, was du genau verändert hast ... und die ganze Zeit die beiden # vor dem send (hello) und dem recv (answer) übersehen 

Gruß Nobby

[Nobby1805]

Hallo Reiner,

seitdem ich die Änderung eingebaut habe hat sich FHEM bei mir heute zum 2. mal komplett aufgehängt

Es fängt damit an, dass Perfmon immer höhere Blockaden meldet

2017.04.26 00:30:16.742 1: Perfmon: possible freeze starting at 00:29:11, delay is 65.742
2017.04.26 00:31:52.849 1: Perfmon: possible freeze starting at 00:30:47, delay is 65.849
...
2017.04.26 04:11:21.934 1: Perfmon: possible freeze starting at 04:10:10, delay is 71.934
2017.04.26 04:13:03.760 1: Perfmon: possible freeze starting at 04:11:52, delay is 71.76
2017.04.26 04:14:45.840 1: Perfmon: possible freeze starting at 04:13:34, delay is 71.84

Mit Apptime, das ich heute noch aufrufen konnte, gestern war alles blockiert ...

name                      function    max    Count       total          average maxDly
  tmr-SONOS_IsSubprocessAliveChecker      HASH(0x24db8d4)  94560        33  2838062       86001.88        28 HASH(Sonos)

was tun?

Gruß Nobby

Edit: hier tritt wieder das Problem auf, dass der can_read sagt es wären Daten da, beim recv das Ergebnis aber undef ist ... das goaway vom Main an den Sub kommt nie an

Code Auswählen Erweitern

    1176 2017.04.25 22:38:06.898 9: Nobby0: recv This is UPnP-Server listening for commands
    1177 2017.04.25 22:38:06.899 9: Nobby0: send goaway


Code Auswählen Erweitern

    3189 2017.04.25 22:38:06.894 3: Nobby0: Connection accepted from HomeServer:3882
    3190 2017.04.25 22:38:06.894 9: Nobby0: send This is UPnP-Server Listening...
    3191 2017.04.25 22:38:06.894 9: Nobby0: send DoWorkAnswer:RINCON_000E58C1DE0A01400_MR:LastActionResult:GetCurrentTrackPosition: 0:02:19

    3192 2017.04.25 22:38:06.895 9: Nobby0: send DoWorkAnswer:RINCON_000E58C1DE0A01400_MR:LastActionResult:GetCurrentTrackPosition: 0:02:19

    3193 2017.04.25 22:38:06.975 1: Nobby0: kein Received: inp ist undef
    3194 2017.04.25 22:38:08.972 1: Nobby0: kein Received: inp ist undef
    3195 2017.04.25 22:38:10.972 1: Nobby0: kein Received: inp ist undef
    3196 2017.04.25 22:38:12.972 1: Nobby0: kein Received: inp ist undef


[Nobby1805]

schon wieder, es reicht eine Stunde Musik zu hören ... wird anscheinend durch die zyklische Abfrage der TrackPosition ausgelöst bzw. verstärkt ...

Ich habe den Eindruck, dass das Problem daher kommt weil socket-shutdown und -Close gemacht werden bevor das goaway gelesen werden konnte ... ich baue da jetzt mal ein wait ein

Gruß Nobby

[Reinerlein]

Hi Nobby,

ich bastele gerade an eine Auslassung der Überprüfung, wenn sowieso im letzten zu prüfenden Zeitraum Daten übertragen wurden.
Damit sollten eigentlich überhaupt keine Überlappungen mehr auftreten, es sei denn, es kommt gerade etwas rein, wenn die Prüfung ansteht.
Eigentlich kannst du das auch simulieren, indem du das Interval einfach mal sehr (sehr!) hoch einstellst. Vielleicht mal auf 86400 (=1 Tag)?

Das Interval ist die erste Zahl hinter dem Host, also

Code Auswählen Erweitern


define Sonos SONOS localhost:4711 86400


Mal schauen, ob es dann besser wird (natürlich wird dann ein verstorbener Prozess erstmal nicht erkannt, was jetzt aber mal egal ist )

Grüße
Reiner

[cortmen]

Hallo,

Unser gutes Sonos Modul ärgert mich im Moment etwas.
Oder spinnt der Google speak service in den letzten Tagen rum?

Per Sonos Speak Ausgabe klappt manchmal, öfters kommt auch nur ..

Code Auswählen Erweitern

Unescaped left brace in regex is deprecated, passed through in regex; marked by <-- HERE in m/(\\%(?:\\=)?(\w|\\{ <-- HERE (?:\w|\\[^\w\\{}]|\\\\\\[\\{}])*\\}|\\\W))/ at FHEM/lib/MP3/Tag.pm line 2611.

Leider hilft dann nur ein Neustart..
Hat das MP3/Tag.pm Modul da was mit zu tun?
Die MP3 Files werden nur mit 2-4KB angelegt.


Danke für einen Tipp

[hoods]

Hallo zusammen,

ich konnte zwar bisher keine Probleme mit der Sprachausgabe feststellen aber ich bekomme seit kurzem die gleiche Fehlermeldung im fhem.log.

Code Auswählen Erweitern

Unescaped left brace in regex is deprecated, passed through in regex; marked by <-- HERE in m/(\\%(?:\\=)?(\w|\\{ <-- HERE (?:\w|\\[^\w\\{}]|\\\\\\[\\{}])*\\}
|\\\W))/ at FHEM/lib/MP3/Tag.pm line 2611.

Ha jemand einen Tipp wie man die abstellen kann?

Danke & Gruss,
Sven

[Nobby1805]

Hi Nobby,

wenn schon Player neugestartet werden müssen, würde ich wirklich mal prüfen, ob du das Netz nicht stabiler gestalten kannst

...

Du solltest mal schauen, warum sogar innerhalb eines Systems soviel Netzwerkkommunikation schief geht....

Grüße
Reiner

Hallo Reiner,

ich musste auch FHEM neu starten und den SONSO-Subprozess musste ich auch "von Hand" totschlagen ...

Ich weiß, ehrlich gesagt, nicht was ich am Netzwerk verbessern soll ... die Bridge ist per LAN verbunden und der jetzt betroffene Player steht 3 Meter daneben.
Aber, ich hatte auch schon mal überlegt den Support von Sonos einzuschalten ... das werde ich dann mal probieren.

Gruß Nobby

Hallo Reiner,

kurze Rückmeldung ... im Rahmen der Kommunikation mit Sonos-Support habe ich dann u.a. Sonos komplett aus FHEM entfernt ... die Probleme traten weiterhin auf ...
Jetzt stellt sich heraus, dass der Connect wohl Probleme mit Multicast-Floods hat, die von Telekom Entertain erzeugt werden, aus ähnlichem Grund hatte ich vor längerem den Switch an dem der HMLAN hängt schon durch eine modernere Version mit IGMP-Snooping ersetzt.
Jetzt hängt die Bridge ebenfalls an diesem Switch und die Probleme sind nicht wieder aufgetreten 

Ich warte das jetzt mal noch ein paar Tage ab und werde Sonos im FHEM dann wieder aktivieren ... zusätzlich werde ich auch den anderen Switch in meinem Netz austauschen

Viele Grüße
Norbert