Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BLE client "DISCONNECTING" state is terminal and leaks btproxy connections #6701

Open
dotdoom opened this issue Jan 21, 2025 · 18 comments · May be fixed by esphome/esphome#8297
Open

BLE client "DISCONNECTING" state is terminal and leaks btproxy connections #6701

dotdoom opened this issue Jan 21, 2025 · 18 comments · May be fixed by esphome/esphome#8297

Comments

@dotdoom
Copy link

dotdoom commented Jan 21, 2025

The problem

It looks like disconnect() may mark a Bluetooth connection as DISCONNECTING if some conditions are not satisfied, which is a terminal state in this FSM and makes connection unusable.

Relevant code:

https://github.com/esphome/esphome/blob/b454f63b3604d766abb038fe3c0f79dc20ab5cad/esphome/components/esp32_ble_client/ble_client_base.cpp#L125-L142

As a result, connection becomes unusable. Repeat this twice, and esp32 is out of connection slots and Bluetooth is dead on that one.

Which version of ESPHome has the issue?

2024.12.2

What type of installation are you using?

pip

Which version of Home Assistant has the issue?

2025.1.3

What platform are you using?

ESP32-IDF

Board

Olimex PoE

Component causing the issue

bluetooth_proxy

YAML Config

esp32:
  board: esp32-poe
  framework:
    type: esp-idf

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

bluetooth_proxy:
  id: btproxy
  active: true

# The following is likely irrelevant but included for posterity:

api:
  encryption:
    key: !secret api_encryption_key

status_led:
  pin: GPIO2

ethernet:
  type: LAN8720
  mdc_pin: GPIO23
  mdio_pin: GPIO18
  clk_mode: GPIO17_OUT
  phy_addr: 0
  power_pin: GPIO12
  domain: ""

text_sensor:
- platform: ethernet_info
  ip_address:
    name: "Device IP (Ethernet)"
  mac_address:
    name: "Device MAC (Ethernet)"

logger:

sensor:
- platform: uptime
  name: "Uptime"

button:
- platform: restart
  name: "ESP chip restart"
  entity_category: diagnostic

ota:
  - platform: esphome
    password: !secret ota_password

Anything in the logs that might be useful for us?

2025-01-21T11:56:22.749711+00:00 btproxy-c257a8 btproxy-c257a8[esp32_ble_client] [D][esp32_ble_client:171]: [0] [04:EE:03:BC:C5:2F] ESP_GATTC_DISCONNECT_EVT, reason 256
2025-01-21T11:56:22.766376+00:00 btproxy-c257a8 btproxy-c257a8[esp32_ble_tracker] [D][esp32_ble_tracker:273]: Starting scan...
2025-01-21T11:56:22.910660+00:00 btproxy-c257a8 btproxy-c257a8[esp-idf] [D][esp-idf:000]#033[1;31m[BTU_TASK]#033[0;36m: #033[0;33mW (68318623) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1#033[0m
2025-01-21T11:56:23.337690+00:00 btproxy-c257a8 btproxy-c257a8[esp-idf] [D][esp-idf:000]#033[1;31m[BTU_TASK]#033[0;36m: #033[0;31mE (68319049) BT_L2CAP: L2CAP got BLE scanner conn_comp in bad state: 0#033[0m
2025-01-21T11:56:23.424043+00:00 btproxy-c257a8 btproxy-c257a8[esp-idf] [D][esp-idf:000]#033[1;31m[BTU_TASK]#033[0;36m: #033[0;33mW (68319135) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e#033[0m
2025-01-21T11:56:42.875170+00:00 btproxy-c257a8 btproxy-c257a8[esp32_ble_client] [I][esp32_ble_client:084]: [0] [80:6F:B0:A9:EC:25] Disconnecting.
2025-01-21T11:56:42.887162+00:00 btproxy-c257a8 btproxy-c257a8[esp-idf] [D][esp-idf:000]#033[1;31m[BTU_TASK]#033[0;36m: #033[0;33mW (68338599) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1#033[0m
2025-01-21T11:57:03.123322+00:00 btproxy-c257a8 btproxy-c257a8[bluetooth_proxy] [W][bluetooth_proxy:272]: [0] [80:6F:B0:A9:EC:25] Connection request ignored, device is disconnecting
2025-01-21T11:57:43.377583+00:00 btproxy-c257a8 btproxy-c257a8[bluetooth_proxy] [W][bluetooth_proxy:272]: [0] [80:6F:B0:A9:EC:25] Connection request ignored, device is disconnecting

...

Additional information

The problem was discovered following my post:

https://community.home-assistant.io/t/bt-proxy-btproxy-suddenly-stops-discovering-debugging/832665

Looks like related problems have been seen before:

https://community.home-assistant.io/t/esphome-bluetooth-ble-proxy-stops-working/649181/14

dotdoom added a commit to dotdoom/esphome that referenced this issue Jan 23, 2025
@fightforlife
Copy link

fightforlife commented Jan 28, 2025

I can also reproduce this with 5 eq3 thermostats that need a short active connection to update the status.


07:43:50	[VV	][esp-idf:000]�[1;31m[BTU_TASK]�[0;38m	
�[0;33mW (40893086) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
07:43:50	[VV	][esp-idf:000]�[1;31m[BTU_TASK]�[0;38m	
�[0;33mW (40893095) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x3e
07:43:51	[VV	][api.service:938]	
on_bluetooth_device_request: BluetoothDeviceReque
07:43:51	[I]	[esp32_ble_client:128]	
[0] [00:1A:22:0B:07:65] Disconnecting.
07:43:51	[D]	[esp32_ble_tracker:115]	
connecting: 0, discovered: 0, searching: 0, disconnecting: 3

@bdraco
Copy link
Member

bdraco commented Feb 21, 2025

Got a few stuck disconnecting. Noticed this while adding some more logging in Bluetooth-Devices/habluetooth#154 and there were less paths to the device than expected

Image
[17:21:40][C][esp32_ble_tracker:677]: BLE Tracker:
[17:21:40][C][esp32_ble_tracker:678]:   Scan Duration: 300 s
[17:21:40][C][esp32_ble_tracker:679]:   Scan Interval: 320.0 ms
[17:21:40][C][esp32_ble_tracker:680]:   Scan Window: 30.0 ms
[17:21:40][C][esp32_ble_tracker:681]:   Scan Type: PASSIVE
[17:21:40][C][esp32_ble_tracker:682]:   Continuous Scanning: YES
[17:21:40][C][esp32_ble_tracker:683]:   Scanner Idle: NO
[17:21:40][C][esp32_ble_tracker:684]:   Scan End: YES
[17:21:40][C][esp32_ble_tracker:685]:   Connecting: 0, discovered: 0, searching: 0, disconnecting: 1
[17:21:40][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:21:40][C][esp32_ble_client:048]:   Address: 78:9C:85:0A:94:40
[17:21:40][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:21:40][C][esp32_ble_client:083]:   State: DISCONNECTING
[17:21:40][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:21:40][C][esp32_ble_client:048]:   Address: 
[17:21:40][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:21:40][C][esp32_ble_client:083]:   State: IDLE
[17:21:41][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:21:41][C][esp32_ble_client:048]:   Address: 
[17:21:41][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:21:41][C][esp32_ble_client:083]:   State: IDLE
[17:22:27][C][esp32_ble_tracker:677]: BLE Tracker:
[17:22:27][C][esp32_ble_tracker:678]:   Scan Duration: 300 s
[17:22:27][C][esp32_ble_tracker:679]:   Scan Interval: 320.0 ms
[17:22:27][C][esp32_ble_tracker:680]:   Scan Window: 30.0 ms
[17:22:27][C][esp32_ble_tracker:681]:   Scan Type: PASSIVE
[17:22:27][C][esp32_ble_tracker:682]:   Continuous Scanning: YES
[17:22:27][C][esp32_ble_tracker:683]:   Scanner Idle: NO
[17:22:27][C][esp32_ble_tracker:684]:   Scan End: YES
[17:22:27][C][esp32_ble_tracker:685]:   Connecting: 0, discovered: 0, searching: 0, disconnecting: 2
[17:22:27][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:22:27][C][esp32_ble_client:048]:   Address: 78:9C:85:0A:94:40
[17:22:27][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:22:27][C][esp32_ble_client:083]:   State: DISCONNECTING
[17:22:27][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:22:27][C][esp32_ble_client:048]:   Address: 10:76:36:15:59:32
[17:22:27][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:22:27][C][esp32_ble_client:083]:   State: DISCONNECTING
[17:22:27][C][bluetooth_proxy.connection:017]: BLE Connection:
[17:22:27][C][esp32_ble_client:048]:   Address: 
[17:22:27][C][esp32_ble_client:049]:   Auto-Connect: FALSE
[17:22:27][C][esp32_ble_client:083]:   State: IDLE

@bdraco
Copy link
Member

bdraco commented Feb 21, 2025

2025-02-21 17:27:26.222 INFO (MainThread) [habluetooth.base_scanner] entryclosetgliproxy (08:3A:8D:B3:75:A4): Bluetooth scanner has gone quiet for 90s, check logs on the scanner device for more information
2025-02-21 17:27:56.258 INFO (MainThread) [habluetooth.base_scanner] livingroomgliproxy (B0:B2:1C:7C:62:58): Bluetooth scanner has gone quiet for 90s, check logs on the scanner device for more information

@bdraco
Copy link
Member

bdraco commented Feb 21, 2025

Looks like there is a race if we call disconnect while connecting

@bdraco
Copy link
Member

bdraco commented Feb 22, 2025

Fix can be tested with 2025.2.x by adding the following to your yaml and rebuilding

@probot-esphome
Copy link

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

@dotdoom
Copy link
Author

dotdoom commented Feb 22, 2025

Great, flashed that on 2 out of 4 btproxies, will report how it goes. Thanks

@dotdoom
Copy link
Author

dotdoom commented Feb 23, 2025

Update after ~24h run: I have not observed a substantial improvement in my situation. Running esphome 2025.2.0, with the snippet from #6701 (comment) which resolved to git rev 370c87536d0782426df005c8978886296cf781e1.

Average uptime (before auto-restart due to no scan within 15-min interval) was about 6 hours. Looks like the culprit is still there in "Disconnecting before connected" logs.

Log samples:

  • btproxy-c25b74 going silent 2025-02-23 00:50 UTC
    2025-02-23T00:48:02.593975+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 0
    2025-02-23T00:48:21.415688+00:00 btproxy btproxy-c25b74 [I][bluetooth_proxy:282]: [1] [D8:71:4D:96:CB:1B] Connecting v3 with cache
    2025-02-23T00:48:21.422601+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:48:22.546396+00:00 btproxy btproxy-c25b74 [W][esp32_ble_client:129]: [0] [60:98:66:B8:26:93] Disconnecting before connected
    2025-02-23T00:48:22.552544+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 1
    2025-02-23T00:48:22.554233+00:00 btproxy btproxy-c25b74 [I][esp32_ble_client:110]: [1] [D8:71:4D:96:CB:1B] 0x00 Attempting BLE connection
    2025-02-23T00:48:22.557921+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34815578) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:48:22.565878+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 1
    2025-02-23T00:48:32.592648+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825612) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100
    2025-02-23T00:48:32.593927+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825615) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100
    2025-02-23T00:48:32.595047+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825616) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100
    2025-02-23T00:48:32.603507+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825623) BT_APPL: gattc_conn_cb: if=3 st=0 id=259 rsn=0x2
    2025-02-23T00:48:32.604801+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825626) BT_APPL: gattc_conn_cb: if=4 st=0 id=260 rsn=0x2
    2025-02-23T00:48:32.605881+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825627) BT_APPL: gattc_conn_cb: if=5 st=0 id=261 rsn=0x2
    2025-02-23T00:48:32.610188+00:00 btproxy btproxy-c25b74 [D][esp32_ble_client:247]: [0] [60:98:66:B8:26:93] ESP_GATTC_DISCONNECT_EVT, reason 256
    2025-02-23T00:48:32.617608+00:00 btproxy btproxy-c25b74 [D][esp32_ble_client:247]: [1] [D8:71:4D:96:CB:1B] ESP_GATTC_DISCONNECT_EVT, reason 2
    2025-02-23T00:48:32.624499+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 0
    2025-02-23T00:48:32.625856+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:282]: Starting scan...
    2025-02-23T00:48:32.628159+00:00 btproxy btproxy-c25b74 [D][sensor:093]: 'BLE scans finished': Sending state 445.00000  with 0 decimals of accuracy
    2025-02-23T00:48:32.635384+00:00 btproxy btproxy-c25b74 [D][script:077]: Script 'restart_after_delay' restarting (mode: restart)
    2025-02-23T00:48:32.731834+00:00 btproxy btproxy-c25b74 [I][bluetooth_proxy:282]: [0] [D8:71:4D:96:CB:1B] Connecting v3 with cache
    2025-02-23T00:48:32.738360+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:48:32.739596+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:231]: Pausing scan to make connection...
    2025-02-23T00:48:32.755688+00:00 btproxy btproxy-c25b74 [I][esp32_ble_client:110]: [0] [D8:71:4D:96:CB:1B] 0x00 Attempting BLE connection
    2025-02-23T00:48:32.759179+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34825779) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:48:32.763984+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 0
    2025-02-23T00:48:35.026813+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: E (34828046) BT_L2CAP: L2CAP got BLE scanner conn_comp in bad state: 0
    2025-02-23T00:48:35.115985+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34828136) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
    2025-02-23T00:48:50.791982+00:00 btproxy btproxy-c25b74 [D][sensor:093]: 'btproxy connections free': Sending state 2.00000  with 0 decimals of accuracy
    2025-02-23T00:48:51.140887+00:00 btproxy btproxy-c25b74 [D][sensor:093]: 'ESP chip uptime': Sending state 34843.34375 s with 0 decimals of accuracy
    2025-02-23T00:48:52.731339+00:00 btproxy btproxy-c25b74 [W][esp32_ble_client:129]: [0] [D8:71:4D:96:CB:1B] Disconnecting before connected
    2025-02-23T00:48:52.734937+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 1
    2025-02-23T00:49:50.792340+00:00 btproxy btproxy-c25b74 [D][sensor:093]: 'btproxy connections free': Sending state 2.00000  with 0 decimals of accuracy
    2025-02-23T00:49:51.141106+00:00 btproxy btproxy-c25b74 [D][sensor:093]: 'ESP chip uptime': Sending state 34903.34375 s with 0 decimals of accuracy
    2025-02-23T00:49:59.599269+00:00 btproxy btproxy-c25b74 [I][bluetooth_proxy:282]: [1] [80:6F:B0:59:2A:52] Connecting v3 with cache
    2025-02-23T00:49:59.607516+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 1
    2025-02-23T00:49:59.609240+00:00 btproxy btproxy-c25b74 [I][esp32_ble_client:110]: [1] [80:6F:B0:59:2A:52] 0x00 Attempting BLE connection
    2025-02-23T00:49:59.612911+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34912633) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:49:59.621252+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 1
    2025-02-23T00:50:02.548059+00:00 btproxy btproxy-c25b74 [I][bluetooth_proxy:282]: [2] [60:98:66:B8:26:93] Connecting v3 with cache
    2025-02-23T00:50:02.555096+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 1, searching: 0, disconnecting: 1
    2025-02-23T00:50:19.605830+00:00 btproxy btproxy-c25b74 [W][esp32_ble_client:129]: [1] [80:6F:B0:59:2A:52] Disconnecting before connected
    2025-02-23T00:50:19.615010+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 2
    2025-02-23T00:50:19.616729+00:00 btproxy btproxy-c25b74 [I][esp32_ble_client:110]: [2] [60:98:66:B8:26:93] 0x00 Attempting BLE connection
    2025-02-23T00:50:19.620542+00:00 btproxy btproxy-c25b74 [D][esp-idf:000][BTU_TASK]: W (34932640) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:50:19.626308+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 2
    2025-02-23T00:50:22.548547+00:00 btproxy btproxy-c25b74 [W][esp32_ble_client:129]: [2] [60:98:66:B8:26:93] Disconnecting before connected
    2025-02-23T00:50:22.552322+00:00 btproxy btproxy-c25b74 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 3
    
  • btproxy-c257a8 going silent 2025-02-23 01:00 UTC
    2025-02-23T00:52:54.016348+00:00 btproxy btproxy-c257a8 [I][bluetooth_proxy:286]: [0] [80:6F:B0:59:2A:52] Connecting v3 without cache
    2025-02-23T00:52:54.027485+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:52:54.031933+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:231]: Pausing scan to make connection...
    2025-02-23T00:52:54.042700+00:00 btproxy btproxy-c257a8 [I][esp32_ble_client:110]: [0] [80:6F:B0:59:2A:52] 0x00 Attempting BLE connection
    2025-02-23T00:52:54.057546+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 0
    2025-02-23T00:52:58.195783+00:00 btproxy btproxy-c257a8 [I][bluetooth_proxy:286]: [1] [FC:A8:9B:F2:36:6B] Connecting v3 without cache
    2025-02-23T00:52:58.203125+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:53:14.005709+00:00 btproxy btproxy-c257a8 [W][esp32_ble_client:129]: [0] [80:6F:B0:59:2A:52] Disconnecting before connected
    2025-02-23T00:53:14.009283+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 1
    2025-02-23T00:53:14.011287+00:00 btproxy btproxy-c257a8 [I][esp32_ble_client:110]: [1] [FC:A8:9B:F2:36:6B] 0x00 Attempting BLE connection
    2025-02-23T00:53:14.017844+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8599275) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:53:14.026253+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 1
    2025-02-23T00:53:18.190756+00:00 btproxy btproxy-c257a8 [W][esp32_ble_client:129]: [1] [FC:A8:9B:F2:36:6B] Disconnecting before connected
    2025-02-23T00:53:18.194588+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 2
    2025-02-23T00:53:24.054297+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609311) BT_APPL: gattc_conn_cb: if=3 st=0 id=259 rsn=0x100
    2025-02-23T00:53:24.055579+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609314) BT_APPL: gattc_conn_cb: if=4 st=0 id=260 rsn=0x100
    2025-02-23T00:53:24.056792+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609315) BT_APPL: gattc_conn_cb: if=5 st=0 id=261 rsn=0x100
    2025-02-23T00:53:24.065463+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609322) BT_APPL: gattc_conn_cb: if=3 st=0 id=515 rsn=0x2
    2025-02-23T00:53:24.067646+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609326) BT_APPL: gattc_conn_cb: if=4 st=0 id=516 rsn=0x2
    2025-02-23T00:53:24.068935+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609327) BT_APPL: gattc_conn_cb: if=5 st=0 id=517 rsn=0x2
    2025-02-23T00:53:24.074588+00:00 btproxy btproxy-c257a8 [D][esp32_ble_client:247]: [0] [80:6F:B0:59:2A:52] ESP_GATTC_DISCONNECT_EVT, reason 256
    2025-02-23T00:53:24.083229+00:00 btproxy btproxy-c257a8 [D][esp32_ble_client:247]: [1] [FC:A8:9B:F2:36:6B] ESP_GATTC_DISCONNECT_EVT, reason 2
    2025-02-23T00:53:24.090342+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 0
    2025-02-23T00:53:24.091728+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:282]: Starting scan...
    2025-02-23T00:53:24.094022+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'BLE scans finished': Sending state 67.00000  with 0 decimals of accuracy
    2025-02-23T00:53:24.101115+00:00 btproxy btproxy-c257a8 [D][script:077]: Script 'restart_after_delay' restarting (mode: restart)
    2025-02-23T00:53:24.341919+00:00 btproxy btproxy-c257a8 [I][bluetooth_proxy:286]: [0] [80:6F:B0:59:2A:52] Connecting v3 without cache
    2025-02-23T00:53:24.351551+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:53:24.353310+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:231]: Pausing scan to make connection...
    2025-02-23T00:53:24.362938+00:00 btproxy btproxy-c257a8 [I][bluetooth_proxy:286]: [1] [FC:A8:9B:F2:36:6B] Connecting v3 without cache
    2025-02-23T00:53:24.370158+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 2, searching: 0, disconnecting: 0
    2025-02-23T00:53:24.372244+00:00 btproxy btproxy-c257a8 [I][esp32_ble_client:110]: [0] [80:6F:B0:59:2A:52] 0x00 Attempting BLE connection
    2025-02-23T00:53:24.375703+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8609634) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:53:24.385220+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 1, searching: 0, disconnecting: 0
    2025-02-23T00:53:37.585292+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'btproxy connections free': Sending state 1.00000  with 0 decimals of accuracy
    2025-02-23T00:53:44.347867+00:00 btproxy btproxy-c257a8 [W][esp32_ble_client:129]: [0] [80:6F:B0:59:2A:52] Disconnecting before connected
    2025-02-23T00:53:44.352111+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 1
    2025-02-23T00:53:44.354080+00:00 btproxy btproxy-c257a8 [I][esp32_ble_client:110]: [1] [FC:A8:9B:F2:36:6B] 0x00 Attempting BLE connection
    2025-02-23T00:53:44.357636+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8629616) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:53:44.363382+00:00 btproxy btproxy-c257a8 [W][esp32_ble_client:129]: [1] [FC:A8:9B:F2:36:6B] Disconnecting before connected
    2025-02-23T00:53:44.367249+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 2
    2025-02-23T00:53:52.227363+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'ESP chip uptime': Sending state 8636.67676 s with 0 decimals of accuracy
    2025-02-23T00:54:04.588149+00:00 btproxy btproxy-c257a8 [W][bluetooth_proxy:272]: [0] [80:6F:B0:59:2A:52] Connection request ignored, device is disconnecting
    2025-02-23T00:54:04.595241+00:00 btproxy btproxy-c257a8 [W][bluetooth_proxy:272]: [1] [FC:A8:9B:F2:36:6B] Connection request ignored, device is disconnecting
    2025-02-23T00:54:36.565069+00:00 btproxy btproxy-c257a8 [I][bluetooth_proxy:286]: [2] [80:6F:B0:D7:34:D1] Connecting v3 without cache
    2025-02-23T00:54:36.572402+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 1, searching: 0, disconnecting: 2
    2025-02-23T00:54:36.574321+00:00 btproxy btproxy-c257a8 [I][esp32_ble_client:110]: [2] [80:6F:B0:D7:34:D1] 0x00 Attempting BLE connection
    2025-02-23T00:54:36.578828+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8681836) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1
    2025-02-23T00:54:36.587798+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 1, discovered: 0, searching: 0, disconnecting: 2
    2025-02-23T00:54:37.581375+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'btproxy connections free': Sending state 0.00000  with 0 decimals of accuracy
    2025-02-23T00:54:52.231818+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'ESP chip uptime': Sending state 8696.68066 s with 0 decimals of accuracy
    2025-02-23T00:54:56.557312+00:00 btproxy btproxy-c257a8 [W][esp32_ble_client:129]: [2] [80:6F:B0:D7:34:D1] Disconnecting before connected
    2025-02-23T00:54:56.563691+00:00 btproxy btproxy-c257a8 [D][esp32_ble_tracker:115]: connecting: 0, discovered: 0, searching: 0, disconnecting: 3
    2025-02-23T00:55:37.580010+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'btproxy connections free': Sending state 0.00000  with 0 decimals of accuracy
    2025-02-23T00:55:52.230448+00:00 btproxy btproxy-c257a8 [D][sensor:093]: 'ESP chip uptime': Sending state 8756.67871 s with 0 decimals of accuracy
    2025-02-23T00:56:08.297346+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: E (8773553) BT_L2CAP: L2CAP got BLE scanner conn_comp in bad state: 0
    2025-02-23T00:56:08.383553+00:00 btproxy btproxy-c257a8 [D][esp-idf:000][BTU_TASK]: W (8773639) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x3e
    

@dotdoom
Copy link
Author

dotdoom commented Feb 23, 2025

I find the journey of D8:71:4D:96:CB:1B (an Airthings Wave+ device) in btproxy-c25b74 particularly interesting. After failing connect on slot #1 ("ESP_GATTC_DISCONNECT_EVT, reason 2"), it went for a retry in slot #0 within 130ms and soon triggered a "Disconnecting before connected".

Similarly 80:6F:B0:59:2A:52 (another Airthings Wave+) in btproxy-c257a8.

Could it be a race condition where "disconnect" event has not been propagated properly, and esphome went for a reconnect, then when "disconnect" eventually get to HA, HA issued a manual disconnect but this time affecting "connection in-progress" slot #1 (addressed by peer MAC)? Without much knowledge of btproxy details I am only speculating at this point.

There's also a theme: egrep -B1 "reason 2$" has a consistent "reason 256" preceding it within milliseconds:

[D][esp32_ble_client:247]: [0] [80:6F:B0:59:2A:52] ESP_GATTC_DISCONNECT_EVT, reason 256
[D][esp32_ble_client:247]: [1] [FC:A8:9B:F2:36:6B] ESP_GATTC_DISCONNECT_EVT, reason 2

reason 256=0x100=ESP_GATT_CONN_CONN_CANCEL, reason 2 I couldn't find from the docs (source).

@bdraco
Copy link
Member

bdraco commented Feb 23, 2025

Looks like we cannot change the state to disconnecting if we are connecting until the connection callback comes as the scanner will start another connection attempt as soon as we change the state to disconnecting which means we have two in flight and the failure happens.

So we need some type of other flag on the connection to signal we want to disconnect the connection as soon as we can when we want to disconnect while already connecting that doesn't change the state

It means we can never go directly from connecting to disconnecting and when we set to idle we must clear the want_disconnect flag as well as check it every time the state changes.... messy

@bdraco
Copy link
Member

bdraco commented Feb 23, 2025

@dotdoom I updated the PR for the finding above, can you try again? Please note that esp32_ble_tracker has to be included in the yaml as well now

esphome/esphome#8297

@dotdoom
Copy link
Author

dotdoom commented Feb 23, 2025

@bdraco on it. Fetched both components externally, 2 out of 4 proxies are running patched to 3f47f72.

@bdraco
Copy link
Member

bdraco commented Feb 23, 2025

I'm flying most of the day, but should still have wifi if it works in flight so I should be able to do another turn if needed.

Feel free to reach out on discord (same handle) when you have the latest results.

@bdraco
Copy link
Member

bdraco commented Feb 23, 2025

I pushed a change with a bit more logging (not a functional change so no need to update again if everything is going well)

@dotdoom
Copy link
Author

dotdoom commented Feb 24, 2025

@bdraco thank you, the version from 3f47f72 is most reliable. Getting to 24h uptime now (with previous, albeit rare record being 48h so I will let it bake a tad more).

Observations are positive:

  • btproxies are discovering devices (confirmed with the new Blutooth advert monitor from HA 2025.02)
  • there are connections made, according to the esphome log
  • no "ESP_GATTC_DISCONNECT_EVT, reason 2" in the esphome log - the only ones are 62 (ESP_GATT_CONN_FAIL_ESTABLISH) and a handful of 256 (ESP_GATT_CONN_CONN_CANCEL)
  • there are still 3 available connection slots for each as I'm writing this

I kept the 2 proxies at 3f47f72 untouched to keep them running for more, and flashed the latest from esphome/esphome#8297 to the other two.

Do you have interest in any specific logs at all?

@bdraco
Copy link
Member

bdraco commented Feb 24, 2025

Thanks for the update. I'm glad its going well so far.

Do you have interest in any specific logs at all?

Only if there are new errors.

I have it running on 12 of mine and so far so good

@dotdoom
Copy link
Author

dotdoom commented Feb 25, 2025

Alright, on the uptime graph it's a clear win, and no immediately noticeable difference in BLE device reachability or measurement latency. Thank you, @bdraco !

Image

@bdraco
Copy link
Member

bdraco commented Feb 25, 2025

Great news. We will get this shipped. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants