Fix missing conn_id check in bluetooth_proxy disconnect event #6590

bdraco · 2024-04-19T23:55:17Z

What does this implement/fix?

Fix missing conn_id check in bluetooth_proxy disconnect event
Pointed out by @elupus while debugging home-assistant/core#103117

Test yaml

external_components:
  - source: github://pr#6590
    components: [ bluetooth_proxy ]

Types of changes

Bugfix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
Other

Related issue or feature (if applicable): fixes

Pull request in esphome-docs with documentation (if applicable): esphome/esphome-docs#

Test Environment

Example entry for `config.yaml`:

# Example config.yaml

Checklist:

The code change is tested and works locally.
Tests have been added to verify that the new code works (under tests/ folder).

If user exposed functionality or configuration variables are added/changed:

Documentation added/updated in esphome-docs.

@elupus

Pointed out by @elupus while debugging home-assistant/core#103117

bdraco · 2024-04-20T00:35:22Z

Pushed to al my production and so far so good. But I didn't see a problem before, however that is likely because I have so many proxies and it was very rare for one to have more than one connection at a time

elupus · 2024-04-20T06:31:27Z

I think it looks correct. Will report back if i get confirmation on that other issue.

probot-esphome · 2024-04-20T14:45:44Z

Hey there @jesserockz, mind taking a look at this pull request as it has been labeled with an integration (bluetooth_proxy) you are listed as a code owner for? Thanks!
_{^{(message by CodeOwnersMention)}}

bdraco · 2024-04-20T14:45:48Z

Running fine overnight here

elupus · 2024-04-21T07:32:53Z

Looks like the base class has similar code:

esphome/esphome/components/esp32_ble_client/ble_client_base.cpp

Line 170 in 655dbc4

return false;

Im suddenly not fully sure here. A bit unclear från docs how one is expected to handle this.

elupus · 2024-04-21T08:07:11Z

So there are virtual and physical connections. If there are multiple virtual connections to same device, there will not be a disconnect event, only a close event untill all virtual connections are closed.

I dont think this change here will make a difference, might break things if there was never any OPEN event. That said, this should likely listen to CLOSE events with that check.

Not sure if the proxy code manages this virtual connections.

bdraco · 2024-04-21T09:11:21Z

https://docs.espressif.com/projects/esp-idf/en/stable/esp32/api-reference/bluetooth/esp_gattc.html

close is the virtual
open is the virtual
disconnect is for the physical
connect is for the physical

bdraco · 2024-04-21T09:13:12Z

Looks like we don't handle ESP_GATTC_CANCEL_OPEN_EVT

bdraco · 2024-04-21T09:13:50Z

not sure ESP_GATTC_CANCEL_OPEN_EVT actually ever happens?

bdraco · 2024-04-21T09:14:25Z

ESP_GATTC_CANCEL_OPEN_EVT is never referenced in the underlying code so I don't think it actually ever happens

bdraco · 2024-04-21T09:22:39Z

I dont think this change here will make a difference, might break things if there was never any OPEN event. That said, this should likely listen to CLOSE events with that check.

Should be fine if there is never an open event as it will end up freeing the connection slot as it does the same thing as an open failure

bdraco · 2024-04-21T09:26:02Z

Here is the order of events for a connection to a lock

[04:24:46][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[04:24:46][I][esp32_ble_client:067]: [0] [78:9C:85:0A:94:40] 0x00 Attempting BLE connection
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_CONNECT_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_OPEN_EVT
[04:24:47][I][esp32_ble_client:154]: [0] [78:9C:85:0A:94:40] Connected
[04:24:47][D][esp32_ble_tracker:266]: Starting scan...
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_REG_FOR_NOTIFY_EVT
[04:24:47][D][esp32_ble_client:188]: [0] [78:9C:85:0A:94:40] cfg_mtu status 0, mtu 512
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_DESCR_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_REG_FOR_NOTIFY_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_DESCR_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:47][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:49][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:49][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:24:54][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:56][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:24:56][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_NOTIFY_EVT
[04:25:06][D][esp32_ble_client:306]: [0] [78:9C:85:0A:94:40] Event 39
[04:25:06][D][esp32_ble_client:110]: [0] [78:9C:85:0A:94:40] ESP_GATTC_WRITE_CHAR_EVT
[04:25:06][D][esp-idf:000]: W (52904) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x13

[04:25:06][D][esp-idf:000]: W (52908) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x13

[04:25:06][D][esp-idf:000]: W (52909) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x13

[04:25:06][D][esp-idf:000]: W (52911) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x13

[04:25:06][D][esp32_ble_client:172]: [0] [78:9C:85:0A:94:40] ESP_GATTC_DISCONNECT_EVT, reason 19
[04:25:06][D][esp32_ble_client:110]: [0] [] ESP_GATTC_CLOSE_EVT

elupus · 2024-04-21T09:44:36Z

My point was if we have

open() > 1
conn_event
open_event

Second virtual connection starts up

open() > 2
open_event

First virtual connection is closed

close(1)
close_event

(no disconnect here, so proxy still thinks the virtual connection is open)

close(2)
disconnect_event
close_event

Strange order of close disconnect from your log. Now both the proxy connection will be considered closed.

bdraco · 2024-04-21T09:58:30Z

Didn't realize it was possible with the proxy code to create more than one virtual connection to the same device. Need to check that it actually is and the library doesn't assume already connected means you get the same connection

elupus · 2024-04-21T10:01:49Z

I am not sure it is, but ive seen users playing with ble_client configs on the esp proxy itself. See this log.

[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

bdraco · 2024-04-21T10:02:04Z

It looks like if you try to connect to an address and it's already connected we return the existing connection

esphome/esphome/components/bluetooth_proxy/bluetooth_proxy.cpp

Line 243 in 655dbc4

if (connection->state() == espbt::ClientState::CONNECTED ||

bdraco · 2024-04-21T10:11:16Z

That definitely doesn't look right. It shouldn't see two connect events. It does look like the check is wrong in esp32_ble_client as well.

[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

bdraco · 2024-04-21T10:14:48Z

We don't set the conn_id until the open event. Hmmm

bdraco · 2024-04-21T10:15:46Z

Do you by chance have a reproducer for the above log transaction?

elupus · 2024-04-21T10:23:11Z

Do you by chance have a reproducer for the above log transaction?

This is all i know:
home-assistant/core#103117 (comment)

bdraco · 2024-04-21T10:38:00Z

Are they using the esphome component and the Home Assistant integration at the same time?

home-assistant/core#103117 (comment)

elupus · 2024-04-21T10:45:12Z

I think in this case incorrectly so yes. I don't think that is the original source of the problem though. I think they have ended up trying many weird things. That said, we should probably behave good in that case too (or fail in a understandable way)

elupus · 2024-04-21T10:48:59Z

Looks like we don't need to check any conn_id in the proxy code. The base class should have filtered all those events already. but we should likely look at both disconnect and close event.

elupus · 2024-04-21T11:06:00Z

Here is actually one of those cases where the proxy missing the close event: home-assistant/core#103117 (comment) if you look at the last log lines, we have an event == 5, which is ESP_GATTC_CLOSE_EVT , but no disconnect ever comes. So it's likely still connected by some background connection, which breaks the next proxy connection.

elupus · 2024-04-21T14:12:39Z

Looks like some things changes (and broke) in #5277, the proxy code will no longer get the failed event status for a ESP_GATTC_OPEN_EVT. It now will return false in base class for this here: https://github.com/esphome/esphome/pull/5277/files#diff-63fb25f9255daa17cf4c5e4faa27822d42c678f5fbca526e44010ba4055ce905R145 so the proxy will no longer parse this event.

elupus · 2024-04-21T18:13:03Z

I made an alternate change here: #6596 not sure how i'm going to test that thou.

bdraco · 2024-05-03T14:25:08Z

superseded by #6596

Fix missing conn_id check in bluetooth_proxy disconnect event

dd34626

Pointed out by @elupus while debugging home-assistant/core#103117

probot-esphome bot added integration: bluetooth_proxy small-pr labels Apr 19, 2024

bdraco marked this pull request as ready for review April 20, 2024 14:45

bdraco requested a review from jesserockz as a code owner April 20, 2024 14:45

probot-esphome bot assigned jesserockz Apr 20, 2024

bdraco marked this pull request as draft April 21, 2024 09:11

dry

17db30f

elupus mentioned this pull request Apr 21, 2024

Ble client fixes for proxy #6596

Merged

13 tasks

bdraco closed this May 3, 2024

github-actions bot locked and limited conversation to collaborators May 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix missing conn_id check in bluetooth_proxy disconnect event #6590

Fix missing conn_id check in bluetooth_proxy disconnect event #6590

bdraco commented Apr 19, 2024 •

edited

bdraco commented Apr 20, 2024

elupus commented Apr 20, 2024

probot-esphome bot commented Apr 20, 2024

bdraco commented Apr 20, 2024 •

edited

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024 •

edited

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented May 3, 2024

Fix missing conn_id check in bluetooth_proxy disconnect event #6590

Fix missing conn_id check in bluetooth_proxy disconnect event #6590

Conversation

bdraco commented Apr 19, 2024 • edited

What does this implement/fix?

Types of changes

Test Environment

Example entry for config.yaml:

Checklist:

bdraco commented Apr 20, 2024

elupus commented Apr 20, 2024

probot-esphome bot commented Apr 20, 2024

bdraco commented Apr 20, 2024 • edited

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024 • edited

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

elupus commented Apr 21, 2024

bdraco commented May 3, 2024

bdraco commented Apr 19, 2024 •

edited

Example entry for `config.yaml`:

bdraco commented Apr 20, 2024 •

edited

bdraco commented Apr 21, 2024 •

edited