Can't command or query HS200 v5 switch #161
Description
No commands or querying work with a new HS200 non-dimmable wall switch.
When I run in debug mode from the latest code on master (as of 5/10/21) the CLI stalls out until I break out of it:
python3 cli.py --debug --plug --host kasa-sw01 off
DEBUG:kasa.smartdevice:Initializing kasa-sw01 of type <class 'kasa.smartplug.SmartPlug'>
DEBUG:kasa.protocol:> (143) {"system": {"get_sysinfo": null}, "emeter": {"get_realtime": null, "get_monthstat": {"year": 2021}, "get_daystat": {"month": 5, "year": 2021}}}
^CTraceback (most recent call last):
File "/Users/brian/FTP/brianthedavis-python-kasa/kasa/cli.py", line 456, in <module>
cli()
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/asyncclick/core.py", line 799, in __call__
return anyio.run(self._main, main, args, kwargs, backend=_anyio_backend)
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/__init__.py", line 72, in run
return asynclib.run(func, *args, **backend_options) # type: ignore
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py", line 112, in run
loop.run_until_complete(task)
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
self.run_forever()
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
self._run_once()
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 1854, in _run_once
event_list = self._selector.select(timeout)
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/selectors.py", line 562, in select
kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending name='asyncclick.core.BaseCommand._main' coro=<run.<locals>.wrapper() running at /Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py:76> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x10c3a5070>()]>>
After digging into the code a bit, I've confirmed that the same workaround for #119 works here: commenting out
python-kasa/kasa/smartdevice.py
Line 303 in 0471e1a
pass).
From what I can tell, the code never enters the has_emeter method at
python-kasa/kasa/smartdevice.py
Line 283 in 0471e1a
self._last_update is still none and so we fire off a request to _create_emeter_request() even though this switch does not have an emeter. It seems like there's a race condition here where the initial request hasn't returned a value yet so we ask for additional info that causes the lock.
If I run without specifying --plug in the command line, the discovery at least returns with the initial device dump information, but it still stalls out:
python3 cli.py --debug --host kasa-sw01 off
No --strip nor --bulb nor --plug given, discovering..
DEBUG:kasa.protocol:> (33) {"system": {"get_sysinfo": null}}
DEBUG:kasa.protocol:< (573) {'system': {'get_sysinfo': {'active_mode': 'none',
'alias': 'House Fan',
'dev_name': 'Smart Wi-Fi Light Switch',
'deviceId': '8006537A25B360E196DFC5B433BBF7E41DFBA004',
'err_code': 0,
'feature': 'TIM',
'hwId': '6F710464613C9F1EA67305BD422BC2D0',
'hw_ver': '5.0',
'icon_hash': '',
'latitude_i': 397310,
'led_off': 0,
'longitude_i': -1049060,
'mac': '90:9A:4A:55:BC:71',
'mic_type': 'IOT.SMARTPLUGSWITCH',
'model': 'HS200(US)',
'next_action': {'type': -1},
'oemId': '8754F01961F1BCDAEC5B68B74FFFA7E0',
'on_time': 0,
'relay_state': 0,
'rssi': -50,
'status': 'new',
'sw_ver': '1.0.2 Build 200819 Rel.105309',
'updating': 0}}}
DEBUG:kasa.smartdevice:Initializing kasa-sw01 of type <class 'kasa.smartplug.SmartPlug'>
DEBUG:kasa.protocol:> (143) {"system": {"get_sysinfo": null}, "emeter": {"get_realtime": null, "get_monthstat": {"year": 2021}, "get_daystat": {"month": 5, "year": 2021}}}
^CTraceback (most recent call last):
File "/Users/brian/FTP/brianthedavis-python-kasa/kasa/cli.py", line 456, in <module>
cli()
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/asyncclick/core.py", line 799, in __call__
return anyio.run(self._main, main, args, kwargs, backend=_anyio_backend)
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/__init__.py", line 72, in run
return asynclib.run(func, *args, **backend_options) # type: ignore
File "/Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py", line 112, in run
loop.run_until_complete(task)
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
self.run_forever()
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
self._run_once()
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 1854, in _run_once
event_list = self._selector.select(timeout)
File "/usr/local/Cellar/python@3.9/3.9.1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/selectors.py", line 562, in select
kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending name='asyncclick.core.BaseCommand._main' coro=<run.<locals>.wrapper() running at /Users/brian/Library/Caches/pypoetry/virtualenvs/python-kasa-Q4pCC_uy-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py:76> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x107c120a0>()]>>
and once again, the additional logging output I added to def has_emeter never gets output (so we are likely hitting the self._last_update is None in the if statement and proceeding into the emeter request.
I tried to figure out a way to ensure that we had the sys_info populated before hitting that line in code but my asynchronous python skills are non-existent and I couldn't figure out what change would be required (I tried swapping the order of the if statement, but the .has_emeter method requires the update to finish first which presented a chicken and an egg problem that I couldn't figure out)
The new HS200 fixture file can be found in PR #160 if it helps.
I'm happy to help debug/test anything...I just couldn't figure out what the next steps on this might be.