Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add support for passive devices #171

Merged
merged 7 commits into from
Dec 15, 2020
Merged

Add support for passive devices #171

merged 7 commits into from
Dec 15, 2020

Conversation

postlund
Copy link
Collaborator

A passive device will by-pass the re-connect loop and not try to connect or re-connect at all by itself. Instead, connects and re-connects are fully driven by discovery (which we do all the time in the background). When a discovery message is received from a passive device, a connection attempt will be made.

This has several benefits, e.g. we can deal with devices where power is cut. We will not try to re-connect randomly in vain, also giving potentially long re-connect times (due to backoff). A passive device will handle this gracefully, giving almost instead feedback. It also helps us deal with battery powered devices that goes to sleep most of the time. Additional improvements to the latter case will be done separately, namely keeping previous state after a disconnect.

@SmartM-ui
Copy link

Hi @postlund ,
I tried the new pull and I configured the yaml for the single bulb that I turn off via the switch:

localtuya:

  • host: IP #lampadario studio
    device_id: 654 ... f9d
    local_key: mylocalkey
    friendly_name: Studio LocalTuya chandelier
    protocol_version: "3.3"
    passive_device: true
    entities:
    • platform: light
      .....
      ......

With the wall switch on and the bulb off, I restarted Home Assistant and this is the log for the bulb:

2020-11-19 00:28:49 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Started heartbeat loop
2020-11-19 00:28:49 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command heartbeat (device type: type_0a)
2020-11-19 00:28:49 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{}'
2020-11-19 00:28:49 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number -100
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command status (device type: type_0a)
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"gwId":"654...f9d","devId":"654...f9d"}'
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 1
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Got heartbeat response
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x93\xb8Z\xef\xbb\xdf\xd3\x86\x84g\xb9\x7fp\xcdO\x9bn\xcf\xe8\x8e\x08\x08\x11\xb8\x11\xa1T\x8c\x10v\xd4\xc5\xc1K\xbf\xae\xd3\x9d\xeag\x00,\x8c\xc49\xc9\x93l\x90e=ZBh\x88B<\x9b\x84\xb3\xd0\x9a7Y\r9O\xcb\xf7\xb09/\xa7\xe4\x97\xe5\x8d\xdf1KZ[\x93\xdcfb#\xda\x99\x8b\xee\x03\xc5\x83\xbbU\x8df\x12\xcc\xdb\x8cQh\xff\xc6\x80d\x1f\xc1\xee\x86y\r\xbb\xb9c(\xb6\xb5Q\xfa\xb9+\xd0\x13\x8c\xec\x08PBSw|{\xe79[\x8f\x92\xc9\xc7\xb8\xab\xe3\xf0\xfb\x08g\x12\xfat\x03\x0e\xc6\xe9\x8d|oe', crc=977456425)
2020-11-19 00:28:50 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching sequence number 1
2020-11-19 00:28:51 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {"devId":"654...f9d","dps":{"20":false,"21":"white","22":507,"23":532,"24":"011d011e01fb","25":"020e0d0000e80383000003e803e8","26":0}}
2020-11-19 00:28:51 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {}

I turned off the wall switch and found that even after many minutes, the state of the light bulb is off instead of unavailable.

I tried to turn on the light bulb from the button in Home Assistant and this is the reported error:

Logger: homeassistant.components.websocket_api.http.connection.54...92
Source: custom_components/localtuya/pytuya/init.py:140
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 00:34:21 (2 occurrences)
Last logged: 00:34:26
module 'logging' has no attribute 'EXCEPTION'

Traceback (most recent call last):
File "/config/custom_components/localtuya/common.py", line 195, in set_dps
await self._interface.set_dps(states)
File "/config/custom_components/localtuya/pytuya/init.py", line 482, in set_dps
return await self.exchange(SET, dps)
File "/config/custom_components/localtuya/pytuya/init.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/init.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 135, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1448, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1483, in _execute_service
await handler.job.target(service_call)
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
await self.hass.helpers.service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 482, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 664, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 519, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/light/init.py", line 249, in async_handle_light_on_service
await light.async_turn_on(**params)
File "/config/custom_components/localtuya/light.py", line 358, in async_turn_on
await self._device.set_dps(states)
File "/config/custom_components/localtuya/common.py", line 197, in set_dps
self.exception("Failed to set DPs %r", states)
File "/config/custom_components/localtuya/pytuya/init.py", line 140, in exception
return self._logger.log(logging.EXCEPTION, msg, *args)
AttributeError: module 'logging' has no attribute 'EXCEPTION'

REGISTER DETAIL

2020-11-19 00:34:21 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command set (device type: type_0a)
2020-11-19 00:34:21 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"devId":"654...f9d","uid":"654...f9d","t":"1605742461","dps":{"20":true}}'
2020-11-19 00:34:21 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 9
2020-11-19 00:34:21 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.547762633792] module 'logging' has no attribute 'EXCEPTION'

I turned on the wall switch and very quickly it changed the state from off to on

2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Started heartbeat loop
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command heartbeat (device type: type_0a)
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{}'
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number -100
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command status (device type: type_0a)
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"gwId":"654...f9d","devId":"654...f9d"}'
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 1
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Got heartbeat response
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {}
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x93\xb8Z\xef\xbb\xdf\xd3\x86\x84g\xb9\x7fp\xcdO\x9bn\xcf\xe8\x8e\x08\x08\x11\xb8\x11\xa1T\x8c\x10v\xd4\xc5\x82w\x86i2\x92\xa4\x16i\x8b\xa5l\xf2\xb0\x93\x94\x91(\x1fVV_\xe2;\xdb\x90\xd6\xe1M\xa1\x14\x94\xfe\x87\xfc\xc0\x04\xafR\xcb\xfa\xd3\xc9\x97\x12(\xc1\x866\x8b=\xd13\xa1\n\x87\x1d\x0b\xa9o\xef\x87:\x99l\xd4\xa2\xf1\x91\xc4\xc27\xa5\x17\x80\x11\xf5/@QLX\x0f<\xbb\xb5aL\xd1G\x8bw\xf6\xa6\x93<\xf3\xe6\xe9\xcc{Nc\xd0\x86)yM\x9d<P\xda\xb2x=\xebO\xcePS9\xd4\xc9I\x83_]{', crc=3408650248)
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching sequence number 1
2020-11-19 00:47:16 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {"devId":"654...f9d","dps":{"20":true,"21":"white","22":507,"23":532,"24":"011d011e01fb","25":"020e0d0000e80383000003e803e8","26":0}}

The problem is that when the light bulb is on and I turn it off from the wall switch, the status remains fixed on ON, while with the previous version, after 15 seconds it was unavailable.
By forcing the recharge of the localtuya integration, the state went unavailable

From unavailable to ON, the change of state is very fast, about 5 seconds, but tomorrow I try better, leaving the wall switch off for many hours

For my "needs", the very fast change of state from "unavailable" to "ON" is what I was looking for, while for the very long state change from "ON" to "unavailable" is what I would like to avoid.

After how long is the parameter set to verify that the wall switch changes state?

Sorry for the very detailed message, but maybe you need to understand the logs

Thanks again Big Pierre :-)

@postlund
Copy link
Collaborator Author

I will try to fix the error soon. You will get instant state changes once it works, but when there's an exception something isn't working so we can't make any assumptions yet.

@postlund
Copy link
Collaborator Author

So, I have pushed an update now. You don't have to wait any long period of time when testing. Just turn the light off, wait for it to go unavailable and then turn it off. If it doesn't work, I need the debug log to verify what is happening.

@ultratoto14
Copy link
Collaborator

ultratoto14 commented Nov 19, 2020

Just tested and waaaaoooouuu. I had the same problem as @SmartM-ui as i have multiple lights with physical switches.
The time taken to discover status vary from 5 to 20 seconds. Seems that longer times occur when I switch on multiple lights at the same time (4 GU10 in living room ceiling).
When they are on, i have this kind of log every 5s:
2020-11-19 09:50:50 DEBUG (MainThread) [custom_components.localtuya.common] [bf7...aiu] Already connecting to 192.168.15.168 (bf7bf96ea08f9cc4c0zaiu) - False, None, bf7bf96ea08f9cc4c0zaiu
2020-11-19 09:50:50 DEBUG (MainThread) [custom_components.localtuya] Passive device bfa0f9a2a52cf1d76fir76 found with IP 192.168.15.166

@@ -71,7 +71,7 @@

from .common import TuyaDevice
from .config_flow import config_schema
from .const import DATA_DISCOVERY, DOMAIN, TUYA_DEVICE
from .const import CONF_PASSIVE_DEVICE, DATA_DISCOVERY, DOMAIN, TUYA_DEVICE
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't we add the "passive_device" option in the YAML sample in init.py ?
I'd also document it in the README.md and info.md.
Great work!

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, I missed that part when I split up the previous PR. Will fix that. Documentation is certainly needed. Maybe we should start looking at GitHub pages for documentation, it's pretty ok (I use it for pyatv over at pyatv.dev).

@postlund
Copy link
Collaborator Author

Just tested and waaaaoooouuu. I had the same problem as @SmartM-ui as i have multiple lights with physical switches.
The time taken to discover status vary from 5 to 20 seconds. Seems that longer times occur when I switch on multiple lights at the same time (4 GU10 in living room ceiling).
When they are on, i have this kind of log every 5s:
2020-11-19 09:50:50 DEBUG (MainThread) [custom_components.localtuya.common] [bf7...aiu] Already connecting to 192.168.15.168 (bf7bf96ea08f9cc4c0zaiu) - False, None, bf7bf96ea08f9cc4c0zaiu
2020-11-19 09:50:50 DEBUG (MainThread) [custom_components.localtuya] Passive device bfa0f9a2a52cf1d76fir76 found with IP 192.168.15.166

You mean the discovery time is between 5-20 seconds with this change? Could be right I guess, I depends on how the device acts. Can you try power-toggling a device and attach the complete log, so I can see what is really going on? That error message shouldn't be there of course.

@ultratoto14
Copy link
Collaborator

@postlund i mean status change from on/off to unavailable, 5 to 20s.
I'm pretty busy today, but I'll try as soon as i have some time. Do you want complete log, or just the log of one device ? This is very verbose.

@ultratoto14
Copy link
Collaborator

ultratoto14 commented Nov 19, 2020

@postlund
Log only for that device, tell me if you need the full log.
Steps:

  • 13:56:00 Physical switch off
  • 13:56:24 HA status switch to unavailable
  • 13:57:00 Physical switch on
  • 13:57:13 HA status switch to on
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:56:24 ERROR (MainThread) [custom_components.localtuya.pytuya] [684...908] Heartbeat failed (), disconnecting
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Stopped heartbeat loop
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Closing connection
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Connection lost: None
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Closing connection
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Disconnected: None
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Connecting to 192.168.15.163
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Waiting 0 seconds before connecting
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Connecting to 192.168.15.163
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Started heartbeat loop
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Retrieving initial state
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command status (device type: type_0a)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{"gwId":"68426301c44f33cdb908","devId":"68426301c44f33cdb908"}'
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number 1
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x15\xa3\x18\xfd\x03I\x97\xfd\nZ|\xffk\xb0)mx\xaf5\x18\x85y\x16$,\x04}\xfc\xc7\x91;^\'3\xbf54AI\xa7\xffK\xc2\xd9\x0c\t\xc3}\xd9\'\xf0J`\x0e\xf8\xd9E\xdf\xac\xeb\xe9\xf1\x01\xb3\xfe\xc0m\xd7H\xab\xf6o\xc5\xae\xdc` \x1a\xe0\x92\x08=\x03\x11\xe7\x94\xa8\x8e[O\x19\x9a\x9a\x1aI\xb4\x946\xd7x\xf8U\x9dm\x1d\xf8\xcb"=vG\xb2\x18\xddOd\xd7e#[\xebsP\x97\xb3\xcb9l\xeb\xcb\x13v/\xd8\x1cU4\xf4A\x98~\xd4\x93r\x1a\x96g]\xb0.\xac\xed\x7f\xe2-I\xf4\xc5\x9b\x89\xa2\x99_\x81\xee\xb1\xa5\xe6\x8e\x12,i\x03\x98?k\x03\x9a\xf4\\\xc2\xa9;\xbe\\[\x1e\xf0S\x84\x8c\xaf\x08(!acl"\x12\xb6\\\xe6\xedE\xe4\xb9\xf9\x00\xd6/\xa2\xd1\x15\x07\x99\xfe8c\x9fs\xad\x81P2\xff$\x85\xc0\xc0\xbc\xe7>\x1d\x13\x8f\xb1\x81\xe1e\x1f\xbc\x91\xe8M\x9eX\xbe!\x0f\xee\xe4t\x1b\xf11\xb9\xd9\x87p\xfc\xc1\x92\xbe\xe9\xbf@\x19\x08\'\x8e\xedXY*\xed7\x8f\x1c\xfe\xbf2\xe8V\xf8my#', crc=287463418)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching sequence number 1
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {"devId":"68426301c44f33cdb908","dps":{"1":true,"2":"white","3":255,"4":145,"5":"ff00000168ffff","6":"bd76000168ffff","7":"ffff500100ff00","8":"ffff8003ff000000ff000000ff000000000000000000","9":"ffff5001ff0000","10":"ffff0505ff000000ff00ffff00ff00ff0000ff000000","101":true}}
2020-11-19 13:57:33 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)

@SmartM-ui
Copy link

SmartM-ui commented Nov 19, 2020

I will try to fix the error soon. You will get instant state changes once it works, but when there's an exception something isn't working so we can't make any assumptions yet.

@postlund
Hello my hero,
i did some tests and the switch from
UNAVAILABLE to ON takes 5 to 10 seconds,
while switching from
ON to UNAVAILABLE takes 12 to 18 seconds! Great

I congratulate you and I am really satisfied with your quick intervention!

LOG from UNAVAILABLE to ON:

2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Started heartbeat loop
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command heartbeat (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number -100
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command status (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"gwId":"654...f9d","devId":"654...f9d"}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Got heartbeat response
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {}
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x93\xb8Z\xef\xbb\xdf\xd3\x86\x84g\xb9\x7fp\xcdO\x9bn\xcf\xe8\x8e\x08\x08\x11\xb8\x11\xa1T\x8c\x10v\xd4\xc5\x82w\x86i2\x92\xa4\x16i\x8b\xa5l\xf2\xb0\x93\x94\x91(\x1fVV_\xe2;\xdb\x90\xd6\xe1M\xa1\x14\x94\xfe\x87\xfc\xc0\x04\xafR\xcb\xfa\xd3\xc9\x97\x12(\xc1\x866\x8b=\xd13\xa1\n\x87\x1d\x0b\xa9o\xef\x87:\x99l\xd4\xa2\xf1\x91\xc4\xc27\xa5\x17\x80\x11\xf5/@Qlx\x0f<\xbb\xb5aL\xd1G\x8bw\xf6\xa6\x93<\xf3\xe6\xe9\xcc{Nc\xd0\x86)yM\x9d<P\xda\xb2x=\xebO\xcePS9\xd4\xc9I\x83_]{', crc=3408650248)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {"devId":"654...f9d","dps":{"20":true,"21":"white","22":507,"23":532,"24":"011d011e01fb","25":"020e0d0000e80383000003e803e8","26":0}}

LOG from ON to UNAVAILABLE

2020-11-20 00:34:28 ERROR (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Heartbeat failed (), disconnecting
Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/__init__.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/__init__.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Stopped heartbeat loop
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Connection lost: None
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
` ``

**Log details (ERROR)**

Logger: custom_components.localtuya.pytuya
Source: custom_components/localtuya/pytuya/init.py:239
Integration: LocalTuya integration (documentation, issues)
First occurred: 00:34:28 (1 occurrences)
Last logged: 00:34:28
[654...f9d] Heartbeat failed (), disconnecting

Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/init.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/init.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/init.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/init.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

@postlund
Copy link
Collaborator Author

@postlund
Log only for that device, tell me if you need the full log.
Steps:

  • 13:56:00 Physical switch off
  • 13:56:24 HA status switch to unavailable
  • 13:57:00 Physical switch on
  • 13:57:13 HA status switch to on
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:55:39 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:55:59 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:56:19 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:56:24 ERROR (MainThread) [custom_components.localtuya.pytuya] [684...908] Heartbeat failed (), disconnecting
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Stopped heartbeat loop
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Closing connection
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Connection lost: None
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Closing connection
2020-11-19 13:56:24 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Disconnected: None
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Connecting to 192.168.15.163
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Waiting 0 seconds before connecting
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Connecting to 192.168.15.163
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Started heartbeat loop
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{}'
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number -100
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.common] [684...908] Retrieving initial state
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command status (device type: type_0a)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Send payload: b'{"gwId":"68426301c44f33cdb908","devId":"68426301c44f33cdb908"}'
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Waiting for sequence number 1
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Got heartbeat response
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {}
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x15\xa3\x18\xfd\x03I\x97\xfd\nZ|\xffk\xb0)mx\xaf5\x18\x85y\x16$,\x04}\xfc\xc7\x91;^\'3\xbf54AI\xa7\xffK\xc2\xd9\x0c\t\xc3}\xd9\'\xf0J`\x0e\xf8\xd9E\xdf\xac\xeb\xe9\xf1\x01\xb3\xfe\xc0m\xd7H\xab\xf6o\xc5\xae\xdc` \x1a\xe0\x92\x08=\x03\x11\xe7\x94\xa8\x8e[O\x19\x9a\x9a\x1aI\xb4\x946\xd7x\xf8U\x9dm\x1d\xf8\xcb"=vG\xb2\x18\xddOd\xd7e#[\xebsP\x97\xb3\xcb9l\xeb\xcb\x13v/\xd8\x1cU4\xf4A\x98~\xd4\x93r\x1a\x96g]\xb0.\xac\xed\x7f\xe2-I\xf4\xc5\x9b\x89\xa2\x99_\x81\xee\xb1\xa5\xe6\x8e\x12,i\x03\x98?k\x03\x9a\xf4\\\xc2\xa9;\xbe\\[\x1e\xf0S\x84\x8c\xaf\x08(!acl"\x12\xb6\\\xe6\xedE\xe4\xb9\xf9\x00\xd6/\xa2\xd1\x15\x07\x99\xfe8c\x9fs\xad\x81P2\xff$\x85\xc0\xc0\xbc\xe7>\x1d\x13\x8f\xb1\x81\xe1e\x1f\xbc\x91\xe8M\x9eX\xbe!\x0f\xee\xe4t\x1b\xf11\xb9\xd9\x87p\xfc\xc1\x92\xbe\xe9\xbf@\x19\x08\'\x8e\xedXY*\xed7\x8f\x1c\xfe\xbf2\xe8V\xf8my#', crc=287463418)
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Dispatching sequence number 1
2020-11-19 13:57:13 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Decrypted payload: {"devId":"68426301c44f33cdb908","dps":{"1":true,"2":"white","3":255,"4":145,"5":"ff00000168ffff","6":"bd76000168ffff","7":"ffff500100ff00","8":"ffff8003ff000000ff000000ff000000000000000000","9":"ffff5001ff0000","10":"ffff0505ff000000ff00ffff00ff00ff0000ff000000","101":true}}
2020-11-19 13:57:33 DEBUG (MainThread) [custom_components.localtuya.pytuya] [684...908] Sending command heartbeat (device type: type_0a)

Can't see any problems here, did it work?

@postlund
Copy link
Collaborator Author

I will try to fix the error soon. You will get instant state changes once it works, but when there's an exception something isn't working so we can't make any assumptions yet.

@postlund
Hello my hero,
i did some tests and the switch from
UNAVAILABLE to ON takes 5 to 10 seconds,
while switching from
ON to UNAVAILABLE takes 12 to 18 seconds! Great

I congratulate you and I am really satisfied with your quick intervention!

LOG from UNAVAILABLE to ON:

2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Started heartbeat loop
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command heartbeat (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number -100
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command status (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"gwId":"654...f9d","devId":"654...f9d"}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Got heartbeat response
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {}
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x93\xb8Z\xef\xbb\xdf\xd3\x86\x84g\xb9\x7fp\xcdO\x9bn\xcf\xe8\x8e\x08\x08\x11\xb8\x11\xa1T\x8c\x10v\xd4\xc5\x82w\x86i2\x92\xa4\x16i\x8b\xa5l\xf2\xb0\x93\x94\x91(\x1fVV_\xe2;\xdb\x90\xd6\xe1M\xa1\x14\x94\xfe\x87\xfc\xc0\x04\xafR\xcb\xfa\xd3\xc9\x97\x12(\xc1\x866\x8b=\xd13\xa1\n\x87\x1d\x0b\xa9o\xef\x87:\x99l\xd4\xa2\xf1\x91\xc4\xc27\xa5\x17\x80\x11\xf5/@Qlx\x0f<\xbb\xb5aL\xd1G\x8bw\xf6\xa6\x93<\xf3\xe6\xe9\xcc{Nc\xd0\x86)yM\x9d<P\xda\xb2x=\xebO\xcePS9\xd4\xc9I\x83_]{', crc=3408650248)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {"devId":"654...f9d","dps":{"20":true,"21":"white","22":507,"23":532,"24":"011d011e01fb","25":"020e0d0000e80383000003e803e8","26":0}}

LOG from ON to UNAVAILABLE

2020-11-20 00:34:28 ERROR (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Heartbeat failed (), disconnecting
Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/__init__.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/__init__.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Stopped heartbeat loop
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Connection lost: None
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
` ``

**Log details (ERROR)**

Logger: custom_components.localtuya.pytuya
Source: custom_components/localtuya/pytuya/init.py:239
Integration: LocalTuya integration (documentation, issues)
First occurred: 00:34:28 (1 occurrences)
Last logged: 00:34:28
[654...f9d] Heartbeat failed (), disconnecting

Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/init.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/init.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/init.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/init.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Sounds great then! Heartbeats are sent sent every 20s (to verify if connection is still alive) with a timeout of 5s. So it should take roughly at most 25s to detect if connection was lost. But generally faster. Great that it works 👍 Maybe we can merge this then.

@ultratoto14
Copy link
Collaborator

Hi @postlund, to go further with this post
I provide a full log
home-assistant.log.zip

Context:
HA just started

Passive Devices:

  • [548...46f] Already on at start
  • [548...51f] Already on at start
  • [684...908] Already on at start
  • [bf7...aiu] Switched physically on at 08:15:16
  • [bfb...yqm] Switched physically on at 08:15:16
  • [bf6...fzl] Switched physically on at 08:15:16
  • [bfa...r76] Switched physically on at 08:15:16

For the already on devices, i get two Already connecting to ... messages
For the ones I switched physically on after some time, I've got the Already connecting to ... message every 5 seconds

Tell me if you need more data.

P.S. I was hitting an issue before but was not able to find a way to ensure i can reproduce it. It's like there are two HA connections to the same device. I know when it happens because in that situation each time I change color or brightness of some of my devices, they are flickering. Will open an issue if i can reproduce it. I just mention it as it may be related to the devices that are physically off some times.

@SmartM-ui
Copy link

I will try to fix the error soon. You will get instant state changes once it works, but when there's an exception something isn't working so we can't make any assumptions yet.

@postlund
Hello my hero,
i did some tests and the switch from
UNAVAILABLE to ON takes 5 to 10 seconds,
while switching from
ON to UNAVAILABLE takes 12 to 18 seconds! Great
I congratulate you and I am really satisfied with your quick intervention!
LOG from UNAVAILABLE to ON:

2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Started heartbeat loop
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command heartbeat (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number -100
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Sending command status (device type: type_0a)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Send payload: b'{"gwId":"654...f9d","devId":"654...f9d"}'
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Waiting for sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Got heartbeat response
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {}
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching message TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b'\x93\xb8Z\xef\xbb\xdf\xd3\x86\x84g\xb9\x7fp\xcdO\x9bn\xcf\xe8\x8e\x08\x08\x11\xb8\x11\xa1T\x8c\x10v\xd4\xc5\x82w\x86i2\x92\xa4\x16i\x8b\xa5l\xf2\xb0\x93\x94\x91(\x1fVV_\xe2;\xdb\x90\xd6\xe1M\xa1\x14\x94\xfe\x87\xfc\xc0\x04\xafR\xcb\xfa\xd3\xc9\x97\x12(\xc1\x866\x8b=\xd13\xa1\n\x87\x1d\x0b\xa9o\xef\x87:\x99l\xd4\xa2\xf1\x91\xc4\xc27\xa5\x17\x80\x11\xf5/@Qlx\x0f<\xbb\xb5aL\xd1G\x8bw\xf6\xa6\x93<\xf3\xe6\xe9\xcc{Nc\xd0\x86)yM\x9d<P\xda\xb2x=\xebO\xcePS9\xd4\xc9I\x83_]{', crc=3408650248)
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Dispatching sequence number 1
2020-11-20 00:31:22 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Decrypted payload: {"devId":"654...f9d","dps":{"20":true,"21":"white","22":507,"23":532,"24":"011d011e01fb","25":"020e0d0000e80383000003e803e8","26":0}}

LOG from ON to UNAVAILABLE

2020-11-20 00:34:28 ERROR (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Heartbeat failed (), disconnecting
Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/__init__.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/__init__.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/__init__.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Stopped heartbeat loop
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Connection lost: None
2020-11-20 00:34:28 DEBUG (MainThread) [custom_components.localtuya.pytuya] [654...f9d] Closing connection
` ``

**Log details (ERROR)**

Logger: custom_components.localtuya.pytuya
Source: custom_components/localtuya/pytuya/init.py:239
Integration: LocalTuya integration (documentation, issues)
First occurred: 00:34:28 (1 occurrences)
Last logged: 00:34:28
[654...f9d] Heartbeat failed (), disconnecting
Traceback (most recent call last):
File "/config/custom_components/localtuya/pytuya/init.py", line 379, in heartbeat_loop
await self.heartbeat()
File "/config/custom_components/localtuya/pytuya/init.py", line 468, in heartbeat
return await self.exchange(HEARTBEAT)
File "/config/custom_components/localtuya/pytuya/init.py", line 440, in exchange
msg = await self.dispatcher.wait_for(seqno)
File "/config/custom_components/localtuya/pytuya/init.py", line 239, in wait_for
await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Sounds great then! Heartbeats are sent sent every 20s (to verify if connection is still alive) with a timeout of 5s. So it should take roughly at most 25s to detect if connection was lost. But generally faster. Great that it works 👍 Maybe we can merge this then.

It works well for me!
To avoid the generation of errors in the logs, of the bulbs that I turn off through the switch, I have entered in the configuration.yaml:
logs:
custom_components.localtuya: fatal

@postlund In your opinion, do I leave passive recognition only for the bulbs that I turn off through the wall switch or is it preferable to provide it for all the bulbs?

@postlund
Copy link
Collaborator Author

It works well for me!
To avoid the generation of errors in the logs, of the bulbs that I turn off through the switch, I have entered in the configuration.yaml:
logs:
custom_components.localtuya: fatal

This part is a bit tricky to deal with as we still want to log when it happens, but it might not always be a "big deal" to scream loud about it. I gladly take input for improvements.

@postlund In your opinion, do I leave passive recognition only for the bulbs that I turn off through the wall switch or is it preferable to provide it for all the bulbs?

In theory, this could be default mode and to some extent I would prefer to make it so. But it will only work as long as discovery works, which might not always be the case for some people. So I'm not sure yet. But the answer is that you can use this as default for all your devices, it's better.

@postlund
Copy link
Collaborator Author

Hi @postlund, to go further with this post
I provide a full log
home-assistant.log.zip

Context:
HA just started

Passive Devices:

  • [548...46f] Already on at start
  • [548...51f] Already on at start
  • [684...908] Already on at start
  • [bf7...aiu] Switched physically on at 08:15:16
  • [bfb...yqm] Switched physically on at 08:15:16
  • [bf6...fzl] Switched physically on at 08:15:16
  • [bfa...r76] Switched physically on at 08:15:16

For the already on devices, i get two Already connecting to ... messages
For the ones I switched physically on after some time, I've got the Already connecting to ... message every 5 seconds

Tell me if you need more data.

P.S. I was hitting an issue before but was not able to find a way to ensure i can reproduce it. It's like there are two HA connections to the same device. I know when it happens because in that situation each time I change color or brightness of some of my devices, they are flickering. Will open an issue if i can reproduce it. I just mention it as it may be related to the devices that are physically off some times.

Thanks for the log, I will have a log after lunch and see what I can find.

@SmartM-ui
Copy link

Just for information, I report that when you start Home Assistant the following errors are reported in the log:

Logger: homeassistant
Source: custom_components/localtuya/init.py:161
First occurred: 00:23:13 (4 occurrences)
Last logged: 00:23:14
Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()

Traceback (most recent call last):
File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 1021, in _read_ready
self._protocol.datagram_received(data, addr)
File "/config/custom_components/localtuya/discovery.py", line 70, in datagram_received
self.device_found(decoded)
File "/config/custom_components/localtuya/discovery.py", line 79, in device_found
self._callback(device)
File "/config/custom_components/localtuya/init.py", line 161, in _device_discovered
device = hass.data[DOMAIN][entry.entry_id][TUYA_DEVICE]
KeyError: 'af6...7e9'

2020-11-22 00:23:13 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 1021, in _read_ready
self._protocol.datagram_received(data, addr)
File "/config/custom_components/localtuya/discovery.py", line 70, in datagram_received
self.device_found(decoded)
File "/config/custom_components/localtuya/discovery.py", line 79, in device_found
self._callback(device)
File "/config/custom_components/localtuya/init.py", line 161, in _device_discovered
device = hass.data[DOMAIN][entry.entry_id][TUYA_DEVICE]
KeyError: 'af6...7e9'
2020-11-22 00:23:13 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 1021, in _read_ready
self._protocol.datagram_received(data, addr)
File "/config/custom_components/localtuya/discovery.py", line 70, in datagram_received
self.device_found(decoded)
File "/config/custom_components/localtuya/discovery.py", line 79, in device_found
self._callback(device)
File "/config/custom_components/localtuya/init.py", line 161, in _device_discovered
device = hass.data[DOMAIN][entry.entry_id][TUYA_DEVICE]
KeyError: '597...dc7'
2020-11-22 00:23:14 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 1021, in _read_ready
self._protocol.datagram_received(data, addr)
File "/config/custom_components/localtuya/discovery.py", line 70, in datagram_received
self.device_found(decoded)
File "/config/custom_components/localtuya/discovery.py", line 79, in device_found
self._callback(device)
File "/config/custom_components/localtuya/init.py", line 161, in _device_discovered
device = hass.data[DOMAIN][entry.entry_id][TUYA_DEVICE]
KeyError: 'a04...a64'
2020-11-22 00:23:14 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 1021, in _read_ready
self._protocol.datagram_received(data, addr)
File "/config/custom_components/localtuya/discovery.py", line 70, in datagram_received
self.device_found(decoded)
File "/config/custom_components/localtuya/discovery.py", line 79, in device_found
self._callback(device)
File "/config/custom_components/localtuya/init.py", line 161, in _device_discovered
device = hass.data[DOMAIN][entry.entry_id][TUYA_DEVICE]
KeyError: 'af6...659'

Thanks

@ultratoto14
Copy link
Collaborator

@postlund checking my log, I encountered the same exception on a one device sometimes, the id is in core registry, do not know why this error occurs.

@sqazi95
Copy link

sqazi95 commented Nov 30, 2020

Hi @postlund,

I just installed the latest release and tried to use the passive_device feature but I keep getting this error.

`Logger: homeassistant.components.hassio

Source: components/hassio/init.py:407

Integration: Hass.io (documentation, issues)

First occurred: 5:43:40 PM (2 occurrences)

Last logged: 5:43:50 PM

Invalid config for [localtuya]: [passive_device] is an invalid option for [localtuya]. Check: localtuya->localtuya->0->passive_device. (See /config/configuration.yaml, line 17).`

This is my configuration.yaml

`localtuya:

  • host: 192.168.100.199
    device_id: xxxx
    local_key: xxxx
    friendly_name: Room Lights
    protocol_version: "3.3"
    passive_device: True
    entities:
    • platform: switch
      friendly_name: C Light
      id: 1
    • platform: switch
      friendly_name: B Light
      id: 2`

Is there something wrong with my configuration?

@ultratoto14
Copy link
Collaborator

@sqazi95 this PR is not yet merged, you need to get the passive branch of this repository.

@sqazi95
Copy link

sqazi95 commented Nov 30, 2020

@sqazi95 this PR is not yet merged, you need to get the passive branch of this repository.

Okay thanks.

@postlund
Copy link
Collaborator Author

postlund commented Dec 7, 2020

Ok, so I pushed some changes. The "passive device" option has been removed and is now default: all connection attempts are initiated when discovery broadcasts are received. Should work fine. When doing this I reverted back to version 1 of the config entry (since it does not have to change anymore), so that means you have to remove and re-create devices if you tried the PR prior to that. You can also change the version manually for each config entry to 1 in core.config_entries and remove the passive_device row. But you do that at your own risk!

@postlund
Copy link
Collaborator Author

@ultratoto14 I can revert the seqno change, no problem. Do you see any other problems, e.g. error messages that could be used to debug? Seems strange to me that the mentioned situation could happen. The implementation is a bit jiffy right now. I map the sequence number to a semaphore used to wait for the message. When the message has been received, the semaphore is replaced with the message before releasing it.

After I revert the seqno change we should be able to merge, no?

@postlund
Copy link
Collaborator Author

Removed seqno reset in latest commit.

@ultratoto14
Copy link
Collaborator

ultratoto14 commented Dec 15, 2020

@postlund, i let it run all the night, the reconnect is now ok, but without the closer heartbeats, some devices switch to available/unavailable every now and then
image

I think we can merge that as it will help a lot of users but I will keep my closer heartbeats locally as my connections was rock stable with them.

edit:
In the close method in common.py

        if self._connect_task:
            self._connect_task.cancel()
            await self._connect_task
        if self._interface:
            await self._interface.close()

should be

        if self._connect_task is not None:
            self._connect_task.cancel()
            await self._connect_task
        if self._interface is not None:
            await self._interface.close()

It's not linked to that PR but it's involved.

@postlund
Copy link
Collaborator Author

@ultratoto14 I'm not sure I follow, what do you mean by "without closer heartbeats? You mean the tighter interval? I guess we can decrease that as well, but it would be great if we could try decreasing in steps to find a better threshold. Can you try 15s for instance? Is the heartbeat retry counter ever triggered and actually work? I mean, have you seen actual proof that the second heartbeat actually receives a response? I suggest that you add a log point when a heartbeat succeeds and `count

0` to verify.

@ultratoto14
Copy link
Collaborator

@postlund Yep i mean the tighter interval, i'll check and report, i think that it's already so much better that what we had, it can be merged, i'll check during the next days and open a PR if it's more conclusive, what do you think ?

@postlund
Copy link
Collaborator Author

@ultratoto14 That sounds very good 👍

@postlund postlund merged commit 10e55e6 into master Dec 15, 2020
@postlund postlund deleted the passive branch December 15, 2020 08:08
@postlund
Copy link
Collaborator Author

We need to make a clarification that discovery broadcasts are needed now, I'll see what I can come up with.

@postlund
Copy link
Collaborator Author

I added something about the service here. We should probably rename the page to something like "working with datapoints", just to avoid having a billion pages with a sentence or two on.

@ultratoto14
Copy link
Collaborator

@postlund you were right, I reduced to 10 seconds and added a log in case, second heartbeat succeeds but it never occurred in the last 4 hours. With 10 seconds interval, the devices are rock stable.

I found another crazy thing. The device i debug with that seemed to not support two connections at a time is now able to have Home Assistant and Tuya App at the same time, changing the light functions in the tuya app almost immediately replicated in HA 👍,

@DavidFFerreira
Copy link

@ultratoto14 I still have problemes with my wifi bulbs. It goes unavaliable, after a few minutes or hours turn on
image
image
image

@DavidFFerreira
Copy link

PS .. I have the last "master" branch

@postlund
Copy link
Collaborator Author

Seems to be a failure from my pylint fixes. I will try to fix that.

@DavidFFerreira
Copy link

@postlund if you want a beta tester, i'm avaliable lol

@postlund
Copy link
Collaborator Author

@DavidFFerreira Then I have an assignment for you: #252

@Matssa56
Copy link

Matssa56 commented Jan 2, 2021

Hey guys, just a question. I see we need to foward port 6666 and 6667 from the devices to the HA instance (on my side it's from my covers to my RPI4). Is this really necessary when they are on the same network? If my understanding is correct, this needs to be done directly on the router right?
Thanks a bunch!

@jfparis
Copy link

jfparis commented Jan 2, 2021 via email

@postlund
Copy link
Collaborator Author

postlund commented Jan 2, 2021

I'm also working on a similar re-connect loop as before since this backfired more than I thought, see #288.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

9 participants