Anfragen an CCU generiert bis dem Prozess die Filedeskriptoren ausgehen

[XXL-Wing]

Hallo zusammen,

Ich habe recht massive Probleme beim Start der Kommunikation zu meiner CCU2.
Wenn FHEM startet, werden aus heiterem Himmel extrem viele Meldungen dieser Art im Logfile generiert:

Code Auswählen Erweitern


2021.12.21 20:21:14 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2010


Dies passiert so lange bis dem Prozess die file descriptors ausgehen und andere Teile Fehlermeldungen wie diese bringen:

Code Auswählen Erweitern


2021.12.21 20:21:20 1: BlinkCamera_PollInfo Blink: Poll call resulted in BlinkCamera_DoCmd Blink: password retrieval failed with :Can't open ./FHEM/FhemUtils/uniqueID: Too many open files:
/code]

Wer der erste Betroffene ist, ist unterschiedlich und hängt davon ab wer als erstes drankommt nachdem die file descriptors aus sind.

Hat jemand so etwas schon hesehen und hat dafür eine Lösung? Die Suche im Forum hat nicht wirklich etwas ergeben.

Systemsetup:
Debian 11 (up-to-date), Vanilla ohne spezielle Pakete.
FHEM am letzten Stand (Latest Revision: 25360)

Danke für Ideen und viele Grüße
Mike

[zap]

Vielleicht ist die Firewall in der CCU nicht richtig konfiguriert?

Die vielen BuildURL Meldungen sind normal. Das wird bei jedem Request Richtung CCU aufgerufen. Du hast halt Verbose auf 4 stehen. Da werden diese Meldungen eben ins Log geschrieben.

[XXL-Wing]

Die Firewall in der CCU ist aus.
Wenn ich es laufen lasse erholt es sich irgendwann und die Requests funktionieren auch, mit dem Nachteil dass dann halt einiges kaputt ist wie z.B. keine Logfiles mehr geschrieben werden usw....

[zap]

Gibt es vor der BuildURL Meldung noch andere Meldungen von HMCCU?

Die BuildURL Meldungen sind normal bei Loglevel 4.

[XXL-Wing]

Hi,

hat etwas länger gedauert, hab eiun wenig versucht den Fehler einzugrenzen.
Zu deiner Frage zap:
Ja, die HMCCU gibt davor Meldungen aus.

Code Auswählen Erweitern


2021.12.31 18:47:30 1: HMCCU [HMIP_RPCCU] Reading device config from CCU. This may take a couple of seconds ...
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Reading Device Descriptions for interface VirtualDevices
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:9292/groups
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Read 0 Device Descriptions for interface VirtualDevices
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Reading Paramset Descriptions for interface VirtualDevices
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Read 0 Paramset Descriptions for interface VirtualDevices
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Reading Peer Descriptions for interface VirtualDevices
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:9292/groups
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Read 0 Peer Descriptions for interface VirtualDevices
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Reading Device Descriptions for interface BidCos-RF
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Read 52 Device Descriptions for interface BidCos-RF
2021.12.31 18:47:30 2: HMCCU [HMIP_RPCCU] Reading Paramset Descriptions for interface BidCos-RF
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:30 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
2021.12.31 18:47:31 4: HMCCU [HMIP_RPCCU] Build URL = http://192.168.0.15:2001
und da geht es dann mit dem Wahnsinn los....


Was ich auch herausgefunden habe:
Ich habe auf 2 Installationen exakt den selben Stand probiert (FHEM directory per NFS jeweils gemountet)
Eine Maschine war eine alte debian 9 (stretch), auf der läuft es anstandslos, da kamen diese Fehler nicht vor.
Die "normale" Maschine auf der es laufen soll ist eine debian 11 (bullseye), auf der treten die Probleme auf.

Um dann Hardware oder ähnliche Themen auszuschließen habe ich die debian 9 auf eine debian 11 upgegradet.
Und siehe da, auch diese Maschine fing mit exakt den selben Problemen an. Scheint also an irgendetwas zu liegen, was auf der debian 11 anders ist als auf der debian 9.
Habe dann das Spiel weitergetrieben und eine nackte debian 11 frisch aufgesetzt und die FHEM installation drauf laufen lassen, die selben Probleme.

Irgendjemand ähnliches auf einer debian 11 beobachtet?

lG
Mike

[zap]

Ich zitiere mich mal selbst: "Die BuildURL Meldungen sind normal bei Loglevel 4."

Wenn Du das Loglevel reduzierst, verschwinden auch die Meldungen. Hintergrund: Beim Starten von FHEM werden die Parameter für alle Geräte abgefragt. Für jedes Gerät wird eine Anfrage an die CCU geschickt. Vor jeder Anfrage wird die URL zusammengebaut => Das wird bei Verbose >= 4 protokolliert.

Eigentlich sind die Meldungen überflüssig. Ich werde die demnächst mal entfernen.

[XXL-Wing]

Hey,

alles klar, aber wieso läuft er out of file descriptors? Das ganze zerstört recht viel an Funktionalität...
Vor allem warum ist es jetzt so, aber bei älteren debian Versionen nicht?
Ich experimentiere grade damit dem perl prozess mehr static file descriptors vom system er zu geben ob das was hilft...
Irgendwoher muss die Verschlechterung ja kommen wenn es nicht von FHEM ist.

Danke für die Aufklärung!

lG
Mike

[zap]

Da Du bisher der Einzige bist, der dieses Problem hat, gehe ich davon aus, dass es nicht HMCCU liegt.

[XXL-Wing]

Hi zap,

nachdem ich noch ein paar Runden gedreht habe...
Wie werden die requests generiert?
Meine Installation generiert eine große Menge an requests...
ich hab die relevanten stellen (glaube ich) mal zusammengefasst:

Code Auswählen Erweitern


2022.01.10 08:07:57 2: HMCCU [HMIP_RPCCU] Read 217 Device Descriptions for interface HmIP-RF
2022.01.10 08:08:53 2: HMCCU [HMIP_RPCCU] Read 123 Paramset Descriptions for interface HmIP-RF
2022.01.10 08:08:54 2: HMCCU [HMIP_RPCCU] Read 19 Peer Descriptions for interface HmIP-RF
2022.01.10 08:08:54 2: HMCCU [HMIP_RPCCU] Read 52 Device Descriptions for interface BidCos-RF
2022.01.10 08:09:06 2: HMCCU [HMIP_RPCCU] Read 52 Paramset Descriptions for interface BidCos-RF


Wenn ich das richtig sehe, werden für jede der Zeilen die entsprechende Anzahl an requests generiert... wären in meiner Installation (und die ist nicht sehr groß) 563 requests...
Und das innerhalb von Millisekunden. Wen ndann parallel dazu einiges (vieles) andere am Starten ist und auch jede menge Reuqests in die Welt hinausschickt, files liest usw. kann das eine große Menge Filedeskriptoren werden die da gebraucht werden.

Gibt es eine Möglichkeit, das Starten von einzelnen Devices zu verzögern? also z.B. starte HMCCU erst, wenn alle anderen devices startup beendet haben?

Ich versuche grade dem perl Prozess mehr Filedskriptioren zu geben bin mir aber nicht sicher ob das funktioniert, das Problem geht trotz der Versuche (noch) nicht weg.

lG
Mike

[rudolfkoenig]

Wenn ich das richtig sehe, werden für jede der Zeilen die entsprechende Anzahl an requests generiert...

Wenn das stimmt, dann waere eine Begrenzung der Request-Anzahl sinnvoll.
Das kann man entweder im Modul oder im HttpUtils.pm implementieren.
Gibt es noch weitere Faelle, wo sowas relevant ist?

[zap]

Code Auswählen Erweitern


2022.01.10 08:07:57 2: HMCCU [HMIP_RPCCU] Read 217 Device Descriptions for interface HmIP-RF
2022.01.10 08:08:53 2: HMCCU [HMIP_RPCCU] Read 123 Paramset Descriptions for interface HmIP-RF
2022.01.10 08:08:54 2: HMCCU [HMIP_RPCCU] Read 19 Peer Descriptions for interface HmIP-RF


Wenn ich das richtig sehe, werden für jede der Zeilen die entsprechende Anzahl an requests generiert... wären in meiner Installation (und die ist nicht sehr groß) 563 requests...
Und das innerhalb von Millisekunden. Wen ndann parallel dazu einiges (vieles) andere am Starten ist und auch jede menge Reuqests in die Welt hinausschickt, files liest usw. kann das eine große Menge Filedeskriptoren werden die da gebraucht werden.

Also parallel läuft bei FHEM nur wenig, und beim Starten so gut wie nichts. Soll heißen: die Requests werden sequenziell ausgeführt.

httputils wird nicht verwendet. Das sind alles RPC-Requests, ausgeführt per RPC::XML::Client.

Ich schaue mir den Aktualisierungsprozess nochmal an. Vielleicht lässt sich da noch etwas optimieren. Es gibt 2 Ansätze:
- RPC Connection keep-alive
- RPC Multicalls

Bei beiden Dingen muss die CCU mitspielen bzw. das unterstützen. Das zu testen wird relative aufwändig => braucht Zeit.

Das Ausbremsen des Startvorgangs ist keine Option, das dauert sowieso schon relativ lange. Ich komme in meiner Umgebung mit 2 CCUs auf fast 1000 Requests beim Start von FHEM, ohne Probleme.

[zap]

Ein kurzes Update dazu: Ich arbeite an der Implementierung von RPC multicalls => weniger Requests.

Ich habe mir den Code nochmal angeschaut: Bei diesem Beispiel werden folgende Requests ausgeführt:

2022.01.10 08:07:57 2: HMCCU [HMIP_RPCCU] Read 217 Device Descriptions for interface HmIP-RF => 1 Request
2022.01.10 08:08:53 2: HMCCU [HMIP_RPCCU] Read 123 Paramset Descriptions for interface HmIP-RF => 123 Requests
2022.01.10 08:08:54 2: HMCCU [HMIP_RPCCU] Read 19 Peer Descriptions for interface HmIP-RF => 19 Requests

Also nicht ganz so schlimm wie befürchtet, aber optimierbar.

[zap]

Ein interessanter Punkt im Changelog zum Homematic CCU Firmware Release 3.61.5:

"Beim Erzeugen / Löschen von Service Meldungen wurde ein UDP Socket nicht ordnungsgemäß geschlossen. Dies konnte zu einer maximalen Ausschöpfung der verfügbaren Linux-File Handles führen."

Das dürfte aber nur auf dem Rechner zu Problemen führen, auf dem die CCU (als Software) läuft.