Apollon77 / ioBroker.tuya

ioBroker adapter to connect to several small and cheap Wifi devices that care connected to the Tuya Cloud and mostly use the Smartlife App/Alexa-Skill
MIT License
87 stars 21 forks source link

Error: A set command is already in progress. Can not issue a second one that also should return a response. #531

Open iobroker-sentry-github-app[bot] opened 1 year ago

iobroker-sentry-github-app[bot] commented 1 year ago

Sentry Issue: IOBROKER-TUYA-5CB

Error: A set command is already in progress. Can not issue a second one that also should return a response.
  File "/opt/iobroker/node_modules/tuyapi/index.js", line 396, in TuyaDevice.set
    throw new Error('A set command is already in progress. Can not issue a second one that also should return a response.');
  File "/opt/iobroker/node_modules/iobroker.tuya/main.js", line 280, in Object.onChange [as 44674606a4cf12cd3178.2]
    knownDevices[physicalDeviceId].device.set({
  File "/opt/iobroker/node_modules/@apollon/iobroker-tools/lib/objectHelper.js", line 269, in Object.handleStateChange
    stateChangeTrigger[id](state.val);
  File "/opt/iobroker/node_modules/iobroker.tuya/main.js", line 181, in Adapter.<anonymous>
    objectHelper.handleStateChange(id, state);
  File "events.js", line 400, in Adapter.emit
...
(3 additional frame(s) were not displayed)
Apollon77 commented 1 year ago

Bildschirm­foto 2023-04-12 um 08 17 39

Add queue?

larryxxl2 commented 1 year ago

With Version 3.14.2 fewer messages are displayed.

tuya.0 2023-04-13 15:16:51.171 warn bf17d09824e596a204wgqu error on refresh: A set command is already in progress. Can not issue a second one that also should return a response.
tuya.0 2023-04-13 15:10:37.203 warn bf555713b9595272afqivz error on refresh: A set command is already in progress. Can not issue a second one that also should return a response.
tuya.0 2023-04-13 14:45:47.192 warn bfc42b03ee26beb86dghsh error on refresh: A set command is already in progress. Can not issue a second one that also should return a response.
tuya.0 2023-04-13 14:40:56.916 warn bfc42b03ee26beb86dghsh error on refresh: A set command is already in progress. Can not issue a second one that also should return a response.
tuya.0 2023-04-13 14:36:52.858 warn bf17d09824e596a204wgqu error on refresh: A set command is already in progress. Can not issue a second one that also should return a response.
Apollon77 commented 1 year ago

Please provide a debug log of such a case. Especially interesting is the timepoint a bit before and after it started the first time!

larryxxl2 commented 1 year ago

debug log tuya.txt

Tuya warn.txt

vepman commented 1 year ago

log.txt Auch bei mir erscheinen diesen Fehlermeldungen. Der Adapter funktioniert aber einwandfrei. Das aktuelle Log habe ich angefügt.

LG log-18-39.txt

vepman commented 1 year ago

Der Adapter funktioniert ja gut, aber ein Tipp, wie man die Fehlermeldungen reduziert wäre sehr hilfreich. Vielen Dank im voraus.

Apollon77 commented 1 year ago

Naja am ende ist da was nicht ganz ok :-) Was du tun kannst ist das loglevel der instanz auf stufe "error" setzen dann wird alles andere nichtgeloggt

Foradh commented 1 year ago

Hallo zusammen, hat jemand herausgefunden wodurch dieser Fehler verursacht wird. Bei mir erscheint dieser auch seit einiger Zeit.

tuya.0 | 2023-07-02 11:30:17.102 | warn | 47033807a4e57ca592fc.1: A set command is already in progress. Can not issue a second one that also should return a response.. Try to use cloud. -- | -- | -- | --

Die lokale Verbindung funktioniert damit nicht mehr zuverlässig und ich habe nun parallel die Cloud Funktion eingerichtet. Das Gerät wurde bereits komplett gelöscht und mit dem Proxy erneut eingerichtet...wird auch gefunden und hinzugefügt, wenn ich allerdings die Datenpunkte verändere kommt oben aufgeführte Fehler.

Beste Grüße Foradh

Apollon77 commented 1 year ago

Ich muss mir ansehen wann das passiert ... am besten gern auch mal Debug log mitlaufen lassen. Da scheint wohl ein "set" kommando nicht vom gerät bestätigt zu werden aber die Library wartet noch darauf und blockiert neues senden deswegen.

Foradh commented 1 year ago

Hi Apollon77, anbei der debug log beim erwähnten event und vielen Dank für den wirklich tollen Adapter bzw. das gesamte ioBroker Projekt!!!!

tuya.0 | 2023-07-03 15:50:19.546 | debug | Received 1 devices from cloud: [{"virtual":false,"lon":"10.4983","ownerId":"57340746","uuid":"47033807a4e57ca592fc","mac":"a4e57ca592fc","accessType":0,"otaInfo":{"supportAuto":true,"otaUpgradeModes":[0],"otaModuleMap":{"wifi":{"upgradeStatus":0,"cdv":"1.0.0","bv":"5.57","verSw":"3.1.4"},"mcu":{"upgradeStatus":0,"cdv":"","verSw":"1.0.0"}}},"iconUrl":"https://images.tuyaeu.com/smart/icon/1537857926nlb8964flm_0.png","communication":{"mqttTopicAttr":1,"communicationNode":"47033807a4e57ca592fc","communicationModes":[{"pv":"","type":0},{"pv":"2.2","type":1}],"dataModel":1,"connectionStatus":1},"gatewayVerCAD":"","lat":"50.0320","runtimeEnv":"prod","devKey":"","devId":"47033807a4e57ca592fc","productId":"koAASpds906awojG","ip":"31.19.79.92","activeTime":1685292929,"cloudOnline":true,"baseAttribute":1024,"devAttribute":3,"dataPointInfo":{"dpMaxTime":1688392217400,"dpName":{},"dps":{"1":true,"102":31,"103":true,"104":0,"105":"warm","106":29,"107":18,"108":40,"115":0,"116":0,"117":true,"118":false,"120":-22,"122":-22,"124":-22,"125":0,"126":0,"127":-22,"128":0,"129":0,"130":false,"134":false,"135":false,"136":false,"139":false,"140":"LowSpeed"},"dpsTime":{"1":1688392217400,"102":1688389702497,"103":1687692878411,"104":1688383732352,"105":1687692878529,"106":1688390026197,"107":1687692878646,"108":1687692878698,"115":1688317701783,"116":1687692878903,"117":1688392217218,"118":1662491784580,"120":1662491784580,"122":1662491784580,"124":1662491784580,"125":1662491784580,"126":1662491784580,"127":1662491784580,"128":1662491784580,"129":1662491784580,"130":1662491784580,"134":1662491784580,"135":1662491784580,"136":1662491784580,"139":1662491784580,"140":1662491784580}},"meta":{},"name":"Inverter Pool Wärmepumpe 2","timezoneId":"Europe/Berlin","deviceTopo":{},"localKey":"fE45il(1tC!FSL0?","dps":{"1":true,"102":31,"103":true,"104":0,"105":"warm","106":29,"107":18,"108":40,"115":0,"116":0,"117":true,"118":false,"120":-22,"122":-22,"124":-22,"125":0,"126":0,"127":-22,"128":0,"129":0,"130":false,"134":false,"135":false,"136":false,"139":false,"140":"LowSpeed"},"dpName":{},"groudId":57340746}] -- | -- | -- | -- tuya.0 | 2023-07-03 15:50:17.409 | debug | stateChange tuya.0.47033807a4e57ca592fc.1 {"val":true,"ack":true,"ts":1688392217403,"q":0,"from":"system.adapter.tuya.0","user":"system.user.admin","lc":1688371217153} tuya.0 | 2023-07-03 15:50:17.392 | debug | 47033807a4e57ca592fc: Received data: {"devId":"47033807a4e57ca592fc","dps":{"1":true},"t":1688392216} tuya.0 | 2023-07-03 15:50:17.371 | debug | 47033807a4e57ca592fc.1: set value true via 47033807a4e57ca592fc (Cloud): res=true tuya.0 | 2023-07-03 15:50:17.300 | debug | stateChange tuya.0.47033807a4e57ca592fc.117 {"val":true,"ack":true,"ts":1688392217296,"q":0,"from":"system.adapter.tuya.0","user":"system.user.admin","lc":1688198548891} tuya.0 | 2023-07-03 15:50:17.249 | debug | 47033807a4e57ca592fc.117: set value true via 47033807a4e57ca592fc (Local): res={"devId":"47033807a4e57ca592fc","dps":{"117":true},"t":1688392216} tuya.0 | 2023-07-03 15:50:17.247 | debug | 47033807a4e57ca592fc: Received data: {"devId":"47033807a4e57ca592fc","dps":{"117":true},"t":1688392216} tuya.0 | 2023-07-03 15:50:17.188 | warn | 47033807a4e57ca592fc.1: A set command is already in progress. Can not issue a second one that also should return a response.. Try to use cloud. tuya.0 | 2023-07-03 15:50:17.187 | debug | 47033807a4e57ca592fc onChange triggered for 1 and value true tuya.0 | 2023-07-03 15:50:17.186 | debug | stateChange tuya.0.47033807a4e57ca592fc.1 {"val":true,"ack":false,"ts":1688392217172,"q":0,"c":"script.js.Eigene_Skripte.Pool.Poolheizung","from":"system.adapter.javascript.0","user":"system.user.admin","lc":1688371217153} tuya.0 | 2023-07-03 15:50:17.179 | debug | 47033807a4e57ca592fc onChange triggered for 117 and value true
Dirk-KI commented 1 year ago

Hi Apollon77, zu allererst: vielen Dank für die supergute Arbeit!

ich habe heute mittag mal die Anzahl der heutigen Warnmeldungen ausgewertet (5.7.23 0:00h bis 12:00h) von meinen 59 aktiven Geräten zeigen 23 eine sehr hohe Warnmelungsfrequenz (ca 2Meldungen/Minute).

Diese Geräte mit der hohen Warnmeldungsfrequenz sind ausnahmslos Geräte, die - bisher problemlos- über 2 Zigbee-Gateways eingebunden waren. Es gibt 3 Zigbee-geräte, die keine oder sehr wenige dieser Meldungen senden.

die 33 über Wlan eingebundene Geräte senden keine dieser Warnmeldungen; mit einer Ausnahme, dort gab es 2 Meldungen an einem halben Tag.

warn-io2.txt

Dirk-KI commented 1 year ago

Die Endungen "ero" und "gw2" gehören zu den beiden zigbee-gateways

warnlog

007Schneiderlein commented 10 months ago

Hi @Apollon77 ,

ich schon wieder... bei mir ist aktuell noch ein kleines weiteres Würmchen (nach ALEXA) drin..

Seit ein paar Tagen, vermutlich nach meiner raspi Neuinstallation habe ich folgende Fehlermeldungen vom Tuya adapter im Log und auch habe ich sehr schnelle Zustandsänderungen am Aktor, wenn ich diesen per iobroker anspreche. z.B. Rollladen fährt unkontrolliert hoch und runter....

Der Adapter kann sich wohl nicht mehr lokal mit den Aktoren / Sensoren verbinden... Ssiehe log..

tuyalog.txt

Liegt das ggf. an meiner aktuellen Systemkonfiguration?

Plattform: linux Betriebssystem: linux Architektur: arm64 CPUs: 4 Geschwindigkeit: 1500 MHz Modell: Cortex-A72 RAM: 3.7 GB System-Betriebszeit: 00:08:30 Node.js: v20.5.0 time: 1692304499396 timeOffset: -120 Adapter-Anzahl: 489 NPM: v9.8.0 Datenträgergröße: 219.9 GB Freier Festplattenspeicher: 201.7 GB Betriebszeit: 00:08:17 Aktive Instanzen: 31 Pfad: /opt/iobroker/ aktiv:

Oder muss ich die Geräte nochmal mit der Tuya Android App via Proxy etc. neu mit dem Adapter lokal verbinden?

Allerbesten Dank wieder Mal, Grüße Stefan

FlorianSchulze commented 8 months ago

Ich kann diesen Fehler produzieren, wenn ich per script zum Beispiel bei einer Heizung "mode" und "temp" direkt hintereinander schreibe - dann kommt er zuverlässig. Lasse ich die zweite Property-änderung mit einer Verzögerung von 500msec laufen, kommt er zuverlässig nicht. Lokale connection, versteht sich. Kurze Ansicht im Code lässt den Verdacht aufkommen das hier weder geblockt wird (bis zu einem timeout) oder - besser - eine queue vorgeschaltet ist?

Apollon77 commented 8 months ago

Ok das ist eine gute information ... Danke

robschii commented 7 months ago

ich hänge mich mal mit dran.

ich habe den fehler auch.

ich schlate 4 Lampen uber "Szenen" in 3 verschiedenen Modis Dimmung 100% 50% und Nachlicht. Wenn ich teste ohne verzögerung dann habe ich auch die fehler. habe ich die befehle in 500ms Abstand geht es ohne Fehler hin uns wieder

disaster123 commented 7 months ago

same here...

disaster123 commented 7 months ago

Nutze nun setStateDelayed und erhöhe nach jedem Befehl das Delay um 500ms - schön ist aber etwas anderes...

Apollon77 commented 7 months ago

Ja, ich muss schauen was das ist und wie ich es behandeln kann.

FlorianSchulze commented 7 months ago

Hi Ingo,

einfach eine Idee die ich einwerfen möchte, ich stecke aber nicht im Detail in Deinem code: — https://github.com/taskforcesh/bullmqhttps://optimalbits.github.io/bull/

Damit implementierst Du eine Queue und entkoppelst den Sendeprozess vom direkten Ablauf. Die Queue kann dann auch auf fails reagieren und zum Beispiel zweifach einen retry ausführen. Außerdem kannst Du Kommando´s in der Queue mit einer TTL, also einer maximalen “Lebenszeit” ausstatten. Soweit ich das sehe würde das Problem damit gelöst und es würde sogar noch etwas Stabilität reinbringen durch retry´s.

liebe Grüße Florian

On 21. Nov 2023, at 09:02, Ingo Fischer @.***> wrote:

Ja, ich muss schauen was das ist und wie ich es behandeln kann.

— Reply to this email directly, view it on GitHub https://github.com/Apollon77/ioBroker.tuya/issues/531#issuecomment-1820413164, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJYRJSKZZZJP67564W2HWK3YFRN23AVCNFSM6AAAAAAW3GXVZ2VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQMRQGQYTGMJWGQ. You are receiving this because you commented.

Apollon77 commented 7 months ago

@FlorianSchulze Da wird schon eine Queue verwendet in der Library ... und DAS ist das Problem! Es kommt keine Antwort zurück und deswegen hängt die Queue fest. Die Magie wird also sein irgendwie rauszufinden wie lange man auf antwort wartet und wie man damit umgeht

stale[bot] commented 3 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs within the next 7 days. Please check if the issue is still relevant in the most current version of the adapter and tell us. Also check that all relevant details, logs and reproduction steps are included and update them if needed. Thank you for your contributions. Dieses Problem wurde automatisch als veraltet markiert, da es in letzter Zeit keine Aktivitäten gab. Es wird geschlossen, wenn nicht innerhalb der nächsten 7 Tage weitere Aktivitäten stattfinden. Bitte überprüft, ob das Problem auch in der aktuellsten Version des Adapters noch relevant ist, und teilt uns dies mit. Überprüft auch, ob alle relevanten Details, Logs und Reproduktionsschritte enthalten sind bzw. aktualisiert diese. Vielen Dank für Eure Unterstützung.

disaster123 commented 3 months ago

Still valid and still a problem!

vepman commented 3 months ago

Yes, that's the way it is.

Vippis2000 commented 2 weeks ago

Ich habe diesen Fehler auch bei vielen Geräten