maximum of 1000 setState during boot

[hschief]

@asgothian
Hi, nun zu der Fehlermeldung ... sorry, ja dies ist im Text missvertständlich ausgedrückt. Ich hatte ein kleines Testscript gebaut, bei dem einfach nur alle 10s über die LogDirective die Meldung: in Function ausgegeben wird.

Es gibt leider keine Fehlermeldung ausser maximum 1000 setstate reached. Die Meldungen die zu sehen sind, sind die Ausgaben des Scripts, die eigentlich ja nur 6x Minute erscheinen dürfen.

[hschief]

@thomas-braun said in maximum of 1000 setState during boot:

iob nodejs-update

Update durchgeführt, aktuelle Version ist jetzt: v.18.20.2, Fehler ist aber auch nach dem Update da.

Noch eine zusätzliche Info, wenn ich nach dem start des IOBrokers ein
iobroker restart javascript.0 läuft alles sauber.

Evtl. braucht der JavaScript Adapter andere Dienste die zu diesem Zeitpunkt noch nicht verfügbar sind ... nur eine Idee.

[paul53]

@hschief sagte: Evtl. braucht der JavaScript Adapter andere Dienste die zu diesem Zeitpunkt noch nicht verfügbar sind ... nur eine Idee.

Dann starte mal den schedule() mit einigen Sekunden Verzögerung.

[mcm1957]

@hschief
Falls hier keine Lösung kommt oder wenn klar ist was passiert und das nicht als eh klar zu klassifizieren ist , erstell bitte jedenfalls ein Issue beim Javascript Adapter. Weil so ganz erklärbar ist das Verhaltend derzeit nicht. Und auch wenn ein Startverzögerung der Problem beheben sollte, rege ich an zu prüfen ob die nicht dann gleich zentral im Adapter erfolgen sollte. Das mjuss sich aber jemand ansehen der den Adapter in und auswendig kennt...

[peterfido]

Vielleicht sollte beim Testskript der Zeitstempel geschrieben werden. So könnte man sehen, ob Cron evtl. "denkt", dass es da noch einige Auslösungen in Verzug hat, falls Cron überhaupt "verpasste" Einsätze nachholt.

[hschief]

@mcm57 ich folge mal deinem Rat und mache dies unter dem Adapter als Issue auf.

Ich habe eben noch folgenden Test gemacht:

function Test1() {
    log('In Function','error');
    setState('0_userdata.0.Allgemein.TestBoot', 'test', false);
};


log('Script Test1 gestartet:','error');


setTimeout(function(){schedule("*/10 * * * * *", Test1 )},50000);

Hier müsste beim Boot im Log ja als erstes der Log mit dem Text: "Script Test1 gestartet" erscheinen und dann deutlich später die Meldung: "In Function" alle 10s.

Das Ergebnis beim Boot sieht aber wie Folgt aus: 12:51:32 ... letzte Meldung vor dem Shutdown und dann um 12:55:26.076 direkt die Meldung "In Function" ... sieht so aus als würde die schedule Anweisung komplett ignoriert.

2024-04-17 12:51:32.643 - ^[[32minfo^[[39m: nina.0 (903) terminating
2024-04-17 12:55:26.076 - ^[[31merror^[[39m: javascript.0 (954) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 12:55:26.140 - ^[[31merror^[[39m: javascript.0 (954) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 12:55:26.184 - ^[[31merror^[[39m: javascript.0 (954) script.js.Technik.Heizung.BootTestScript: In Function

Vielen, Vielen Dank für die Tipps und Ideen!

[haus-automatisierung]

@mcm57 sagte in maximum of 1000 setState during boot:

Leider hab ich zum eigentlichen Problem keine Idee was da abgeht. @haus-automatisierung fällt dir da was dazu ein?

So spontan nicht. Konnte jemand das Verhalten auf seinem eigenen System reproduzieren?

[mcm1957]

@haus-automatisierung
Ja,
Gibt mittlerweile ein Issue mit einem Testsckrip wo das repoduzierbar sein soll (habs nicht selbst getestet)

https://github.com/ioBroker/ioBroker.javascript/issues/1552

Helmut1965 created this issue in ioBroker/ioBroker.javascript

closed [Bug]: Schedule command seems to be ignored during boot up (each fresh IOBroker start) #1552

[hschief]

@mcm57 Ich habe das dort als Issue auf deinen Rat hin aufgenommen, ich hoffe dies war vom Ablauf ok,

[peterfido]

@hschief
ich habe das Testskript auf meinem zweiten iobroker getestet. Keine mehrfachen Aufrufe beim Start zu entdecken.

2024-04-17 19:40:51.936 - info: javascript.0 (706) starting. Version 7.8.0 in /opt/iobroker/node_modules/iobroker.javascript, node: v18.20.2, js-controller: 5.0.19
2024-04-17 19:40:52.184 - info: javascript.0 (706) requesting all states
2024-04-17 19:40:52.185 - info: javascript.0 (706) requesting all objects
2024-04-17 19:40:52.446 - info: javascript.0 (706) received all objects
2024-04-17 19:40:52.493 - info: javascript.0 (706) received all states
2024-04-17 19:40:52.574 - info: javascript.0 (706) Start javascript script.js.Scripte.CronJobs
2024-04-17 19:40:52.590 - error: javascript.0 (706) script.js.Scripte.CronJobs: Script Test1 aufgerufen
2024-04-17 19:40:52.606 - info: javascript.0 (706) script.js.Scripte.CronJobs: registered 0 subscriptions, 1 schedule, 0 messages, 0 logs and 0 file subscriptions
2024-04-17 19:40:55.160 - info: host.iob instance system.adapter.simple-api.0 started with pid 721
2024-04-17 19:40:55.593 - info: simple-api.0 (721) starting. Version 2.7.2 in /opt/iobroker/node_modules/iobroker.simple-api, node: v18.20.2, js-controller: 5.0.19
2024-04-17 19:40:55.599 - warn: simple-api.0 (721) Information for Developer: Using the direct "Let's encrypt" module import is deprecated and will be removed in the next js-controller version, use @iobroker/webserver instead
2024-04-17 19:40:55.600 - info: simple-api.0 (721) simpleAPI server listening on port 8087
2024-04-17 19:40:55.601 - info: simple-api.0 (721) Allow states only when user is owner: false
2024-04-17 19:40:55.603 - info: simple-api.0 (721) http server listening on port 8087
2024-04-17 19:40:59.155 - info: host.iob instance system.adapter.socketio.0 started with pid 736
2024-04-17 19:40:59.643 - info: socketio.0 (736) starting. Version 6.6.1 in /opt/iobroker/node_modules/iobroker.socketio, node: v18.20.2, js-controller: 5.0.19
2024-04-17 19:40:59.652 - warn: socketio.0 (736) Information for Developer: Using the direct "Let's encrypt" module import is deprecated and will be removed in the next js-controller version, use @iobroker/webserver instead
2024-04-17 19:40:59.664 - info: socketio.0 (736) socket.io server listening on port 8088
2024-04-17 19:41:00.005 - error: javascript.0 (706) script.js.Scripte.CronJobs: In Function
2024-04-17 19:41:10.002 - error: javascript.0 (706) script.js.Scripte.CronJobs: In Function
2024-04-17 19:41:20.001 - error: javascript.0 (706) script.js.Scripte.CronJobs: In Function

[Homoran]

@peterfido

gilt das bei dir auch:

@hschief sagte in maximum of 1000 setState during boot:

Javascript Version 7.8.0
node 18.17.1
jscontroller 5.0.19

?

[peterfido]

@homoran Steht in der ersten Zeile meines Logs. Mein System ist mit node 18.20.2 aktueller.

[Homoran]

@peterfido

mit der gerade gefundenen Antwort
@hschief sagte in maximum of 1000 setState during boot:

@thomas-braun said in maximum of 1000 setState during boot:

iob nodejs-update

Update durchgeführt, aktuelle Version ist jetzt: v.18.20.2, Fehler ist aber auch nach dem Update da.

seid ihr also was diese Versionen angeht, identisch!
Sehr gut.

[peterfido]

@homoran Evtl. nützlich: Meine iobroker sind VMs unter proxmox. Die Uhren stehen auf Host.

[hschief]

@homoran ich hatte die Version ja auf anraten hochgezogen, mir ist aber gestern bei der Erstellung des Issues im Debug Log folgendes aufgefallen, was auch durch dein Log hier nochmals bestätigt wird:

Mein Log fängt direkt mit den Meldungen der Function an und nicht mit der Initialisierung des Javascript Adapters. Jetzt kann es natürlich sein, dass Meldungen auf meinem System nur einfach zeitlich vorher in den Log kommen. Ich vermute aber eher, dass der Adapter aus irgendeinem Grund noch nicht vollständig gestartet ist,

Shutdown at 13:55:35 -> Boot at 13:59:24
2024-04-17 13:55:35.534 - ^[[32minfo^[[39m: javascript.0 (2626) terminating
2024-04-17 13:59:24.355 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 13:59:24.410 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 13:59:24.441 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 13:59:24.475 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function
2024-04-17 13:59:24.492 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function

Vielen Dank fürs testen, somit scheint es kein allgemeiner Fehler sondern eher eine ganz spezielles Zusammenspiel beim booten zu sein. Kann man irgendwo die Reihenfolge der Adapter beim Starten vorgeben?

[Wildbill]

@hschief Ich habe mir angewöhnt, bei einem Neustart des iobroker (also vor dem Reboot nach Kernel-Updates beispielsweise, oder wenn der js-controller ein Update bekommt) einfach vor dem Beenden selbstständig bestimmte Adapter anzuhalten. Bei mir sind das javascript, Sourceanalytix und devicewatcher. Die starte ich dann erst manuell, wenn die restlichen Adapter wieder laufen. Javascript, da anonsten diverse Scripte mit falschen Werten laufen würden, da manche Adapter hier vor dem Start manchmal „falsche“ Werte anzeigen, Sourceanalytix aus demselben Grund, weil beispielsweise Homematic-Stecker mit Strimmessung hier kurz auf 0 springen und der device-watcher, weil sonst Meldungen über viele Offline-Geräte kommen, weil die jeweiligen Adapter eben noch nicht gestartet sind und deren Geräte teilweise bei alive auf false stehen würden.

Hat sich bewährt bei mir. Ob sich das irgendwie automatisieren lässt, so dass man eine Reihenfolge für Adapterstarts (selbst) einstellen kann, weiss ich nicht. Ich meine, mal gelesen zu haben, dass der Adapter-Ersteller hier zumindest selbst Abhängigkeiten hingterlegen kann, so dass voneinander abhängige Adapter/Instanzen in korrekter Reihenfolge starten.
Ungeplante Neustarts von iobroker kommen bei mir höchstens mal vor, wenn ein Stromausfall länger dauert, die USVs leer laufen und die Hosts runterfahren ohne dass ich vorher selbst aktiv geworden wäre. Also höchst selten.

Gruss, Jürgen

[paul53]

@hschief sagte: spezielles Zusammenspiel beim booten zu sein.

Es ist mir unerklärlich wie Node.js zwischen Start nach Boot und normalem Neustart von ioBroker unterscheiden kann.
Vielleicht passiert etwas Eigenartiges beim Shutdown? Hast du mal ioBroker vor dem Shutdown gestoppt?

[peterfido]

@hschief sagte in maximum of 1000 setState during boot:

function Test1() { log('In Function','error'); setState('0_userdata.0.Allgemein.TestBoot', 'test', false); }; log('Script Test1 gestartet:','error'); setTimeout(function(){schedule("*/10 * * * * *", Test1 )},50000);

Ich habe das eben mit der Verzögerung getestet.:

2024-04-18 11:42:27.863 - info: host.iob instance system.adapter.javascript.0 started with pid 705
2024-04-18 11:42:28.702 - info: javascript.0 (705) starting. Version 7.8.0 in /opt/iobroker/node_modules/iobroker.javascript, node: v18.20.2, js-controller: 5.0.19
2024-04-18 11:42:28.931 - info: javascript.0 (705) requesting all states
2024-04-18 11:42:28.932 - info: javascript.0 (705) requesting all objects
2024-04-18 11:42:29.223 - info: javascript.0 (705) received all objects
2024-04-18 11:42:29.269 - info: javascript.0 (705) received all states
2024-04-18 11:42:29.383 - info: javascript.0 (705) Start javascript script.js.Scripte.CronJobs
2024-04-18 11:42:29.405 - error: javascript.0 (705) script.js.Scripte.CronJobs: Script Test1 gestartet:
2024-04-18 11:42:29.406 - info: javascript.0 (705) script.js.Scripte.CronJobs: registered 0 subscriptions, 0 schedules, 0 messages, 0 logs and 0 file subscriptions
2024-04-18 11:42:31.861 - info: host.iob instance system.adapter.simple-api.0 started with pid 720
2024-04-18 11:42:32.347 - info: simple-api.0 (720) starting. Version 2.7.2 in /opt/iobroker/node_modules/iobroker.simple-api, node: v18.20.2, js-controller: 5.0.19
2024-04-18 11:42:32.355 - warn: simple-api.0 (720) Information for Developer: Using the direct "Let's encrypt" module import is deprecated and will be removed in the next js-controller version, use @iobroker/webserver instead
2024-04-18 11:42:32.358 - info: simple-api.0 (720) simpleAPI server listening on port 8087
2024-04-18 11:42:32.358 - info: simple-api.0 (720) Allow states only when user is owner: false
2024-04-18 11:42:32.362 - info: simple-api.0 (720) http server listening on port 8087
2024-04-18 11:42:35.867 - info: host.iob instance system.adapter.socketio.0 started with pid 735
2024-04-18 11:42:36.419 - info: socketio.0 (735) starting. Version 6.6.1 in /opt/iobroker/node_modules/iobroker.socketio, node: v18.20.2, js-controller: 5.0.19
2024-04-18 11:42:36.433 - warn: socketio.0 (735) Information for Developer: Using the direct "Let's encrypt" module import is deprecated and will be removed in the next js-controller version, use @iobroker/webserver instead
2024-04-18 11:42:36.452 - info: socketio.0 (735) socket.io server listening on port 8088
2024-04-18 11:43:20.004 - error: javascript.0 (705) script.js.Scripte.CronJobs: In Function
2024-04-18 11:43:30.001 - error: javascript.0 (705) script.js.Scripte.CronJobs: In Function

Somit bei mir wie es soll.

[haus-automatisierung]

@wildbill sagte in maximum of 1000 setState during boot:

Ich meine, mal gelesen zu haben, dass der Adapter-Ersteller hier zumindest selbst Abhängigkeiten hingterlegen kann, so dass voneinander abhängige Adapter/Instanzen in korrekter Reihenfolge starten.

Genau, es gibt verschiedene Tier-Level, welche die Startreihenfolge festlegen. Damit zB Logikadapter laufen, bevor die ersten Werte kommen

[hschief]

@haus-automatisierung Vielen Dank für die tollen Antworten und auch die Information, dass der Fehler bei euch nicht reproduziert werden kann, Ich werde das Issue in GitHub erstmal schliessen und weiter forschen um das Problem einzugrenzen. Ich berichte was sich weiter ergibt.