Node-Red Absturz bei Verbindungsverlust zur CCU

[dewenni]

ich habe seit kurzem ein Problem mit meiner Kombination von RaspberryMatic und einer getrennten Node-Red Installation im Docker auf dem NAS. Das hat jetzt schon viele Monate prima funktioniert.

Jetzt ist es aber so, dass Node-Red abstürzt sobald die Verbindung zur CCU verloren geht.
Beispielsweise wenn man auf der CCU ein Update macht oder die CCU aus anderen Gründen mal vorübergehend nicht im Netzwerk erreichbar ist.

Hier ein Log aus dem das auch einigermaßen hervorgeht.
Erst geht die Verbindung verloren und dann am Ende stürzt Node-Red ab.

Unklar ist mir noch ob das an der CCU-node liegt oder was allgemeines von Node-red ist.

`

2021-12-19 07:42:23	stderr	npm ERR!
2021-12-19 07:42:23	stderr	npm ERR! Exit status 1
2021-12-19 07:42:23	stderr	npm ERR! node-red-docker@2.1.3 start: node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"
2021-12-19 07:42:23	stderr	npm ERR! errno 1
2021-12-19 07:42:23	stderr	npm ERR! code ELIFECYCLE
2021-12-19 07:42:23	stdout	at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
2021-12-19 07:42:23	stdout	19 Dec 08:42:23 - [error] Error: connect ECONNREFUSED 192.168.178.50:8701
2021-12-19 07:42:23	stdout	19 Dec 08:42:23 - [red] Uncaught Exception:
2021-12-19 07:42:22	stdout	19 Dec 08:42:22 - [error] [ccu-connection:raspi] Cannot call write after a stream was destroyed
2021-12-19 07:42:22	stdout	19 Dec 08:42:22 - [error] [ccu-connection:raspi]     < CUxD init Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:42:22	stdout	19 Dec 08:42:22 - [info] [ccu-connection:raspi] init CUxD binrpc://192.168.178.2:2048 nr_RwevYh_CUxD
2021-12-19 07:42:22	stdout	19 Dec 08:42:22 - [warn] [ccu-connection:raspi] ping timeout CUxD 63
2021-12-19 07:42:12	stdout	19 Dec 08:42:12 - [error] [ccu-connection:raspi]     < CUxD ping Error: response timeout
2021-12-19 07:42:04	stdout	19 Dec 08:42:04 - [error] [ccu-connection:raspi] getRegaPrograms Error: connect EHOSTUNREACH 192.168.178.50:8181
2021-12-19 07:42:01	stdout	19 Dec 08:42:01 - [error] [ccu-connection:raspi] getRegaVariables Error: connect EHOSTUNREACH 192.168.178.50:8181
2021-12-19 07:41:52	stdout	19 Dec 08:41:52 - [error] [ccu-connection:raspi]     < CUxD ping Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:48	stdout	19 Dec 08:41:48 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:3","SET_STATE",{"explicitDouble":0}] < Error: response timeout
2021-12-19 07:41:48	stdout	19 Dec 08:41:48 - [error] [ccu-connection:raspi]     < CUxD setValue Error: response timeout
2021-12-19 07:41:46	stdout	19 Dec 08:41:46 - [error] [ccu-connection:raspi] setVariable failed. variables still not known after timeout
2021-12-19 07:41:39	stdout	19 Dec 08:41:39 - [info] [alexa-remote-account:fbd54ce8.c2c61] intialising with the PROXY method and saved data...
2021-12-19 07:41:28	stdout	19 Dec 08:41:28 - [info] [ccu-connection:raspi] regadata saved to /data/ccu_rega_192.168.178.50.json
2021-12-19 07:41:27	stdout	19 Dec 08:41:27 - [error] [ccu-connection:raspi] getRegaPrograms Error: connect EHOSTUNREACH 192.168.178.50:8181
2021-12-19 07:41:24	stdout	19 Dec 08:41:24 - [error] [ccu-connection:raspi] getRegaVariables Error: connect EHOSTUNREACH 192.168.178.50:8181
2021-12-19 07:41:24	stdout	19 Dec 08:41:24 - [info] [ccu-connection:raspi] Interface ReGaHSS disconnected
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [info] [ccu-connection:raspi] Interface CUxD disconnected
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] init CUxD Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD init Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:5","SET_STATE",{"explicitDouble":0}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:4","SET_STATE",{"explicitDouble":0}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:2","SET_STATE",{"explicitDouble":0}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:3","SET_STATE",{"explicitDouble":0}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX4000001:1","SET_STATE",{"explicitDouble":0}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:22	stdout	19 Dec 08:41:22 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX9002003:1","SET_HUMIDITY",{"explicitDouble":76.38}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX9002003:1","SET_TEMPERATURE",{"explicitDouble":5.54}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX9002002:1","SET_HUMIDITY",{"explicitDouble":62.54}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX9002002:1","SET_TEMPERATURE",{"explicitDouble":12.97}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] rpc > CUxD setValue ["CUX9002001:1","SET_HUMIDITY",{"explicitDouble":59.26}] < Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < CUxD setValue Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [info] [ccu-connection:raspi] Interface VirtualDevices disconnected
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] init VirtualDevices Error: connect EHOSTUNREACH 192.168.178.50:9292
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < VirtualDevices init Error: connect EHOSTUNREACH 192.168.178.50:9292
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [info] [ccu-connection:raspi] Interface HmIP-RF disconnected
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi] init HmIP-RF Error: connect EHOSTUNREACH 192.168.178.50:2010
2021-12-19 07:41:21	stdout	19 Dec 08:41:21 - [error] [ccu-connection:raspi]     < HmIP-RF init Error: connect EHOSTUNREACH 192.168.178.50:2010
`

[ckohrt]

Hi,
I also have this issue, see here:
https://homematic-forum.de/forum/viewtopic.php?f=77&t=70828&p=695336#p695336

I will write tomorrow more.

My current solution for my issue: Sega poll time to 60s.
Still testing....

[ckohrt]

Hallo,
jetzt also etwas mehr (eine Kopie der Infos die ich oben verlinkt habe).

Meine Konfiguration:

• Aktuelle raspberrymatic auf Raspi3 3.61.7.20211218
• auf QNAP server läuft ein (latest) Node Red docker container mit CCU Erweiterungen

Leider stürzt der Container ab, und ich dachte es liegt evtl. am Docker Container. Fehlermeldung:

17 Dec 09:30:15 - [red] Uncaught Exception: 17 Dec 09:30:15 - [error] Error: read ETIMEDOUT at TCP.onStreamRead (internal/stream_base_commons.js:209:20) npm ERR! code ELIFECYCLE npm ERR! errno 1 npm ERR! node-red-docker@2.1.4 start: node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data" npm ERR! Exit status 1 npm ERR! npm ERR! Failed at the node-red-docker@2.1.4 start script. npm ERR! This is probably not a problem with npm. There is likely additional logging output above. npm ERR! A complete log of this run can be found in: npm ERR! /data/.npm/_logs/2021-12-17T09_30_15_543Z-debug.log

Unter /share/CACHEDEV1_DATA/Container/container-station-data/lib/docker/volumes/NodeRedDashData/_data/.npm/_logs/2021-12-17T09_30_19_539Z-debug.log findet sich noch im Log:

14 verbose stack Error: node-red-docker@2.1.3 start: node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data" 14 verbose stack Exit status 1 14 verbose stack at EventEmitter.<anonymous> (/usr/local/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16) 14 verbose stack at EventEmitter.emit (events.js:400:28) 14 verbose stack at ChildProcess.<anonymous> (/usr/local/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14) 14 verbose stack at ChildProcess.emit (events.js:400:28) 14 verbose stack at maybeClose (internal/child_process.js:1058:16) 14 verbose stack at Process.ChildProcess._handle.onexit (internal/child_process.js:293:5) 15 verbose pkgid node-red-docker@2.1.3 16 verbose cwd /usr/src/node-red 17 verbose Linux 4.14.24-qnap 18 verbose argv "/usr/local/bin/node" "/usr/local/bin/npm" "--no-update-notifier" "--no-fund" "start" "--cache" "/data/.npm" "--" "--userDir" "/data" 19 verbose node v14.18.1 20 verbose npm v6.14.15 21 error code ELIFECYCLE 22 error errno 1 23 error node-red-docker@2.1.3 start: node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data" 23 error Exit status 1 24 error Failed at the node-red-docker@2.1.3 start script. 24 error This is probably not a problem with npm. There is likely additional logging output above. 25 verbose exit [ 1, true ]

Ich hab schonmal geschaut, aber ich finde keine Logs mit mehr Infos. Weder Docker, noch QNAP, noch Node Red oder syslog.

Vermutung: Beim Senden geht was schief, also die CCU antwortet evtl. nicht und schwupps ist Node Red weg. Ich schau mal ob ich ein CUXD Log irgendwo finde...

Ich konnte eine Verbesserung erreichen, indem ich das "Rega poll interval (s)" des CCU Konfigurations-Node auf 60s gestellt habe. Ich teste gerade noch, aber seit Umstellung vorgestern kein Absturz mehr (=2d). Verdächtig auch, dass ich nichts in den Protokollen finden konnte. So ein Poll Intervall, wenn es denn zuschlägt, sollte eigentlich eine Nachricht hinterlassen, aber er weiß....
Ich gehe davon aus, dass es das wohl nicht tut und damit auch erklärt ist warum ich keine Fehler im log finde.
Das Verhalten der CCU Node ist meines Erachtens ein Bug, es darf deswegen nicht Node red abstürzen.
In einem Docker Container ist das natürlich 2 mal dumm, weil ich zumindest auf der QNAP kein crash recovery habe, also manuell den Container starten muss.

VG
Christian

[ckohrt]

ich habe seit kurzem ein Problem mit meiner Kombination von RaspberryMatic und einer getrennten Node-Red Installation im Docker auf dem NAS. Das hat jetzt schon viele Monate prima funktioniert.

Jetzt ist es aber so, dass Node-Red abstürzt sobald die Verbindung zur CCU verloren geht. Beispielsweise wenn man auf der CCU ein Update macht oder die CCU aus anderen Gründen mal vorübergehend nicht im Netzwerk erreichbar ist.

Hier ein Log aus dem das auch einigermaßen hervorgeht. Erst geht die Verbindung verloren und dann am Ende stürzt Node-Red ab.

Unklar ist mir noch ob das an der CCU-node liegt oder was allgemeines von Node-red ist.

`

2021-12-19 07:42:23 stderr npm ERR!
2021-12-19 07:42:23 stderr npm ERR! Exit status 1
`

Hallo @dewenni,
Node-Red alleine sollte ja nicht das Problem haben, daher denke ich schon, dass die einzige Verbindung die CCU Erweiterung ist. Ich bin mir nicht ganz sicher, ob wir tatsächlich das gleiche Problem haben.
Kannst du mal bei dir auch die ReGa Intervall höher setzen?

[ckohrt]

Hallo,
ich habe nun mein System nochmal angeschaut, hier kam ja leider keine weitere Antwort. Aber für evtl. weitere Fälle hier mein aktueller Stand.

Es sieht so aus, dass bei mir schlicht zu viel Kommunikation stattgefunden hat, sodass nicht immer ein RPC durchgeführt werden konnte, was dann zum Abruch führt. Daher hab ich die jeweiligen Hommatik Skirlt Programme um die Zeilen:
dom.GetObject("CUxD.CUX2801001:1.SYSLOG").State("MyProgramName: Wurde am "#system.Date("%d.%m.%y %H:%M Uhr") #" ausgefuehrt.");
bzw.
dom.GetObject("CUxD.CUX2801001:1.SYSLOG").State("MyProgramName: Wurde am "#system.Date("%d.%m.%y %H:%M Uhr") #" beendet.");
ergänzt. Damit konnte ich im CUX Log sehen, welche Programme oft ausgeführt werden.
Diese habe ich dann soweit reduziert, dass die Kommunikationslast reduziert wurde. Zudem hatte ich ja noch den Timeout von CCU-Node-Red Konfig sehr weit hoch gesetzt. Die letzten Tage hatte ich keine Abbrüche mehr.

VG
Christian

[PatrickM2201]

Hallo @ckohrt,
bei mir tritt der selbe Fehler in einem getrennten Node-Red in einem Debian-LXC auf Proxmox auf :-/
Ich habe den RPC-Ping-Timeout von 60 auf 240s erhöht und so "überlebt" Node-Red zumindest einen Neustart der CCU.

Ich vermute mal, dass auch bei Dir dies zum Ziel geführt hat, und die Reduktion der Kommunikationslast (wenn überhaupt) nur sekundär etwas bewirkt hat. Bei mir steht der Rega-Poll-Intervall übrigens auf 30s und ich frage von Node-Red ca. 3000 Datenpunkte bei der CCU ab.

Genauer habe ich meine Ergebnisse hier beschrieben:
Link zum HM-Forum

Viele Grüße
Patrick

[ckohrt]

Ich glaube da fehlt der Link.
Ja ich habe sogar auf 999s gesetzt. Rega Poll hab ich aus geschaltet. Ich mach das selbst indem ich bei Änderung einer Variable die mich interessiert einen CUX Button betätige, w den ich ja registrieren kann. Dann hol ich mir die values ab. Damit die Last nicht zu groß wird hab ich einen Puffer dazwischen gechaltet. Ist aber auch egal, schalte mal Rega Poll ab, nur um zu sehen ob es besser wird. Ich hatte aber tatsächlich eine sehr große Last durch andere Programme. Ein Zeichen, dass das Problem Last abhängig ist. Brei mir stürzt das System c.a. alle 5 Tage ab. Noch keine Muster entdeckt.

[PatrickM2201]

Upps, danke... Der Link fehlte nicht, er war nur unsichtbar, weil ich zu dämlich war :-)
Ich habe jetzt mal den RegaPoll ausgeschaltet, den Timeout wieder heruntergesetzt und die CCU neugestartet. Leider ist Node-Red wieder mit der uncaught exception abgestürzt.
Somit Timeout wieder hochgesetzt, nochmal einen CCU-Neustart gemacht und nun bleibt Node-Red am Leben. Bisher hatte ich ausschließlich Abstürze von Node-Red, wenn die CCU neugestartet wurde. Abstürze im "Normalen Betrieb" sind nicht aufgetreten.

[ckohrt]

Ich konnte heute den Absturz beobachten ( bei mir läuft mit sehr großem timeout Node Red c.a. 5 Tage) sobald ich Netzwerk Stecker ziehe.

Ps
Danke für das sichtbar machen des links

[ckohrt]

I run now node-red in a docker container with restart set.... It works, but this can't be a solution.... not really...

[PatrickM2201]

Since I increased the ping timeout, I had no crash of node-red, even when I restart the CCU or plug-out the network cable. So from my perspective it seems, that the problem is somewhere in the timeout function.