History: Restart alle paar Minuten - Downgrade geht nicht

[klassisch]

Hatte gerade wieder einen event ohne erkennbare Ursache. Bin nach Hause gekommen, HM-Öffnungen von Garage, Keymatic, ein paar Bewegungsmelder beim Einräumen der Einkäufe, Beim Firefox (Rechner lief durch) den Admin in focus nehmen und da wars schon da. Wahrscheinloch war das event schon vorher.

! 2018-03-24 12:31:20.515 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9002066.1.ABS_HUMIDITY, last-value=6.13, new-value=6.38, ts=1521891065485 2018-03-24 12:31:20.545 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.KEQ019xxxx.1.BRIGHTNESS, last-value=219, new-value=218, ts=1521891072585 2018-03-24 12:31:20.547 - [34mdebug[39m: history.0 Min-Delta ignored because no number hm-rpc.0.KEQ019xxxx.1.MOTION, last-value=false, new-value=true, ts=1521891072594 2018-03-24 12:31:20.549 - [34mdebug[39m: history.0 value not changed hm-rpc.0.KEQ019xxxxx.1.INSTALL_TEST, last-value=true, new-value=true, ts=1521891072599 2018-03-24 12:31:20.551 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.STATE, last-value=false, new-value=false, ts=1521891072707 2018-03-24 12:31:20.553 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.WORKING, last-value=false, new-value=false, ts=1521891072716 2018-03-24 12:31:20.758 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-24 12:31:20.860 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-24 12:31:21.513 - [34mdebug[39m: history.0 statesDB connected 2018-03-24 12:31:21.561 - [34mdebug[39m: history.0 statesDB connected 2018-03-24 12:31:22.086 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-24 12:31:22.377 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-24 12:31:22.950 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-24 12:31:22.952 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-24 12:31:22.953 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-24 12:31:22.953 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-24 12:31:22.954 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-24 12:31:22.955 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-24 12:31:22.956 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG 2018-03-24 12:31:22.957 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT 2018-03-24 12:31:22.958 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL !
….

`2018-03-24 12:31:42.975  - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.Humid-SHT31
2018-03-24 12:31:42.976  - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.Humid-abs-SHT31
2018-03-24 12:31:42.977  - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.DewTemp-SHT31
2018-03-24 12:32:15.411  - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.STATE, last-value=false, new-value=false, ts=1521891135395
2018-03-24 12:32:15.459  - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.WORKING, last-value=false, new-value=false, ts=1521891135400
2018-03-24 12:32:15.463  - [34mdebug[39m: history.0 value not changed hm-rpc.0.KEQ019xxxx.1.BRIGHTNESS, last-value=218, new-value=218, ts=1521891135403
2018-03-24 12:32:15.466  - [34md[/code]` 
>! Mäßige peaks bei Auslastung CPU1 von 0.22 auf 1.7 und bei der Temp von 27 auf 36°C aber mutmasslich als Folge des history enable events.
>! Könnte folgende Vorwärtsstrategie aufgehen?
>! - Das Problem scheint ja ein lokales zu sein. Andere haben das nicht, warum auch immer. Könnte jetzt den Rechner wechseln aber worauf? Eigentlich lief der OPi stabil und recht entspannt. Macht es Sinn History auf einen anderen Rechner auszulagern?
>! - Kann noch ein, zwei Tage auf gut Glück suchen. Mehr als gut Glück wirds wohl nicht, zumindest sehe ich keine weitere Möglichkeit mit meinen Mitteln und Kenntnissen.
>! - Mein ioBroker ist derzeit massiv downgegradet, das hat keine lange Zukunft.
>! - Kann dann in einer Nachtschicht ioBroker neu aufsetzen.
>! - Wenn dann das Problem immer noch besteht (wovon ich ausgehe), müßte ich History bei mir aufgeben. 
>! - Wäre Influx-DB die geeignete Vorwärtsstrategie?
>! - Habe irgendwo gelesen, daß man den Datenbestand von history nach InfluxDB portieren kann. Das würde ich versuchen.
>!  Mein History-Datenbestand sind ca. 1.3 GByte auf einer 32GB SSD 
>! - Nehme an daß FLOT dann auch mit Influx-DB arbeitet, oder gibt es da andere Tools?

[apollon77]

Naja, die andere Frage ist - was exakt sind denn die Nebenwirkungen des History-Restarts?! Wenn es nur ein bissl logging ist … loglevel hochsetzen und fertig

Aber Du hast Recht schon komisch und ich wüsste jetzt weitersuchtechnisch auch nicht weiter.

Ist der "History" der einzige Adapter der hier und da das problem mit dem Reconnect hat? Oder andere auch?

Die Frage ist wenn Du auf was anderes umsteigst (ich bin InfluxDB Fan, andere nehmen eher SQL) ob das Problem nicht mitwandert - genau weil es eher ein "lokales" ist

[klassisch]

Beim upgegradeten System kamen die history restarts viel zu oft. eher im 10 min Takt. Und jedes Mal dauerte die enablerei länger. Und irgendwann kamen rote overloadmeldungen und IoBroker hat sich neu gestartet. Völlig ungesund.

Habe jetzt mal den USB-SATA - SSD Adapter modifiziert, so daß sicher ausreichend Strom und Pufferung zur Verfügung stehen wird. Falls es je daran gelegen haben sollte….

Wenn der Fehler mitwandert, dann weiss ich genauer, daß es an der HW oder armbian liegt. Dann muß ich mich nach einer anderen Plattform umschauen.

[klassisch]

Habe jetzt nochmals ein Eperiment gestartet:

Aufgrund der Rechteerfahrungen beim Versuch influxDB oder MariaDB zu installieren und die Daten auf die FAT32 formatierte SSD zu veragern, habe ich meine Reserve-/Spiel-SSD mit ext4 formatiert und history auf diese ext4 SSD umgestellt.

Das läuft jetzt 6h stabil ohne history-Neustarts. Wenn es morgen noch stabil läuft, werde ich ioBroker wieder auf den neuesten Stand bringen und weiter beobachten.

Wenn es nichts wird, dann werde ich mein altes Notebook (i5-3210M, 8GB; 200GB SSD und 1TBHDD), das jetzt im Hobbyraum Dienst tut und mit dem gelegentlichen Auslesen von Messgeräten und Recherchen nicht ausgelastet ist, als ioBroker Plattform ausbauen. Bin gerade bei der Langzeit Energieverbrauchsmessung; 12W im idle kann ich mir dann auch noch leisten.

Keine Ahnung wie gut sich Win 10 und ioBroker vertragen, aber so wie es die letzten Tage und Wochen war, geht es auch nicht weiter. Kann ja den Mulithost nutzen und mit dem OPI z.B. den RFLink weiter betreiben. Könnte mir vorstellen, daß IoBroker und USB durch Windows durch Probleme macht.

[Homoran]

Was die Formatierung der SSD/HDD angeht kann ich mich im Moment nur auf die uralte Cubietruck-Anleitung beziehen, wo die HDD am SATA Port hängt.

Hier war explizit ext4 gefordert.

Alles andere hatte auch nicht geklappt.

ich kann mir vorstellen, dass das bei USB-Platten genau so ist, auch wenn es sich "nur" um eine Daten-Platte handelt.

Gruß

Rainer

[klassisch]

Hat ja das letzte Jahr über gut funktioniert. Die ersten Probleme gabs mit dem Kernelupdate Ende Januar/Anfang Februar und dann ganz massiv mit einen großflächigen ioBroker-Update.

Habe die letzten Tage versucht parallel zu Hilstory influx oder MariaDB mit der FAT32-SSD in Betrieb zu nehmen und das hat nicht funktioniert. Ein Rechteübertragungsbefehl lief nicht durch und dann startete die Datenbank nicht mehr. Bei den entsprechenden Recherchen habe ich gelesen, daß FAT32 keine Rechte verwalten kann und deshalb einige Applikationen damit nicht gehen. Es gibt mittlerweile Leute, die NTFS als generelles Austauschformat empfehlen, weil es damit am wenigsten Probleme gäbe.

Bin gespannt wie es jetzt läuft. Falls der Umstieg auf mein Win 10 Notebook erforderlich werden sollte: Wie sind denn die Erfahrungen der Windows- ioBroker Nutzer?

[klassisch]

Seit der Umstellung der Datenplatte von FAT32 auf ext4 vor 40h hatte ich keine history reconecting to DB mehr. Warum verstehe ich nicht, bin aber auch kein Linux Spezialist und habe nach diesem event in meiner Annäherung an Linux wieder einen kräftigen Dämfer erfahren. Ich nehme an, Linux, debian, armbian hat mit dem letzten Kernel-Update Anfang des Jahres die Fähigkeit verloren, ordentlich mit FAT32 umzugehen.

Mein altes Windows 10 Notebook (i5, 8GB) würde im Dauerbetrieb ca. 25 EUR/Jahr an Stromkosten erzeugen. Beim nächsten größeren Problem mit meinem Linux/armbian System wird auf Windows umgestellt. Dann bräuchte ich auch kein Reservesystem mehr zu kaufen, denn da könnte dann im Ernstfall mein jeweiliges Hauptnotebook herhalten. Und gebrauchte Notebooks dieser Kategorie gäbe es für ca. 200EUR mit 2 jähriger Garantie. Was mich noch am meisten abhält sind die seit Win 10 nicht mehr voll kontrollierbaren update-Zeitpunkte.

Vielen Dank jedenfalls für alle Zeit, Sachverstand und Tipps bei der Analyse der logs etc.

[apollon77]

Hochinteressant … hätte nicht erwartet das es am Filesystem liegt ... Auch wieder was gelernt

[klassisch]

Ich hätte es auch nicht erwartet, zumal es ja bislang klaglos funktioniert hat. Weiss auch nicht, ob die Erkenntnis verallgemeinerbar ist und vielleicht wäre nach dem nächsten Kernel-Update der Spuk vorbei. Das sind halt die Kosten der Vielfalt, um es mal neutral zu formulieren.

[TomT]

Hallo Klassisch,

deine Erkenntnisse sind klasse !

Schön das dein System wieder läuft und beim durchlesen dieses Threats bin ich meinem eigenen Problem wahrscheinlich auch auf die Schliche gekommen.

Seit dem letzten Armbian Update vor 2 Wochen hatte ich nämlich auch große Probleme, an meinen mit FAT32 gemounteten USB-Stick ranzukommen.

Das Verzeichnis in media war unter rootanmeldung angeblich nicht verfügbar, wollte ich mit mkdir das Verzeichnis neu anlegen, hat armbian bemotzt, es wäre schon vorhanden.

Strange :shock:

Werde die Tage mal schauen, was passiert, wenn ich den Stick ext4 formatiere und einbinde….

Danke für das teilen deiner Erfahrungen !

Grüße

Tom

[klassisch]

Viel Erfolg, keine Ahnung, ob es bei Dir ähnlich gelagert ist. Aber irgendetwas ist mit armbian und FAT32 passiert.

Mein System ist wieder seit 47h stabil.

BTW: Bei ali ist gerade wieder ein Sale. Man bekommt Kingdian SSD 32GB für <15EUR und die etwas performantere 60GB für <21EUR, Orico 20UT Adapter für 4,50EUR. Nicht, daß man eine solche Datenmenge in den nächsten Jahren brauchen würde, aber es soll sich kein Performance-Bottleneck auftun und ich war froh, noch eine Reserve da zu haben…

[klassisch]

So, nach update auf 1.8.5 ist das Problem wieder da! Alle paar Stunden startet history neu und hinteläßt Psudomesswerte und versaut die Messkurven:
Siehe Grüne Kurve. Tankinhalt wird nur einmal am Tang um 01:11 gemessen. Durch die sporadischen History-Neustarts werden unechte Messpunkte eingezeichnet und die Kurve verfälscht.
Was tun? Downgraden?
Log:

2019-03-09 21:39:30.544  - warn: history.0 Reconnection to DB.
2019-03-09 21:39:30.702  - warn: history.0 Reconnection to DB.
2019-03-09 21:39:30.862  - info: history.0 starting. Version 1.8.5 in /opt/iobroker/node_modules/iobroker.history, node: v6.14.3
2019-03-09 21:39:30.887  - info: history.0 starting. Version 1.8.5 in /opt/iobroker/node_modules/iobroker.history, node: v6.14.3
2019-03-09 21:39:31.846  - info: history.0 enabled logging of system.adapter.admin.0.uptime (Count=1), Alias=false
2019-03-09 21:39:31.848  - info: history.0 enabled logging of system.adapter.admin.0.memRss (Count=2), Alias=false
2019-03-09 21:39:31.849  - info: history.0 enabled logging of system.adapter.admin.0.memHeapTotal (Count=3), Alias=false
2019-03-09 21:39:31.850  - info: history.0 enabled logging of system.adapter.admin.0.memHeapUsed (Count=4), Alias=false
2019-03-09 21:39:31.850  - info: history.0 enabled logging of system.adapter.admin.0.connected (Count=5), Alias=false
2019-03-09 21:39:31.851  - info: history.0 enabled logging of system.adapter.admin.0.alive (Count=6), Alias=false
2019-03-09 21:39:31.851  - info: history.0 enabled logging of system.host.$__hostname__$.mem (Count=7), Alias=false
2019-03-09 21:39:31.852  - info: history.0 enabled logging of system.host.$__hostname__$.memHeapUsed (Count=8), Alias=false
2019-03-09 21:39:31.853  - info: history.0 enabled logging of system.host.$__hostname__$.memHeapTotal (Count=9), Alias=false
2019-03-09 21:39:31.853  - info: history.0 enabled logging of system.host.$__hostname__$.memRss (Count=10), Alias=false
2019-03-09 21:39:31.854  - info: history.0 enabled logging of system.host.$__hostname__$.uptime (Count=11), Alias=false
2019-03-09 21:39:31.855  - info: history.0 enabled logging of system.host.$__hostname__$.load (Count=12), Alias=false
2019-03-09 21:39:31.855  - info: history.0 enabled logging of system.host.$__hostname__$.alive (Count=13), Alias=false
2019-03-09 21:39:31.856  - info: history.0 enabled logging of hm-rpc.0.updated (Count=14), Alias=false
2019-03-09 21:39:31.857  - info: history.0 enabled logging of system.adapter.hm-rpc.0.uptime (Count=15), Alias=false
2019-03-09 21:39:31.858  - info: history.0 enabled logging of system.adapter.hm-rpc.0.memRss (Count=16), Alias=false
2019-03-09 21:39:31.858  - info: history.0 enabled logging of system.adapter.hm-rpc.0.memHeapTotal (Count=17), Alias=false
2019-03-09 21:39:31.859  - info: history.0 enabled logging of system.adapter.hm-rpc.0.memHeapUsed (Count=18), Alias=false
2019-03-09 21:39:31.859  - info: history.0 enabled logging of system.adapter.hm-rpc.0.connected (Count=19), Alias=false
2019-03-09 21:39:31.860  - info: history.0 enabled logging of system.adapter.hm-rpc.0.alive (Count=20), Alias=false
2019-03-09 21:39:31.860  - info: history.0 enabled logging of system.adapter.hm-rega.0.uptime (Count=21), Alias=false
2019-03-09 21:39:31.861  - info: history.0 enabled logging of system.adapter.hm-rega.0.memRss (Count=22), Alias=false
2019-03-09 21:39:31.861  - info: history.0 enabled logging of system.adapter.hm-rega.0.memHeapTotal (Count=23), Alias=false
2019-03-09 21:39:31.862  - info: history.0 enabled logging of system.adapter.hm-rega.0.memHeapUsed (Count=24), Alias=false
2019-03-09 21:39:31.863  - info: history.0 enabled logging of system.adapter.hm-rega.0.connected (Count=25), Alias=false
2019-03-09 21:39:31.863  - info: history.0 enabled logging of system.adapter.hm-rega.0.alive (Count=26), Alias=false
2019-03-09 21:39:31.864  - info: history.0 enabled logging of system.adapter.web.0.uptime (Count=27), Alias=false
2019-03-09 21:39:31.864  - info: history.0 enabled logging of system.adapter.web.0.memRss (Count=28), Alias=false
2019-03-09 21:39:31.865  - info: history.0 enabled logging of system.adapter.web.0.memHeapTotal (Count=29), Alias=false
2019-03-09 21:39:31.865  - info: history.0 enabled logging of system.adapter.web.0.memHeapUsed (Count=30), Alias=false
2019-03-09 21:39:31.866  - info: history.0 enabled logging of system.adapter.web.0.connected (Count=31), Alias=false
2019-03-09 21:39:31.866  - info: history.0 enabled logging of system.adapter.web.0.alive (Count=32), Alias=false
2019-03-09 21:39:31.867  - info: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE (Count=33), Alias=false
2019-03-09 21:39:31.868  - info: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL (Count=34), Alias=false
2019-03-09 21:39:31.868  - info: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG (Count=35), Alias=false

[klassisch]

Der Vollständigkeit halber:
Nach Umstieg auf eine Windows-Notebook alles gut. Der hat genügend Rechenleistung und Bandbreite.
Aber bei der Sichtung der Datenmengen bin ich auf die wahrscheinliche Ursache gestoßen:

• Februar 2019 habe ich alle Datenpunkte in History abonniert, um History zu vervollständigen. Nichts ungewöhnliches an sich.
• Dabei war aber anscheinend die Expertenansicht aktiviert. Und das sollte man bei einer solchen Aktion nicht machen.
• Dadurch wurden auch alle system.adapter. Datenpunkte abonniert. Waen nicht sehr viele, knapp unter 300. Aber die werden sehr häufig geschrieben, so daß jeder Datenpunkt täglich ca. 400kB bis 500kB (für mich nutzlose) Daten und damit den zugehörigen Traffic erzeugt. Dadurch hat sich auch mein tägliches Datenvolumen (für mich) sinnlos verfünffacht. Diesem Daten(raten)-Aufkommen war der OPi nicht wirklich gewachsen.
  Wie gesagt mit einem ordentlichen Windows Notebook kein Problem aber auch da für mich unnötig.