Changed behaviour (2.1.3 vs 2.2.0) when retrieving remote descriptors

[gkoh]

After updating to v2.2.0, retrieving descriptors has changed behaviour due to 74ac317 (found via bisect).

In v2.1.3, the debug output for one particular characteristic looks like:

D NimBLERemoteCharacteristic: >> setNotify()
D NimBLERemoteCharacteristic: >> getDescriptor: uuid: 0x2902
D NimBLERemoteCharacteristic: >> retrieveDescriptors() for characteristic: 049ec406-ef75-4205-a390-08fe209c51f0
I (27700) NimBLE: GATT procedure initiated: discover all descriptors; 
I (27707) NimBLE: chr_val_handle=20562 end_handle=20738

D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20563
D NimBLERemoteCharacteristic: << Descriptor Discovery
D NimBLERemoteCharacteristic: << retrieveDescriptors(): found 1 descriptors.
D NimBLERemoteCharacteristic: << getDescriptor: found
D NimBLERemoteCharacteristic: << setNotify()
D NimBLERemoteValueAttribute: >> writeValue()
I (27805) NimBLE: GATT procedure initiated: write; 
I (27810) NimBLE: att_handle=20563 len=2

I NimBLERemoteValueAttribute: Write complete; status=0
D NimBLERemoteValueAttribute: << writeValue

The same scenario for v2.2.0:

D NimBLERemoteCharacteristic: >> setNotify()
D NimBLERemoteCharacteristic: >> getDescriptor: uuid: 0x2902
D NimBLERemoteCharacteristic: >> retrieveDescriptors() for characteristic: 049ec406-ef75-4205-a390-08fe209c51f0
I (29345) NimBLE: GATT procedure initiated: discover all descriptors; 
I (29352) NimBLE: chr_val_handle=20562 end_handle=20738

D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20563
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20577
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20578
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20579
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20593
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20594
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20595
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20609
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20610
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20611
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20625
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20626
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20737
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 0 handle: 20738
D NimBLERemoteCharacteristic: Descriptor Discovery >> status: 14 handle: -1
D NimBLERemoteCharacteristic: << Descriptor Discovery
D NimBLERemoteCharacteristic: << retrieveDescriptors(): found 4 descriptors.
D NimBLERemoteCharacteristic: << getDescriptor: found
D NimBLERemoteCharacteristic: << setNotify()
D NimBLERemoteValueAttribute: >> writeValue()
I (30132) NimBLE: GATT procedure initiated: write; 
I (30137) NimBLE: att_handle=20611 len=2

I NimBLERemoteValueAttribute: Write complete; status=0
D NimBLERemoteValueAttribute: << writeValue

Note that more descriptors are discovered and the found descriptor has a different attribute handle.
I found that if I remove this line:

NimBLE-Arduino/src/NimBLERemoteCharacteristic.cpp

Line 89 in 3081bc1

return 0;

the previous behaviour is restored.

I'm not sure if this is my problem (ie bad assumptions) or not.

[thekurtovic]

As far as I understand, the previous version was incorrect and released the task on the first result opposed to waiting for the status to indicate done/error with a non-zero value. The rest of the log appears fine, no?

The different attribute handle is probably due to 20611 being the last one pushed into the vector, which is what gets returned from getDescriptor

NimBLE-Arduino/src/NimBLERemoteCharacteristic.cpp

Line 153 in 3081bc1

pDsc = m_vDescriptors.back();

[gkoh]

Apologies, I should clarify, my app fails with 2.2.0 whereas it did not with 2.1.3.

The major difference I found in the debug log was the descriptor retrieval.

I'm working with a blackbox target which expects the client to subscribe for indications on that particular characteristic to complete the handshake process.

I'm not 100% convinced NimBLE-Arduino is incorrect in this regard, but I haven't found anything else so far.

I also note that if I change m_vDescriptors().back() to m_vDescriptors().front(), things return to working (since this emulates the <=2.1.3 behaviour of first and singular descriptor).

[thekurtovic]

Could you try changing this line to return rc?

NimBLE-Arduino/src/NimBLERemoteCharacteristic.cpp

Line 89 in 3081bc1

return 0;

[gkoh]

Could you try changing this line to return rc?

NimBLE-Arduino/src/NimBLERemoteCharacteristic.cpp

Line 89 in 3081bc1

return 0;

No change, still fails.
However, that would be expected, given the block is within a if (rc ==0).

[gkoh]

After some investigation, I think my problem is specific to subscriptions via CCCD and writing to the correct descriptor.

[gkoh]

Could you try changing this line to return rc?
NimBLE-Arduino/src/NimBLERemoteCharacteristic.cpp
Line 89 in 3081bc1
return 0;

No change, still fails. However, that would be expected, given the block is within a if (rc ==0).

Oh, sorry, it could be BLE_HS_EDONE if the UUID filter matches.

[thekurtovic]

Sorry, I forgot that the task must be released when descriptorDiscCB returns rc != 0, which is why your edit worked.

I found that if I remove this line:

Would you mind testing this? I have a PR open which should fix this h2zero/esp-nimble-cpp#287

int NimBLERemoteCharacteristic::descriptorDiscCB(
    uint16_t conn_handle, const ble_gatt_error* error, uint16_t chr_val_handle, const ble_gatt_dsc* dsc, void* arg) {
    int rc = error->status;
    NIMBLE_LOGD(LOG_TAG, "Descriptor Discovery >> status: %d handle: %d", rc, (rc == 0) ? dsc->handle : -1);

    auto              filter     = (desc_filter_t*)arg;
    auto              pTaskData  = (NimBLETaskData*)filter->task_data;
    const auto        pChr       = (NimBLERemoteCharacteristic*)pTaskData->m_pInstance;
    const NimBLEUUID* uuidFilter = filter->uuid;

    if (rc == 0 && pChr->getHandle() == chr_val_handle) 
      && (!uuidFilter || 0 == ble_uuid_cmp(uuidFilter->getBase(), &dsc->uuid.u))) {
        // Return BLE_HS_EDONE if the descriptor was found, stop the search
        pChr->m_vDescriptors.push_back(new NimBLERemoteDescriptor(pChr, dsc));
        rc = !!uuidFilter * BLE_HS_EDONE;
    }

    if (rc != 0) {
        NimBLEUtils::taskRelease(*pTaskData, rc);
        NIMBLE_LOGD(LOG_TAG, "<< Descriptor Discovery");
    }
    return rc;
}

[gkoh]

Sorry, I forgot that the task must be released when descriptorDiscCB returns rc != 0, which is why your edit worked.

I found that if I remove this line:

I should clarify that when it 'failed' again, it actually hung and I didn't notice 😐

Would you mind testing this? I have a PR open which should fix this h2zero/esp-nimble-cpp#287

int NimBLERemoteCharacteristic::descriptorDiscCB(
    uint16_t conn_handle, const ble_gatt_error* error, uint16_t chr_val_handle, const ble_gatt_dsc* dsc, void* arg) {
    int rc = error->status;
    NIMBLE_LOGD(LOG_TAG, "Descriptor Discovery >> status: %d handle: %d", rc, (rc == 0) ? dsc->handle : -1);

    auto              filter     = (desc_filter_t*)arg;
    auto              pTaskData  = (NimBLETaskData*)filter->task_data;
    const auto        pChr       = (NimBLERemoteCharacteristic*)pTaskData->m_pInstance;
    const NimBLEUUID* uuidFilter = filter->uuid;

    if (rc == 0 && pChr->getHandle() == chr_val_handle) 
      && (!uuidFilter || 0 == ble_uuid_cmp(uuidFilter->getBase(), &dsc->uuid.u))) {
        // Return BLE_HS_EDONE if the descriptor was found, stop the search
        pChr->m_vDescriptors.push_back(new NimBLERemoteDescriptor(pChr, dsc));
        rc = !!uuidFilter * BLE_HS_EDONE;
    }

    if (rc != 0) {
        NimBLEUtils::taskRelease(*pTaskData, rc);
        NIMBLE_LOGD(LOG_TAG, "<< Descriptor Discovery");
    }
    return rc;
}

I have tested and indeed this fixes it!
Thanks @thekurtovic

For now I will stay on 2.1.3 and wait for 2.2.0+.

[thekurtovic]

Great, thanks for testing 👍

[Berg0162]

Since installation of 2.2.0 I have structural problems to subscribe remote characteristics like:

pRemote_CP_ControlPoint_Chr->subscribe(indications, Static_CP_ControlPoint_Indicate_Callback);

In the previous version my code worked perfectly....
My code has 6 remote characteristics to subscribe to and 1 out of 6 is failing consequently with 2.2.0!
After inserting a retry loop the second or third retry was only successful!
I am sure this is related to this issue #867, since I have inserted the following:

    if ((rc == 0 && pChr->getHandle() == chr_val_handle) 
      && (!uuidFilter || 0 == ble_uuid_cmp(uuidFilter->getBase(), &dsc->uuid.u))) {
        // Return BLE_HS_EDONE if the descriptor was found, stop the search
        pChr->m_vDescriptors.push_back(new NimBLERemoteDescriptor(pChr, dsc));
        rc = !!uuidFilter * BLE_HS_EDONE;
    }

    if (rc != 0) {
        NimBLEUtils::taskRelease(*pTaskData, rc);
        NIMBLE_LOGD(LOG_TAG, "<< Descriptor Discovery");
    }
    return rc;

and subscribing to remote characteristics is no longer randomly successfull....
I look forward to version 2.2.0+ that will hav fixed this!

[doudar]

Related, I've found that 2.2.0 cannot subscribe to notifications if any service contains more than 3 characteristics. Rolling back to 2.1.3 as mentioned above resolves the issue.

I have test code with a simple server and client for duplication at: https://github.com/doudar/NimBLE_Test