Sonos steuern

fhem-challenge · 05 Juli 2017, 08:55:20

Zitat von: Wuppi68 am 04 Juli 2017, 11:35:09
bei mir habe ich auch (nur noch sporadisch) das Problem mit den disappearten Player ...

meine Vermutung liegt bei dem Linux unten drunter

Meistens verschwinden diese nachdem shared libraries ausgetauscht worden sind (apt upgrade). Ein normaler Boot des Computers hilft dann bestens

Viel Erfolg

Wuppi

Ich vermute bei den "disapered" eher zu geringe Timeout Einstellungen in 00_SONOS.pm. Ich habe nun reproduzierbar auch den Effekt, dass in FHEM bei einem "backup", danach die SONOS alle disapered sind. Also auch hier ggf. Abhängigkeiten mit Timeouts.

Frage an Reinerlein:

Gibt es eine Möglichkeit diese Timeouts zu erhöhen ?

Viele Grüße!

Andreas

Reinerlein · 05 Juli 2017, 09:36:41

Hi Andreas,

Das Problem ist, herauszufinden, warum die Player auf disappeared gehen. Bislang gibt es leider keine Logs dazu...

Es gibt dafür mehrere Prüfungen:
1. Der Teil, der prüft, ob der SubProzess überhaupt noch erreichbar ist. Wenn dieser einen nicht mehr erreichbaren Prozess erkennt (momentan: dreimal hintereinander nicht erreichbar gewesen), dann wird versucht den SubProzess neuzustarten. Dabei werden erstmal *alle* Player auf disappeared gesetzt.

2. Der Teil, der prüft, ob ein einzelner Player noch erreichbar ist. Wenn der Player dreimal nicht erreichbar war, dann wird *dieser* Player auf disappeared gesetzt.

in beiden Fällen ist das der Wert, den man hinter der Definition von <Host:Port> angibt (das Internal INTERVAL). Die Timeouts sind also identisch.
In allen Fällen wird im Log ausgegeben, wenn ein Player oder der ganze SubProzess nicht mehr gefunden werden konnte. Das kann man also nachlesen. Auch, wenn ein Player mal kurz nicht erreichbar war, und es dann wieder ist, kann man das dann im Log erkennen...

Grüße
Reiner

fhem-challenge · 05 Juli 2017, 10:10:17

Zitat von: Reinerlein am 05 Juli 2017, 09:36:41
Hi Andreas,

Das Problem ist, herauszufinden, warum die Player auf disappeared gehen. Bislang gibt es leider keine Logs dazu...

Es gibt dafür mehrere Prüfungen:
1. Der Teil, der prüft, ob der SubProzess überhaupt noch erreichbar ist. Wenn dieser einen nicht mehr erreichbaren Prozess erkennt (momentan: dreimal hintereinander nicht erreichbar gewesen), dann wird versucht den SubProzess neuzustarten. Dabei werden erstmal *alle* Player auf disappeared gesetzt.

2. Der Teil, der prüft, ob ein einzelner Player noch erreichbar ist. Wenn der Player dreimal nicht erreichbar war, dann wird *dieser* Player auf disappeared gesetzt.

in beiden Fällen ist das der Wert, den man hinter der Definition von <Host:Port> angibt (das Internal INTERVAL). Die Timeouts sind also identisch.
In allen Fällen wird im Log ausgegeben, wenn ein Player oder der ganze SubProzess nicht mehr gefunden werden konnte. Das kann man also nachlesen. Auch, wenn ein Player mal kurz nicht erreichbar war, und es dann wieder ist, kann man das dann im Log erkennen...

Grüße
Reiner

Hallo Reinerlein,

danke für die Info!. Ja , das habe ich noch überlesen. Ich werde mal ein Timeout von 60 oder mehr probieren.

Ich hatte das log mal gepostet (vor ein paar Tagen).

Code Auswählen

2017.07.04 03:51:52 2: SONOS0: LastProcessAnswer way too old (Lastanswer: 2017-07-04 03:49:36)... try to restart the process and connection...
2017.07.04 03:51:54 3: SONOS0: Disconnecting client and shutdown server...
2017.07.04 03:51:54 3: SONOS0: Trying to kill Sonos_Thread...
2017.07.04 03:51:54 3: SONOS0: Trying to kill IsAlive_Thread...
2017.07.04 03:51:54 3: SONOS0: Trying to kill PlayerRestore_Thread...
2017.07.04 03:51:54 0: SONOS0: Das Lauschen auf der Schnittstelle wurde beendet. Prozess endet nun auch...
2017.07.04 03:52:22 1: SONOS0: Kein UPnP-Server gefunden... Starte selber einen und warte 8 Sekunde(n) darauf...
2017.07.04 03:52:24 1: SONOS0: /opt/fhem/FHEM/00_SONOS.pm is listening to Port 4711
2017.07.04 03:52:30 3: Opening Sonos device localhost:4711
2017.07.04 03:52:30 3: SONOS0: Connection accepted from localhost:33879
2017.07.04 03:52:30 3: Sonos device opened

Danach sind alle Player "disapered". Aus irgend einem Grund werden die Player nach "SONOS0: Trying to kill Sonos_Thread" nicht mehr erreicht. Ich versuche mal ein Interval von >= 60.

Viele Grüße!

Andreas

Reinerlein · 05 Juli 2017, 10:48:29

Hi Andreas,

und versucbh auf jeden Fall die neue Version. Ich habe noch etwas an den Stellschrauben gedreht, in diesem Fall wird ab sofort eine LastProcessAnswer von 4*INTERVAL erst berücksichtigt.
Außerdem habe ich noch ein bißchen am Restart korrigiert. Das sollte besser abgearbeitet werden.

Vielleicht ist das dann tatsächlich schon alles... Man darf ja mal hoffen

Grüße
Reiner

fhem-challenge · 05 Juli 2017, 11:07:16

Zitat von: Reinerlein am 05 Juli 2017, 10:48:29
Hi Andreas,

und versucbh auf jeden Fall die neue Version. Ich habe noch etwas an den Stellschrauben gedreht, in diesem Fall wird ab sofort eine LastProcessAnswer von 4*INTERVAL erst berücksichtigt.
Außerdem habe ich noch ein bißchen am Restart korrigiert. Das sollte besser abgearbeitet werden.

Vielleicht ist das dann tatsächlich schon alles... Man darf ja mal hoffen

Grüße
Reiner

Hi Reiner,

ja, ich verwende die neueste Version. Habe nun:

define Sonos SONOS localhost:4711 180 20 10

... mit deutlich erhöhten Werten verwendet und warte mal ab, ob es läuft.

Vielen Dank!

Gruss

Andreas

dantist · 05 Juli 2017, 11:38:45

Hi Reinerlein,

hast du vielleicht eine Idee zu meinem Problem und wie ich diesen Fehler debuggen könnte, der die ganze FHEM-Installation zum Stillstand bringt?

Danke & Gruß
Daniel

Reinerlein · 05 Juli 2017, 13:25:36

Hi Daniel,

ohne Log ist das immer schwierig. Versuch doch mal vor dem Fhem-Start den verbose-Wert am Sonos-Device (oder wenn das nicht geht am global-Device) auf 5 zu setzen. Das kannst du ja auch direkt in der Config-Datei machen...

Das wird zwar eine Menge Logs erzeugen, aber mit etwas Glück ist dann auch das eigentliche Problem dabei...

Grüße
Reiner

Fixel2012 · 05 Juli 2017, 17:04:14

Muss mich leider auch nochmal melden, Fhem ist so eben wieder abgeschmiert.

Folgende Zeilen Finden sich im Log auf (gekürzt):

Code Auswählen

2017.07.05 16:46:23 1: PERL WARNING: Deep recursion on subroutine "main::SONOS_getSonosPlayerByUDN" at ./FHEM/00_SONOS.pm line 9870.
2017.07.05 16:46:23 1: stacktrace:
2017.07.05 16:46:23 1:     main::__ANON__                      called by ./FHEM/00_SONOS.pm (9870)
2017.07.05 16:46:23 1:     main::SONOS_getSonosPlayerByUDN     called by ./FHEM/00_SONOS.pm (9870)
2017.07.05 16:46:23 1:     main::SONOS_Log                     called by ./FHEM/00_SONOS.pm (9619)

mit einem anschließendem

Code Auswählen

2017.07.05 16:46:23 1:     main::SONOS_Log                     called by ./FHEM/00_SONOS.pm (9619)
Out of memory!

hat sich Fhem bzw der ganze Raspi dann verabschiedet

Lässt sich damit was anfangen?

Gruß Fixel

Reinerlein · 05 Juli 2017, 17:21:55

Hi Fixel,

verwendest du schon die neueste Version von Heute?
Ich hatte da etwas am Log-Mechanismus angepasst....

Grüße
Reiner

Fixel2012 · 05 Juli 2017, 18:18:26

Hi, danke für deine Antwort.

Zitat von: Reinerlein am 05 Juli 2017, 17:21:55
Hi Fixel,

verwendest du schon die neueste Version von Heute?
Ich hatte da etwas am Log-Mechanismus angepasst....

Grüße
Reiner

Nein, ich wollte noch warten, bis es im SVN verfügbar ist.

Vielleicht kommt die Fehlermeldungen Morgen nochmal, wer weiß

Grüße und trotzdem Danke,

Fixel

dantist · 05 Juli 2017, 20:58:30

Zitat von: Reinerlein am 05 Juli 2017, 13:25:36
Hi Daniel,

ohne Log ist das immer schwierig. Versuch doch mal vor dem Fhem-Start den verbose-Wert am Sonos-Device (oder wenn das nicht geht am global-Device) auf 5 zu setzen. Das kannst du ja auch direkt in der Config-Datei machen...

Das wird zwar eine Menge Logs erzeugen, aber mit etwas Glück ist dann auch das eigentliche Problem dabei...

Grüße
Reiner

Hallo Reinerlein,

ich habe zur Sicherheit die neue Version aus dem SVN gezogen, global verbose auf 5 gestellt und ein SONOS-Device definiert. FHEM leitet zur Device-Seite weiter, der Status dort ist "waiting for subprocess", danach geht nichts mehr. Anbei das Log vom Absenden des Befehls bis zum Freeze:

Code Auswählen

2017.07.05 20:52:33 4: Connection accepted from WEB_192.168.108.51_56632
2017.07.05 20:52:33 4: WEB_192.168.108.51_56632 POST /fhem&fw_id=230&room=00+-+%C3%9Cbersicht&cmd=define+Sonos+SONOS+localhost%3A4711+30; BUFLEN:0
2017.07.05 20:52:33 5: Cmd: >define Sonos SONOS localhost:4711 30<
2017.07.05 20:52:33 5: Loading ./FHEM/00_SONOS.pm
2017.07.05 20:52:34 5: Starting notify loop for global, 1 event(s), first is DEFINED Sonos
2017.07.05 20:52:35 5: createNotifyHash
2017.07.05 20:52:35 5: End notify loop for global
2017.07.05 20:52:35 4: WEB_192.168.108.51_56632 GET /fhem?detail=Sonos&fw_id=230; BUFLEN:0
2017.07.05 20:52:35 4: name: /fhem?detail=Sonos&fw_id=230 / RL:3566 / text/html; charset=UTF-8 / Content-Encoding: gzip
 / 
2017.07.05 20:52:35 4: Connection closed for WEB_192.168.108.51_56631: EOF
2017.07.05 20:52:35 4: WEB_192.168.108.51_56632 GET /fhem?cmd={ReadingsVal(%22Sonos%22,%22DisableBookmark%22,%22%22)}&XHR=1; BUFLEN:0
2017.07.05 20:52:35 5: Cmd: >{ReadingsVal("Sonos","DisableBookmark","")}<
2017.07.05 20:52:35 4: name: /fhem?cmd={ReadingsVal(%22Sonos%22,%22DisableBookmark%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / 
2017.07.05 20:52:35 4: Connection accepted from WEB_192.168.108.51_56633
2017.07.05 20:52:35 4: WEB_192.168.108.51_56633 GET /fhem?cmd={AttrVal(%22Sonos%22,%22room%22,%22%22)}&XHR=1; BUFLEN:0
2017.07.05 20:52:35 5: Cmd: >{AttrVal("Sonos","room","")}<
2017.07.05 20:52:35 4: name: /fhem?cmd={AttrVal(%22Sonos%22,%22room%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / 
2017.07.05 20:52:35 5: Starting notify loop for BewegungsmelderFlur, 3 event(s), first is motion: off
2017.07.05 20:52:35 5: End notify loop for BewegungsmelderFlur
2017.07.05 20:52:35 4: WEB_192.168.108.51_56633 GET /fhem?XHR=1&inform=type=status;filter=Sonos;since=1499280754;fmt=JSON&fw_id=230&timestamp=1499280755501; BUFLEN:0

Anschließend muss ich mit einem "sudo /etc/init.d/fhem stop" und "sudo /etc/init.d/fhem start" FHEM wieder zum Leben erwecken.

Reinerlein · 05 Juli 2017, 21:22:17

Hi Daniel,

das ist echt komisch..
Wieso versucht er das Reading "DisableBookmark" zu lesen, oder das Attribut "room"?
Vor Allem als Web-Command abgesetzt...

Ist da vielleicht noch ein TabletUI oder ähnliches dran? Aber selbst das sollte gehen...

Ich bin echt überfragt... Wie sieht das denn in einem htop auf Systemebene aus? Wird der SubProzess denn noch erzeugt? Werden auch noch dessen drei SubThreads erzeugt?
Das Log endet dafür eigentlich zu früh, da der SubProzess ja erst nach 8 Sekunden angestartet wird...
Aber es müssten überhaupt mal Logausgaben des Moduls kommen... da kommt ja gar nichts... So, als wäre das Modul gar nicht geladen worden...
Gibt es vielleicht im Systemlog der Maschine einen gemeldeten Perl Absturz?

Sorry für das gestocher, aber da habe ich echt gerade keine direkt zielführende Idee...

Grüße
Reiner

dantist · 05 Juli 2017, 22:01:51

Hi Reinerlein,

kannst du mir kurz sagen, wie ich an diese Infos (htop, Subprozesse, etc.) rankomme? Ich bin kein Linux-Profi, werde aber gerne alles machen, das bei der Fehlersuche hilft. Ohne Sonos macht FHEM nämlich nur halb so viel Spaß..

Eine TabletUI oder andere Dinge, die unaufgefordert Web-Requests absetzen, laufen übrigens nicht.

Danke & Gruß
Daniel

Reinerlein · 05 Juli 2017, 22:29:53

Hi Daniel,

ich weiß ja nicht, auf was für einem System dein Fhem läuft. Ich gehe mal von einem Raspberry Pi mit Debian aus.

"htop" ist ein Prozessanzeige-Tool für die Linux Konsole. Einfach mal auf der Konsole per ssh anmelden und htop eingeben.

Wenn da eine Fehlermeldung kommt, dass es nicht installiert sei, kannst du es einfach mit

Code Auswählen


sudo apt-get install htop

installieren.

Wenn htop läuft, kannst du mit F4 und der anschließenden Angabe von "perl" die Ausgabe auf Perl-Prozesse hin filtern.

Im Anhang mal ein Screenshot von mir. Dort siehst du, dass es einen Perl-Prozess mit dem Parametr fhem.pl gibt, und vier Stück mit dem Parameter 00_SONOS.pm.
Das wäre der Normalzustand

Aber wie gesagt, das wird vermutlich darauf hinauslaufen, dass bei dir nur der Fhem-Prozess läuft...

Grüße
Reiner

dantist · 06 Juli 2017, 08:58:17

Danke Reiner,

habe ich getestet, und wie du vermutet hast, wird nur fhem-Prozess angezeigt. Ich habe danach aufgegeben, ein altes Images meiner RPi SD-Karte eingespielt und ein aktuelles Backup von FHEM installiert. Was soll ich sagen - es läuft wieder alles wie gewohnt. Weiß der Geier, was das gewesen sein könnte. Wenn FHEM jetzt noch ein "apt-get upgrade" übersteht, ist alles gut

Danke Dir für deine Hilfe!

Gruß
Daniel