TP Link Bulb - returning error but still working: Failed to call service light/turn_on

cohenavi commented 8 months ago

The problem

When I turn my TP-Link bulb on/off through home assistant, it works but I receive an error message. This resolves after reloading the integration or restarting power to the bulb.

Failed to call service light/turn_off. No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}

This only occurs with one bulb type, the rest of my bulbs and switches work flawlessly: KL 125 Hardware Version 3.0 Firmware Version 1.0.13

What version of Home Assistant Core has the issue?

core-2024.1.0

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

TP-Link Kasa Smart

Link to integration documentation on our website

https://www.home-assistant.io/integrations/tplink

Diagnostics information

config_entry-tplink-63ebb12c9539f3d5a87a6af29a860c40.json (1).txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:238
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: January 3, 2024 at 9:16:37 PM (26 occurrences)
Last logged: 7:27:52 PM

[546882695616] No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
[546884948032] No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
[546884948032] No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 900, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
[546742296000] No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
[546742654656] No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 42, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}, {'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 24}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 237}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 238, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2173, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2210, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 882, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 624, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/group/light.py", line 174, in async_turn_on
    await self.hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2173, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2210, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 907, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1493, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 624, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/tplink/entity.py", line 26, in _async_wrap
    await func(self, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/tplink/light.py", line 245, in async_turn_on
    await self._async_turn_on_with_brightness(brightness, transition)
  File "/usr/src/homeassistant/homeassistant/components/tplink/light.py", line 230, in _async_turn_on_with_brightness
    await self.device.turn_on(transition=transition)
  File "/usr/local/lib/python3.11/site-packages/kasa/smartbulb.py", line 518, in turn_on
    return await self.set_light_state({"on_off": 1}, transition=transition)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/kasa/smartbulb.py", line 353, in set_light_state
    light_state = await self._query_helper(
                  ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdevice.py", line 275, in _query_helper
    raise SmartDeviceException(f"No required {target} in response: {response}")
kasa.exceptions.SmartDeviceException: No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 18, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 19}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 113}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 213}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': 'REDACTED@gmail.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}

Additional information

No response

home-assistant[bot] commented 8 months ago

Hey there @rytilahti, @thegardenmonkey, @bdraco, mind taking a look at this issue as it has been labeled with an integration (tplink) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `tplink` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign tplink` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

tplink documentation tplink source _{^{(message by IssueLinks)}}

bdraco commented 8 months ago

We will need the logs of the communication with the bulb a few minutes before the problem happens to get a better idea about what is happening.

Please make sure there are no other tplink devices in the log (you may need to disable the config entries in the UI before doing the test)

cohenavi commented 8 months ago

Forgive my ignorance. When you say logs of the communication with the bulb, is this the diagnostic log for the device or does this refer to a different log? If it's a different log, how do I retrieve it?

guillermoleib commented 8 months ago

This looks like the same error:

No required smartlife.iot.smartbulb.lightingservice in response: {'smartlife.iot.common.emeter': {'get_realtime': {'power_mw': 0, 'total_wh': 503, 'err_code': 0}, 'get_daystat': {'day_list': [{'year': 2024, 'month': 1, 'day': 1, 'energy_wh': 81}, {'year': 2024, 'month': 1, 'day': 2, 'energy_wh': 34}, {'year': 2024, 'month': 1, 'day': 3, 'energy_wh': 56}, {'year': 2024, 'month': 1, 'day': 4, 'energy_wh': 46}, {'year': 2024, 'month': 1, 'day': 5, 'energy_wh': 99}, {'year': 2024, 'month': 1, 'day': 6, 'energy_wh': 54}, {'year': 2024, 'month': 1, 'day': 7, 'energy_wh': 18}], 'err_code': 0}, 'get_monthstat': {'month_list': [{'year': 2024, 'month': 1, 'energy_wh': 388}], 'err_code': 0}}, 'smartlife.iot.common.cloud': {'get_info': {'username': '[REDACTED]', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 1, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 1, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}

After adding outdoor access points I've been disabling "problematic" TPlink lightbulbs one by one, as it looked like this was related to some connectivity issues. Good news, I have the best wifi coverage I ever imagined, now even outside my house. Bad news: it didn't solve these messages, that are causing my custom scripts to abort.

Sometime cycling the power for the bulb, sometimes reloading the device in the integration, sometimes restarting HA fixes it. Sorry about not having more precise information :)

But after some "resetting", everything works. The issue starts to happen a while after.

Next attempt will be to add a custom Python service script to see if I can implement error handling just enough to ignore the offending device(s) and avoid crashing the yaml scripts.

Please, any instructions on how to provide more debugging info will be greatly appreciated.

Thank you very much for your effort!

bdraco commented 8 months ago

Forgive my ignorance. When you say logs of the communication with the bulb, is this the diagnostic log for the device or does this refer to a different log? If it's a different log, how do I retrieve it?

Once debug logs are enabled, scroll down on /config/logs

and click download logs

shogun168 commented 8 months ago

+1 here .. hard to replicate as it appears every few weeks out of the blue and sometimes I don't notice it until many hours later when the error stops some other automation from completing.

bdraco commented 8 months ago

KL125s showed up today

Going to see if I can replicate the issue

bdraco commented 8 months ago

Worked flawlessly out of the box with no issues 😢

bdraco commented 8 months ago

It looks like the bulb is part of a group.

Would you please post the group configuration and the exact service call you use to trigger the error?

rytilahti commented 8 months ago

For me, the device seems to be in some weird state as if this response is coming from the turn on/off query (which basically calls this: https://github.com/python-kasa/python-kasa/blob/460054ced7f9b4c13002fb96b8ef349aaa8f5770/kasa/smartbulb.py#L333), there should be no emeter nor cloud responses in there. If this were a response to the regular update (that got somehow mixed in), there should be more data in the response.

It could be a firmware bug, but we should probably still try to handle it somewhat gracefully if possible... Perhaps resetting the TCP session could be enough?

When you encounter this issue the next time, could you please try the cli tool shipped by the backend lib and execute kasa -d --host <ip> (see https://github.com/python-kasa/python-kasa#getting-started for installation instructions) to see if that crashes, too?

cohenavi commented 8 months ago

Some updates. I completely replaced the bulbs with new ones but kept the same HomeAsssitant configurations. It was working well for about 3 days and then happened again. Here are the logs:

2024-01-10 18:08:56.355 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.1.100 data in 0.142 seconds (success: True)
2024-01-10 18:08:57.284 DEBUG (MainThread) [kasa.smartdevice] The device has emeter, querying its information along sysinfo
2024-01-10 18:08:57.284 DEBUG (MainThread) [kasa.smartdevice] Module emeter already registered, ignoring...
2024-01-10 18:08:57.284 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Schedule (smartlife.iot.common.schedule) for 192.168.1.99>: {'smartlife.iot.common.schedule': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:08:57.284 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Usage (smartlife.iot.common.schedule) for 192.168.1.99>: {'smartlife.iot.common.schedule': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:08:57.284 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Antitheft (smartlife.iot.common.anti_theft) for 192.168.1.99>: {'smartlife.iot.common.anti_theft': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:08:57.285 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Time (smartlife.iot.common.timesetting) for 192.168.1.99>: {'smartlife.iot.common.timesetting': {'get_time': None, 'get_timezone': None}}
2024-01-10 18:08:57.285 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Emeter (smartlife.iot.common.emeter) for 192.168.1.99>: {'smartlife.iot.common.emeter': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:08:57.285 DEBUG (MainThread) [kasa.smartdevice] Module <Module Countdown (countdown) for 192.168.1.99> not supported, skipping
2024-01-10 18:08:57.285 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Cloud (smartlife.iot.common.cloud) for 192.168.1.99>: {'smartlife.iot.common.cloud': {'get_info': None}}
2024-01-10 18:08:57.285 DEBUG (MainThread) [kasa.protocol] 192.168.1.99 >> {"system":{"get_sysinfo":null},"smartlife.iot.common.schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.anti_theft":{"get_rules":null,"get_next_action":null},"smartlife.iot.common.timesetting":{"get_time":null,"get_timezone":null}}
2024-01-10 18:08:57.290 DEBUG (MainThread) [kasa.protocol] 192.168.1.99 << {'smartlife.iot.common.cloud': {'get_info': {'binded': 1,
                                             'cld_connection': 1,
                                             'err_code': 0,
                                             'fwDlPage': '',
                                             'fwNotifyType': -1,
                                             'illegalType': 0,
                                             'server': 'n-devs.tplinkcloud.com',
                                             'stopConnect': 0,
                                             'tcspInfo': '',
                                             'tcspStatus': 1,
                                             'username': 'cohenavi@gmail.com'}},
 'smartlife.iot.common.emeter': {'get_daystat': {'day_list': [{'day': 6,
                                                               'energy_wh': 25,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 7,
                                                               'energy_wh': 4,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 8,
                                                               'energy_wh': 9,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 9,
                                                               'energy_wh': 33,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 10,
                                                               'energy_wh': 23,
                                                               'month': 1,
                                                               'year': 2024}],
                                                 'err_code': 0},
                                 'get_monthstat': {'err_code': 0,
                                                   'month_list': [{'energy_wh': 94,
                                                                   'month': 1,
                                                                   'year': 2024}]},
                                 'get_realtime': {'err_code': 0,
                                                  'power_mw': 10800,
                                                  'total_wh': 19}}}
2024-01-10 18:08:57.290 DEBUG (MainThread) [kasa.protocol] 192.168.1.99 >> {"smartlife.iot.common.emeter":{"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.cloud":{"get_info":null}}
2024-01-10 18:08:57.361 DEBUG (MainThread) [kasa.protocol] 192.168.1.99 << {'smartlife.iot.common.anti_theft': {'get_next_action': {'err_code': -2000,
                                                         'err_msg': 'member '
                                                                    'not '
                                                                    'support'},
                                     'get_rules': {'enable': 0,
                                                   'err_code': 0,
                                                   'rule_list': [],
                                                   'version': 2}},
 'smartlife.iot.common.schedule': {'get_daystat': {'day_list': [{'day': 6,
                                                                 'month': 1,
                                                                 'time': 267,
                                                                 'year': 2024},
                                                                {'day': 7,
                                                                 'month': 1,
                                                                 'time': 141,
                                                                 'year': 2024},
                                                                {'day': 8,
                                                                 'month': 1,
                                                                 'time': 279,
                                                                 'year': 2024},
                                                                {'day': 9,
                                                                 'month': 1,
                                                                 'time': 523,
                                                                 'year': 2024},
                                                                {'day': 10,
                                                                 'month': 1,
                                                                 'time': 614,
                                                                 'year': 2024}],
                                                   'err_code': 0},
                                   'get_monthstat': {'err_code': 0,
                                                     'month_list': [{'month': 1,
                                                                     'time': 1824,
                                                                     'year': 2024}]},
                                   'get_next_action': {'err_code': 0,
                                                       'type': -1},
                                   'get_realtime': {'err_code': -2000,
                                                    'err_msg': 'member not '
                                                               'support'},
                                   'get_rules': {'enable': 1,
                                                 'err_code': 0,
                                                 'rule_list': [],
                                                 'version': 2}},
 'smartlife.iot.common.timesetting': {'get_time': {'err_code': 0,
                                                   'hour': 18,
                                                   'mday': 10,
                                                   'min': 8,
                                                   'month': 1,
                                                   'sec': 56,
                                                   'year': 2024},
                                      'get_timezone': {'err_code': 0,
                                                       'index': 18}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Kitchen Table',
                            'ctrl_protocols': {'name': 'Linkie',
                                               'version': '1.0'},
                            'description': 'Smart Wi-Fi LED Bulb with Color '
                                           'Changing',
                            'dev_state': 'normal',
                            'deviceId': '801278733082706AB9BBDA762E19F27921480351',
                            'disco_ver': '1.0',
                            'err_code': 0,
                            'hwId': 'CCCEA814DB7786E5A00F65412AAD11CE',
                            'hw_ver': '3.0',
                            'is_color': 1,
                            'is_dimmable': 1,
                            'is_factory': False,
                            'is_variable_color_temp': 1,
                            'latitude_i': -1879048193,
                            'light_state': {'brightness': 100,
                                            'color_temp': 2700,
                                            'hue': 0,
                                            'mode': 'normal',
                                            'on_off': 1,
                                            'saturation': 0},
                            'longitude_i': -1879048193,
                            'mic_mac': '5C628B60AB0D',
                            'mic_type': 'IOT.SMARTBULB',
                            'model': 'KL125(US)',
                            'obd_src': 'tplink',
                            'oemId': '44560C6D92259EB1042C47EC18943A80',
                            'preferred_state': [{'brightness': 50,
                                                 'color_temp': 2700,
                                                 'hue': 0,
                                                 'index': 0,
                                                 'saturation': 0},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 0,
                                                 'index': 1,
                                                 'saturation': 100},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 120,
                                                 'index': 2,
                                                 'saturation': 100},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 240,
                                                 'index': 3,
                                                 'saturation': 100}],
                            'rssi': -29,
                            'status': 'new',
                            'sw_ver': '1.0.13 Build 220714 Rel.162126'}}}
2024-01-10 18:08:57.361 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.1.99 data in 0.077 seconds (success: True)
2024-01-10 18:08:58.876 DEBUG (MainThread) [kasa.smartdevice] The device has emeter, querying its information along sysinfo
2024-01-10 18:08:58.876 DEBUG (MainThread) [kasa.smartdevice] Module emeter already registered, ignoring...
2024-01-10 18:08:58.877 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Schedule (smartlife.iot.common.schedule) for 192.168.1.101>: {'smartlife.iot.common.schedule': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:08:58.877 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Usage (smartlife.iot.common.schedule) for 192.168.1.101>: {'smartlife.iot.common.schedule': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:08:58.877 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Antitheft (smartlife.iot.common.anti_theft) for 192.168.1.101>: {'smartlife.iot.common.anti_theft': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:08:58.878 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Time (smartlife.iot.common.timesetting) for 192.168.1.101>: {'smartlife.iot.common.timesetting': {'get_time': None, 'get_timezone': None}}
2024-01-10 18:08:58.878 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Emeter (smartlife.iot.common.emeter) for 192.168.1.101>: {'smartlife.iot.common.emeter': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:08:58.879 DEBUG (MainThread) [kasa.smartdevice] Module <Module Countdown (countdown) for 192.168.1.101> not supported, skipping
2024-01-10 18:08:58.879 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Cloud (smartlife.iot.common.cloud) for 192.168.1.101>: {'smartlife.iot.common.cloud': {'get_info': None}}
2024-01-10 18:08:58.879 DEBUG (MainThread) [kasa.protocol] 192.168.1.101 >> {"system":{"get_sysinfo":null},"smartlife.iot.common.schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.anti_theft":{"get_rules":null,"get_next_action":null},"smartlife.iot.common.timesetting":{"get_time":null,"get_timezone":null}}
2024-01-10 18:08:58.887 DEBUG (MainThread) [kasa.protocol] 192.168.1.101 << {'smartlife.iot.common.cloud': {'get_info': {'binded': 1,
                                             'cld_connection': 1,
                                             'err_code': 0,
                                             'fwDlPage': '',
                                             'fwNotifyType': -1,
                                             'illegalType': 0,
                                             'server': 'n-devs.tplinkcloud.com',
                                             'stopConnect': 0,
                                             'tcspInfo': '',
                                             'tcspStatus': 1,
                                             'username': 'cohenavi@gmail.com'}},
 'smartlife.iot.common.emeter': {'get_daystat': {'day_list': [{'day': 6,
                                                               'energy_wh': 15,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 7,
                                                               'energy_wh': 5,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 8,
                                                               'energy_wh': 33,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 9,
                                                               'energy_wh': 33,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 10,
                                                               'energy_wh': 23,
                                                               'month': 1,
                                                               'year': 2024}],
                                                 'err_code': 0},
                                 'get_monthstat': {'err_code': 0,
                                                   'month_list': [{'energy_wh': 109,
                                                                   'month': 1,
                                                                   'year': 2024}]},
                                 'get_realtime': {'err_code': 0,
                                                  'power_mw': 10800,
                                                  'total_wh': 19}}}
2024-01-10 18:08:58.887 DEBUG (MainThread) [kasa.protocol] 192.168.1.101 >> {"smartlife.iot.common.emeter":{"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.cloud":{"get_info":null}}
2024-01-10 18:08:59.012 DEBUG (MainThread) [kasa.protocol] 192.168.1.101 << {'smartlife.iot.common.anti_theft': {'get_next_action': {'err_code': -2000,
                                                         'err_msg': 'member '
                                                                    'not '
                                                                    'support'},
                                     'get_rules': {'enable': 0,
                                                   'err_code': 0,
                                                   'rule_list': [],
                                                   'version': 2}},
 'smartlife.iot.common.schedule': {'get_daystat': {'day_list': [{'day': 6,
                                                                 'month': 1,
                                                                 'time': 661,
                                                                 'year': 2024},
                                                                {'day': 7,
                                                                 'month': 1,
                                                                 'time': 615,
                                                                 'year': 2024},
                                                                {'day': 8,
                                                                 'month': 1,
                                                                 'time': 279,
                                                                 'year': 2024},
                                                                {'day': 9,
                                                                 'month': 1,
                                                                 'time': 523,
                                                                 'year': 2024},
                                                                {'day': 10,
                                                                 'month': 1,
                                                                 'time': 1264,
                                                                 'year': 2024}],
                                                   'err_code': 0},
                                   'get_monthstat': {'err_code': 0,
                                                     'month_list': [{'month': 1,
                                                                     'time': 3342,
                                                                     'year': 2024}]},
                                   'get_next_action': {'err_code': 0,
                                                       'type': -1},
                                   'get_realtime': {'err_code': -2000,
                                                    'err_msg': 'member not '
                                                               'support'},
                                   'get_rules': {'enable': 0,
                                                 'err_code': 0,
                                                 'rule_list': [],
                                                 'version': 2}},
 'smartlife.iot.common.timesetting': {'get_time': {'err_code': 0,
                                                   'hour': 15,
                                                   'mday': 10,
                                                   'min': 8,
                                                   'month': 1,
                                                   'sec': 58,
                                                   'year': 2024},
                                      'get_timezone': {'err_code': 0,
                                                       'index': 6}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Kitchen Light 1',
                            'ctrl_protocols': {'name': 'Linkie',
                                               'version': '1.0'},
                            'description': 'Smart Wi-Fi LED Bulb with Color '
                                           'Changing',
                            'dev_state': 'normal',
                            'deviceId': '8012B0FE582A0372B82EA2A84FF5890221489F78',
                            'disco_ver': '1.0',
                            'err_code': 0,
                            'hwId': 'CCCEA814DB7786E5A00F65412AAD11CE',
                            'hw_ver': '3.0',
                            'is_color': 1,
                            'is_dimmable': 1,
                            'is_factory': False,
                            'is_variable_color_temp': 1,
                            'latitude_i': 0,
                            'light_state': {'brightness': 100,
                                            'color_temp': 2700,
                                            'hue': 0,
                                            'mode': 'normal',
                                            'on_off': 1,
                                            'saturation': 0},
                            'longitude_i': 0,
                            'mic_mac': '5C628B609611',
                            'mic_type': 'IOT.SMARTBULB',
                            'model': 'KL125(US)',
                            'obd_src': 'tplink',
                            'oemId': '44560C6D92259EB1042C47EC18943A80',
                            'preferred_state': [{'brightness': 50,
                                                 'color_temp': 2700,
                                                 'hue': 0,
                                                 'index': 0,
                                                 'saturation': 0},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 0,
                                                 'index': 1,
                                                 'saturation': 100},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 120,
                                                 'index': 2,
                                                 'saturation': 100},
                                                {'brightness': 100,
                                                 'color_temp': 0,
                                                 'hue': 240,
                                                 'index': 3,
                                                 'saturation': 100}],
                            'rssi': -30,
                            'status': 'new',
                            'sw_ver': '1.0.10 Build 210726 Rel.141846'}}}
2024-01-10 18:08:59.012 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.1.101 data in 0.136 seconds (success: True)
2024-01-10 18:09:01.213 DEBUG (MainThread) [kasa.smartdevice] The device has emeter, querying its information along sysinfo
2024-01-10 18:09:01.214 DEBUG (MainThread) [kasa.smartdevice] Module emeter already registered, ignoring...
2024-01-10 18:09:01.214 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Schedule (smartlife.iot.common.schedule) for 192.168.1.100>: {'smartlife.iot.common.schedule': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:09:01.214 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Usage (smartlife.iot.common.schedule) for 192.168.1.100>: {'smartlife.iot.common.schedule': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:09:01.215 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Antitheft (smartlife.iot.common.anti_theft) for 192.168.1.100>: {'smartlife.iot.common.anti_theft': {'get_rules': None, 'get_next_action': None}}
2024-01-10 18:09:01.215 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Time (smartlife.iot.common.timesetting) for 192.168.1.100>: {'smartlife.iot.common.timesetting': {'get_time': None, 'get_timezone': None}}
2024-01-10 18:09:01.215 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Emeter (smartlife.iot.common.emeter) for 192.168.1.100>: {'smartlife.iot.common.emeter': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-10 18:09:01.216 DEBUG (MainThread) [kasa.smartdevice] Module <Module Countdown (countdown) for 192.168.1.100> not supported, skipping
2024-01-10 18:09:01.216 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Cloud (smartlife.iot.common.cloud) for 192.168.1.100>: {'smartlife.iot.common.cloud': {'get_info': None}}
2024-01-10 18:09:01.217 DEBUG (MainThread) [kasa.protocol] 192.168.1.100 >> {"system":{"get_sysinfo":null},"smartlife.iot.common.schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.anti_theft":{"get_rules":null,"get_next_action":null},"smartlife.iot.common.timesetting":{"get_time":null,"get_timezone":null}}
2024-01-10 18:09:01.224 DEBUG (MainThread) [kasa.protocol] 192.168.1.100 << {'smartlife.iot.common.cloud': {'get_info': {'binded': 1,
                                             'cld_connection': 1,
                                             'err_code': 0,
                                             'fwDlPage': '',
                                             'fwNotifyType': -1,
                                             'illegalType': 0,
                                             'server': 'n-devs.tplinkcloud.com',
                                             'stopConnect': 0,
                                             'tcspInfo': '',
                                             'tcspStatus': 1,
                                             'username': 'cohenavi@gmail.com'}},
 'smartlife.iot.common.emeter': {'get_daystat': {'day_list': [{'day': 6,
                                                               'energy_wh': 16,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 7,
                                                               'energy_wh': 4,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 8,
                                                               'energy_wh': 33,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 9,
                                                               'energy_wh': 34,
                                                               'month': 1,
                                                               'year': 2024},
                                                              {'day': 10,
                                                               'energy_wh': 23,
                                                               'month': 1,
                                                               'year': 2024}],
                                                 'err_code': 0},
                                 'get_monthstat': {'err_code': 0,
                                                   'month_list': [{'energy_wh': 110,
                                                                   'month': 1,
                                                                   'year': 2024}]},
                                 'get_realtime': {'err_code': 0,
                                                  'power_mw': 10800,
                                                  'total_wh': 19}}}
2024-01-10 18:09:01.225 DEBUG (MainThread) [kasa.protocol] 192.168.1.100 >> {"smartlife.iot.common.emeter":{"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"smartlife.iot.common.cloud":{"get_info":null}}

cohenavi commented 8 months ago

It looks like the bulb is part of a group.

Would you please post the group configuration and the exact service call you use to trigger the error?

This occurs when individually switching the lights: Untitled

Shomesomesho commented 8 months ago

I'm getting what seems to be the same/very similar errors on 6 HS220 switches. I have 3 other HS220 switches that don't get these errors, as well as various other Kasa devices that are fine.

I disabled all but the 6 problem switches and enabled debug logging. Hopefully I did this correctly.

home-assistant_tplink_2024-01-12T02-37-24.362Z.log

Living room error

bdraco commented 8 months ago

Thanks for the logs. It looks like there are still other tplink devices in the logs that are enabled so it makes it very difficult to figure out what is going on

bdraco commented 8 months ago

2024-01-11 21:36:46.426 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Schedule (schedule) for 192.168.1.104>: {'schedule': {'get_rules': None, 'get_next_action': None}}
2024-01-11 21:36:46.426 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Usage (schedule) for 192.168.1.104>: {'schedule': {'get_realtime': None, 'get_daystat': {'year': 2024, 'month': 1}, 'get_monthstat': {'year': 2024}}}
2024-01-11 21:36:46.426 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Antitheft (anti_theft) for 192.168.1.104>: {'anti_theft': {'get_rules': None, 'get_next_action': None}}
2024-01-11 21:36:46.426 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Time (time) for 192.168.1.104>: {'time': {'get_time': None, 'get_timezone': None}}
2024-01-11 21:36:46.427 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Cloud (cnCloud) for 192.168.1.104>: {'cnCloud': {'get_info': None}}
2024-01-11 21:36:46.427 DEBUG (MainThread) [kasa.smartdevice] Module <Module Motion (smartlife.iot.PIR) for 192.168.1.104> not supported, skipping
2024-01-11 21:36:46.427 DEBUG (MainThread) [kasa.smartdevice] Module <Module AmbientLight (smartlife.iot.LAS) for 192.168.1.104> not supported, skipping
2024-01-11 21:36:46.427 DEBUG (MainThread) [kasa.protocol] 192.168.1.104 >> {"system":{"get_sysinfo":null},"schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"anti_theft":{"get_rules":null,"get_next_action":null},"time":{"get_time":null,"get_timezone":null},"cnCloud":{"get_info":null}}
2024-01-11 21:36:46.430 DEBUG (MainThread) [kasa.protocol] 192.168.1.104 << {'anti_theft': {'get_next_action': {'err_code': -2,
                                    'err_msg': 'member not support'},
                'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'cnCloud': {'get_info': {'binded': 1,
                          'cld_connection': 0,
                          'err_code': 0,
                          'fwDlPage': '',
                          'fwNotifyType': -1,
                          'illegalType': 0,
                          'server': 'n-devs.tplinkcloud.com',
                          'stopConnect': 0,
                          'tcspInfo': '',
                          'tcspStatus': 0,
                          'username': '********.com'}},
 'schedule': {'get_daystat': {'day_list': [], 'err_code': 0},
              'get_monthstat': {'err_code': 0, 'month_list': []},
              'get_next_action': {'err_code': 0, 'type': -1},
              'get_realtime': {'err_code': -2, 'err_msg': 'member not support'},
              'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Kitchen Pantry',
                            'brightness': 50,
                            'dev_name': 'Wi-Fi Smart Dimmer',
                            'deviceId': '80067134C23C2757627FA9B49DC562AE1EDFFAD1',
                            'err_code': 0,
                            'feature': 'TIM',
                            'hwId': '50B3F5C5DF12106A8C85E8903749DF1B',
                            'hw_ver': '3.0',
                            'icon_hash': '',
                            'latitude_i': 263202,
                            'led_off': 0,
                            'longitude_i': -801577,
                            'mac': '10:27:F5:72:3A:6C',
                            'mic_type': 'IOT.SMARTPLUGSWITCH',
                            'model': 'HS220(US)',
                            'next_action': {'type': -1},
                            'ntc_state': 0,
                            'oemId': '774577CB2E1782A8BA53CDBBA136FAE6',
                            'on_time': 0,
                            'preferred_state': [{'brightness': 100, 'index': 0},
                                                {'brightness': 75, 'index': 1},
                                                {'brightness': 50, 'index': 2},
                                                {'brightness': 2, 'index': 3}],
                            'relay_state': 0,
                            'rssi': -47,
                            'status': 'new',
                            'sw_ver': '1.0.3 Build 210202 Rel.190636',
                            'updating': 0}},
 'time': {'get_time': {'err_code': 0,
                       'hour': 20,
                       'mday': 1,
                       'min': 23,
                       'month': 1,
                       'sec': 36,
                       'year': 2000},
          'get_timezone': {'err_code': 0, 'index': 18}}}
2024-01-11 21:36:46.430 INFO (MainThread) [homeassistant.components.tplink.coordinator] Fetching 192.168.1.104 data recovered
2024-01-11 21:36:46.430 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.1.104 data in 0.004 seconds (success: True)
2024-01-11 21:36:47.076 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139644930583232] No required smartlife.iot.dimmer in response: {'system': {'get_sysinfo': {'sw_ver': '1.0.3 Build 210202 Rel.190636', 'hw_ver': '3.0', 'model': 'HS220(US)', 'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692', 'oemId': '774577CB2E1782A8BA53CDBBA136FAE6', 'hwId': '50B3F5C5DF12106A8C85E8903749DF1B', 'rssi': -48, 'latitude_i': 263202, 'longitude_i': -801577, 'alias': 'Living Room', 'status': 'new', 'mic_type': 'IOT.SMARTPLUGSWITCH', 'feature': 'TIM', 'mac': '10:27:F5:72:2F:19', 'updating': 0, 'led_off': 0, 'relay_state': 0, 'brightness': 50, 'on_time': 0, 'icon_hash': '', 'dev_name': 'Wi-Fi Smart Dimmer', 'active_mode': 'none', 'next_action': {'type': -1}, 'preferred_state': [{'index': 0, 'brightness': 100}, {'index': 1, 'brightness': 75}, {'index': 2, 'brightness': 50}, {'index': 3, 'brightness': 25}], 'ntc_state': 0, 'err_code': 0}}, 'schedule': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'type': -1, 'err_code': 0}, 'get_realtime': {'err_code': -2, 'err_msg': 'member not support'}, 'get_daystat': {'day_list': [], 'err_code': 0}, 'get_monthstat': {'month_list': [], 'err_code': 0}}, 'anti_theft': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'err_code': -2, 'err_msg': 'member not support'}}, 'time': {'get_time': {'year': 2000, 'month': 1, 'mday': 1, 'hour': 20, 'min': 24, 'sec': 3, 'err_code': 0}, 'get_timezone': {'index': 18, 'err_code': 0}}, 'cnCloud': {'get_info': {'username': '********.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 0, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 0, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 238, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2149, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2186, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 882, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 624, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/tplink/entity.py", line 26, in _async_wrap
    await func(self, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/tplink/light.py", line 245, in async_turn_on
    await self._async_turn_on_with_brightness(brightness, transition)
  File "/usr/src/homeassistant/homeassistant/components/tplink/light.py", line 230, in _async_turn_on_with_brightness
    await self.device.turn_on(transition=transition)
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdevice.py", line 78, in wrapped
    return await f(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdimmer.py", line 144, in turn_on
    return await self.set_dimmer_transition(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdimmer.py", line 170, in set_dimmer_transition
    return await self._query_helper(
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdevice.py", line 275, in _query_helper
    raise SmartDeviceException(f"No required {target} in response: {response}")
kasa.exceptions.SmartDeviceException: No required smartlife.iot.dimmer in response: {'system': {'get_sysinfo': {'sw_ver': '1.0.3 Build 210202 Rel.190636', 'hw_ver': '3.0', 'model': 'HS220(US)', 'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692', 'oemId': '774577CB2E1782A8BA53CDBBA136FAE6', 'hwId': '50B3F5C5DF12106A8C85E8903749DF1B', 'rssi': -48, 'latitude_i': 263202, 'longitude_i': -801577, 'alias': 'Living Room', 'status': 'new', 'mic_type': 'IOT.SMARTPLUGSWITCH', 'feature': 'TIM', 'mac': '10:27:F5:72:2F:19', 'updating': 0, 'led_off': 0, 'relay_state': 0, 'brightness': 50, 'on_time': 0, 'icon_hash': '', 'dev_name': 'Wi-Fi Smart Dimmer', 'active_mode': 'none', 'next_action': {'type': -1}, 'preferred_state': [{'index': 0, 'brightness': 100}, {'index': 1, 'brightness': 75}, {'index': 2, 'brightness': 50}, {'index': 3, 'brightness': 25}], 'ntc_state': 0, 'err_code': 0}}, 'schedule': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'type': -1, 'err_code': 0}, 'get_realtime': {'err_code': -2, 'err_msg': 'member not support'}, 'get_daystat': {'day_list': [], 'err_code': 0}, 'get_monthstat': {'month_list': [], 'err_code': 0}}, 'anti_theft': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'err_code': -2, 'err_msg': 'member not support'}}, 'time': {'get_time': {'year': 2000, 'month': 1, 'mday': 1, 'hour': 20, 'min': 24, 'sec': 3, 'err_code': 0}, 'get_timezone': {'index': 18, 'err_code': 0}}, 'cnCloud': {'get_info': {'username': '********.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 0, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 0, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}

I think this is the error from the .104 device

bdraco commented 8 months ago

actually its coming from 192.168.1.107

probably too much mixed together to really tell whats going on there

bdraco commented 8 months ago

Its pretty clear that responses are being mixed up though

24-01-11 21:36:56.122 ERROR (MainThread) [homeassistant.components.tplink.coordinator] Unexpected error fetching 192.168.1.102 data: 'get_sysinfo'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/tplink/coordinator.py", line 53, in _async_update_data
    await self.device.update(update_children=self.update_children)
  File "/usr/local/lib/python3.11/site-packages/kasa/smartdevice.py", line 334, in update
    self._set_sys_info(self._last_update["system"]["get_sysinfo"])
                       ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^
KeyError: 'get_sysinfo'

But that doesn't tell us how

Shomesomesho commented 8 months ago

To confirm, this is how I should disable the other devices? I can try again to get logs for just 1 device.

disabled

bdraco commented 8 months ago

Yes perfect 👍

bdraco commented 8 months ago

2024-01-11 21:36:56.113 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 >> {"system":{"get_sysinfo":null},"schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"anti_theft":{"get_rules":null,"get_next_action":null},"time":{"get_time":null,"get_timezone":null},"cnCloud":{"get_info":null}}
2024-01-11 21:36:56.117 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 << {'anti_theft': {'get_next_action': {'err_code': -2,
                                    'err_msg': 'member not support'},
                'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'cnCloud': {'get_info': {'binded': 1,
                          'cld_connection': 0,
                          'err_code': 0,
                          'fwDlPage': '',
                          'fwNotifyType': -1,
                          'illegalType': 0,
                          'server': 'n-devs.tplinkcloud.com',
                          'stopConnect': 0,
                          'tcspInfo': '',
                          'tcspStatus': 0,
                          'username': '********.com'}},
 'schedule': {'get_daystat': {'day_list': [], 'err_code': 0},
              'get_monthstat': {'err_code': 0, 'month_list': []},
              'get_next_action': {'err_code': 0, 'type': -1},
              'get_realtime': {'err_code': -2, 'err_msg': 'member not support'},
              'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Living Room',
                            'brightness': 50,
                            'dev_name': 'Wi-Fi Smart Dimmer',
                            'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692',
                            'err_code': 0,
                            'feature': 'TIM',
                            'hwId': '50B3F5C5DF12106A8C85E8903749DF1B',
                            'hw_ver': '3.0',
                            'icon_hash': '',
                            'latitude_i': 263202,
                            'led_off': 0,
                            'longitude_i': -801577,
                            'mac': '10:27:F5:72:2F:19',
                            'mic_type': 'IOT.SMARTPLUGSWITCH',
                            'model': 'HS220(US)',
                            'next_action': {'type': -1},
                            'ntc_state': 0,
                            'oemId': '774577CB2E1782A8BA53CDBBA136FAE6',
                            'on_time': 4,
                            'preferred_state': [{'brightness': 100, 'index': 0},
                                                {'brightness': 75, 'index': 1},
                                                {'brightness': 50, 'index': 2},
                                                {'brightness': 25, 'index': 3}],
                            'relay_state': 1,
                            'rssi': -48,
                            'status': 'new',
                            'sw_ver': '1.0.3 Build 210202 Rel.190636',
                            'updating': 0}},
 'time': {'get_time': {'err_code': 0,
                       'hour': 20,
                       'mday': 1,
                       'min': 24,
                       'month': 1,
                       'sec': 8,
                       'year': 2000},
          'get_timezone': {'err_code': 0, 'index': 18}}}
2024-01-11 21:36:56.117 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.1.107 data in 0.005 seconds (success: True)

than we sent

2024-01-11 21:36:57.348 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 >> {"system":{"set_relay_state":{"state":0}}}
2024-01-11 21:36:57.352 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 << {'anti_theft': {'get_next_action': {'err_code': -2,
                                    'err_msg': 'member not support'},
                'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'cnCloud': {'get_info': {'binded': 1,
                          'cld_connection': 0,
                          'err_code': 0,
                          'fwDlPage': '',
                          'fwNotifyType': -1,
                          'illegalType': 0,
                          'server': 'n-devs.tplinkcloud.com',
                          'stopConnect': 0,
                          'tcspInfo': '',
                          'tcspStatus': 0,
                          'username': '********.com'}},
 'schedule': {'get_daystat': {'day_list': [], 'err_code': 0},
              'get_monthstat': {'err_code': 0, 'month_list': []},
              'get_next_action': {'err_code': 0, 'type': -1},
              'get_realtime': {'err_code': -2, 'err_msg': 'member not support'},
              'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Living Room',
                            'brightness': 50,
                            'dev_name': 'Wi-Fi Smart Dimmer',
                            'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692',
                            'err_code': 0,
                            'feature': 'TIM',
                            'hwId': '50B3F5C5DF12106A8C85E8903749DF1B',
                            'hw_ver': '3.0',
                            'icon_hash': '',
                            'latitude_i': 263202,
                            'led_off': 0,
                            'longitude_i': -801577,
                            'mac': '10:27:F5:72:2F:19',
                            'mic_type': 'IOT.SMARTPLUGSWITCH',
                            'model': 'HS220(US)',
                            'next_action': {'type': -1},
                            'ntc_state': 0,
                            'oemId': '774577CB2E1782A8BA53CDBBA136FAE6',
                            'on_time': 9,
                            'preferred_state': [{'brightness': 100, 'index': 0},
                                                {'brightness': 75, 'index': 1},
                                                {'brightness': 50, 'index': 2},
                                                {'brightness': 25, 'index': 3}],
                            'relay_state': 1,
                            'rssi': -48,
                            'status': 'new',
                            'sw_ver': '1.0.3 Build 210202 Rel.190636',
                            'updating': 0}},
 'time': {'get_time': {'err_code': 0,
                       'hour': 20,
                       'mday': 1,
                       'min': 24,
                       'month': 1,
                       'sec': 13,
                       'year': 2000},
          'get_timezone': {'err_code': 0, 'index': 18}}}
2024-01-11 21:36:57.353 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139644930583232] No command in response: {'system': {'get_sysinfo': {'sw_ver': '1.0.3 Build 210202 Rel.190636', 'hw_ver': '3.0', 'model': 'HS220(US)', 'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692', 'oemId': '774577CB2E1782A8BA53CDBBA136FAE6', 'hwId': '50B3F5C5DF12106A8C85E8903749DF1B', 'rssi': -48, 'latitude_i': 263202, 'longitude_i': -801577, 'alias': 'Living Room', 'status': 'new', 'mic_type': 'IOT.SMARTPLUGSWITCH', 'feature': 'TIM', 'mac': '10:27:F5:72:2F:19', 'updating': 0, 'led_off': 0, 'relay_state': 1, 'brightness': 50, 'on_time': 9, 'icon_hash': '', 'dev_name': 'Wi-Fi Smart Dimmer', 'active_mode': 'none', 'next_action': {'type': -1}, 'preferred_state': [{'index': 0, 'brightness': 100}, {'index': 1, 'brightness': 75}, {'index': 2, 'brightness': 50}, {'index': 3, 'brightness': 25}], 'ntc_state': 0, 'err_code': 0}}, 'schedule': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'type': -1, 'err_code': 0}, 'get_realtime': {'err_code': -2, 'err_msg': 'member not support'}, 'get_daystat': {'day_list': [], 'err_code': 0}, 'get_monthstat': {'month_list': [], 'err_code': 0}}, 'anti_theft': {'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}, 'get_next_action': {'err_code': -2, 'err_msg': 'member not support'}}, 'time': {'get_time': {'year': 2000, 'month': 1, 'mday': 1, 'hour': 20, 'min': 24, 'sec': 13, 'err_code': 0}, 'get_timezone': {'index': 18, 'err_code': 0}}, 'cnCloud': {'get_info': {'username': '********.com', 'server': 'n-devs.tplinkcloud.com', 'binded': 1, 'cld_connection': 0, 'illegalType': 0, 'stopConnect': 0, 'tcspStatus': 0, 'fwDlPage': '', 'tcspInfo': '', 'fwNotifyType': -1, 'err_code': 0}}}

And we get back the previous response

Shomesomesho commented 8 months ago

Ok. I turned on Debug logging, let it sit for about 3 minutes before toggling the "Living Room" on and off.

home-assistant_tplink_2024-01-12T03-13-55.110Z.log

bdraco commented 8 months ago

Seems like some type of buffering problem

2024-01-11 22:13:46.933 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 >> {"smartlife.iot.dimmer":{"set_dimmer_transition":{"brightness":50,"duration":1}}}
2024-01-11 22:13:46.936 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 << {'anti_theft': {'get_next_action': {'err_code': -2,
                                    'err_msg': 'member not support'},
                'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'cnCloud': {'get_info': {'binded': 1,
                          'cld_connection': 0,
                          'err_code': 0,
                          'fwDlPage': '',
                          'fwNotifyType': -1,
                          'illegalType': 0,
                          'server': 'n-devs.tplinkcloud.com',
                          'stopConnect': 0,
                          'tcspInfo': '',
                          'tcspStatus': 0,
                          'username': '********@gmail.com'}},
 'schedule': {'get_daystat': {'day_list': [], 'err_code': 0},
              'get_monthstat': {'err_code': 0, 'month_list': []},
              'get_next_action': {'err_code': 0, 'type': -1},
              'get_realtime': {'err_code': -2, 'err_msg': 'member not support'},
              'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'Living Room',
                            'brightness': 50,
                            'dev_name': 'Wi-Fi Smart Dimmer',
                            'deviceId': '8006378AB373B4255F0C7A647B62FA011EDF5692',
                            'err_code': 0,
                            'feature': 'TIM',
                            'hwId': '50B3F5C5DF12106A8C85E8903749DF1B',
                            'hw_ver': '3.0',
                            'icon_hash': '',
                            'latitude_i': 263202,
                            'led_off': 0,
                            'longitude_i': -801577,
                            'mac': '10:27:F5:72:2F:19',
                            'mic_type': 'IOT.SMARTPLUGSWITCH',
                            'model': 'HS220(US)',
                            'next_action': {'type': -1},
                            'ntc_state': 0,
                            'oemId': '774577CB2E1782A8BA53CDBBA136FAE6',
                            'on_time': 0,
                            'preferred_state': [{'brightness': 100, 'index': 0},
                                                {'brightness': 75, 'index': 1},
                                                {'brightness': 50, 'index': 2},
                                                {'brightness': 25, 'index': 3}],
                            'relay_state': 0,
                            'rssi': -49,
                            'status': 'new',
                            'sw_ver': '1.0.3 Build 210202 Rel.190636',
                            'updating': 0}},
 'time': {'get_time': {'err_code': 0,
                       'hour': 21,
                       'mday': 1,
                       'min': 1,
                       'month': 1,
                       'sec': 3,
                       'year': 2000},
          'get_timezone': {'err_code': 0, 'index': 18}}}

We send {"smartlife.iot.dimmer":{"set_dimmer_transition":{"brightness":50,"duration":1}}} but the device acts like it got the previous message again because it sends the same reply but with a new time code

first

 'time': {'get_time': {'err_code': 0,
                       'hour': 21,
                       'mday': 1,
                       'min': 0,
                       'month': 1,
                       'sec': 58,
                       'year': 2000},

second

 'time': {'get_time': {'err_code': 0,
                       'hour': 21,
                       'mday': 1,
                       'min': 1,
                       'month': 1,
                       'sec': 3,
                       'year': 2000},

Its also exactly 5s apart which is the polling interval

bdraco commented 8 months ago

Than we send the poll request

2024-01-11 22:13:51.114 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 >> {"system":{"get_sysinfo":null},"schedule":{"get_rules":null,"get_next_action":null,"get_realtime":null,"get_daystat":{"year":2024,"month":1},"get_monthstat":{"year":2024}},"anti_theft":{"get_rules":null,"get_next_action":null},"time":{"get_time":null,"get_timezone":null},"cnCloud":{"get_info":null}}

And get back the message we were expecting earlier

2024-01-11 22:13:51.115 DEBUG (MainThread) [kasa.protocol] 192.168.1.107 << {'smartlife.iot.dimmer': {'set_dimmer_transition': {'err_code': 0}}}

bdraco commented 8 months ago

You don't by chance have more than one home assistant device polling the tplink device or the tplink app also open?

Shomesomesho commented 8 months ago

I only have 1 Home Assistant server, and the Kasa app isn't open on my phone.

bdraco commented 8 months ago

I have 3 other HS220 switches that don't get these errors, as well as various other Kasa devices that are fine.

This is sure starting to look like a buffer overflow problem.

Which firmware version do you have on the problem HS220s ?

Which firmware version do you have on the working HS220s ?

Shomesomesho commented 8 months ago

Problem HS220 Firmwares are: Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.102 Firmware: 1.0.8 Build 210423 Rel.075507 - 192.168.1.103 Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.104 Firmware: 1.0.8 Build 210423 Rel.075507 - 192.168.1.105 Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.106 Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.107

Working HS220 Firmwares are: Firmware: 1.0.8 Build 210423 Rel.075507 - 192.168.1.101 Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.108 Firmware: 1.0.3 Build 210202 Rel.190636 - 192.168.1.110

bdraco commented 8 months ago

So no correlation between firmwares.

I've purchased 6 different devices trying to make this problem happen but I still can get it to happen locally.

I'm almost to the point were we need to rewrite the protocol to not use asyncio streams and make our own protocol handler so we don't have to do locking.. but that would be a major change which might introduce more problems while we work through it

bdraco commented 8 months ago

I think we need wireshark dumps or pcaps on the access point if someone has unifi

https://help.ui.com/hc/en-us/articles/204959834 https://www.reddit.com/r/Ubiquiti/comments/fjmnvd/capturing_traffic_with_tcpdump_as_per_ubnt_docs/

Than we can see the raw traffic and the problem might be a bit more obvious

Shomesomesho commented 8 months ago

Sorry that my switches cause you headaches. :( Its weird that these worked fine for over a year and then started throwing errors. I almost want to say that I only noticed the problem when I updated HA from the November to December updates.

bdraco commented 8 months ago

There was a library change from 0.5.3 to 0.5.4 around that time, but I don't see anything obvious that would cause this in the diff

https://github.com/python-kasa/python-kasa/compare/0.5.3...0.5.4

bdraco commented 8 months ago

The only other way I could see this happening if we somehow have two connections open to the device and we are mixing them up.

Only way to tell that would be a pcap/wireshark dump though

bdraco commented 8 months ago

A huge part of the connection process was rewritten in 0.6.0 (not yet released) so we might be best waiting to see if that fixes it

Shomesomesho commented 8 months ago

How could I send you a wireshark dump privately? And maybe give me a quick rundown of the steps you'd like me to take? All other Kasa devices disabled? Start capture and just toggle the switch on/off?

bdraco commented 8 months ago

You can send it to gdrive bdraco@gmail.com or Dropbox nick@koston.org

You'll either need to use tcpdump on the access point with the articles I posted above or install tcpdump and dump the traffic on the HA install for the src and dst of the tplink device's IP address while triggering the issue

Shomesomesho commented 8 months ago

I'll look into this, but it seems above my skills.

Shomesomesho commented 8 months ago

I've had a crazy thought and was hoping you could let me know if I'm wasting my time. Could these errors be caused by ZigBee interference?

Shomesomesho commented 8 months ago

Rolling back to a 2023.11.3 backup seems to have fixed this immediately as well as fixed my ZigBee devices lagging/dropping. These issues feel related, like one is causing the other or they share a root issue causing both issues. I'm not sure how to diagnose it further, but also can't just stay on 2023.11.3 forever.

bdraco commented 8 months ago

Good to know it it's likely not firmware problem and has something to do with the python-kaka bump, or the python version. I can't find anything in the Kasa library, so it could be the python version given it's affecting ZHA as well but it might just be correlated and not the actual cause.

2024.2 will use cpython 3.12 so it might change the equation a bit more

bdraco commented 8 months ago

I think at this point the only way I'm gonna figure it out is if I get access to an affected system, but I could certainly understand if you don't feel comfortable with that.

Shomesomesho commented 8 months ago

I made a temp admin account. Could I email you the login info and discuss when you'd be available to look at it?

bdraco commented 8 months ago

Sounds good. Feel free to reach out on discord. My handle is the same there

bdraco commented 8 months ago

Documenting investigation so far:

2023.11.3 and 2024.1.2 both have

python-kasa[speedups]==0.5.4
kasa-crypt==0.4.0
python 3.11.6

2024.1.3 has kasa-crypt==0.4.1

bdraco commented 8 months ago

payloads all match the tcpdump so not an encryption problem

I think its a cancellation problem

bdraco commented 8 months ago

theory is that

http (likely a service call) request fails in some way or connection drops aiohttp connection is cancelled it raises CancelledError down into the protocol which is a BaseException

It happens in the middle of a request so it the connection is now in an indeterminate state

If we trap BaseException and close the connection without a wait we get back to a good state.

bdraco commented 8 months ago

This will be fixed in the next library bump of python-kasa

Watch the changelog in the next ha release for a bump of the python-kasa version to know when its available

home-assistant / core