FHEM reagiert nicht / sehr verzögert, wenn Sonos-Modul aktiv ist

hoppel118 · 11 November 2019, 17:36:00

Hallo Otto,

du hast auch "packet receive errors" und in der gleichen Menge "RcvbufErrors".

Meine Ausgabe sieht momentan wie folgt aus:

Code Auswählen

:~# netstat -anus
IcmpMsg:
    InType3: 23252
    OutType3: 23161
Udp:
    636435 packets received
    48 packets to unknown port received
    132972 packet receive errors
    411440 packets sent
    132972 receive buffer errors
    0 send buffer errors
    IgnoredMulti: 61323
UdpLite:
IpExt:
    InMcastPkts: 577973
    OutMcastPkts: 368468
    InBcastPkts: 83725
    OutBcastPkts: 2070
    InOctets: 21499684706
    OutOctets: 13568690530
    InMcastOctets: 234573936
    OutMcastOctets: 142540820
    InBcastOctets: 22349345
    OutBcastOctets: 480151
    InNoECTPkts: 44260954
    InECT0Pkts: 7590

Warum bei mir "receive buffer errors" und bei dir "RcvbufErrors" weiß ich nicht. Wahrscheinlich nutzt du ein anderes OS als ich (Debian Stretch).

Auf was für einer Hardware betreibst du FHEM? Wie viele Sonos Endgeräte hast du in Betrieb?

Bei mir sind es mittlerweile 8 insgesamt:

- 4 im Wohnzimmer (5.1) - 1x Beam, 1x Sub, 2x Symfonisk Tischleuchte,
- 2 im Schlafzimmer (Stereo), 2x Symfonisk Tischleuchte,
- 1 im Büro, 1x Sonos One,
- 1 in der Galerie, 1x Sonos One

Ich habe dieses Thema seit ich das Sonos Modul nutze. Meine Erkenntnis (Fakt) ist, dass sich mein System innerhalb kürzester Zeit selbständig heilt, sobald das Sonos Modul disabled ist. Aber wie gesagt, außer die Warning Emails von meinem netdata kann ich sonst keine Probleme an meinem System feststellen. Wenn ich das Modul deaktiviere, erhalte ich kurz im Anschluss von netdata eine Email, dass alles wieder ok ist.

Ansonsten ist mir noch folgendes aufgefallen:

- in Otto's Output steht "0 packets to unknown port received",
- in dantist's Output steht "12 packets to unknown port received",
- in meinem Output steht "48 packets to unknown port received".

Ich habe keine Ahnung, ob die UDP-Thematik überhaupt mit dantist's Problem in Verbindung zu bringen ist.

Ich weiß auch nicht, wie man das lösen bzw. besser analysieren könnte.

Evtl. hat hier ja noch jemand anderes eine Idee? Ich bin zu jeder tiefer gehenden Analyse bereit.

Viele Grüße Hoppel

Otto123 · 11 November 2019, 17:49:21

Ich habe 7 Sonos Geräte.
FHEM läuft derzeit auf Raspbian Jessie.
Ich habe keine Probleme. Außer wenn der Strom ausfällt und dann wiederkommt ist manchmal anschließend der eine oder andere Player disappeared. Das löse ich mit disable / enable

Gruß Otto

hoppel118 · 11 November 2019, 21:13:21

Ok, Fazit:

1. An der Performance von dantist's RPi sollte es also nicht liegen. Bei dir läuft es ja auch mit 7 Sonos Geräten.
2. ,,ignoredIPs/usedonlyIPs" hat dantist erfolglos ausprobiert (Oder?)
3. Andere Services, die ebenfalls auf Port 1900 lauschen, gibt es bei dantist nicht, wie oben auf dem ersten Screenshot zu sehen ist. Dort werden wie bei mir nur die beiden Perl-Einträge angezeigt.

Warum sind das eigentlich 2 Einträge?

Bei mir sieht das beispielsweise wie folgt aus:

Code Auswählen

 ~# netstat -unlp | grep ":1900"
udp   8389376      0 0.0.0.0:1900            0.0.0.0:*                           4704/perl
udp        0      0 0.0.0.0:1900            0.0.0.0:*                           4704/perl

2 Perl Prozesse, die auf Port 1900 lauschen. Bei einem läuft der von mir definierte Receive Buffer voll...

Wenn ich mir das bei TVHeadend bzw. Emby ansehe, sehe im Output dieses Befehls immer genau ein Eintrag pro Service.

@Otto123 Kannst du nochmal deinen Output zeigen?

@Reinerlein Ist das so richtig, dass hier 2 Perl Prozesse auf Port 1900 agieren?

Viele Grüße Hoppel

Otto123 · 11 November 2019, 21:41:13

ähnlich wie bei Dir:

Code Auswählen

netstat -unlp | grep ":1900"
udp   163840      0 0.0.0.0:1900            0.0.0.0:*                           941/perl        
udp        0      0 0.0.0.0:1900            0.0.0.0:*                           941/perl

hoppel118 · 12 November 2019, 06:19:06

Ok, das bestätigt nochmal, dass deine Recv-Q auch übergelaufen ist. Bei dir ist allerdings der Defaultwert für die Buffergröße konfiguriert. Den Buffer zu erhöhen bringt definitiv nix (siehe meine Analyse bei Github: https://github.com/netdata/netdata/issues/6527 ).

Wie ist deine Meinung dazu, dass 2 Perl Prozesse auf Port 1900 lauschen?

Meiner Analyse nach ,,kämpfen" die verschiedenen UPnP-Prozesse um den Port 1900. Als bei mir früher noch alle 3 Services (FHEM/Sonos-Modul, TVHeadend und EmbyServer) unter der IP Adresse des Hosts verfügbar waren, war auch immer nur einer wirklich per UPnP verfügbar, auch wenn ich mehrere mit netstat sehen konnte. Das Verhalten war allerdings unterschiedlich. Wenn EmbyServer zuerst gestartet wurde, hat der Perl-Prozess nicht mehr funktioniert (alle Player waren disappeared) und netdata meldete mir, dass das System nun geheilt ist. Wenn TVHeadend vor Pearl gestartet wurde, lief der Receive Buffer weiter über und ich bekam Warning Emails von netdata. So richtig nachvollziehbar ist dieses UPnP-Verhalten für mich nicht.

Mit dem folgenden Befehl sieht man sehr schön, dass ausschließlich bei dem einen Perl-Prozess die Recv-Q vollläuft:

Code Auswählen

 :~# netstat -unlp
Aktive Internetverbindungen (Nur Server)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
udp        0      0 0.0.0.0:31909           0.0.0.0:*                           17804/perl
udp        0      0 0.0.0.0:68              0.0.0.0:*                           2580/dhclient
udp        0      0 0.0.0.0:111             0.0.0.0:*                           2250/rpcbind
udp        0      0 172.17.0.1:123          0.0.0.0:*                           2884/ntpd
udp        0      0 10.11.11.11:123         0.0.0.0:*                           2884/ntpd
udp        0      0 127.0.0.1:123           0.0.0.0:*                           2884/ntpd
udp        0      0 0.0.0.0:123             0.0.0.0:*                           2884/ntpd
udp        0      0 172.17.255.255:137      0.0.0.0:*                           2728/nmbd
udp        0      0 172.17.0.1:137          0.0.0.0:*                           2728/nmbd
udp        0      0 10.11.11.255:137        0.0.0.0:*                           2728/nmbd
udp        0      0 10.11.11.11:137         0.0.0.0:*                           2728/nmbd
udp        0      0 0.0.0.0:137             0.0.0.0:*                           2728/nmbd
udp        0      0 172.17.255.255:138      0.0.0.0:*                           2728/nmbd
udp        0      0 172.17.0.1:138          0.0.0.0:*                           2728/nmbd
udp        0      0 10.11.11.255:138        0.0.0.0:*                           2728/nmbd
udp        0      0 10.11.11.11:138         0.0.0.0:*                           2728/nmbd
udp        0      0 0.0.0.0:138             0.0.0.0:*                           2728/nmbd
udp        0      0 0.0.0.0:730             0.0.0.0:*                           2250/rpcbind
udp   8390400      0 0.0.0.0:1900            0.0.0.0:*                           17804/perl
udp        0      0 0.0.0.0:1900            0.0.0.0:*                           17804/perl
udp        0      0 10.11.11.11:5353        0.0.0.0:*                           2721/homebridge
udp        0      0 10.11.11.11:5353        0.0.0.0:*                           2722/homebridge
udp        0      0 10.11.11.11:5353        0.0.0.0:*                           2739/homebridge
udp        0      0 0.0.0.0:5353            0.0.0.0:*                           2263/avahi-daemon:
udp        0      0 0.0.0.0:7359            0.0.0.0:*                           15259/EmbyServer
udp        0      0 127.0.0.1:8125          0.0.0.0:*                           14584/netdata
udp        0      0 0.0.0.0:48213           0.0.0.0:*                           2263/avahi-daemon:
udp        0      0 0.0.0.0:56620           0.0.0.0:*                           10418/tvheadend
udp6       0      0 172.17.0.1:59104        :::*                                15416/java
udp6       0      0 :::111                  :::*                                2250/rpcbind
udp6       0      0 ::1:123                 :::*                                2884/ntpd
udp6       0      0 :::123                  :::*                                2884/ntpd
udp6       0      0 :::730                  :::*                                2250/rpcbind
udp6       0      0 :::3478                 :::*                                15416/java
udp6       0      0 :::10001                :::*                                15416/java
udp6       0      0 10.11.11.11:22480       :::*                                15416/java

Es wäre wirklich schön, wenn @Reinerlein sich dazu mal äußern könnte.

Keine Ahnung, ob das nun die Ursache für das Verhalten bei @dantist ist. Ich schätze eher nicht, da dieses Verhalten bei mir, Otto und wahrscheinlich allen anderen dasselbe ist und in FHEM nicht zum Totalabsturz führt. Auch eine zu schwache Hardware ist meiner Ansicht nach ausgeschlossen.

Gruß Hoppel

t1me2die · 12 November 2019, 07:24:59

Zitat von: Otto123 am 11 November 2019, 17:49:21
Ich habe 7 Sonos Geräte.
FHEM läuft derzeit auf Raspbian Jessie.
Ich habe keine Probleme. Außer wenn der Strom ausfällt und dann wiederkommt ist manchmal anschließend der eine oder andere Player disappeared. Das löse ich mit disable / enable

Gruß Otto

Offtopic:
Das Problem habe ich auch, habe mir dazu folgenden Workaround gebaut (musst nur auf deine Sonos Geräte regexen

):

Code Auswählen


define n_Sonos notify Sonos_Bad:.*|Sonos_Kueche:.*
{   if ($EVENT eq "initialized")
    {   fhem "defmod -temporary t_Sonos_Rescan at +00:01:00 set Sonos RescanNetwork" 
    }
    elsif (($EVENT eq "closed") or ($EVENT eq "disappeared") or ($EVENT eq "disabled"))
    {   fhem "defmod -temporary t_Sonos_Rescan at +00:01:00 set Sonos RescanNetwork";
        fhem "attr Sonos disable 1 ;; sleep 10 ;; attr Sonos disable 0";
    }
}

Gruß
Mathze

hoppel118 · 12 November 2019, 08:53:06

@t1me2die Ich habe das Problem auch. Ich musste kürzlich den FI für das Obergeschoss umlegen. Mein Server hängt am FI vom Dachgeschoss. Anschließend waren alle Player disappeared. Nachdem ich einmal das Sonos Modul disabled und anschließend wieder enabled hatte, waren die Player wieder da.

Kannst du auch mal die Outputs der beiden folgenden Befehle posten?

Code Auswählen


netstat -unlp | grep ":1900"
netstat -anus

Danke für das Regex. Schöner wäre, wenn man das direkt im Modul-Code lösen könnte...

Viele Grüße Hoppel

dantist · 12 November 2019, 09:47:03

Zitat von: hoppel118 am 11 November 2019, 21:13:21
,,ignoredIPs/usedonlyIPs" hat dantist erfolglos ausprobiert (Oder?)

usedonlyIPs hat bei mir nicht funktioniert, richtig. Dazu möchte ich noch sagen, dass die Probleme vor einigen Wochen scheinbar grundlos angefangen haben, ohne dass ich irgendwas am Setup geändert habe. Anfangs hing sich FHEM komplett auf (Logfile wurde noch befüllt, aber Befehle kamen nicht mehr an und die Web-Oberfläche war tot). Inzwischen hat sich das Problem dahingehend verlagert, dass sich das Sonos-Modul nach kurzer Zeit selbst beendet. Ein Rollback auf eine etwas ältere Version des Moduls hat nicht geholfen.

huhu · 18 Mai 2020, 11:30:45

Hallo zusammen,

ich würde das Thema gerne nochmal aufgreifen, da ich exakt die gleichen Freezer beobachte. Habt ihr eine Lösung oder Workaround herausgefunden?
Durch das Freezemon Tool sehe ich auch wann diese passieren:

Code Auswählen

2020.05.18 11:15:47 1: [Freezemon] myFreezemon: possible freeze starting at 11:15:24, delay is 23.812 possibly caused by: tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) 
2020.05.18 11:25:44 1: [Freezemon] myFreezemon: possible freeze starting at 11:25:24, delay is 20.766 possibly caused by: tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer) tmr-SONOSPLAYER_SimulateCurrentTrackPosition(Sonos_Wohnzimmer)

Interessant ist, dass dies ca. exakt alle 10Min passiert. usedonlyIPs hat leider keine Besserung gebracht.
Viele Grüße
huhu