ArduinoBLE: BTstack's Enable Notifications fails against ArduinoBLE GATT Server

Originally reported this bug to the pi pico arduino library here: https://github.com/earlephilhower/arduino-pico/issues/1735 but was directed to check here for a potential issue/fix as the implementation is based on btstack and the issue could be here. Here is the full content of that issue:

Hardware: Pi Pico W Library Version: 3.6.0 (earlephilhower/arduino-pico)

I am not sure if it I am doing something wrong with the Bluetooth implementation or this is an actual bug but it does appear the callbacks are not working as expected in the current Bluetooth stack.

I am connecting to a Nano33BLESense that has 1 characteristic that is setup to notify and writes a new value every 5 seconds. I have tested the notify options with an android app to verify notification updates are working on the nano

I modified the LECentral code slightly to try to get updates from characteristic subscriptions but these callbacks do not appear to work.

Basic state order:

Connect to peripheral (Nano33BLESense)
Discover characteristics
Subscribe to characteristic
Wait for characteristic updates

1-2 work as expected

Subscribe callback will always return BLEState of BLE_STATUS_OTHER_ERROR when you attempt to subscribe, no matter how many times you attempt. If you perform a read of the characteristic, then subscribe, you will receive a subscribe call back status of BLE_STATUS_OK
Never receives any callback even after a subscribe callback of BLE_STATUS_OK

Additional testing on just reading the characteristic value every second resulted in a subscribe callback every time a read callback was completed. No further subscriptions are occurring past the very first successful subscription but a successful read callback in turn receives a subscription callback.

The gattCharacteristicNotification is never called despite successful subscription callback status and continual update of the characteristic in the nano.

Console Output showing connection and initial subscription failure, read, then success:

10:52:49.616 -> BLE ShieldService V2 found!
10:52:49.616 -> 
10:52:49.804 -> Device connected!
10:52:50.692 -> Service Discovered: :1800
10:52:50.692 -> Service Discovered: :1801
10:52:50.786 -> Service Discovered: :B8E06067-62AD-41BA-9231-206AE80AB550
10:52:50.786 -> Our service located!
10:52:50.879 -> Service discovery finished
10:52:50.972 -> Characteristic Discovered: F897177B-AEE8-4767-8ECC-CC694FD5FCEE, handle 0xC
10:52:50.972 -> Characteristic found: RX
10:52:50.972 -> Characteristic Discovered: BF45E40A-DE2A-4BC8-BBA0-E5D6065F1B4B, handle 0xF
10:52:50.972 -> Characteristic found: TX
10:52:50.972 -> Characteristic Discovered: 2FBC0F31-726A-4014-B9FE-C8BE0652E982, handle 0x11
10:52:50.972 -> Characteristic found: Baudrate
10:52:50.972 -> Characteristic Discovered: 1D132F28-5D85-11EE-8C99-0242AC120002, handle 0x13
10:52:50.972 -> Characteristic found: Intent
10:52:50.972 -> Characteristic discovery finished, status 1
10:52:50.972 -> Subscribing to charRX
10:52:50.972 -> Subscribing
10:52:51.066 -> 
10:52:51.066 -> Subscribe Callback: 4
10:52:51.066 -> BLE_STATUS_OTHER_ERROR
10:52:51.160 -> Read callback
10:52:51.160 -> Read Value:108 
10:52:51.160 -> 
10:52:51.160 -> Subscribe Callback: 0
10:52:51.160 -> BLE_STATUS_OK

One second reads showing a updates from nano but also a seemingly random subscription callback during every read and no gattCharacteristicNotification ever received:

`10:52:58.091 -> Subscribe Callback: 0
10:52:58.091 -> BLE_STATUS_OK
10:52:58.978 -> Reading...
10:52:59.071 -> Read callback
10:52:59.071 -> Read Value:80 
10:52:59.071 -> 
10:52:59.071 -> Subscribe Callback: 0
10:52:59.071 -> BLE_STATUS_OK
10:52:59.956 -> Reading...
10:53:00.049 -> Read callback
10:53:00.049 -> Read Value:80 
10:53:00.049 -> 
10:53:00.049 -> Subscribe Callback: 0
10:53:00.049 -> BLE_STATUS_OK
10:53:00.968 -> Reading...
10:53:01.060 -> Read callback
10:53:01.060 -> Read Value:81 
`

Pi Pico W Code:


#include <BTstackLib.h>
#include <SPI.h>

/*
   EXAMPLE_START(LECentral): LE Central

   @text Compared with the other examples, the LE Central is
   a bit more complex. This is because it performs multiple
   steps in sequence as it is common with GATT Client APIs.

   It shows how to first scan for other
   devices and then connect to one. When connected, a series of
   GATT Client operations are performed: first the list of
   GATT Services is queried. If a particular service is found,
   the list of its GATT Characteristics is retrieved and a set
   of known Characteristics are cached for later access.
*/

/*
   @section Characteristic Summary
   @text As multiple Characteristics need to be found, a custom
   struct is used to collect all information about it. This allows
   to define the list of necessary characteristics in the
   characteristics[] array
*/
/* LISTING_START(LECentralSummary): Characteristic Summary */

// BLE Shield Service V2 incl. used Characteristics
UUID bleShieldServiceV2UUID("B8E06067-62AD-41BA-9231-206AE80AB550");

typedef struct characteristic_summary {
  UUID         uuid;
  const char * name;
  bool         found;
  BLECharacteristic characteristic;
} characteristic_summary_t;

typedef enum characteristicIDs {
  charRX = 0,
  charTX,
  charBaud,
  charBdAddr,
  intent,
  numCharacteristics  /* last one */
} characteristicIDs_t;

characteristic_summary characteristics[] = {
  { UUID("F897177B-AEE8-4767-8ECC-CC694FD5FCEE"), "RX", false, BLECharacteristic() },
  { UUID("bf45e40a-de2a-4bc8-bba0-e5d6065f1b4b"), "TX", false, BLECharacteristic() },
  { UUID("2fbc0f31-726a-4014-b9fe-c8be0652e982"), "Baudrate", false, BLECharacteristic() },
  { UUID("65c228da-bad1-4f41-b55f-3d177f4e2196"), "BD ADDR", false, BLECharacteristic() },
  { UUID("1d132f28-5d85-11ee-8c99-0242ac120002"), "Intent", false, BLECharacteristic() }
};

/* LISTING_END(LECentralSummary): Characteristic Summary */

// Application state
BLEDevice  myBLEDevice;
BLEService myBLEService;
bool serviceFound;
bool sendCounter = false;
bool discovered = false;
bool shouldSubscribe = true;

int counter = 0;
char counterString[20];

long timer = 0;
// static btstack_timer_source_t heartbeat;

/*
   @section Setup
   @text In the setup, various callbacks are registered. After that
   we start scanning for other devices
*/
/* LISTING_START(LECentralSetup): LE Central Setup */
void setup(void) {
  Serial.begin(9600);
  while (!Serial);
  BTstack.setBLEAdvertisementCallback(advertisementCallback);
  BTstack.setBLEDeviceConnectedCallback(deviceConnectedCallback);
  BTstack.setBLEDeviceDisconnectedCallback(deviceDisconnectedCallback);
  BTstack.setGATTServiceDiscoveredCallback(gattServiceDiscovered);
  BTstack.setGATTCharacteristicDiscoveredCallback(gattCharacteristicDiscovered);
  BTstack.setGATTCharacteristicNotificationCallback(gattCharacteristicNotification);
  BTstack.setGATTCharacteristicReadCallback(gattReadCallback);
  BTstack.setGATTCharacteristicWrittenCallback(gattWrittenCallback);
  BTstack.setGATTCharacteristicSubscribedCallback(gattSubscribedCallback);
  BTstack.setup();
  BTstack.bleStartScanning();
  timer = millis();
}
/* LISTING_END(LECentralSetup): LE Central Setup */

/*
   @section Loop

   @text In the standard Arduino loop() function, BTstack's loop() is called first
   If we're connected, we send the string "BTstack" plus a counter as fast as possible.
   As the Bluetooth module might be busy, it's important to check the result of the
   writeCharacteristicWithoutResponse() call. If it's not ok, we just try again in the
   next loop iteration.
*/
/* LISTING_START(LECentralLoop): Loop */
void loop(void) {
  BTstack.loop();
  if(discovered){
    //Serial.println("Reading Char");
    //myBLEDevice.readCharacteristic(&characteristics[charRX].characteristic);
    if( (millis() - timer) > 1000){
      timer = millis();
      if(shouldSubscribe){
        Serial.println("Subscribing");
        myBLEDevice.subscribeForNotifications(&characteristics[charRX].characteristic);
      }
      else{
        Serial.println("Reading...");
        myBLEDevice.readCharacteristic(&characteristics[charRX].characteristic);
      }
    }     
  }
}
/* LISTING_END(LECentralLoop): Loop */

/*
   @section Advertisement Callback

   @text When an Advertisement is received, we check if it contains
   the UUID of the service we're interested in. Only a single service
   with a 128-bit UUID can be contained in and Advertisement and not
   all BLE devices provides this. Other options are to match on the
   reported device name or the BD ADDR prefix.

   If we found an interesting device, we try to connect to it.
*/
/* LISTING_START(LECentralAdvertisementCallback): Advertisement Callback */
void advertisementCallback(BLEAdvertisement *bleAdvertisement) {
  Serial.print("Device discovered: ");
  Serial.print(bleAdvertisement->getBdAddr()->getAddressString());
  Serial.print(", RSSI: ");
  Serial.println(bleAdvertisement->getRssi());
  if (bleAdvertisement->containsService(&bleShieldServiceV2UUID)) {
    Serial.println("\nBLE ShieldService V2 found!\n");
    BTstack.bleStopScanning();
    BTstack.bleConnect(bleAdvertisement, 10000);  // 10 s
  }
}
/* LISTING_END(LECentralAdvertisementCallback): Advertisement Callback */

/*
   @section Device Connected Callback

   @text At the end of bleConnect(), the device connected callback is callec.
   The status argument tells if the connection timed out, or if the connection
   was established successfully.

   On a successful connection, a GATT Service Discovery is started.
*/
/* LISTING_START(LECentralDeviceConnectedCallback): Device Connected Callback */
void deviceConnectedCallback(BLEStatus status, BLEDevice *device) {
  switch (status) {
    case BLE_STATUS_OK:
      Serial.println("Device connected!");
      myBLEDevice = *device;
      counter = 0;
      myBLEDevice.discoverGATTServices();
      break;
    case BLE_STATUS_CONNECTION_TIMEOUT:
      Serial.println("Error while Connecting the Peripheral");
      BTstack.bleStartScanning();
      break;
    default:
      break;
  }
}
/* LISTING_END(LECentralDeviceConnectedCallback): Device Connected Callback */

/*
   @section Device Disconnected Callback

   @text If the connection to a device breaks, the device disconnected callback
   is called. Here, we start scanning for new devices again.
*/
/* LISTING_START(LECentralDeviceDisconnectedCallback): Device Disconnected Callback */
void deviceDisconnectedCallback(BLEDevice * device) {
  (void) device;
  Serial.println("Disconnected, starting over..");
  sendCounter = false;
  BTstack.bleStartScanning();
}
/* LISTING_END(LECentralDeviceDisconnectedCallback): Device Disconnected Callback */

/*
   @section Service Discovered Callback

   @text The service discovered callback is called for each service and after the
   service discovery is complete. The status argument is provided for this.

   The main information about a discovered Service is its UUID.
   If we find our service, we store the reference to this service.
   This allows to discover the Characteristics for our service after
   the service discovery is complete.
*/
/* LISTING_START(LECentralServiceDiscoveredCallback): Service Discovered Callback */
void gattServiceDiscovered(BLEStatus status, BLEDevice *device, BLEService *bleService) {
  switch (status) {
    case BLE_STATUS_OK:
      Serial.print("Service Discovered: :");
      Serial.println(bleService->getUUID()->getUuidString());
      if (bleService->matches(&bleShieldServiceV2UUID)) {
        serviceFound = true;
        Serial.println("Our service located!");
        myBLEService = *bleService;
      }
      break;
    case BLE_STATUS_DONE:
      Serial.println("Service discovery finished");
      if (serviceFound) {
        device->discoverCharacteristicsForService(&myBLEService);
      }
      break;
    default:
      Serial.println("Service discovery error");
      break;
  }
}
/* LISTING_END(LECentralServiceDiscoveredCallback): Service Discovered Callback */

/*
   @section Characteristic Discovered Callback

   @text Similar to the Service Discovered callback, the Characteristic Discovered
   callback is called for each Characteristic found and after the discovery is complete.

   The main information is again its UUID. If we find a Characteristic that we're
   interested in, it's name is printed and a reference stored for later.

   On discovery complete, we subscribe to a particular Characteristic to receive
   Characteristic Value updates in the Notificaation Callback.
*/
/* LISTING_START(LECentralCharacteristicDiscoveredCallback): Characteristic Discovered Callback */
void gattCharacteristicDiscovered(BLEStatus status, BLEDevice *device, BLECharacteristic *characteristic) {
  switch (status) {
    case BLE_STATUS_OK:
      Serial.print("Characteristic Discovered: ");
      Serial.print(characteristic->getUUID()->getUuidString());
      Serial.print(", handle 0x");
      Serial.println(characteristic->getCharacteristic()->value_handle, HEX);
      int i;
      for (i = 0; i < numCharacteristics; i++) {
        if (characteristic->matches(&characteristics[i].uuid)) {
          Serial.print("Characteristic found: ");
          Serial.println(characteristics[i].name);
          characteristics[i].found = 1;
          characteristics[i].characteristic = *characteristic;
          break;
        }
      }
      break;
    case BLE_STATUS_DONE:
      Serial.print("Characteristic discovery finished, status ");
      Serial.println(status, HEX);
      if (characteristics[charRX].found) {
        Serial.println("Subscribing to charRX");
        discovered=true;
        device->subscribeForNotifications(&characteristics[charRX].characteristic);
      }
      break;
    default:
      Serial.println("Characteristics discovery error");
      break;
  }
}
/* LISTING_END(LECentralCharacteristicDiscoveredCallback): Characteristic Discovered Callback */

/*
   @section Subscribed Callback

   @text After the subscribe operation is complete, we get notified if it was
   successful. In this example, we read the Characteristic that contains the
   BD ADDR of the other device. This isn't strictly necessary as we already
   know the device address from the Advertisement, but it's a common pattern
   with iOS as the device address is hidden from applications.
*/
/* LISTING_START(LECentralSubscribedCallback): Subscribed Callback */
void gattSubscribedCallback(BLEStatus status, BLEDevice * device) {
  (void) status;
  Serial.print("\nSubscribe Callback: ");
  Serial.println(status);
  switch (status) {
    case BLE_STATUS_OK:
      Serial.println("BLE_STATUS_OK");
      shouldSubscribe=false;
      break;
    case BLE_STATUS_OTHER_ERROR:
      Serial.println("BLE_STATUS_OTHER_ERROR");
      device->readCharacteristic(&characteristics[charRX].characteristic);
      shouldSubscribe=false;
  }
}
/* LISTING_END(LECentralSubscribedCallback): Subscribed Callback */

/*
   @section Read Callback

   @text The Read callback is called with the result from a read operation.
   Here, we write to the TX Characteristic next.
*/
/* LISTING_START(LECentralReadCallback): Read Callback */
void gattReadCallback(BLEStatus status, BLEDevice *device, uint8_t *value, uint16_t length) {
  (void) status;
  (void) length;
  Serial.print("Read callback\nRead Value:");
  // Print each element of the value array
  for (int i = 0; i < length; i++) {
    Serial.print(value[i]);
    Serial.print(" ");
  }
  Serial.println();
}
/* LISTING_END(LECentralReadCallback): Read Callback */

/*
   @section Written Callback

   @text After the write operation is complete, the Written Callback is callbed with
   the result in the status argument. As we're done with the initial setup of the remote
   device, we set the flag to write the test string as fast as possible.
*/
/* LISTING_START(LECentralWrittenCallback): Written Callback */
void gattWrittenCallback(BLEStatus status, BLEDevice *device) {
  (void) status;
  (void) device;
  sendCounter = true;
}
/* LISTING_END(LECentralWrittenCallback): Written Callback */

/*
   @section Notification Callback
72
   @text Notifications for Characteristic Value Updates are delivered via the
   Notification Callback. When more than one Characteristic is subscribed,
   the value handle can be used to distinguish between them. The
   BLECharacteristic.isValueHandle(int handle) allows to test if a value handle
   belongs to a particular Characteristic.
*/
/* LISTING_START(LECentralNotificationCallback): Notification Callback */
void gattCharacteristicNotification(BLEDevice *device, uint16_t value_handle, uint8_t *value, uint16_t length) {
  Serial.print("Char Notification: ");
  (void) device;
  (void) value_handle;
  (void) length;
  Serial.print("Notification: ");
  Serial.println((const char *)value);
}
/* LISTING_END(LECentralNotificationCallback): Notification Callback */

NanoBLE33Sense Code:

/*
  BLE_Peripheral.ino

  This program uses the ArduinoBLE library to set-up an Arduino Nano 33 BLE 
  as a peripheral device and specifies a service and a characteristic. Depending 
  of the value of the specified characteristic, an on-board LED gets on. 

  The circuit:
  - Arduino Nano 33 BLE. 

  This example code is in the public domain.
*/

#include <ArduinoBLE.h>      

// BLE Shield Service V2 incl. used Characteristics
const char* bleShieldServiceV2UUID = "B8E06067-62AD-41BA-9231-206AE80AB550";
const char* picoVoiceCharacteristicRxUuid = "F897177B-AEE8-4767-8ECC-CC694FD5FCEE";
const char* picoVoiceCharacteristicTxUuid = "bf45e40a-de2a-4bc8-bba0-e5d6065f1b4b";
const char* picoVoiceCharacteristicBaudUuid = "2fbc0f31-726a-4014-b9fe-c8be0652e982";
const char* picoVoiceIntentUuid = "1d132f28-5d85-11ee-8c99-0242ac120002";

BLEByteCharacteristic picoVoiceCharacteristicTx(picoVoiceCharacteristicTxUuid, BLERead | BLEWrite);
BLEByteCharacteristic picoVoiceCharacteristicRx(picoVoiceCharacteristicRxUuid, BLERead | BLENotify);
BLEByteCharacteristic picoVoiceCharacteristicBaud(picoVoiceCharacteristicBaudUuid, BLERead);
BLEStringCharacteristic picoVoiceCharacteristicIntent(picoVoiceIntentUuid, BLERead, 100);

BLEService bleShieldService(bleShieldServiceV2UUID);
long lastWrite = 0;

void setup() {
  Serial.begin(9600);
  while (!Serial);  

  if (!BLE.begin()) {
    Serial.println("- Starting Bluetooth® Low Energy module failed!");
    while (1);
  }

  BLE.setLocalName("Arduino Nano 33 BLE (Peripheral)");

  BLE.setAdvertisedService(bleShieldService);

  bleShieldService.addCharacteristic(picoVoiceCharacteristicRx);
  bleShieldService.addCharacteristic(picoVoiceCharacteristicTx);
  bleShieldService.addCharacteristic(picoVoiceCharacteristicBaud);
  bleShieldService.addCharacteristic(picoVoiceCharacteristicIntent);

  BLE.addService(bleShieldService);

  picoVoiceCharacteristicRx.writeValue((byte)0x50);
  picoVoiceCharacteristicIntent.writeValue("");
  BLE.advertise();

  Serial.println("Nano 33 BLE (Peripheral Device)");
  Serial.println(" ");
}

void loop() {
  BLEDevice central = BLE.central();
  Serial.println("- Discovering central device...");
  delay(500);

  if (central) {
    Serial.println("* Connected to central device!");
    Serial.print("* Device MAC address: ");
    Serial.println(central.address());
    Serial.println(" ");
    lastWrite = millis();
    byte val = 0x50;
    while (central.connected()) {
      BLE.poll();
      central.poll();
        if( (millis() - lastWrite) > 5000){ 
          Serial.print("Writing RX: ");
          Serial.println(val);
          picoVoiceCharacteristicRx.writeValue(val);
          lastWrite = millis();
          val+=1;
        }
    }
    Serial.println("* Disconnected to central device!");
  }   
}

I didn't know anybody is still using this Arduino abstraction. If possible please use the native BTstack API.

Anyway, please check if you get an error for the call to device->subscribeForNotifications()

Also, please enable the packet logger to see if the Bluetooth communication is correct. See here: https://github.com/raspberrypi/pico-examples/pull/427/files

What is the native BTstack API? I'm not aware of any other arduino library for the pi pico w that enables bluetooth so this appears to be the only option currently out there.

Since I'm not using this directly but using the project that is using this as it's core BT API, I don't really have a way to enable debugging directly as it doesn't appear to have the same options in the make file for that project.

Well, I was referring to use the Pico SDK that includes BTstack.

PacketLogger: there are enablePacketLogger() and enableDebugLogger() in the BTstackManager class.

Anyway, please also check if you get an error for the call to device->subscribeForNotifications()

I'll have to spend some time with the pico SDK, haven't dealt with that as I've relied on this arduino library for past projects so it'll be some work to try to move everything to that dev style.

Anyway, please also check if you get an error for the call to device->subscribeForNotifications()

Are you referring to using this library as is? Might have been lost in the original issue report as it was long but this always returns an error until you attempt to read a characteristic. I can attempt to subscribe to a characteristic in a loop forever and it will always return BLE_STATUS_OTHER_ERROR. Once you read the characteristic, that's where you start seeing subscribe callbacks (even though subscribes aren't happening) and never a characteristic notification callback.

Yes. This call device->subscribeForNotifications() might return an error (at least in theory). On the other hand, all BTstack API function either return an error, or, execute the callback later. As you're getting the subscribed callback, there's probably no error returned here.

Ok, then let's the packet logger to shed some light on the issue:

BTstack.enablePacketLogger() BTstack.enableDebugLogger()

Make sure you've enabled Tools->Debug Port->Serial or, since the BTstack library uses printf() to dump debugging, you won't be able to capture anything.

Here is the debug output. Not really sure what to make of it though.

10:34:27.963 -> [00:00:10.717] LOG -- att_db.c.237: att_set_db 0x20007f89
10:34:27.963 -> [00:00:10.717] LOG -- hci.c.5207: hci_power_control: 1, current mode 0
10:34:27.963 -> [00:00:11.579] LOG -- hci.c.7684: BTSTACK_EVENT_STATE 1
10:34:27.963 -> [00:00:11.579] EVT <= 60 01 01 
10:34:27.963 -> [00:00:11.581] CMD => 03 0C 00 
10:34:27.963 -> [00:00:11.581] EVT <= 6E 00 
10:34:27.963 -> [00:00:11.586] EVT <= 0E 04 01 03 0C 00 
10:34:27.963 -> [00:00:11.586] CMD => 01 10 00 
10:34:27.963 -> [00:00:11.587] EVT <= 6E 00 
10:34:27.963 -> [00:00:11.588] EVT <= 0E 0C 01 01 10 00 0B 00 00 0B 31 01 10 23 
10:34:27.963 -> [00:00:11.588] LOG -- hci.c.2841: Treat Cypress/Infineon as Broadcom
10:34:27.963 -> [00:00:11.588] LOG -- hci.c.2849: Manufacturer: 0x000f
10:34:27.963 -> [00:00:11.589] CMD => 14 0C 00 
10:34:27.963 -> [00:00:11.589] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.590] EVT <= 0E FC 01 14 0C 00 53 44 49 4F 20 33 37 5F 34 4D 20 77 6C 62 67 61 5F 42 55 20 52 50 49 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
10:34:28.010 -> [00:00:11.594] LOG -- hci.c.2695: local name: SDIO 37_4M wlbga_BU RPI
10:34:28.010 -> [00:00:11.594] CMD => 02 10 00 
10:34:28.010 -> [00:00:11.595] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.596] EVT <= 0E 44 01 02 10 00 FF FF FF 03 CC FF 0F FF FF FF FC 1F F2 0F E8 FE 3F F7 8F FF 1C 00 04 00 61 F7 FF FF 7F F8 FF FF FF FF FF 0F 00 00 80 04 00 0C 00 04 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
10:34:28.010 -> [00:00:11.597] LOG -- hci.c.2663: Command 0x00 supported 2/5
10:34:28.010 -> [00:00:11.597] LOG -- hci.c.2663: Command 0x01 supported 10/4
10:34:28.010 -> [00:00:11.597] LOG -- hci.c.2663: Command 0x02 supported 14/7
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x03 supported 18/3
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x04 supported 20/4
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x05 supported 22/2
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x06 supported 24/6
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x07 supported 32/1
10:34:28.010 -> [00:00:11.598] LOG -- hci.c.2663: Command 0x08 supported 32/3
10:34:28.010 -> [00:00:11.599] LOG -- hci.c.2663: Command 0x09 supported 32/6
10:34:28.010 -> [00:00:11.599] LOG -- hci.c.2663: Command 0x0a supported 34/0
10:34:28.010 -> [00:00:11.599] LOG -- hci.c.2663: Command 0x0b supported 35/1
10:34:28.010 -> [00:00:11.599] LOG -- hci.c.2663: Command 0x0c supported 35/3
10:34:28.010 -> [00:00:11.599] LOG -- hci.c.2668: Local supported commands summary 00001fff
10:34:28.010 -> [00:00:11.600] LOG -- btstack_crypto.c.1121: controller supports ECDH operation: 1
10:34:28.010 -> [00:00:11.600] LOG -- hci.c.1868: Set Public BD ADDR to 28:CD:C1:06:BF:47
10:34:28.010 -> [00:00:11.600] CMD => 01 FC 06 47 BF 06 C1 CD 28 
10:34:28.010 -> [00:00:11.601] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.602] EVT <= 0E 04 01 01 FC 00 
10:34:28.010 -> [00:00:11.602] CMD => 09 10 00 
10:34:28.010 -> [00:00:11.603] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.604] EVT <= 0E 0A 01 09 10 00 47 BF 06 C1 CD 28 
10:34:28.010 -> [00:00:11.604] LOG -- hci.c.2792: Local Address, Status: 0x00: Addr: 28:CD:C1:06:BF:47
10:34:28.010 -> [00:00:11.605] CMD => 05 10 00 
10:34:28.010 -> [00:00:11.605] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.606] EVT <= 0E 0B 01 05 10 00 FD 03 40 08 00 0A 00 
10:34:28.010 -> [00:00:11.607] LOG -- hci.c.2710: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 3 / SCO size 64, count 3
10:34:28.010 -> [00:00:11.607] CMD => 03 10 00 
10:34:28.010 -> [00:00:11.607] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.608] EVT <= 0E 0C 01 03 10 00 BF FE CF FE DB FF 7B 87 
10:34:28.010 -> [00:00:11.609] LOG -- hci.c.2826: ACL Packet types ff1e
10:34:28.010 -> [00:00:11.609] LOG -- hci.c.2830: SCO Packet types 03ff - eSCO 1
10:34:28.010 -> [00:00:11.609] LOG -- hci.c.2833: BR/EDR support 1, LE support 1
10:34:28.010 -> [00:00:11.609] CMD => 33 0C 07 00 04 78 03 00 03 00 
10:34:28.010 -> [00:00:11.610] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.611] EVT <= 0E 04 01 33 0C 00 
10:34:28.010 -> [00:00:11.611] CMD => 31 0C 01 03 
10:34:28.010 -> [00:00:11.612] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.613] EVT <= 0E 04 01 31 0C 00 
10:34:28.010 -> [00:00:11.613] CMD => 01 0C 08 FF FF FF FF FF FF FF 3F 
10:34:28.010 -> [00:00:11.614] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.615] EVT <= 0E 04 01 01 0C 00 
10:34:28.010 -> [00:00:11.615] CMD => 63 0C 08 00 00 00 02 00 00 00 00 
10:34:28.010 -> [00:00:11.616] EVT <= 6E 00 
10:34:28.010 -> [00:00:11.617] EVT <= 0E 04 01 63 0C 00 
10:34:28.010 -> [00:00:11.617] CMD => 56 0C 01 01 
10:34:28.010 -> [00:00:11.618] EVT <= 6E 00 
10:34:28.104 -> [00:00:11.723] EVT <= 0E 04 01 56 0C 00 
10:34:28.104 -> [00:00:11.724] CMD => 45 0C 01 00 
10:34:28.104 -> [00:00:11.724] EVT <= 6E 00 
10:34:28.104 -> [00:00:11.725] EVT <= 0E 04 01 45 0C 00 
10:34:28.104 -> [00:00:11.726] CMD => 7A 0C 01 01 
10:34:28.104 -> [00:00:11.726] EVT <= 6E 00 
10:34:28.104 -> [00:00:11.727] EVT <= 0E 04 01 7A 0C 00 
10:34:28.104 -> [00:00:11.727] CMD => 2F 0C 01 01 
10:34:28.104 -> [00:00:11.728] EVT <= 6E 00 
10:34:28.104 -> [00:00:11.729] EVT <= 0E 04 01 2F 0C 00 
10:34:28.104 -> [00:00:11.729] CMD => 5B 0C 01 01 
10:34:28.104 -> [00:00:11.730] EVT <= 6E 00 
10:34:28.104 -> [00:00:11.731] EVT <= 0E 04 01 5B 0C 00 
10:34:28.104 -> [00:00:11.731] LOG -- hci.c.2115: BCM: Route SCO data via HCI transport
10:34:28.104 -> [00:00:11.731] CMD => 1C FC 05 01 00 00 00 00 
10:34:28.104 -> [00:00:11.732] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.733] EVT <= 0E 04 01 1C FC 00 
10:34:28.151 -> [00:00:11.733] CMD => 02 20 00 
10:34:28.151 -> [00:00:11.734] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.735] EVT <= 0E 07 01 02 20 00 FB 00 08 
10:34:28.151 -> [00:00:11.735] LOG -- hci.c.2740: hci_le_read_buffer_size: acl size 251, acl count 8
10:34:28.151 -> [00:00:11.736] CMD => 6D 0C 02 01 00 
10:34:28.151 -> [00:00:11.736] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.737] EVT <= 0E 04 01 6D 0C 00 
10:34:28.151 -> [00:00:11.738] CMD => 01 20 08 FF FD FF FF 07 00 00 00 
10:34:28.151 -> [00:00:11.738] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.739] EVT <= 0E 04 01 01 20 00 
10:34:28.151 -> [00:00:11.739] CMD => 0F 20 00 
10:34:28.151 -> [00:00:11.740] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.741] EVT <= 0E 05 01 0F 20 00 80 
10:34:28.151 -> [00:00:11.741] LOG -- hci.c.2753: hci_le_read_white_list_size: size 128
10:34:28.151 -> [00:00:11.741] CMD => 24 0C 03 0C 02 7A 
10:34:28.151 -> [00:00:11.742] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.743] EVT <= 0E 04 01 24 0C 00 
10:34:28.151 -> [00:00:11.743] CMD => 13 0C F8 42 54 73 74 61 63 6B 20 32 38 3A 43 44 3A 43 31 3A 30 36 3A 42 46 3A 34 37 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
10:34:28.151 -> [00:00:11.747] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.748] EVT <= 0E 04 01 13 0C 00 
10:34:28.151 -> [00:00:11.749] CMD => 52 0C F1 00 1A 09 42 54 73 74 61 63 6B 20 32 38 3A 43 44 3A 43 31 3A 30 36 3A 42 46 3A 34 37 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
10:34:28.151 -> [00:00:11.753] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.754] EVT <= 0E 04 01 52 0C 00 
10:34:28.151 -> [00:00:11.754] CMD => 0F 08 02 00 00 
10:34:28.151 -> [00:00:11.755] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.756] EVT <= 0E 04 01 0F 08 00 
10:34:28.151 -> [00:00:11.756] CMD => 18 0C 02 00 60 
10:34:28.151 -> [00:00:11.757] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.758] EVT <= 0E 04 01 18 0C 00 
10:34:28.151 -> [00:00:11.758] CMD => 1A 0C 01 00 
10:34:28.151 -> [00:00:11.759] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.760] EVT <= 0E 04 01 1A 0C 00 
10:34:28.151 -> [00:00:11.760] EVT <= 66 02 00 00 
10:34:28.151 -> [00:00:11.760] CMD => 0B 20 07 01 E0 01 30 00 00 00 
10:34:28.151 -> [00:00:11.761] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.762] EVT <= 0E 04 01 0B 20 00 
10:34:28.151 -> [00:00:11.762] LOG -- hci.c.1805: hci_init_done -> HCI_STATE_WORKING
10:34:28.151 -> [00:00:11.762] LOG -- hci.c.7684: BTSTACK_EVENT_STATE 2
10:34:28.151 -> [00:00:11.762] EVT <= 60 01 02 
10:34:28.151 -> BTstack up and running at 28:CD:C1:06:BF:47
10:34:28.151 -> [00:00:11.763] LOG -- sm.c.3726: HCI Working!
10:34:28.151 -> [00:00:11.763] CMD => 18 20 00 
10:34:28.151 -> [00:00:11.764] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.764] LOG -- hci.c.8531: hci_le_set_own_address_type: old 0, new 0
10:34:28.151 -> [00:00:11.765] EVT <= 0E 0C 01 18 20 00 0F 3B 6B 7A 51 BA E4 EA 
10:34:28.151 -> [00:00:11.765] CMD => 18 20 00 
10:34:28.151 -> [00:00:11.766] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.766] EVT <= 0E 0C 01 18 20 00 38 45 8C 1F B3 49 62 88 
10:34:28.151 -> [00:00:11.767] LOG -- btstack_tlv_flash_bank.c.420: write '534d4552', len 16 at 8
10:34:28.151 -> [00:00:11.768] LOG -- sm.c.3669: Generated ER key. Store in TLV status: 0
10:34:28.151 -> [00:00:11.769] LOG -- btstack_util.c.314: ER     0F3B6B7A51BAE4EA38458C1FB3496288
10:34:28.151 -> [00:00:11.769] CMD => 18 20 00 
10:34:28.151 -> [00:00:11.770] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.771] EVT <= 0E 0C 01 18 20 00 DF DA 2E 84 7E C3 B5 7F 
10:34:28.151 -> [00:00:11.771] CMD => 18 20 00 
10:34:28.151 -> [00:00:11.772] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.773] EVT <= 0E 0C 01 18 20 00 E3 36 32 7E D8 9B C1 7C 
10:34:28.151 -> [00:00:11.773] LOG -- btstack_tlv_flash_bank.c.420: write '534d4952', len 16 at 20
10:34:28.151 -> [00:00:11.775] LOG -- sm.c.3650: Generated IR key. Store in TLV status: 0
10:34:28.151 -> [00:00:11.775] LOG -- btstack_util.c.314: IR     DFDA2E847EC3B57FE336327ED89BC17C
10:34:28.151 -> [00:00:11.775] CMD => 06 20 0F 30 00 30 00 00 00 00 00 00 00 00 00 00 07 00 
10:34:28.151 -> [00:00:11.776] EVT <= 6E 00 
10:34:28.151 -> [00:00:11.778] EVT <= 0E 04 01 06 20 00 
10:34:28.151 -> [00:00:11.778] LOG -- sm.c.2140: DKG_CALC_IRK started
10:34:28.151 -> [00:00:11.779] LOG -- btstack_util.c.314: irk    73603B299BD12E33BAECA3DDD89BAA0A
10:34:28.198 -> [00:00:11.779] CMD => 08 20 20 16 02 01 02 12 09 42 54 73 74 61 63 6B 20 4C 45 20 53 68 69 65 6C 64 00 00 00 00 00 00 00 00 00 
10:34:28.198 -> [00:00:11.780] EVT <= 6E 00 
10:34:28.198 -> [00:00:11.782] EVT <= 0E 04 01 08 20 00 
10:34:28.198 -> [00:00:11.782] LOG -- sm.c.2151: DKG_CALC_DHK started
10:34:28.198 -> [00:00:11.783] LOG -- btstack_util.c.314: dhk    93809CF1DFA6058D962DBBC27F9C252E
10:34:28.198 -> [00:00:11.783] CMD => 0C 20 02 01 00 
10:34:28.198 -> [00:00:11.784] EVT <= 6E 00 
10:34:28.198 -> [00:00:11.785] EVT <= 0E 04 01 0C 20 00 
10:34:28.198 -> [00:00:11.815] EVT <= 3E 21 02 01 00 00 5D 19 A3 76 9D A1 15 02 01 06 11 06 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 D5 
10:34:28.198 -> [00:00:11.816] EVT <= DA 1F 00 00 5D 19 A3 76 9D A1 D5 15 02 01 06 11 06 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 
10:34:28.198 -> Device discovered: A1:9D:76:A3:19:5D, RSSI: -43
10:34:28.198 -> 
10:34:28.198 -> BLE ShieldService V2 found!
10:34:28.198 -> 
10:34:28.198 -> [00:00:11.817] CMD => 0C 20 02 00 00 
10:34:28.198 -> [00:00:11.817] EVT <= 6E 00 
10:34:28.198 -> [00:00:11.818] LOG -- hci.c.8094: gap_connect: no connection exists yet, creating context
10:34:28.198 -> [00:00:11.818] LOG -- hci.c.316: create_connection_for_addr A1:9D:76:A3:19:5D, type 0
10:34:28.198 -> [00:00:11.818] LOG -- hci.c.8109: gap_connect: send create connection next
10:34:28.198 -> [00:00:11.819] EVT <= 3E 0C 02 01 04 00 5D 19 A3 76 9D A1 00 D6 
10:34:28.198 -> [00:00:11.820] EVT <= 0E 04 01 0C 20 00 
10:34:28.198 -> [00:00:11.821] LOG -- hci.c.6868: sending hci_le_create_connection
10:34:28.198 -> [00:00:11.821] CMD => 0D 20 19 60 00 30 00 00 00 5D 19 A3 76 9D A1 00 08 00 18 00 04 00 48 00 00 00 00 00 
10:34:28.198 -> [00:00:11.822] EVT <= 6E 00 
10:34:28.198 -> [00:00:11.824] EVT <= 0F 04 00 01 0D 20 
10:34:28.666 -> [00:00:12.245] EVT <= 3E 13 01 00 40 00 00 00 5D 19 A3 76 9D A1 18 00 04 00 48 00 00 
10:34:28.666 -> [00:00:12.246] LOG -- hci.c.3198: LE Connection_complete (status=0) type 0, A1:9D:76:A3:19:5D
10:34:28.666 -> [00:00:12.246] LOG -- hci.c.3277: New connection: handle 64, A1:9D:76:A3:19:5D
10:34:28.666 -> [00:00:12.246] LOG -- hci.c.7753: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
10:34:28.666 -> [00:00:12.246] EVT <= 61 01 01 
10:34:28.666 -> Connection complete, con_handle 0x0040
10:34:28.666 -> Device connected!
10:34:28.666 -> [00:00:12.247] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:28.666 -> [00:00:12.247] EVT <= CD 09 40 00 00 5D 19 A3 76 9D A1 
10:34:28.666 -> [00:00:12.248] LOG -- att_server.c.406: SM_EVENT_IDENTITY_RESOLVING_STARTED
10:34:28.666 -> [00:00:12.248] LOG -- sm.c.2263: LE Device Lookup: not found
10:34:28.666 -> [00:00:12.248] EVT <= CE 09 40 00 00 5D 19 A3 76 9D A1 
10:34:28.666 -> [00:00:12.249] LOG -- att_server.c.424: SM_EVENT_IDENTITY_RESOLVING_FAILED
10:34:28.666 -> [00:00:12.249] ACL => 40 00 07 00 03 00 04 00 02 9B 06 
10:34:28.666 -> [00:00:12.249] EVT <= 6E 00 
10:34:28.666 -> [00:00:12.250] CMD => 16 20 02 40 00 
10:34:28.666 -> [00:00:12.251] EVT <= 6E 00 
10:34:28.666 -> [00:00:12.251] EVT <= 79 02 04 00 
10:34:28.666 -> [00:00:12.252] EVT <= 3E 04 14 40 00 01 
10:34:28.666 -> [00:00:12.253] EVT <= 0F 04 00 01 16 20 
10:34:28.760 -> [00:00:12.371] EVT <= 3E 0C 04 00 40 00 2F 40 01 00 00 00 00 00 
10:34:28.856 -> [00:00:12.459] EVT <= 13 05 01 40 00 01 00 
10:34:28.950 -> [00:00:12.551] ACL <= 40 20 07 00 03 00 04 00 03 F7 00 
10:34:28.950 -> [00:00:12.552] EVT <= AB 04 40 00 F7 00 
10:34:28.950 -> [00:00:12.552] ACL => 40 00 0B 00 07 00 04 00 10 01 00 FF FF 00 28 
10:34:28.950 -> [00:00:12.553] EVT <= 6E 00 
10:34:28.950 -> [00:00:12.553] CMD => 35 0C 05 01 40 00 01 00 
10:34:28.950 -> [00:00:12.554] EVT <= 6E 00 
10:34:28.950 -> [00:00:12.554] EVT <= 79 02 04 00 
10:34:29.092 -> [00:00:12.709] EVT <= 13 05 01 40 00 01 00 
10:34:29.467 -> [00:00:13.091] ACL <= 40 20 12 00 0E 00 04 00 11 06 01 00 05 00 00 18 06 00 09 00 01 18 
10:34:29.467 -> [00:00:13.091] EVT <= A1 16 40 00 01 00 05 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 00 18 00 00 
10:34:29.467 -> Service Discovered: :1800
10:34:29.467 -> [00:00:13.092] EVT <= A1 16 40 00 06 00 09 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 01 18 00 00 
10:34:29.467 -> Service Discovered: :1801
10:34:29.467 -> [00:00:13.093] ACL => 40 00 0B 00 07 00 04 00 10 0A 00 FF FF 00 28 
10:34:29.467 -> [00:00:13.093] EVT <= 6E 00 
10:34:29.467 -> [00:00:13.094] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.467 -> [00:00:13.094] EVT <= 6E 00 
10:34:29.467 -> [00:00:13.095] EVT <= 79 02 04 00 
10:34:29.591 -> [00:00:13.181] ACL <= 40 20 1A 00 16 00 04 00 11 14 0A 00 14 00 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 
10:34:29.591 -> [00:00:13.181] EVT <= A1 16 40 00 0A 00 14 00 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 
10:34:29.591 -> Service Discovered: :B8E06067-62AD-41BA-9231-206AE80AB550
10:34:29.591 -> Our service located!
10:34:29.591 -> [00:00:13.182] ACL => 40 00 0B 00 07 00 04 00 10 15 00 FF FF 00 28 
10:34:29.591 -> [00:00:13.183] EVT <= 6E 00 
10:34:29.591 -> [00:00:13.183] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.591 -> [00:00:13.184] EVT <= 6E 00 
10:34:29.591 -> [00:00:13.184] EVT <= 79 02 04 00 
10:34:29.591 -> [00:00:13.211] EVT <= 13 05 01 40 00 02 00 
10:34:29.685 -> [00:00:13.271] ACL <= 40 20 09 00 05 00 04 00 01 10 15 00 0A 
10:34:29.685 -> [00:00:13.271] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:29.685 -> [00:00:13.271] EVT <= A0 03 40 00 00 
10:34:29.685 -> Service discovery finished
10:34:29.685 -> [00:00:13.272] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:29.685 -> [00:00:13.272] ACL => 40 00 0B 00 07 00 04 00 08 0A 00 14 00 03 28 
10:34:29.685 -> [00:00:13.273] EVT <= 6E 00 
10:34:29.685 -> [00:00:13.273] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.685 -> [00:00:13.274] EVT <= 6E 00 
10:34:29.685 -> [00:00:13.274] EVT <= 79 02 04 00 
10:34:29.778 -> [00:00:13.361] ACL <= 40 20 1B 00 56 00 04 00 09 15 0B 00 12 0C 00 EE FC D5 4F 69 CC CC 8E 67 47 E8 AE 7B 17 97 F8 
10:34:29.778 -> [00:00:13.361] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.778 -> [00:00:13.362] EVT <= 6E 00 
10:34:29.778 -> [00:00:13.363] ACL <= 40 10 1B 00 0E 00 0A 0F 00 4B 1B 5F 06 D6 E5 A0 BB C8 4B 2A DE 0A E4 45 BF 10 00 02 11 00 82 
10:34:29.778 -> [00:00:13.363] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.778 -> [00:00:13.364] EVT <= 6E 00 
10:34:29.778 -> [00:00:13.365] ACL <= 40 10 1B 00 E9 52 06 BE C8 FE B9 14 40 6A 72 31 0F BC 2F 12 00 12 13 00 02 00 12 AC 42 02 99 
10:34:29.778 -> [00:00:13.366] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.778 -> [00:00:13.366] EVT <= 6E 00 
10:34:29.778 -> [00:00:13.367] ACL <= 40 10 09 00 8C EE 11 85 5D 28 2F 13 1D 
10:34:29.778 -> [00:00:13.367] EVT <= A2 1A 40 00 0B 00 0C 00 0D 00 12 00 EE FC D5 4F 69 CC CC 8E 67 47 E8 AE 7B 17 97 F8 
10:34:29.778 -> Characteristic Discovered: F897177B-AEE8-4767-8ECC-CC694FD5FCEE, handle 0xC
10:34:29.778 -> Characteristic found: RX
10:34:29.778 -> [00:00:13.368] EVT <= A2 1A 40 00 0E 00 0F 00 0F 00 0A 00 4B 1B 5F 06 D6 E5 A0 BB C8 4B 2A DE 0A E4 45 BF 
10:34:29.778 -> Characteristic Discovered: BF45E40A-DE2A-4BC8-BBA0-E5D6065F1B4B, handle 0xF
10:34:29.778 -> Characteristic found: TX
10:34:29.778 -> [00:00:13.369] EVT <= A2 1A 40 00 10 00 11 00 11 00 02 00 82 E9 52 06 BE C8 FE B9 14 40 6A 72 31 0F BC 2F 
10:34:29.778 -> Characteristic Discovered: 2FBC0F31-726A-4014-B9FE-C8BE0652E982, handle 0x11
10:34:29.778 -> Characteristic found: Baudrate
10:34:29.778 -> [00:00:13.370] ACL => 40 00 0B 00 07 00 04 00 08 14 00 14 00 03 28 
10:34:29.778 -> [00:00:13.370] EVT <= 6E 00 
10:34:29.778 -> [00:00:13.371] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.778 -> [00:00:13.371] EVT <= 6E 00 
10:34:29.778 -> [00:00:13.372] EVT <= 79 02 04 00 
10:34:29.778 -> [00:00:13.391] EVT <= 13 05 01 40 00 02 00 
10:34:29.826 -> [00:00:13.451] ACL <= 40 20 09 00 05 00 04 00 01 08 14 00 0A 
10:34:29.826 -> [00:00:13.451] EVT <= A2 1A 40 00 12 00 13 00 14 00 12 00 02 00 12 AC 42 02 99 8C EE 11 85 5D 28 2F 13 1D 
10:34:29.826 -> Characteristic Discovered: 1D132F28-5D85-11EE-8C99-0242AC120002, handle 0x13
10:34:29.826 -> Characteristic found: Intent
10:34:29.826 -> [00:00:13.452] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:29.826 -> [00:00:13.452] EVT <= A0 03 40 00 00 
10:34:29.826 -> Characteristic discovery finished, status 1
10:34:29.826 -> Subscribing to charRX
10:34:29.826 -> [00:00:13.453] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:29.826 -> [00:00:13.453] ACL => 40 00 0B 00 07 00 04 00 08 0C 00 0D 00 02 29 
10:34:29.826 -> [00:00:13.454] EVT <= 6E 00 
10:34:29.826 -> [00:00:13.454] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.872 -> [00:00:13.455] EVT <= 6E 00 
10:34:29.872 -> [00:00:13.455] EVT <= 79 02 04 00 
10:34:29.919 -> [00:00:13.541] ACL <= 40 20 09 00 05 00 04 00 01 08 0C 00 0A 
10:34:29.919 -> [00:00:13.542] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:29.919 -> [00:00:13.542] EVT <= A0 03 40 00 0A 
10:34:29.919 -> 
10:34:29.919 -> Subscribe Callback: 4
10:34:29.919 -> BLE_STATUS_OTHER_ERROR
10:34:29.919 -> [00:00:13.542] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:29.919 -> [00:00:13.543] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:29.919 -> [00:00:13.543] EVT <= 6E 00 
10:34:29.919 -> [00:00:13.544] CMD => 35 0C 05 01 40 00 01 00 
10:34:29.919 -> [00:00:13.544] EVT <= 6E 00 
10:34:29.919 -> [00:00:13.545] EVT <= 79 02 04 00 
10:34:29.966 -> [00:00:13.571] EVT <= 13 05 01 40 00 02 00 
10:34:30.011 -> [00:00:13.631] ACL <= 40 20 06 00 02 00 04 00 0B 62 
10:34:30.011 -> [00:00:13.631] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:30.011 -> [00:00:13.631] EVT <= A5 07 40 00 0C 00 01 00 62 
10:34:30.011 -> Read callback
10:34:30.011 -> Read Value:98 
10:34:30.011 -> [00:00:13.632] EVT <= A0 03 40 00 00 
10:34:30.011 -> 
10:34:30.011 -> Subscribe Callback: 0
10:34:30.011 -> BLE_STATUS_OK
10:34:30.011 -> [00:00:13.632] CMD => 35 0C 05 01 40 00 01 00 
10:34:30.011 -> [00:00:13.633] EVT <= 6E 00 
10:34:32.962 -> Reading...
10:34:32.962 -> [00:00:16.583] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:32.962 -> [00:00:16.584] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:32.962 -> [00:00:16.584] EVT <= 6E 00 
10:34:32.962 -> [00:00:16.585] EVT <= 79 02 04 00 
10:34:33.103 -> [00:00:16.721] ACL <= 40 20 06 00 02 00 04 00 0B 62 
10:34:33.103 -> [00:00:16.722] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:33.103 -> [00:00:16.722] EVT <= A5 07 40 00 0C 00 01 00 62 
10:34:33.103 -> Read callback
10:34:33.103 -> Read Value:98 
10:34:33.103 -> [00:00:16.722] EVT <= A0 03 40 00 00 
10:34:33.103 -> 
10:34:33.103 -> Subscribe Callback: 0
10:34:33.103 -> BLE_STATUS_OK
10:34:33.103 -> [00:00:16.722] CMD => 35 0C 05 01 40 00 01 00 
10:34:33.103 -> [00:00:16.723] EVT <= 6E 00 
10:34:33.244 -> [00:00:16.834] EVT <= 13 05 01 40 00 01 00 
10:34:37.961 -> Reading...
10:34:37.961 -> [00:00:21.584] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:37.961 -> [00:00:21.585] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:37.961 -> [00:00:21.585] EVT <= 6E 00 
10:34:37.961 -> [00:00:21.586] EVT <= 79 02 04 00 
10:34:38.147 -> [00:00:21.761] ACL <= 40 20 06 00 02 00 04 00 0B 50 
10:34:38.147 -> [00:00:21.761] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:38.147 -> [00:00:21.761] EVT <= A5 07 40 00 0C 00 01 00 50 
10:34:38.147 -> Read callback
10:34:38.147 -> Read Value:80 
10:34:38.147 -> [00:00:21.762] EVT <= A0 03 40 00 00 
10:34:38.147 -> 
10:34:38.147 -> Subscribe Callback: 0
10:34:38.147 -> BLE_STATUS_OK
10:34:38.147 -> [00:00:21.762] CMD => 35 0C 05 01 40 00 01 00 
10:34:38.147 -> [00:00:21.763] EVT <= 6E 00 
10:34:38.241 -> [00:00:21.834] EVT <= 13 05 01 40 00 01 00 
10:34:42.966 -> Reading...
10:34:42.966 -> [00:00:26.585] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:42.966 -> [00:00:26.586] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:42.966 -> [00:00:26.586] EVT <= 6E 00 
10:34:42.966 -> [00:00:26.587] EVT <= 79 02 04 00 
10:34:43.060 -> [00:00:26.651] ACL <= 40 20 06 00 02 00 04 00 0B 51 
10:34:43.060 -> [00:00:26.651] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:43.060 -> [00:00:26.651] EVT <= A5 07 40 00 0C 00 01 00 51 
10:34:43.060 -> Read callback
10:34:43.060 -> Read Value:81 
10:34:43.060 -> [00:00:26.652] EVT <= A0 03 40 00 00 
10:34:43.060 -> 
10:34:43.060 -> Subscribe Callback: 0
10:34:43.060 -> BLE_STATUS_OK
10:34:43.060 -> [00:00:26.652] CMD => 35 0C 05 01 40 00 01 00 
10:34:43.060 -> [00:00:26.653] EVT <= 6E 00 
10:34:43.247 -> [00:00:26.834] EVT <= 13 05 01 40 00 01 00 
10:34:47.972 -> Reading...
10:34:47.972 -> [00:00:31.586] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:47.972 -> [00:00:31.587] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:47.972 -> [00:00:31.587] EVT <= 6E 00 
10:34:47.972 -> [00:00:31.588] EVT <= 79 02 04 00 
10:34:48.066 -> [00:00:31.690] ACL <= 40 20 06 00 02 00 04 00 0B 52 
10:34:48.066 -> [00:00:31.691] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:48.066 -> [00:00:31.691] EVT <= A5 07 40 00 0C 00 01 00 52 
10:34:48.066 -> Read callback
10:34:48.066 -> Read Value:82 
10:34:48.066 -> [00:00:31.691] EVT <= A0 03 40 00 00 
10:34:48.066 -> 
10:34:48.066 -> Subscribe Callback: 0
10:34:48.066 -> BLE_STATUS_OK
10:34:48.066 -> [00:00:31.692] CMD => 35 0C 05 01 40 00 01 00 
10:34:48.066 -> [00:00:31.692] EVT <= 6E 00 
10:34:48.209 -> [00:00:31.834] EVT <= 13 05 01 40 00 01 00 
10:34:52.995 -> Reading...
10:34:52.995 -> [00:00:36.587] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:52.995 -> [00:00:36.588] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:52.995 -> [00:00:36.588] EVT <= 6E 00 
10:34:52.995 -> [00:00:36.589] EVT <= 79 02 04 00 
10:34:53.136 -> [00:00:36.731] ACL <= 40 20 06 00 02 00 04 00 0B 53 
10:34:53.136 -> [00:00:36.731] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:53.136 -> [00:00:36.731] EVT <= A5 07 40 00 0C 00 01 00 53 
10:34:53.136 -> Read callback
10:34:53.136 -> Read Value:83 
10:34:53.136 -> [00:00:36.732] EVT <= A0 03 40 00 00 
10:34:53.136 -> 
10:34:53.136 -> Subscribe Callback: 0
10:34:53.136 -> BLE_STATUS_OK
10:34:53.136 -> [00:00:36.732] CMD => 35 0C 05 01 40 00 01 00 
10:34:53.136 -> [00:00:36.733] EVT <= 6E 00 
10:34:53.230 -> [00:00:36.834] EVT <= 13 05 01 40 00 01 00 
10:34:57.956 -> Reading...
10:34:57.956 -> [00:00:41.588] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:34:57.956 -> [00:00:41.589] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:34:57.956 -> [00:00:41.589] EVT <= 6E 00 
10:34:57.956 -> [00:00:41.590] EVT <= 79 02 04 00 
10:34:58.142 -> [00:00:41.770] ACL <= 40 20 06 00 02 00 04 00 0B 54 
10:34:58.142 -> [00:00:41.771] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:34:58.142 -> [00:00:41.771] EVT <= A5 07 40 00 0C 00 01 00 54 
10:34:58.142 -> Read callback
10:34:58.142 -> Read Value:84 
10:34:58.142 -> [00:00:41.771] EVT <= A0 03 40 00 00 
10:34:58.142 -> 
10:34:58.142 -> Subscribe Callback: 0
10:34:58.142 -> BLE_STATUS_OK
10:34:58.142 -> [00:00:41.772] CMD => 35 0C 05 01 40 00 01 00 
10:34:58.142 -> [00:00:41.772] EVT <= 6E 00 
10:34:58.330 -> [00:00:41.959] EVT <= 13 05 01 40 00 01 00 
10:35:02.968 -> Reading...
10:35:02.968 -> [00:00:46.589] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:35:02.968 -> [00:00:46.590] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:35:02.968 -> [00:00:46.590] EVT <= 6E 00 
10:35:02.968 -> [00:00:46.591] EVT <= 79 02 04 00 
10:35:03.061 -> [00:00:46.660] ACL <= 40 20 06 00 02 00 04 00 0B 55 
10:35:03.061 -> [00:00:46.661] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:35:03.061 -> [00:00:46.661] EVT <= A5 07 40 00 0C 00 01 00 55 
10:35:03.061 -> Read callback
10:35:03.061 -> Read Value:85 
10:35:03.061 -> [00:00:46.661] EVT <= A0 03 40 00 00 
10:35:03.061 -> 
10:35:03.061 -> Subscribe Callback: 0
10:35:03.061 -> BLE_STATUS_OK
10:35:03.061 -> [00:00:46.662] CMD => 35 0C 05 01 40 00 01 00 
10:35:03.061 -> [00:00:46.662] EVT <= 6E 00 
10:35:03.200 -> [00:00:46.833] EVT <= 13 05 01 40 00 01 00 
10:35:07.970 -> Reading...
10:35:07.970 -> [00:00:51.590] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:35:07.970 -> [00:00:51.591] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:35:07.970 -> [00:00:51.591] EVT <= 6E 00 
10:35:07.970 -> [00:00:51.592] EVT <= 79 02 04 00 
10:35:08.064 -> [00:00:51.700] ACL <= 40 20 06 00 02 00 04 00 0B 56 
10:35:08.064 -> [00:00:51.700] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:35:08.064 -> [00:00:51.701] EVT <= A5 07 40 00 0C 00 01 00 56 
10:35:08.064 -> Read callback
10:35:08.064 -> Read Value:86 
10:35:08.064 -> [00:00:51.701] EVT <= A0 03 40 00 00 
10:35:08.064 -> 
10:35:08.064 -> Subscribe Callback: 0
10:35:08.064 -> BLE_STATUS_OK
10:35:08.064 -> [00:00:51.701] CMD => 35 0C 05 01 40 00 01 00 
10:35:08.111 -> [00:00:51.702] EVT <= 6E 00 
10:35:08.204 -> [00:00:51.833] EVT <= 13 05 01 40 00 01 00 
10:35:12.982 -> Reading...
10:35:12.982 -> [00:00:56.591] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40
10:35:12.982 -> [00:00:56.592] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 
10:35:12.982 -> [00:00:56.592] EVT <= 6E 00 
10:35:12.982 -> [00:00:56.593] EVT <= 79 02 04 00 
10:35:13.123 -> [00:00:56.740] ACL <= 40 20 06 00 02 00 04 00 0B 57 
10:35:13.123 -> [00:00:56.740] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40
10:35:13.123 -> [00:00:56.741] EVT <= A5 07 40 00 0C 00 01 00 57 
10:35:13.123 -> Read callback
10:35:13.123 -> Read Value:87 
10:35:13.123 -> [00:00:56.741] EVT <= A0 03 40 00 00 
10:35:13.123 -> 
10:35:13.123 -> Subscribe Callback: 0
10:35:13.123 -> BLE_STATUS_OK
10:35:13.123 -> [00:00:56.741] CMD => 35 0C 05 01 40 00 01 00 
10:35:13.123 -> [00:00:56.742] EVT <= 6E 00 
10:35:13.217 -> [00:00:56.833] EVT <= 13 05 01 40 00 01 00

Thanks for the log. If possible, please remove the time stamps from your serial terminal, the conversion tool does not expect them as the HCI log already has time stamps.

After removing the PC timestamps, you can run the log through btstack/tool/create_packet_log.py to get a .pklg that can be analyzed in Wireshark.

Here it is (zipped as GitHub doesnn't accept .pklg files): arduino.pklg.zip

The Arduino wrapper and your code seem to be ok. The stack first looks and finds the RX characteristic with ATT handles 0x000b - 0x000d:

Characteristic Handle: 0x000B
    Properties: Read, Notify
    Value Handle: 0x000C
    UUID: F897177B-AEE8-4767-8ECC-CC694FD5FCEE

Characteristic Handle: 0x000E
    ...

So we have:

0x000b - characteristic declaration
0x000c - characteristic value
0x000d - client characteristic configuration descriptor (CCCD)

Next, the stack first tries to read the current value of the CCCD but gets an error!

Jan 01 11:00:13.453 ATT Send Read By Type Request - Start Handle: 0x000C - End Handle: 0x000D - UUID: Client Characteristic Configuration SEND
Read By Type Request - Start Handle: 0x000C - End Handle: 0x000D - UUID: Client Characteristic Configuration Opcode: 0x0008 Starting Handle: 0x000C Ending Handle: 0x000D Attribute Type: 2902 (Client Characteristic Configuration) Jan 01 11:00:13.453 L2CAP Send Channel ID: 0x0004 Length: 0x0007 (07) [ 08 0C 00 0D 00 02 29 ] SEND
Jan 01 11:00:13.541 ATT Receive Error Response - Attribute Handle: 0x000C - Error Code: Attribute Not Found (0x0A) RECV

If the remote side does have a CCCD at handle 0x000D, the ATT_READ_BY_TYPE_REQ should return it. However, it doesn't.

Although you've tested with your Android phone, this looks like a bug in the Bluetooth Stack on the NanoBLE. Which one is this?

It looks like BTstack uses different, but valid ATT requests to enable notifications, which are handled incorrectly by the Peripheral.

Could you try with a different Peripheral / different Bluetooth Stack to see if your Central on top of BTstack on Pico works correctly then?

Could you ask the developer of the stack on the NanoBLE about this behaviour and provide your log?

Looks like the NanoBLE33 is running this code here - didn't know that Arduino implemented an LE Host Stack: https://github.com/arduino-libraries/ArduinoBLE/blob/dff9e414abc20df491b46d0b38b360eb1a3507fb/src/utility/ATT.cpp#L1105

Maybe the end condition in the loop is off by one or something like that.

Could you print:

GATT.attributeCount()
readByTypeReq->startHandle
(readByTypeReq->endHandle before entering the for loop (line 1124) and in the loop (line 1128)
i
handle
attribute->type() to see if it exits too early?

I don't have another peripheral I can test at the moment.

Here is the output with that modification from the nano:

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 9 Handle: 10 Type: 10240

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 10 Handle: 11 Type: 10243

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 12 Handle: 13 Type: 10496

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 13 Handle: 14 Type: 10243

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 15 Handle: 16 Type: 10243

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 17 Handle: 18 Type: 10243

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 19 Handle: 20 Type: 10496

AttrCount: 20 StarHandle: 20 EndHandle: 20 i: 19 Handle: 20 Type: 10496

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 11 Handle: 12 Type: 10243

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 12 Handle: 13 Type: 10496

I think I found it. The attribute->type() only returns BLETypeService (2800), BLETypeCharacteristic (2803) or BLETypeDescriptor (2900), but never 2902. With this

if (attribute->type() == readByTypeReq->uuid)

is never true for our query - although there's code to explicitly handle 2902 but it's not possible to reach it.

Could you try this hack/patch:

diff --git a/src/local/BLELocalDescriptor.cpp b/src/local/BLELocalDescriptor.cpp index c466897..0c81fe7 100644 --- a/src/local/BLELocalDescriptor.cpp +++ b/src/local/BLELocalDescriptor.cpp @@ -40,6 +40,9 @@ BLELocalDescriptor::~BLELocalDescriptor()

enum BLEAttributeType BLELocalDescriptor::type() const {

if (strcmp("2902", uuid.str()) == 0){
return (enum BLEAttributeType) 0x2902;
} return BLETypeDescriptor; }

This let's the CCCD return 0x2902 as type() and should enable the code to handle ATT Read By Type for UUID 2902.

I updated the code, slightly modified so it would compile as follows:

enum BLEAttributeType BLELocalDescriptor::type() const
{
  if (strcmp("2902", uuid()) == 0){
    return (enum BLEAttributeType) 0x2902;
  }
  return BLETypeDescriptor;
}

No change in behavior.

GitHub munged his diff, but I think he meant to write:

enum BLEAttributeType BLELocalDescriptor::type() const
{
   return BLETypeDescriptor;
}

I.e. just return what it has, no strcmp() or any other comparison needed.

That is how the original code looked, just returned the type with no check.

Oh, the diff didn't survive. The idea was to have the BLELocalDescriptor return 0x2902 if the UUID is 2902, such that this comparison in the ATT.cpp code becomes true:

if (attribute->type() == readByTypeReq->uuid)

(as the readByTypeReq->uuid is 2902 and the BLELocalDescriptor should have UUID "2902" as well).

Again, a correct way (give the 'cross-layer optimization': ATT.cpp is implementing the logic for GATT) would be to do a switch on attribute->type() and for BLETypeDescriptor, compare the attribute->uuid() to the request UUID.

GitHub munged his diff, but I think he meant to write:
enum BLEAttributeType BLELocalDescriptor::type() const
{
   return BLETypeDescriptor;
}
I.e. just return what it has, no strcmp() or any other comparison needed.

Could you also log attribute->type() and paste the output?

Where do you want me to add that output? It is already in the first output with the updatedATT.cpp file and that hasn't changed from the previous output.

Btw, it would be convenient to print the attribute->type() as hex. Could you also print attribute->uuid()?

Anyway, when the hack/patch works, it should list type 0x2902 = 10498. If that's not the case, then it's not working. Please try to get it to work.

When it attribute->type() returns 0x2902, the ATT Read By Type Request should be answered correctly (at least that's what I read in the code)

Changed the print statement in the ATT.cpp readByTypeReq for loop and get the output below. I do see the expected 2902 value showing up but still no change in behavior. Not sure if there's something farther down the line in the code still having issues.

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 9 Handle: 10 UUID: B8E06067-62AD-41BA-9231-206AE80AB550 readByTypeReqUUID: 2803 Type: 2800

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 10 Handle: 11 UUID: F897177B-AEE8-4767-8ECC-CC694FD5FCEE readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 12 Handle: 13 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 13 Handle: 14 UUID: bf45e40a-de2a-4bc8-bba0-e5d6065f1b4b readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 15 Handle: 16 UUID: 2fbc0f31-726a-4014-b9fe-c8be0652e982 readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 17 Handle: 18 UUID: 1d132f28-5d85-11ee-8c99-0242ac120002 readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 19 Handle: 20 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 20 EndHandle: 20 i: 19 Handle: 20 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 11 Handle: 12 UUID: F897177B-AEE8-4767-8ECC-CC694FD5FCEE readByTypeReqUUID: 2902 Type: 2803

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 12 Handle: 13 UUID: 2902 readByTypeReqUUID: 2902 Type: 2902

Generated from this updated code in the ATT.cpp readByTypeReq function.

    Serial.print("\nAttrCount: ");
    Serial.println(GATT.attributeCount());
    Serial.print("StarHandle: ");
    Serial.println(readByTypeReq->startHandle);
    Serial.print("EndHandle: ");
    Serial.println(readByTypeReq->endHandle);
    Serial.print("i: ");
    Serial.println(i);
    Serial.print("Handle: ");
    Serial.println(handle);
    Serial.print("UUID: ");
    Serial.println(attribute->uuid());
    Serial.print("readByTypeReqUUID: ");
    Serial.println(readByTypeReq->uuid, HEX);
    Serial.print("Type: ");
    Serial.println(attribute->type(),HEX);

I'm not sure if it would help here, but the latest git master now supports the built-in BTstack logging through the IDE Debug menus.

Ok, so the attribute->type is now fixed to 2902, but it's not working. Could you a) provide a new HCI trace from the Pico? b) add more debug output to see if the code after if (attribute->type() == 0x2902) { is actually executed and what value is returned. For BTstack, I don't think the actual value is relevant, but the it will use the attribute handle to do a write request and enable notifications.

@earlephilhower Are you referring to the lines:

 BTstack.enablePacketLogger();
 BTstack.enableDebugLogger();

Or is there some other logging I am able to turn on to help troubleshoot?

@mringwal

Code modified to print after if statement:

} else if (attribute->type() == 0x2902) {
        Serial.println("\nAttribute 0x2902 found");
        BLELocalDescriptor* descriptor = (BLELocalDescriptor*)attribute;

        // add the handle
        memcpy(&response[responseLength], &handle, sizeof(handle));
        responseLength += sizeof(handle);

        // add the value
        int valueSize = min((uint16_t)(mtu - responseLength), (uint16_t)descriptor->valueSize());
        memcpy(&response[responseLength], descriptor->value(), valueSize);
        responseLength += valueSize;

        response[1] = 2 + valueSize;

        Serial.print("Response: ");
        Serial.println(response[1]);

        break; // all done
      }

Results in this output:

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 9 Handle: 10 UUID: B8E06067-62AD-41BA-9231-206AE80AB550 readByTypeReqUUID: 2803 Type: 2800

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 10 Handle: 11 UUID: F897177B-AEE8-4767-8ECC-CC694FD5FCEE readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 12 Handle: 13 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 13 Handle: 14 UUID: bf45e40a-de2a-4bc8-bba0-e5d6065f1b4b readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 15 Handle: 16 UUID: 2fbc0f31-726a-4014-b9fe-c8be0652e982 readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 17 Handle: 18 UUID: 1d132f28-5d85-11ee-8c99-0242ac120002 readByTypeReqUUID: 2803 Type: 2803

AttrCount: 20 StarHandle: 10 EndHandle: 20 i: 19 Handle: 20 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 20 EndHandle: 20 i: 19 Handle: 20 UUID: 2902 readByTypeReqUUID: 2803 Type: 2902

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 11 Handle: 12 UUID: F897177B-AEE8-4767-8ECC-CC694FD5FCEE readByTypeReqUUID: 2902 Type: 2803

AttrCount: 20 StarHandle: 12 EndHandle: 13 i: 12 Handle: 13 UUID: 2902 readByTypeReqUUID: 2902 Type: 2902

Attribute 0x2902 found Response: 4

Pi PIco Output:

Device discovered: A1:9D:76:A3:19:5D, RSSI: -56

BLE ShieldService V2 found!

[01:03:57.340] CMD => 0C 20 02 00 00 [01:03:57.341] EVT <= 6E 00 [01:03:57.341] LOG -- hci.c.8094: gap_connect: no connection exists yet, creating context [01:03:57.341] LOG -- hci.c.316: create_connection_for_addr A1:9D:76:A3:19:5D, type 0 [01:03:57.342] LOG -- hci.c.8109: gap_connect: send create connection next [01:03:57.342] EVT <= 3E 0C 02 01 04 00 5D 19 A3 76 9D A1 00 C7 [01:03:57.343] EVT <= 0E 04 01 0C 20 00 [01:03:57.344] LOG -- hci.c.6868: sending hci_le_create_connection [01:03:57.344] CMD => 0D 20 19 60 00 30 00 00 00 5D 19 A3 76 9D A1 00 08 00 18 00 04 00 48 00 00 00 00 00 [01:03:57.345] EVT <= 6E 00 [01:03:57.348] EVT <= 0F 04 00 01 0D 20 [01:03:57.448] EVT <= 3E 13 01 00 40 00 00 00 5D 19 A3 76 9D A1 18 00 04 00 48 00 00 [01:03:57.448] LOG -- hci.c.3198: LE Connection_complete (status=0) type 0, A1:9D:76:A3:19:5D [01:03:57.449] LOG -- hci.c.3277: New connection: handle 64, A1:9D:76:A3:19:5D [01:03:57.449] LOG -- hci.c.7753: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1 [01:03:57.449] EVT <= 61 01 01 Connection complete, con_handle 0x0040 Device connected! [01:03:57.450] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:03:57.450] EVT <= CD 09 40 00 00 5D 19 A3 76 9D A1 [01:03:57.450] LOG -- att_server.c.406: SM_EVENT_IDENTITY_RESOLVING_STARTED [01:03:57.451] LOG -- sm.c.2263: LE Device Lookup: not found [01:03:57.451] EVT <= CE 09 40 00 00 5D 19 A3 76 9D A1 [01:03:57.451] LOG -- att_server.c.424: SM_EVENT_IDENTITY_RESOLVING_FAILED [01:03:57.452] ACL => 40 00 07 00 03 00 04 00 02 9B 06 [01:03:57.452] EVT <= 6E 00 [01:03:57.453] CMD => 16 20 02 40 00 [01:03:57.453] EVT <= 6E 00 [01:03:57.454] EVT <= 79 02 04 00 [01:03:57.455] EVT <= 3E 04 14 40 00 01 [01:03:57.456] EVT <= 0F 04 00 01 16 20 [01:03:57.590] EVT <= 3E 0C 04 00 40 00 2F 40 01 00 00 00 00 00 [01:03:57.681] ACL <= 40 20 07 00 03 00 04 00 03 F7 00 [01:03:57.681] EVT <= AB 04 40 00 F7 00 [01:03:57.682] ACL => 40 00 0B 00 07 00 04 00 10 01 00 FF FF 00 28 [01:03:57.682] EVT <= 6E 00 [01:03:57.683] CMD => 35 0C 05 01 40 00 01 00 [01:03:57.683] EVT <= 6E 00 [01:03:57.684] EVT <= 79 02 04 00 [01:03:57.742] EVT <= 13 05 01 40 00 01 00 [01:03:57.992] EVT <= 13 05 01 40 00 01 00 [01:03:58.190] ACL <= 40 20 12 00 0E 00 04 00 11 06 01 00 05 00 00 18 06 00 09 00 01 18 [01:03:58.191] EVT <= A1 16 40 00 01 00 05 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 00 18 00 00 Service Discovered: :1800 [01:03:58.191] EVT <= A1 16 40 00 06 00 09 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 01 18 00 00 Service Discovered: :1801 [01:03:58.192] ACL => 40 00 0B 00 07 00 04 00 10 0A 00 FF FF 00 28 [01:03:58.193] EVT <= 6E 00 [01:03:58.193] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.194] EVT <= 6E 00 [01:03:58.194] EVT <= 79 02 04 00 [01:03:58.280] ACL <= 40 20 1A 00 16 00 04 00 11 14 0A 00 14 00 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 [01:03:58.281] EVT <= A1 16 40 00 0A 00 14 00 50 B5 0A E8 6A 20 31 92 BA 41 AD 62 67 60 E0 B8 Service Discovered: :B8E06067-62AD-41BA-9231-206AE80AB550 Our service located! [01:03:58.281] ACL => 40 00 0B 00 07 00 04 00 10 15 00 FF FF 00 28 [01:03:58.282] EVT <= 6E 00 [01:03:58.283] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.283] EVT <= 6E 00 [01:03:58.284] EVT <= 79 02 04 00 [01:03:58.310] EVT <= 13 05 01 40 00 02 00 [01:03:58.370] ACL <= 40 20 09 00 05 00 04 00 01 10 15 00 0A [01:03:58.371] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:03:58.371] EVT <= A0 03 40 00 00 Service discovery finished [01:03:58.371] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:03:58.372] ACL => 40 00 0B 00 07 00 04 00 08 0A 00 14 00 03 28 [01:03:58.372] EVT <= 6E 00 [01:03:58.373] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.373] EVT <= 6E 00 [01:03:58.374] EVT <= 79 02 04 00 Reading... [01:03:58.419] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:03:58.520] ACL <= 40 20 1B 00 56 00 04 00 09 15 0B 00 12 0C 00 EE FC D5 4F 69 CC CC 8E 67 47 E8 AE 7B 17 97 F8 [01:03:58.521] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.521] EVT <= 6E 00 [01:03:58.550] ACL <= 40 10 1B 00 0E 00 0A 0F 00 4B 1B 5F 06 D6 E5 A0 BB C8 4B 2A DE 0A E4 45 BF 10 00 02 11 00 82 [01:03:58.551] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.551] EVT <= 6E 00 [01:03:58.552] ACL <= 40 10 1B 00 E9 52 06 BE C8 FE B9 14 40 6A 72 31 0F BC 2F 12 00 12 13 00 02 00 12 AC 42 02 99 [01:03:58.553] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.553] EVT <= 6E 00 [01:03:58.554] ACL <= 40 10 09 00 8C EE 11 85 5D 28 2F 13 1D [01:03:58.555] EVT <= A2 1A 40 00 0B 00 0C 00 0D 00 12 00 EE FC D5 4F 69 CC CC 8E 67 47 E8 AE 7B 17 97 F8 Characteristic Discovered: F897177B-AEE8-4767-8ECC-CC694FD5FCEE, handle 0xC Characteristic found: RX [01:03:58.556] EVT <= A2 1A 40 00 0E 00 0F 00 0F 00 0A 00 4B 1B 5F 06 D6 E5 A0 BB C8 4B 2A DE 0A E4 45 BF Characteristic Discovered: BF45E40A-DE2A-4BC8-BBA0-E5D6065F1B4B, handle 0xF Characteristic found: TX [01:03:58.556] EVT <= A2 1A 40 00 10 00 11 00 11 00 02 00 82 E9 52 06 BE C8 FE B9 14 40 6A 72 31 0F BC 2F Characteristic Discovered: 2FBC0F31-726A-4014-B9FE-C8BE0652E982, handle 0x11 Characteristic found: Baudrate [01:03:58.557] ACL => 40 00 0B 00 07 00 04 00 08 14 00 14 00 03 28 [01:03:58.558] EVT <= 6E 00 [01:03:58.558] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.559] EVT <= 6E 00 [01:03:58.559] EVT <= 79 02 04 00 [01:03:58.580] EVT <= 13 05 01 40 00 02 00 [01:03:58.640] ACL <= 40 20 09 00 05 00 04 00 01 08 14 00 0A [01:03:58.640] EVT <= A2 1A 40 00 12 00 13 00 14 00 12 00 02 00 12 AC 42 02 99 8C EE 11 85 5D 28 2F 13 1D Characteristic Discovered: 1D132F28-5D85-11EE-8C99-0242AC120002, handle 0x13 Characteristic found: Intent [01:03:58.641] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:03:58.641] EVT <= A0 03 40 00 00 Characteristic discovery finished, status 1 Subscribing to charRX [01:03:58.642] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:03:58.642] ACL => 40 00 0B 00 07 00 04 00 08 0C 00 0D 00 02 29 [01:03:58.643] EVT <= 6E 00 [01:03:58.643] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.644] EVT <= 6E 00 [01:03:58.644] EVT <= 79 02 04 00 [01:03:58.760] ACL <= 40 20 0A 00 06 00 04 00 09 04 0D 00 00 00 [01:03:58.761] ACL => 40 00 09 00 05 00 04 00 12 0D 00 01 00 [01:03:58.761] EVT <= 6E 00 [01:03:58.762] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.762] EVT <= 6E 00 [01:03:58.763] EVT <= 79 02 04 00 [01:03:58.791] EVT <= 13 05 01 40 00 02 00 [01:03:58.850] ACL <= 40 20 09 00 05 00 04 00 01 12 0D 00 03 [01:03:58.851] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:03:58.851] EVT <= A0 03 40 00 03

Subscribe Callback: 4 BLE_STATUS_OTHER_ERROR [01:03:58.851] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:03:58.851] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 [01:03:58.852] EVT <= 6E 00 [01:03:58.853] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.853] EVT <= 6E 00 [01:03:58.854] EVT <= 79 02 04 00 [01:03:58.940] ACL <= 40 20 06 00 02 00 04 00 0B 50 [01:03:58.941] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:03:58.941] EVT <= A5 07 40 00 0C 00 01 00 50 Read callback Read Value:80 [01:03:58.941] EVT <= A0 03 40 00 00

Subscribe Callback: 0 BLE_STATUS_OK [01:03:58.942] CMD => 35 0C 05 01 40 00 01 00 [01:03:58.942] EVT <= 6E 00 [01:03:59.117] EVT <= 13 05 01 40 00 01 00 Reading... [01:04:03.420] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:04:03.421] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 [01:04:03.421] EVT <= 6E 00 [01:04:03.422] EVT <= 79 02 04 00 [01:04:03.530] ACL <= 40 20 06 00 02 00 04 00 0B 50 [01:04:03.530] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:04:03.531] EVT <= A5 07 40 00 0C 00 01 00 50 Read callback Read Value:80 [01:04:03.531] EVT <= A0 03 40 00 00

Subscribe Callback: 0 BLE_STATUS_OK [01:04:03.531] CMD => 35 0C 05 01 40 00 01 00 [01:04:03.532] EVT <= 6E 00 [01:04:03.617] EVT <= 13 05 01 40 00 01 00 Reading... [01:04:08.421] LOG -- gatt_client.c.124: GATT client timeout start, handle 0x40 [01:04:08.422] ACL => 40 00 07 00 03 00 04 00 0A 0C 00 [01:04:08.422] EVT <= 6E 00 [01:04:08.423] EVT <= 79 02 04 00 [01:04:08.570] ACL <= 40 20 06 00 02 00 04 00 0B 51 [01:04:08.570] LOG -- gatt_client.c.132: GATT client timeout stop, handle 0x40 [01:04:08.570] EVT <= A5 07 40 00 0C 00 01 00 51 Read callback Read Value:81 [01:04:08.571] EVT <= A0 03 40 00 00

Subscribe Callback: 0 BLE_STATUS_OK [01:04:08.571] CMD => 35 0C 05 01 40 00 01 00 [01:04:08.572] EVT <= 6E 00 [01:04:08.741] EVT <= 13 05 01 40 00 01 00

Nice. Progress! Here's the packet log for Wireshark

arduino.pklg.zip

Jan 01 12:03:58.760 ATT Receive Read By Type Response RECV
Read By Type Response Opcode: 0x0009 Length: 0x0004 (4) Characteristic Handle: 0x000D Raw Value: : 0D00 0000

With the changes, the ATT Read By Type Request is answered correctly: BTstack learns that the CCCD Handle is 0x000d.

Ok, next BTstack sends a write request to enable notifications.

Jan 01 12:03:58.761 ATT Send Write Request - Handle:0x000D - F897177B-AEE8-4767-8ECC-CC694FD5FCEE - Value: 0100 SEND
Write Request - Handle:0x000D - F897177B-AEE8-4767-8ECC-CC694FD5FCEE - Value: 0100 Opcode: 0x0012 Attribute Handle: 0x000D (13) Value: 0100

Looks good. The Nano responds with:

Jan 01 12:03:58.850 ATT Receive Error Response - Attribute Handle: 0x000D - Error Code: Write Not Permitted (0x03) - Write Not Permitted RECV
Error Response - Attribute Handle: 0x000D - Error Code: Write Not Permitted (0x03) Opcode: 0x0001 Request Opcode In Error: 0x0012 (Write Request) Attribute Handle In Error: 0x000D (13) Error Code: 0x0003 (Write Not Permitted)

Quick look into the code, it looks like the previous hack broke the write request. Going forward, could you patch

https://github.com/arduino-libraries/ArduinoBLE/blob/dff9e414abc20df491b46d0b38b360eb1a3507fb/src/utility/ATT.cpp#L1306

and replace BLETypeDescriptor with ((enum BLEAttributeType) 0x2902)? It should then enter that scope again.

bluekitchen / btstack

ArduinoBLE: BTstack's Enable Notifications fails against ArduinoBLE GATT Server #529