Unerwarteter, selbständiger Neustart von ioBroker

LoxDUS

Liebe ioBroker Gemeinde,

vielleicht kann mir jemand einen kleinen Tipp geben. Heute Nacht hat mein komplettes ioBroker Systemen einen völlig unerwarteten Neustart hingelegt und ich weiß nicht warum das ganze passiert ist. Ich hatte gestern bereits gesehen dass das System mit Speicherproblemen zu kämpfen hatte. Die äußerten sich so, dass ich teilweise laut Anzeige im Admin Adapter nur noch 40MByte freien Speicher hatte. Das System lief aber trotzdem stabil. Auf dem Server selbst, auf dem ioBroker läuft, habe ich gestern gesehen (top-Befehl) das der "iobroker.js-con" Prozess ca. 50% des Speichers verbraucht hatte.

Heute Nacht kann ich folgendes in dem Logfile sehen:

Um ca. 01:04:35 Uhr gab es anscheinend Probleme mit dem ALEXA Adapter und um 01:12:00 gab es dann einen
error: host.IOBROKER2 uncaught exception: spawn ENOMEM
Fehler

...
2020-07-09 00:22:42.665 - info: javascript.0 (8118) script.js.common.LichtSteuerung: DE_S_LKUUS_1
2020-07-09 00:22:42.667 - info: javascript.0 (8118) script.js.common.LichtSteuerung: AUS
2020-07-09 00:30:00.012 - warn: host.IOBROKER2 instance system.adapter.odl.0 already running with pid 28886
2020-07-09 00:30:00.103 - info: javascript.0 (8118) script.js.common.SzenenSteuerung: Mitternacht - Tageswechsel
2020-07-09 00:32:06.865 - info: info.0 (2767) Popup news was read...
2020-07-09 01:02:06.723 - info: info.0 (2767) Popup news was read...
2020-07-09 01:04:35.793 - info: alexa2.0 (24155) Alexa-Push-Connection disconnected - retry: Retry Connection in 5s
2020-07-09 01:04:40.013 - error: iot.0 (2386) Error by device connection: "premature close"
2020-07-09 01:04:40.156 - info: iot.0 (2386) Connection changed: disconnect
2020-07-09 01:04:40.157 - info: iot.0 (2386) Connection lost
2020-07-09 01:04:43.281 - info: alexa2.0 (24155) Alexa-Push-Connection established. Disable Polling
2020-07-09 01:04:45.512 - info: iot.0 (2386) Connection changed: connect
2020-07-09 01:12:00.073 - error: host.IOBROKER2 uncaught exception: spawn ENOMEM
2020-07-09 01:12:02.103 - info: deconz.0 (14934) cleaned everything up...
2020-07-09 01:12:02.073 - info: shelly.0 (27063) Closing Adapter
...

danach fährt ioBroker alle seine Adapter herunter, beendet alle Javascript Programme und um 01:13:34Uhr fährt das System dann wieder hoch:

...
2020-07-09 01:12:07.055 - info: nuki-extended.1 (2339) Terminated (START_IMMEDIATELY_AFTER_STOP): Without reason
2020-07-09 01:12:07.054 - info: backitup.0 (9737) Terminated (START_IMMEDIATELY_AFTER_STOP): Without reason
2020-07-09 01:12:07.069 - info: upnp.0 (9275) Terminated (START_IMMEDIATELY_AFTER_STOP): Without reason
2020-07-09 01:13:34.498 - info: host.IOBROKER2 iobroker.js-controller version 2.2.9 js-controller starting
2020-07-09 01:13:34.507 - info: host.IOBROKER2 Copyright (c) 2014-2020 bluefox, 2014 hobbyquaker
2020-07-09 01:13:34.509 - info: host.IOBROKER2 hostname: IOBROKER2, node: v10.17.0
2020-07-09 01:13:34.511 - info: host.IOBROKER2 ip addresses: <IP Adresse von mir hier aus dem Log entfernt>
2020-07-09 01:13:36.828 - info: host.IOBROKER2 connected to Objects and States
2020-07-09 01:13:37.394 - info: host.IOBROKER2 54 instances found
2020-07-09 01:13:37.602 - info: host.IOBROKER2 starting 29 instances
...

Heute Morgen ist mir das ganze dann aufgefallen weil in meinem "Hausdisplay" eine Lücke in den Temperaturaufzeichnungen war (der SQL-Datenbank brauchte wieder einen "flush hosts" nach dem Neustart des Systems).

Nach dem Neustart habe ich auch keine Speicherprobleme mehr. Jetzt braucht auch der "iobroker.js-con" Prozess nur noch ca. 4,7% des Speichers:

Könnt ihr mir helfen herauszufinden warum es zu dem Neustart gekommen ist?
Das ganze System hat ca. 7 Monate lang ohne Problem seinen Dienst getan.

Vielen Dank,

Artur

Informationen zu meinem System:
Plattform: linux
Betriebssystem: linux
Die Architektur: x64
CPUs: 4
Geschwindigkeit: 735 MHz
Modell: Intel(R) Atom(TM) x5-Z8350 CPU @ 1.44GHz
RAM: 3.7 GB
System-Betriebszeit: 211 T. 20:06:25
Node.js: v10.17.0
NPM: 6.11.3
Datenträgergröße: 52.1 GiB
Datenträger verfügbar: 46.9 GiB
Adapter-Anzahl: 355
Betriebszeit: 07:49:50
Aktive Instanzen: 21

arteck

@LoxDUS was soll man mit den LOG schnippseln.. poste mal den kompletten LOG bitte.. meine Glaskugel ist gerade zur politur

LoxDUS

Nunja, nach dem Neustart sind im Log ca. 5 Millionen Fehlermeldungen mit dem Hinweis, dass nicht auf die Datenbank zugegriffen werden kann. Aber das ist ja glaube ich nicht von interresse. Vor dem Runterfahren sieht, zumindest für mich, alles im LOG OK aus:
Log09_07_2020.txt

Ich glaube interressant ist dann auch das Log vom Vortag:
Log08_07_2020.txt

Da kann ich nichts Auffälliges entdecken. Der ERROR um 09:16Uhr im javascript.1 adapter kommt von mir weil ich da versucht hatte mit einem regulären Ausdruck Auf mehrere "Events" zu triggern. "javascript.1" nutze ich immer zum ausprobieren von Codeschnipseln.

Vielen Dank,

Artur

arteck

hier läuft ein adapter doppelt

2020-07-09 00:30:00.012 - warn: host.IOBROKER2 instance system.adapter.odl.0 already running with pid 28886

und hier geht di der speicher aus

2020-07-09 01:12:00.073 - error: host.IOBROKER2 uncaught exception: spawn ENOMEM

Homoran · 2020-07-09 01:12:00.073 - error: host.IOBROKER2 uncaught exception: spawn ENOMEM

@arteck sagte in Unerwarteter, selbständiger Neustart von ioBroker:

2020-07-09 01:12:00.073

@LoxDUS
läuft bei dir Backitup um diese Zeit?

Glasfaser

@LoxDUS

error: sql.0 (4742) Error: ER_HOST_IS_BLOCKED: Host 'OpenWRT.fritz.box' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

Link Text

LoxDUS · 2020-07-09 01:12:00.073 - error: host.IOBROKER2 uncaught exception: spawn ENOMEM

@arteck
Ich habe den ODL Adapter mittlerweile auch deinstalliert. Die Fehlermeldung hatte ich aber seit der Installation des Adapters und dachte deswegen das es "OK" sei.
Wie geschrieben, ich hatte am Tag zuvor bereits gesehen das der Speicher knapp war. Der dümpelte immer so bei ca. 40MByte rum. Da aber alles an dem Tag Problemlos funktionierte habe ich dem keinen weiteren Gedanken gewidmet...

@Homoran
Mein Backup läuft alle 7 Tage Nachts um 2:00Uhr. Am 08.07.2020 wurde um 02:01Uhr das letzte Backup erstellt. Also einen Tag vorher.

@Glasfaser
Ja, die Fehlermeldung kommt wenn ich das System, bzw. die SQL-Adapter Instanz sql.0 neu starte. Dann muss ich in der MYSQL Datenbank den Befehl "flush hosts" absetzen und alles läuft wieder. Die Fehlermeldungen kommen ja aber erst nach dem automatischen Neustart des Systems.

@Alle
Eure Antworten zeigen mir das ich mehr in der Vergangenheit des Systems forschen muss. Warum hatte ich nur noch 40MByte freien Speicher?
Ich lasse jetzt mal die verschiedenen Speicherverbräuche, die man so in den Systemobjekten findet in die History Datenbank schreiben. Vielleicht kann man da ja Sprünge erkennen und dann ggf. nachforschen ob zu diesem Zeitpunkt etwas "besonderes" mit dem System passiert ist.

Vielen Dank für eure Antworten.

Artur

LoxDUS

@Glasfaser
Danke für den Hinweis, habe für meine DB auch die Anzahl der maximalen Verbindungen auf 200 erhöht:

set global max_connections = 200;

Glasfaser

@LoxDUS

Schon mal ein Fehler weniger ...... ;)

LoxDUS

So, habe jetzt mal ein paar Speicherdaten über ca. 2 Wochen aufgenommen.

So wie es sich für mich darstellt gibt es nur einen Weg, und der ist mit dem Speicherverbrauch nach oben. Gut sieht man es an der hellblauen kurve. Am linken Rand schwank die noch um den Mittelwert von ca. 250MByte. nach ungefähr zwei Wochen schwank die Kurve um einen Wert von ca. 260MByte. Das ist nicht viel aber es ist ja auch nur der Wert von einem Adapter und ich habe ca. 24 Adapter Instanzen am laufen.

Bei der erwähnten hellblauen Kurve handelt es sich um den javascript Adapter (javascript.0.actual_used_heap).

Das Schwanken bzw. die Sägezahnkurve kommt ja, so denke ich zumindest von java und der garbage collection. Den Speicherleck kann ich mir aber nicht erklären zumal dieser Aufwärtstrend bei fast allen Adaptern die ich installiert habe zu sehen ist.

Hat jemand eine Idee? Ich würde sonst die nächsten Tage mal auf die neusten Adapterversionen updaten und dann mal von allen Instanzen die heap speicherverbräuche loggen. Aktuelle hänge ich mit vielen Adaptern mit dem Update hinterher...

Viele Grüße,

Artur

LoxDUS

Liebe ioBroker Gemeinde,

irgendwie bekomme ich das nicht in den Griff. Ich habe jetzt alles auf dem neuesten Stand gebracht - bis auf die node-Version.
Ich habe jetzt das Gefühl dass das System noch mehr Speicher braucht. Könnt ihr mal prüfen ob eure Adapter auch soviel Speicher verbrauchen:

sind das normale Werte?

Was mich jetzt absolut wundert ist, dass nach meiner Updateaktion zwar wieder 57% des Speichers frei waren (Update war in dem unteren Bild ungefähr in der Mitte) aber jetzt innerhalb von 3 Tagen der Speicher wieder auf 21% zusammen geschrumpft ist. Warum? Ich habe doch nichts gemacht.

Glasfaser

@LoxDUS sagte in Unerwarteter, selbständiger Neustart von ioBroker:

sind das normale Werte?

sieht recht normal aus , verglichen mit meinen 42 Instanzen die laufen .

Beispiel einer Momentaufnahme :

LoxDUS

@Glasfaser Vielen Dank für die Rückmeldung. Dann muss ich mal an anderer Stelle suchen um herauszufinden warum mein Speicherverbrauch immer größer wird.

Community Forum

NEWS

Unerwarteter, selbständiger Neustart von ioBroker

Support us

728

32.6k

82.2k

1.3m