Power outage to tuya devices makes homebridge unresponsive due to excessive logging

[sasikiran]

Checklist

• [ x ] I have read the common issues wiki page
• [ x ] I have checked to make sure the plugin is up to date

Describe the bug
If a tuya device on homebridge loses power / connectivity, homebridge becomes unresponsive and requires force restart.

To Reproduce
Steps to reproduce the behavior:

• Add and configure Tuya devices. In my case, it was a 16A smart plug and a 12W light bulb. I have more devices added to homebridge but all those have power backup.
• Disconnect power to the devices.
• Watch homebridge logs for continuous errors.
• After few mins (say 15 mins), give the power back to the devices.
• The logs in homebridge still keep logging in.
• Restarting homebridge becomes unresponsive.
• Force reboot raspberry pi to fix the problem.

Expected behavior
It can log errors, but only periodically. It shouldn't make homebridge unresponsive due to excessive logging.

Screenshots
Couldn't take screenshots. Had to force reboot Raspberry Pi 4B with 4GB RAM. If this happens again, will take screenshots and update it here.

Environment (please complete the following information):

• OS: HOOBS 3.2.6
• iOS version: 14.0
• Homehubs: -
• Node Version: 12.16.3
• Plugin Version: 1.0.5
• Accessory Type: Smart plug and Smart bulb

[iRayanKhan]

Hi there, this is a known issue, and will be patched in the next release. I'm going to release it as part of V1.x instead of V2.

[dkossman]

not sure if this is related, but after i updated the plugin to the latest version, I'm getting thousands of log messages like:
[TuyaAccessory] Slowing down retry attempts; if you see this happening often, it could mean some sort of incompatibility.
[TuyaAccessory] Socket had a problem and will reconnect to Porch Lights (Error: ERR_CONNECTION_TIMED_OUT)

The plugin had been working perfectly up til then. Note that I have also updated Homebridge to the latest released version (I think 1.2.0)

All my other plugins are working fine but i've had to remove all my Tuya accessories from the config.

I'm on

• Node v11.5.0 (the latest i found that runs on a Pi Zero)
• Raspian Buster
• Homebridge 1.2.0
• all devices are Tuya-compatable smart switches

[davidh2075]

If the original issue that @sasikiran reported is an "ECONNRESET storm" (see below) when powering on a Tuya accessory powered off more than about a minute ago, I experienced the same thing about a month ago while repurposing some outlet accessories and fixed it last week in my own copy of TuyaAccessory.js.

I don't know if I've made the correct fixes. The ECONNRESET storm in the logs is about 50 or more message pairs per second like this:

[TuyaAccessory] Sending first query to Driveway io-WiFi-Plug-PM 3 (3.3)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (ECONNRESET)

It happens for me only if you leave the accessory powered off long enough to get an ERR_CONNECTION_TIMED_OUT. The sequence where it starts looks like this:

[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (Error: ERR_PING_TIMED_OUT)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (EHOSTUNREACH)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (EHOSTUNREACH)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (EHOSTUNREACH)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (Error: ERR_CONNECTION_TIMED_OUT)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (EHOSTUNREACH)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (EHOSTUNREACH)
##########
# turned outlet back on here
#########
[TuyaDiscovery] UDP from 192.168.0.193:6667 0x000055aa...0x0000aa55
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (ECONNREFUSED)
[TuyaAccessory] Sending first query to Driveway io-WiFi-Plug-PM 3 (3.3)
[TuyaAccessory] Heard back from Driveway io-WiFi-Plug-PM 3 with command 10
[TuyaAccessory] Heard back from Driveway io-WiFi-Plug-PM 3 with command 8
[TuyaAccessory] Sending first query to Driveway io-WiFi-Plug-PM 3 (3.3)
[TuyaAccessory] Socket had a problem and will reconnect to Driveway io-WiFi-Plug-PM 3 (ECONNRESET)

My TuyaAccessory.js still includes some DEBUG log messages, as I'm not convinced I've really fixed it, despite it working repeatedly. These are the changes I made, and the console.log DEBUG statements can all be deleted with no functional impact:

56a57,58
>       console.log(
>           `[TuyaAccessory DEBUG] reconnect called for ${this.context.name}`);
66a69,73
>       if (this._socket._errorReconnect) {
>         clearTimeout(this._socket._errorReconnect);
>         this._socket._errorReconnect = null;
>       }
> 
75a83,84
>       this._incrementAttemptCounter();
> 
99c108,110
<       setTimeout(() => this._socket._ping(), 1000);
---
>       if (this._socket._pinger)
>         clearTimeout(this._socket._pinger);
>       this._socket._pinger = setTimeout(() => this._socket._ping(), 1000);
144a156,158
>         console.log(
>             `[TuyaAccessory DEBUG] Reconnecting with connection attempts =  ${
>                 this._connectionAttempts}`);
165c179,187
<       setTimeout(() => { process.nextTick(this._connect.bind(this)); }, delay);
---
>       if (!this._socket._errorReconnect) {
>         console.log(
>             `[TuyaAccessory DEBUG] after error setting _connect in ${delay}ms`);
>         this._socket._errorReconnect = setTimeout(() => {
>           console.log(`[TuyaAccessory DEBUG] executing _connect after ${
>               delay}ms delay`);
>           process.nextTick(this._connect.bind(this));
>         }, delay);
>       }
182c204,209
<     setTimeout(() => { this._connectionAttempts--; }, 10000);
---
>     setTimeout(() => {
>       console.log(
>           `[TuyaAccessory DEBUG] decrementing this._connectionAttempts, currently ${
>               this._connectionAttempts}`);
>       this._connectionAttempts--;
>     }, 10000);

This is the commit comment explaining my changes:

    To prevent a fast ECONNRESET loop when turning off an accessory and 
    turning it back on more than a few minutes later, e.g. to move and 
    re-purpose it, did the following:
    In _socket.on('error') recorded the _connect() Timeout in
    this._socket._errorReconnect and tested that value before setting
    another Timeout to prevent scheduling two _connect() calls;
    Added _errorReconnect to the list of Timeouts cleared in _connect();
    In this._socket.reconnect, incremented the Attempt Counter
    this._connectionAttempts just before the call to
    this._socket.connect(). The attempt counter was being incremented only
    on _connect(), not on reconnect;
    In _socket.on('connect'), cleared an existing pinger Timeout before
    setting another one;
    Added several DEBUG console.log statements to help trace what was
    happening and confirm the above changes worked.

[dkossman]

@iRayanKhan apologies if this is being discussed elsewhere and has already been addressed, but can you take a look at the changes above and if it seems appropriate, incorporate this change? I'm having the same issue with the current version of the plugin.

[iRayanKhan]

Try 1.2.0

[AndrewJ1990]

This is still happening in v1.2

[davidh2075]

I finally got around to opening a PR for this. #197

[ElphaX]

Merged and fixed.