Sonos Play1 soll TV-Sound abspielen und ggf Rückmeldung

[Reinerlein]

Hi Claudiu,

damit hast du mich natürlich auf eine Idee gebracht. Das Sonos-Modul kann ja auch selber auf ein "rereadcfg"-Event reagieren... und tut es jetzt auch
Damals gab es dieses "Event" einfach noch nicht...

Wenn es ein Rereadcfg mitbekommt, wird die Verbindung zm Subprozess sauber getrennt, und kann danach auch sauber wieder aufgenommen werden. Wenn es keine anderweitigen Störungen gab, läuft es danach normal weiter (ausser, das sich in der Log-Ausgabe des Subprozesses die Threadnummern erhöhen)...

Leider ist dein Notify jetzt für diesen Fall nicht mehr soo wichtig
Aber die Idee war dagegen sehr wichtig, danke nochmal.

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

super dass ich dir damit eine kleine Idee liefern konnte 

Nur leider funktioniert das bei mir nicht 
Nach einem rereadcfg erhalte ich das hier:

fhem.log:

Code Auswählen Erweitern

...
2014.11.19 12:57:01.418 1: Including ./FHEM/sonos.cfg
2014.11.19 12:57:01.919 3: Opening Sonos device localhost:4711
2014.11.19 12:57:01.919 3: Sonos device opened
2014.11.19 12:57:01.923 1: Including ./FHEM/TEST.cfg
2014.11.19 12:57:01.929 1: Including ./log/fhem.save
2014.11.19 12:57:01.998 0: SONOS0: Detecting rereadcfg. Restart Sonos-Subprocess...
2014.11.19 12:57:03.000 3: Opening Sonos device localhost:4711
2014.11.19 12:57:03.001 3: Sonos device opened
...


Und das hier im stdout:

Code Auswählen Erweitern

2014.11.19 12:57:00 3: SONOS0: Disconnecting client...
2014.11.19 12:57:00 3: SONOS0: Trying to kill Sonos_Thread...
2014.11.19 12:57:00 3: SONOS0: Trying to kill PlayerRestore_Thread...
2014.11.19 12:57:00 1: SONOS2: Restore-Thread wurde beendet.
2014.11.19 12:57:01 3: SONOS1: Controlpoint-Listener wurde beendet.
2014.11.19 12:57:01 2: SONOS1: Error during UPnP-Handling:
2014.11.19 12:57:01 3: SONOS1: UPnP-Thread wurde beendet.
2014.11.19 12:57:02 1: SONOS0: Connection accepted from localhost:37296
2014.11.19 12:57:02 1: SONOS0: Connection accepted from localhost:37297
2014.11.19 12:57:02 3: SONOS0: Disconnecting client...
2014.11.19 12:57:04 1: SONOS0: Connection accepted from localhost:37298
2014.11.19 12:57:04 3: SONOS0: Disconnecting client...
2014.11.19 12:57:06 1: SONOS0: Connection accepted from localhost:37299
2014.11.19 12:57:06 3: SONOS0: Disconnecting client...
2014.11.19 12:58:04 1: SONOS0: Connection accepted from localhost:37300
2014.11.19 12:58:34 1: SONOS0: Connection accepted from localhost:37301
2014.11.19 12:59:04 1: SONOS0: Connection accepted from localhost:37302
2014.11.19 12:59:34 1: SONOS0: Connection accepted from localhost:37303
2014.11.19 13:00:04 1: SONOS0: Connection accepted from localhost:37304
2014.11.19 13:00:34 1: SONOS0: Connection accepted from localhost:37305
2014.11.19 13:01:04 1: SONOS0: Connection accepted from localhost:37306
2014.11.19 13:01:34 1: SONOS0: Connection accepted from localhost:37307
2014.11.19 13:02:04 1: SONOS0: Connection accepted from localhost:37308
2014.11.19 13:02:34 1: SONOS0: Connection accepted from localhost:37311
2014.11.19 13:03:04 1: SONOS0: Connection accepted from localhost:37312
2014.11.19 13:03:34 1: SONOS0: Connection accepted from localhost:37313
2014.11.19 13:04:04 1: SONOS0: Connection accepted from localhost:37314
2014.11.19 13:04:34 1: SONOS0: Connection accepted from localhost:37315
2014.11.19 13:05:04 1: SONOS0: Connection accepted from localhost:37316
2014.11.19 13:05:34 1: SONOS0: Connection accepted from localhost:37317
2014.11.19 13:06:04 1: SONOS0: Connection accepted from localhost:37318
2014.11.19 13:06:34 1: SONOS0: Connection accepted from localhost:37319
2014.11.19 13:07:04 1: SONOS0: Connection accepted from localhost:37320
2014.11.19 13:07:34 1: SONOS0: Connection accepted from localhost:37321
2014.11.19 13:08:04 1: SONOS0: Connection accepted from localhost:37322
2014.11.19 13:08:34 1: SONOS0: Connection accepted from localhost:37323
2014.11.19 13:09:04 1: SONOS0: Connection accepted from localhost:37324


Nachdem ich den Sonos-Prozess abschieße gehts dann wieder, erhalte aber obwohl es funktioniert weiterhin diese Meldungen im stdout (Nach receiving der ganzen Events):

Code Auswählen Erweitern

2014.11.19 13:16:13 1: SONOS0: Connection accepted from localhost:37407
2014.11.19 13:16:43 1: SONOS0: Connection accepted from localhost:37408
2014.11.19 13:17:13 1: SONOS0: Connection accepted from localhost:37409

Hast du vll. noch eine Idee woran es jetzt liegen könnte?

Danke und Gruß Claudiu

[Reinerlein]

Hi Claudiu,

also die Sache mit den "Connection accepted"-Meldungen ist gerade normal. Ich bin gerade dabei ein Feature einzubauen, welches "verschwundene" oder nicht mehr reagierende Subprozesse aus Sicht von Fhem erkennen soll.
Dazu baue ich in Intervallen eine Verbindung auf, frage etwas ab, und werte das Ergebnis aus. Auf Subprozess-Seite landet dann genau diese Verbindungsmeldung im Log.
Das ist noch nicht ganz fertig, geht aber schon mal in die gewünschte Richtung...

Zu dem rereadcfg-Problem: Schade
Bei mir sieht das gut aus. Aber irgendwie scheint dein System ja gerne anders zu reagieren (siehe Verbose-Problematik). Da muss ich also noch mal ran...

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

OK, gib bescheid sobald du was zum testen für mich hast 

Ich (wir) haben die Sonos-Dev (von vorhin) bei einem Kollegen auf seinem Raspberry ausprobiert, hier hat es funktioniert.
Er erhält allerdings auch anschließend dauerhaft die Connection accepted messages.

Habe gesehen du hast wieder ein Update rausgebracht.
Leider wieder keine Funktion bei mir, sondern das Problem das der UPnP Thread irgendein error bringt nach einem rereadcfg:
Ich habe vorsichtshalber auch die Waittime mal wieder auf 8 gesetzt, leider ohne Erfolg.
Aber ist zumindest noch kompatibel zu meinem Notify

Code Auswählen Erweitern

2014.11.19 18:02:50 3: SONOS0: Disconnecting client...
2014.11.19 18:02:50 3: SONOS0: Trying to kill Sonos_Thread...
2014.11.19 18:02:50 3: SONOS0: Trying to kill PlayerRestore_Thread...
2014.11.19 18:02:50 1: SONOS2: Restore-Thread wurde beendet.
2014.11.19 18:02:51 3: SONOS1: Controlpoint-Listener wurde beendet.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
Odd number of elements in hash assignment at /usr/share/perl5/IO/Socket/IP.pm line 352, <$client> line 6.
2014.11.19 18:02:51 2: SONOS1: Error during UPnP-Handling:
2014.11.19 18:02:51 3: SONOS1: UPnP-Thread wurde beendet.
2014.11.19 18:02:52 1: SONOS0: Connection accepted from localhost:38633
2014.11.19 18:02:52 3: SONOS0: Disconnecting client...
2014.11.19 18:02:54 1: SONOS0: Connection accepted from localhost:38634
2014.11.19 18:02:54 1: SONOS0: Connection accepted from localhost:38635
2014.11.19 18:02:54 3: SONOS0: Disconnecting client...
2014.11.19 18:02:56 1: SONOS0: Connection accepted from localhost:38636
2014.11.19 18:02:56 3: SONOS0: Disconnecting client...
2014.11.19 18:03:56 1: SONOS0: Connection accepted from localhost:38637



Danke und Gruß Claudiu

[Reinerlein]

Hi Claudiu,

ich habe noch eine Kleingkeit angepasst. Irgendwie komme ich dem Problem auf deiner Maschine aber nicht wirklich näher...
Die Kommunikation sieht eigentlich recht gut aus. Eigentlich sollte da auch nix verwirrendes für irgendwelche Plattfomen dran sein...

Kannst du noch mal kurz einen Test machen?

Danke schon mal...

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

was auch immer du angepasst hast, diese Kleinigkeit scheints ausgemacht zu haben!

Jedenfalls funktioniert es jetzt einwandfrei, das Modul "erholt" sich selbstständig nach einem rereadcfg!

Auch die logs sehen in meinen Augen OK aus..
Im Anhang mal das fhem-log + stdout mit allem nach dem rereadcfg.


Danke für deine Mühe!, glaub dieses feature/fix wird so einigen freuen  (hatte man ja doch öfter was über dieses Problem gelesen).


Dass er das hier immer noch bringt ist gewollt, oder?

Code Auswählen Erweitern


2014.11.20 00:52:45 1: SONOS0: Connection accepted from localhost:41049
2014.11.20 00:53:15 1: SONOS0: Connection accepted from localhost:41050
2014.11.20 00:53:45 1: SONOS0: Connection accepted from localhost:41051
Da ja rein rechnerisch Port 65.535 nach knappen 9 Tagen erreicht wird, was passiert dann?


Gruß Claudiu

[Reinerlein]

Hi Claudiu,

schön, das es jetzt geht

Kurze Erklärung:
Der Subprozess meldet sich mit einer Begrüßung. Diesen String hatte ich im Fhem-Modul aber nie weggelesen. In deiner Perl-Implementierung scheinen ihn die nicht abgeholten Daten gestört zu haben...

Zu der Portnummer: Die wird ja vom Betriebsystem zufällig ausgesucht, und nach dem Versuch sauber wieder freigegeben. Das ganze geht also irgendwann woanders weiter.
Mich wundert sowieso, dass das so monoton aufsteigend ist. Da zerbrechen sich viele Sicherheitsexperten den Kopf darüber, dass genau das ein Problem sein könnte, und trotzdem ist es noch so implementiert...
Naja, soll uns egal sein. Das entscheidet das Betriebssystem

Grüße
Reinerlein

[yetiman]

Hi Reinerlein,

seit dem letzten Dev Update schnappt sich das Sonos Modul die komplette CPU von meinem RaPi (

Code Auswählen Erweitern

fhem      2405 10.5  8.4  43456 37676 pts/0    R    09:28   0:44 perl fhem.pl fhem.cfg
fhem      2411 87.4  6.3  49812 28392 pts/0    Rl   09:29   6:00 perl FHEM/00_SONOS.pm 4711 3
root      2471  0.0  0.2   4460  1136 pts/0    R+   09:35   0:00 ps aux


Ingo

[Reinerlein]

Hi Ingo,

Himmel, du hast recht. Da habe ich gar nicht drauf geachtet
Ich schaue mir das an, danke für den Hinweis.

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

danke für den Hinweis worans lag.
Das mit den Ports klingt ja dann ok, sah nur echt komisch aus weils so sauber raufgezählt wird 

Zu Ingo seinem Problem, das liegt nicht am Raspi, wenn man dem Prozess einige Ghz mehr gibt verschlingt er diese auch komplett merke ich grad 
Mir ist aber aufgefallen dass dies nicht kontinuirlich auftritt, sondern ich denke immer passend zum eingestellten Intervall, und sich anschließend wieder normalisiert.

Gruß Claudiu

[Reinerlein]

Hi Claudiu,

ich bin da gerade dran... ich hatte heute z.B. auch das Problem, dass mein Fhem einfach aus war. Der Prozess war sang- und klanglos verstorben.
Das Problem meine ich gefunden zu haben: Die Ports wurden auf Client-Seite tatsächlich nicht wirklich geschlossen, sondern nur als zum schließen markiert.
Das habe ich schon angepasst, leider ändert es an den 100% nichts. Die treten sofort auf, wenn man eine neue Telnet-Verbindung mit dem Subprozess aufmacht, und bleiben dann auch da oben (trotz echten Portschließens)...

Aber ich bin guter Dinge

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

Super! 
ja das Problem mit dem verstorbenen Fhem hatten Ingo und Ich auch, nach ~8Stunden ist Fhem einfach weg gewesen bei mir.

Danke dir, Gruß Claudiu

[Reinerlein]

Hallo zusammen,

ich habe eine neue Version im Dev-Bereich eingestellt.
Bitte alle, die bei sich die Dev-Version installiert haben, auf diese neue Version umstellen.

Hier ist das Problem mit der 100% CPU-Last behoben, und, was viel wichtiger ist, die Ports werden wieder freigegeben.
Ich denke letzteres war die Ursache für den Fhem-Abschied. Aber da weiss ich natürlich erst genaueres, wenn die 6-8 Stunden um sind

Grüße
Reinerlein

[rapster]

Hi Reinerlein,

danke, funktioniert soweit schonmal alles!

Wir werden sehen wie es heute Abend aussieht 

Gruß Claudiu

[Reinerlein]

Hallo zusammen,

nach knapp 10 Stunden Fhem-Betrieb ohne Ausfälle würde ich von meiner Seite aus sagen, dass das Absturzproblem vom Tisch ist.

Wenn bis nächste Woche keine größeren Dinge mehr auftauchen, dann würde ich diese Version auch gerne in den normalen Downloadbereich verschieben...

Also bitte noch testen

Grüße
Reinerlein