core Lutron Caseta Sporadic Async Issues

The problem

I appear to be getting sporadic issues concerning the Lutron Caseta integration. I have an automation setup to turn lights on when arriving home after it is dark out. The automation will work fine sometimes and other times it will fail with the attached errors. I don't have a consistent way to replicate the issue.

Another person on the forums appears to be experiencing the same issue

What version of Home Assistant Core has the issue?

core-2023.12.3

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

Lutron Caseta

Link to integration documentation on our website

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

Diagnostics information

home-assistant_lutron_caseta_2023-12-23T14-34-45.559Z.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: pylutron_caseta.leap
Source: runner.py:188
First occurred: December 21, 2023 at 8:51:41 PM (3 occurrences)
Last logged: 8:28:14 PM

Was not expecting message with tag b6e6e61e-a3f9-41a7-a37a-6692ee43808d: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/6/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/6/status', 'Level': 100, 'SwitchedLevel': 'On', 'Zone': {'href': '/zone/6'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag 8ae2398a-6a4f-423b-852e-f2078cf0ee46: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/6/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/6/status', 'Level': 100, 'SwitchedLevel': 'On', 'Zone': {'href': '/zone/6'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag fc8ff5c6-0b18-4b46-8371-a50dd99b534d: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/6/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/6/status', 'Level': 100, 'SwitchedLevel': 'On', 'Zone': {'href': '/zone/6'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}



Logger: homeassistant.components.automation.automation_31
Source: helpers/script.py:468
Integration: Automation (documentation, issues)
First occurred: December 21, 2023 at 8:51:41 PM (3 occurrences)
Last logged: 8:28:14 PM

Arrive Home After Dark: Error executing script. Unexpected error for call_service at pos 2:
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2067, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2104, 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 903, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1233, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 948, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 580, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/switch_as_x/entity.py", line 150, in async_turn_on
    await self.hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2067, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2104, 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 878, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 948, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/lutron_caseta/switch.py", line 56, in async_turn_on
    await self._smartbridge.turn_on(self.device_id)
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 435, in turn_on
    await self.set_value(device_id, 100, **kwargs)
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 343, in set_value
    await self._request(
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 253, in _request
    async with asyncio_timeout(REQUEST_TIMEOUT):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError



Logger: homeassistant.components.automation.automation_31
Source: components/automation/__init__.py:655
Integration: Automation (documentation, issues)
First occurred: December 21, 2023 at 8:51:41 PM (3 occurrences)
Last logged: 8:28:14 PM

While executing automation automation.automation_31
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 655, in async_trigger
    await self.action_script.async_run(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1578, in async_run
    return await asyncio.shield(run.async_run())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 420, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 470, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 493, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2067, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2104, 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 903, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1233, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 948, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 580, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/switch_as_x/entity.py", line 150, in async_turn_on
    await self.hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2067, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2104, 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 878, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 948, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/lutron_caseta/switch.py", line 56, in async_turn_on
    await self._smartbridge.turn_on(self.device_id)
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 435, in turn_on
    await self.set_value(device_id, 100, **kwargs)
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 343, in set_value
    await self._request(
  File "/usr/local/lib/python3.11/site-packages/pylutron_caseta/smartbridge.py", line 253, in _request
    async with asyncio_timeout(REQUEST_TIMEOUT):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

Additional information

No response

Dec 23 '23 14:12 RobX82

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

Code owner commands

Code owners of lutron_caseta 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 lutron_caseta 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)}}

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

Dec 23 '23 14:12 home-assistant[bot]

I'm also experiencing this issue.

Logger: pylutron_caseta.leap
Source: runner.py:188
First occurred: 9:51:02 PM (1629 occurrences)
Last logged: 9:51:59 PM

Was not expecting message with tag 401e4ea9-df6d-496d-934c-760d93166461: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/3359/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/3359/status', 'Level': 0, 'Zone': {'href': '/zone/3359'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag 407ef5d0-445f-4c5e-9785-eaf18d0b809c: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/9864/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/9864/status', 'Level': 0, 'Zone': {'href': '/zone/9864'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag dbeb2a73-0599-489d-92b8-7d0e0ee123f8: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/3325/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/3325/status', 'Level': 0, 'Zone': {'href': '/zone/3325'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag 2503ac38-55ed-4ce8-8bd8-ea7d73b3df67: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/3341/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/3341/status', 'Level': 0, 'Zone': {'href': '/zone/3341'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}
Was not expecting message with tag 3e473e8e-4c93-46a7-97ad-fde744e3d97b: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/3375/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/3375/status', 'Level': 0, 'Zone': {'href': '/zone/3375'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}

Dec 27 '23 04:12 pjatx

Whats happening is the timeout is hitting here https://github.com/gurumitts/pylutron-caseta/blob/adb2ec9af45eaee60b8f09afe0709b80d63584d0/src/pylutron_caseta/smartbridge.py#L254

and than the request is removed from the dict of waiting requests in the finally block https://github.com/gurumitts/pylutron-caseta/blob/adb2ec9af45eaee60b8f09afe0709b80d63584d0/src/pylutron_caseta/leap.py#L73

and it does finally arrive and you get that exception.

I can't get this to happen on my system but it might be device type specific so maybe someone who has a large set of devices has an idea or the timeout might simply be too low and changing it to 10s from 5s will solve it. Please open an issue with the library https://github.com/gurumitts/pylutron-caseta/issues/new

Jan 28 '24 19:01 bdraco

Do you have a bad integration that is blocking the asyncio loop? (Does Home Assistant have a diagnostic for that? I don't know how you're supposed to identify a misbehaving integration.)

Response times seem normal, but at 2023-12-22 17:09:46, three requests are sent to the bridge, and we can see zone status messages come back indicating that the bridge is responding to those requests, but then no events are logged between 17:09:46.529 and 17:09:53.621, and at 17:09:53.621 we receive responses that we should have received at 17:09:46.

The strong evidence that it's a problem with the computer or another integration blocking the asyncio loop is:

the timeout should have occurred at 17:09:51 but doesn't show up in the log until 17:09:53.654, after other messages have been processed, including one that would have prevented a timeout.
The bridge is pinged every minute, and it was last pinged at 17:08:48, so it should be pinged again at 17:09:48, but the ping doesn't get sent until 17:09:53, about five seconds late.

The pattern is similar at 2023-12-22 20:28:06. The bridge sends some messages that indicate it received the requests, but then suddenly it's 20:28:14 and we're receiving responses to requests that are simultaneously timing out.

There's also an interruption 2023-12-19 19:52:43. The same automation is running, and time skips from 19:52:43 to 19:52:50. I think requests should have timed out, but didn't.

If this happens often enough that you can tell whether it's working or not, try removing other actions from the automation to see if that fixes it.

Increasing the timeout could probably work around the problem, at the expense of it taking longer to recover from network interruptions.

Jan 31 '24 03:01 mdonoughe

Well I only had 2 automations tied to the lights that were having an issue. During the second automation I am now disabling the first automation before I do anything concerning the lights. The last couple times it has ran, it appears to be working much better but going to continue keeping an eye on it.

Feb 11 '24 20:02 RobX82

Unfortunately the issue has reappeared, updated to Home Assistant 2024.2.2 which appears to update pylutron to 0.2.12.

Logger: pylutron_caseta.leap Source: runner.py:188 First occurred: 8:18:11 PM (3 occurrences) Last logged: 8:18:11 PM

Was not expecting message with tag 8bdeb7d6-2552-48d8-b463-b3b099d01a4c: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/3/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/3/status', 'Level': 100, 'Zone': {'href': '/zone/3'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}} Was not expecting message with tag 9daf1226-3e05-4cd6-a61b-4d75f1c5b59d: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/5/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/5/status', 'Level': 100, 'SwitchedLevel': 'On', 'Zone': {'href': '/zone/5'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}} Was not expecting message with tag 1b056b1b-ccb6-4ec1-b313-f35ceb1c2768: {'CommuniqueType': 'CreateResponse', 'Header': {'MessageBodyType': 'OneZoneStatus', 'StatusCode': '201 Created', 'Url': '/zone/6/commandprocessor'}, 'Body': {'ZoneStatus': {'href': '/zone/6/status', 'Level': 100, 'SwitchedLevel': 'On', 'Zone': {'href': '/zone/6'}, 'StatusAccuracy': 'Good', 'Availability': 'Available'}}}

Feb 17 '24 04:02 RobX82

If you turn on asyncio debug mode (https://docs.python.org/3/library/asyncio-dev.html#debug-mode) or enable debugpy: in configuration.yaml and restart, you should be able to see if something is blocking your event loop.

Feb 17 '24 04:02 bdraco

2024.3.x may improve this a bit as well

Feb 28 '24 07:02 bdraco

May be solved by https://github.com/home-assistant/core/pull/112127 in 2024.4 (import_executor=True is now the default)

Mar 04 '24 18:03 bdraco

@bdraco Forgive my ignorance, is the theory that another HA plugin is blocking the event loop long enough to cause the message to timeout and then the eventual response to cause an error?

What are your thoughts on increasing the timeout and/or improving the error message?

Apr 09 '24 00:04 don4of4

@bdraco Forgive my ignorance, is the theory that another HA plugin is blocking the event loop long enough to cause the message to timeout and then the eventual response to cause an error?

What are your thoughts on increasing the timeout and/or improving the error message?

Increasing the timeout is a bit of a band-aid for the problem, and will only solve it if the block isn't for so long. It will also mean that if there is a failure or error you end up waiting longer to find out which makes everyone else have a worse experience because some integration didn't get their code right.

You need to find what is blocking the event loop since thats going to affect all other integrations and home assistant operation itself.

Apr 09 '24 01:04 bdraco

If you put asyncio in debug mode, it may give you a better hint on where its happening. You can use the profiler service to do that: https://www.home-assistant.io/integrations/profiler/#service-profilerset_asyncio_debug

If you can't get far enough along you can also enable debugpy: in configuration.yaml instead (but its much slower) https://www.home-assistant.io/integrations/debugpy/

Apr 09 '24 01:04 bdraco

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

Jul 08 '24 01:07 issue-triage-workflows[bot]