Repeat HCI_EVENT_PKT bytes causing "crash"

[tekwiz]

It appears something is causing my Arduino Nano 33 BLE and Arduino Nao 33 BLE Sense to load repeated HCI_EVENT_PKT bytes into _recvBuffer. This is what the serial output looks like when using BLE.debug(Serial):

HCI EVENT RX <- 0404040404
3E
1B

Another example failure:

HCI EVENT RX <- 0404043E0C0201
HCI EVENT RX <- 0401B7DAD7FA625700C80404040404040404040404043E1E02010001B7DAD7FA62571202011A020A070BFF4C001006381E04B474BFCE043E0C02010401B7DAD7FA625700CE040404043E1D020100001BF99F3732501102011A020A0C0AFF4C0010050314109CE8BD04043E0C02010401A7AE7B27BD5000CD040404043E2B02010301D9201A4FC5331F1EFF060001092002DF763A72CF5951F1D056BB5486C5A6EE4DA5E21EE2AF5CAD04043E1D020100001BF99F373250110201
1A

After that, the Serial interface hangs and the main LED repeatedly flashes 4 long and 4 short.

I was able to hack this fix into void HCIClass::poll(unsigned long timeout):

while (HCITransport.available()) {
  byte b = HCITransport.read();

  //haxhaxhax for repeated start-event bytes
  if (_recvIndex == 1 && _recvBuffer[0] == HCI_EVENT_PKT && b == HCI_EVENT_PKT) {
    _recvIndex = 0;
  }
  //ENDhaxhaxhax

  _recvBuffer[_recvIndex++] = b;

  if (_recvBuffer[0] == HCI_ACLDATA_PKT) {

This works for my particular use case because I'm dealing only with advertisements, but it would break for anyone trying to make connections since it would blow up an HCI_Connection_Request event.

If anyone has any guidance for what might be causing the HCI_EVENT_PKT byte to be repeated, I can work on a real patch and pull-request.

[polldo]

Hi @tekwiz ,
can you please share a test sketch which I can use to reproduce the issue?
Also, have you tried also other boards or just the nano ble/ble sense?
It may be possible that packets are dropped here https://github.com/arduino-libraries/ArduinoBLE/blob/master/src/utility/HCICordioTransport.cpp#L262 . To verify this, you could insert a Serial.print there. The packet drop may occur when too much time passes between calls to BLE.poll() function.
Thanks!

[harikattar]

It's not trivially reproducible. I'm sending 100+ byte notifications at 40-50hz and it may take 20-30 minutes to crash or it may work for hours.

I'm able to trigger it sending notifications to a generic BLE explorer app (any, the receiver doesn't matter. nrfConnect from nordic on android, gatttool on linux, etc). I don't know if bumping the MTU is required but mine is 243.

[polldo]

This issue is now encapsulated here #130 . There you can find a description of the problem and some possible solutions we are going to analyze.
Please refer to that new issue, I'm going to close this one.

[baconcheese113]

Getting the same issue on my Arduino Nano 33 BLE, Xiao nRF52840, and Xiao nRF52840 Sense. Not running into this problem with my Arduino Nano 33 IoT.

I can make it more likely to reproduce by setting BLE.debug(Serial); in setup() or shrinking the size of my _recvBuffer and _aclPktBuffer. Following some of the suggestions in #130 like increasing the buffer sizes can delay the error up to 2 hours. BLE.poll() is called inbetween almost every line of code. There are 50+ other BLE devices advertising here, but others have run this code without any problems if the environment only has a few BLE devices

#include <Arduino.h>
#include <ArduinoBLE.h>

unsigned long scanHits;
unsigned long lastScanStart;

void setup() {
  Serial.begin(115200);
  BLE.debug(Serial);
  while(!BLE.begin());
}

void loop() {
  int scanRes = BLE.scanForName("Client", false);
  lastScanStart = millis();
  while(millis() < lastScanStart + 200) {
    BLE.poll();
    if(BLE.available()) {
      ++scanHits;
    }
  }
  int stopRes = -1;
  int fails = 0;
  while(stopRes == -1) {
    unsigned long beforeStopTime = millis();
    BLE.poll();
    BLE.stopScan(); // for this port of the code I'm just assuming the stopRes when it goes over its typical 20ms
    if(millis() - beforeStopTime < 100) {
      stopRes = 0;
    }
    BLE.poll();
    Serial.print("Uptime: (");
    Serial.print(millis() / 1000);
    Serial.print(")s, interval: (");
    Serial.print(millis() - lastScanStart);
    Serial.print(")ms, stopScan duration: (");
    Serial.print(millis() - beforeStopTime);
    Serial.print(")ms, total hits: ");
    Serial.print(scanHits);
    Serial.print(", scanRes: ");
    Serial.print(scanRes);
    Serial.print(", stopRes: ");
    Serial.println(stopRes);
    if(stopRes != 0) {
      unsigned long cooldownStartTime = millis();
      while(millis() < cooldownStartTime + 3000) {
        BLE.poll();
      }
    }
    // if things go south, stop making new logs
    if(++fails > 10) {
      Serial.println("Failed to recover");
      while(true);
    }
  }
  fails = 0;
}

My logs look like

Uptime: (28)s, interval: (222)ms, stopScan duration: (16)ms, total hits: 73, scanRes: 1, stopRes: 0 <--- my log at the end of each scan window, stopRes is the return value of `HCIClass::sendCommand()` called from `stopScan()`
HCI COMMAND TX -> 010C20020001
HCI EVENT RX <- 040E04010C2000
HCI COMMAND TX -> 010B200701100010000000
HCI EVENT RX <- 040E04010B2000
HCI COMMAND TX -> 010C20020101
HCI EVENT RX <- 040E04010C2000
HCI EVENT RX <- 043E2802010201BB182367715D1C03039FFE17169FFE02726934444A346F58674C6700000182CE78D006BC
HCI EVENT RX <- 043E1602010401BB182367715D0A09FFE000007BCA9ECFD8BC
HCI EVENT RX <- 043E2902010000D62780EA70E01D0201061916F7FD0170F16329EBD6FDA3C0BC8B77EDFC4D010000000001B3
HCI EVENT RX <- 043E1B02010301F5DA05F7BB390F02011A0BFF4C0009060309C0A8001CB9
HCI EVENT RX <- 043E28020103006C87AEE5FC241C1BFF7500420401806024FCE5AE876C26FCE5AE876B01630000000000B4
HCI EVENT RX <- 043E280201020130778943365D1C03039FFE17169FFE0000000000000000000000000000000000000000BB
HCI EVENT RX <- 043E160201040130778943365D0A09FFE0000041CA6E8C50BB
HCI EVENT RX <- 043E2702010000FB6EF4504B801B02010604FFFF02001209734341505F383034623530663436656662B0
HCI EVENT RX <- 043E280201020158B1B900C0411C03039FFE17169FFE0000000000000000000000000000000000000000C3
HCI EVENT RX <- 043E160201040158B1B900C0410A09FFE0000102CA6143B8C3
HCI EVENT RX <- 043E2B02010001AF17B95E8CCB1F1EFF4C001219390316DFBD308608433D5BE44BAAA6A8F6D12B479421DD0055B1
HCI EVENT RX <- 043E20020100019BD93354166614020119100948616E646C65497420436C69656E74C3
HCI EVENT RX <- 043E0C020104019BD93354166600C3
HCI EVENT RX <- 043E2B02010000634C380703BA1F130969686F6D656E745F48363035325F3443363307FF0188EC000101020106B1
HCI EVENT RX <- 043E2802010201BDA3049898581C03039FFE17169FFE0000000000000000000000000000000000000000B2
HCI EVENT RX <- 043E1E02010001A20A967DC5411202011A020A0C0BFF4C00100601194477CB78AE
HCI EVENT RX <- 043E0C02010401A20A967DC54100AE
HCI EVENT RX <- 043E1402010301AACA39CD57F30807FF4C0012020003B0
HCI EVENT RX <- 043E1B02010301CD3B0FF7AA030F02011A0BFF4C000906031B0A00004DB0
HCI EVENT RX <- 043E2702010000FB6EF4504B801B02010604FFFF02001209734341505F383034623530663436656662AF
HCI EVENT RX <- 043E28020103006C87AEE5FC241C1BFF7500420401806024FCE5AE876C26FCE5AE876B01630000000000B4
HCI EVENT RX <- 043E1B02010301F5DA05F7BB390F02011A0BFF4C0009060309C0A8001CBA
HCI EVENT RX <- 043E2B02010001AF17B95E8CCB1F1EFF4C001219390316DFBD308608433D5BE44BAAA6A8F6D12B479421DD0055B2
HCI COMMAND TX -> 010C20020000
HCI EVENT RX <- 04043E0C02010400FB6EF4504B8000BA043E280201020130778943365D1C03039FFE17169FFE0000000000000000000000000000000000000000B6040E04010C20
0
Uptime: (30)s, interval: (1327)ms, stopScan duration: (1014)ms, total hits: 73, scanRes: 1, stopRes: -1  
HCI COMMAND TX -> 010C20020000
HCI EVENT RX <- 040E04010C2000

Then it just repeats the error