8000 Homekit controller can still get stuck in _find_data_for_device_id / not using shared zeroconf · Issue #38668 · home-assistant/core · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

Homekit controller can still get stuck in _find_data_for_device_id / not using shared zeroconf #38668

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
bdraco opened this issue Aug 8, 2020 · 10 comments · Fixed by #38678 or #38679
Closed

Comments

@bdraco
Copy link
Member
bdraco commented Aug 8, 2020

The problem

We thought we got them all in #37691 (reported via https://community.home-assistant.io/t/python3-high-cpu-usage/160012/26) but it appears something still needs to be found
https://community.home-assistant.io/t/high-cpu-usage-after-0-113/214655/25?u=bdraco

Screen Shot 2020-08-08 at 9 06 21 AM

https://alexander.koston.org:8123/local/cpu.svg
zeroconf swamping the event loop
Screen Shot 2020-08-08 at 9 06 56 AM

Environment

  • Home Assistant Core release with the issue:
  • Last working Home Assistant Core release (if known):
  • Operating environment (OS/Container/Supervised/Core):
  • Integration causing this issue:
  • Link to integration documentation on our website:

Problem-relevant configuration.yaml

Traceback/Error logs

bash-5.0# ./py-spy dump --pid 208
Process 208: python3 -m homeassistant --config /config
Python v3.8.3 (/usr/local/bin/python3.8)

Thread 0x55776CFBE8B0 (idle): "MainThread"
    select (selectors.py:468)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    run_until_complete (asyncio/base_events.py:603)
    run (asyncio/runners.py:43)
    run (homeassistant/runner.py:119)
    main (homeassistant/__main__.py:312)
    <module> (homeassistant/__main__.py:320)
    _run_code (runpy.py:87)
    _run_module_as_main (runpy.py:194)
Thread 230 (idle): "Thread-1"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 231 (idle): "SyncWorker_0"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 232 (idle): "SyncWorker_1"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 233 (idle): "SyncWorker_2"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 234 (idle): "SyncWorker_3"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 235 (idle): "SyncWorker_4"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 236 
8000
(idle): "SyncWorker_5"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 237 (idle): "SyncWorker_6"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 238 (idle): "SyncWorker_7"
    wait (threading.py:306)
    wait (threading.py:558)
    _find_data_for_device_id (aiohomekit/zeroconf/__init__.py:253)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 241 (idle): "Recorder"
    wait (threading.py:302)
    get (queue.py:170)
    run (homeassistant/components/recorder/__init__.py:338)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 242 (idle): "Thread-2"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 244 (active): "zeroconf-Engine-244"
    update_record (netdisco/mdns.py:21)
    update_record (zeroconf/__init__.py:2622)
    handle_response (zeroconf/__init__.py:2662)
    handle_read (zeroconf/__init__.py:1405)
    run (zeroconf/__init__.py:1314)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7FD1B6355B20 (active): "zeroconf-Reaper_245"
    entries (zeroconf/__init__.py:1270)
    run (zeroconf/__init__.py:1426)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 275 (idle): "zeroconf-ServiceBrowser__hap._tcp.local.-_printer._tcp.local.-_miio._udp.local.-_api._udp.local.-_spotify-connect._tcp.local.-_daap._tcp.local.-_esphomelib._tcp.local.-_ipp._tcp.local.-_nut._tcp.local.-_Volumio._tcp.local.-_ipps._tcp.local.-_googlecast._tcp.local.-_bond._tcp.local.-_axis-video._tcp.local.-_dkapi._tcp.local.-_wled._tcp.local.-_plugwise._tcp.local.-_elg._tcp.local.-_viziocast._tcp.local._275"
    send (zeroconf/__init__.py:2826)
    run (zeroconf/__init__.py:1673)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 276 (idle): "Thread-33"
    send_events (pyhap/accessory_driver.py:483)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 277 (idle): "Thread-34"
    select (selectors.py:415)
    serve_forever (socketserver.py:232)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 279 (idle): "Thread-36"
    send_events (pyhap/accessory_driver.py:483)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 280 (idle): "Thread-37"
    select (selectors.py:415)
    serve_forever (socketserver.py:232)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11752 (idle): "zeroconf-Engine-11752"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11753 (idle): "zeroconf-Reaper_11753"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11754 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11754"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11755 (idle): "zeroconf-Engine-11755"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11756 (idle): "zeroconf-Reaper_11756"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11757 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11757"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11758 (idle): "zeroconf-Engine-11758"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11759 (idle): "zeroconf-Reaper_11759"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11760 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11760"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11761 (idle): "zeroconf-Engine-11761"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11762 (idle): "zeroconf-Reaper_11762"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11763 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11763"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11764 (idle): "zeroconf-Engine-11764"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11765 (idle): "zeroconf-Reaper_11765"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11766 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11766"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11767 (active): "zeroconf-Engine-11767"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11768 (idle): "zeroconf-Reaper_11768"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11769 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11769"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11770 (active): "zeroconf-Engine-11770"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11771 (idle): "zeroconf-Reaper_11771"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11772 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11772"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11773 (idle): "zeroconf-Engine-11773"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11774 (idle): "zeroconf-Reaper_11774"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 11775 (idle): "zeroconf-ServiceBrowser__hap._tcp.local._11775"
    send (zeroconf/__init__.py:2826)
    run (zeroconf/__init__.py:1673)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

Additional information

@probot-home-assistant
Copy link

homekit_controller documentation
homekit_controller source
(message by IssueLinks)

@probot-home-assistant
Copy link

Hey there @Jc2k, mind taking a look at this issue as its been labeled with an integration (homekit_controller) you are listed as a codeowner for? Thanks!
(message by CodeOwnersMention)

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020
2020-08-08 18:58:49 ERROR (SyncWorker_5) [root] _find_data_for_device_id: device_id=16:D9:5C:D4:88:00, max_seconds=10, zeroconf_instance=None
Stack (most recent call last):
  File "/usr/local/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/zeroconf/__init__.py", line 253, in _find_data_for_device_id
    logging.error(

Definitely being called without the instance

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020
2020-08-08 19:02:40 ERROR (MainThread) [root] async_find_device_ip_and_port: device_id=48:B4:E0:75:3E:E8, max_seconds=10, zeroconf_instance=None
Stack (most recent call last):
  File "/usr/local/lib/python3.8/runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.8/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 320, in <module>
    sys.exit(main())
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 312, in main
    exit_code = runner.run(runtime_conf)
  File "/usr/src/homeassistant/homeassistant/runner.py", line 119, in run
    return asyncio.run(setup_and_run_hass(runtime_config))
  File "/usr/local/lib/python3.8/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 603, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 570, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 1859, in _run_once
    handle._run()
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 475, in _reconnect
    return await self._connect_once()
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 533, in _connect_once
    self.host, self.port = await async_find_device_ip_and_port(
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/zeroconf/__init__.py", line 286, in async_find_device_ip_and_port
    logging.error(

Its being called from here

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020
diff --git a/homeassistant/components/homekit_controller/__init__.py b/homeassistant/components/homekit_controller/__init__.py
index 47f3cf2057..4a8730b2e9 100644
--- a/homeassistant/components/homekit_controller/__init__.py
+++ b/homeassistant/components/homekit_controller/__init__.py
@@ -11,6 +11,7 @@ from aiohomekit.model.characteristics import (
 )
 from aiohomekit.model.services import Service, ServicesTypes
 
+from homeassistant.components import zeroconf
 from homeassistant.exceptions import ConfigEntryNotReady
 from homeassistant.helpers import device_registry as dr
 from homeassistant.helpers.entity import Entity
@@ -212,7 +213,8 @@ async def async_setup(hass, config):
     map_storage = hass.data[ENTITY_MAP] = EntityMapStorage(hass)
     await map_storage.async_initialize()
 
-    hass.data[CONTROLLER] = aiohomekit.Controller()
+    zeroconf_instance = await zeroconf.async_get_instance(hass)
+    hass.data[CONTROLLER] = aiohomekit.Controller(zeroconf_instance=zeroconf_instance)
     hass.data[KNOWN_DEVICES] = {}
 
     return True

Should fix it with a PR here #38678

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020

Tracked down why its calling async_find_device_ip_and_port so often: Its re-setting up my iDevices Switch over and over because of this

2020-08-08 19:20:38 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry iDevices Switch for homekit_controller
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 222, in async_setup
    result = await component.async_setup_entry(  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/__init__.py", line 189, in async_setup_entry
    if not await conn.async_setup():
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 145, in async_setup
    if await self.async_refresh_entity_map(self.config_num):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 217, in async_refresh_entity_map
    self.entity_map = Accessories.from_list(self.accessories)
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/model/__init__.py", line 259, in from_list
    self.add_accessory(Accessory.create_from_dict(accessory))
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/model/__init__.py", line 190, in create_from_dict
    "format": char_data["format"],
KeyError: 'format'

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020
2020-08-08 19:26:09 ERROR (MainThread) [root] Service_Data: {'iid': 1, 'type': '0000003E-0000-1000-8000-0026BB765291', 'characteristics': [{'iid': 2, 'type': '00000023-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': 'iDevices Switch'}, {'iid': 3, 'type': '00000020-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': 'iDevices LLC'}, {'iid': 4, 'type': '00000021-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': 'IDEV0001'}, {'iid': 5, 'type': '00000030-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': '00080685'}, {'iid': 6, 'type': '00000014-0000-1000-8000-0026BB765291', 'perms': ['pw']}, {'iid': 7, 'type': '00000052-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': '1.2.1'}, {'iid': 8, 'type': '00000053-0000-1000-8000-0026BB765291', 'perms': ['pr'], 'value': '1'}]}
2020-08-08 19:26:09 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry iDevices Switch for homekit_controller
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 222, in async_setup
    result = await component.async_setup_entry(  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/__init__.py", line 189, in async_setup_entry
    if not await conn.async_setup():
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 145, in async_setup
    if await self.async_refresh_entity_map(self.config_num):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 217, in async_refresh_entity_map
    self.entity_map = Accessories.from_list(self.accessories)
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/model/__init__.py", line 261, in from_list
    self.add_accessory(Accessory.create_from_dict(accessory))
  File "/usr/local/lib/python3.8/site-packages/aiohomekit/model/__init__.py", line 192, in create_from_dict
    "format": char_data["format"],
KeyError: 'format'

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020

Looks like format is optional?

diff --git a/aiohomekit/model/__init__.py b/aiohomekit/model/__init__.py
index 5efdb2c..a05422a 100644
--- a/aiohomekit/model/__init__.py
+++ b/aiohomekit/model/__init__.py
@@ -189,9 +189,9 @@ class Accessory(ToDictMixin):
             for char_data in service_data["characteristics"]:
                 kwargs = {
                     "perms": char_data["perms"],
-                    "format": char_data["format"],
                 }
-
+                if "format" in char_data:
+                    kwargs["format"] = char_data["format"]
                 if "description" in char_data:
                     kwargs["description"] = char_data["description"]
                 if "value" in char_data:

That should fix that issue Jc2k/aiohomekit#16 with a bump here #38679

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020

With the two changes, everything is working great now

@bdraco
Copy link
Member Author
bdraco commented Aug 8, 2020

I unplugged all my homekit devices that were linked to home assistant and no more cpu spikes

hahn-th pushed a commit to hahn-th/core that referenced this issue May 2, 2025
…e-assistant#38668)

Bumps [sorbet-runtime](https://github.com/sorbet/sorbet) from 0.5.12026 to 0.5.12028.
- [Release notes](https://github.com/sorbet/sorbet/releases)
- [Commits](https://github.com/sorbet/sorbet/commits)

---
updated-dependencies:
- dependency-name: sorbet-runtime
  dependency-version: 0.5.12028
  dependency-type: indirect
  update-type: version-update:semver-patch
...

Signed-off-by: dependabot[bot] <support@github.com>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
0