UPDATE 31.10.: Amazon Alexa - ioBroker Skill läuft aus ?

[LittleNo]

Nachdem ich in der Vergangenheit schon Schwierigkeiten mit den einfacheren ZigBee-Sticks hatte, habe ich seit ca. einem Jahr diesen im Einsatz: https://zig-star.com/projects/zigbee-gw-lan/ Also ein CC2652P über TCP am ioBroker angebunden. Das hat jetzt ein Jahr lang super funktioniert. Auch meine ZigBee-Leuchtmittel, die nun mal bei Nichtgebrauch auch einfach über den Lichtschalter stromlos sind, findet er nach dem einschalten innerhalb weniger Sekunden und baut sein ZigBee-Netz wieder ordentlich auf.

Kürzlich habe ich zwei weitere innr Steckdosen angelernt. Seit dem stürzt der ZigBee-Adapter 2-3 Mal am Tag ab. Den Adapter anhalten und wieder starten genügt, dann läuft einen halben Tag ca. alles wieder problemlos. Vom gleichen Steckdosen-Typ hatte ich auch vorher schon 4 Stück in meiner Instanz.

Ich habe dann erstmal alles geupdatet:
js-controller auf 5.0.16
npm 10.2.4
node 20.10.0
ZigBee 1.8.24
Alle übrigen Adapter auch auf aktuellsten Stand.
Die Firmware des CC2652P ist laut seiner WebUI auch die Neueste.

Der ioBroker läuft bei mir auf einer Ubuntu 20.04 VM auf ESXi, auch das darunter liegende Ubuntu ist aktuell. Ressourcen (HDD, RAM & CPU) hat die VM genug.

Über die Suche habe ich mehrere ähnliche Themen gefunden, aber keine deren Ursachen scheint mit meiner identisch zu sein.

Das Log sieht dann so aus:

2023-12-01 01:50:52.912  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.918  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.920  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.922  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.925  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.927  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.929  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:50:52.937  - error: zigbee.0 (1148395) Adapter disconnected, stopping
2023-12-01 01:51:02.948  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.949  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.949  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.950  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.950  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.950  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.951  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.951  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.951  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.952  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.952  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.952  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.953  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.953  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.954  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:02.954  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:02.983  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.984  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.984  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.984  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.985  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.997  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.997  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:02.998  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:04.440  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Cannot read properties of undefined (reading 'execute')"
2023-12-01 01:51:04.440  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:04.441  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:04.460  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Cannot read properties of undefined (reading 'execute')"
2023-12-01 01:51:04.460  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:04.460  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:04.471  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Cannot read properties of undefined (reading 'execute')"
2023-12-01 01:51:04.471  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:04.472  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:04.481  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Cannot read properties of undefined (reading 'execute')"
2023-12-01 01:51:04.481  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:04.481  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:04.504  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Cannot read properties of undefined (reading 'execute')"
2023-12-01 01:51:04.504  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:04.505  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:14.445  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:14.446  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:14.451  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:14.459  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Error while opening socket"
2023-12-01 01:51:14.459  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:14.459  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:14.465  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:14.465  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:14.472  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:14.473  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:14.474  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:14.485  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:14.495  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:14.495  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:14.506  - info: zigbee.0 (1148395) Try to reconnect.
2023-12-01 01:51:14.506  - info: zigbee.0 (1148395) Starting Zigbee  npm ...
2023-12-01 01:51:14.507  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:14.512  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Error while opening socket"
2023-12-01 01:51:14.512  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:14.513  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:14.528  - info: zigbee.0 (1148395) Installed Version: iobroker.zigbee@1.8.24
2023-12-01 01:51:14.534  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Error while opening socket"
2023-12-01 01:51:14.534  - error: zigbee.0 (1148395) Failed to start Zigbee
2023-12-01 01:51:14.534  - error: zigbee.0 (1148395) Error herdsman start
2023-12-01 01:51:22.002  - error: zigbee.0 (1148395) Starting zigbee-herdsman problem : "Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms)"

Ich könnte jetzt natürlich versuchen die zwei neu angelernten Steckdosen wieder zu entfernen und zu beobachten. Aber selbst wenn es dann wieder ginge, weiss ich dadurch nur was ich eh schon weiss, nämlich dass das Anlernen dieser Steckdosen der Auslöser war. Der eigentlichen Ursache bringt es mich aber nicht näher.

Hat jemand Tips wie ich das weiter diagnostizieren kann?

[Winni]

@littleno was mir auffällt, aktuell empfohlen sind Node.js v18.19.0 und NPM 10.2.3.
Dann probiere mal iob fix.

[arteck]

@littleno so und jetzt nochmal das LOG aber ALLES incl. Adapter start..

[LittleNo]

@arteck bitteschön, hier das Log von heute. Ich vermute um 03:50 Uhr gehts los mit dem Problem (wann genau er in der Nacht aufgehört hat zu funktionieren weiss ich natürlich nicht)

Heute wars auch wieder so dass die CPU-Last der VM, während der ZigBee-Adapter sich aufgehängt hatte, auf Anschlag lief. Das wurde ziemlich sicher davon ausgelöst, weil es sofort vorbei war als ich den Adapter gestoppt habe.

iobroker.2023-12-06.log

[arteck]

@littleno

2023-12-06 06:15:03.696  - error: host.iobrokervm Caught by controller[1]: <--- Last few GCs --->
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[1]: [1123827:0x5e7fac0] 28959251 ms: Mark-Compact (reduce) 1921.3 (1993.9) -> 1920.4 (1993.9) MB, 5257.16 / 0.00 ms  (average mu = 0.082, current mu = 0.003) allocation failure; scavenge might not succeed
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[1]: [1123827:0x5e7fac0] 28964003 ms: Mark-Compact (reduce) 1921.3 (1993.9) -> 1920.4 (1993.9) MB, 4737.37 / 0.00 ms  (average mu = 0.047, current mu = 0.003) allocation failure; scavenge might not succeed
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[1]: <--- JS stacktrace --->
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[2]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[3]:  1: 0xc9e850 node::Abort() [io.zigbee.0]
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[4]:  2: 0xb720ff  [io.zigbee.0]
2023-12-06 06:15:03.697  - error: host.iobrokervm Caught by controller[5]:  3: 0xec1a70 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[6]:  4: 0xec1d57 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[7]:  5: 0x10d3dc5  [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[8]:  6: 0x10d4354 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[9]:  7: 0x10eb244 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[10]:  8: 0x10eba5c v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[11]:  9: 0x10c1d61 v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[12]: 10: 0x10c2ef5 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[13]: 11: 0x109f536 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[14]: 12: 0x1090b6c v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawArray(int, v8::internal::AllocationType) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[15]: 13: 0x1090cd4 v8::internal::FactoryBase<v8::internal::Factory>::NewFixedArrayWithFiller(v8::internal::Handle<v8::internal::Map>, int, v8::internal::Handle<v8::internal::Oddball>, v8::internal::AllocationType) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[16]: 14: 0x13bfcbd v8::internal::OrderedHashTable<v8::internal::OrderedHashMap, 2>::Allocate(v8::internal::Isolate*, int, v8::internal::AllocationType) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[17]: 15: 0x13bfd63 v8::internal::OrderedHashTable<v8::internal::OrderedHashMap, 2>::Rehash(v8::internal::Isolate*, v8::internal::Handle<v8::internal::OrderedHashMap>, int) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[18]: 16: 0x14f0973 v8::internal::Runtime_MapGrow(int, unsigned long*, v8::internal::Isolate*) [io.zigbee.0]
2023-12-06 06:15:03.698  - error: host.iobrokervm Caught by controller[19]: 17: 0x1934ef6  [io.zigbee.0]
2023-12-06 06:15:03.698  - warn: host.iobrokervm instance system.adapter.zigbee.0 terminated due to SIGABRT
2023-12-06 06:15:03.699  - info: host.iobrokervm instance system.adapter.zigbee.0 terminated with code null ()

hier ist dein Problem.. nicht der zigbee adapter sonder JAVASCRIPT..
JavaScript heap out of memory

und der reist den rest mit

[LittleNo]

@arteck okay, also erstmal Danke für die Aufklärung, denn das hätte ich so vermutlich nicht selbst deuten können

Dann aber die Frage warum? denn physisch zu wenig Speicher scheint nicht das Problem zu sein. Die VM hat 4GB und auch während dem Crash sind davon 1,2GB ungenutzt:

Es ist also wohl eher ein logisches Problem, dass innerhalb des JavaScripts sich irgendwas zumüllt. Auch das sieht jetzt nicht nach zu wenig Speicher aus:

Und dann natürlich die Frage, da der Javascript-Adapter nicht abgestürtzt ist, habe ich den nie neu gestartet, und trotzdem läuft wieder alles wenn ich nur den ZigBee-Adapter neu starte.

Ich habe da natürlich ein paar Blockly-Scripte laufen, aber an denen habe ich nichts verändert, es lief also auch vorher schon damit ohne diese Abstürze.

[Thomas Braun]

@littleno

JavaScript heap out of memory

Der sog. heap ist in nodejs begrenzt, das hat mit dem Arbeitsspeicher nichts zu tun.
Ich vermute, da kippt dir ein Skript weg.

[LittleNo]

@thomas-braun habe mal alle Skripte gestoppt, ZigBee stürzt trotzdem wieder nach paar Stunden ab. Das log sieht jetzt aber anders aus.

iobroker.2023-12-08.log.zip

Ich habe jetzt den ganzen javascript Adapter gestoppt und teste wieder. Vielleicht kann ja auch jemand hier im log was erkennen.

[Thomas Braun]

@littleno

Dann lass das Log mal sehen.
Ein zip werde ich nicht öffnen.

[LittleNo]

@thomas-braun ungezippt hat das log 22MB

[LittleNo]

ok also trotz ausgeschaltetem Javascript-Adapter ist ZigBee grade wieder abgestürzt

[LittleNo]

@thomas-braun hier das heutige Log. Musste halt die Massenwiederholungen rauslöschen, sonst wäre die Datei wieder riesig geworden iobroker.2023-12-13.log

[David G.]

@littleno

Naja, es reicht ja, wenn du erstmal nur das Log vom Zigbee sendest.

Das sollte hier ja sogar mit

code_text

gepostet werden können.

Die paar Zeilen kannst du dir ja auch aus dem Admin unter Logs holen.
Dort filtern, dass man nur Zigbee sieht und das bisschen dann c&p.

Reicht ja ab ankernen bis absturz.

[LittleNo]

@david-g im Prinzip ist das in dieser Log-Datei. Die Menge kommt ja durch den ZigBee-Adapter zustande, weil er mehrere hundert Log-Einträge pro Sekunde schreibt, während er abgestürzt ist