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

esp32_ble_tracker scan is not restarted after active connection when active scans are enabled #5119

Open
fightforlife opened this issue Nov 16, 2023 · 22 comments

Comments

@fightforlife
Copy link

fightforlife commented Nov 16, 2023

The problem

I have a ESP32 with Ethernet running as a bluetooth proxy for HomeAssistant.
I am using the recommended parameters on latest ESP-IDF. (scan interval, etc)

Once a day the it happens that the esp32_ble_tracker component does not restart the paused scan after a connection is made.
Then all BLE connected devices are reported as offline, since no scan is running.
This is fixed by rebooting the ESP32.
Note: I also have this problem using Wifi and/or using the arduino framework.

I have a 50mb logfile from Boot till the error happens. Below is an excerpt of the relevant parts. Since BLE is the only component running, there are no traces anymore when scan is not restarted. See at the End of the log below for the error. There is no starting scan...

Which version of ESPHome has the issue?

ESPHome version 2023.11.0b3 compiled on Nov 12 2023, 09:36:50

What type of installation are you using?

Docker

Which version of Home Assistant has the issue?

No response

What platform are you using?

ESP32-IDF

Board

ESP32 + WS5500 Ethernet

Component causing the issue

esp32_ble_tracker

Example YAML snippet

substitutions:
  name: gateway2
  friendly_name: Gateway2

esphome:
  name: ${name}
  friendly_name: ${friendly_name}

esp32:
  board: esp32doit-devkit-v1
  variant: esp32
  framework:
    type: esp-idf
    version: latest
    platform_version: 6.4.0

external_components:
  - source:
      type: local
      path: ./components
    components:
      - ethernet
      
esp32_ble_tracker:
  scan_parameters:
    active: false
    interval: 1100ms
    window: 1100ms

bluetooth_proxy:
  active: true
  cache_services: true

logger:
  level: VERBOSE
  baud_rate: 115200

api:
  encryption:
    key: !secret api_secret

ota:
  password: !secret api_secret

ethernet:
  type: W5500
  clk_pin: GPIO18
  mosi_pin: GPIO23
  miso_pin: GPIO19
  cs_pin: GPIO5
  interrupt_pin: GPIO21
  reset_pin: GPIO22
  clock_speed: 30

web_server:
  port: 80

Anything in the logs that might be useful for us?

[04:00:15][I][app:102]: ESPHome version 2023.11.0b3 compiled on Nov 12 2023, 09:36:50
[04:00:15][C][logger:416]: Logger:
[04:00:15][C][logger:417]:   Level: VERBOSE
[04:00:15][C][logger:418]:   Log Baud Rate: 115200
[04:00:15][C][logger:420]:   Hardware UART: UART0
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][C][bluetooth_proxy:088]: Bluetooth Proxy:
[04:00:15][C][bluetooth_proxy:089]:   Active: YES
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][C][esp32_ble:374]: ESP32 BLE:
[04:00:15][C][esp32_ble:375]:   MAC address: 8C:AA:B5:86:3C:5E
[04:00:15][C][esp32_ble:377]:   IO Capability: none
[04:00:15][C][esp32_ble_tracker:645]: BLE Tracker:
[04:00:15][C][esp32_ble_tracker:646]:   Scan Duration: 300 s
[04:00:15][C][esp32_ble_tracker:647]:   Scan Interval: 1100.0 ms
[04:00:15][C][esp32_ble_tracker:648]:   Scan Window: 1100.0 ms
[04:00:15][C][esp32_ble_tracker:649]:   Scan Type: PASSIVE
[04:00:15][C][esp32_ble_tracker:650]:   Continuous Scanning: True
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][C][ethernet:313]: Ethernet:
[04:00:15][C][ethernet:455]:   IP Address: 192.168.1.104
[04:00:15][C][ethernet:456]:   Hostname: 'gateway2'
[04:00:15][C][ethernet:457]:   Subnet: 255.255.255.0
[04:00:15][C][ethernet:458]:   Gateway: 192.168.1.1
[04:00:15][C][ethernet:463]:   DNS1: 192.168.1.3
[04:00:15][C][ethernet:464]:   DNS2: 0.0.0.0
[04:00:15][C][ethernet:484]:   MAC Address: 8C:AA:B5:86:3C:5F
[04:00:15][C][ethernet:489]:   Is Full Duplex: YES
[04:00:15][C][ethernet:494]:   Link Speed: 100
[04:00:15][C][ethernet:316]:   CLK Pin: 18
[04:00:15][C][ethernet:317]:   MISO Pin: 19
[04:00:15][C][ethernet:318]:   MOSI Pin: 23
[04:00:15][C][ethernet:319]:   CS Pin: 5
[04:00:15][C][ethernet:320]:   IRQ Pin: 21
[04:00:15][C][ethernet:321]:   Reset Pin: 22
[04:00:15][C][ethernet:322]:   Clock Speed: 30 MHz
[04:00:15][C][ethernet:331]:   Type: W5500
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 8 packets
[04:00:15][C][web_server:168]: Web Server:
[04:00:15][C][web_server:169]:   Address: gateway2.local:80
[04:00:15][C][mdns:115]: mDNS:
[04:00:15][C][mdns:116]:   Hostname: gateway2
[04:00:15][V][mdns:117]:   Services:
[04:00:15][V][mdns:119]:   - _esphomelib, _tcp, 6053
[04:00:15][V][mdns:121]:     TXT: friendly_name = Gateway2
[04:00:15][V][mdns:121]:     TXT: version = 2023.11.0b3
[04:00:15][V][mdns:121]:     TXT: mac = 8caab5863c5c
[04:00:15][V][mdns:121]:     TXT: platform = ESP32
[04:00:15][V][mdns:121]:     TXT: board = esp32doit-devkit-v1
[04:00:15][V][mdns:121]:     TXT: network = ethernet
[04:00:15][V][mdns:121]:     TXT: api_encryption = Noise_NNpsk0_25519_ChaChaPoly_SHA256
[04:00:15][V][mdns:119]:   - _http, _tcp, 80
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 4 packets
[04:00:15][C][ota:097]: Over-The-Air Updates:
[04:00:15][C][ota:098]:   Address: gateway2.local:3232
[04:00:15][C][ota:101]:   Using Password.
[04:00:15][C][api:139]: API Server:
[04:00:15][C][api:140]:   Address: gateway2.local:6053
[04:00:15][C][api:142]:   Using noise encryption: YES
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:15][V][bluetooth_proxy:058]: Proxying 2 packets
[04:00:16][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[04:00:16][V][esp32_ble:314]: (BLE) gap_event_handler - 3
...
...
...
...
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:26][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 3 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:27][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:28][V][bluetooth_proxy:058]: Proxying 1 packets
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:28][I][bluetooth_proxy:277]: [0] [00:1A:22:0B:07:86] Connecting v3 with cache
[09:21:28][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:21:28][V][bluetooth_proxy:097]: [1] Free connection
[09:21:28][V][bluetooth_proxy:097]: [2] Free connection
[09:21:28][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[09:21:28][V][esp32_ble:314]: (BLE) gap_event_handler - 18
[09:21:28][I][esp32_ble_client:068]: [0] [00:1A:22:0B:07:86] 0x00 Attempting BLE connection
[09:21:48][I][esp32_ble_client:086]: [0] [00:1A:22:0B:07:86] Disconnecting.
[09:21:54][V][esp-idf:000]: W (4659881) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[09:21:57][V][esp-idf:000]: W (4662886) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100

[09:21:57][V][esp-idf:000]: W (4662888) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100

[09:21:57][V][esp-idf:000]: W (4662890) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100

[09:21:57][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[09:21:57][V][esp32_ble_client:118]: [0] [00:1A:22:0B:07:86] gattc_event_handler: event=41 gattc_if=3
[09:21:57][V][esp32_ble_client:172]: [0] [00:1A:22:0B:07:86] ESP_GATTC_DISCONNECT_EVT, reason 256
[09:21:57][V][bluetooth_proxy:097]: [0] Free connection
[09:21:57][V][bluetooth_proxy:097]: [1] Free connection
[09:21:57][V][bluetooth_proxy:097]: [2] Free connection
[09:21:57][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[09:21:57][V][esp32_ble_client:118]: [0] [] gattc_event_handler: event=2 gattc_if=3
[09:21:57][V][esp32_ble_client:134]: [0] [] ESP_GATTC_OPEN_EVT
[09:21:57][W][esp32_ble_client:138]: [0] [] Connection failed, status=133
[09:21:57][V][bluetooth_proxy:097]: [0] Free connection
[09:21:57][V][bluetooth_proxy:097]: [1] Free connection
[09:21:57][V][bluetooth_proxy:097]: [2] Free connection
[09:21:57][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[09:21:57][V][esp32_ble_client:118]: [1] [] gattc_event_handler: event=41 gattc_if=4
[09:21:57][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[09:21:57][V][esp32_ble_client:118]: [2] [] gattc_event_handler: event=41 gattc_if=5
[09:21:57][W][component:214]: Component esp32_ble took a long time for an operation (0.09 s).
[09:21:57][W][component:215]: Components should block for at most 20-30ms.
[09:21:57][D][esp32_ble_tracker:266]: Starting scan...
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 2
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 7
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:57][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:57][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:21:57][V][bluetooth_proxy:058]: Proxying 2 packets
[09:21:57][I][bluetooth_proxy:277]: [0] [00:1A:22:0B:07:86] Connecting v3 with cache
[09:21:57][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:21:57][V][bluetooth_proxy:097]: [1] Free connection
[09:21:58][V][bluetooth_proxy:097]: [2] Free connection
[09:21:58][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[09:21:58][V][esp32_ble:314]: (BLE) gap_event_handler - 18
[09:21:58][I][esp32_ble_client:068]: [0] [00:1A:22:0B:07:86] 0x00 Attempting BLE connection
[09:22:17][I][esp32_ble_client:086]: [0] [00:1A:22:0B:07:86] Disconnecting.
[09:22:28][V][esp-idf:000]: W (4693259) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100

[09:22:28][V][esp-idf:000]: W (4693262) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100

[09:22:28][V][esp-idf:000]: W (4693264) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100

[09:22:28][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[09:22:28][V][esp32_ble_client:118]: [0] [00:1A:22:0B:07:86] gattc_event_handler: event=41 gattc_if=3
[09:22:28][V][esp32_ble_client:172]: [0] [00:1A:22:0B:07:86] ESP_GATTC_DISCONNECT_EVT, reason 256
[09:22:28][V][bluetooth_proxy:097]: [0] Free connection
[09:22:28][V][bluetooth_proxy:097]: [1] Free connection
[09:22:28][V][bluetooth_proxy:097]: [2] Free connection
[09:22:28][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[09:22:28][V][esp32_ble_client:118]: [0] [] gattc_event_handler: event=2 gattc_if=3
[09:22:28][V][esp32_ble_client:134]: [0] [] ESP_GATTC_OPEN_EVT
[09:22:28][W][esp32_ble_client:138]: [0] [] Connection failed, status=133
[09:22:28][V][bluetooth_proxy:097]: [0] Free connection
[09:22:28][V][bluetooth_proxy:097]: [1] Free connection
[09:22:28][V][bluetooth_proxy:097]: [2] Free connection
[09:22:28][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[09:22:28][V][esp32_ble_client:118]: [1] [] gattc_event_handler: event=41 gattc_if=4
[09:22:28][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[09:22:28][V][esp32_ble_client:118]: [2] [] gattc_event_handler: event=41 gattc_if=5
[09:22:28][W][component:214]: Component esp32_ble took a long time for an operation (0.09 s).
[09:22:28][W][component:215]: Components should block for at most 20-30ms.
[09:22:28][D][esp32_ble_tracker:266]: Starting scan...
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 2
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 7
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:28][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:28][I][bluetooth_proxy:277]: [0] [00:1A:22:0B:07:86] Connecting v3 with cache
[09:22:28][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:22:28][V][bluetooth_proxy:097]: [1] Free connection
[09:22:28][V][bluetooth_proxy:097]: [2] Free connection
[09:22:28][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[09:22:28][V][esp32_ble:314]: (BLE) gap_event_handler - 18
[09:22:28][I][esp32_ble_client:068]: [0] [00:1A:22:0B:07:86] 0x00 Attempting BLE connection
[09:22:48][I][esp32_ble_client:086]: [0] [00:1A:22:0B:07:86] Disconnecting.
[09:22:58][V][esp-idf:000]: W (4723883) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100

[09:22:58][V][esp-idf:000]: W (4723886) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100

[09:22:58][V][esp-idf:000]: W (4723887) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100

[09:22:58][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[09:22:58][V][esp32_ble_client:118]: [0] [00:1A:22:0B:07:86] gattc_event_handler: event=41 gattc_if=3
[09:22:58][V][esp32_ble_client:172]: [0] [00:1A:22:0B:07:86] ESP_GATTC_DISCONNECT_EVT, reason 256
[09:22:58][V][bluetooth_proxy:097]: [0] Free connection
[09:22:58][V][bluetooth_proxy:097]: [1] Free connection
[09:22:58][V][bluetooth_proxy:097]: [2] Free connection
[09:22:58][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[09:22:58][V][esp32_ble_client:118]: [0] [] gattc_event_handler: event=2 gattc_if=3
[09:22:58][V][esp32_ble_client:134]: [0] [] ESP_GATTC_OPEN_EVT
[09:22:58][W][esp32_ble_client:138]: [0] [] Connection failed, status=133
[09:22:58][V][bluetooth_proxy:097]: [0] Free connection
[09:22:58][V][bluetooth_proxy:097]: [1] Free connection
[09:22:58][V][bluetooth_proxy:097]: [2] Free connection
[09:22:58][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[09:22:58][V][esp32_ble_client:118]: [1] [] gattc_event_handler: event=41 gattc_if=4
[09:22:58][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[09:22:58][V][esp32_ble_client:118]: [2] [] gattc_event_handler: event=41 gattc_if=5
[09:22:58][W][component:214]: Component esp32_ble took a long time for an operation (0.09 s).
[09:22:58][W][component:215]: Components should block for at most 20-30ms.
[09:22:58][D][esp32_ble_tracker:266]: Starting scan...
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 2
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 7
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:58][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:58][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:58][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:58][I][bluetooth_proxy:277]: [0] [00:1A:22:0B:07:86] Connecting v3 with cache
[09:22:58][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:22:58][V][bluetooth_proxy:097]: [1] Free connection
[09:22:59][V][bluetooth_proxy:097]: [2] Free connection
[09:22:59][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:59][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[09:22:59][V][bluetooth_proxy:058]: Proxying 2 packets
[09:22:59][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[09:22:59][V][esp32_ble:314]: (BLE) gap_event_handler - 18
[09:22:59][I][esp32_ble_client:068]: [0] [00:1A:22:0B:07:86] 0x00 Attempting BLE connection
[09:23:09][I][bluetooth_proxy:277]: [1] [00:1A:22:0B:07:65] Connecting v3 with cache
[09:23:09][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:23:09][V][bluetooth_proxy:099]: [1] Used connection by [00:1A:22:0B:07:65]
[09:23:09][V][bluetooth_proxy:097]: [2] Free connection
[09:23:09][I][bluetooth_proxy:277]: [2] [00:1A:22:0B:06:46] Connecting v3 with cache
[09:23:09][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:86]
[09:23:09][V][bluetooth_proxy:099]: [1] Used connection by [00:1A:22:0B:07:65]
[09:23:09][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:18][I][esp32_ble_client:086]: [0] [00:1A:22:0B:07:86] Disconnecting.
[09:23:19][I][esp32_ble_client:068]: [1] [00:1A:22:0B:07:65] 0x00 Attempting BLE connection
[09:23:19][V][esp-idf:000]: W (4744208) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1

[09:23:29][V][esp-idf:000]: W (4754274) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x100

[09:23:29][V][esp-idf:000]: W (4754277) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x100

[09:23:29][V][esp-idf:000]: W (4754279) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x100

[09:23:29][V][esp-idf:000]: W (4754283) BT_APPL: gattc_conn_cb: if=3 st=0 id=259 rsn=0x2

[09:23:29][V][esp-idf:000]: W (4754289) BT_APPL: gattc_conn_cb: if=4 st=0 id=260 rsn=0x2

[09:23:29][V][esp-idf:000]: W (4754290) BT_APPL: gattc_conn_cb: if=5 st=0 id=261 rsn=0x2

[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[09:23:29][V][esp32_ble_client:118]: [0] [00:1A:22:0B:07:86] gattc_event_handler: event=41 gattc_if=3
[09:23:29][V][esp32_ble_client:172]: [0] [00:1A:22:0B:07:86] ESP_GATTC_DISCONNECT_EVT, reason 256
[09:23:29][V][bluetooth_proxy:097]: [0] Free connection
[09:23:29][V][bluetooth_proxy:099]: [1] Used connection by [00:1A:22:0B:07:65]
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[09:23:29][V][esp32_ble_client:118]: [0] [] gattc_event_handler: event=2 gattc_if=3
[09:23:29][V][esp32_ble_client:134]: [0] [] ESP_GATTC_OPEN_EVT
[09:23:29][W][esp32_ble_client:138]: [0] [] Connection failed, status=133
[09:23:29][V][bluetooth_proxy:097]: [0] Free connection
[09:23:29][V][bluetooth_proxy:099]: [1] Used connection by [00:1A:22:0B:07:65]
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[09:23:29][V][esp32_ble_client:118]: [1] [00:1A:22:0B:07:65] gattc_event_handler: event=41 gattc_if=4
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[09:23:29][V][esp32_ble_client:118]: [2] [00:1A:22:0B:06:46] gattc_event_handler: event=41 gattc_if=5
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[09:23:29][V][esp32_ble_client:118]: [0] [] gattc_event_handler: event=41 gattc_if=3
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[09:23:29][V][esp32_ble_client:118]: [1] [00:1A:22:0B:07:65] gattc_event_handler: event=41 gattc_if=4
[09:23:29][V][esp32_ble_client:172]: [1] [00:1A:22:0B:07:65] ESP_GATTC_DISCONNECT_EVT, reason 2
[09:23:29][V][bluetooth_proxy:097]: [0] Free connection
[09:23:29][V][bluetooth_proxy:097]: [1] Free connection
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 2
[09:23:29][V][esp32_ble_client:118]: [1] [] gattc_event_handler: event=2 gattc_if=4
[09:23:29][V][esp32_ble_client:134]: [1] [] ESP_GATTC_OPEN_EVT
[09:23:29][W][esp32_ble_client:138]: [1] [] Connection failed, status=133
[09:23:29][V][bluetooth_proxy:097]: [0] Free connection
[09:23:29][V][bluetooth_proxy:097]: [1] Free connection
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[09:23:29][V][esp32_ble_client:118]: [2] [00:1A:22:0B:06:46] gattc_event_handler: event=41 gattc_if=5
[09:23:29][W][component:214]: Component esp32_ble took a long time for an operation (0.25 s).
[09:23:29][W][component:215]: Components should block for at most 20-30ms.
[09:23:29][I][esp32_ble_client:068]: [2] [00:1A:22:0B:06:46] 0x00 Attempting BLE connection
[09:23:29][V][esp-idf:000]: W (4754558) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1

[09:23:29][V][bluetooth_proxy:097]: [0] Free connection
[09:23:29][V][bluetooth_proxy:097]: [1] Free connection
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][I][esp32_ble_client:086]: [2] [00:1A:22:0B:06:46] Disconnecting.
[09:23:29][I][bluetooth_proxy:277]: [0] [00:1A:22:0B:07:65] Connecting v3 with cache
[09:23:29][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:65]
[09:23:29][V][bluetooth_proxy:097]: [1] Free connection
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:29][I][esp32_ble_client:068]: [0] [00:1A:22:0B:07:65] 0x00 Attempting BLE connection
[09:23:29][V][esp-idf:000]: W (4754756) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1

[09:23:29][I][bluetooth_proxy:277]: [1] [00:1A:22:0B:07:86] Connecting v3 with cache
[09:23:29][V][bluetooth_proxy:099]: [0] Used connection by [00:1A:22:0B:07:65]
[09:23:29][V][bluetooth_proxy:099]: [1] Used connection by [00:1A:22:0B:07:86]
[09:23:29][V][bluetooth_proxy:099]: [2] Used connection by [00:1A:22:0B:06:46]
[09:23:40][V][esp-idf:000]: E (4765815) BT_L2CAP: L2CAP got BLE scanner conn_comp in bad state: 0

[09:23:40][V][esp-idf:000]: E (4765880) BT_L2CAP: L2CAP - rcvd ACL for unknown handle:0 ls:0 cid:6 opcode:11 cur count:0

[09:23:49][I][esp32_ble_client:086]: [0] [00:1A:22:0B:07:65] Disconnecting.
[09:23:49][I][esp32_ble_client:068]: [1] [00:1A:22:0B:07:86] 0x00 Attempting BLE connection
[09:23:49][V][esp-idf:000]: W (4774758) BT_L2CAP: L2CAP - LE - cannot start new connection at conn st: 1

[09:23:49][I][esp32_ble_client:086]: [1] [00:1A:22:0B:07:86] Disconnecting.
[09:25:10][V][esp-idf:000]: W (4855915) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[13:35:53][V][web_server_idf:066]: Enter AsyncWebServer::request_handler. method=1, uri=/
[13:35:53][V][web_server_idf:066]: Enter AsyncWebServer::request_handler. method=1, uri=/events
[13:35:53][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[13:35:53][V][json:058]: Size after shrink 132 bytes

Additional information

No response

@bdraco
Copy link
Member

bdraco commented Nov 20, 2023

It looks like your esp is always trying to establish a connection or disconnecting so it won’t start the scan until the connect or disconnect finishes

There are some known issues with esp-idf taking a long time to disconnect which are fixed in 4.4.6, unfortunately ESPHome still uses 4.4.5

@fightforlife
Copy link
Author

That sounds promising!
But currently I am using latest esp-idf which should result in v5.1.
Do you have a link to the relevant changes on 4.4.6 maybe they were not ported to 5.1?

In the meantime I will try with esp-idf 5.1.2 and 4.4.6.

bdraco added a commit to esphome/esphome that referenced this issue Nov 20, 2023
It looks like this is no longer used as we always set the state
to ESTABLISHED

Noticed while investigating esphome/issues#5119
@bdraco
Copy link
Member

bdraco commented Nov 20, 2023

https://github.com/espressif/esp-idf/releases/tag/v4.4.6

Fixed BLE disconnection failure on ESP32 (espressif/esp-idf@efdd085)

@fightforlife
Copy link
Author

I checked the code for the dfferent Branches, and it seems that the fix is already availablwe atleast in 5.2 5.1 5.0 4.4 4.3.
So I think this is another case. Is there a possibility to compile with esp-idf logs? Or should i just try with very verbose.

@jesserockz
Copy link
Member

Unfortunately 4.4.6 also has not made it onto the platformio registry which is kinda annoying
https://registry.platformio.org/tools/platformio/framework-espidf/versions

@fightforlife
Copy link
Author

Current esphome beta with esp-idf 5.1.1 seems to be much more stable.
Will wait 1-2 days before closing.

@fightforlife
Copy link
Author

ESP IDF 5.1.1 was now stable for 2 day straight. This never happend before. So I will close this as solved with espidf 5.1.1
Most likely also 4.4.6, but I did no test.

@bdraco
Copy link
Member

bdraco commented Dec 5, 2023

Lets leave it open until we bump ESP-IDF since we know what the solution is.

At this point we are waiting for platformio to release the new 4.4.6 idf

@fightforlife
Copy link
Author

fightforlife commented Dec 16, 2023

It started happening again after 2 weeks with 5.1.1.
Need some time to get logs.

@blind-oracle
Copy link

Same here for me also with Ethernet ESP32. Some random lithium BMS that's lying near the ESP is lost from Home Assistant after some hours of uptime. Then, after the ESP reboot it reappears instantly.

Gonna try setting active: false for proxy and tracker and see if that helps. Or switch to beta.

@bdraco
Copy link
Member

bdraco commented Jan 1, 2024

Looks like 4.4.6 is now available on platform IO

@bdraco
Copy link
Member

bdraco commented Jan 1, 2024

As is 5.1.2

@fightforlife
Copy link
Author

Had this happen again this night with 5.1.2.
Will have to find a good way to log this.

@bdraco
Copy link
Member

bdraco commented Jan 5, 2024

Maybe you have a device stuck in a connecting state somehow.

Maybe add logging of the number of each of these

  int connecting = 0;
  int discovered = 0;
  int searching = 0;
  int disconnecting = 0;

https://github.com/esphome/esphome/blob/a2e152ad1252444a9d12e3a129270f62076d4c12/esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp#L102

@loca5790
Copy link

I'm having the same issue, nearly identical yaml. Any success?

@fightforlife
Copy link
Author

Last week I had this happening 1-2 per day.
Then I recompiled again with esp-idf 5.1.2 and the esphome beta branch.
Now it is already stable for 3 days in a row.
I am pretty sure it will start happening again. Then I will add the logging mentioned above.

@blind-oracle
Copy link

I've fallen back to active: false and it seems to be stable that way.

@bdraco bdraco changed the title esp32_ble_tracker scan is not restarted after active connection esp32_ble_tracker scan is not restarted after active connection when active scans are enabled Jan 24, 2024
@bdraco
Copy link
Member

bdraco commented Jan 24, 2024

I have active: false on all my ESPs so that likely why I never saw this issue

@bdraco bdraco self-assigned this Feb 17, 2024
@bdraco
Copy link
Member

bdraco commented Feb 17, 2024

I had one fail today with 4.4.6 and passive. It took > 1000 hours of uptime to hit the failure case unfortunately.

@bdraco
Copy link
Member

bdraco commented Feb 18, 2024

5.2 is out with some more BLE fixes.

@fightforlife
Copy link
Author

fightforlife commented Mar 3, 2024

I created an automation in HA whcih reboots my btproxy when at least one BT Devcie is not seen in 5 minutes.
it is just a bandage, but at least it heals itself. Uptime is quite a mixed bag.
Maximum being around 30h
image

bdraco added a commit to esphome/esphome that referenced this issue May 8, 2024
@bdraco
Copy link
Member

bdraco commented May 8, 2024

4.4.7 has some more fixes
https://github.com/espressif/esp-idf/releases/tag/v4.4.7

Fixed scan event timeout on ESP32. ( espressif/esp-idf@597a4d4)

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

No branches or pull requests

5 participants