UNSOLVED ioBroker (JS Controller) stürzt alle 6-8 Tage ab

[darkiop]

Der Kollege ioBroker hat heute wieder das zeitliche gesegnet .... ich helfe mir jetzt mit einem kleinen Bash Skript das den Docker Container neu startet (läuft alle 15min):

#!/bin/bash
if [[ $(sudo docker exec -it iobroker-odin sh -c "iobroker status") = *not* ]]; then
  echo "$(date '+%Y-%m-%d %H:%M:%S') ioBroker Prozess im Container ist nicht aktiv,  Container wird neu gestartet." 2>&1 | tee /volume1/docker/check-iobroker.log
  sudo docker restart iobroker-odin 2>&1 >/dev/null
else
  echo "$(date '+%Y-%m-%d %H:%M:%S') ioBroker Prozess im Container ist aktiv." 2>&1 | tee /volume1/docker/check-iobroker.log
fi

[simatec]

Was mir hier in der ganzen Diskussion aufgefallen ist, dass hier diskutiert wird, ob backitup an dem Absturz schuld ist, aber kein einziger Log im debug Modus von backitup mal gepostet wird.
Backitup kann vom Aufbau der Backup-Ausführung nicht der Verursacher sein.

Eventuell müssten bei euch mal die Rechte kontrolliert werden.
Dafür gibt es einen Fix für den iobroker Installer (siehe Signatur).

Beim Minimal Backup wird der gleiche Prozess aufgerufen, wie beim manuellen Backup über Konsole mit "iobroker backup".

Wenn ihr bei einem Total Backup iobroker stoppt, werden ebenfalls die gleichen Befehle aufgerufen wie beim manuellen starten und stoppen von iobroker.
Wenn euren iobroker User die Rechte fehlen, kann auch dies dazu führen, dass iobroker nicht mehr gestartet wird.

Auch besteht die Möglichkeit, des fehlenden RAM.
Bei einem Total Backup wird der komplette iobroker Ordner gepackt, was je nach Installationsgröße schon etwas RAM benötigt.
Um hier aber weiter Spekulationen auszuschließen, wäre es wichtig die Instanz von backitup mal auf debug zu stellen und dann im Log zu schauen, was passiert.

[darkiop]

Hallo @simatec,

hatte in der Vergangenheit keine Logs gefunden die auf den Absturz hinwiesen. Habe jetzt aber backitup sowohl in den Optionen selbst als auch die Instanz in den Debug Modus gesetzt. Beim nächsten mal wird dann nochmal geschaut.

Bin allerdings sehr sicher das backitup der Auslöser ist (was ja nicht bedeuten muss das backitup 'Schuld' ist :)), denn

• Die Uhrzeit des Absturzes stimmt immer mit der Uhrzeit des Backups (bei mir nur das Standard + CCU Backup) überein
• Kontrolliert man nach dem Absturz mittels ps -ef die Prozesse sieht man das der js-controller Prozess mit dem Backup Aufruf noch läuft (aber nichts macht, denn die Kontrolle kann durchaus auch mal einige Stunden nach dem Absturz gewesen sein).
• Im folgenden Screen sieht man das es beim minimal Backup (bei mir) passieren muss (immer alle 4-6 Tage ...):

Bei manuellen Backups direkt auf der Shell bzw. aus dem ioBroker WebUI heraus ist mir das Verhalten noch nicht aufgefallen. Werde das aber ggf. heut einfach einige viele male von Hand starten und beobachten.

ioBroker läuft bei mir im Docker Container unter root - also noch ohne Installfix ... der letzte vor ein paar Wochen ging schief, hatte noch keine Zeit das nochmal anzugehen. Therotisch stehen dem Container 12GB RAM zur Verfügung, das sollte also gut ausreichen.

Grüße Thorsten

[darkiop]

Ok - Update: Habe einige Backups auf der Shell laufen lassen und dabei geht auch der js-controller irgendwann auf die Bretter:

[eumats]

Hi. Ich habe das gleiche Problem auf einem Raspi3. Alle 3-4 Tage stürzt auch bei mir der js-controller im Zeitpunkte des Backups (minimal) ab. Mit einer geänderten Backupzeit ist auch die Absturzzeit des js-controllers auch "gewandert". Das Komprimieren in gz scheint den Rechner dabei lahm zu legen.
Ich habe bei Backitup den Debug-Level auf silly gesetzt. Anbei die Ausgaben. Aus meiner Sicht ist nichts besonderes zu sehen. Außer das 2min nach dem Start des Backup der Raspi faxen macht...

Wäre ein "nice -n 19" für das tar Kommando vielleicht eine Möglichkeit der Lösung?

2019-05-02 02:00:10.054 - silly: backitup.1 inMem message backitup.1.oneClick.* backitup.1.oneClick.minimal val=true, ack=true, ts=1556755210039, q=0, from=system.adapter.backitup.1, user=system.user.admin, lc=1556755210039
2019-05-02 02:00:20.242 - debug: backitup.1 [minimal/mount] done
2019-05-02 02:02:47.757 - debug: backitup.1 [minimal/minimal] done
2019-05-02 02:02:47.881 - silly: backitup.1 transport close
2019-05-02 02:02:47.916 - debug: backitup.1 [minimal/cifs] done
2019-05-02 02:02:47.923 - debug: backitup.1 [minimal/clean] done
2019-05-02 02:02:47.927 - debug: backitup.1 [minimal/telegram] [minimal] used Telegram-Instance: telegram.0
2019-05-02 02:02:47.937 - debug: backitup.1 sendTo "send" to system.adapter.telegram.0 from system.adapter.backitup.1
2019-05-02 02:02:47.937 - debug: backitup.1 [minimal/telegram] done
2019-05-02 02:02:48.101 - error: cloud.0 Ping timeout
2019-05-02 02:02:48.606 - warn: web.0 Reconnection to DB.
2019-05-02 02:02:48.710 - warn: web.0 Reconnection to DB.
2019-05-02 02:02:48.713 - warn: backitup.1 Reconnection to DB.
2019-05-02 02:02:48.636 - warn: sonos.0 Reconnection to DB.
2019-05-02 02:02:48.729 - warn: sonos.0 Reconnection to DB.
2019-05-02 02:02:48.710 - warn: admin.0 Reconnection to DB.
2019-05-02 02:02:48.741 - warn: backitup.1 Reconnection to DB.
2019-05-02 02:02:48.743 - warn: admin.0 Reconnection to DB.
2019-05-02 02:02:48.828 - warn: shelly.0 Reconnection to DB.
2019-05-02 02:02:48.881 - warn: shelly.0 Reconnection to DB.
2019-05-02 02:02:48.894 - debug: backitup.1 statesDB connected
2019-05-02 02:02:48.912 - debug: backitup.1 statesDB connected
2019-05-02 02:02:48.952 - warn: cloud.0 Reconnection to DB.
2019-05-02 02:02:48.930 - warn: sayit.0 Reconnection to DB.
2019-05-02 02:02:49.020 - warn: cloud.0 Reconnection to DB.
2019-05-02 02:02:49.045 - info: backitup.1 starting. Version 1.1.4 in /opt/iobroker/node_modules/iobroker.backitup, node: v8.15.1
2019-05-02 02:02:49.060 - warn: sayit.0 Reconnection to DB.
2019-05-02 02:02:49.011 - warn: deconz.0 Reconnection to DB.
2019-05-02 02:02:49.057 - warn: text2command.0 Reconnection to DB.
2019-05-02 02:02:49.163 - warn: deconz.0 Reconnection to DB.
2019-05-02 02:02:49.192 - warn: text2command.0 Reconnection to DB.
2019-05-02 02:02:49.319 - warn: tradfri.0 Reconnection to DB.
2019-05-02 02:02:49.475 - debug: backitup.1 mount activ... umount in 2 Seconds!!
2019-05-02 02:02:49.756 - warn: tradfri.0 Reconnection to DB.
2019-05-02 02:02:49.760 - info: backitup.1 [minimal] backup was activated at 02:00 every 1 day(s)
2019-05-02 02:02:49.755 - warn: telegram.0 Reconnection to DB.
2019-05-02 02:02:49.803 - debug: backitup.1 [minimal] 10 00 02 */1 * *
2019-05-02 02:02:49.803 - info: backitup.1 [total] backup was activated at 02:30 every 3 day(s)
2019-05-02 02:02:49.822 - debug: backitup.1 [total] 10 30 02 */3 * *
2019-05-02 02:02:49.965 - debug: backitup.1 [minimal/history] backitup.1.history.html
2019-05-02 02:02:49.977 - warn: telegram.0 Reconnection to DB.
2019-05-02 02:02:49.999 - info: admin.0 starting. Version 3.6.0 in /opt/iobroker/node_modules/iobroker.admin, node: v8.15.1
2019-05-02 02:02:50.001 - warn: javascript.0 Reconnection to DB.
2019-05-02 02:02:50.031 - info: backitup.1 starting. Version 1.1.4 in /opt/iobroker/node_modules/iobroker.backitup, node: v8.15.1
2019-05-02 02:02:50.067 - debug: backitup.1 [minimal/umount] mount activ... umount in 60 Seconds!!
2019-05-02 02:02:50.077 - debug: backitup.1 mount activ... umount in 2 Seconds!!
2019-05-02 02:02:50.186 - info: backitup.1 [minimal] backup was activated at 02:00 every 1 day(s)
2019-05-02 02:02:50.220 - info: admin.0 starting. Version 3.6.0 in /opt/iobroker/node_modules/iobroker.admin, node: v8.15.1
2019-05-02 02:02:50.241 - info: javascript.0 starting. Version 4.1.12 in /opt/iobroker/node_modules/iobroker.javascript, node: v8.15.1
2019-05-02 02:02:50.228 - info: admin.0 requesting all states
2019-05-02 02:02:50.229 - info: admin.0 requesting all objects
2019-05-02 02:02:50.231 - info: admin.0 Request actual repository...
2019-05-02 02:02:50.256 - debug: backitup.1 [minimal] 10 00 02 */1 * *
2019-05-02 02:02:50.257 - info: backitup.1 [total] backup was activated at 02:30 every 3 day(s)
2019-05-02 02:02:50.293 - debug: backitup.1 [total] 10 30 02 */3 * *
2019-05-02 02:02:50.303 - info: javascript.0 requesting all states
2019-05-02 02:02:50.305 - info: javascript.0 requesting all objects
2019-05-02 02:02:50.336 - info: javascript.0 starting. Version 4.1.12 in /opt/iobroker/node_modules/iobroker.javascript, node: v8.15.1
2019-05-02 02:02:50.340 - info: javascript.0 requesting all states
2019-05-02 02:02:50.341 - info: javascript.0 requesting all objects
2019-05-02 02:02:50.342 - warn: javascript.0 Reconnection to DB.
2019-05-02 02:02:50.462 - error: web.0 port 8082 already in use
2019-05-02 02:02:50.516 - error: host.homepi-client instance system.adapter.web.0 terminated with code 1 ()
2019-05-02 02:02:50.517 - info: host.homepi-client Restart adapter system.adapter.web.0 because enabled
2019-05-02 02:02:50.683 - error: javascript.0 Longitude or latitude does not set. Cannot use astro.
2019-05-02 02:02:50.693 - error: javascript.0 Error in callback: TypeError: Cannot read property 'toLocaleTimeString' of undefined
2019-05-02 02:02:50.694 - error: javascript.0 at Object. (script.js.common.SK_Astro:346:47)
...

[simatec]

@darkiop
Also kann man backitup ausschließen.
Kamen Fehlermeldungen auf der Konsole?

[simatec]

@eumats
Das backup ist schon durch, bevor dein iobroker abstürzt.
Hast du mal dein Telegram überprüft? Beim senden der Telegram Nachricht bricht etwas ab

[eumats]

Hhmmm. Aber die Nachricht per Telegramm über das erfolgreiche Backup kam ohne Probleme an...

[simatec]

@eumats
Was passiert, wenn du das minimal über Konsole machst?

[darkiop]

@simatec Backitup kann mal als Ursache ausschließen, ist nur der Auslöser Ich stelle das heut Mittag nochmal nach - mit einem Blick auf das ioBroker/System Log.

[eumats]

@simatec
Da muss ich etwas ausholen....
Den von mir beschriebenen Fehlerfall konnte ich wieder auflösen, in dem ich admin und javascript wieder neu gestartet hatte. Aber in diesem Zustand, also nach dem Fehler aus meinem oben geposteten Log, konnte ich mit iobroker backup kein Backup mehr starten. Die Prozesse zum Backup wurden zwar gestartet, aber es kam nie zum Ende.
Erst nach einem Reboot beider Raspi (Master und Slave im Multihostsystem) konnte ich iobroker backup wieder ausführen. Innerhalb von 1-2 min konnte ich mehrfach (5-6x) ein Backup ohne Problem oder Absturz erzeugen.

Ich bin nun etwas ratlos, warum ist wirklich liegt, bzw. wo ich weiter suchen kann...

[eumats]

@darkiop
Kannst Du bitte mal Dein testbackup Skripte posten. Dann lasse ich das heute Abend auch mal auf meinen Raspi los...

EDIT: Hat sich erledigt. Ich habe mir selbst eins gebaut.

[eumats]

Ich habe jetzt mal 45min zyklisch Biobroker backup mit 30sek Pause dazwischen durchlaufen lassen. Und bisher ist das Problem nicht aufgetreten.

Mein Fehlerbild ist sehr ähnlich zu dem folgenden Thread:
https://forum.iobroker.net/topic/21541/probleme-mit-iobroker-bin-mit-meinem-latein-am-ende

Wobei es da auch noch keine Lösung gibt...

[darkiop]

Ich kann den Absturz immer wieder nachstellen, im ioBroker Log zu dem Zeitpunkt leider keine Meldungen: