Maxcul ist komplett unbrauchbar (geloest mit 0.5.2)

[skraw.iobroker]

Das hier verstehe ich nicht:

maxcul.0	2018-03-12 19:13:56.476	debug	LOVF: credits=503
maxcul.0	2018-03-12 19:13:56.475	debug	incoming raw data from CUL: LOVF
maxcul.0	2018-03-12 19:13:56.474	debug	serial port buffer have been drained
maxcul.0	2018-03-12 19:13:56.455	debug	Send Packet to CUL: Zs0b0100401234561b7e310067, awaiting drain event
maxcul.0	2018-03-12 19:13:56.448	debug	delayed next send by 5000ms (Queue length left = 7, Current Credit = 503)
maxcul.0	2018-03-12 19:13:56.383	debug	Ignore command because already in queue X
maxcul.0	2018-03-12 19:13:51.451	debug	redis pmessage io.maxcul.0.* io.maxcul.0.info.limitOverflow {"val":true,"ack":true,"ts":1520878431441,"q":0,"from":"system.adapter.maxcul.0","lc":1520878431441}
maxcul.0	2018-03-12 19:13:51.450	debug	serial port buffer have been drained
maxcul.0	2018-03-12 19:13:51.443	debug	LOVF: credits=503
maxcul.0	2018-03-12 19:13:51.442	debug	incoming raw data from CUL: LOVF
maxcul.0	2018-03-12 19:13:51.422	debug	Send Packet to CUL: Zs0b0100401234561b7edc0067, awaiting drain event
maxcul.0	2018-03-12 19:13:51.416	debug	delayed next send by 5000ms (Queue length left = 8, Current Credit = 503)
maxcul.0	2018-03-12 19:13:51.379	debug	Ignore command because already in queue X
maxcul.0	2018-03-12 19:13:47.498	debug	got OK-ACK Packet from 1b7d41
maxcul.0	2018-03-12 19:13:47.497	debug	RSSI for Message: -54
maxcul.0	2018-03-12 19:13:47.495	debug	decoding Message Z0E0102021B7D41123456000139643128
maxcul.0	2018-03-12 19:13:47.494	debug	incoming raw data from CUL: Z0E0102021B7D41123456000139643128
maxcul.0	2018-03-12 19:13:46.413	debug	serial port buffer have been drained
maxcul.0	2018-03-12 19:13:46.410	debug	Send Packet to CUL: Zs0b0100401234561b7d410071, awaiting drain event

Warum bekommt man bei 503 credits einen LOVF zurueck?

geändert: Code in Code-Tags! Homoran(Mod)

[apollon77]

Also ich sehe da vor allem ein "Ignore command because already in queue X" … also wie lange ist denn das letze "X" Kommando her und wieviel ging danach schon an Kommandos raus? Damit die Frage "wie alt ist das 503" ...

Meine Annahme ist das es mal 503 war dann mehreres gesendet wurde und der CUL ein "LOVF" zurückliefert ... also die 503 ist aaaalt weil zu viel nach dem letzten X kam und damit ist das Logging müll. Man müsste nach jedem Kommando immer ein "X" senden um den aktuellen Status zu bekommen. Wie wäre es damit?

[skraw.iobroker]

So einfach ist das ja nicht. Das LOVF zeigt ja selbst 503 credits. Und daran haengt meine Verwunderung. wie kann das denn sein, dass ein LOVF zurueckkommt und man gleichzeitig 503 credits haette … ?

[apollon77]

LOVF ist exkt diese Info. Ich habe im Code nichts gesehncdas zusammen mit LOFV vom CUL ein Wert kommt. Der nimmt den "letzten" Credit-Wert den er kennt und gibt Ihn bei LOFV aus … Rest siehe oben: Wenn der letzte Wert also alt ist, ist die Ausgabe damit schrott

[skraw.iobroker]

Mir scheint, dass die credits nicht hochzaehlen, wenn man keine X Kommandos schickt. Das wuerde bedeuten dass es kontraproduktiv ist die X zu ignorieren wenn schon eines in der Queue ist, denn man "verloere" dadurch anschliessend 5 credits …

Die Frage ist wirklich ob es ginge die X nicht zu queuen sondern gnadenlos im 5-Sekundentakt zu schicken und nur "normale" (sprich echte Sende-) Kommandos in die Queue zu schicken...

[apollon77]

Die credis im CUl zählen IMMER weiter - nur der Adapter kennt diesen aktuellen Stand nicht weil er Ihn nur bekommt wenn ein "X" gesendet wurde.

Daher ja meine Idee: Nach einem Kommando IMMER ein "X" zu senden um den aktuellen credit-Stand nach diesem Kommando im Programm zu haben. Dann kann man das restliche Handling so lassen

[skraw.iobroker]

Ich wuerds eher anders herum machen. Alle 5 Sekunden das X senden, und wenn die Credits jeweils ueber Y gross sind (Y=220?), dann das naechste Kommando aus der Queue senden… ?

[skraw.iobroker]

Mal eine Frage zur Programmierung:

shift() holt das erste Element aus einer Queue. Wie schiebe ich so ein Element wieder zurueck an die erste Position in der Queue? Ich nehme an dass push() das Element an die letzte Stelle der Queue haengt, richtig?

Habs gefunden …

Hier ist meine neue Variante des Queue Handlings mit dem Vorteil, dass keine Nachrichten mehr dadurch verloren gehen, dass die Credits offensichtlich nicht reichen. Gleichzeitig fuege ich hinter jedem gesendeten Kommando ein X Kommando ein um die Credits auch bei gefuellter Queue aktuell zu halten. Das sieht mir im Moment als mit Abstand die beste Variante aus, die wir bisher hatten.

Der Delay allein reicht ganz einfach nicht aus bei vielen CUL-Clients an einem Broker-Adapter. Da geht einfach sehr viel verloren von dem was gesendet werden soll.

In dieser Version schauen wir erst obs ein X Kommando ist, das laeuft dann ohne Delay durch.

Wenns kein X ist wird geschaut ob die Credits reichen, falls nein wird aus dem Kommando ein X gemacht und geschickt. Dabei ist wichtig, dass der Delay nicht auf 0 ms steht (trotz X), weil wir sonst eine Busy-Loop haben. Ich nehm an dieser Stelle mal 5000ms.

Falls die Credits reichen wird das Kommando geschickt, vorher aber als naechstes Kommando ein X in die Queue geschoben um den Credit-Update gleich zu haben.

Im Nicht-X Fall wird das Delay auf 2000 ms gesetzt, damit auch Zeit bleibt fuer ein ACK.

        CommunicationServiceLayer.prototype.writeQueue = function() {
            if (!this._queuedWrites.length) return Promise.resolve(true);

            this._queueSendInProgress = true;
            var command = this._queuedWrites[0];
            var delay = 2000;

            if (command[0] === 'X') {
                command = this._queuedWrites.shift();
                delay = 0;
            }
            else {
                if (this._credits < 220) {
                    command = 'X\n';
                    delay = 5000;
                }
                else {
                    command = this._queuedWrites.shift();
                    this._queuedWrites.unshift('X\n');
                }
            }

            return this._serialDeviceInstance.writeAsync(command).then(() => {
                env.logger.debug('Send Packet to CUL: ' + command.trim() + ', awaiting drain event');
                return this._serialDeviceInstance.drainAsync()
            }).then(() => {
                env.logger.debug('serial port buffer have been drained');
                Promise.delay(delay).then(() => {
                    env.logger.debug('delayed next send by ' + delay + 'ms (Queue length left = ' + this._queuedWrites.length + ', Current Credit = ' + this._credits + ')' );
                    this._queueSendInProgress = false;
                    return this.writeQueue();
                });
            });
        };

Ich hab mir zusaetzlich die _credits besorgt:

        function CommunicationServiceLayer(baudrate, serialPortName, _baseAddress) {
            this._baseAddress = _baseAddress;
            this.serialPortName = serialPortName;
            env.logger.info('using serial device ' + this.serialPortName + '@' + baudrate);
            this._messageQueue = [];
            this._queueSendInProgress = false;
            this._current = void 0;
            this._busy = false;
            this._ackResolver = null;
            this._currentSentPromise = null;
            this._serialDeviceInstance = new SerialPort(serialPortName, {
                baudrate: baudrate,
                parser: SerialPort.parsers.readline('\n'),
                autoOpen: false
            });
            this._queuedWrites = [];
            this._credits = 0;
        }

Und sie hier aktualisiert (ca Zeile 87):

                        if (/^\d+\s+\d+$/.test(dataString)) {
                            var m = dataString.match(/^(\d+)\s+(\d+)$/);
                            _this._credits = parseInt(m[2],10);
                            return _this.emit('creditsReceived', m[2], m[1]);
                        }

Und es hat sich herausgestellt, dass die folgende Sache auch noch geaendert werden muss (Zeile 188 im main.js):

   if (!timers[channel]) return;

    if (credits < 220) {
        var crinfo = 'Not enough credits(' + credits + '). Wait for more...';

Das ist notwendig, weil man bei 120 gerne mal LOVF kassiert.

[apollon77]

0.5.3 mit Deinen Änderungen (Danke dafür!!) auf GitHub und NPM.

[Unterstedter]

Ich greife das Thema mal wieder auf. Ich habe Version 1.0 installiert und hier stellt es sich mittlerweile auch so für mich da, dass der Adapter nicht brauchbar ist aufgrund der am Anfang der Themas beschriebenen Problematik. Mal läuft der Adapter für einige Stunden, häufig ist es direkt beim Start: Jede Menge unknow data. Ich habe das Gefühl, dass der String dann nicht mehr richtig gelesen wird.
Beim Adapterstart wird ja normalerweise die CULFW gelogt, hier kommt bei mir:
"received unknown data: 0V 1.67 nanoCUL868".
Kann da jemand helfen?