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.

Sign up for GitHub

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

Jump to bottom

Some of my localtuya devices periodically become unavailable #1259

Open
JampireX opened this issue Jan 23, 2023 · 4 comments
Open

Some of my localtuya devices periodically become unavailable #1259

JampireX opened this issue Jan 23, 2023 · 4 comments
Labels
bug Something isn't working

Comments

@JampireX
Copy link

JampireX commented Jan 23, 2023 •
edited
Loading

I have 15 localtuya devices connected. It's powered, connected to wifi, internet connection and dns requests blocked but sometimes they become unavailable. Sometimes they become available again after few hours, sometimes only after HA restart - I don't see any pattern.

I have enabled debugging for one of this device and got the init log. I see some exception here

2023-01-23 11:12:25.340 DEBUG (MainThread) [custom_components.localtuya] Updating keys for device bf97fb99ebbedb46d3qhkm: 192.168.2.31 XXXXXXXXXXX 
2023-01-23 11:12:25.341 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.10/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.10/asyncio/selector_events.py", line 1027, 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 142, in _device_discovered
device = hass.data[DOMAIN][TUYA_DEVICES][device_id]
KeyError: 'bf97fb99ebbedb46d3qhkm'
2023-01-23 11:12:25.899 INFO (MainThread) [homeassistant.components.light] Setting up light.localtuya
2023-01-23 11:12:25.929 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new light.localtuya entity: light.bf97fb99ebbedb46d3qhkm
2023-01-23 11:12:26.368 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending command 10 (device type: type_0a)
2023-01-23 11:12:26.368 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending payload: b'{"gwId":"bf97fb99ebbedb46d3qhkm","devId":"bf97fb99ebbedb46d3qhkm","uid":"bf97fb99ebbedb46d3qhkm","t":"1674461546"}'
2023-01-23 11:12:26.371 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Command 10 waiting for sequence number 1
2023-01-23 11:12:26.397 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 10 TuyaMessage(seqno=1, cmd=10, retcode=1, payload=b'r\xbe\xe9\x1e"Nl\xfb\x81\xdc\x9d;\n\xf9\xa6Cl?WU\xbf4f\xd1\x0c\x9b4]\xe6\xc0&\x8e', crc=3883590208, crc_good=True)
2023-01-23 11:12:26.399 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] 'data unvalid' error detected: switching to dev_type 'type_0d'
2023-01-23 11:12:26.399 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Re-send 10 due to device type change (type_0a -> type_0d)
2023-01-23 11:12:26.400 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending command 10 (device type: type_0d)
2023-01-23 11:12:26.400 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending payload: b'{"devId":"bf97fb99ebbedb46d3qhkm","uid":"bf97fb99ebbedb46d3qhkm","t":"1674461546","dps":{"20":null,"22":null,"23":null,"21":null,"24":null,"25":null}}'
2023-01-23 11:12:26.405 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Command 13 waiting for sequence number 2
2023-01-23 11:12:26.469 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 8 TuyaMessage(seqno=0, cmd=8, retcode=0, payload=b'3.3\x00\x00\x00\x00\x00\x00\xf9\xfd\x00\x00\x00\x01\xaczXl\xd46\x1c\xd0)I9\xe0\xee\xb1!\x89\xb6\xd8\xa2\xd9Q\xd3N\xe2\xfa\xb0$\x1e\xfa\x8fc#', crc=612605166, crc_good=True)
2023-01-23 11:12:26.469 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Got status update
2023-01-23 11:12:26.473 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Deciphered data = '{"dps":{},"t":577}'
2023-01-23 11:12:26.536 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 13 TuyaMessage(seqno=2, cmd=13, retcode=0, payload=b'', crc=2380353348, crc_good=True)
2023-01-23 11:12:26.539 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] ACK received for command 13: ignoring it
2023-01-23 11:12:26.539 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Started heartbeat loop
2023-01-23 11:12:26.539 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending command 9 (device type: type_0d)
2023-01-23 11:12:26.540 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending payload: b'{"gwId":"bf97fb99ebbedb46d3qhkm","devId":"bf97fb99ebbedb46d3qhkm"}'
2023-01-23 11:12:26.541 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Command 9 waiting for sequence number -100
2023-01-23 11:12:26.556 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 9 TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211, crc_good=True)
2023-01-23 11:12:26.556 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Got heartbeat response
2023-01-23 11:12:26.557 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] ACK received for command 9: ignoring it

Another settings save for this device:

2023-01-23 11:27:15.467 DEBUG (MainThread) [custom_components.localtuya] Updating keys for device bf97fb99ebbedb46d3qhkm: 192.168.2.31 XXXXXXXXXXX 
2023-01-23 11:27:15.468 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.10/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.10/asyncio/selector_events.py", line 1027, 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 142, in _device_discovered
device = hass.data[DOMAIN][TUYA_DEVICES][device_id]
KeyError: 'bf97fb99ebbedb46d3qhkm'
2023-01-23 11:27:16.342 INFO (MainThread) [homeassistant.components.light] Setting up light.localtuya
2023-01-23 11:27:16.359 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new light.localtuya entity: light.bf97fb99ebbedb46d3qhkm
2023-01-23 11:27:17.577 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending command 10 (device type: type_0a)
2023-01-23 11:27:17.578 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending payload: b'{"gwId":"bf97fb99ebbedb46d3qhkm","devId":"bf97fb99ebbedb46d3qhkm","uid":"bf97fb99ebbedb46d3qhkm","t":"1674462437"}'
2023-01-23 11:27:17.579 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Command 10 waiting for sequence number 1
2023-01-23 11:27:17.783 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 10 TuyaMessage(seqno=1, cmd=10, retcode=0, payload=b"X\x1a(P\xfc\x85s\xd2\xed\x02\x18_*\x98\xa1\xd7\x89\x01\x11\xd4\x10\x8a\xbb3j\xc9\xe6\x988\xdf'\x88\xf7;\xf7\x8a\x85d\xd8LC\\EQ\xf8\xe1\xce\xe8\xac\x0c\x0bJYK]\x87y\x88j\xa6ZUS\xa2\xbf2E\xb5o\x18\xcc\xe0%\xd9{\x94\x1b\xec\x17\x1bW\\\xaa\x00\xb8\xd3D4:w\xda\xd4\xaa\xf4\x87\xc5Q\x04\x0b4\xdb\xef+\xaf\xe6S\xd2\x94U\x8c\xb5 c.\x95\xd2\xbd\xe9\nI\x8f$\xacs\x08\xc2\x06\xfb\x89\x8f\x99&(=r\x86\xafZa\xf8\x0f\x14\xff\x82}x\xa3\x84\x1e \xce\x12\xd7O\x96\xd1\xc3\x93\xdf4\xfe}6\x89,C\x0fz\x95.\xc0\xd9 W\x06a", crc=303129845, crc_good=True)
2023-01-23 11:27:17.786 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Deciphered data = '{"dps":{"20":true,"21":"white","22":1000,"23":170,"24":"00f003e803e8","25":"05464601000003e803e800000000464601007803e803e80000000046460100f003e803e800000000","26":0}}'
2023-01-23 11:27:17.790 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Started heartbeat loop
2023-01-23 11:27:17.790 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending command 9 (device type: type_0a)
2023-01-23 11:27:17.791 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Sending payload: b'{"gwId":"bf97fb99ebbedb46d3qhkm","devId":"bf97fb99ebbedb46d3qhkm"}'
2023-01-23 11:27:17.796 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Command 9 waiting for sequence number -100
2023-01-23 11:27:17.803 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Dispatching message CMD 9 TuyaMessage(seqno=0, cmd=9, retcode=0, payload=b'', crc=2958142211, crc_good=True)
2023-01-23 11:27:17.803 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Got heartbeat response
2023-01-23 11:27:17.804 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] ACK received for command 9: ignoring it

Looks like after second save device become available. I see the difference in Deciphered data line. In first case it was empty.

And this when device become unavailable

2023-01-23 11:49:07.980 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Heartbeat failed due to timeout, disconnecting
2023-01-23 11:49:07.982 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Connection lost: None

2023-01-23 13:21:08.922 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Connection lost: [Errno 104] Connection reset by peer
2023-01-23 13:21:09.329 DEBUG (MainThread) [custom_components.localtuya.pytuya] [bf9...hkm] Heartbeat failed due to timeout, disconnecting

After that connection lost localtuya doesn't trying to recover connection as soon as possible.
@JampireX JampireX added the bug Something isn't working label Jan 23, 2023
@rootd
Copy link

rootd commented Jan 28, 2023

This is the exact same behaviour I'm having in issue #1124, also your logs look similar. Are you using a Ledvance bulb by any chance?

@JampireX
Copy link
Author

JampireX commented Jan 28, 2023 •
edited
Loading

This is the exact same behaviour I'm having in issue #1124, also your logs look similar. Are you using a Ledvance bulb by any chance?

Not Ledvance, but another cheap ones. Now waiting for fix #1248. Can't even remove this painful bulb from HASS or edit config for additional testing.

@paulius2k paulius2k mentioned this issue Feb 5, 2023
Closed
1 task
@cataseven
Copy link

Should be top priority

@JampireX
Copy link
Author

Looks more stable after v5.1.0 release. Updated yesterday and haven't had this issue for now.

@paulius2k paulius2k mentioned this issue Jul 28, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@rootd @JampireX @cataseven