home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
69.88k stars 28.97k forks source link

Gardena Bluetooth Irrigation Bluetooth connection is unreliable #103117

Closed alistair23 closed 2 weeks ago

alistair23 commented 8 months ago

The problem

This is somewhat similar to https://github.com/home-assistant/core/issues/98561 in that the Bluetooth connection disconnects when using an ESPHome Bluetooth proxy. The connection stays up for a few days, but eventually the Gardena device becomes unavailable.

Once the device has become unavailable it won't reappear until I remove and reinsert the battery from the device.

That doesn't always work though. The attached log in the issue is while I power cycle the Gardena device but it doesn't reconnect in the HA UI.

The ESPHome device is located very close to the Gardena Bluetooth controller, but it is a long distance from the WiFi access point. I am working on hard wiring it encase that is the issue.

What version of Home Assistant Core has the issue?

core-2023.10.5

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

gardena_bluetooth

Link to integration documentation on our website

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

Diagnostics information

logs_esp32-bluetooth-proxy_logs.txt

ha.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2023-10-27 10:07:48.474 WARNING (MainThread) [homeassistant.components.sensor] Entity sensor.esp32_bluetooth_proxy_front_soil_moisture (<class 'homeassistant.components.esphome.sensor.EsphomeSensor'>) is using native unit of measurement '%' which is not a valid unit for the device class ('voltage') it is using; expected one of ['mV', 'V']; Please update your configuration if your entity is manually configured, otherwise create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+esphome%22

2023-10-27 15:08:18.153 WARNING (MainThread) [aioesphomeapi.connection] esp32-bluetooth-proxy @ 172.16.2.8: Connection error occurred: [Errno 104] Connection reset by peer

2023-10-31 08:41:34.553 WARNING (Recorder) [homeassistant.components.esphome.bluetooth.client] Bluetooth 
Proxy 3daf64 [e0:e2:e6:3d:af:64]: None - E4:E1:12:FF:A3:E0: ESPHomeClient bleak client was not properly d
isconnected before destruction


### Additional information

_No response_
home-assistant[bot] commented 8 months ago

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

Code owner commands Code owners of `gardena_bluetooth` 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 gardena_bluetooth` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


gardena_bluetooth documentation gardena_bluetooth source (message by IssueLinks)

elupus commented 8 months ago

Your logs above indicate that the proxy disconnects. Also looks like the proxy is exposing some soil moisture data?? You are not connecting using the esp device to the gardena too?

alistair23 commented 8 months ago

The proxy isn't being power cycled or anything. It does seem like the WiFi connection resets, do you think that is causing the Bluetooth to disconnect and then not reconnect?

The ESPHome device is also measuring the soil moisture. It's unrelated to the Gardena integration

The Gardena device is connecting via the Bluetooth proxy as well

elupus commented 8 months ago

I suspect something goes wrong if we are connected to the gardena device and the esp proxy restarts/disconnects.

alistair23 commented 7 months ago

I have now setup a second wired ESP proxy device to prevent proxy disconnects, but still the Gardena device is disconnecting after a few days

elupus commented 7 months ago

Annoying. Unsure how to find out the cause.

alistair23 commented 7 months ago

This is some relevant parts of the log

2023-12-09 12:55:40.586 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Timeout fetching 
Gardena Bluetooth Data Update Coordinator data
2023-12-09 12:55:40.721 WARNING (MainThread) [asyncio] Executing <Task finished name='DataUpdateCoordinat
or Coordinator Gardena Bluetooth Data Update Coordinator Gardena Water Computer gardena_bluetooth 1152767
35f3923d1ea8672716fc30759' coro=<DataUpdateCoordinator._handle_refresh_interval() done, defined at /usr/s
rc/homeassistant/homeassistant/helpers/update_coordinator.py:240> result=None created at /usr/src/homeass
istant/homeassistant/core.py:568> took 0.138 seconds
2023-12-09 13:01:21.407 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Gardena Bluetooth - E4:E1:12:FF:A3:E0: Failed to connect after 11 attempt(s): No backend with an avai
lable connection slot that can reach address E4:E1:12:FF:A3:E0 was found: The proxy/adapter is out of con
nection slots or the device is no longer reachable; Add additional proxies (https://esphome.github.io/blu
etooth-proxies/) near this device
2023-12-09 13:01:21.412 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Ga
rdena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0013-0b0e-421a-84e5-ddbf75dc6
de4 due to Communcation failed with device: Gardena Bluetooth - E4:E1:12:FF:A3:E0: Failed to connect afte
r 11 attempt(s): No backend with an available connection slot that can reach address E4:E1:12:FF:A3:E0 wa
s found: The proxy/adapter is out of connection slots or the device is no longer reachable; Add additiona
l proxies (https://esphome.github.io/bluetooth-proxies/) near this device
...
2023-12-09 18:03:47.095 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 error=17 description=Insufficient resources
2023-12-09 18:03:47.136 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Ga
rdena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0013-0b0e-421a-84e5-ddbf75dc6
de4 due to Communcation failed with device: Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 erro
r=17 description=Insufficient resources
...
2023-12-09 18:06:27.797 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 error=17 description=Insufficient resources
2023-12-09 18:06:27.802 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Ga
rdena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0013-0b0e-421a-84e5-ddbf75dc6
de4 due to Communcation failed with device: Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 erro
r=17 description=Insufficient resources
2023-12-09 18:07:49.533 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 error=17 description=Insufficient resources
2023-12-09 18:08:51.986 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 error=17 description=Insufficient resources
...
2023-12-09 19:13:27.534 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Bluetooth GATT Error address=E4:E1:12:FF:A3:E0 handle=28 error=133 description=Error
2023-12-09 19:21:50.410 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Peripheral E4:E1:12:FF:A3:E0 changed connection status while waiting for BluetoothGATTReadResponse, B
luetoothGATTErrorResponse: Insufficient authorization (8)
2023-12-09 19:23:15.051 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Peripheral E4:E1:12:FF:A3:E0 changed connection status while waiting for BluetoothGATTReadResponse, B
luetoothGATTErrorResponse: Insufficient authorization (8)
...
2023-12-09 21:27:19.795 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Gardena Bluetooth - E4:E1:12:FF:A3:E0: Failed to connect after 9 attempt(s): No backend with an avail
able connection slot that can reach address E4:E1:12:FF:A3:E0 was found: The proxy/adapter is out of conn
ection slots or the device is no longer reachable; Add additional proxies (https://esphome.github.io/blue
tooth-proxies/) near this device
2023-12-09 21:30:50.926 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Peripheral E4:E1:12:FF:A3:E0 changed connection status while waiting for BluetoothGATTReadResponse, B
luetoothGATTErrorResponse: Unknown error (22)
2023-12-09 21:35:27.458 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Gardena Bluetooth - E4:E1:12:FF:A3:E0: Failed to connect after 4 attempt(s): Timeout waiting for conn
ect response while connecting to E4:E1:12:FF:A3:E0 after 20.0s, disconnect timed out: False,  after 20.0s

and from the ESP side

2023-12-09 08:17:56.968 WARNING (MainThread) [asyncio] Executing <Task pending name='olimex-water-ble-pro
xy @ 172.16.1.26: aioesphomeapi do_connect' coro=<APIConnection._do_connect() running at aioesphomeapi/co
nnection.py:None> wait_for=<Future pending cb=[BaseSelectorEventLoop._sock_write_done(37, handle=<Handle 
BaseS...events.py:297>)(), Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.p
y:427> cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.134 seco
nds
    async with self.session.get(f'http://{self._device_ip}/{resource}') as resp:
    self._resp = await self._coro
    await resp.start(conn)
    async with self.session.get(f'http://{self._device_ip}/{resource}') as resp:
    self._resp = await self._coro
    await resp.start(conn)
2023-12-09 10:54:01.586 WARNING (MainThread) [asyncio] Executing <Task finished name='Task-1834881' coro=
<AsyncClient.sync() done, defined at /usr/local/lib/python3.11/site-packages/nio/client/base_client.py:10
0> result=SyncResponse(...ata_events=[]) created at /usr/local/lib/python3.11/asyncio/tasks.py:680> took 
0.113 seconds
    async with self.session.get(f'http://{self._device_ip}/{resource}') as resp:
    self._resp = await self._coro
    await resp.start(conn)
2023-12-09 12:54:53.313 WARNING (MainThread) [aioesphomeapi.connection] esp32-bluetooth-proxy @ 172.16.2.
8: Connection error occurred: esp32-bluetooth-proxy @ 172.16.2.8: EOF received
2023-12-09 12:57:03.701 WARNING (MainThread) [aioesphomeapi.connection] esp32-bluetooth-proxy @ 172.16.2.
8: Connection error occurred: Ping response not received after 90.0 seconds
2023-12-09 13:00:44.533 WARNING (MainThread) [aioesphomeapi.connection] esp32-bluetooth-proxy @ 172.16.2.
8: Connection error occurred: Ping response not received after 90.0 seconds
2023-12-09 13:01:02.630 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting dev
ice info for 172.16.2.8: Timeout waiting for DeviceInfoResponse after 10.0s
2023-12-09 13:01:12.649 ERROR (MainThread) [aioesphomeapi.connection] esp32-bluetooth-proxy @ 172.16.2.8:
 disconnect request failed: Timeout waiting for DisconnectResponse after 10.0s
2023-12-09 13:01:21.407 WARNING (MainThread) [gardena_bluetooth.client] Unexpected disconnection from dev
ice Gardena Bluetooth - E4:E1:12:FF:A3:E0: Failed to connect after 11 attempt(s): No backend with an avai
lable connection slot that can reach address E4:E1:12:FF:A3:E0 was found: The proxy/adapter is out of con
nection slots or the device is no longer reachable; Add additional proxies (https://esphome.github.io/blu
etooth-proxies/) near this device
alistair23 commented 7 months ago

Some more logs from the ESPHome proxy

[20:25:18][D][esp32_ble_tracker:266]: Starting scan...
[20:25:24][I][esp32_ble_client:086]: [0] [E4:E1:12:FF:A3:E0] Disconnecting.
[20:25:24][D][esp-idf:000]: W (211893) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13

[20:25:24][D][esp-idf:000]: W (211895) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[20:25:24][D][esp-idf:000]: W (211897) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16

[20:25:24][D][esp-idf:000]: W (211898) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16

[20:25:24][D][esp-idf:000]: W (211906) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[20:26:19][I][bluetooth_proxy:278]: [0] [E4:E1:12:FF:A3:E0] Connecting v3 with cache
[20:26:19][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[20:26:19][I][esp32_ble_client:069]: [0] [E4:E1:12:FF:A3:E0] 0x00 Attempting BLE connection
[20:26:39][I][esp32_ble_client:086]: [0] [E4:E1:12:FF:A3:E0] Disconnecting.
[20:26:49][D][esp-idf:000]: W (296898) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100

[20:26:49][D][esp-idf:000]: W (296903) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100

[20:26:49][D][esp-idf:000]: W (296904) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100

[20:26:49][W][esp32_ble_client:139]: [0] [] Connection failed, status=133

and

[bluetooth_proxy:268]: [0] [E4:E1:12:FF:A3:E0] Connection request ignored, device is disconnecting
alistair23 commented 7 months ago

Some verbose logs

[22:52:15][W][component:214]: Component esp32_ble took a long time for an operation (0.45 s).
[22:52:15][W][component:215]: Components should block for at most 20-30ms.
[22:52:18][V][esp32_ble:314]: (BLE) gap_event_handler - 20
[22:52:59][I][bluetooth_proxy:278]: [0] [E4:E1:12:FF:A3:E0] Connecting v3 with cache
[22:52:59][V][bluetooth_proxy:100]: [0] Used connection by [E4:E1:12:FF:A3:E0]
[22:52:59][V][bluetooth_proxy:097]: [1] Free connection
[22:52:59][V][bluetooth_proxy:097]: [2] Free connection
[22:52:59][I][esp32_ble_client:069]: [0] [E4:E1:12:FF:A3:E0] 0x00 Attempting BLE connection
[22:52:59][V][esp-idf:000]: W (676381) BT_GATT: gatt_connect wrong state 4

[22:52:59][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[22:52:59][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=2 gattc_if=3
[22:52:59][V][esp32_ble_client:134]: [0] [E4:E1:12:FF:A3:E0] ESP_GATTC_OPEN_EVT
[22:52:59][I][esp32_ble_client:149]: [0] [E4:E1:12:FF:A3:E0] Connected
[22:52:59][V][bluetooth_proxy:100]: [0] Used connection by [E4:E1:12:FF:A3:E0]
[22:52:59][V][bluetooth_proxy:097]: [1] Free connection
[22:52:59][V][bluetooth_proxy:097]: [2] Free connection
[22:52:59][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 115
[22:52:59][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 18
[22:52:59][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=18 gattc_if=3
[22:52:59][V][esp32_ble_client:165]: [0] [E4:E1:12:FF:A3:E0] cfg_mtu status 0, mtu 247
[22:53:00][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:00][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:00][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 110
[22:53:00][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:00][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:00][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 113
[22:53:00][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:00][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:00][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 41
[22:53:00][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:00][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:01][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 32
[22:53:01][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:01][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:01][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 45
[22:53:01][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:01][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:01][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 28
[22:53:01][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:01][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:01][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 25
[22:53:01][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:01][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:02][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 30
[22:53:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:02][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:02][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 22
[22:53:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:02][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:02][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 107
[22:53:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:02][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:03][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 34
[22:53:03][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:03][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:03][V][bluetooth_proxy.connection:180]: [0] [E4:E1:12:FF:A3:E0] Reading GATT characteristic handle 47
[22:53:03][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 3
[22:53:03][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=3 gattc_if=3
[22:53:08][I][esp32_ble_client:086]: [0] [E4:E1:12:FF:A3:E0] Disconnecting.
[22:53:08][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 5
[22:53:08][V][esp32_ble_client:119]: [0] [E4:E1:12:FF:A3:E0] gattc_event_handler: event=5 gattc_if=3
[22:54:03][W][bluetooth_proxy:268]: [0] [E4:E1:12:FF:A3:E0] Connection request ignored, device is disconnecting

It seems like the disconnecting isn't working

alistair23 commented 7 months ago

I have a theory

From the logs it seems like this line is the problem: Connection request ignored, device is disconnecting

Once we disconnect from the device for too long we can't resume the connection (neither can the official app) without power cycling the Gardena device. So we either need to remain connected OR connect to the device quicker.

Note that this might not be an issue on newer firmware, which might be why you don't have the problem.

It looks like the device disconnects after each read

    async def async_read_data(self):
        """Try to connect to device and extract information."""
        client = Client(get_connection(self.hass, self.address))
        try:
            model = await client.read_char(DeviceInformation.model_number)
            _LOGGER.debug("Found device with model: %s", model)
        except (CharacteristicNotFound, CommunicationFailure) as exception:
            raise AbortFlow(
                "cannot_connect", description_placeholders={"error": str(exception)}
            ) from exception
        finally:
            await client.disconnect()

https://github.com/home-assistant/core/blob/dev/homeassistant/components/gardena_bluetooth/config_flow.py#L79

That seems to call this code from the gardena_bluetooth library

    async def disconnect(self):
        await self._disconnect_job.call_now()

https://github.com/elupus/gardena-bluetooth/blob/7f6dd1af1086e8378292d793872de87742be2a9e/gardena_bluetooth/client.py#L79

Which ends up calling _disconnect() via the CallLaterJob() https://github.com/elupus/gardena-bluetooth/blob/master/gardena_bluetooth/client.py#L76C10-L76C10

I'm guessing that somehow the disconnect request gets cancelled by https://github.com/elupus/gardena-bluetooth/blob/master/gardena_bluetooth/client.py#L101 OR gets called with too long of a delay https://github.com/elupus/gardena-bluetooth/blob/master/gardena_bluetooth/client.py#L115

That somehow results in us getting into a weird state where the ESP proxy thinks we are disconnecting but we aren't actually.

I'm able to run this command on my Linux PC

for i in $(seq 1 1000); do python3 -m gardena_bluetooth connect E4:E1:12:FF:A3:E0; sleep 30; done

and I don't see any issues after a few hours. I also noticed that WiFi ESP proxies actually are more reliable then Ethernet ones. The WiFi devices are sharing the antenna between Bluetooth and WiFi. So I think the issue is a failure to disconnect.

alistair23 commented 7 months ago

I have tried removing the disconnect line from the integration.

That does seem to be much better! I'll keep testing it for a few days just to be sure that is the issue.

Assuming that is the problem is there a more robust way to async the disconnect?

elupus commented 7 months ago

Ive suspected the disconnect to be an issue before. I think we end up in a state where the gardena device thinks we are connected, while we think we are disconnected.

The device only allow a single connection at a time, which is why we try to disconnect. Also i think battery will drain quick if we are always connected.

alistair23 commented 7 months ago

Yeah, it does seem like removing the disconnect fixes the issue.

I personally don't care about allowing other connections. So maybe for now we could add an option to skip the disconnect? I'm not sure if that's possible for HA integrations though.

I suspect you are right about the battery drain. Although connecting and disconnecting all the time also probably drains battery a fair bit. I'll keep an eye on the battery life.

For me at least I would rather it be reliable then to save power.

alistair23 commented 6 months ago

For anyone else who has the same issue, this is how to fix it.

First you need this diff to the Gardena component. Otherwise the device will eventually disconnect and stop working

diff --git a/homeassistant/components/gardena_bluetooth/config_flow.py b/homeassistant/components/gardena_bluetooth/config_flow.py
index 7b34edd29a..2b95611a9f 100644
--- a/homeassistant/components/gardena_bluetooth/config_flow.py
+++ b/homeassistant/components/gardena_bluetooth/config_flow.py
@@ -75,8 +75,6 @@ class ConfigFlow(config_entries.ConfigFlow, domain=DOMAIN):
             raise AbortFlow(
                 "cannot_connect", description_placeholders={"error": str(exception)}
             ) from exception
-        finally:
-            await client.disconnect()

         return {CONF_ADDRESS: self.address}

Then hard reset the device by holding the button while inserting the battery. Keep holding the button until all 3 lights flash at you. This is an important step as it seems to stop the devices from trying to connect to anything else.

Then using a single ESPHome proxy device as the proxy connect to the Gardena device. The ESPHome device must be hardwired, no WiFi. This should be done with the two devices physically close.

An example of my ESPHome config is below

esp32_ble_tracker:
  scan_parameters:
    interval: 1100ms
    window: 1100ms
    active: false
    continuous: true

bluetooth_proxy:
  active: true
  cache_services: true

ble_client:
  - mac_address: AB:CD:1EF:12:34:56
    id:  gardena_water_switch

You can then move the devices a littler further apart, Mine are about 5 to 7 metres apart. But try to keep them as close as possible. You need to power cycle the Gardena device on any disconnect (like an ESPHome update or power loss)

From what I can tell, as long as everything is close enough you should now get a reliable connection.

I've hit issues having multiple ESP proxies, so I don't think that is a good idea. The factory reset also seems pretty critical

elupus commented 6 months ago

For anyone else who has the same issue, this is how to fix it.

It is not. You changed the code only used for setup of the integration, it is never used later on nor on restart.

If you want a never disconnecting connection, just change https://github.com/home-assistant/core/blob/3e07cf50ce82fe1559c0f2e1183c1906696953c7/homeassistant/components/gardena_bluetooth/__init__.py#L32 to something large.

alistair23 commented 6 months ago

So just this diff made a huge improvement:

diff --git a/homeassistant/components/gardena_bluetooth/config_flow.py b/homeassistant/components/gardena_bluetooth/config_flow.py
index 7b34edd29a..2b95611a9f 100644
--- a/homeassistant/components/gardena_bluetooth/config_flow.py
+++ b/homeassistant/components/gardena_bluetooth/config_flow.py
@@ -75,8 +75,6 @@ class ConfigFlow(config_entries.ConfigFlow, domain=DOMAIN):
             raise AbortFlow(
                 "cannot_connect", description_placeholders={"error": str(exception)}
             ) from exception
-        finally:
-            await client.disconnect()

         return {CONF_ADDRESS: self.address}

It went from a day long connections to multiple days, eventually I update or reinstall the BLE proxy leading to a disconnect.

If that is just for setup, can we make the diff change above to upstream?

alistair23 commented 6 months ago

I have also switched to a longer DISCONNECT_DELAY. It seems to help if the device is far away from the proxy, but if the devices are close enough I don't think I need to increase it.

elupus commented 6 months ago

It went from a day long connections to multiple days, eventually I update or reinstall the BLE proxy leading to a disconnect.

If that is just for setup, can we make the diff change above to upstream?

Absolutely not. It is not executed at all when integration is already set up. Your analysis is wrong here. Something else caused your problems to go away.

issue-triage-workflows[bot] commented 3 months ago

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.

elupus commented 3 months ago

Was this mostly solved by https://github.com/home-assistant/core/pull/113056?

alistair23 commented 3 months ago

This still needs https://github.com/home-assistant/core/pull/106282 or something similar. I haven't had a chance to figure out how to add an timeout option. After that it seems to be a lot more reliable

jurgenhaas commented 3 months ago

I'm seeing a similar issue, although I'm not using ESP BLE hub, my HA server has direct bluetooth support and my Gardena device is connected that way. It works just fine, until I see the following error message in the HA logs:

2024-04-08 10:58:38.058 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Gardena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0f14-0b0e-421a-84e5-ddbf75dc6de4 due to Communcation failed with device: [org.bluez.Error.Failed] Operation failed with ATT error: 0x0e (Unlikely Error)

This happens every few hours. I've checked, the code from #113056 seems to be applied already (I'm using HA 2024.4.1), but the code from #106282 is not there yet. So, I've now patched with that latter PR and will continue watching the logs. Coming back when I know more.

thebeater commented 3 months ago

Is there and Progress to integrate that pr or can anyone give me an direction to Patch it? I have the Same Problem Here

jurgenhaas commented 3 months ago

Unfortunately, those changes from #106282 don't make any difference in my case. After a few hours, connection is lost between HA and my Gardena device, which is just 1 meter away from the host. So, distance or bad connection can't be an issue.

When I try to reload the Gardena integration, I'm getting the following error messages and I have to put the battery out and back in to reconnect.

2024-04-09 07:44:36.301 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139646778564416] Unable to write characteristic CharacteristicLong(uuid='98bd0f13-0b0e-421a-84e5-ddbf75dc6de4', name='Remaining Open Time') dur to Communcation failed with device: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 110, in __call__
    yield client
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 194, in write_char_raw
    await client.write_gatt_char(characteristic, data, response=response)
  File "/usr/local/lib/python3.12/site-packages/bleak/__init__.py", line 776, in write_gatt_char
    await self._backend.write_gatt_char(characteristic, data, response)
  File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/client.py", line 861, in write_gatt_char
    assert_reply(reply)
  File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/gardena_bluetooth/coordinator.py", line 97, in write
    await self.client.write_char(char, value)
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 204, in write_char
    await self.write_char_raw(char.uuid, data, response)
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 187, in write_char_raw
    async with self._client() as client:
  File "/usr/local/lib/python3.12/contextlib.py", line 231, in __aexit__
    await self.gen.athrow(value)
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 119, in __call__
    raise CommunicationFailure(
gardena_bluetooth.exceptions.CommunicationFailure: Communcation failed with device: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2543, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2580, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 971, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1043, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/gardena_bluetooth/switch.py", line 64, in async_turn_on
    await self.coordinator.write(Valve.remaining_open_time, value)
  File "/usr/src/homeassistant/homeassistant/components/gardena_bluetooth/coordinator.py", line 99, in write
    raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Unable to write characteristic CharacteristicLong(uuid='98bd0f13-0b0e-421a-84e5-ddbf75dc6de4', name='Remaining Open Time') dur to Communcation failed with device: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist

2024-04-09 07:44:36.313 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139646778564416] Unable to write characteristic CharacteristicLong(uuid='98bd0f13-0b0e-421a-84e5-ddbf75dc6de4', name='Remaining Open Time') dur to Communcation failed with device: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 110, in __call__
    yield client
  File "/usr/local/lib/python3.12/site-packages/gardena_bluetooth/client.py", line 194, in write_char_raw
    await client.write_gatt_char(characteristic, data, response=response)
  File "/usr/local/lib/python3.12/site-packages/bleak/__init__.py", line 776, in write_gatt_char
    await self._backend.write_gatt_char(characteristic, data, response)
  File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/client.py", line 861, in write_gatt_char
    assert_reply(reply)
  File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.UnknownObject] Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist

Any ideas what could be wrong with this one? Is it related or should I open a new issue for it?

elupus commented 3 months ago

@jurgenhaas the referenced commit was known to not work in general. You could have a problem with the built in bluetooth stack of your system.

The linux based bluez stack is know flaky and need really really new versions to work okey, but still buggy. HAOS has new bluez.

Usually better to run with an esp gateway.

jurgenhaas commented 3 months ago

I'm using HA with their docker image, does that not come with the largest bluez then?

elupus commented 3 months ago

No it will use bluez and kernel from your hosting computer.

wtom commented 3 months ago

I'm using a esp Bluetooth proxy and I'm having the same disconnecting issue.

alistair23 commented 3 months ago

It's not an issue with the host Bluetooth stack. I'm using HA Supervisor with ESPHome BLE proxies.

My other BLE devices (even the Husqvarna Automower) are much more reliable. It's specifically an issue with the Gardena water controller. It seems that once you disconnect you can't reconnect without a power cycle of the Gardena.

That's the idea behind https://github.com/home-assistant/core/pull/106282 which does seem to improve things

That combined with my ESPHome config below makes things pretty stable

esp32_ble_tracker:
  id: ble_tracker_id
  scan_parameters:
    interval: 1100ms
    window: 1100ms
    active: false
    continuous: false
    duration: 50sec

bluetooth_proxy:
  active: true
  cache_services: true

ble_client:
  - mac_address: xxxx
    id:  gardena_water_switch
    on_disconnect:
      then:
        - esp32_ble_tracker.start_scan:

time:
  - platform: homeassistant
    on_time:
      - seconds: 0
        minutes: '*'
        then:
          esp32_ble_tracker.start_scan:
wtom commented 3 months ago

I will try it tomorrow

wtom commented 2 months ago

I will try it tomorrow

Didn't help, after 3 days it got disconnected again.

marithpl commented 2 months ago

Home-Assisstant: 2024.4.2 Connection via ESPHome Bluetooth Proxy

I similar problem. I've bought 2 Water Valves HA found them instantly, but they are disconnected(unavaliable) just after integration is connected with valve.

elupus commented 2 months ago

Did you guys firmware update the controllers? I think i did that before hooking mine up. (Been running for a month this summer.)

marithpl commented 2 months ago

My is 1.7.8.18

elupus commented 2 months ago

Seems older than mine: 1.7.23.29

marithpl commented 2 months ago

Seems older than mine: 1.7.23.29

My doesn't ask for an update.

wtom commented 2 months ago

HA: 2024.4.2 Firmware: 1.7.13.20 Water Control Bluetooth® / Article No. 1889-20

alistair23 commented 2 months ago

You can't update older versions

wtom commented 2 months ago

I'm currently updating my Water Control, let's see if that helps somehow.

wtom commented 2 months ago

Okay, updated to Firmware: 1.7.23.29 and changed your config, for 20sec scan duration and then scan every 30sec. Because i thing they will not merge your timeout fix? I changed it locally with the TIMEOUT to test now as well. Lets see how long the connection is kept now. :)

esp32_ble_tracker:
  scan_parameters:
    interval: 1100ms
    window: 1100ms
    active: false
    continuous: false
    duration: 20sec

ble_client:
  - mac_address: XXX
    id: gardena_water_switch
    on_disconnect:
      then:
        - esp32_ble_tracker.start_scan:

bluetooth_proxy:
  active: true
  cache_services: true

time:
  - platform: homeassistant
    on_time:
      - seconds: '0,30'
        minutes: '*'
        then:
          esp32_ble_tracker.start_scan:

EDIT: Your TIMEOUT change in the gardena_bluetooth component is needed. I played around with it a little now, and when i set the values high enough, i don't see "disconnecting" in the logs (then mostly the connection is lost until you power cycle the gardena devise again).

wtom commented 2 months ago

6 hours later it got disconnected again. I compiled the bluetooth proxy again with some different settings and after the restart the gardena water switch was connected again, without power cycling.

EDIT: I've activated the debug logs for the component.

2024-04-16 10:12:53.125 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth.config_flow] Discovered device: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f5307a65340>
2024-04-16 10:12:53.126 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth.config_flow] Unsupported device: ManufacturerData(pairable=True, serial=None, group=<ProductGroup.WATER_CONTROL: 18>, model=255, variant=255)
2024-04-16 10:13:18.932 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 1.309 seconds (success: True)
2024-04-16 10:14:40.247 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 21.781 seconds (success: True)
2024-04-16 10:16:02.261 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 21.795 seconds (success: True)
2024-04-16 10:17:38.476 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Gardena Bluetooth Data Update Coordinator data: Unable to update data for 98bd2a19-0b0e-421a-84e5-ddbf75dc6de4 due to Communcation failed with device: Gardena Bluetooth - B0:D2:78:91:4C:42: Failed to connect after 9 attempt(s): No backend with an available connection slot that can reach address B0:D2:78:91:4C:42 was found: The proxy/adapter is out of connection slots or the device is no longer reachable; Add additional proxies (https://esphome.github.io/bluetooth-proxies/) near this device
2024-04-16 10:17:38.476 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 36.010 seconds (success: False)
2024-04-16 10:19:14.477 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 36.012 seconds (success: False)

I think this is the problem, right? Means it's not yet fully disconnected but it's starting a new connection?

[12:53:38][D][esp-idf:000]: W (163011) BT_GATT: gatt_connect wrong state 4

EDIT2: Yes, that's the problem, when i power cycle the gardena device, then i see in the esphome logs, that it's disconnecting 4 open connections, before connecting again. Then it does the connect-disconnect cycle for 4 rounds, like 4 minutes and then it stops again, because no more slots. So it seems like the disconnecting either on esphome or on the gardena device doesn't fully work. That's why raising the disconnect delay to a high number helps, to have a longer period.


[13:11:56][D][esp-idf:000]: W (1261171) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x8

[13:11:56][D][esp-idf:000]: W (1261177) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x8

[13:11:56][D][esp-idf:000]: W (1261179) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x8

[13:11:56][D][esp-idf:000]: W (1261182) BT_APPL: gattc_conn_cb: if=6 st=0 id=6 rsn=0x8

[13:11:56][D][esp-idf:000]: W (1261184) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x8

[13:11:56][D][esp32_ble_client:172]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_DISCONNECT_EVT, reason 8
[13:11:56][D][esp32_ble_client:172]: [3] [B0:D2:78:91:4C:42] ESP_GATTC_DISCONNECT_EVT, reason 8
[13:11:56][D][esp32_ble_client:110]: [3] [B0:D2:78:91:4C:42] ESP_GATTC_CLOSE_EVT
[13:11:56][D][esp32_ble_client:110]: [3] [B0:D2:78:91:4C:42] Found device

I now have the DISCONNECT_DELAY set to 12000, let's see how it goes. I will post the logs as soon as i get a disconnect. For now, i have like 20 _async_update_data cycles without any problem. (all on one connection, since it's not disconnecting anymore) @elupus if you need any specific logs, just let me know. I can reproduce it.

wtom commented 2 months ago

Here are the component logs from the last days. Start of the log is a power cycle.

2024-04-16 12:16:25.415 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth.config_flow] Discovered device: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f079e8889c0>
2024-04-16 12:16:25.417 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth.config_flow] Unsupported device: ManufacturerData(pairable=True, serial=None, group=<ProductGroup.WATER_CONTROL: 18>, model=255, variant=255)
2024-04-16 12:16:54.468 DEBUG (MainThread) [gardena_bluetooth.client] Connecting to B0:D2:78:91:4C:42
2024-04-16 12:16:54.953 DEBUG (MainThread) [gardena_bluetooth.client] Connected to B0:D2:78:91:4C:42
2024-04-16 12:16:55.421 WARNING (MainThread) [gardena_bluetooth.client] Updating time on device to match local time delta was -1 day, 23:16:14.687903
2024-04-16 12:16:56.855 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 1.314 seconds (success: True)

2024-04-16 19:32:06.611 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 1.438 seconds (success: True)
2024-04-16 19:33:06.173 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Gardena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0f13-0b0e-421a-84e5-ddbf75dc6de4 due to Unable to find device
2024-04-16 19:33:06.174 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 0.000 seconds (success: False)

2024-04-17 20:49:33.388 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth.config_flow] Discovered device: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f079ef6e840>
2024-04-17 20:50:06.172 DEBUG (MainThread) [gardena_bluetooth.client] Connecting to B0:D2:78:91:4C:42
2024-04-17 20:50:06.360 DEBUG (MainThread) [gardena_bluetooth.client] Connected to B0:D2:78:91:4C:42
2024-04-17 20:50:07.692 INFO (MainThread) [homeassistant.components.gardena_bluetooth] Fetching Gardena Bluetooth Data Update Coordinator data recovered
2024-04-17 20:50:07.693 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 1.520 seconds (success: True)

2024-04-18 01:31:44.548 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 1.375 seconds (success: True)
2024-04-18 01:32:44.173 ERROR (MainThread) [homeassistant.components.gardena_bluetooth] Error fetching Gardena Bluetooth Data Update Coordinator data: Unable to update data for 98bd0f13-0b0e-421a-84e5-ddbf75dc6de4 due to Unable to find device
2024-04-18 01:32:44.173 DEBUG (MainThread) [homeassistant.components.gardena_bluetooth] Finished fetching Gardena Bluetooth Data Update Coordinator data in 0.001 seconds (success: False)
wtom commented 2 months ago

I've now reverted everything on the components to standard, and on the esphome config i disabled the autoconnect. That does help with the connecting and disconnecting.

ble_client:
  - mac_address: B0:D2:78:91:4C:42
    id: gardena_water_switch
    auto_connect: false
[13:26:03][I][bluetooth_proxy:278]: [0] [B0:D2:78:91:4C:42] Connecting v3 with cache
[13:26:03][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[13:26:03][I][esp32_ble_client:067]: [0] [B0:D2:78:91:4C:42] 0x00 Attempting BLE connection
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_CONNECT_EVT
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_OPEN_EVT
[13:26:04][I][esp32_ble_client:154]: [0] [B0:D2:78:91:4C:42] Connected
[13:26:04][D][esp32_ble_client:110]: [3] [B0:D2:78:91:4C:42] ESP_GATTC_CONNECT_EVT
[13:26:04][D][esp32_ble_tracker:266]: Starting scan...
[13:26:04][D][esp32_ble_client:188]: [0] [B0:D2:78:91:4C:42] cfg_mtu status 0, mtu 247
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:04][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:05][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_READ_CHAR_EVT
[13:26:10][I][esp32_ble_client:084]: [0] [B0:D2:78:91:4C:42] Disconnecting.
[13:26:10][D][esp-idf:000]: W (419421) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13

[13:26:10][D][esp-idf:000]: W (419425) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[13:26:10][D][esp-idf:000]: W (419427) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16

[13:26:10][D][esp-idf:000]: W (419428) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16

[13:26:10][D][esp-idf:000]: W (419430) BT_APPL: gattc_conn_cb: if=6 st=0 id=6 rsn=0x16

[13:26:10][D][esp32_ble_client:110]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_CLOSE_EVT
[13:26:10][D][esp32_ble_client:172]: [0] [B0:D2:78:91:4C:42] ESP_GATTC_DISCONNECT_EVT, reason 22
[13:26:10][D][esp32_ble_client:172]: [3] [B0:D2:78:91:4C:42] ESP_GATTC_DISCONNECT_EVT, reason 22
[13:26:10][D][esp-idf:000]: W (419465) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

First time that i see a "disc complete" message.

Let's see how long it works now.

elupus commented 2 months ago

@wtom i assume you just added that (ble_client) section to the proxy? That is not expected to be there and would conflict with normal operation of the proxy.

wtom commented 2 months ago

Yes i added it as @alistair23 mentioned it. But yes, if the auto_connect is true, that's creating problems. I will now wait for the next disconnect, to see what the logs say.

By the way connecting-disconnecting uses more energy than keeping the connection alive.

Detmud commented 2 months ago

Just wanted to pitch in that i am having exactly the same issue.

elupus commented 2 months ago

Why do you guys @alistair23 @wtom have esp32_ble_tracker.start_scan in your configs?

elupus commented 2 months ago

Ps. What we need to figure out is why disconnects fail. If the ble client can recover the disconnection and complete a failed one in some way.

elupus commented 2 months ago

I also wonder why your logs on the esp show two disconnection events.

elupus commented 2 months ago

Might have found something. This case here https://github.com/esphome/esphome/blob/655dbc48b5f7e53a4ceee83f4aa159e276d8b864/esphome/components/bluetooth_proxy/bluetooth_connection.cpp#L22 is likely missing a conn_id check.

param->disconnect.conn_id should likely be checked similar to the other cases.