Skip to content

implement pairing for bluetooth proxy#4475

Merged
jesserockz merged 31 commits intoesphome:devfrom
jagheterfredrik:just-works
Mar 6, 2023
Merged

implement pairing for bluetooth proxy#4475
jesserockz merged 31 commits intoesphome:devfrom
jagheterfredrik:just-works

Conversation

@jagheterfredrik
Copy link
Copy Markdown
Contributor

@jagheterfredrik jagheterfredrik commented Feb 21, 2023

This patch implements bluetooth pairing for bluetooth proxy on ESP32.

What does this implement/fix?

The pairing function was not implemented

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):

Test Environment

  • ESP32
  • ESP32 IDF
  • ESP8266
  • RP2040

Example entry for config.yaml:

https://esphome.github.io/bluetooth-proxies/

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:

This patch will turn on encryption when making active connections in order to comply with just-works BLE encryption.
@probot-esphome
Copy link
Copy Markdown

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

@jesserockz
Copy link
Copy Markdown
Member

While this change seems to be working, it does bring in a bunch of error logs from esp-idf now

[09:49:38][I][bluetooth_proxy:250]: [0] [78:9C:85:19:4F:53] Connecting v3 with cache
[09:49:38][I][esp32_ble_client:064]: [0] [78:9C:85:19:4F:53] 0x00 Attempting BLE connection
[09:49:39][I][esp-idf:000]: W (477511) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[09:49:39][I][esp32_ble_client:141]: [0] [78:9C:85:19:4F:53] Connected
[09:49:39][I][esp-idf:000]: E (478183) BT_APPL: earlier enc was not done for same device


[09:49:39][I][esp-idf:000]: E (478185) BT_APPL: earlier enc was not done for same device


[09:49:39][I][esp32_ble_client:263]: [0] [78:9C:85:19:4F:53] auth complete. remote BD_ADDR: 789c85194f53
[09:49:39][E][esp32_ble_client:266]: [0] [78:9C:85:19:4F:53] auth fail reason = 0x55
[09:49:39][I][esp32_ble_client:263]: [1] [] auth complete. remote BD_ADDR: 789c85194f53
[09:49:39][E][esp32_ble_client:266]: [1] [] auth fail reason = 0x55
[09:49:39][I][esp32_ble_client:263]: [2] [] auth complete. remote BD_ADDR: 789c85194f53
[09:49:39][E][esp32_ble_client:266]: [2] [] auth fail reason = 0x55
[09:49:39][I][esp-idf:000]: E (478375) BT_BTM: BTM_GetSecurityFlags false

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

jagheterfredrik commented Feb 21, 2023

Interesting, is ESP_GAP_BLE_SEC_REQ_EVT being called?

My device does not trigger it and thus encryption is never setup leading to char write returning GATT_INSUFFICIENT_ENCRYPTION. I assume your device is asking for it and thus complain that it is being re-setup.

Thanks a bunch for testing so quickly 👍

@jesserockz
Copy link
Copy Markdown
Member

No this event is not received on the ESP

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

jagheterfredrik commented Feb 22, 2023

Ok, so the esp_ble_set_encryption(...) is what ESP32-people call pairing. I'll rework this to implement the pair() function instead.

I assume your device is unpaired, unencrypted, “Bluetooth Smart” device

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

relates to esphome/aioesphomeapi#390

@jagheterfredrik jagheterfredrik changed the title enable just-works encryption on active connections implement pairing for bluetooth proxy Feb 22, 2023
@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

jagheterfredrik commented Feb 22, 2023

OK! @jesserockz, I've tested the changes with my device and issuing a pair() command through aioesphomeapi works beautifully, e.g.:

import aioesphomeapi
import asyncio
 
async def main():
    api = aioesphomeapi.APIClient("10.0.13.37", 6053, password=None)
    await api.connect(login=True)
 
    def _on_bluetooth_connection_state(
        connected: bool, mtu: int, error: int
    ) -> None:
        print(f"Connect cb! {connected=} {mtu=}")
 
    address = int("MY:DE:VI:CE:HE:RE".replace(":", ""), 16)
    await api.bluetooth_device_connect(
        address,
        _on_bluetooth_connection_state,
        timeout=10,
        has_cache=False,
        version=3,
        address_type=0,
    )
    await api.bluetooth_device_pair(address)
 
    def on_notify(int, data):
        print(data)
 
    await api.bluetooth_gatt_start_notify(address, 26, on_notify)
    print(await api.bluetooth_gatt_write(address, 29, bytes([3]), True))
    await asyncio.sleep(0.5)
    print(await api.bluetooth_gatt_write(address, 23, bytes(b'get sy v\r\n'), True))
 
    await asyncio.sleep(5)
    await api.bluetooth_device_disconnect(address)
 
loop = asyncio.get_event_loop()
loop.run_until_complete(main())

Without calling bluetooth_device_pair() the device returns GATT_INSUFFICIENT_ENCRYPTION.

@bdraco
Copy link
Copy Markdown
Member

bdraco commented Feb 22, 2023

We need to bump the Bluetooth proxy version as well so hass can know it's available

@bdraco
Copy link
Copy Markdown
Member

bdraco commented Feb 22, 2023

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

I started https://github.com/jagheterfredrik/core/tree/bluetooth-proxy-pair but you're quick @bdraco, thank you! 🙏 I'll bump the version here

@emontnemery
Copy link
Copy Markdown

emontnemery commented Feb 27, 2023

There seems to be some issue with the latest version. I'm testing with two pairable devices, and Home Assistant often gets auth errors when trying to communicate with the devices.

It seems like the first device Home Assistant talks to works fine, whereas the 2nd device has issues. I've only tested a handful of times though, so I'm not sure if it's always the 2nd device which fails.

The error in the Home Assistant log (actually from bleak) say there's a problem with "insufficient authentication".

Note: The problem doesn't always occur, it happens maybe 3 out of 4 times when restarting Home Assistant.

In the ESPHome logs I see this:

[11:20:05][D][api.connection:920]: Home Assistant 2023.4.0.dev0 (192.168.0.5): Connected successfully
[11:20:09][I][bluetooth_proxy:254]: [0] [F0:94:0A:BD:3D:0A] Connecting v3 without cache
[11:20:09][D][esp32_ble_tracker:206]: Pausing scan to make connection...
[11:20:09][I][bluetooth_proxy:254]: [1] [ED:D2:90:2E:4C:69] Connecting v3 without cache
[11:20:09][I][esp32_ble_client:064]: [0] [F0:94:0A:BD:3D:0A] 0x01 Attempting BLE connection
[11:20:11][D][esp-idf:000]: W (106446) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[11:20:13][I][esp32_ble_client:196]: [0] [F0:94:0A:BD:3D:0A] Connected
[11:20:13][I][esp32_ble_client:064]: [1] [ED:D2:90:2E:4C:69] 0x01 Attempting BLE connection
[11:20:13][I][esp32_ble_client:261]: [0] [F0:94:0A:BD:3D:0A] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:13][I][esp32_ble_client:261]: [1] [ED:D2:90:2E:4C:69] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:13][I][esp32_ble_client:261]: [2] [] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:14][I][esp32_ble_client:081]: [0] [F0:94:0A:BD:3D:0A] Disconnecting.
[11:20:14][D][esp-idf:000]: W (109006) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13

[11:20:14][D][esp-idf:000]: W (109011) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[11:20:14][D][esp-idf:000]: W (109015) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16

[11:20:14][D][esp-idf:000]: W (109017) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16

[11:20:14][D][esp-idf:000]: W (109019) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[11:20:14][I][esp32_ble_client:196]: [1] [ED:D2:90:2E:4C:69] Connected
[11:20:14][D][esp32_ble_tracker:238]: Starting scan...
[11:20:16][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x F, status=5
[11:20:16][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x12, status=5
[11:20:16][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:16][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:16][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:16][W][bluetooth_proxy:217]: [1] [ED:D2:90:2E:4C:69] Connection already established
[11:20:17][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x F, status=5
[11:20:17][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x12, status=5
[11:20:17][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:17][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:17][W][bluetooth_proxy.connection:101]: [1] [ED:D2:90:2E:4C:69] Error writing char/descriptor at handle 0x E, status=5
[11:20:28][W][bluetooth_proxy:217]: [1] [ED:D2:90:2E:4C:69] Connection already established

Let me know what I can do to aid debugging.

@jagheterfredrik jagheterfredrik requested review from jesserockz and removed request for OttoWinter February 28, 2023 06:32
@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

There seems to be some issue with the latest version

So you mean that it was working before?

@emontnemery
Copy link
Copy Markdown

emontnemery commented Feb 28, 2023

@jagheterfredrik I tested on an earlier commit, before the waiting for ACK after pairing was implemented, that had other issues, probably because there was no wait for pairing to complete?
By the way, this stands out to me, what's with the index 2?

[11:20:13][I][esp32_ble_client:261]: [0] [F0:94:0A:BD:3D:0A] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:13][I][esp32_ble_client:261]: [1] [ED:D2:90:2E:4C:69] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:13][I][esp32_ble_client:261]: [2] [] auth complete. remote BD_ADDR: f0940abd3d0a

You can contact me on discord if you want to chat, I'm emontnemery#6618 there.

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

I see. Would you mind bisecting?

@emontnemery
Copy link
Copy Markdown

I don't mind bisecting, but I think it gets a bit tricky since there's interdependencies between the Home Assistant Core, aioesphomeapi and esphome PRs?

If you can outline which combinations commits you'd like me to test or bisect, I'll do that though.

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

esphome should suffice. Did you try to explicitly disconnect-> connect -> pair -> write?

@emontnemery
Copy link
Copy Markdown

esphome should suffice

That's where I'm confused, if I just bisect the commits in this PR, I'll run into problems because aioesphome and home assistant are not compatible with ESPHome? Or do you have some suggestion for how to test ESPHome in isolation?

Did you try to explicitly disconnect-> connect -> pair -> write

No, I did not try that.

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

Latest aioesphomeapi should be backwards compatible. I’m not sure I follow how you are testing, is it a custom HA component?

I’d prefer to move this to a separate issue as it’s working on your other device. Insufficient auth could mean that the device is not happy with just-works pairing and requires a passcode pairing procedure which is not implemented and would require a lot of additional work.

@emontnemery
Copy link
Copy Markdown

Latest aioesphomeapi should be backwards compatible

Is it really backwards compatible considering the protobuf definitions were changed several times, with new messages added and so on?

I’m not sure I follow how you are testing, is it a custom HA component

I'm testing with a core integration which has support for a Bluetooth device which requires pairing: https://next.home-assistant.io/integrations/dormakaba_dkey/
My test involves two identical devices added to Home Assistant. Sometimes it's possible to talk to both of them, sometimes only one of them.

I’d prefer to move this to a separate issue as it’s working on your other device

The pairing implemented by this PR seems to be flaky; it sometimes works and it sometimes doesn't, so I think that should be solved before this PR is merged?

Based on some more testing:

  • It always seems to be successful to talk to the very first device Home Assistant contacts, that means the first config entry which is setup
  • The 2nd config entry to be setup is not reliable
    • It's not a problem with the device themselves; the problem depends on setup order (verified by reordering config entries in core.config_entries)
    • The problem with the 2nd device seems to be triggered if Home Assistant is stopped, and then immediately started again.

Could you contact me on discord, I'm emontnemery#6618 there, I think it may be easier to explain how I'm testing etc. if it's still unclear?

@emontnemery
Copy link
Copy Markdown

I just took a another look at the error logs I posted when I first mentioned the issue, and it seems clear that ESPHome is mixing up the two connections:

[11:20:09][I][bluetooth_proxy:254]: [0] [F0:94:0A:BD:3D:0A] Connecting v3 without cache
[11:20:09][D][esp32_ble_tracker:206]: Pausing scan to make connection...
[11:20:09][I][bluetooth_proxy:254]: [1] [ED:D2:90:2E:4C:69] Connecting v3 without cache
[11:20:09][I][esp32_ble_client:064]: [0] [F0:94:0A:BD:3D:0A] 0x01 Attempting BLE connection
[11:20:11][D][esp-idf:000]: W (106446) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[11:20:13][I][esp32_ble_client:196]: [0] [F0:94:0A:BD:3D:0A] Connected
[11:20:13][I][esp32_ble_client:064]: [1] [ED:D2:90:2E:4C:69] 0x01 Attempting BLE connection
[11:20:13][I][esp32_ble_client:261]: [0] [F0:94:0A:BD:3D:0A] auth complete. remote BD_ADDR: f0940abd3d0a
[11:20:13][I][esp32_ble_client:261]: [1] [ED:D2:90:2E:4C:69] auth complete. remote BD_ADDR: f0940abd3d0a  <-- THIS IS THE ADDRESS OF THE 1ST DEVICE!!!!
[11:20:13][I][esp32_ble_client:261]: [2] [] auth complete. remote BD_ADDR: f0940abd3d0a <-- WHERE DOES INDEX 2 COME FROM, WE'RE TALKING TO 2 DEVICES, NOT 3

@emontnemery
Copy link
Copy Markdown

emontnemery commented Mar 1, 2023

Here's a successful log, the difference is that the connections to the two devices do not happen in parallel:

[12:31:28][D][api.connection:920]: Home Assistant 2023.4.0.dev0 (192.168.0.5): Connected successfully
[12:31:35][I][bluetooth_proxy:254]: [0] [ED:D2:90:2E:4C:69] Connecting v3 without cache
[12:31:35][D][esp32_ble_tracker:206]: Pausing scan to make connection...
[12:31:35][I][esp32_ble_client:064]: [0] [ED:D2:90:2E:4C:69] 0x01 Attempting BLE connection
[12:31:37][I][esp32_ble_client:196]: [0] [ED:D2:90:2E:4C:69] Connected
[12:31:37][D][esp32_ble_tracker:238]: Starting scan...
[12:31:37][I][esp32_ble_client:261]: [0] [ED:D2:90:2E:4C:69] auth complete. remote BD_ADDR: edd2902e4c69
[12:31:37][I][esp32_ble_client:261]: [1] [] auth complete. remote BD_ADDR: edd2902e4c69
[12:31:37][I][esp32_ble_client:261]: [2] [] auth complete. remote BD_ADDR: edd2902e4c69
[12:31:39][I][esp32_ble_client:081]: [0] [ED:D2:90:2E:4C:69] Disconnecting.
[12:31:39][D][esp-idf:000]: W (57608670) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13

[12:31:39][D][esp-idf:000]: W (57608676) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[12:31:39][D][esp-idf:000]: W (57608678) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16

[12:31:39][D][esp-idf:000]: W (57608681) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16

[12:31:39][D][esp-idf:000]: W (57608688) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[12:31:39][I][bluetooth_proxy:254]: [0] [F0:94:0A:BD:3D:0A] Connecting v3 without cache
[12:31:39][D][esp32_ble_tracker:206]: Pausing scan to make connection...
[12:31:39][I][esp32_ble_client:064]: [0] [F0:94:0A:BD:3D:0A] 0x01 Attempting BLE connection
[12:31:41][I][esp32_ble_client:196]: [0] [F0:94:0A:BD:3D:0A] Connected
[12:31:41][D][esp32_ble_tracker:238]: Starting scan...
[12:31:41][I][esp32_ble_client:261]: [0] [F0:94:0A:BD:3D:0A] auth complete. remote BD_ADDR: f0940abd3d0a
[12:31:41][I][esp32_ble_client:261]: [1] [] auth complete. remote BD_ADDR: f0940abd3d0a
[12:31:41][I][esp32_ble_client:261]: [2] [] auth complete. remote BD_ADDR: f0940abd3d0a
[12:31:42][I][esp32_ble_client:081]: [0] [F0:94:0A:BD:3D:0A] Disconnecting.

@emontnemery
Copy link
Copy Markdown

I got some help from @jesserockz, the problem is that the newly added code does not check if BLE events are for the correct connection slot. After adding that, it works 👍

@emontnemery
Copy link
Copy Markdown

This needs to be added:

diff --git a/esphome/components/bluetooth_proxy/bluetooth_connection.cpp b/esphome/components/bluetooth_proxy/bluetooth_connection.cpp
index f4504983..452f5fd8 100644
--- a/esphome/components/bluetooth_proxy/bluetooth_connection.cpp
+++ b/esphome/components/bluetooth_proxy/bluetooth_connection.cpp
@@ -163,6 +163,8 @@ void BluetoothConnection::gap_event_handler(esp_gap_ble_cb_event_t event, esp_bl

   switch (event) {
     case ESP_GAP_BLE_AUTH_CMPL_EVT:
+      if (memcmp(param->ble_security.auth_cmpl.bd_addr, this->remote_bda_, 6) != 0)
+        return;
       if (param->ble_security.auth_cmpl.success) {
         api::global_api_server->send_bluetooth_device_pairing(this->address_, true);
       } else {
diff --git a/esphome/components/esp32_ble_client/ble_client_base.cpp b/esphome/components/esp32_ble_client/ble_client_base.cpp
index 9654287f..9008e7bd 100644
--- a/esphome/components/esp32_ble_client/ble_client_base.cpp
+++ b/esphome/components/esp32_ble_client/ble_client_base.cpp
@@ -250,11 +250,15 @@ void BLEClientBase::gap_event_handler(esp_gap_ble_cb_event_t event, esp_ble_gap_
   switch (event) {
     // This event is sent by the server when it requests security
     case ESP_GAP_BLE_SEC_REQ_EVT:
+      if (memcmp(param->ble_security.ble_req.bd_addr, this->remote_bda_, 6) != 0)
+        return;
       ESP_LOGV(TAG, "[%d] [%s] ESP_GAP_BLE_SEC_REQ_EVT %x", this->connection_index_, this->address_str_.c_str(), event);
       esp_ble_gap_security_rsp(param->ble_security.ble_req.bd_addr, true);
       break;
     // This event is sent once authentication has completed
     case ESP_GAP_BLE_AUTH_CMPL_EVT:
+      if (memcmp(param->ble_security.auth_cmpl.bd_addr, this->remote_bda_, 6) != 0)
+        return;
       esp_bd_addr_t bd_addr;
       memcpy(bd_addr, param->ble_security.auth_cmpl.bd_addr, sizeof(esp_bd_addr_t));
       ESP_LOGI(TAG, "[%d] [%s] auth complete. remote BD_ADDR: %s", this->connection_index_, this->address_str_.c_str(),

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

Thanks @emontnemery, nice debugging 👍

@emontnemery
Copy link
Copy Markdown

@jagheterfredrik do you have some example of BLE devices that require pairing? Is it the igrill device you need it for?

@jagheterfredrik
Copy link
Copy Markdown
Contributor Author

I'm testing on a Wallbox Pulsar Plus (https://github.com/jagheterfredrik/wallbox-ble)

@emontnemery
Copy link
Copy Markdown

I've tested this a bit more now, with the address guards in place things seem to work fine every time 👍

@jesserockz jesserockz added this pull request to the merge queue Mar 6, 2023
Merged via the queue into esphome:dev with commit 29571a1 Mar 6, 2023
@github-actions github-actions bot locked and limited conversation to collaborators Mar 8, 2023
@jagheterfredrik jagheterfredrik deleted the just-works branch March 13, 2023 06:02
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants