search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.89k stars 7.33k forks source link

HCI packet count mismatch? (IDFGH-3084) #5105

Open fpgamaster opened 4 years ago

fpgamaster commented 4 years ago

Environment

Problem Description

In few minutes such messages appear on the console: .... lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 2) .... lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)

BLE disconnects happen too often but not at the same time as messages above.

Expected Behavior

Stable BLE connection

fpgamaster commented 4 years ago

Some more log from a remote device:

lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) W (240036) BT_APPL: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0008 W (240036) BT_APPL: bta_gattc_conn_cback() - cif=4 connected=0 conn_id=4 reason=0x0008 W (240046) BT_APPL: bta_gattc_conn_cback() - cif=5 connected=0 conn_id=5 reason=0x0008

I (240066) GATTC: CATTC Event 41, gattc if 3, app_id 0 I (240066) GATTC: GATTC Event handler idx 0, event 41 I (240076) GATTC: DISCONECT_EVT, reason 8 I (240076) GATTC: CATTC Event 2, gattc if 3, app_id 0 I (240086) GATTC: GATTC Event handler idx 0, event 2 I (240096) GATTC: OPEN_EVT E (240096) GATTC: connect device failed, status 133 I (240106) GATTC: CATTC Event 41, gattc if 4, app_id 0 I (240106) GATTC: GATTC Event handler idx 1, event 41 I (240116) GATTC: DISCONECT_EVT, reason 8 I (240116) GATTC: CATTC Event 41, gattc if 5, app_id 0 I (240126) GATTC: GATTC Event handler idx 2, event 41 I (240126) GATTC: DISCONECT_EVT, reason 8

Sushant-Espressif commented 4 years ago

@fpgamaster Can you please help me to understand the scenario better? Following info would be helpful:

  1. Which Host stack is used: Bluedroid/NimBLE?
  2. Does issue occur with standard BLE gatt client example? If not, can you provide simple procedure to reproduce the issue?
  3. Is this a single BLE link scenario? Is Wifi also running at the same time?
fpgamaster commented 4 years ago

@Sushant-Espressif

  1. Bluedroid
  2. Not tested with the standard BLE client example as is but the standard BLE example is used to implement a BLUFI client and we see the issue when connected to a BLUFI GATTS which is not modified. We transfer 100-200 bytes at 20-30 secs as custom data.
  3. Yes, it is a single BLE link. WiFi is not enabled on the device running GATTS but enabled and connected on the device running GATTC. It hard to say that the issue happens when there is a traffic or not.
hb-kaertech commented 4 years ago

@Sushant-Espressif

I am hitting the same issue:

  1. Bluedroid
  2. ESP32 runs a modified version of the GATTC example.
  3. Single BLE link. Wifi is also running.
Sushant-Espressif commented 4 years ago

@hb-kaertech @fpgamaster As per debugging on our local setup we have following findings :

  1. lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) is triggered after disconnection is initiated. This error print mostly occurs in abrupt disconnection scenarios (example: connection timeout) but it is not the reason for disconnection.
  2. lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) has no affect on subsequent connections, when Bluedroid host stack is used.
  3. HCI packet count in the error log is maintained just to monitor the flow control from Host to controller. We have fixed the issue causing “HCI packet count mismatch” locally and will upload the MR ASAP.

We suggest you to ignore the print “HCI packet count mismatch” for now and focus on the reason for disconnection.

Alvin1Zhang commented 4 years ago

Thanks for reporting, sorry for late update, the fix is at https://github.com/espressif/esp-idf/commit/5da526a0cb0b1017c3ae08b5baaf8a07edfcb003.

dpgeorge commented 3 years ago

We are still seeing these symptoms when using MicroPython + NimBLE on the esp32. It seems that the message is triggered if the connect is followed very closely by a disconnect (<200ms between them).

We have a BLE test suite that runs multiple devices at once and coordinates their BLE activity. The simple GAP connect/disconnect test will generate this lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) message on the esp32.

Here is the output of our test running on a TinyPICO (esp32) and a PYBD-SF6 (Cypress BT), both running the NimBLE stack:

$ ./run-multitests.py -i pyb:u0 -i pyb:a0 -t multi_bluetooth/ble_gap_connect.py
multi_bluetooth/ble_gap_connect.py on ttyUSB0|ttyACM0: 
TRACE ttyUSB0|ttyACM0:
   652 i0 : SET BDADDR = (0, b'\xd8\xa0\x1dF\xe2\xc2')
   653 i0 : gap_advertise
   754 i0 : NEXT
  1216 i1 : NEXT
  1217 i1 : gap_connect
  1218 i1 : _IRQ_PERIPHERAL_CONNECT
  1218 i1 : gap_disconnect: True
  1319 i0 : _IRQ_CENTRAL_CONNECT
  1320 i1 : _IRQ_PERIPHERAL_DISCONNECT
  1322 i0 : lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
  1322 i1 : gap_connect
  1323 i0 : _IRQ_CENTRAL_DISCONNECT
  1323 i1 : _IRQ_PERIPHERAL_CONNECT
  1324 i0 : gap_advertise
  1324 i0 : _IRQ_CENTRAL_CONNECT
  1324 i0 : gap_disconnect: True
  1627 i0 : _IRQ_CENTRAL_DISCONNECT
  1829 i1 : _IRQ_PERIPHERAL_DISCONNECT

i0 is the esp32 and i1 is the board with the Cypress BT chip ("i" stands for instance). The leftmost column is a millisecond timestamp.

The esp32 is essentially just running "GAP advertise" and the Cypress is doing "GAP connect, GAP disconnect". Adding a delay of 200ms between the connect/disconnect makes the lld_pdu_get_tx_flush_nb go away.

dpgeorge commented 3 years ago

I forgot to mention, the test uses IDF v4.4-dev-1404-gc13afea63 (ie latest master as of now). The HCI messages are also seen on all prior v4.x stable releases that I've checked.

koenieee commented 3 years ago

I have the same issue, can't find a fix for it. Someone who can help me out?

AngelVersa commented 3 years ago

I have the same issue using nimble in esp-idf v4.3 on ESP32-WROOM

I (507956) BLE_PER: connection established; status=0 lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) I (508142) BLE_PER: disconnect; reason=574

valnenov commented 2 years ago

I have a similar random BLE disconnect issue using ESP32 6- Axis IMU from: https://www.makerfabs.com/esp32-6-axis-imu.html Testing with: 1) https://github.com/dzindra/BLE-iOS-demo 2) https://github.com/Makerfabs/ESP32_IMU_Module with basic BLE stack added

dpgeorge commented 2 years ago

Maybe a new issue needs to be created so this can be tracked by Espressif?

0x5e commented 2 years ago

Same issue using MicroPython 1.18 + ESP32 DevKit C

lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
stephanelsmith commented 2 years ago

bump, I see this as well sometimes when connecting to central lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)

I see this after IRQ_SCAN_DONE, after IRQ_PERIPHERAL_CONNECT, starting discovering services and immediately starting a new scan. Instead of IRQ_GATTC_SERVICE_RESULT, I see the packet count mistmatch statement, IRQ_GATTC_SERVICE_DONE then IRQ_PERIPHERAL_DISCONNECT. In the next scan/connect iteration, it could either repeat the error or discover services and continue correctly.

I've introduced a 100ms delay before the new scan and the issue is seems to have subsided. Since the issue was intermittent in the first place for me, I can't tell if this is definitive or not.

dpgeorge commented 2 years ago

Here are some related issues: #8187, #8303

UmangSuthar101 commented 2 years ago

Environment

Problem Description

I upload the code for the BLE multi-client in this module.

After some time such logs appear in the console: .... lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 2) .... lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)

BLE disconnects happen too often and show me these types of logs. image

Expected Behavior

Stable BLE connection

Can connect multiple BLE server on this module and get the data simultaneously

SatishSolankeEsp commented 2 years ago

We are still seeing these symptoms when using MicroPython + NimBLE on the esp32. It seems that the message is triggered if the connect is followed very closely by a disconnect (<200ms between them).

We have a BLE test suite that runs multiple devices at once and coordinates their BLE activity. The simple GAP connect/disconnect test will generate this lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) message on the esp32.

Here is the output of our test running on a TinyPICO (esp32) and a PYBD-SF6 (Cypress BT), both running the NimBLE stack:


$ ./run-multitests.py -i pyb:u0 -i pyb:a0 -t multi_bluetooth/ble_gap_connect.py
multi_bluetooth/ble_gap_connect.py on ttyUSB0|ttyACM0: 
TRACE ttyUSB0|ttyACM0:
   652 i0 : SET BDADDR = (0, b'\xd8\xa0\x1dF\xe2\xc2')
   653 i0 : gap_advertise
   754 i0 : NEXT
  1216 i1 : NEXT
  1217 i1 : gap_connect
  1218 i1 : _IRQ_PERIPHERAL_CONNECT
  1218 i1 : gap_disconnect: True
  1319 i0 : _IRQ_CENTRAL_CONNECT
  1320 i1 : _IRQ_PERIPHERAL_DISCONNECT
  1322 i0 : lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
  1322 i1 : gap_connect
  1323 i0 : _IRQ_CENTRAL_DISCONNECT
  1323 i1 : _IRQ_PERIPHERAL_CONNECT
  1324 i0 : gap_advertise
  1324 i0 : _IRQ_CENTRAL_CONNECT
  1324 i0 : gap_disconnect: True
  1627 i0 : _IRQ_CENTRAL_DISCONNECT
  1829 i1 : _IRQ_PERIPHERAL_DISCONWe are still seeing these symptoms when using MicroPython + NimBLE on the esp32. It seems that the message is triggered if the connect is followed very closely by a disconnect (<200ms between them).

We have a BLE test suite that runs multiple devices at once and coordinates their BLE activity. The simple GAP connect/disconnect test will generate this lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) message on the esp32.

Here is the output of our test running on a TinyPICO (esp32) and a PYBD-SF6 (Cypress BT), both running the NimBLE stack:

$ ./run-multitests.py -i pyb:u0 -i pyb:a0 -t multi_bluetooth/ble_gap_connect.py
multi_bluetooth/ble_gap_connect.py on ttyUSB0|ttyACM0: 
TRACE ttyUSB0|ttyACM0:
   652 i0 : SET BDADDR = (0, b'\xd8\xa0\x1dF\xe2\xc2')
   653 i0 : gap_advertise
   754 i0 : NEXT
  1216 i1 : NEXT
  1217 i1 : gap_connect
  1218 i1 : _IRQ_PERIPHERAL_CONNECT
  1218 i1 : gap_disconnect: True
  1319 i0 : _IRQ_CENTRAL_CONNECT
  1320 i1 : _IRQ_PERIPHERAL_DISCONNECT
  1322 i0 : lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
  1322 i1 : gap_connect
  1323 i0 : _IRQ_CENTRAL_DISCONNECT
  1323 i1 : _IRQ_PERIPHERAL_CONNECT
  1324 i0 : gap_advertise
  1324 i0 : _IRQ_CENTRAL_CONNECT
  1324 i0 : gap_disconnect: True
  1627 i0 : _IRQ_CENTRAL_DISCONNECT
  1829 i1 : _IRQ_PERIPHERAL_DISCONNECT

i0 is the esp32 and i1 is the board with the Cypress BT chip ("i" stands for instance). The leftmost column is a millisecond timestamp.

The esp32 is essentially just running "GAP advertise" and the Cypress is doing "GAP connect, GAP disconnect". Adding a delay of 200ms between the connect/disconnect makes the lld_pdu_get_tx_flush_nb go away.NECT



`i0` is the esp32 and `i1` is the board with the Cypress BT chip ("i" stands for instance). The leftmost column is a millisecond timestamp.

The esp32 is essentially just running "GAP advertise" and the Cypress is doing "GAP connect, GAP disconnect". Adding a delay of 200ms between the connect/disconnect makes the `lld_pdu_get_tx_flush_nb` go away.

> @dpgeorge

HI @dpgeorge , I have gone through the “HCI packet count mismatch” and this print will come mostly abrupt disconnection. This is not the reason for the disconnect. We should focus on Disconnection Issue. I have gone through the above log i0 and i1 and seen you doing connect and disconnect within 1 msec. This process is not as per the spec(LL.TS).

As per link-layer test specification if the master (cypress ) and slave (esp32) trying to connect after the connection complete event is received you should wait at least *10 connection interval time** to stable the connection between them and you should disconnect the device. I guess that you have already done keeping 200msec as a delay.

You can refer LL/DDI/ADV/BI-07-C test case in LLTS spec. image

Once you have done the above modification if you still see the disconnect issue with the reason of ( like connection failed to be established 0x3e, connection timeout, LMP response timeout ) with esp32 please let us know. Could you please share the log with OTA and let us know the reproduction rate (like 1 out of 100)?

Thanks, Satish

SatishSolankeEsp commented 2 years ago

koenieee

I have the same issue, can't find a fix for it. Someone who can help me out?

Could you please share the log with the disconnect reason, and let us know the reproduction rate (like 1 out of 100)?

SatishSolankeEsp commented 2 years ago

AngelVersa, As I see you have just mentioned connection is failing for the reason of 0x3E.

Could you please share the log with details like the role of device esp32, and connection interval, and let us know the reproduction rate ? Thanks, Satish

AngelVersa commented 2 years ago

Sorry, I could not give this information as the problem is not reproducing anymore (but I can not remember if we did something with it). We advanced in the development and the code is far different from the code when I posted. As half year has past, most of the issue logs have been deleted.

SatishSolankeEsp commented 2 years ago

Sorry, I could not give this information as the problem is not reproducing anymore (but I can not remember if we did something with it). We advanced in the development and the code is far different from the code when I posted. As half year has past, most of the issue logs have been deleted.

AngelVersa Cool Thanks for the update will close your request as of now.

markingle commented 2 years ago

Hi I am having the same problem with the HCI packet count mismatch....I have tried both idf and nimble libraries and get the same result. I am posting here as well to hopefully get some help troubleshooting. Thanks in advance for the help!

Environment

Development Kit: HiLetGo ESP32 Dev Board Module or chip used: ESP32-WROOM-32D IDF version: Build System: Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r1) 8.2.0 Operating System: Mac OSX Big Sur Using an IDE?: Arduino Power Supply: USB

Problem Description

I am working to develop an WatchOS BLE application to control a water pump. By design when the Apple watch goes into sleep mode the Watch BLE app disconnects from the server application running on the ESP32. Eventually the connection state gets stuck on "device connected" and the HCI error message is displayed in the serial output...See below

Starting BLE work! Characteristic defined! Now you can read it in your phone! device connected Device is connecting device connected device connected device connected device connected device connected start advertising device connected Device is connecting device connected device connected device connected device connected start advertising device connected Device is connecting device connected device connected device connected device connected device connected start advertising device connected lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)

Expected Behavior

To maintain a stable connection state based on current connection with Watch app.

Wireshark Capture Link

https://drive.google.com/file/d/1muiVhvKGq0Gc-K3awjBWnBMphY0jAlCt/view?usp=sharing

Arduino Code Snippet


void setup() {
  Serial.begin(115200);
  Serial.println("Starting BLE work!");

  pinMode(WIFI_CLIENT_CONNECTED, OUTPUT);
  digitalWrite(WIFI_CLIENT_CONNECTED, LOW);

  BLEDevice::init("Long name works now");

  BLEServer *pServer = BLEDevice::createServer();
  pServer->setCallbacks(new MyServerCallbacks());

  BLEService *pService = pServer->createService(SERVICE_UUID);
  BLECharacteristic *pCharacteristic = pService->createCharacteristic(
                                        CHARACTERISTIC_UUID,
                                  /***** Enum Type NIMBLE_PROPERTY now *****      
                                        BLECharacteristic::PROPERTY_READ   |
                                        BLECharacteristic::PROPERTY_WRITE  
                                        );
                                  *****************************************/
                                        NIMBLE_PROPERTY::READ |
                                        NIMBLE_PROPERTY::WRITE 
                                       );

  pCharacteristic->setValue("Hello World says Neil");
  pService->start();
  // BLEAdvertising *pAdvertising = pServer->getAdvertising();  // this still is working for backward compatibility
  BLEAdvertising *pAdvertising = BLEDevice::getAdvertising();
  pAdvertising->addServiceUUID(SERVICE_UUID);
  pAdvertising->setScanResponse(true);
  pAdvertising->setMinPreferred(0x06);  // functions that help with iPhone connections issue
  pAdvertising->setMaxPreferred(0x12);

  BLEDevice::startAdvertising();
  Serial.println("Characteristic defined! Now you can read it in your phone!");
}

void loop() {
  if (deviceConnected) {
        Serial.println("device connected");
        //value++;
        digitalWrite(WIFI_CLIENT_CONNECTED, HIGH);
        delay(1000); // bluetooth stack will go into congestion, if too many packets are sent, in 6 hours test i was able to go as low as 3ms
        //pCharacteristicB->setValue((uint8_t*)&onState, 4);
        //pCharacteristicB->notify(); 
        //pCharacteristicA->setValue((uint8_t*)&pumpEnabled, 4);
        //pCharacteristicA->notify();
        BLEDevice::getAdvertising()->stop();
    }
    // disconnecting
    if (!deviceConnected && oldDeviceConnected) {
        delay(500); // give the bluetooth stack the chance to get things ready
        digitalWrite(WIFI_CLIENT_CONNECTED, LOW);
        BLEDevice::getAdvertising()->start();
        Serial.println("start advertising");
        oldDeviceConnected = deviceConnected;
    }
    // connecting
    if (deviceConnected && !oldDeviceConnected) {
        // do stuff here on connecting
        Serial.println(" Device is connecting");
        oldDeviceConnected = deviceConnected;  
    }
   }
roysG commented 2 years ago

Any update?

markingle commented 2 years ago

@roysG I have not heard from anyone....its a blocker for me on a BLE project

SatishSolankeEsp commented 2 years ago

Hi, @markingle @roysG, I will look into it, could you please tell me to reproduce the rate and disconnect the reason for the same?

HCI packet count mismatch is not related to disconnecting it is just printed for our internal HCI level debugging.

could you please share the info of the IDF version, iPhone model, and some input related to the issue so that we can reproduce it on our end.

Thanks, Satish

markingle commented 2 years ago

@SatishSolankeEsp Could you please clarify your question? Also please note the Wireshark packet capture that is available in my post. Thanks!

I am using an Apple Watch to connect to the ESP32. By default the watch will disconnect when it goes into sleep mode

W-M-D commented 2 years ago

Yeah, I'm getting this too. It's weird because it only happens when. 1.) The ESP32 is connecting to another ESP32 (This doesn't happen at all when connecting to android) 2.) The ESP32 and the other ESP32 rebooted at different times.

So I'm guessing it's a failure to clean something up in the Bluetooth stack. One of the connection variables or something. I Have two ESP devices connecting to each other in a mixed client-server mode and it works 99% of the time. This is my only issue.

SatishSolankeEsp commented 2 years ago

@markingle , I will check the Wireshark packet capture log and get back to you. Thanks, Satish

markingle commented 2 years ago

Thanks @SatishSolankeEsp !! Much appreciated!

SatishSolankeEsp commented 2 years ago

Hi @markingle, I have gone through the Wireshark capture, and only the L2CAP packet is seen in (unassembled) hex format. a couple of technique is used to decode it but have not worked.

image

Could you please capture a precise log of over-the-air packet transmission and share the log again? We will try to root cause the issue once we have it.

Thanks, Satish

markingle commented 2 years ago

@SatishSolankeEsp you will need to set your filter to the ble address of the ESP32. Sorry I didnt provide it in my post...see screenshot below. If I need to do another capture please let me know.

The ble address for the AppleWatch is 78:e0:ae:32:59:f1

image

markingle commented 2 years ago

@SatishSolankeEsp Just checking to see if you need anything else from me to diagnose the HCI packet issue.....Thanks in advance for looking!

SatishSolankeEsp commented 2 years ago

Hi @markingle , I was able to open your log, It was not about the filter. I guess you capture the log on windows so shifted on windows and now I'm able to see it.

Do I need one Info from you which IDF version are you using?

Thanks, Satish

markingle commented 2 years ago

@SatishSolankeEsp

Screen Shot 2022-08-21 at 8 32 10 PM
veneno-529 commented 1 year ago

@h2zero @prasad-alatkar ### Environment Development Kit: ESP32 Do it board Module or chip used: ESP32 IDF version: v4.4.2 Build System: idf.py Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r1) 8.4.0 Operating System: Windows Using an IDE?: Yes (VS Code withe Platformio extension) NimBLE version : 1.3.0

Problem Description

I am having problems with BLE bonding on android device.

Basically, what happens is that, after bonding one phone to the same ESP32 ( Android 12 phone). Everything works fine once bonded for first time. When I disconnect and connect it again the bonding fails and The only way to reconnect is to delete the old bond and reconnect. Still, the error will appear again.

The maximum number of bonds is set to 3.

I have noticed that peer device records restored displays zero. Even after bonding it.

Expected Behavior

After bonding was done, even after disconnecting and reconnecting again (Bond info still maintained on android) connection should be successful.

Actual Behavior

After bonding and disconnecting, then trying to reconnect it fails to connect successfully.

### Steps to reproduce This is easily reproducible.

  1. Bond Android 13 / Iphone
  2. Once connected, Disconnect again. (Do not delete bond information from phone).
  3. Try to reconnect again.

Code to reproduce this issue

I managed to reproduce the problem using the bleprph example. I have only added RPA address resolution to that example and I have attached the project files: bleprph.zip

### Debug Logs Logs : After erasing flash, uploading firmware, booting for first time and connecting android phone for first time D (2601) NIMBLE_NVS: ble_store_config_cccds restored 0 bonds D (2611) nvs: nvs_open_from_partition nimble_bond 1 D (2611) nvs: nvs_get_str_or_blob p_dev_rec_1 D (2621) nvs: nvs_close 40 D (2621) nvs: nvs_open_from_partition nimble_bond 1 D (2621) nvs: nvs_get_str_or_blob p_dev_rec_2 D (2631) nvs: nvs_close 41 D (2631) nvs: nvs_open_from_partition nimble_bond 1 D (2641) nvs: nvs_get_str_or_blob p_dev_rec_3 D (2641) nvs: nvs_close 42 D (2641) nvs: nvs_open_from_partition nimble_bond 1 D (2651) nvs: nvs_get_str_or_blob p_dev_rec_4 D (2651) nvs: nvs_close 43 D (2661) NIMBLE_NVS: peer_dev_rec restored 0 records I (2661) NimBLE_BLE_PRPH: BLE Host Task Started D (2671) NimBLE: registered service 0x1800 with handle=1

D (2671) NimBLE: registering characteristic 0x2a00 with def_handle=2 val_handle=3

D (2681) NimBLE: registering characteristic 0x2a01 with def_handle=4 val_handle=5

D (2691) NimBLE: registered service 0x1801 with handle=6

D (2691) NimBLE: registering characteristic 0x2a05 with def_handle=7 val_handle=8

D (2701) NimBLE: registered service 59462f12-9543-9999-12c8-58b459a2712d with handle=10

D (2711) NimBLE: registering characteristic 5c3a659e-897e-45e1-b016-007107c96df6 with def_handle=11 val_handle=12

D (2721) NimBLE: registering characteristic 5c3a659e-897e-45e1-b016-007107c96df7 with def_handle=13 val_handle=14

I (2731) uart: queue free spaces: 8 V (2731) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args V (2741) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0xE D (2751) intr_alloc: Connected src 34 to int 3 (cpu 1) I (2771) NimBLE: Device Address: I (2771) NimBLE: 5b:13:6d:d2:73:35 I (2771) NimBLE:

I (2781) NimBLE: GAP procedure initiated: advertise; I (2781) NimBLE: disc_mode=2 I (2781) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (2791) NimBLE:

I (15311) NimBLE: connection established; status=0 I (15321) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (15321) NimBLE: 5b:13:6d:d2:73:35 I (15321) NimBLE: our_id_addr_type=1 our_id_addr= I (15331) NimBLE: 5b:13:6d:d2:73:35 I (15331) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (15341) NimBLE: 2c:be:eb:27:93:6f I (15341) NimBLE: peer_id_addr_type=0 peer_id_addr= I (15341) NimBLE: 2c:be:eb:27:93:6f I (15351) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (15361) NimBLE:

I (15811) NimBLE: connection updated; status=0 I (15811) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (15811) NimBLE: 5b:13:6d:d2:73:35 I (15821) NimBLE: our_id_addr_type=1 our_id_addr= I (15821) NimBLE: 5b:13:6d:d2:73:35 I (15831) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (15831) NimBLE: 2c:be:eb:27:93:6f I (15841) NimBLE: peer_id_addr_type=0 peer_id_addr= I (15841) NimBLE: 2c:be:eb:27:93:6f I (15851) NimBLE: conn_itvl=6 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (15861) NimBLE:

I (16071) NimBLE: connection updated; status=0 I (16071) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (16071) NimBLE: 5b:13:6d:d2:73:35 I (16071) NimBLE: our_id_addr_type=1 our_id_addr= I (16081) NimBLE: 5b:13:6d:d2:73:35 I (16081) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (16091) NimBLE: 2c:be:eb:27:93:6f I (16091) NimBLE: peer_id_addr_type=0 peer_id_addr= I (16101) NimBLE: 2c:be:eb:27:93:6f I (16101) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (16111) NimBLE:

I (22681) NimBLE: encryption change event; status=0 I (22681) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (22681) NimBLE: 5b:13:6d:d2:73:35 I (22691) NimBLE: our_id_addr_type=1 our_id_addr= I (22691) NimBLE: 5b:13:6d:d2:73:35 I (22701) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (22701) NimBLE: 2c:be:eb:27:93:6f I (22711) NimBLE: peer_id_addr_type=0 peer_id_addr= I (22711) NimBLE: 2c:be:eb:27:93:6f I (22721) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=500 encrypted=1 authenticated=0 bonded=1

Logs : After disconnecting I (68012) NimBLE: subscribe event; conn_handle=0 attr_handle=8 reason=2 prevn=0 curn=0 previ=1 curi=0

I (68012) NimBLE: disconnect; reason=531 I (68022) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (68022) NimBLE: 7a:3a:2b:f1:0b:84 I (68032) NimBLE: our_id_addr_type=0 our_id_addr= I (68032) NimBLE: 0c:b8:15:f6:92:f2 I (68042) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (68042) NimBLE: 2c:be:eb:27:93:6f I (68052) NimBLE: peer_id_addr_type=0 peer_id_addr= I (68052) NimBLE: 2c:be:eb:27:93:6f I (68062) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=500 encrypted=1 authenticated=0 bonded=1

I (68072) NimBLE:

E (68072) NimBLE_BLE_PRPH: ble_rpa_get_num_peer_dev_records() returned 0 I (68082) NimBLE: GAP procedure initiated: advertise; I (68082) NimBLE: disc_mode=2 I (68092) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (68102) NimBLE:

LOG : After reconnecting I (406681) NimBLE: connection established; status=0 I (406681) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (406681) NimBLE: 60:7b:29:00:45:0b I (406681) NimBLE: our_id_addr_type=1 our_id_addr= I (406691) NimBLE: 60:7b:29:00:45:0b I (406691) NimBLE: peer_ota_addr_type=1 peer_ota_addr= I (406701) NimBLE: 68:bc:48:03:92:84 I (406701) NimBLE: peer_id_addr_type=1 peer_id_addr= I (406711) NimBLE: 68:bc:48:03:92:84 I (406711) NimBLE: conn_itvl=24 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (406731) NimBLE:

I (407171) NimBLE: connection updated; status=0 I (407181) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (407181) NimBLE: 60:7b:29:00:45:0b I (407181) NimBLE: our_id_addr_type=1 our_id_addr= I (407191) NimBLE: 60:7b:29:00:45:0b I (407191) NimBLE: peer_ota_addr_type=1 peer_ota_addr= I (407201) NimBLE: 68:bc:48:03:92:84 I (407201) NimBLE: peer_id_addr_type=1 peer_id_addr= I (407211) NimBLE: 68:bc:48:03:92:84 I (407211) NimBLE: conn_itvl=6 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (407221) NimBLE:

lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1) I (408921) NimBLE: disconnect; reason=543 I (408921) NimBLE: handle=0 our_ota_addr_type=1 our_ota_addr= I (408921) NimBLE: 60:7b:29:00:45:0b I (408931) NimBLE: our_id_addr_type=1 our_id_addr= I (408931) NimBLE: 60:7b:29:00:45:0b I (408941) NimBLE: peer_ota_addr_type=1 peer_ota_addr= I (408941) NimBLE: 68:bc:48:03:92:84 I (408951) NimBLE: peer_id_addr_type=1 peer_id_addr= I (408951) NimBLE: 68:bc:48:03:92:84 I (408961) NimBLE: conn_itvl=6 conn_latency=0 supervision_timeout=500 encrypted=0 authenticated=0 bonded=0

I (408971) NimBLE:

I (408981) NimBLE: GAP procedure initiated: advertise; I (408981) NimBLE: disc_mode=2 I (408981) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (408991) NimBLE:

Log : After restarting ESP32 (Bond info not deleted from android)

D (2151) nvs: nvs_open_from_partition nimble_bond 1 D (2151) nvs: nvs_get_str_or_blob our_sec_1 D (2151) nvs: nvs_get_str_or_blob our_sec_1 D (2151) nvs: nvs_close 2 D (2151) NIMBLE_NVS: KEY in RAM is filled up from NVS index = 1 D (2161) nvs: nvs_open_from_partition nimble_bond 1 D (2161) nvs: nvs_get_str_or_blob our_sec_2 D (2171) nvs: nvs_close 3 D (2171) nvs: nvs_open_from_partition nimble_bond 1 D (2171) nvs: nvs_get_str_or_blob our_sec_3 D (2181) nvs: nvs_close 4 D (2181) NIMBLE_NVS: ble_store_config_our_secs restored 1 bonds D (2191) nvs: nvs_open_from_partition nimble_bond 1 D (2191) nvs: nvs_get_str_or_blob peer_sec_1 D (2201) nvs: nvs_get_str_or_blob peer_sec_1 D (2201) nvs: nvs_close 5 D (2201) NIMBLE_NVS: KEY in RAM is filled up from NVS index = 1 D (2211) nvs: nvs_open_from_partition nimble_bond 1 D (2211) nvs: nvs_get_str_or_blob peer_sec_2 D (2221) nvs: nvs_close 6 D (2221) nvs: nvs_open_from_partition nimble_bond 1 D (2231) nvs: nvs_get_str_or_blob peer_sec_3 D (2231) nvs: nvs_close 7 D (2231) NIMBLE_NVS: ble_store_config_peer_secs restored 1 bonds D (2241) nvs: nvs_open_from_partition nimble_bond 1 D (2241) nvs: nvs_get_str_or_blob cccd_sec_1 D (2251) nvs: nvs_get_str_or_blob cccd_sec_1 D (2251) nvs: nvs_close 8 D (2261) NIMBLE_NVS: CCCD in RAM is filled up from NVS index = 1 D (2261) nvs: nvs_open_from_partition nimble_bond 1 D (2271) nvs: nvs_get_str_or_blob cccd_sec_2 D (2271) nvs: nvs_close 9 D (2271) nvs: nvs_open_from_partition nimble_bond 1 D (2281) nvs: nvs_get_str_or_blob cccd_sec_3 D (2281) nvs: nvs_close 10 D (2291) nvs: nvs_open_from_partition nimble_bond 1 D (2291) nvs: nvs_get_str_or_blob cccd_sec_4 D (2301) nvs: nvs_close 11 D (2301) nvs: nvs_open_from_partition nimble_bond 1 D (2301) nvs: nvs_get_str_or_blob cccd_sec_5 D (2311) nvs: nvs_close 12 D (2311) nvs: nvs_open_from_partition nimble_bond 1 D (2311) nvs: nvs_get_str_or_blob cccd_sec_6 D (2321) nvs: nvs_close 13 D (2321) nvs: nvs_open_from_partition nimble_bond 1 D (2331) nvs: nvs_get_str_or_blob cccd_sec_7 D (2331) nvs: nvs_close 14 D (2331) nvs: nvs_open_from_partition nimble_bond 1 D (2341) nvs: nvs_get_str_or_blob cccd_sec_8 D (2341) nvs: nvs_close 15 D (2351) nvs: nvs_open_from_partition nimble_bond 1 D (2351) nvs: nvs_get_str_or_blob cccd_sec_9 D (2361) nvs: nvs_close 16 D (2361) nvs: nvs_open_from_partition nimble_bond 1 D (2361) nvs: nvs_get_str_or_blob cccd_sec_10 D (2371) nvs: nvs_close 17 D (2371) nvs: nvs_open_from_partition nimble_bond 1 D (2381) nvs: nvs_get_str_or_blob cccd_sec_11 D (2381) nvs: nvs_close 18 D (2381) nvs: nvs_open_from_partition nimble_bond 1 D (2391) nvs: nvs_get_str_or_blob cccd_sec_12 D (2391) nvs: nvs_close 19 D (2391) nvs: nvs_open_from_partition nimble_bond 1 D (2401) nvs: nvs_get_str_or_blob cccd_sec_13 D (2401) nvs: nvs_close 20 D (2411) nvs: nvs_open_from_partition nimble_bond 1 D (2411) nvs: nvs_get_str_or_blob cccd_sec_14 D (2421) nvs: nvs_close 21 D (2421) nvs: nvs_open_from_partition nimble_bond 1 D (2421) nvs: nvs_get_str_or_blob cccd_sec_15 D (2431) nvs: nvs_close 22 D (2431) nvs: nvs_open_from_partition nimble_bond 1 D (2441) nvs: nvs_get_str_or_blob cccd_sec_16 D (2441) nvs: nvs_close 23 D (2441) nvs: nvs_open_from_partition nimble_bond 1 D (2451) nvs: nvs_get_str_or_blob cccd_sec_17 D (2451) nvs: nvs_close 24 D (2461) nvs: nvs_open_from_partition nimble_bond 1 D (2461) nvs: nvs_get_str_or_blob cccd_sec_18 D (2461) nvs: nvs_close 25 D (2471) nvs: nvs_open_from_partition nimble_bond 1 D (2471) nvs: nvs_get_str_or_blob cccd_sec_19 D (2481) nvs: nvs_close 26 D (2481) nvs: nvs_open_from_partition nimble_bond 1 D (2481) nvs: nvs_get_str_or_blob cccd_sec_20 D (2491) nvs: nvs_close 27 D (2491) nvs: nvs_open_from_partition nimble_bond 1 D (2501) nvs: nvs_get_str_or_blob cccd_sec_21 D (2501) nvs: nvs_close 28 D (2501) nvs: nvs_open_from_partition nimble_bond 1 D (2511) nvs: nvs_get_str_or_blob cccd_sec_22 D (2511) nvs: nvs_close 29 D (2521) nvs: nvs_open_from_partition nimble_bond 1 D (2521) nvs: nvs_get_str_or_blob cccd_sec_23 D (2531) nvs: nvs_close 30 D (2531) nvs: nvs_open_from_partition nimble_bond 1 D (2531) nvs: nvs_get_str_or_blob cccd_sec_24 D (2541) nvs: nvs_close 31 D (2541) nvs: nvs_open_from_partition nimble_bond 1 D (2551) nvs: nvs_get_str_or_blob cccd_sec_25 D (2551) nvs: nvs_close 32 D (2551) nvs: nvs_open_from_partition nimble_bond 1 D (2561) nvs: nvs_get_str_or_blob cccd_sec_26 D (2561) nvs: nvs_close 33 D (2561) nvs: nvs_open_from_partition nimble_bond 1 D (2571) nvs: nvs_get_str_or_blob cccd_sec_27 D (2571) nvs: nvs_close 34 D (2581) nvs: nvs_open_from_partition nimble_bond 1 D (2581) nvs: nvs_get_str_or_blob cccd_sec_28 D (2591) nvs: nvs_close 35 D (2591) nvs: nvs_open_from_partition nimble_bond 1 D (2591) nvs: nvs_get_str_or_blob cccd_sec_29 D (2601) nvs: nvs_close 36 D (2601) nvs: nvs_open_from_partition nimble_bond 1 D (2611) nvs: nvs_get_str_or_blob cccd_sec_30 D (2611) nvs: nvs_close 37 D (2611) nvs: nvs_open_from_partition nimble_bond 1 D (2621) nvs: nvs_get_str_or_blob cccd_sec_31 D (2621) nvs: nvs_close 38 D (2631) nvs: nvs_open_from_partition nimble_bond 1 D (2631) nvs: nvs_get_str_or_blob cccd_sec_32 D (2631) nvs: nvs_close 39 D (2641) NIMBLE_NVS: ble_store_config_cccds restored 1 bonds D (2641) nvs: nvs_open_from_partition nimble_bond 1 D (2651) nvs: nvs_get_str_or_blob p_dev_rec_1 D (2651) nvs: nvs_close 40 D (2661) nvs: nvs_open_from_partition nimble_bond 1 D (2661) nvs: nvs_get_str_or_blob p_dev_rec_2 D (2661) nvs: nvs_close 41 D (2671) nvs: nvs_open_from_partition nimble_bond 1 D (2671) nvs: nvs_get_str_or_blob p_dev_rec_3 D (2681) nvs: nvs_close 42 D (2681) nvs: nvs_open_from_partition nimble_bond 1 D (2681) nvs: nvs_get_str_or_blob p_dev_rec_4 D (2691) nvs: nvs_close 43 D (2691) NIMBLE_NVS: peer_dev_rec restored 0 records I (2701) NimBLE_BLE_PRPH: BLE Host Task Started D (2701) NimBLE: registered service 0x1800 with handle=1

D (2711) NimBLE: registering characteristic 0x2a00 with def_handle=2 val_handle=3

D (2721) NimBLE: registering characteristic 0x2a01 with def_handle=4 val_handle=5

D (2721) NimBLE: registered service 0x1801 with handle=6

D (2731) NimBLE: registering characteristic 0x2a05 with def_handle=7 val_handle=8

D (2741) NimBLE: registered service 59462f12-9543-9999-12c8-58b459a2712d with handle=10

D (2741) NimBLE: registering characteristic 5c3a659e-897e-45e1-b016-007107c96df6 with def_handle=11 val_handle=12

D (2761) NimBLE: registering characteristic 5c3a659e-897e-45e1-b016-007107c96df7 with def_handle=13 val_handle=14

I (2771) uart: queue free spaces: 8 V (2771) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args V (2781) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0xE D (2781) intr_alloc: Connected src 34 to int 3 (cpu 1) I (2811) NimBLE: Device Address: I (2811) NimBLE: 5d:4f:bc:40:76:32 I (2811) NimBLE:

I (2821) NimBLE: GAP procedure initiated: advertise; I (2821) NimBLE: disc_mode=2 I (2821) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (2831) NimBLE

Notice that even after device was bonded peer records restored is 0. Please help me out me it.

ricardoquesada commented 1 year ago

It happens when the peripheral does not respond the the LL_FEATURE_REQ in time. Central (ESP32) sends about five LL_FEATURE_REQ... but if there is no answer, from peripheral, I see the lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) message.

I sniffed the connections... and all the ones that fail, have this pattern.

Attached two sessions. Open with Wireshark.

Tested with an ESP32 as central and a Xbox Controller (Fw 5.15 BLE) as peripheral.

I was able to reproduce the "fail" scenario multiple times. Each time that it fails, it is with that pattern.

ms-gamepad-2btn-fail.zip ms-gamepad-2btn-ok.zip

QuentinFarizon commented 1 year ago

Could it be that Espressif sometimes sends ll requests too quickly, like mentionned here : https://devzone.nordicsemi.com/f/nordic-q-a/49428/ll_version_ind-and-ll_feature_req-continuous-messages (in my case, the peripheral is à Nordic board)

Le dim. 29 janv. 2023, 03:23, Ricardo Quesada @.***> a écrit :

I happens when the peripheral does not respond the the LL_FEATURE_REQ in time. Central (ESP32) sends about five LL_FEATURE_REQ... but if there is no answer, from peripheral, I see the lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) message.

I sniffed the connections... and all the ones that fail, have this pattern.

Attached two sessions. Open with Wireshark.

  • ms-gamepad-2btn-fail: shows the pattern mentioned above
  • ms-gamepad-2btn-ok: where the peripheral answers back immediately and works ok.

Tested with an ESP32 as central and a Xbox Controller (Fw 5.15 BLE) as peripheral.

I was able to reproduce the "fail" scenario multiple times. Each time that it fails, it with that pattern.

ms-gamepad-2btn-fail.zip https://github.com/espressif/esp-idf/files/10528800/ms-gamepad-2btn-fail.zip ms-gamepad-2btn-ok.zip https://github.com/espressif/esp-idf/files/10528801/ms-gamepad-2btn-ok.zip

— Reply to this email directly, view it on GitHub https://github.com/espressif/esp-idf/issues/5105#issuecomment-1407540749, or unsubscribe https://github.com/notifications/unsubscribe-auth/AIATUIBITIUWJKOIS77XEO3WUXIBNANCNFSM4MGKRFXA . You are receiving this because you are subscribed to this thread.Message ID: @.***>

ricardoquesada commented 1 year ago

in other situations, I get LL_ENC_REQ (instead of LL_FEATURE_REQ)... but with a similar parttern:

Central (ESP32) sends five LL_ENC_REQ packets right after connection... but peripheral does not answer in time.

Attached session with LL_ENC_REQ

ms-gamepad-3btn-fail.zip

eduardocintas commented 1 year ago

Any update? @ricardoquesada findings seems to point the cause. Any confirm?

I'm using an esp32 as game controller, it works OK with android, but on windows it works only on first connection. If i disconnect by any way (reboot esp32, turning windows bt off, etc) when them are both online, they get automatically connected just for a second and disconnect again esp32 print the "ram_lld_pdu_tx_flush HCI packet count mismatch (1, 2)" and repeat: connect, disconnect, message on an endless loop. If i remove pairing from windows and pair again it works OK once more till i disconnect. Then same problem repeat each time 100% reproducible.

Getting same message and reading @ricardoquesada findings i think i can be having same problem.