Handle unlikely error during put BLE
bdraco opened this issue · 2 comments
bdraco commented
Sep 26 05:21:23 homeassistant homeassistant[485]: 2022-09-25 19:21:23.654 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [281472644916480] [org.bluez.Error.Failed] Operation failed with ATT error: 0x0e (Unlikely Error)
Sep 26 05:21:23 homeassistant homeassistant[485]: Traceback (most recent call last):
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 200, in handle_call_service
Sep 26 05:21:23 homeassistant homeassistant[485]: await hass.services.async_call(
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/core.py", line 1738, in async_call
Sep 26 05:21:23 homeassistant homeassistant[485]: task.result()
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/core.py", line 1775, in _execute_service
Sep 26 05:21:23 homeassistant homeassistant[485]: await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 207, in handle_service
Sep 26 05:21:23 homeassistant homeassistant[485]: await service.entity_service_call(
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 678, in entity_service_call
Sep 26 05:21:23 homeassistant homeassistant[485]: future.result() # pop exception if have
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 931, in async_request_call
Sep 26 05:21:23 homeassistant homeassistant[485]: await coro
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 715, in _handle_entity_call
Sep 26 05:21:23 homeassistant homeassistant[485]: await result
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 557, in async_handle_light_off_service
Sep 26 05:21:23 homeassistant homeassistant[485]: await light.async_turn_off(**filter_turn_off_params(light, params))
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/components/homekit_controller/light.py", line 161, in async_turn_off
Sep 26 05:21:23 homeassistant homeassistant[485]: await self.async_put_characteristics({CharacteristicsTypes.ON: False})
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/components/homekit_controller/entity.py", line 91, in async_put_characteristics
Sep 26 05:21:23 homeassistant homeassistant[485]: return await self._accessory.put_characteristics(payload)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 616, in put_characteristics
Sep 26 05:21:23 homeassistant homeassistant[485]: results = await self.pairing.put_characteristics(characteristics)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 110, in _async_wrap
Sep 26 05:21:23 homeassistant homeassistant[485]: return await func(self, *args, **kwargs)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 76, in _async_wrap
Sep 26 05:21:23 homeassistant homeassistant[485]: return await func(*args, **kwargs)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 758, in put_characteristics
Sep 26 05:21:23 homeassistant homeassistant[485]: await self._populate_accessories_and_characteristics()
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 577, in _populate_accessories_and_characteristics
Sep 26 05:21:23 homeassistant homeassistant[485]: await self._async_pair_verify()
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 359, in _async_pair_verify
Sep 26 05:21:23 homeassistant homeassistant[485]: session_id, derive = await drive_pairing_state_machine(
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 258, in drive_pairing_state_machine
Sep 26 05:21:23 homeassistant homeassistant[485]: decoded = await _pairing_char_write(client, char, iid, request)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 212, in _pairing_char_write
Sep 26 05:21:23 homeassistant homeassistant[485]: data = await char_write(client, None, None, handle, iid, next_write)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 195, in char_write
Sep 26 05:21:23 homeassistant homeassistant[485]: pdu_status, data = await ble_request(
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 101, in ble_request
Sep 26 05:21:23 homeassistant homeassistant[485]: return await _read_pdu(client, decryption_key, handle, tid)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 137, in _read_pdu
Sep 26 05:21:23 homeassistant homeassistant[485]: data = await client.read_gatt_char(handle)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 482, in read_gatt_char
Sep 26 05:21:23 homeassistant homeassistant[485]: return await self._backend.read_gatt_char(char_specifier, **kwargs)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/client.py", line 601, in read_gatt_char
Sep 26 05:21:23 homeassistant homeassistant[485]: assert_reply(reply)
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
Sep 26 05:21:23 homeassistant homeassistant[485]: raise BleakDBusError(reply.error_name, reply.body)
Sep 26 05:21:23 homeassistant homeassistant[485]: bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Operation failed with ATT error: 0x0e (Unlikely Error)
bdraco commented
It looks like it should already be retried.
Of course I can't get it to happen again with debug logging on :(
bdraco commented
So this one is going through the retry wrapper already
Sep 26 05:21:23 homeassistant homeassistant[485]: File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/client.py", line 76, in _async_wrap
The issue is that the device is dropping the connection so the retry doesn't help because it just fails when we try again.
We need to implement a back off like we do in bleak-retry-connector to all time for the disconnected callback to fire