Timing issue createState --> setState trotz Callback

[HGlab]

Hallo Community,

ich nutze folgende Logik um ein Json mit 100+ Werten als Datenpunkte abzulegen.

function setStateCus(id, name, value) {
    if (existsObject(id) == false) {
        createState(id, '', creat_param, function () {
            setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
        });
    } else {
        setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
    }
}

setState ist im Callback von createState verpackt, trotzdem kommt bei mehr als ca. 50 JSON Werten dazu, dass das setState folgende Warning erzeugt (für jeden Datenpunkt):

2020-12-29 07:12:45.204 - warn: javascript.0 (32532) State "TEST.daily.7.temp.day" not found
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at setState (/opt/iobroker/node_modules/iobroker.javascript/lib/sandbox.js:1358:20)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at script.js.Test:63:13
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at client.set.err (/opt/iobroker/node_modules/iobroker.js-controller/lib/states/statesInRedis.js:547:55)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at tryCatcher (/opt/iobroker/node_modules/standard-as-callback/built/utils.js:11:23)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at promise.then (/opt/iobroker/node_modules/standard-as-callback/built/index.js:19:49)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at process._tickCallback (internal/process/next_tick.js:68:7)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) State "TEST.daily.7.temp.min" not found
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at setState (/opt/iobroker/node_modules/iobroker.javascript/lib/sandbox.js:1358:20)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at script.js.Test:63:13
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at client.set.err (/opt/iobroker/node_modules/iobroker.js-controller/lib/states/statesInRedis.js:547:55)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at tryCatcher (/opt/iobroker/node_modules/standard-as-callback/built/utils.js:11:23)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at promise.then (/opt/iobroker/node_modules/standard-as-callback/built/index.js:19:49)
2020-12-29 07:12:45.205 - warn: javascript.0 (32532) at process._tickCallback (internal/process/next_tick.js:68:7)

Für mich sieht es so aus, also würde der JS-Controller ab einer gewissen Menge trotz Callback-Commit mit dem Einarbeiten nicht nachkommen oder mache ich was falsch?
Danke für euren Support!

[UncleSam]

@HGlab sagte in Timing issue createState --> setState trotz Callback:

client.set.err

Ich würde mal schauen, ob da nicht ein Fehler im Callback zurück kommt. Einfach so im Callback weiter zu machen ohne die Argumente anzuschauen ist gefährlich.

[HGlab]

@UncleSam

if (existsObject(id) == false) {
        createState(id, '', creat_param, function (err) {
            log(err);
            setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
        });
    } else {
        setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
    }
}

Error = null trotzdem ist der State nicht da

2020-12-29 11:27:55.995 - info: javascript.0 (32532) script.js.TEST: null
2020-12-29 11:27:55.995 - info: javascript.0 (32532) script.js.TEST: null
2020-12-29 11:27:55.995 - warn: javascript.0 (32532) State "x.wind.speed" not found
2020-12-29 11:27:55.996 - warn: javascript.0 (32532) at setState (/opt/iobroker/node_modules/iobroker.javascript/lib/sandbox.js:1358:20)
2020-12-29 11:27:55.996 - warn: javascript.0 (32532) at script.js.TEST:76:13
2020-12-29 11:27:55.996 - warn: javascript.0 (32532) at client.set.err (/opt/iobroker/node_modules/iobroker.js-controller/lib/states/statesInRedis.js:547:55)
2020-12-29 11:27:55.996 - warn: javascript.0 (32532) at tryCatcher (/opt/iobroker/node_modules/standard-as-callback/built/utils.js:11:23)
2020-12-29 11:27:55.998 - warn: javascript.0 (32532) at promise.then (/opt/iobroker/node_modules/standard-as-callback/built/index.js:19:49)
2020-12-29 11:27:55.998 - warn: javascript.0 (32532) at process._tickCallback (internal/process/next_tick.js:68:7)
2020-12-29 11:27:56.028 - info: javascript.0 (32532) script.js.TEST: null
2020-12-29 11:27:56.028 - info: javascript.0 (32532) script.js.TEST: null

[paul53]

@HGlab sagte:

der JS-Controller ab einer gewissen Menge trotz Callback-Commit mit dem Einarbeiten nicht nachkommen

Ja, das ist leider so: setState() wird zu früh aufgerufen, wenn das in einer Schleife abgearbeitet wird. Weshalb übergibst Du an createState() als Init-Wert einen Leerstring und nicht die Variable value ?

[HGlab]

@paul53
Guter Punkt, kann nur dann kein 'ack' und 'expire' mitgeben

[paul53]

@HGlab sagte:

kann nur dann kein 'ack' und 'expire' mitgeben

Wozu dient "expire" ?
Nach meiner Erfahrung macht es nur Probleme.

[HGlab]

@paul53
das JSON-Objekt hat Bäume und Blätter die optional sind. Da ich generisch durch das Objekt traversiere schreibe ich alles rein was da ist. Wenn etwas nicht mehr da ist läuft es ins expire.

Mit folgender Ergänzung rennt es nun ohne Warnings durch - eigentlich gibt es dafür keinen Grund, aber so klappt es - warum auch immer!

if (existsObject(id) == false) {
    createState(id, '', creat_param, function (err,state) {
        if (err) log(err + ' | ' + state, 'error'); 
        setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
    });
} else {
    setState(id, { 'val': value, 'ack': true, 'expire': 5.1 * 60 });
}

[paul53]

@HGlab sagte:

Mit folgender Ergänzung rennt es nun ohne Warnings durch - eigentlich gibt es dafür keinen Grund

Der log-Befehl benötigt Zeit, sorgt also dafür dass setState() etwas später ausgeführt wird.

[UncleSam]

@HGlab Was sagt denn das Log nun?

[HGlab]

@paul53
war auch ein Verdacht, es ist aber nur das "if", ist nie TRUE;
Wenn ich nur

log(err + ' | ' + state, 'error'); 

ohne if nehme, dann kommen die Fehler wieder. Sehr strange!

[UncleSam]

@UncleSam sagte in Timing issue createState --> setState trotz Callback:

@HGlab Was sagt denn das Log nun?

?

[HGlab]

@UncleSam said in Timing issue createState --> setState trotz Callback:

@HGlab Was sagt denn das Log nun?

keine Fehler im Log; die CreateState funktionieren alle
siehe https://forum.iobroker.net/topic/40222/timing-issue-createstate-setstate-trotz-callback/4

[paul53]

@HGlab sagte:

ohne if nehme, dann kommen die Fehler wieder. Sehr strange!

Allerdings.
Möglicher Workaround wäre, die Funktion in einem Intervall (z.B. alle 200 ms) anstelle in einer Schleife aufzurufen, denn die JSON-Abfrage erfolgt anscheinend alle 5 Minuten.

[HGlab]

@paul53
Ich traversiere rekursiv durch das JSON Objekt und rufe für jedes Blatt die setStateCus-Methode auf.
Wüsste nicht wie ich das sinnvoll entkoppeln kann.
Hab auch schon setState mit 1000ms verzögert ausgeführt, auch das hat nichts geholfen.
Ich denke es liegt am Übergang zu Reddis. Reddis funktioniert ja auch asynchron und vermutlich stecken die "creates" noch in der Queue und werden teilweise von den setStates überholt.

Vielleicht lege ich mal ein issue beim JS-Controller an...

[paul53]

@HGlab sagte in:

Vielleicht lege ich mal ein issue beim JS-Controller an...

Da gibt es bereits etwas.

[HGlab]

@paul53