Verbindung zwischen Fhem und Sonos bricht ab

Reinerlein · 14 Februar 2017, 00:21:54

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


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


my @ready = $SONOS_Client_Selector->can_read(0.1);

nach unten verschieben, direkt vor die entsprechende for-Schleife:

Code Auswählen


.
.
# 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 · 14 Februar 2017, 11:22:01

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

    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 · 14 Februar 2017, 18:21:20

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 · 15 Februar 2017, 23:27:15

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

    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 · 16 Februar 2017, 22:43:36

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 · 16 Februar 2017, 23:52:36

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 · 17 Februar 2017, 09:01:18

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 · 17 Februar 2017, 11:08:00

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 · 21 Februar 2017, 18:43:48

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

    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

	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

    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 · 24 Februar 2017, 12:27:33

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

     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

   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

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

schaun wir mal ...

Gruß Nobby

Reinerlein · 24 Februar 2017, 15:05:23

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 · 11 März 2017, 10:49:40

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

   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 · 11 März 2017, 11:50:53

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 · 11 März 2017, 14:43:20

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

Zitat von: Reinerlein am 11 März 2017, 11:50:53
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 · 11 März 2017, 16:10:58

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