core: Homekit device fails to update sensor entities after connection times out

The problem

I originally started this as a forum posting, which contains some additional information.

Fundamentally, the issue is that a HomeKit thermostat (Mysa AC) sometimes stops logging state changes into Home Assistant, leading to charts that look like the following, where the values for temperature and humidity just stop:

Curiously, the device continues getting logged to a connected InfluxDB instance via the built-in influxdb integration, meaning I can see the updated values in a separate Grafana dashboard (notice the corresponding ramp up in humidity values between 11:30PM and 1:00 AM):

With debug logging, I have tracked down the issue to a Homekit device that loses connection. Attached below are the HA logs filtered for this thermostat’s IP (xxx.xxx.30.113) and/or its identifier (93:A8:5B:xx:xx:xx). It appears that at 01:02:46, HA lost connection to the thermostat, but it then regained connection since it received data once again at 01:03:51.059, but those values (and all subsequent ones) are not saved into HA as state changes, even though they are sent to InfluxDB. So something about this “hiccup” causes it to stop logging entirely, even though it’s still receiving information.

2023-10-18 01:02:46.790 ERROR (MainThread) [aiohomekit.utils] Failure running background task: Task-375786
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 138, in _ensure_connected
    await connection.ensure_connection()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 293, in ensure_connection
    await asyncio.shield(self._connector)
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 137, in _ensure_connected
    async with asyncio_timeout(10):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/utils.py", line 40, in _handle_task_result
    task.result()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 415, in _process_config_changed
    await self.list_accessories_and_characteristics()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 176, in list_accessories_and_characteristics
    await self._ensure_connected()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 144, in _ensure_connected
    raise AccessoryDisconnectedError(
aiohomekit.exceptions.AccessoryDisconnectedError: Timeout while waiting for connection to device xxx.xxx.30.113:57959
2023-10-18 01:03:00.378 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x01
  3 (PublicKey): (32 bytes/<class 'bytes'>) b'1e\xf47V \x1aH4\x84^\x8c0\xd2\r\x8c\xf4\t\x0b\xdcy\xd6\xcb#\x90k\xad\x8e\xa7\x05\x13q'
]

2023-10-18 01:03:05.771 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: xxx.xxx.30.113\r\nContent-Length: 37\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x01\x03 \xdc\xcc\xa0\xbex\xfb?(\x1f\xb8\xa2\xcc2\xf1\x1c \x10AOI\x8c\x04\xef\xf1\xf6\xa1T\xf5\xe7\xbe\x9bX'
2023-10-18 01:03:05.772 ERROR (MainThread) [aiohomekit.utils] Failure running background task: Task-375784
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 91, in send_bytes
    return await result
           ^^^^^^^^^^^^
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 90, in send_bytes
    async with asyncio_timeout(30):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/utils.py", line 40, in _handle_task_result
    task.result()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 415, in _process_config_changed
    await self.list_accessories_and_characteristics()
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/pairing.py", line 178, in list_accessories_and_characteristics
    response = await self.connection.get_json("/accessories")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 327, in get_json
    response = await self.get(target)
               ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 321, in get
    return await self.request(
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 476, in request
    resp = await self.protocol.send_bytes(request_bytes)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 158, in send_bytes
    return await super().send_bytes(b"".join(buffer))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohomekit/controller/ip/connection.py", line 95, in send_bytes
    raise AccessoryDisconnectedError("Timeout while waiting for response")
aiohomekit.exceptions.AccessoryDisconnectedError: Timeout while waiting for response
2023-10-18 01:03:06.274 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw response: bytearray(b'\x06\x01\x02\x03 \xc6\xe6\xc5\xb03\xfb\x88 \x01P\\"\x98\xec\x9e\x14\xa0\xd3\xeb\x01\x1bC\x7f\x9f2Y\x878\x0e^*\x02\x05e\xa3\x13\xb2\x14q\xe3SC\x82\xd7\x1bH\x81\xe1|\x92EG\xbbP\xf7U\xebC\x99\x13\ra\x0e\xb0x\x85[\xa4\xb7\xa7\x071N_\xd6R\x1d\xa1/\x85x\xbe_\xeb\x88\x9dy\x94B/\x9a\n~9\xf1\x9c\x803\x9f\x96\x12\x92\xdf\x1d\x00t$\xe8\xc0^\xb8\x81ZfK\xe9\x10Pb\xb5g\xd2\x05\xef\xdc\x8b\xcca\xe1x\x1e\xb8\xafj\xc4')
2023-10-18 01:03:06.275 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x02
  3 (PublicKey): (32 bytes/<class 'bytearray'>) 0xc6e6c5b033fb882001505c2298ec9e14a0d3eb011b437f9f325987380e5e2a02
  5 (EncryptedData): (101 bytes/<class 'bytearray'>) 0xa313b21471e3534382d71b4881e17c924547bb50f755eb4399130d610eb078855ba4b7a707314e5fd6521da12f8578be5feb889d7994422f9a0a7e39f19c80339f961292df1d007424e8c05eb8815a664be9105062b567d205efdc8bcc61e1781eb8af6ac4
]

2023-10-18 01:03:06.322 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1 (Identifier): (17 bytes/<class 'bytearray'>) 0x39333a41383a35423a46463a46303a3233
  10 (Signature): (64 bytes/<class 'bytearray'>) 0xca6910c84530a784983ba5e7bd24e72b62344ad55a8ebfd295f9a6fbdd2c94c7f0b499276b0db97d52aaeb6ee206b4a7decbf1e67f3e1e49be0c29fa120ac709
]

2023-10-18 01:03:06.323 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (36 bytes/<class 'bytes'>) b'a8699a5b-c0f3-4e78-9671-67a69b5550c8'
  10 (Signature): (64 bytes/<class 'bytes'>) b'\x13z\xebZ|d\xc8G\xce8\xf5y\x03\xee\xcf$\x06Z9\xf1\'\x07\x86\x0e\x0e\nK\xd077:o\xe5\\\xe7\x16\xbeV.\xce\xde%"\x98\xa5C\xc0\xe7\xde\x7f\x9f.\xad\x8e\xc3B:\xab5\xbf\x9e~=\x08'
]

2023-10-18 01:03:06.325 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x03
  5 (EncryptedData): (120 bytes/<class 'bytes'>) b'\n}\x92\r\x12\x1a\xa7\xb3m\x08\x0eL\x9b\xc94\xf1\x8b\x987`\xbarC\xa3\xb9\x1b\x8e\xcf\x85b\xc9\xbdqw\x10o\xff[\x84\x10\x06\x18\x12\x19\x1c\x11\xf4\xe7\xdb\xd1m[\x0c\x0b\x17\x9b\xc2\x93\x87\x80\x81\xddlYSF\xe3\xb0\xb9\x84\x1e\r\xfc\xecX\x8e=\xe8\xeaeo\x10ug?\xbd\xa4\xe0-\x1fC\x0f5\x8a\xac\xe2\x81\xe7\xb4~\xb2P\xec\x9a\xfc\xa81"\xe35\x15.b~^\xda\xed2ob'
]

2023-10-18 01:03:06.325 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: xxx.xxx.30.113\r\nContent-Length: 125\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x03\x05x\n}\x92\r\x12\x1a\xa7\xb3m\x08\x0eL\x9b\xc94\xf1\x8b\x987`\xbarC\xa3\xb9\x1b\x8e\xcf\x85b\xc9\xbdqw\x10o\xff[\x84\x10\x06\x18\x12\x19\x1c\x11\xf4\xe7\xdb\xd1m[\x0c\x0b\x17\x9b\xc2\x93\x87\x80\x81\xddlYSF\xe3\xb0\xb9\x84\x1e\r\xfc\xecX\x8e=\xe8\xeaeo\x10ug?\xbd\xa4\xe0-\x1fC\x0f5\x8a\xac\xe2\x81\xe7\xb4~\xb2P\xec\x9a\xfc\xa81"\xe35\x15.b~^\xda\xed2ob'
2023-10-18 01:03:06.514 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw response: bytearray(b'\x06\x01\x04')
2023-10-18 01:03:06.514 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x04
]

2023-10-18 01:03:06.515 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to xxx.xxx.30.113:57959 established
2023-10-18 01:03:06.515 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2023-10-18 01:03:06.515 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 93:A8:5B:xx:xx:xx
2023-10-18 01:03:06.515 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 93:A8:5B:xx:xx:xx
2023-10-18 01:03:06.516 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: xxx.xxx.30.113\r\nContent-Length: 263\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":1,"iid":272,"ev":true},{"aid":1,"iid":1027,"ev":true},{"aid":1,"iid":261,"ev":true},{"aid":1,"iid":262,"ev":true},{"aid":1,"iid":259,"ev":true},{"aid":1,"iid":1026,"ev":true},{"aid":1,"iid":260,"ev":true},{"aid":1,"iid":263,"ev":true}]}'
2023-10-18 01:03:06.549 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw response: bytearray(b'')
2023-10-18 01:03:50.927 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 93:A8:5B:xx:xx:xx
2023-10-18 01:03:50.927 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw request: b'GET /characteristics?id=1.272,1.262,1.1027,1.259,1.261,1.1026,1.260,1.263 HTTP/1.1\r\nHost: xxx.xxx.30.113\r\n\r\n'
2023-10-18 01:03:51.059 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw response: bytearray(b'{"characteristics":[{"aid":1,"iid":272,"value":35},{"aid":1,"iid":262,"value":25.5},{"aid":1,"iid":1027,"value":0},{"aid":1,"iid":259,"value":0},{"aid":1,"iid":261,"value":21.9},{"aid":1,"iid":1026,"value":0},{"aid":1,"iid":260,"value":0},{"aid":1,"iid":263,"value":1}]}')
2023-10-18 01:03:51.059 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 93:A8:5B:xx:xx:xx
2023-10-18 01:03:51.060 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Finished HomeKit device update: 93:A8:5B:xx:xx:xx

Reloading the device via the integrations page appears to resolve the issue temporarily, until the next time the device times out:

Any ideas what’s going on here?

What version of Home Assistant Core has the issue?

core-2023.10.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

homekit_controller

Link to integration documentation on our website

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

Diagnostics information

config_entry-homekit_controller-b475198185de7c629665b7429a54105a.json.txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

See above.

Additional information

No response