dolphin-robot icon indicating copy to clipboard operation
dolphin-robot copied to clipboard
verified publisher icon sh00t2kill

MyDolphin Plus integration causing home assistant to crash

Open rybackisback opened this issue 1 year ago • 95 comments

Since ha core update to 2024.4.0 having the MyDolphin Plus integration enabled causes home assistant instance to become sluggish, unresponsive and crash. I am unable to find anything in the logs probably because it gets over written on re-start? Is anyone else seeing this? See below details on my system.

Intel NUC Core 2024.4.2 Supervisor 2024.04.0 Operating System 12.1 Frontend 20240404.1

MyDolphin Plus v1.0.10

rybackisback avatar Apr 08 '24 23:04 rybackisback

I've seen similar issues with an HA crash every 24hrs or so, but havent been able to pinpoint the source and didnt think to look at MyDolphin. I'll disable it for a few days now to test. I am using the MyDolphin Plus v1.0.10, HA Core 2024.4.2 in Docker.

gk-lurker avatar Apr 09 '24 00:04 gk-lurker

I am having the same issue - running home assistant directly on an Intel Nuc. The system would be unresponsive, but I could ssh into it. When googling I found this: https://github.com/home-assistant/core/issues/114944, which mentioned another issue which blamed an integration I don't have installed, but it made me suspect some custom integration as the cause.

When I looked into the logs I could see lots of errors for mydolphin. I deleted the directory for this component and the system became stable.

HA Core core-2024.4.2

matthewhadley avatar Apr 09 '24 03:04 matthewhadley

Interesting. There seem to be a number of custom components affected, but none of those has any fixes applied to it, and i cant see anytihng as part of 2024.4.x that would explain it.

Weirdly, it hasnt happened to me, although I only upgraded to .2 today. I also have a manual fix for the disconnect/reconnect issue, while I dont think thats likely to cause this issue, its possible

Those having the issue, can you try applying this change manually? https://github.com/sh00t2kill/dolphin-robot/pull/183/files

sh00t2kill avatar Apr 09 '24 09:04 sh00t2kill

Thanks @sh00t2kill I have applied the new aws_client.py file and hopefully it will stay connected.

rybackisback avatar Apr 09 '24 10:04 rybackisback

Has happened to me twice now, usually overnight. I managed to grab a screenshot of the log as it was in this crashed state. (It was flying by FAST)

I have applied the PR 183 fix manually and will report back if it crashes again. Thanks!

image

Scope666 avatar Apr 09 '24 11:04 Scope666

Crashed again, this time I grabbed better logs:

EDIT: I see references to the Watchman custom component, I've removed that to see if it helps.

2024-04-10 09:15:10.697 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c3df14550>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:11.034 WARNING (MainThread) [homeassistant.components.light] Updating sengledapi light took longer than the scheduled update interval 0:00:10
2024-04-10 09:15:11.411 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcb80a0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:11.738 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcbaa10>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1629909' coro=<XRegistryLocal._handler2() running at /config/custom_components/sonoff/core/ewelink/local.py:105>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:11.839 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-10 09:15:11.840 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c3df17670>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1629910' coro=<RemoteProtocol._async_idle_disconnect() running at /usr/local/lib/python3.12/site-packages/androidtvremote2/remote.py:198>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:12.361 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcba470>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:12.860 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcb8100>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:12.972 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c95f874f0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:13.087 WARNING (MainThread) [homeassistant.components.media_player] Updating samsungtv media_player took longer than the scheduled update interval 0:00:10
2024-04-10 09:15:13.136 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-10 09:15:13.137 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcba290>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1629957' coro=<RemoteProtocol._async_idle_disconnect() running at /usr/local/lib/python3.12/site-packages/androidtvremote2/remote.py:198>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:13.391 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-10 09:15:13.392 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c9fcbac50>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1629958' coro=<RemoteProtocol._async_idle_disconnect() running at /usr/local/lib/python3.12/site-packages/androidtvremote2/remote.py:198>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:13.392 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c95f86ef0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:13.593 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c95f87a00>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:13.711 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c95f87eb0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:15.361 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c3e063e80>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:15.448 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c4d69cd90>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:15.551 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c4d69d870>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-10 09:15:15.567 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x152c74963eb0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1629959' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.

Scope666 avatar Apr 10 '24 13:04 Scope666

I can confirm that my home assistant instance has not crashed and the the integration works with aws not disconnecting since making the following changes:

  • remove and re-add the integration
  • applied the change from @sh00t2kill with the new aws_client.py file

rybackisback avatar Apr 10 '24 23:04 rybackisback

Crashed again, this is the log at the exact moment the crash happens. (best I can tell)

2024-04-11 10:05:38.625 ERROR (Dummy-12) [custom_components.mydolphin_plus.managers.aws_client] AWS IoT connection interrupted, Error: AWS_ERROR_MQTT_UNEXPECTED_HANGUP: The connection was closed unexpectedly.
2024-04-11 10:05:38.625 ERROR (Dummy-12) [custom_components.mydolphin_plus.managers.aws_client] Status changed from 'Connected to the API' to 'Failed to access API'
2024-04-11 10:05:38.625 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback Task.task_wakeup(<Future finished result=None>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='SPA:Partial status block handler' coro=<GeckoUdpProtocolHandler.consume() running at /usr/local/lib/python3.12/site-packages/geckolib/driver/udp_protocol_handler.py:157> wait_for=<Future finished result=None>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 10:05:38.628 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback Task.task_wakeup(<Future finished result=None>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='SPA:RFErr handler' coro=<GeckoUdpProtocolHandler.consume() running at /usr/local/lib/python3.12/site-packages/geckolib/driver/udp_protocol_handler.py:157> wait_for=<Future finished result=None>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 10:05:38.628 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback Task.task_wakeup(<Future finished result=None>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='SPA:WCErr handler' coro=<GeckoUdpProtocolHandler.consume() running at /usr/local/lib/python3.12/site-packages/geckolib/driver/udp_protocol_handler.py:157> wait_for=<Future finished result=None>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 10:05:38.629 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback Task.task_wakeup(<Future finished result=None>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='SPAMAN:Sequence Pump' coro=<GeckoAsyncSpaMan._sequence_pump() running at /usr/local/lib/python3.12/site-packages/geckolib/async_spa_manager.py:545> wait_for=<Future finished result=None>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 10:05:38.629 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback Task.task_wakeup(<Future finished result=None>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)

EDIT: Removed the integration for now to see if the crashes stop or not.

EDIT2: Seems a lot of people are having crashing with HA 2024.4.x versions and custom components: https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+crash+label%3A%22non-thread-safe+operation%22

Scope666 avatar Apr 11 '24 14:04 Scope666

It is definitely an issue -- just not sure exactly what the fix is at this moment. I tihnk we have to wrap the requests to make them thread safe, but its likely an underlying library problem.

Its not crashing for me, but i am getting intermittent performance issues. Maybe it depends on how much compute is available when the black magic happens.

sh00t2kill avatar Apr 12 '24 00:04 sh00t2kill

From what I've been reading, it seems to be related to this. This is about another custom component (Arlo) that's having similar symptoms:

"This problem looks like its present in almost all the platforms. Using the async api in another thread is not thread safe, and any time that code is called it can crash HA."

https://docs.python.org/3/library/asyncio-dev.html#concurrency-and-multithreading

image

Scope666 avatar Apr 12 '24 00:04 Scope666

Yeah i think thats right. Just need to find the time to look at them. I found a similar example in alarmo.

sh00t2kill avatar Apr 12 '24 01:04 sh00t2kill

I've been running the patched version for 24hrs and just had homeassistant crash and restart. A number of these errors in the log:

RuntimeError: Cannot enter into task <Task pending name='Task-1508641' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:12.881 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b5e1e9750>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508642' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:13.614 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b51d5ab90>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.119 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-11 21:56:14.120 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-11 21:56:14.121 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-11 21:56:14.122 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-04-11 21:56:14.126 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b3e729cf0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508643' coro=<CatchingTaskMixin.catching_coro() running at /usr/local/lib/python3.12/site-packages/zigpy/util.py:313> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.142 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b477c9b70>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508644' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.253 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b52e81ae0>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.255 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b3546e020>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508645' coro=<CatchingTaskMixin.catching_coro() running at /usr/local/lib/python3.12/site-packages/zigpy/util.py:313> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.656 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b33ea4e20>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508646' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.657 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b39339270>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='Task-1508647' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.12/asyncio/selector_events.py:213>> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.
2024-04-11 21:56:14.777 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback <_asyncio.TaskStepMethWrapper object at 0x7f5b51d58880>()
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
RuntimeError: Cannot enter into task <Task pending name='listen state_changed' coro=<add_event_handlers.<locals>.async_on_state_changed() running at /config/custom_components/watchman/__init__.py:303> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:113>> is being executed.

As noted, these errors seem to come from async thread issues. If it's helpful I noticed @bdraco call out some examples from another lib here: https://github.com/home-assistant/core/issues/115060#issuecomment-2041605497

and some links to relevant docs: https://developers.home-assistant.io/docs/asyncio_working_with_async https://docs.python.org/3/library/asyncio-dev.html

matthewhadley avatar Apr 12 '24 03:04 matthewhadley

i can confirm that issue still persists even with patch and removing/adding integration back

thomasdelaet avatar Apr 12 '24 07:04 thomasdelaet

Same problem HA Crash asyncio

msaphoto06 avatar Apr 17 '24 19:04 msaphoto06

Pretty sure sh00t2kill is on the case, he just has to find the time. I haven't crashed since I removed MyDolphin so it's definitely the culprit for me.

Looking forward to testing any fixes because it really is handy to be able to see how much time is left on a cycle.

During the week I had an M400, I thought it was amazing that I could do things like "Floor Only" with this integration which the official app doesn't allow. I ended up having to switch to an M600 because the 400 was getting itself wedged between a stool and the wall. (long story, 600 is exactly 1/4" narrower which was just enough to solve the issue)

Scope666 avatar Apr 17 '24 20:04 Scope666

i started encountering this issue, I think i found the root cause, my direction is that once AWS IoT connection interrupted takes place, it tries to disconnect which kills the automatic reconnect, since it happens in non main thread and fail it leads to more and more failure up until it crashes the app due to limits of threads / connections....

in documentation of reconnect method of the AWS IoT library found:

awscrt.mqtt.ClientConnection automatically reconnects.
To cease reconnect attempts, call disconnect().

fix in my code is reducing more the terminate action:

async def terminate(self):
        if self._awsiot_client is not None:
            self._awsiot_client = None            

        self._set_status(ConnectivityStatus.Disconnected)
        _LOGGER.debug("AWS Client is disconnected")

and set the clean_session to False as we want it to automatically reconnect if possible

testing and will report back.

elad-bar avatar Apr 17 '24 21:04 elad-bar

@elad-bar do you have the changes somewhere in a branch and I can do some testing?

sh00t2kill avatar Apr 18 '24 01:04 sh00t2kill

I created new pre-release (beta) - v1.0.12b0 with that fix, HA seems to be much more stable since then. to use HACS to download that version, enable "Show beta versions", choose the relevant version, download, restart and report back :) image

thanks

elad-bar avatar Apr 18 '24 06:04 elad-bar

Have deployed it. Haven't had any cannot enter into task errors yet, and load averages staying pretty stable.

That's the first thing I noticed previously.

sh00t2kill avatar Apr 18 '24 07:04 sh00t2kill

I have also installed the beta, will report back on any crashes. Thanks so much for the quick fix!!! :)

image

Scope666 avatar Apr 18 '24 10:04 Scope666

Looking good so far RE performance. However the broker disconnect issue is potentially back :(

I am still getting some cannot enter into task errors. At first, I did not think they were strictly related to this integration, however i think there is an issue with dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL not completing.

Lots of errors similar to this, all referencing the same task. They don't start until the broker disconnected.

RuntimeError: Cannot enter into task <Task pending name='Entity schedule update ha state binary_sensor.study_blind_status' coro=<Entity.async_update_ha_state() running at /usr/src/homeassistant/homeassistant/helpers/entity.py:933> cb=[set.remove()]> while another task <Task pending name='dispatcher mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL' coro=<_async_wrapper() running at /usr/src/homeassistant/homeassistant/util/logging.py:115>> is being executed.

I then eventually get an exception,

2024-04-18 21:41:12.181 ERROR (Dummy-344) [homeassistant.util.logging] Exception in _on_aws_client_status_changed when dispatching 'mydolphin_plus_AWS_CLIENT_STATUS_SIGNAL': ('d1d9f283726648f34f594664a197119a', <ConnectivityStatus.Failed: 'Failed to access API'>)

and the cannot enter into task errors go away.

sh00t2kill avatar Apr 19 '24 00:04 sh00t2kill

So the fix is fine, until the broker disconnects.

At that point it holds the task and nothing new can execute. HA doesn't crash but states don't update in other integrations, even after the exception is thrown.

sh00t2kill avatar Apr 20 '24 12:04 sh00t2kill

released new pre-release version v1.0.12b1, running in my system for 6 hours, looks pretty stable, sharing to get more feedbacks.

In general reverted previous fix, and add thread safe handling for all calls of the AWS IoT SDK

elad-bar avatar Apr 22 '24 20:04 elad-bar

So far so good with b1 here, will report back if I see any issues. Thanks!!!!!

Scope666 avatar Apr 23 '24 00:04 Scope666

I deployed it to my production HA. Same issue as before, the only difference being it successfully reconnects.

It seems to hold on to a task somewhere, and stops other tasks from executing. I start seeing lots of xxx took longer than the scheduled update interview.

If i disable the integration and restart, it doesnt happen so its unfortunately being caused by this

sh00t2kill avatar Apr 23 '24 05:04 sh00t2kill

@sh00t2kill, just to confirm, with the latest versoin 12b1, it reconnects but creates timeouts on other components? can you pls set the logs to debug and share the log once it start take place?

thanks

elad-bar avatar Apr 23 '24 07:04 elad-bar

Yeah pretty much. It's a weird one.

sh00t2kill avatar Apr 23 '24 12:04 sh00t2kill

not weird, first I experienced the same in previous version, same after 12b0 that it fixed it but reconnect stopped working, but now it works smooth.

In general, what I read yesterday about the root cause, when the application is working with asyncio and within it create handlers working in future, it should be managed in a way that will sync the threads safely, although working with Future is unsafe thread invocation.

12b1 is managing it much better but since it's not working for you, I would like to understand from the log the sequence to understand what is wrong.

elad-bar avatar Apr 23 '24 16:04 elad-bar

anyone else tried that beta version? @sh00t2kill, any progress with logs?

thanks

elad-bar avatar Apr 25 '24 05:04 elad-bar

I've been away, will be a few days

sh00t2kill avatar Apr 25 '24 05:04 sh00t2kill