vinodsr / node-red-contrib-tuya-smart-device

a node-red module for managing tuya smart devices
https://flows.nodered.org/node/node-red-contrib-tuya-smart-device
MIT License
47 stars 15 forks source link

Device always disconnects and just reconnects on deploy #84

Closed fah closed 2 years ago

fah commented 2 years ago

My log if full of messages like this:

- [error] [tuya-smart-device:WP1] Device not connected. Can't send the GET commmand 

I tried to setup the device node with ip address and Device Virtual ID in all combinations. I all cases the connection gets lost when leaving the node-red editor for a while.

Sometimes the reconnect works - most times it does not.

The network is monitored and ping is stable working to the device. (Tested over many hours.)

In the log below I changed the name of the node from WP1 to WP11. After deploy the device reconnected.

2022-04-23 22:50:18.606 - info: node-red.0 (994) Loglevel changed from "warn" to "silly"
2022-04-23 22:51:07.712 - debug: node-red.0 (994) 23 Apr 22:51:07 - [info] [tuya-smart-device:WP12] Recieved input : {"_msgid":"a0a21a5acf308f0e","payload":{"operation":"SET","dps":"1","set":false}}
2022-04-23 22:51:07.714 - error: node-red.0 (994) 23 Apr 22:51:07 - [info] [tuya-smart-device:WP12] Device not connected. Can't send the SET commmand
23 Apr 22:51:07 - [error] [tuya-smart-device:WP12] Device not connected. Can't send the SET commmand
2022-04-23 22:51:19.279 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] Geänderte Nodes werden gestoppt
2022-04-23 22:51:19.280 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] [tuya-smart-device:WP12] closeComm(): Cleaning up the state
2022-04-23 22:51:19.281 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] [tuya-smart-device:WP12] closeComm(): Clearing the find timeout handler
23 Apr 22:51:19 - [info] [tuya-smart-device:WP12] closeComm(): Disconnecting from Tuya Device
2022-04-23 22:51:19.282 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] Geänderte Nodes sind gestoppt
2022-04-23 22:51:19.290 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] Geänderte Nodes werden gestartet
2022-04-23 22:51:19.292 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] Recieved the config {"id":"77212ca8.79cff4","type":"tuya-smart-device","z":"...","deviceName":"WP1","disableAutoStart":false,"deviceId":"","deviceKey":"...","deviceIp":"192.168.1.1","retryTimeout":"21600000","findTimeout":"21600000","tuyaVersion":"3.3","eventMode":"event-both","x":330,"y":240,"wires":[[...],[]],"moduleVersion":"4.1.1"}
2022-04-23 22:51:19.293 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] Event subscription : shouldSubscribeData=>true , shouldSubscribeRefreshData=>true
2022-04-23 22:51:19.294 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] Auto start probe on connect...
23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] closeComm(): Cleaning up the state
23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] closeComm(): Clearing the find timeout handler
23 Apr 22:51:19 - [info] [tuya-smart-device:WP1] closeComm(): Disconnecting from Tuya Device
2022-04-23 22:51:19.295 - debug: node-red.0 (994) 23 Apr 22:51:19 - [info] Geänderte Nodes sind gestartet
2022-04-23 22:51:19.851 - info: node-red.0 (994) Save /opt/iobroker/iobroker-data/node-red/flows.json
2022-04-23 22:51:20.294 - debug: node-red.0 (994) 23 Apr 22:51:20 - [info] [tuya-smart-device:WP1] startComm(): Connecting to Tuya with params {"id":"","key":"...","ip":"192.168.1.1","issueGetOnConnect":false,"nullPayloadOnJSONError":false,"version":"3.3"} , findTimeout : 21600000 , retryTimeout: 21600000
2022-04-23 22:51:20.295 - debug: node-red.0 (994) 23 Apr 22:51:20 - [info] [tuya-smart-device:WP1] findDevice(): Initiating the find command
2022-04-23 22:51:23.435 - debug: node-red.0 (994) 23 Apr 22:51:23 - [info] [tuya-smart-device:WP1] findDevice(): Found device, going to connect
2022-04-23 22:51:24.809 - debug: node-red.0 (994) 23 Apr 22:51:24 - [info] [tuya-smart-device:WP1] Connected to device!
2022-04-23 22:51:25.111 - debug: node-red.0 (994) 23 Apr 22:51:25 - [info] [tuya-smart-device:WP1] Error from tuyaDevice. shouldTryReconnect = true, error = {}
2022-04-23 22:51:25.112 - error: node-red.0 (994) 23 Apr 22:51:25 - [error] [tuya-smart-device:WP1] Error: Error from socket: read ECONNRESET
at Socket. (/opt/iobroker/iobroker-data/node-red/node_modules/node-red-contrib-tuya-smart-device/node_modules/tuyapi/index.js:492:30)
at Socket.emit (events.js:314:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21)
23 Apr 22:51:25 - [info] [tuya-smart-device:WP1] Will try to reconnect after 21600000 milliseconds
2022-04-23 22:51:25.114 - debug: node-red.0 (994) 23 Apr 22:51:25 - [info] [tuya-smart-device:WP1] Disconnected from tuyaDevice. shouldTryReconnect = true
23 Apr 22:51:25 - [info] [tuya-smart-device:WP1] Will try to reconnect after 21600000 milliseconds
2022-04-23 22:52:16.467 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] Geänderte Nodes werden gestoppt
2022-04-23 22:52:16.468 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] [tuya-smart-device:WP1] closeComm(): Cleaning up the state
23 Apr 22:52:16 - [info] [tuya-smart-device:WP1] closeComm(): Clearing the find timeout handler
23 Apr 22:52:16 - [info] [tuya-smart-device:WP1] closeComm(): Disconnecting from Tuya Device
2022-04-23 22:52:16.469 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] Geänderte Nodes sind gestoppt
2022-04-23 22:52:16.486 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] Geänderte Nodes werden gestartet
2022-04-23 22:52:16.489 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] Recieved the config {"id":"77212ca8.79cff4","type":"tuya-smart-device","z":"...","deviceName":"WP11","disableAutoStart":false,"deviceId":"","deviceKey":"...","deviceIp":"192.168.1.1","retryTimeout":"21600000","findTimeout":"21600000","tuyaVersion":"3.3","eventMode":"event-both","x":330,"y":240,"wires":[[...],[]],"moduleVersion":"4.1.1"}
2022-04-23 22:52:16.490 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] Event subscription : shouldSubscribeData=>true , shouldSubscribeRefreshData=>true
23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] Auto start probe on connect...
23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] closeComm(): Cleaning up the state
2022-04-23 22:52:16.491 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] closeComm(): Clearing the find timeout handler
23 Apr 22:52:16 - [info] [tuya-smart-device:WP11] closeComm(): Disconnecting from Tuya Device
2022-04-23 22:52:16.493 - debug: node-red.0 (994) 23 Apr 22:52:16 - [info] Geänderte Nodes sind gestartet
2022-04-23 22:52:17.094 - info: node-red.0 (994) Save /opt/iobroker/iobroker-data/node-red/flows.json
2022-04-23 22:52:17.491 - debug: node-red.0 (994) 23 Apr 22:52:17 - [info] [tuya-smart-device:WP11] startComm(): Connecting to Tuya with params {"id":"","key":"...","ip":"192.168.1.1","issueGetOnConnect":false,"nullPayloadOnJSONError":false,"version":"3.3"} , findTimeout : 21600000 , retryTimeout: 21600000
2022-04-23 22:52:17.492 - debug: node-red.0 (994) 23 Apr 22:52:17 - [info] [tuya-smart-device:WP11] findDevice(): Initiating the find command
2022-04-23 22:52:18.356 - debug: node-red.0 (994) 23 Apr 22:52:18 - [info] [tuya-smart-device:WP11] findDevice(): Found device, going to connect
2022-04-23 22:52:18.367 - debug: node-red.0 (994) 23 Apr 22:52:18 - [info] [tuya-smart-device:WP11] Connected to device!

I've found reconnect statements in tuya-smart-device.js at some places where the timeout is hard coded to 1000ms. This could be a reason. (line 185, 404, ...)

I also don't understand the long wait time of 6 Minutes (21600000ms) for a reconnect. If I have scheduled commands they will, on a regular base, fail.

Strange is that the reconnect on deploy works most times but fails in normal operation.

Thank you for your good work!

stale[bot] commented 2 years 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. Thank you for your contributions.

fah commented 2 years ago

Still existing in latest version.

vinodsr commented 2 years ago

Can you please set the find time out to 10 seconds and retry to 1 sec and try ?

fah commented 2 years ago

I haven't seen before that you added the two fields. Very nice!

With values for retry: 10800... (the default value) and find: 1 sec. I could not connect after deployment.

With 10 & 1 sec. it works. I'll give it a try.

But I have to wait some time to see if it is stable or not.

Edit: Kept just relevant lines.

vinodsr commented 2 years ago

But I have to wait some time to see if it is stable or not.

How long ?

fah commented 2 years ago

Until now I only got one message about 30 minutes after changing the values:

28 Jun 18:16:12 - [error] [tuya-smart-device:WP11] Error: Error from socket: read ECONNRESET
    at Socket.<anonymous> (/opt/iobroker/iobroker-data/node-red/node_modules/node-red-contrib-tuya-smart-device/node_modules/tuyapi/index.js:492:30)
    at Socket.emit (events.js:314:20)
    at emitErrorNT (internal/streams/destroy.js:92:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
    at processTicksAndRejections (internal/process/task_queues.js:84:21)

This looks pretty good so far.

Edit: Maybe one day?

fah commented 2 years ago

It is very stable now. Thank you!

For the record: I only use the IP address and have the tuya device on site with a very stable WiFi. (Two repeaters within reach.)