search

Zefau / ioBroker.jarvis

jarvis - just another remarkable vis
https://forum.iobroker.net/topic/49776
Other
149 stars 38 forks source link

ioBroker crashes with segmentation fault #386

Closed CC1337 closed 3 years ago

CC1337 commented 4 years ago

Versions

Describe the bug Some days after I installed jarvis, iobroker crashed with segmentation fault in logs (docker, not iobroker internal). I am using the buanet image on rpi4 4GB. It never crashed before BUT it could have been any adapter update, hardware etc. But since I updated to latest jarvis yesterda to verify a bugfix, I had 3 crashes in 16 hours. Either it's pure coincidence, or something got worse for me. While it crashed the iobroker was either updating fuel prices using tankerkoenig, or measuring owfs temperatures. For verification I stopped both and it now also crashed without them. Suspicious here: in 80% of the cases the las log line before the state db seems to crash, I was calling jarvis e.g. from my phone.

I am not sure how to track it down more... any suggestions welcome. For now I will disable jarvis and see if that helps.

Screenshots

2020-11-28 13:04:23.779  - info: web.0 (491) ==>Connected system.user.admin from ::ffff:192.168.0.100
2020-11-28 13:04:26.370  - info: jarvis.0 (975) Processed 171 devices and discarded 0 devices due to incorrect configuration. See browser console log for more details:  ["devices","states","processedDevices","addedDevices","ignoredDevices","discardedDevices"]
2020-11-28 13:04:26.380  - warn: jarvis.0 (975) Value provided for LevelBody not a number!
2020-11-28 13:04:26.482  - warn: jarvis.0 (975) Value provided for LevelBody not a number!
2020-11-28 13:04:28.675  - info: host.iobroker stopInstance system.adapter.node-red.0 (force=false, process=true)
2020-11-28 13:04:28.702  - info: node-red.0 (688) kill node-red task
2020-11-28 13:04:28.755  - info: node-red.0 (688) node-red exited with 0
2020-11-28 13:04:30.091  - error: kodi.2 (876) read ECONNRESET
2020-11-28 13:04:30.133  - error: owfs.0 (514) read ECONNRESET
2020-11-28 13:04:30.149  - error: deconz.0 (673) read ECONNRESET
2020-11-28 13:04:30.116  - error: hm-rpc.0 (639) read ECONNRESET
2020-11-28 13:04:30.168  - error: admin.0 (436) read ECONNRESET
2020-11-28 13:04:35.074  - error: jarvis.0 (975) connect ECONNREFUSED 127.0.0.1:9001
2020-11-28 13:04:35.077  - error: hm-rpc.1 (960) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:04:35.089  - error: mqtt.0 (915) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:04:35.087  - error: alexa2.0 (945) connect ECONNREFUSED 127.0.0.1:9001
2020-11-28 13:04:35.076  - error: jarvis.0 (975) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:04:35.079  - error: hm-rpc.1 (960) connect ECONNREFUSED 127.0.0.1:9001
2020-11-28 13:04:35.092  - error: alexa2.0 (945) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:04:35.098  - error: solarviewdatareader.0 (844) connect ECONNREFUSED 127.0.0.1:9000

(above I also stopped node-red manually)

2020-11-28 13:43:25.087  - info: web.0 (499) ==>Connected system.user.admin from ::ffff:192.168.0.11
2020-11-28 13:43:33.779  - info: jarvis.0 (977) Processed 171 devices and discarded 0 devices due to incorrect configuration. See browser console log for more details:  ["devices","states","processedDevices","addedDevices","ignoredDevices","discardedDevices"]
2020-11-28 13:43:33.783  - warn: jarvis.0 (977) Value provided for LevelBody not a number!
2020-11-28 13:43:33.881  - warn: jarvis.0 (977) Value provided for LevelBody not a number!
2020-11-28 13:43:36.791  - error: solarviewdatareader.0 (857) read ECONNRESET
2020-11-28 13:43:36.816  - error: kodi.0 (778) read ECONNRESET
2020-11-28 13:43:36.828  - error: javascript.0 (607) read ECONNRESET
2020-11-28 13:43:36.831  - error: deconz.0 (675) read ECONNRESET
2020-11-28 13:43:36.842  - error: web.0 (499) read ECONNRESET
2020-11-28 13:43:36.812  - error: node-red.0 (723) read ECONNRESET
2020-11-28 13:43:38.871  - error: node-red.0 (723) connect ECONNREFUSED 127.0.0.1:9001
2020-11-28 13:43:38.873  - error: node-red.0 (723) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:43:40.880  - error: node-red.0 (723) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:43:40.881  - error: node-red.0 (723) connect ECONNREFUSED 127.0.0.1:9001
2020-11-28 13:43:41.800  - error: hm-rpc.1 (962) connect ECONNREFUSED 127.0.0.1:9000
2020-11-28 13:43:41.804  - error: hm-rpc.1 (962) connect ECONNREFUSED 127.0.0.1:9001
Zefau commented 4 years ago

connect ECONNREFUSED 127.0.0.1:9001 actually means that your ioBroker instance is not reachable. Please deactivate jarvis and restart ioBroker. Is it running then?

CC1337 commented 4 years ago

It is always running after iobroker restart (I restart the docker container). For a while. Today max 5 hrs, usually a week since some weeks. Then it crashes which shows up in iobroker logs as port 9000 and 9001 is dead. And in docker container logs I see segmentation fault. Will copy it next time. After restart also with activated jarvis it is running first, so I cannot really blame jarvis alone.

CC1337 commented 4 years ago

/opt/scripts/iobroker_startup.sh: line 173: 414 Segmentation fault (core dumped) gosu root node node_modules/iobroker.js-controller/controller.js

2020-11-28 16:56:08.434  - info: web.0 (500) <==Disconnect system.user.admin from ::ffff:192.168.0.100 
2020-11-28 16:56:08.827  - info: web.0 (500) ==>Connected system.user.admin from ::ffff:192.168.0.100
2020-11-28 16:56:16.343  - error: hm-rpc.0 (639) read ECONNRESET
2020-11-28 16:56:16.361  - error: kodi.2 (879) read ECONNRESET
2020-11-28 16:56:16.356  - error: deconz.0 (673) read ECONNRESET
2020-11-28 16:56:16.377  - error: owfs.0 (517) read ECONNRESET
2020-11-28 16:56:16.391  - error: admin.0 (437) read ECONNRESET

I might have to stop the web adapter as well... as jarvis is still reachable if I only stop its instance

Zefau commented 3 years ago

@CC1337 hast du das lösen können?

CC1337 commented 3 years ago

Hi, nicht wirklich. Ich hatte jarvis nochmal upgraded, in den letzten Wochen gab es keine Crashes mehr. Hatte sonst nicht viel geändert. Kanns noch nicht mit Sicherheit sagen. Ich denke du kannst das Ticket erstmal schließen wenn sonst niemand ein Problem hatte (So ein Ticket hilft ja auch Leute zu triggern falls sie das auch haben). Denke aber es war kein jarvis issue.

CC1337 commented 3 years ago

Hi @Zefau, ich habe in den letzten Tagen vermehrt mit jarvis gearbeitet und bin mir dadurch jetzt ziemlich sicher, dass die Crashes mit dem Aufruf der jarvis UI in Zusammenhang stehen. Nicht einmal notwendigerweise dem Speichern einer Config. Ich habe mal das node modul segfault-handler installiert, aber leider nicht wirklich brauchbare stacktraces erhalten:

PID 455 received SIGSEGV for address: 0x4
/opt/iobroker/node_modules/segfault-handler/build/Release/segfault-handler.node$
/lib/arm-linux-gnueabihf/libc.so.6(+0x25cb0)[0xf77fbcb0]

Kannst du mir sagen, wie ich ggf. detaillierteres Logging seitens webserver Adapter oder jarvis Adapter aktivieren/einbauen kann, um evtl. heraus zu finden, bei welcher Aktion das passiert? Vielleicht ist ja einfach ein bestimmter state typ/Wert verantwortlich, weshalb das so unregelmäßig reproduzierbar ist. Das Muster ist inzwischen aber, wenn ich jarvis nicht aufrufe, scheint es keinen Absturz zu geben. Vielleicht wird einfach etwas am iobroker abgefragt/ausgelöst, das dann zum Absturz führt.

EDIT: jarvis 2.1.0-rc.5

Zefau commented 3 years ago

wie sieht's mit v3 aus?