Bluetooth proxy doesn't work (well) with 2022.12

[Ulrar]

The problem

I've updated this morning to 2022.12 and noticed that all of my bluetooth devices failed to show up in home assistant. I only use bluetooth_proxy over 4 esp32 relay boards.

I've tried a few things like changing from arduino to esp-idf and back, I also flashed each through serial (using edge) to make sure the partition table would be done but no change.

I don't really have any more info unfortunately, I didn't see any errors anywhere. Home Assistant just does not see the announces of my switchbot curtains or airthings devices, and keep retrying their setup over and over.

I do have a switchbot contact sensor that did not fail to setup, but it also never sent any new values. That may be normal. That's the only device I have that does not depend on active: true, so it's possible that the issue is only with active devices. I don't have other passive devices here to make sure, sadly.

I downgraded to 2022.11 and everything is back to normal, so it must be related to the bluetooth_proxy change in 2022.12 I imagine

Which version of ESPHome has the issue?

2022.12

What type of installation are you using?

Docker

Which version of Home Assistant has the issue?

No response

What platform are you using?

ESP32

Board

doit-devkit-v1 and olimex's esp32-poe, seem to affect both

Component causing the issue

bluetooth_proxy

Example YAML snippet

bluetooth_proxy:
  active: true

### Anything in the logs that might be useful for us?

```txt
Nothing in the logs

Additional information

I have a lot of Switchbot Curtains, and one Airthings Wave+. The curtains and airthings on the side of the house I updated on all failed to appear in HA after the update.

I kept the other side of the house on 2022.11, at the same time, and the curtains on that side kept working, so it's not a HA issue. Downgrading all the boards back to 2022.11 fixed everything.

[bdraco]

Do you want me to give it a try with either (or both ?) of these PRs ?

It would be great if you could test https://github.com/esphome/esphome/pull/4208

The other one is for shelly devices with native firmware (assuming 4208 fixes the issue you are seeing).

[Ulrar]

Sadly no luck, it's still missing :

          {
            "name": "",
            "address": "FA:62:0F:CF:2D:F2",
            "rssi": -57,
            "advertisement_data": [
              null,
              {
                "2409": {
                  "__type": "<class 'bytes'>",
                  "repr": "b'\\xfab\\x0f\\xcf-\\xf2\\x82\\x0f\\x00\"\\x04'"
                }
              },
              {},
              [],
              -127,
              -57,
              []
            ],
            "details": {
              "source": "esp32-relay-livingroom",
              "connector": {
                "__type": "<class 'homeassistant.components.bluetooth.models.HaBluetoothConnector'>",
                "repr": "HaBluetoothConnector(client=<class 'homeassistant.components.esphome.bluetooth.client.ESPHomeClient'>, source='esp32-relay-livingroom', can_connect=<function _async_can_connect_factory.<locals>._async_can_connect at 0x7fdd07b27c70>)"
              },
              "address_type": 1
            }
          },

I used

git fetch origin pull/4208/head:4208
git checkout 4208
pip3 install --upgrade . -vvvv
/usr/local/bin/esphome compile esp32-relay-livingroom.yaml
/usr/local/bin/esphome upload esp32-relay-livingroom.yaml

[bdraco]

Just to be sure you don't have two copies of esphome installed?

Can you give me a list of the devices and firmware versions you are running on them? I'll try to order the same devices.

[Ulrar]

I do, but the firmware version in HA does show 2023.1-dev so presumably it did compile and flash from git as expected.

The board is esp32doit-devkit-v1 and the device(s) is a switchbot curtain using the latest 6.0 firmware.

But it works fine on 2022.11 so I wonder what else might have changed in 2022.12 ? Maybe I should try re-flashing your fix through serial again to make sure it's not a weird partition problem ? I've just done it OTA

[bdraco]

switchbot curtain using the latest 6.0 firmware.

I've got the same device but I'm also running dev core which support passive scans with these devices. I'll downgrade to 2022.12.7 and see if I can replicate the issue.

But it works fine on 2022.11 so I wonder what else might have changed in 2022.12 ? Maybe I should try re-flashing your fix through serial again to make sure it's not a weird partition problem ? I've just done it OTA

It would be good to give it a shot. I'll adjust that PR to add some more logging so we know is installed in a minute and ping you when its done

[bdraco]

I pushed a change to that PR that will add the Adv data length and Scan rsp length to the logging.

Here are the two curtains I have running the 6.0 firmware. Notice that there is no zero padding in the ones I have so I get 28 bytes vs the Adv data: 02.01.06.0E.FF.69.09.FA.62.0F.CF.2D.F2.DA.0F.00.22.04.00.09.16.3D.FD.63.C0.56.00.22.04 (29) we see in your data.

[08:03:25][VV][esp32_ble_tracker:648]: Parse Result:
[08:03:25][VV][esp32_ble_tracker:665]:   Address: D1:4B:33:1F:0A:FD (RANDOM)
[08:03:25][VV][esp32_ble_tracker:667]:   RSSI: -65
[08:03:25][VV][esp32_ble_tracker:668]:   Name: ''
[08:03:25][VV][esp32_ble_tracker:676]:   Ad Flag: 6
[08:03:25][VV][esp32_ble_tracker:682]:   Manufacturer data: D1.4B.33.1F.0A.FD.13.0D.64.11.04 (11)
[08:03:25][VV][esp32_ble_tracker:693]:   Service data:
[08:03:25][VV][esp32_ble_tracker:694]:     UUID: 0xFD3D
[08:03:25][VV][esp32_ble_tracker:695]:     Data: 63.40.64.64.11.04 (6)
[08:03:25][VV][esp32_ble_tracker:698]: Adv data: 02.01.06.0E.FF.69.09.D1.4B.33.1F.0A.FD.13.0D.64.11.04.09.16.3D.FD.63.40.64.64.11.04 (28)
[08:03:25][VV][esp32_ble_tracker:699]: Adv data length: 18
[08:03:25][VV][esp32_ble_tracker:700]: Scan rsp length: 10

[08:03:25][VV][esp32_ble_tracker:648]: Parse Result:
[08:03:25][VV][esp32_ble_tracker:665]:   Address: FC:EE:36:CF:93:95 (RANDOM)
[08:03:25][VV][esp32_ble_tracker:667]:   RSSI: -64
[08:03:25][VV][esp32_ble_tracker:668]:   Name: '' 
[08:03:25][VV][esp32_ble_tracker:676]:   Ad Flag: 6
[08:03:25][VV][esp32_ble_tracker:682]:   Manufacturer data: FC.EE.36.CF.93.95.16.0F.00.22.04 (11)
[08:03:25][VV][esp32_ble_tracker:693]:   Service data:
[08:03:25][VV][esp32_ble_tracker:694]:     UUID: 0xFD3D 
[08:03:25][VV][esp32_ble_tracker:695]:     Data: 63.C0.49.00.22.04 (6)
[08:03:25][VV][esp32_ble_tracker:698]: Adv data: 02.01.06.0E.FF.69.09.FC.EE.36.CF.93.95.16.0F.00.22.04.09.16.3D.FD.63.C0.49.00.22.04 (28)
[08:03:25][VV][esp32_ble_tracker:699]: Adv data length: 18
[08:03:25][VV][esp32_ble_tracker:700]: Scan rsp length: 10

[bdraco]

@Ulrar should be good to pull and retest now. You should get this commit:

commit 170046ed256b41d720fda2c9b232e0ed388e5b9b (HEAD -> padding_in_adv_data, bdraco/padding_in_adv_data)
Author: J. Nick Koston <nick@koston.org>
Date:   Mon Dec 19 08:11:04 2022 -1000

    adjust

[Ulrar]

Aha, this time it seems to have worked, which doesn't make any sense. I wonder if it's a weird coincidence or if I somehow managed to flash from main instead of your PR earlier.

I need to test this again a few times, this is strange, but it looks like it's probably my bad.

[18:45:33][VV][esp32_ble_tracker:648]: Parse Result:
[18:45:33][VV][esp32_ble_tracker:665]:   Address: FA:62:0F:CF:2D:F2 (RANDOM)
[18:45:33][VV][esp32_ble_tracker:667]:   RSSI: -61
[18:45:33][VV][esp32_ble_tracker:668]:   Name: ''
[18:45:33][VV][esp32_ble_tracker:676]:   Ad Flag: 6
[18:45:33][VV][esp32_ble_tracker:682]:   Manufacturer data: FA.62.0F.CF.2D.F2.18.0F.64.22.04 (11)
[18:45:33][VV][esp32_ble_tracker:693]:   Service data:
[18:45:33][VV][esp32_ble_tracker:694]:     UUID: 0xFD3D
[18:45:33][VV][esp32_ble_tracker:695]:     Data: 63.C0.55.64.22.04 (6)
[18:45:33][VV][esp32_ble_tracker:698]: Adv data: 02.01.06.0E.FF.69.09.FA.62.0F.CF.2D.F2.18.0F.64.22.04.00.09.16.3D.FD.63.C0.55.64.22.04 (29)
[18:45:33][VV][esp32_ble_tracker:699]: Adv data length: 19
[18:45:33][VV][esp32_ble_tracker:700]: Scan rsp length: 10
[18:45:33][V][bluetooth_proxy:033]: Proxying packet from  - FA:62:0F:CF:2D:F2. RSSI: -61 dB
[18:45:33][VV][api.service:334]: send_bluetooth_le_advertisement_response: BluetoothLEAdvertisementResponse {
  address: 275299078974962
  name: ''
  rssi: -61
  service_data: BluetoothServiceData {
  uuid: '0xFD3D'
  data: 'c\xc0Ud"'
}
  manufacturer_data: BluetoothServiceData {
  uuid: '0x0969'
  data: '\xfab\xcf-\xf2d"'
}
  address_type: 1
}
[18:45:33][V][component:200]: Component esp32_ble_tracker took a long time for an operation (0.08 s).
[18:45:33][V][component:201]: Components should block for at most 20-30ms.

[bdraco]

Thanks for testing @Ulrar

I marked that PR ready for review

[bdraco]

The fix has been tagged for 2022.12.2

[Ulrar]

Thank you very much for this, appreciate the quick fix and help !

[bdraco]

Thanks for sticking in there and getting the debug data 👍

[txitxo0]

Thanks a lot, already working in my setup

[PetrMa]

Hello,

is already fixed also this issue? [V][api.connection:992]: Cannot send message because of TCP buffer space

[bdraco]

Hello,

is already fixed also this issue?

[V][api.connection:992]: Cannot send message because of TCP buffer space

That means you are running out of ram. You'll have to remove components until your esp32 is stable.

Check the Bluetooth proxy docs for more information

[PetrMa]

@bdraco Which components you mean? On 2022.11.x there is no problem. On 2022.12.x I´ve got this issue everytime. More info in https://github.com/esphome/issues/issues/3907 Sorry, but there is some wrong in 2022.12.x and I need would like to know what.

[bdraco]

@bdraco Which components you mean? On 2022.11.x there is no problem. On 2022.12.x I´ve got this issue everytime.

More info in https://github.com/esphome/issues/issues/3907

Sorry, but there is some wrong in 2022.12.x and I need would like to know what.

You should pursue that issue as it's not the same as the OPs here which was solved here.

[PetrMa]

@bdraco OK, is there someone who can help me with this issue, please? Currently I´am not able to upgrade from 2022.11.x. I tried some tests and it seems that there is some issue with BT proxy.

[Ulrar]

@PetrMa you need to create a new issue, and presumably someone will pick it up

[PetrMa]

@Ulrar I have https://github.com/esphome/issues/issues/3907 So I´ll wait.

[txitxo0]

Finally it doesn't work for me too, I will grab more info and open a ticket. Thannk you!