Verbindung zwischen Fhem und Sonos bricht ab

[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