SONOS Player Disappeared ... immer und immer wieder

Begonnen von KalleBlomquist, 01 Dezember 2017, 08:48:45

Vorheriges Thema - Nächstes Thema
Drucken
Nach unten Seiten 1 2 3 4 5 6 ... 8
Benutzer-Aktionen

Nobby1805

#45
17 Januar 2018, 16:59:13
Ich habe die Logs bei mir mal eingebaut ... und da sieht es so aus
Code Auswählen
2018.01.17 16:52:23.756 1: SONOS1: Angekommen vor pending...
2018.01.17 16:52:24.756 1: SONOS1: Angekommen vor pending...
2018.01.17 16:52:25.756 1: SONOS1: Angekommen vor pending...
2018.01.17 16:52:25.756 1: SONOS1: workType = refreshProcessAnswer
2018.01.17 16:52:25.756 1: SONOS1: Angekommen nach dequeue...
2018.01.17 16:52:26.756 1: SONOS1: Angekommen vor pending...
2018.01.17 16:52:27.756 1: SONOS1: Angekommen vor pending...
Zwischen den pendings liegt 1 Sekunde ... bau doch das loggen des workTypes auch ein
am Anfnag von Discover_DoQueue 
Code Auswählen
########################################################################################
#
#  SONOS_Discover_DoQueue - Do the working job (command from Fhem -> Sonosplayer)
#
########################################################################################
sub SONOS_Discover_DoQueue($) {
my ($data) = @_;

my $workType = $data->{WorkType};
return if (!defined($workType));

        SONOS_Log undef, 5, "workType = $workType";   ### hier das neue Logging
my $udn = $data->{UDN};

FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

#46
17 Januar 2018, 17:20:34
Hallo zusammen,

Mensch, einen Tag mal richtig arbeiten müssen, und schon komme ich hier nicht mehr hinterher :)

Also im ersten Log habe ich etwas gefunden. Der Thread 1 blockiert bei der Verarbeitung des ContentDirectory-Events (genauer nach dem ersten Cover-URL erzeugen).
Dort müssten eigentlich noch 7 weitere Titel verarbeitet werden. Die Frage ist jetzt, ob an der zweiten Stelle in der Queue etwas besonderes steht (scheint aber ja das normale Pink Floyd - Pulse - Album zu sein :) ), oder etwas anderes Probleme bereitet...
Das Problem ist, Thread 1 ist an dieser Stelle auch der wichtige... er kommt also tatsächlich nicht aus dem handleOnce() wieder raus :)

Setz doch mal bitte zum weiterlaufen lassen mal das Attribut "getQueueListAtNewVersion" am Sonos-Device auf 0 (u.U. auch das Attribut "getListsDirectlyToReadings" auf 0).
Dann unterläßt er erstmal die direkte automatische Verarbeitung... Dann schauen wir mal, wie weit er kommt.

Vielleicht hilft es auch die Cover-Proxy-Funktionalitäten zu aktivieren. Vielleicht kann der Player gerade nicht antworten (auf die Cover-Anfrage), während er gerade ein ContentDirectory-Event an das Modul sendet.
Je nachdem wie Sonos das Implementiert hat, ist das auch Single-Threaded, dann hätten wir gerade eine Thread-Blockade über den Sonos-SubProzess-Thread und dem Sonosplayer :)

Grüße
Reiner

nils_

#47
18 Januar 2018, 09:18:44
Zitat von: Nobby1805 am 17 Januar 2018, 16:32:25
@Nils: den Monk-Artikel kannte ich ... und ich meine Reiner und ich haben den vor ca. 1 Jahr auch diskutiert ... aber geholfen hat das auch nicht :(

hatte ich mir schon gedacht, wollte es nur zur sicherheit mal posten, denn manchmal sieht man den wald vor lauter bäumen nicht :)

schade  :-[
viele Wege in FHEM es gibt!

KalleBlomquist

#48
18 Januar 2018, 09:27:13
Hallo zusammen,

ich habe die Logausgabe in das Modul eingebaut:

ZitatSONOS_Log undef, 5, "workType = $workType";   ### hier das neue Logging

Weiterhin habe ich die von Reiner genannten Attribute im Sonos Modul gesetzt ...
sieht jetzt so aus (Anlage "Sonos_Attribute.JPG").

Bisher scheinbar kein Disconnecten mehr  :)

Anbei das aktuelle LogFile (Anhang "Sonos_SubProcess.log").


Gruß Kalle

Reinerlein

#49
18 Januar 2018, 09:36:38
Hi Kalle,

OK, wenn es jetzt besser wird, dann aktivier doch mal die Cover-Proxy-Funktionalität.
- "generateProxyAlbumArtURLs" auf 1
- "proxyCacheDir" auf ein nur dafür verwendetes Verzeichnis zeigen lassen (Schreibrechte für SubProzess beachten/herstellen)
- "proxyCacheTime" kannst du ruhig auf ein paar Stunden oder einen Tag setzen (vielleicht 86400). Cover ändern sich ja nicht sooo häufig :)

Und dann erstmal nochmal beobachten!

Wenn es immer noch geht, dann mal wieder "getListsDirectlyToReadings" auf 1 setzen, und nochmal schauen...

Grüße
Reiner

KalleBlomquist

#50
18 Januar 2018, 13:29:43
Hi Reiner,
Zitat
- "generateProxyAlbumArtURLs" auf 1
- "proxyCacheDir" auf ein nur dafür verwendetes Verzeichnis zeigen lassen (Schreibrechte für SubProzess beachten/herstellen)
- "proxyCacheTime" kannst du ruhig auf ein paar Stunden oder einen Tag setzen (vielleicht 86400). Cover ändern sich ja nicht sooo häufig :)
Die Attribute habe ich gesetzt, das Cache File wurde auch angelegt (Rechte sollten also passen).

Zitat
Und dann erstmal nochmal beobachten!
OK, das werde ich jetzt erstmal tun ...

Zitat
Wenn es immer noch geht, dann mal wieder "getListsDirectlyToReadings" auf 1 setzen, und nochmal schauen...
Das werde ich dann am WE mal wieder auf "1" setzen, wenn es bis dahin stabil durchläuft.

DANKE und Gruß
Kalle

KalleBlomquist

#51
19 Januar 2018, 10:05:41
Hallo,

es lief nun die ganze Zeit ohne Aussetzer und heute morgen habe ich dann die beiden Attribute wieder auf "1" gesetzt:

- getListsDirectlyToReadings
- getQueueListAtNewVersion

Bisher (3h) noch kein Disconnect   ;)

Gruß
Kalle

Nobby1805

#52
19 Januar 2018, 11:08:20
Hast du FHEM danach neu gestartet oder "nur" im laufenden Betrieb geändert?
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

KalleBlomquist

#53
19 Januar 2018, 15:06:53
FHEM hatte ich danach neu gestartet ...

Nun nach 8h immer noch stabil :D
Liegt es vielleicht daran, dass ich die Proxy-Cache-Einstellungen aktiviert habe ?
Es müsste doch eigentlich wieder ein Disconnect passieren, wir haben doch außer an den Attributen nichts geändert ?!

Reinerlein

#54
19 Januar 2018, 15:27:51
Hi Kalle,

genau... sehr lange Rumprobier-und Test-Schleife... kurze Lösung :)

Ich kann mal versuchen das Problem bei mir nachzustellen, das wird aber etwas dauern. Ich denke fürs erste ist das eine praktikable Lösung, die auch andere mit dem Problem mal prüfen können...

Grüße
Reiner

KalleBlomquist

#55
22 Januar 2018, 08:35:09 Letzte Bearbeitung: 22 Januar 2018, 13:40:43 von KalleBlomquist
Hi,

so nun ist es einige Zeit durchgelaufen und seit dem Wochenende disconnecten die Player wieder. Zudem kann ich sie nicht mehr über FHEM ansteuern.
Ich hänge das Log mal an.

Sollte ich jetzt die Attribute wieder auf "0" setzen und dann erstmal so lassen ?

- getListsDirectlyToReadings
- getQueueListAtNewVersion

Gruß Kalle

Edit:
Wenn ich das Attribut "getListsDirectlyToReadings" auf "0" setze und FHEM neu starte, dann kann ich die Player wieder ansteuern.

Bastel Bastel

#56
22 Januar 2018, 17:20:25
Moin, moin!
Heute Nacht habe ich seit einer gefühlten Ewigkeit mein FHEM geupdated und seit dem hat sich die Verbindung zum Sonos auch verabschiedet.
War leider etwas voreilig und habe zu allererst die automatisch angelegten Player gelöscht, danach das Modul angehalten und gelöscht.

Jetzt habe ich per define Sonos SONOS neu angelegt, bekomme aber keine Player mehr gelistet :'(

Kann ich das manuell anstoßen?

Gruß und Dank Karsten
FHEM auf Mac Mini mit i7, Unifi APAC und Controller, 2 Siemens Logo 8er, 1 Wago 830er, diverse Ufos über Wifilight, diverse Homematicdevices, Harmony Hub, Sonos

Reinerlein

#57
22 Januar 2018, 18:00:10
Hi Karsten,

das passiert automatisch. Ansonsten kannst du es natürlich mit "set Sonos RescanNetwork" versuchen...
Du müsstest mal ins Log schauen, um rauszufinden, was genau schief geht...

@Kalle: Das Problem passiert wieder an derselben Stelle. Ich muss mich da erstmal wieder reinvertiefen :)

Grüße
Reiner

Bastel Bastel

#58
23 Januar 2018, 10:03:40
Moin Reiner,

im Log wirft er mir folgendes aus:

Code Auswählen

2018.01.22 15:32:23 3: SONOS0: Disconnecting client and shutdown server...
2018.01.22 15:32:23 3: SONOS0: Trying to kill IsAlive_Thread...
2018.01.22 15:32:23 3: SONOS0: Trying to kill PlayerRestore_Thread...
2018.01.22 15:32:23 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...
Perl exited with active threads:
   0 running and unjoined
   1 finished and unjoined
   1 running and detached
2018.01.22 15:32:56 1: PERL WARNING: 400-URL-Absolute-Error! Location: "192.168.170.48", Content: "400 URL must be absolute
" at ./FHEM/98_DLNARenderer.pm line 249.
2018.01.22 15:32:56 1: PERL WARNING: Loading device description failed with error: 400 URL must be absolute (Location: 192.168.170.48) at ./FHEM/98_DLNARenderer.pm line 249.
2018.01.22 15:34:06 1: SONOS0: Modify Device: Sonos
2018.01.22 15:34:07 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2018.01.22 15:34:08 1: SONOS0: ./FHEM/00_SONOS.pm is listening to Port 4711
2018.01.22 15:34:15 3: Opening Sonos device localhost:4711
2018.01.22 15:34:15 3: SONOS0: Connection accepted from localhost:50693
2018.01.22 15:34:15 3: Sonos device opened
2018.01.22 15:34:16 3: SONOS1: UPnP-Thread gestartet.
2018.01.22 15:34:16 2: SONOS1: Error during UPnP-Handling: Error creating SSDP multicast listen socket: Address already in use
at ./FHEM/00_SONOS.pm line 2395 thread 1.
at ./FHEM/00_SONOS.pm line 2395 thread 1.

2018.01.22 15:34:16 3: SONOS1: UPnP-Thread wurde beendet.
2018.01.22 15:34:16 1: SONOS2: IsAlive-Thread gestartet. Warte 120 Sekunden und pruefe dann alle 30 Sekunden...
2018.01.22 15:34:16 1: SONOS3: Restore-Thread gestartet. Warte auf Arbeit...
Thread 3 terminated abnormally: Error creating SSDP multicast listen socket: Address already in use
at ./FHEM/00_SONOS.pm line 5006 thread 3.
at ./FHEM/00_SONOS.pm line 5006 thread 3.


Kann es sein das SONOS und der DLNARenderer sich beißen?

Gruß Karsten
FHEM auf Mac Mini mit i7, Unifi APAC und Controller, 2 Siemens Logo 8er, 1 Wago 830er, diverse Ufos über Wifilight, diverse Homematicdevices, Harmony Hub, Sonos

Bastel Bastel

#59
23 Januar 2018, 10:14:18
Und hier nochmal mit SONOS auf verbose 4, einmal deaktiviert, wieder aktiviert und NetworkRescan durchgeführt.

Code Auswählen
2018.01.23 10:04:42 3: SONOS0: Disconnecting client and shutdown server...
2018.01.23 10:04:42 3: SONOS0: Trying to kill IsAlive_Thread...
2018.01.23 10:04:42 3: SONOS0: Trying to kill PlayerRestore_Thread...
2018.01.23 10:04:42 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...
Perl exited with active threads:
0 running and unjoined
1 finished and unjoined
1 running and detached
2018.01.23 10:04:48 1: RMDIR: ./restoreDir/2017-08-31
2018.01.23 10:04:55 3: ModbusTCPServer_Timeout, request: SimpleWrite [30 00 00 00 00 06] 00 01 30 00 00 08
2018.01.23 10:08:40 5: SONOS0: Neu-Enabled
2018.01.23 10:08:40 5: SONOS0: Call AttributeFn: Start SubProcess...
2018.01.23 10:08:41 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2018.01.23 10:08:43 1: SONOS0: ./FHEM/00_SONOS.pm is listening to Port 4711
2018.01.23 10:08:49 3: Opening Sonos device localhost:4711
2018.01.23 10:08:49 3: SONOS0: Connection accepted from localhost:55940
2018.01.23 10:08:49 5: SW: Establish connection

2018.01.23 10:08:49 3: Sonos device opened
2018.01.23 10:08:50 5: SONOS0: SetData:Sonos:5:-:syn:::0::
2018.01.23 10:08:50 5: SW: SetData:Sonos:5:-:syn:::0::

2018.01.23 10:08:50 5: SONOS0: Received: 'SetData:Sonos:5:-:syn:::0::'
2018.01.23 10:08:50 5: SONOS0: SetValues:SONOS:INTERVAL=30|NAME=Sonos|disable=0
2018.01.23 10:08:50 5: SW: SetValues:SONOS:INTERVAL=30|NAME=Sonos|disable=0

2018.01.23 10:08:50 5: SONOS0: Received: 'SetValues:SONOS:INTERVAL=30|NAME=Sonos|disable=0'
2018.01.23 10:08:50 5: SW: StartThread

2018.01.23 10:08:50 5: SONOS0: Received: 'StartThread'
2018.01.23 10:08:50 3: SONOS1: UPnP-Thread gestartet.
2018.01.23 10:08:50 4: SONOS1: SONOS_Client_Data_Retreive(SONOS, attr, bookmarkSaveDir, .) -> DEFAULT
2018.01.23 10:08:50 4: SONOS1: Calling SONOS_LoadBookmarkValues("undef", "undef") ~ SaveDir: "."
2018.01.23 10:08:50 2: SONOS1: Error during UPnP-Handling: Error creating SSDP multicast listen socket: Address already in use
at ./FHEM/00_SONOS.pm line 2395 thread 1.
at ./FHEM/00_SONOS.pm line 2395 thread 1.

2018.01.23 10:08:50 4: SONOS1: SONOS_Client_Data_Retreive(SONOS, attr, bookmarkSaveDir, .) -> DEFAULT
2018.01.23 10:08:50 4: SONOS1: Calling SONOS_SaveBookmarkValues("undef", "undef") ~ SaveDir: "."
2018.01.23 10:08:50 3: SONOS1: UPnP-Thread wurde beendet.
2018.01.23 10:08:50 4: SONOS2: SONOS_Client_Data_Retreive(SONOS, def, INTERVAL, 0) -> 30
2018.01.23 10:08:50 1: SONOS2: IsAlive-Thread gestartet. Warte 120 Sekunden und pruefe dann alle 30 Sekunden...
2018.01.23 10:08:50 1: SONOS3: Restore-Thread gestartet. Warte auf Arbeit...
Thread 3 terminated abnormally: Error creating SSDP multicast listen socket: Address already in use
at ./FHEM/00_SONOS.pm line 5006 thread 3.
at ./FHEM/00_SONOS.pm line 5006 thread 3.
2018.01.23 10:09:00 5: SW: DoWork:SONOS:rescanNetwork:

2018.01.23 10:09:00 5: SONOS0: Received: 'DoWork:SONOS:rescanNetwork:'


Was übersehe ich?
FHEM auf Mac Mini mit i7, Unifi APAC und Controller, 2 Siemens Logo 8er, 1 Wago 830er, diverse Ufos über Wifilight, diverse Homematicdevices, Harmony Hub, Sonos
Drucken
Nach oben Seiten 1 2 3 4 5 6 ... 8
Benutzer-Aktionen