Maxcul ist komplett unbrauchbar (geloest mit 0.5.2)

[apollon77]

@skraw.iobroker:

bzgl. delay:

was crasht ist der nanoCUL. `

Sorry, aber einmal muss ich es sagen: Dann ist der nanocul "Schrott" und ein echter cul besser ;-)) Dann gäbe es diese ganzen Probleme nicht.

@skraw.iobroker:

Nachtrag:

ich hab mir das jetzt nochmal ganz genau angeschaut. Das Problem koennte auch am Aufruf des Codes liegen der die Queue ausleert, denn wenn das Flag gleich wieder auf false gesetzt wird kann ein folgender Aufruf vor Ablauf des Delays nochmal zu einem Send fuehren, daher:

Jetzt mit "this._queueSendInProgress = false;" ganz am Schluss… `

Jupp, so war es auch in meinem Code

@skraw.iobroker:

Wenn man genau darueber nachdenkt sollte man das false auch gar nicht am Ende setzen, sondern ganz oben eine Abfrage auf length==0 und dann auf false und exit. Wenn diese Routine "zweimal" parallel laeuft gibts sicher ein Problem…

Das Problem mit dem Locking ist jetzt halt hier konzentriert anstatt bei jedem SendPacket Aufruf wie frueher. `

Nein. Das ist alles so korrekt.

Das "Locking" passiert in der Kombination aus "Länge der Queue" und "wird gerade gesendet". Das passt alles so wie es ist.

Du darfst das _queueSendInProgress erst nach deinem delay zurücksetzen. Vollkommen korrekt.

Jetzt kannst Du mal am Delay drehen und die "Minimale" Wartezeit zwischen dem Senden herausfinden. Ich würde bei 200ms anfangen und in 200ms Schritten erhöhen. Wenn es klappt nochmal 100ms weniger versuchen und wenn das noch klappt wieder zurück. Wenn nicht nochmal sicherheitshalber 100ms drauf und gut

[apollon77]

@skraw.iobroker:

Erst mal zu einem Vorgang der die Sache mit dem mode beweist:

maxcul.0 2018-03-05 10:02:34.335 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.mode {"val":null,"ack":true,"ts":1520240554328,"q":0,"from":"system.adapter.maxcul.0","lc":1520240554328}

maxcul.0 2018-03-05 10:02:34.335 debug ThermostatStateReceived: {"src":"1b7bbd","desiredTemperature":18,"valvePosition":8,"measuredTemperature":18.6,"dstSetting":1,"lanGateway":1,"panel":1,"rfError":0,"batteryLow":0,"untilString":"","rssi"

Man sieht hier dass der Received keinerlei "mode" enthaelt. Aber das erste was als Message generiert wird ist ein mode mit "null".

Hier noch mal die komplette Zeile aus dem logfile:

2018-03-05 10:02:34.327 - debug: maxcul.0 ThermostatStateReceived: {"src":"1b7bbd","desiredTemperature":18,"valvePosition":8,"measuredTemperature":18.6,"dstSetting":1,"lanGateway":1,"panel":1,"rfError":0,"batteryLow":0,"untilString":"","rssi":-69.5} `

Im Code wird "mode" immer gesetzt und ist auch als Key faktisch im Objekt da. Ich denke das es ggf "undefined" ist und daher in der Ausgabe fehlt und auf null gesetzt wird.

Mach mal diese Änderung bei Dir und sag ob es hilft:

https://github.com/ioBroker/ioBroker.ma … 8032f97bae

[skraw.iobroker]

Thema mode:

es scheint jetzt die Aenderung zu geben, dass das Feld jetzt von "Manual" nicht auf <leer>wechselt sondern auf "null".

Warum das so ist kann ich im log nicht sehen …

Nochmal kontrolliert: Der Patch bringt ... naja, also der Wert ueberlebt den naechsten Receive, ist aber rot und "bestätigt:" zeigt "false".

Wie wuerde denn dieser Wert bestaetigt werden? Wenn das Thermostat ihn einmal zurueckschickt?

Das Problem im ungepatchten Code ist wohl ganz einfach dass aus "undefined" erst "null" wird und dann beim naechsten Send am Thermostat "auto", da "null" numerisch "0" ist, ebenso wie "auto".</leer>

[skraw.iobroker]

Thema delay usw:

ich nehme an Du meinst mit Laenge und flag so eine Stelle hier (Z 186 ca)

this._queuedWrites.push(command);

env.logger.debug('Queued send for ' + command.trim());

if (this._queuedWrites.length === 1 && !this._queueSendInProgress) {

return this.writeQueue();

}

return Promise.resolve();

Das Problem an diesem Vergleich ist, dass er in einer Multitasking-Umgebung klar failed. Genau diese Stelle war vormals dafuer verantwortlich dass der Delay im writeQueue nicht ging wenn das Flag irgendwann auf false gesetzt wird. Mit dem Setzen am Ende von writeQueue wird zwar das Zeitfenster kleiner, aber es ist nicht weg. Genau deshalb meinte ich ja, dass das false-Setzen oben bei einem Vergleich auf "0" der Queue-Laenge gemacht werden sollte. Da ist das Fenster immer noch nicht weg, aber sicherlich noch viel kleiner (auf die Laufzeit eines Vergleichs und ein paar Zyklen beschraenkt).

Wenn in writeQueue erst mal zweimal "eingesprungen" wurde ists verloren, weil innerhalb dieser Routine kein Ausschluss des anderen Laufs erfolgen kann.

Mit dem Delay haben wir wenigstens irgendeine halbe Loesung. Ich wuerde mich daher jetzt erst mal auf den klaren Mode-Bug beschraenken…

[skraw.iobroker]

Hier wieder ein Logfile des kuerzesten funktionierenden Delays (1s):

! maxcul.0 2018-03-05 19:49:29.734 debug delayed 1s maxcul.0 2018-03-05 19:49:28.752 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":89,"ack":true,"ts":1520275768748,"q":0,"from":"system.adapter.maxcul.0","lc":1520275768748} maxcul.0 2018-03-05 19:49:28.732 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:28.729 debug Send Packet to CUL: X, awaiting drain event maxcul.0 2018-03-05 19:49:28.728 debug Queued send for X maxcul.0 2018-03-05 19:49:27.758 warn Not enough credits. Wait for more... maxcul.0 2018-03-05 19:49:26.140 warn Not enough credits. Wait for more... maxcul.0 2018-03-05 19:49:24.732 debug delayed 1s maxcul.0 2018-03-05 19:49:23.753 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":84,"ack":true,"ts":1520275763748,"q":0,"from":"system.adapter.maxcul.0","lc":1520275763748} maxcul.0 2018-03-05 19:49:23.753 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.limitOverflow {"val":true,"ack":true,"ts":1520275763746,"q":0,"from":"system.adapter.maxcul.0","lc":1520275763746} maxcul.0 2018-03-05 19:49:23.730 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:23.729 debug Send Packet to CUL: X, awaiting drain event maxcul.0 2018-03-05 19:49:23.727 debug Queued send for X maxcul.0 2018-03-05 19:49:22.797 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.rssi {"val":-71.5,"ack":true,"ts":1520275762792,"q":0,"from":"system.adapter.maxcul.0","lc":1520275762792} maxcul.0 2018-03-05 19:49:22.794 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.batteryLow {"val":false,"ack":true,"ts":1520275762787,"q":0,"from":"system.adapter.maxcul.0","lc":1519978554323} maxcul.0 2018-03-05 19:49:22.789 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.rfError {"val":false,"ack":true,"ts":1520275762781,"q":0,"from":"system.adapter.maxcul.0","lc":1519978554318} maxcul.0 2018-03-05 19:49:22.783 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.measuredTemperature {"val":19,"ack":true,"ts":1520275762777,"q":0,"from":"system.adapter.maxcul.0","lc":1520275762777} maxcul.0 2018-03-05 19:49:22.774 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2604801.valvePosition {"val":4,"ack":true,"ts":1520275762755,"q":0,"from":"system.adapter.maxcul.0","lc":1520275762755} maxcul.0 2018-03-05 19:49:22.771 warn Not enough credits. Wait for more... maxcul.0 2018-03-05 19:49:22.771 debug ThermostatStateReceived: {"src":"1b7bbd","desiredTemperature":18,"valvePosition":4,"measuredTemperature":19,"dstSetting":1,"lanGateway":1,"panel":1,"rfError":0,"batteryLow":0,"untilString":"","rssi":- maxcul.0 2018-03-05 19:49:22.771 debug Ignore desiredTemperature: 18 maxcul.0 2018-03-05 19:49:22.767 debug got data from heatingelement 1b7bbd with payload 39042400BE maxcul.0 2018-03-05 19:49:22.766 debug RSSI for Message: -71.5 maxcul.0 2018-03-05 19:49:22.759 debug decoding Message Z0F0004601B7BBD0000000039042400BE05 maxcul.0 2018-03-05 19:49:22.759 debug incoming raw data from CUL: Z0F0004601B7BBD0000000039042400BE05 maxcul.0 2018-03-05 19:49:21.167 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2605190.rssi {"val":-54,"ack":true,"ts":1520275761164,"q":0,"from":"system.adapter.maxcul.0","lc":1520275761164} maxcul.0 2018-03-05 19:49:21.163 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2605190.batteryLow {"val":false,"ack":true,"ts":1520275761159,"q":0,"from":"system.adapter.maxcul.0","lc":1519666999043} maxcul.0 2018-03-05 19:49:21.158 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2605190.rfError {"val":false,"ack":true,"ts":1520275761149,"q":0,"from":"system.adapter.maxcul.0","lc":1519666999039} maxcul.0 2018-03-05 19:49:21.149 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2605190.measuredTemperature {"val":27.3,"ack":true,"ts":1520275761145,"q":0,"from":"system.adapter.maxcul.0","lc":1520275761145} maxcul.0 2018-03-05 19:49:21.144 debug redis pmessage io.maxcul.0.* io.maxcul.0.OEQ2605190.valvePosition {"val":69,"ack":true,"ts":1520275761137,"q":0,"from":"system.adapter.maxcul.0","lc":1520275761137} maxcul.0 2018-03-05 19:49:21.143 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.limitOverflow {"val":false,"ack":true,"ts":1520275761137,"q":0,"from":"system.adapter.maxcul.0","lc":1520275761137} maxcul.0 2018-03-05 19:49:21.139 warn Not enough credits. Wait for more... maxcul.0 2018-03-05 19:49:21.139 debug ThermostatStateReceived: {"src":"1b7d41","desiredTemperature":24.5,"valvePosition":69,"measuredTemperature":27.3,"dstSetting":1,"lanGateway":1,"panel":1,"rfError":0,"batteryLow":0,"untilString":"","rs maxcul.0 2018-03-05 19:49:21.139 debug Ignore desiredTemperature: 24.5 maxcul.0 2018-03-05 19:49:21.139 debug got data from heatingelement 1b7d41 with payload 3945310111 maxcul.0 2018-03-05 19:49:21.138 debug RSSI for Message: -54 maxcul.0 2018-03-05 19:49:21.138 debug decoding Message Z0F0004601B7D4100000000394531011128 maxcul.0 2018-03-05 19:49:21.138 debug incoming raw data from CUL: Z0F0004601B7D4100000000394531011128 maxcul.0 2018-03-05 19:49:19.955 debug delayed 1s maxcul.0 2018-03-05 19:49:18.973 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":80,"ack":true,"ts":1520275758969,"q":0,"from":"system.adapter.maxcul.0","lc":1520275758969} maxcul.0 2018-03-05 19:49:18.954 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:18.950 debug Send Packet to CUL: X, awaiting drain event maxcul.0 2018-03-05 19:49:18.948 debug delayed 1s maxcul.0 2018-03-05 19:49:18.721 debug Queued send for X maxcul.0 2018-03-05 19:49:17.962 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":79,"ack":true,"ts":1520275757960,"q":0,"from":"system.adapter.maxcul.0","lc":1520275757960} maxcul.0 2018-03-05 19:49:17.946 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:17.943 debug Send Packet to CUL: X, awaiting drain event maxcul.0 2018-03-05 19:49:17.942 debug delayed 1s maxcul.0 2018-03-05 19:49:16.949 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":78,"ack":true,"ts":1520275756943,"q":0,"from":"system.adapter.maxcul.0","lc":1520275756943} maxcul.0 2018-03-05 19:49:16.940 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:16.930 debug Send Packet to CUL: X, awaiting drain event maxcul.0 2018-03-05 19:49:16.928 debug delayed 1s maxcul.0 2018-03-05 19:49:15.933 debug LOVF: credits=503 maxcul.0 2018-03-05 19:49:15.932 debug incoming raw data from CUL: LOVF maxcul.0 2018-03-05 19:49:15.925 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:15.914 debug Send Packet to CUL: Zs0b0100401234561b7c2e0067, awaiting drain event maxcul.0 2018-03-05 19:49:15.909 debug delayed 1s maxcul.0 2018-03-05 19:49:14.914 debug LOVF: credits=503 maxcul.0 2018-03-05 19:49:14.913 debug incoming raw data from CUL: LOVF maxcul.0 2018-03-05 19:49:14.905 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:14.894 debug Send Packet to CUL: Zs0b0100401234561b7bbd0065, awaiting drain event maxcul.0 2018-03-05 19:49:14.893 debug delayed 1s maxcul.0 2018-03-05 19:49:13.891 debug LOVF: credits=503 maxcul.0 2018-03-05 19:49:13.890 debug incoming raw data from CUL: LOVF maxcul.0 2018-03-05 19:49:13.884 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:13.880 debug Send Packet to CUL: Zs0b0100401234561b7e310067, awaiting drain event maxcul.0 2018-03-05 19:49:13.866 debug delayed 1s maxcul.0 2018-03-05 19:49:13.718 debug Queued send for X maxcul.0 2018-03-05 19:49:12.936 debug got OK-ACK Packet from 1b7edc maxcul.0 2018-03-05 19:49:12.935 debug RSSI for Message: -62.5 maxcul.0 2018-03-05 19:49:12.935 debug decoding Message Z0E0102021B7EDC123456000139162517 maxcul.0 2018-03-05 19:49:12.930 debug incoming raw data from CUL: Z0E0102021B7EDC123456000139162517 maxcul.0 2018-03-05 19:49:12.896 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.limitOverflow {"val":true,"ack":true,"ts":1520275752880,"q":0,"from":"system.adapter.maxcul.0","lc":1520275752880} maxcul.0 2018-03-05 19:49:12.893 debug LOVF: credits=503 maxcul.0 2018-03-05 19:49:12.892 debug incoming raw data from CUL: LOVF maxcul.0 2018-03-05 19:49:12.865 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:12.850 debug Send Packet to CUL: Zs0b0100401234561b7e34006b, awaiting drain event maxcul.0 2018-03-05 19:49:12.846 debug delayed 1s maxcul.0 2018-03-05 19:49:11.845 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:11.820 debug Send Packet to CUL: Zs0b0100401234561b7edc0065, awaiting drain event maxcul.0 2018-03-05 19:49:11.817 debug delayed 1s maxcul.0 2018-03-05 19:49:10.815 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:10.796 debug Send Packet to CUL: Zs0b0100401234561b7d410071, awaiting drain event maxcul.0 2018-03-05 19:49:10.793 debug delayed 1s maxcul.0 2018-03-05 19:49:09.796 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:09.795 debug Send Packet to CUL: Zs0b01004012345616fb8f0072, awaiting drain event maxcul.0 2018-03-05 19:49:09.795 debug Queued send for X maxcul.0 2018-03-05 19:49:09.795 debug Queued send for Zs0b0100401234561b7c2e0067 maxcul.0 2018-03-05 19:49:09.794 debug Queued send for Zs0b0100401234561b7bbd0065 maxcul.0 2018-03-05 19:49:09.793 debug Queued send for Zs0b0100401234561b7e310067 maxcul.0 2018-03-05 19:49:09.793 debug Queued send for Zs0b0100401234561b7e34006b maxcul.0 2018-03-05 19:49:09.792 debug Queued send for Zs0b0100401234561b7edc0065 maxcul.0 2018-03-05 19:49:09.792 debug Queued send for Zs0b0100401234561b7d410071 maxcul.0 2018-03-05 19:49:09.791 debug Queued send for Zs0b01004012345616fb8f0072 maxcul.0 2018-03-05 19:49:09.791 debug got OK-ACK Packet from 16e328 maxcul.0 2018-03-05 19:49:09.790 debug RSSI for Message: -52 maxcul.0 2018-03-05 19:49:09.790 debug decoding Message Z0E01020216E32812345600013964312C maxcul.0 2018-03-05 19:49:09.789 debug incoming raw data from CUL: Z0E01020216E32812345600013964312C maxcul.0 2018-03-05 19:49:09.719 debug delayed 1s maxcul.0 2018-03-05 19:49:08.718 debug serial port buffer have been drained maxcul.0 2018-03-05 19:49:08.708 debug Send Packet to CUL: Zs0b01004012345616e3280071, awaiting drain event maxcul.0 2018-03-05 19:49:08.706 info Poll device1 : 1, 19.5 maxcul.0 2018-03-05 19:49:08.703 info Poll device1 : 1, 18.5 maxcul.0 2018-03-05 19:49:08.701 info Poll device1 : 1, 19.5 maxcul.0 2018-03-05 19:49:08.696 info Poll device1 : 1, 21.5 maxcul.0 2018-03-05 19:49:08.694 info Poll device1 : 1, 18.5 maxcul.0 2018-03-05 19:49:08.689 info Poll device1 : 1, 24.5 maxcul.0 2018-03-05 19:49:08.689 info Poll device1 : 1, 25 maxcul.0 2018-03-05 19:49:08.681 debug Queued send for Zs0b01004012345616e3280071 maxcul.0 2018-03-05 19:49:08.680 info Poll device1 : 1, 24.5 maxcul.0 2018-03-05 19:49:04.715 debug delayed 1s maxcul.0 2018-03-05 19:49:03.727 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":503,"ack":true,"ts":1520275743722,"q":0,"from":"system.adapter.maxcul.0","lc":1520275743722} maxcul.0 2018-03-05 19:49:03.719 debug serial port buffer have been drained !
Was bedeutet LOVF als Antwort?

[skraw.iobroker]

@apollon77:

@skraw.iobroker:

bzgl. delay:

was crasht ist der nanoCUL. `

Sorry, aber einmal muss ich es sagen: Dann ist der nanocul "Schrott" und ein echter cul besser ;-)) Dann gäbe es diese ganzen Probleme nicht. `

Tja, ich glaube das ist nicht richtig. Ich hab grad etwas im FHEM Forum quer gelesen. Dort sagte jemand dass ein MAX CUBE hoechstens 5-6 Geraete handeln koennte. Ich nehme an dass bei mehr genau die hier diskutierten Kollisionen beim Senden ebenfalls auftreten, da einer der Tipps darin bestand die Geraete zu verschiedenen Zeiten zu Pairen, wohl damit das Senden zu diesen wenn moeglich nicht dieselbe Zeitscheibe trifft.

Ich betreibe dagegen gerade 10 Thermostate und 13 Fensterkontakte zeitgleich.

Ich glaube es waere viel schlauer anstatt den Delay so klein wie moeglich zu machen ihn wirklich auf 5-10 Sekunden zu ziehen. Es spielt keine grosse Rolle ob man in derselben Minute wirklich alle Geraete erreicht, Hauptsache sie gehen wirklich verlaesslich.

PS: Wofuer sind eigentlich die staendigen X Kommandos gut?

[apollon77]

@skraw.iobroker:

Thema mode:

es scheint jetzt die Aenderung zu geben, dass das Feld jetzt von "Manual" nicht auf <leer>wechselt sondern auf "null".

Warum das so ist kann ich im log nicht sehen …

Nochmal kontrolliert: Der Patch bringt ... naja, also der Wert ueberlebt den naechsten Receive, ist aber rot und "bestätigt:" zeigt "false".

Wie wuerde denn dieser Wert bestaetigt werden? Wenn das Thermostat ihn einmal zurueckschickt?</leer> `

Korrekt. Er wird nur vom Gerät bestätigt. Was passiert denn wenn Du nur den Mode am Gerät änderst ? Wird er dann mitgeliefert?

Ich habe den Codeteil nochmal mit "der Quelle" verglichen und da war wohl was geändert worden. Habe es auf Github gleich gezogen. Bitte mal versuchen.

https://github.com/ioBroker/ioBroker.ma … 61205df5c4

@skraw.iobroker:

Thema delay usw:

Das Problem an diesem Vergleich ist, dass er in einer Multitasking-Umgebung klar failed. `
Wenn nodejs "multitasking" arbeiten würde hättest Du recht. Tut es aber nicht!!

Die asynchrone bzw. "Eventgesteuerte" Logik in node bzw JavaScript allgemein ist Single-Threaded.

Von daher: Das ist korrekt so und macht man so in Nodejs/JavaScript.

Den Fall das "während" einmal "writeQueue" abgearbeitet wird ein zweiter Aufruf erfolgt existiert schlichtweg nicht. Das ist alles streng nacheinander.

Durch das asynchrone "send" und "drain" (wo anderer Code" zwischenrein" laufen kann muss man nur sicherstellen das das writeQueue nicht aufgerufen wird. Daher: Wenn ein neues Kommando in das Array eingefügt wird und damit die Länge 1 ist UND es gerade nicht noch auf send/drain wartet kann sichergestellt writeQueue aufgerufen werden.

Von daher ist der code der das "sendInProgress" nach dem drain und deiner neuen Wartezeit zurücksetzt genau richtig.

@skraw.iobroker:

Genau diese Stelle war vormals dafuer verantwortlich dass der Delay im writeQueue nicht ging wenn das Flag irgendwann auf false gesetzt wird. Mit dem Setzen am Ende von writeQueue wird zwar das Zeitfenster kleiner, aber es ist nicht weg. Genau deshalb meinte ich ja, dass das false-Setzen oben bei einem Vergleich auf "0" der Queue-Laenge gemacht werden sollte. Da ist das Fenster immer noch nicht weg, aber sicherlich noch viel kleiner (auf die Laufzeit eines Vergleichs und ein paar Zyklen beschraenkt).

Wenn in writeQueue erst mal zweimal "eingesprungen" wurde ists verloren, weil innerhalb dieser Routine kein Ausschluss des anderen Laufs erfolgen kann. `
Siehe oben: kann nicht passieren bzw wird vom code korrekt abgefangen wenn das "sendInProgress" skorrekt zurückgesetzt wird "am Ende" wenn der nächste Call kommen darf.

@skraw.iobroker:

Mit dem Delay haben wir wenigstens irgendeine halbe Loesung. Ich wuerde mich daher jetzt erst mal auf den klaren Mode-Bug beschränken…

Hier wieder ein Logfile des kuerzesten funktionierenden Delays (1s):

...

Was bedeutet LOVF als Antwort? `

Na dann haben wir es mit 1s als Delay.Ok. Übernehme nachher deinen Delay code mit 2s ins Github, dann kannst Du nochmal testen. Mit 2s sollte auch ggf eine bessere Verteilung der Kommunikation stattfinden und vllt weniger LOVF (siehe unten).

https://wiki.fhem.de/wiki/LOVF

… dere Stick sagt das er zu schnell zuviel gesendet hat

@skraw.iobroker:

PS: Wofuer sind eigentlich die staendigen X Kommandos gut? `
Mit dem Kommando fragt man beim CUL den Stand des Sendelimits ab. Hab aber noch nicht geschaut was der Adapter/Code damit tut. Ich denke Requests selbst delayen oder so

[Homoran]

Kann das Problem an der deutlich höheren BaudRate des nanoCUL im Vergleich zum Original liegen?

Gruß

Rainer

[skraw.iobroker]

@apollon77:

@skraw.iobroker:

Thema mode:

es scheint jetzt die Aenderung zu geben, dass das Feld jetzt von "Manual" nicht auf <leer>wechselt sondern auf "null".

Warum das so ist kann ich im log nicht sehen …

Nochmal kontrolliert: Der Patch bringt ... naja, also der Wert ueberlebt den naechsten Receive, ist aber rot und "bestätigt:" zeigt "false".

Wie wuerde denn dieser Wert bestaetigt werden? Wenn das Thermostat ihn einmal zurueckschickt?</leer> `

Korrekt. Er wird nur vom Gerät bestätigt. Was passiert denn wenn Du nur den Mode am Gerät änderst ? Wird er dann mitgeliefert?

Ich habe den Codeteil nochmal mit "der Quelle" verglichen und da war wohl was geändert worden. Habe es auf Github gleich gezogen. Bitte mal versuchen.

https://github.com/ioBroker/ioBroker.ma … 61205df5c4 `

Hab das grade probiert. Das geht! Jetzt werden die Modes bestaetigt. Die Received Messages setzen komischerweise jetzt fast alle den Mode (auf 1).

@apollon77:

@skraw.iobroker:

Thema delay usw:

Das Problem an diesem Vergleich ist, dass er in einer Multitasking-Umgebung klar failed. `
Wenn nodejs "multitasking" arbeiten würde hättest Du recht. Tut es aber nicht!!

Die asynchrone bzw. "Eventgesteuerte" Logik in node bzw JavaScript allgemein ist Single-Threaded.

Von daher: Das ist korrekt so und macht man so in Nodejs/JavaScript.

Den Fall das "während" einmal "writeQueue" abgearbeitet wird ein zweiter Aufruf erfolgt existiert schlichtweg nicht. Das ist alles streng nacheinander.

Durch das asynchrone "send" und "drain" (wo anderer Code" zwischenrein" laufen kann muss man nur sicherstellen das das writeQueue nicht aufgerufen wird. Daher: Wenn ein neues Kommando in das Array eingefügt wird und damit die Länge 1 ist UND es gerade nicht noch auf send/drain wartet kann sichergestellt writeQueue aufgerufen werden.

Von daher ist der code der das "sendInProgress" nach dem drain und deiner neuen Wartezeit zurücksetzt genau richtig.

@skraw.iobroker:

Genau diese Stelle war vormals dafuer verantwortlich dass der Delay im writeQueue nicht ging wenn das Flag irgendwann auf false gesetzt wird. Mit dem Setzen am Ende von writeQueue wird zwar das Zeitfenster kleiner, aber es ist nicht weg. Genau deshalb meinte ich ja, dass das false-Setzen oben bei einem Vergleich auf "0" der Queue-Laenge gemacht werden sollte. Da ist das Fenster immer noch nicht weg, aber sicherlich noch viel kleiner (auf die Laufzeit eines Vergleichs und ein paar Zyklen beschraenkt).

Wenn in writeQueue erst mal zweimal "eingesprungen" wurde ists verloren, weil innerhalb dieser Routine kein Ausschluss des anderen Laufs erfolgen kann. `
Siehe oben: kann nicht passieren bzw wird vom code korrekt abgefangen wenn das "sendInProgress" skorrekt zurückgesetzt wird "am Ende" wenn der nächste Call kommen darf.

@skraw.iobroker:

Mit dem Delay haben wir wenigstens irgendeine halbe Loesung. Ich wuerde mich daher jetzt erst mal auf den klaren Mode-Bug beschränken…

Hier wieder ein Logfile des kuerzesten funktionierenden Delays (1s):

...

Was bedeutet LOVF als Antwort? `

Na dann haben wir es mit 1s als Delay.Ok. Übernehme nachher deinen Delay code mit 2s ins Github, dann kannst Du nochmal testen. Mit 2s sollte auch ggf eine bessere Verteilung der Kommunikation stattfinden und vllt weniger LOVF (siehe unten).

https://wiki.fhem.de/wiki/LOVF

… dere Stick sagt das er zu schnell zuviel gesendet hat

Also ich wuerde daraus schliessen dass wir das Delay wirklich groesser machen sollten. Ich nehm jetzt mal 5 Sekunden...

@skraw.iobroker:

PS: Wofuer sind eigentlich die staendigen X Kommandos gut? Mit dem Kommando fragt man beim CUL den Stand des Sendelimits ab. Hab aber noch nicht geschaut was der Adapter/Code damit tut. Ich denke Requests selbst delayen oder so

Mir faellt nur auf dass es jede Menge X Kommandos gibt, wohl ca alle 5 Sekunden eins.

[apollon77]

Das ist der Teil der mir noch nicht gefällt. In jedem Fall braucht man nach einem "X" keine x Sekunden warten weil dieser befehl keine Kommunikation auslöst … oder doch ?! Ich weiss ja nicht warum das Ding crasht

[skraw.iobroker]

Also der Patch fuer den Mode (ToString usw) ist auf jeden Fall zu machen. Der funktioniert!

[apollon77]

Also im Github ist jetzt folgendes drin:

• Änderungen für Thermostat Mode …

• Delays nach dem senden. Bei Kommando "X" 500ms, sonst 2000ms (mal so versuchen)

• Code der vor dem reinlegen in die Queue schaut ob das gleiche Kommando schon drin ist - wenn nein wird es nicht nochmal reingelegt. SOllte vor allem mehrere "X" verhindern.

Please try

[skraw.iobroker]

Also man koennte ja den Delay setzen je nachdem ob das Kommando mit X anfaengt oder nicht….?

[apollon77]

Die neue Version auf Github macht genau das (Version von nach 22:13 Uhr!!!) siehe letzter Post … Sorry, ggf nochnal updaten bitte

[skraw.iobroker]

Ich glaube der Vergleich mit Kommando X geht nicht:

maxcul.0 2018-03-05 22:13:56.910 debug serial port buffer have been drained

maxcul.0 2018-03-05 22:13:56.909 debug Send Packet to CUL: X, awaiting drain event

maxcul.0 2018-03-05 22:13:53.905 debug delayed 2000ms

maxcul.0 2018-03-05 22:13:51.923 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":483,"ack":true,"ts":1520284431918,"q":0,"from":"system.adapter.maxcul.0","lc":1520284431918}

maxcul.0 2018-03-05 22:13:51.905 debug serial port buffer have been drained

maxcul.0 2018-03-05 22:13:51.905 debug Send Packet to CUL: X, awaiting drain event

maxcul.0 2018-03-05 22:13:48.901 debug delayed 2000ms

maxcul.0 2018-03-05 22:13:46.905 debug redis pmessage io.maxcul.0.* io.maxcul.0.info.quota {"val":478,"ack":true,"ts":1520284426898,"q":0,"from":"system.adapter.maxcul.0","lc":1520284426898}

maxcul.0 2018-03-05 22:13:46.904 debug serial port buffer have been drained

maxcul.0 2018-03-05 22:13:46.904 debug Send Packet to CUL: X, awaiting drain event

Der Delay 2000 sollte da nicht stehen, oder?

Habs probiert: Du musst das Kommando trimmen …

Noch was: es waere vielleicht schoen zu sehen wie lang die Queue ist (vielleicht in der delay ausgabe ala delayed 2000ms, 5 in queue)

[skraw.iobroker]

Mein Vorschlag:

CommunicationServiceLayer.prototype.writeQueue = function() {

if (!this._queuedWrites.length) return Promise.resolve(true);

this._queueSendInProgress = true;

var command = this._queuedWrites.shift();

var cmd = command.trim();

var len = this._queuedWrites.length;

return this._serialDeviceInstance.writeAsync(command).then(() => {

env.logger.debug('Send Packet to CUL: ' + cmd + ', awaiting drain event');

return this._serialDeviceInstance.drainAsync()

}).then(() => {

env.logger.debug('serial port buffer have been drained');

var delay = 3000;

if (cmd === 'X') delay = 0;

Promise.delay(delay).then(() => {

env.logger.debug('delayed ' + delay + 'ms, ' + len + ' in queue');

this._queueSendInProgress = false;

return this.writeQueue();

});

});

};

Delay = 0 bei X geht, hab ich probiert.

Fuer mich sehen die Antworten auf die Delays deutlich weniger kritisch aus wenn sie groesser sind, da X jetzt nicht mehr drin ist verzoegert das auch nicht wirklich was. Bei vielen Kommandos bekommt man sowieso per LOVF eins auf die Muetze, da kann man gleich von Haus aus laenger warten.

Meine Idee vom Anfang bestaetigt sich irgendwie, Kommando schicken, dann warten (zwischendrin ACK bekommen), dann naechstes Kommando schicken.

Laut irgendeinem Artikel ist die laengste Zeit fuer ein Kommando + ACK bei ca 2,1 Sekunden. Also sollten wir wenigstens 3 Sekunden warten (als Puffer).

[apollon77]

Hi,

dann hast Du zu früh installiert gehabt Seit der "Version von nach 22:13 Uhr!!!" vergleiche ich einfach das erste Zeichen

Habe jetzt Delay auf 0 gesetzt.

Habe Queue längen-Logging an mehreren Stellen eingebaut.

3000ms als Standard Delay übernommen.

AN sich sollte es nicht nötig sein auf das Ack zu warten … aber ehrlich: Mir egal :-))

Wenn andere User damit Probleme haben melden Sie sich (hoffentlich).

Please try Github version.

[skraw.iobroker]

Bin leider erst jetzt dazu gekommen.

Wenn ich das richtig sehe ignorierst Du auch Zs Kommandos wenn sie schon in der Queue sind?

Jetzt die Frage die kommen musste:

Waere es kompliziert den Delay-Wert in der Konfiguration fuer den User einstellbar zu machen? Ich meine ich kann einfach die Stelle im Code editieren, aber das ist ja eigentlich nicht wirklich der Weg von ioBroker …

Ausserdem koennte es ja verschiedene Hardware geben die auch komplett unterschiedlich reagiert. Irgendwas braucht vielleicht gar kein Delay...

[apollon77]

@skraw.iobroker:

Bin leider erst jetzt dazu gekommen.

Wenn ich das richtig sehe ignorierst Du auch Zs Kommandos wenn sie schon in der Queue sind? `

Ich ignoriere alles was schon in der Queue ist - damit auch Zs Kommandos, aber nur wenn die komplette Message schon drin ist. Am Ende will ich nur sicherstellen das ggf retries oder nicht rausgehen wenn die originale Message noch nicht mal draussen ist

@skraw.iobroker:

Jetzt die Frage die kommen musste:

Waere es kompliziert den Delay-Wert in der Konfiguration fuer den User einstellbar zu machen? Ich meine ich kann einfach die Stelle im Code editieren, aber das ist ja eigentlich nicht wirklich der Weg von ioBroker …

Ausserdem koennte es ja verschiedene Hardware geben die auch komplett unterschiedlich reagiert. Irgendwas braucht vielleicht gar kein Delay... `
Geht grundsätzlich, würde jetzt das mal so releasen und auf weiteres Feedback anderer User warten

[skraw.iobroker]

Die Idee warum ich das mit der User-Config auch frage liegt auch darin, dass man in dem Dropdown Menu dann verschiedene Standard-Werte fuer verschiedene Hardware vorgeben koennte.

Wenn ein nicht-nanoCUL beispielsweise kein Delay braeuchte koennte man:

<delay-feld>0 (supercoole Hardware)

5000 (nanoCUL)

machen…

PS: Bisher laeuft alles gut.

Ich betreibe jetzt 15 Thermostate und 13 Fensterkontakte ziemlich problemlos.

Was mir fehlt ist eine Statistik wo ich ueber die Zeit (sagen wir 24h) sehen kann wie hoch die Credits sind. Das wuerde es ermoeglichen konkret festzustellen wenn man wirklich keine Zeitslots mehr hat oder wann es sich etwas staut...</delay-feld>