thkl / hap-homematic

a AddOn for HomeMatic CCU3 (Raspberrymatic) that will bring HomeKit to your CCU
MIT License
222 stars 24 forks source link

HAP Server crash bei DHCP renew #597

Open KoMa1978 opened 1 year ago

KoMa1978 commented 1 year ago

Hallo,

ich nutze HAP-Homematic 0.0.14 auf einer CCU3 mit V3.65.11.

In unregelmäßigen Abständen verabschiedet sich der HAP Dienst "zum Teil".

"Zum Teil" bedeutet, dass die Web Oberfläche nicht mehr erreichbar ist und z.B. Bewegungen eines HMIP-BWM in Homematic noch erkannt werden aber nicht auf den Apple Geräten in Home gesehen werden. Dort sind ab z.B. Steckdosen noch schaltbar.

Es gibt .crash Dateien vom jeweiligen Abstuz, jeweils mit folgender Meldung:

Error log : Mon Jan 02 2023 16:14:58 GMT+0100 (CET)

Error: send ENETUNREACH 224.0.0.251:5353
    at Object._errnoException (util.js:992:11)
    at _exceptionWithHostPort (util.js:1014:20)
    at SendWrap.afterSend [as oncomplete] (dgram.js:499:11)

In der /var /log/messages steht zum jeweiligen Ereigniszeitpunkt, dass es einen nicht erfolgreichen DHCP Renew gab und scheinbar kurzzeitig (3-4s) keine IP an der NIC anliegt, woraufhin sich kurzzeitig eine 169er IP aufs Interface legt. Ich nutze DHCP mit festem Lease und das funktioniert auf der CCU an sich auch sehr gut. Als einzige weitere Zusatzsoftware ist CUXD installiert und der läuft auch ohne Probleme durch.

Warum der DHCP sich nicht richtig verlängert werde ich prüfen, aber der HAP sollte sich ja eigentlich nicht davon irritieren lassen.

"Enable Monitoring" ist aktiviert und der Watchdog steht auf 300s, das bringt aber scheinbar nichts. Ich habe nur 5 Geräte (1x CUXD, 4x HMIP) in HAP aktiviert, somit hat der Dienst nicht wirklich viel zu tun. Sobald ich über Homematic/Systemsteuerung/Zusatzsoftware den HAP Dienst neu starte ist auch alles wieder OK.

Hier der Auszug aus der /var/log/messages:

Jan  2 16:14:13 hm-ccu daemon.err udhcpc[429]: sending renew to 192.168.xxx.21
Jan  2 16:14:55 hm-ccu daemon.err udhcpc[429]: sending renew to 0.0.0.0
Jan  2 16:14:56 hm-ccu daemon.err udhcpc[429]: received DHCP NAK
Jan  2 16:14:56 hm-ccu daemon.info avahi-autoipd(eth0)[14422]: Found user 'avahi' (UID 1000) and group 'avahi' (GID 1000).
Jan  2 16:14:56 hm-ccu daemon.info avahi-autoipd(eth0)[14422]: Successfully dropped root privileges.
Jan  2 16:14:56 hm-ccu daemon.info avahi-autoipd(eth0)[14422]: Starting with address 169.254.10.103
Jan  2 16:14:56 hm-ccu daemon.info avahi-autoipd(eth0)[14422]: Routable address already assigned, sleeping.
Jan  2 16:14:56 hm-ccu daemon.info avahi-autoipd(eth0)[14422]: Got SIGTERM, quitting.
Jan  2 16:14:57 hm-ccu daemon.info ntpd[530]: Deleting interface #6 eth0, 192.168.yyy.10#123, interface stats: received=88, sent=88, dropped=0, active_time=86357 secs
Jan  2 16:14:57 hm-ccu daemon.info ntpd[530]: 192.168.xxx.21 local addr 192.168.yyy.10 -> <null>
Jan  2 16:14:59 hm-ccu daemon.err udhcpc[429]: sending discover
Jan  2 16:14:59 hm-ccu daemon.err udhcpc[429]: sending select for 192.168.yyy.10
Jan  2 16:14:59 hm-ccu daemon.err udhcpc[429]: lease of 192.168.yyy.10 obtained, lease time 86400
Jan  2 16:15:00 hm-ccu daemon.info ntpd[530]: Listen normally on 7 eth0 192.168.yyy.10:123
Jan  2 16:15:04 hm-ccu daemon.err cuxd[604]: sendbinrpc(127.0.0.1:9876) - write() Connection refused

Wenn weitere Infos benötigt werden oder ich irgendetwas testen soll, kann ich das gerne machen.

Vielen Dank, KoMa1978

jb-home commented 1 year ago

Ich vermute, dass die Listener die auf dem Netzwerk aktiv sind, einen connection reset bekommen, wenn der DHCP lease abläuft. Oder genau in den 3-4 Sekunden auf das Netz zugegriffen wird. Ist halt Broadcast, der ziemlich oft ins Netz rein schreit. Ich würde eine CCU aber nicht mit DHCP laufen lassen. Immer feste IP.

KoMa1978 commented 1 year ago

Die CCU bekommt ja immer die gleiche IP vom DHCP und das läuft auch seit Jahren wunderbar.

Meiner Meinung nach sollte das aber nicht zum Dienstabsturz führen sondern lediglich zu Fehlermeldungen. Auch wenn es ein Broadcast ist, dann geht der halt 2,3,4 Mal nicht raus, aber das direkt der komplette Daemon wegfliegt klingt nicht gesund.

jb-home commented 1 year ago

Schon klar, dass sie immer wieder die gleich IP bekommt. Aber trotzdem werden die Event Listener die auf dem Interface sitzen es mitbekommen und sich dann verabschieden. Da hilft nur feste IP. Oder @thkl müsste den Netzwerkteil umschreiben. Ich vermute eine statische IP ist da wesentlich wahrscheinlicher.

thkl commented 1 year ago

Moin, leider ist das CrashFile nicht sehr gesprächig, was den Ursprung des Fehlers angeht. Es könnte sein, dass der Listener auf die CCU Events crasht, oder das darunterliegende hapnodejs ..

Ich werd mal auf die Suche gehen

KoMa1978 commented 1 year ago

Moin,

ein kleines Update. Ich habe 2 DHCP Server wegen der Redundanz laufen. Das läuft auch alles wunderbar, ich lasse die Configs (z.B. Statische Zuweisungen) nachts synchronisieren. Das Problem bei mir war, dass ich auch die "leases"-Datei vom primären auf den Sekundären DHCP kopiert und damit überschrieben habe.

Das hatte jedes Mal, wenn die CCU eine IP vom sekundären DHCP bekommen hat am Folgetag beim Renewal ein NACK kam (der sekundäre DHCP kannte ja kein Lease duch das Überschreiben).

Ich habe mal die Leases Datei rausgenommen und nun sieht es seit 3 Tagen gut aus. Ein Renew wird angefragt und bestätigt.

Nichts desto trotz sollte der Dienst nicht abschmieren, wenn die NIC grad mal keine IP hat. Zumal die CCU und CUXD damit wunderbar klarkommen. Ihr könnt entscheiden, ob hier weiter dran gearbeitet werden soll, oder ob wir schließen.

Besten Dank auf jeden Fall schon einmal, KoMa1978