esp-idf: BLE service discovery fails on low BLE connections : lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) (IDFGH-6671)

Environment

Development Kit: M5stack Atom
Module or chip used: ESP32-PICO-V3
IDF version : v4.3.2 and v4.4 (tested on both)
Build System: idf.py
Compiler version : xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2) 8.4.0
Operating System: Linux
Using an IDE?: No
Power Supply: USB

Problem Description

I’m using Nimble on a esp32 (ESP32-PICO-V3) acting as central, connecting to a BLE peripheral (nRF 52832). This project is used in production on a few hundreds devices.

When the peripheral is close, everything works fine, connect, discovery, writes, reads, and does long exchanges of data. When the device to connect to is far (RSSI < -86), sometomes all goes well, but I often (randomly) get this error :

lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
E (251969) NimBLE: Error: Service discovery failed; status=7 conn_handle=0
I (251969) NimBLE: GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19

See full log below

I have tried increasing connection max interval and supervision timeout, on the central (initial parameters) and peripheral, with no luck. I have disabled data length extension in Nimble, with no luck. Note that this error line happens relatively quickly after service discovery starts, and is not impacted by connection intervals, which does not point to a timeout.

Expected Behavior

No error, service discovery proceeds correctly

Actual Behavior

Disconnect during service discovery

Steps to reproduce

I have separated the two boards by a few meters, separated by a wall, to be able to reproduce the issue. The more the RSSI drops, the more issue I encounter

Code to reproduce this issue

My code is based on the blecent example (examples/bluetooth/nimble/blecent/main)

I’m just pasting here the part where we launch the service discovery when connnected :

static int
blecent_gap_event(struct ble_gap_event *event, void *arg)
{
(...)
    case BLE_GAP_EVENT_CONNECT:
        /* A new connection was established or a connection attempt failed. */
        if (event->connect.status == 0) {
            /* Connection successfully established. */
            MODLOG_DFLT(INFO, "Connection established ");

            rc = ble_gap_conn_find(event->connect.conn_handle, &desc);
            assert(rc == 0);
            print_conn_desc(&desc);
            MODLOG_DFLT(INFO, "\n");

            /* Remember peer. */
            rc = peer_add(event->connect.conn_handle);
            if (rc != 0) {
                MODLOG_DFLT(ERROR, "Failed to add peer; rc=%d\n", rc);
                return 0;
            }

            /* Perform service discovery. */
            rc = peer_disc_all(event->connect.conn_handle,
                               blecent_on_disc_complete, NULL);
            if (rc != 0) {
                MODLOG_DFLT(ERROR, "Failed to discover services; rc=%d\n", rc);
                return 0;
            }
        } else {
            /* Connection attempt failed; resume scanning. */
            MODLOG_DFLT(ERROR, "Error: Connection failed; status=%d\n",
                        event->connect.status);
            blecent_scan();
        }

        return 0;
    (...)
}

Debug Logs

When error occurs :

I (129309) NimBLE_BLE_CENT: Scan finished, RSSI -92, connecting...
I (129319) NimBLE: GAP procedure initiated: connect; 
I (129329) NimBLE: peer_addr_type=1 peer_addr=
I (129329) NimBLE: ef:0a:ab:e4:b8:a5
I (129329) NimBLE:  scan_itvl=16 scan_window=16 itvl_min=10 itvl_max=250 latency=0 supervision_timeout=800 min_ce_len=0 max_ce_len=0 own_addr_type=0
I (129349) NimBLE: 

I (130049) NimBLE: Connection established 
I (130049) NimBLE: 

I (130049) NimBLE_BLE_CENT: Added peer
I (130049) NimBLE: GATT procedure initiated: discover service by uuid; uuid=
I (130059) NimBLE: a7630001-f491-4f21-95ea-846ba586e361
I (130059) NimBLE: 

**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
E (131909) NimBLE: Error: Service discovery failed; status=7 conn_handle=0**

I (131909) NimBLE: GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19

I (131949) NimBLE: disconnect; reason=574

When all goes well :

I (100629) NimBLE_BLE_CENT: Scan finished, RSSI -85, connecting...
I (100629) NimBLE: GAP procedure initiated: connect; 
I (100639) NimBLE: peer_addr_type=1 peer_addr=
I (100639) NimBLE: ef:0a:ab:e4:b8:a5
I (100649) NimBLE:  scan_itvl=16 scan_window=16 itvl_min=10 itvl_max=250 latency=0 supervision_timeout=800 min_ce_len=0 max_ce_len=0 own_addr_type=0
I (100659) NimBLE: 

I (100769) NimBLE: Connection established 
I (100769) NimBLE: 

I (100769) NimBLE_BLE_CENT: Added peer
I (100769) NimBLE: GATT procedure initiated: discover service by uuid; uuid=
I (100779) NimBLE: a7630001-f491-4f21-95ea-846ba586e361
I (100779) NimBLE: 

I (103509) NimBLE: GATT procedure initiated: discover all characteristics; 
I (103509) NimBLE: start_handle=14 end_handle=22

I (108199) NimBLE: GAP procedure initiated: 
I (108199) NimBLE: connection parameter update; conn_handle=0 itvl_min=6 itvl_max=60 latency=0 supervision_timeout=400 min_ce_len=0 max_ce_len=0
I (108209) NimBLE: 

I (110379) NimBLE: connection params update event; conn_handle=0 status=0

I (110389) NimBLE: 

I (110529) NimBLE: GATT procedure initiated: discover all descriptors; 
I (110529) NimBLE: chr_val_handle=18 end_handle=19

I (111209) NimBLE: GATT procedure initiated: discover all descriptors; 
I (111209) NimBLE: chr_val_handle=21 end_handle=22

I (111429) NimBLE: Service discovery complete; status=0 conn_handle=0

I (111429) NimBLE_BLE_CENT: Subscribing to notifications
I (111439) NimBLE: GATT procedure initiated: write; 
I (111439) NimBLE: att_handle=22 len=2

I (111809) NimBLE: Subscribe complete; status=0 conn_handle=0 attr_handle=22

About this issue

Original URL
State: open
Created 2 years ago
Reactions: 2
Comments: 18 (1 by maintainers)

Most upvoted comments

It seems that calling service discovery too fast can cause such issue. Bluetooth connection needs some time to settle. Additionally BLE expect MTU negotiation to happen. So if you start sending service discovery before MTU, then it might cause such issue. I had the same issue and fixed it by waiting for BLE_GAP_EVENT_MTU:

static int ble_client_gap_event(struct ble_gap_event *event, void *arg) {
  ble_client *client = (ble_client *) arg;
  ESP_LOGD(TAG, "gap event: %d", event->type);
  switch (event->type) {
    case BLE_GAP_EVENT_CONNECT: {
      int status = event->connect.status;
      if (status == 0) {
        ESP_LOGI(TAG, "connection established");
        client->conn_handle = event->connect.conn_handle;
      } else {
        ESP_LOGE(TAG, "connection failed. ble code: %d", status);
        client->semaphore_result = ble_client_convert_ble_code(status);
        client->connected = false;
        xSemaphoreGive(client->semaphore);
      }
      break;
    }
      // notify connected only after MTU negotiation completes
    case BLE_GAP_EVENT_MTU: {
      ESP_LOGI(TAG, "MTU negotiated");
      client->semaphore_result = ESP_OK;
      client->connected = true;
      xSemaphoreGive(client->semaphore);
      break;
    }
    default:
      break;
  }
  return 0;
}

dernasherbrezon on Dec 3, 2023