search

espressif / arduino-esp32

Arduino core for the ESP32
GNU Lesser General Public License v2.1
13.31k stars 7.35k forks source link

[BLE Client] Deadlock on getService #7720

Open jpmeijers opened 1 year ago

jpmeijers commented 1 year ago

Board

ESP32-WROOM-32D

Device Description

FTDI IC and voltage regulator to USB

Hardware Configuration

None

Version

v2.0.6

IDE Name

Arduino IDE (tried both 1.8.19 and 2.0.3)

Operating System

Ubuntu 22.04

Flash frequency

80MHz

PSRAM enabled

yes

Upload speed

921600

Description

ESP intermittently deadlocks on calling pClient->getService(serviceUUID).

Sketch

BLEClient *pClient = BLEDevice::createClient();
  if (pClient == nullptr) {
    commSerial.print("Failed to create client");
    return false;
  }

  pClient->setClientCallbacks(new MyClientCallback());

  commSerial.println(" - Connecting to device");
  pClient->connect(device);

  // https://github.com/nkolban/esp32-snippets/issues/874#issuecomment-944862272
  delay(100);  // wait for it to connect

  long startTime = millis();
  while (!pClient->isConnected()) {
    yield();
    if (millis() - startTime > timeout) {
      commSerial.println("Timeout");
      return false;
    }
  }
  if (!pClient->isConnected()) {
    // Check again !?
    commSerial.println("Not connected");
    return false;
  }
  commSerial.println(" - Connected");
  commSerial.flush();

  // Obtain a reference to the service we are after in the remote BLE server.
  BLERemoteService *pRemoteService = pClient->getService(serviceUUID);
  if (pRemoteService == nullptr) {
    commSerial.print("Failed to find our service UUID: ");
    commSerial.println(serviceUUID.toString().c_str());
    pClient->disconnect();
    return false;
  }

Debug Message

08:49:31.872 -> Found BMS: REVOV-12100-545
08:49:31.872 -> [379552][V][BLEDevice.cpp:60] createClient(): >> createClient
08:49:31.904 -> [379552][V][BLEDevice.cpp:66] createClient(): << createClient
08:49:31.904 ->  - Connecting to device
08:49:31.904 -> [379564][V][BLEClient.cpp:98] connect(): >> connect(a5:c2:37:00:14:9c)
08:49:31.904 -> [379564][I][BLEDevice.cpp:622] addPeerDevice(): add conn_id: 23, GATT role: client
08:49:31.904 -> [379570][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: RegEvt (0x3fffd2e4), owner: <N/A> for connect
08:49:31.937 -> [379579][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: RegEvt (0x3fffd2e4), owner: connect
08:49:31.937 -> [379588][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: RegEvt (0x3fffd2e4), owner: connect for connect
08:49:31.937 -> [379588][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_REG_EVT
08:49:31.968 -> [379608][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_REG_EVT
08:49:31.968 -> [379616][V][BLEUtils.cpp:1444] dumpGattClientEvent(): [status: ESP_GATT_OK, app_id: 0x17]
08:49:31.968 -> [379624][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_REG_EVT
08:49:31.968 -> [379634][V][FreeRTOS.cpp:143] give(): Semaphore giving: name: RegEvt (0x3fffd2e4), owner: connect
08:49:32.001 -> [379643][V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: RegEvt (0x3fffd2e4), owner: <N/A>
08:49:32.001 -> [379652][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: OpenEvt (0x3fffd348), owner: <N/A> for connect
08:49:32.001 -> [379662][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: OpenEvt (0x3fffd348), owner: connect
08:49:32.001 -> [379670][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: OpenEvt (0x3fffd348), owner: connect for connect
08:49:32.356 -> lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
08:49:32.549 -> lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
08:49:32.936 -> [380599][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_CONNECT_EVT
08:49:32.936 -> [380600][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_CONNECT_EVT
08:49:32.936 -> [380607][V][BLEUtils.cpp:1311] dumpGattClientEvent(): [conn_id: 0, remote_bda: a5:c2:37:00:14:9c]
08:49:32.968 -> [380615][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_CONNECT_EVT
08:49:32.968 -> [380626][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_OPEN_EVT
08:49:32.968 -> [380637][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_OPEN_EVT
08:49:32.999 -> [380644][V][BLEUtils.cpp:1402] dumpGattClientEvent(): [status: ESP_GATT_OK, conn_id: 0, remote_bda: a5:c2:37:00:14:9c, mtu: 23]
08:49:32.999 -> [380655][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_OPEN_EVT
08:49:32.999 -> BLEClient onConnect
08:49:32.999 -> [380676][V][FreeRTOS.cpp:143] give(): Semaphore giving: name: OpenEvt (0x3fffd348), owner: connect
08:49:33.032 -> [380677][V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: OpenEvt (0x3fffd348), owner: <N/A>
08:49:33.032 -> [380686][V][BLEClient.cpp:149] connect(): << connect(), rc=1
08:49:33.129 ->  - Connected
08:49:33.129 -> [380793][V][BLEClient.cpp:412] getService(): >> getService: uuid: 0000ff00-0000-1000-8000-00805f9b34fb
08:49:33.129 -> [380793][V][BLEClient.cpp:448] getServices(): >> getServices
08:49:33.129 -> [380796][V][BLEClient.cpp:73] clearServices(): >> clearServices
08:49:33.161 -> [380802][V][BLEClient.cpp:80] clearServices(): << clearServices
08:49:33.161 -> [380807][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: SearchCmplEvt (0x3fffd3ac), owner: <N/A> for getServices
08:49:33.161 -> [380818][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: SearchCmplEvt (0x3fffd3ac), owner: getServices
08:49:33.161 -> [380827][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: SearchCmplEvt (0x3fffd3ac), owner: getServices for getServices
08:49:33.677 -> [381333][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
08:49:33.677 -> [381333][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
08:49:33.677 -> [381340][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
08:49:33.709 -> [381340][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
08:49:33.709 -> [381355][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
08:49:33.709 -> [381355][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
08:49:33.709 -> [381373][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.741 -> [381384][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
08:49:33.741 -> [381392][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 1 0x01, end_handle: 7 0x07, srvc_id: uuid: 00001800-0000-1000-8000-00805f9b34fb, inst_id: 1
08:49:33.741 -> [381407][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.773 -> [381419][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
08:49:33.773 -> [381425][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
08:49:33.773 -> [381433][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.773 -> [381443][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
08:49:33.805 -> [381451][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 8 0x08, end_handle: 11 0x0b, srvc_id: uuid: 00001801-0000-1000-8000-00805f9b34fb, inst_id: 8
08:49:33.805 -> [381467][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.838 -> [381478][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
08:49:33.838 -> [381485][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
08:49:33.838 -> [381492][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.838 -> [381502][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
08:49:33.870 -> [381510][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 12 0x0c, end_handle: 14 0x0e, srvc_id: uuid: 0000180a-0000-1000-8000-00805f9b34fb, inst_id: 12
08:49:33.870 -> [381526][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
08:49:33.870 -> [381537][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
08:49:33.902 -> [381544][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
13:29:50.807 -> Devices found: 9
13:29:50.807 -> Scan done!
13:29:50.807 -> Found BMS: REVOV-12100-543
13:29:50.807 -> [367866][V][BLEDevice.cpp:60] createClient(): >> createClient
13:29:50.840 -> [367866][V][BLEDevice.cpp:66] createClient(): << createClient
13:29:50.840 ->  - Connecting to device
13:29:50.840 -> [367880][V][BLEClient.cpp:98] connect(): >> connect(a5:c2:37:00:14:85)
13:29:50.840 -> [367880][I][BLEDevice.cpp:622] addPeerDevice(): add conn_id: 25, GATT role: client
13:29:50.840 -> [367886][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: RegEvt (0x3fff3040), owner: <N/A> for connect
13:29:50.840 -> [367895][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: RegEvt (0x3fff3040), owner: connect
13:29:50.873 -> [367904][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: RegEvt (0x3fff3040), owner: connect for connect
13:29:50.873 -> [367904][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_REG_EVT
13:29:50.873 -> [367924][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_REG_EVT
13:29:50.906 -> [367932][V][BLEUtils.cpp:1444] dumpGattClientEvent(): [status: ESP_GATT_OK, app_id: 0x19]
13:29:50.906 -> [367940][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_REG_EVT
13:29:50.906 -> [367950][V][FreeRTOS.cpp:143] give(): Semaphore giving: name: RegEvt (0x3fff3040), owner: connect
13:29:50.906 -> [367959][V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: RegEvt (0x3fff3040), owner: <N/A>
13:29:50.939 -> [367968][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: OpenEvt (0x3fffa134), owner: <N/A> for connect
13:29:50.939 -> [367978][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: OpenEvt (0x3fffa134), owner: connect
13:29:50.939 -> [367986][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: OpenEvt (0x3fffa134), owner: connect for connect
13:29:51.404 -> lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
13:29:51.637 -> [368683][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_CONNECT_EVT
13:29:51.637 -> [368684][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_CONNECT_EVT
13:29:51.637 -> [368691][V][BLEUtils.cpp:1311] dumpGattClientEvent(): [conn_id: 0, remote_bda: a5:c2:37:00:14:85]
13:29:51.671 -> [368700][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_CONNECT_EVT
13:29:51.671 -> [368711][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_OPEN_EVT
13:29:51.671 -> [368721][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_OPEN_EVT
13:29:51.704 -> [368728][V][BLEUtils.cpp:1402] dumpGattClientEvent(): [status: ESP_GATT_OK, conn_id: 0, remote_bda: a5:c2:37:00:14:85, mtu: 23]
13:29:51.704 -> [368739][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_OPEN_EVT
13:29:51.704 -> BLEClient onConnect
13:29:51.704 -> [368760][V][FreeRTOS.cpp:143] give(): Semaphore giving: name: OpenEvt (0x3fffa134), owner: connect
13:29:51.704 -> [368761][V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: OpenEvt (0x3fffa134), owner: <N/A>
13:29:51.737 -> [368770][V][BLEClient.cpp:149] connect(): << connect(), rc=1
13:29:51.837 ->  - Connected
13:29:51.837 -> [368876][V][BLEClient.cpp:412] getService(): >> getService: uuid: 0000ff00-0000-1000-8000-00805f9b34fb
13:29:51.837 -> [368876][V][BLEClient.cpp:448] getServices(): >> getServices
13:29:51.837 -> [368879][V][BLEClient.cpp:73] clearServices(): >> clearServices
13:29:51.837 -> [368885][V][BLEClient.cpp:80] clearServices(): << clearServices
13:29:51.837 -> [368891][V][FreeRTOS.cpp:189] take(): Semaphore taking: name: SearchCmplEvt (0x3fffa198), owner: <N/A> for getServices
13:29:51.870 -> [368901][V][FreeRTOS.cpp:198] take(): Semaphore taken:  name: SearchCmplEvt (0x3fffa198), owner: getServices
13:29:51.870 -> [368911][V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: SearchCmplEvt (0x3fffa198), owner: getServices for getServices
13:29:52.735 -> [369791][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
13:29:52.735 -> [369791][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
13:29:52.768 -> [369799][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
13:29:52.768 -> [369799][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
13:29:52.768 -> [369814][V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 46
13:29:52.768 -> [369814][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
13:29:52.801 -> [369832][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.801 -> [369843][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
13:29:52.801 -> [369851][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 1 0x01, end_handle: 7 0x07, srvc_id: uuid: 00001800-0000-1000-8000-00805f9b34fb, inst_id: 1
13:29:52.834 -> [369866][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.834 -> [369877][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
13:29:52.834 -> [369884][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
13:29:52.834 -> [369891][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.868 -> [369902][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
13:29:52.868 -> [369910][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 8 0x08, end_handle: 11 0x0b, srvc_id: uuid: 00001801-0000-1000-8000-00805f9b34fb, inst_id: 8
13:29:52.868 -> [369925][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.901 -> [369936][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
13:29:52.901 -> [369943][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
13:29:52.901 -> [369950][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.934 -> [369961][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
13:29:52.934 -> [369969][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 12 0x0c, end_handle: 14 0x0e, srvc_id: uuid: 0000180a-0000-1000-8000-00805f9b34fb, inst_id: 12
13:29:52.934 -> [369984][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.967 -> [369995][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
13:29:52.967 -> [370002][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()
13:29:52.967 -> [370009][D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:52.967 -> [370020][V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: ESP_GATTC_SEARCH_RES_EVT
13:29:53.000 -> [370028][V][BLEUtils.cpp:1488] dumpGattClientEvent(): [conn_id: 0, start_handle: 15 0x0f, end_handle: 22 0x16, srvc_id: uuid: 0000ff00-0000-1000-8000-00805f9b34fb, inst_id: 15
13:29:53.000 -> [370044][D][BLEClient.cpp:178] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... ESP_GATTC_SEARCH_RES_EVT
13:29:53.000 -> [370055][V][BLERemoteService.cpp:26] BLERemoteService(): >> BLERemoteService()
13:29:53.034 -> [370062][V][BLERemoteService.cpp:34] BLERemoteService(): << BLERemoteService()

Other Steps to Reproduce

My sketch follows the following logic:

  1. Scan for BLE device
  2. Each device with the correct service, connect
  3. Get service
  4. Register notifications
  5. Wait 10 seconds
  6. Disconnect
  7. Start from the beginning after a delay of 2 seconds

The issue never happens the first time around, but normally a couple of loops later.

I have checked existing issues, online documentation and the Troubleshooting Guide

lhtran114 commented 1 year ago

Hi,

I'm observing the same issue with ESP32-C3-MINI1 esp32 for Arduino v 2.0.11 I managed to make it stuck every time I try to call pClient->getService(serviceUUID);

I used the example "BLE_Client" code, just made a small change so I could call getService separately instead of it being called immediately after connected.

Here's the sequence:

  1. Power up the ESP32-C3
  2. Scan for BLE devices
  3. Connect to a server.
  4. Very important step: wait for a few seconds (maybe 10 seconds).
  5. Call pClient->getService(serviceUUID); and it will stuck there forever.

If getService called immediately after connected, then it works fine. After successfully called it once, it will work after that no mater how many disconnect/reconnect attempts.

It only stuck after the first connection, then wait for a few seconds, then call getService.

Any idea?

Thanks!