Problem communication between BLE_APP_UART_C and BLE_APP_UART (TX notifications are not always enabled)

[Andrew_Engineer]

Hello Nordic Guys,

 

 

 

We are working on the system based on BLE_APP_UART_C (central) and BLE_APP_UART (peripheral).

“Central” is always “ON” and scanning for the peripherals.

“Peripheral” wakes up every 5 minutes, connects to the “Central”, sends data, and going back to sleep.

 

System works perfectly when “peripheral” were based on SDK 11 S132 Version 2, now we are migrating to SDK14.0 S132 V5, and experiencing some challenges. (In both cases “Central was always build on SDK14 SD 132 V5)

 

What we are noticing is bellow:

 

1. “Central” is connected to the “peripheral”
2. “Central” is enabling tx notifications by calling function: ble_nus_c_tx_notif_enable(..)

 

On the “peripheral” side we seeing follow behavior:

 

1. “Peripheral” is connected to the “Central”           GAP_EVT_CONNECTED
2. Exchange MTU response event ie “Central” and “Peripheral” is trying to negotiate data package size                                       BLE_GATTC_EVT_EXCHANGE_MTU_RSP
3. BLE_GATTS_EVT_WRITE with event ID 80 and length 20, we are assuming this is a point where “Central” is enabling Notifications on “Peripheral”.

 

What we are experiencing: it seems like Notifications is not always enabling on the “Peripheral” side ie if we try to send message from the “Central” to the ”Peripheral” it is going to be delivered.

 

In “good” case scenario after receiving BLE_GATTS_EVT_WRITE we are getting BLE_NUS_EVT_COMM_STARTED, but in “bad” case scenario we are not getting anything and after roughly 10-12 seconds we are getting: BLE_GAP_EVT_CONN_PARAM_UPDATE. But we still not able to communicate between “peripheral” and central. Once “peripheral” is disconnected from the “Central” on the next connection attempt system could communicate, but behavior is random.

 

Question: if there is way on the “Peripheral” side to make sure Tx notifications had been enabled?

 

What would be the word of advice how we can address this issue?

 

 

Thank you,

 

 

Andrew.

[Kenneth]

Hi,

On the central side there is BLE_NUS_C_EVT_DISCOVERY_COMPLETE event when the database (GATT server) on the peer side have been read. If the correct UUID is found during discovery, then the application will call ble_nus_c_tx_notif_enable() to write to the specific handle on the peer to enable notification. This is done by calling sd_ble_gattc_write() to enable notification. So the first thing to check is if this occurs with no errors on the central side.

On the peripheral side there is a BLE_GATTS_EVT_WRITE event when the peer write to a characteristic. Typically this event will be forwarded to each of the callbacks for the BLE modules that have setup the database. Each callback then check if the write was to a local handle in on_write(), and take some sort of action if the write was to a characteristics handle the specific BLE module setup during init. This means that the BLE module should buffer the handle it receives when init the database, and compare with the BLE_GATTS_EVT_WRITE handle. 

So you should check if on_write() is called as expected, that it is the right CCCD handle in p_nus->tx_handles.cccd_handle and that BLE_NUS_EVT_COMM_STARTED is set as expected as shown in on_write() below.

/**@brief Function for handling the @ref BLE_GATTS_EVT_WRITE event from the SoftDevice.
 *
 * @param[in] p_nus     Nordic UART Service structure.
 * @param[in] p_ble_evt Pointer to the event received from BLE stack.
 */
static void on_write(ble_nus_t * p_nus, ble_evt_t const * p_ble_evt)
{
    ble_gatts_evt_write_t const * p_evt_write = &p_ble_evt->evt.gatts_evt.params.write;
    ble_nus_evt_t evt;
    evt.p_nus = p_nus;
    if (   (p_evt_write->handle == p_nus->tx_handles.cccd_handle)
        && (p_evt_write->len == 2))
    {
        if (ble_srv_is_notification_enabled(p_evt_write->data))
        {
            p_nus->is_notification_enabled = true;
            evt.type = BLE_NUS_EVT_COMM_STARTED;
        }
        else
        {
            p_nus->is_notification_enabled = false;
            evt.type = BLE_NUS_EVT_COMM_STOPPED;
        }
        p_nus->data_handler(&evt);
    }
    else if (   (p_evt_write->handle == p_nus->rx_handles.value_handle)
             && (p_nus->data_handler != NULL))
    {
        evt.params.rx_data.p_data = p_evt_write->data;
        evt.params.rx_data.length = p_evt_write->len;
        evt.type = BLE_NUS_EVT_RX_DATA;
        p_nus->data_handler(&evt);
    }
    else
    {
        // Do Nothing. This event is not relevant for this service.
    }
}

Best regards,
Kenneth

[Andrew_Engineer]

Hi Kenneth,

Thank you for detailed explanations. I have follow your instructions and here my results so far:

On the "Central" Side there are two functions called back to back, from the BLE_NUS_C_EVT_DISCOVERY_COMPLETE event :

err_code = ble_nus_c_handles_assign(...)

err_code = ble_nus_c_tx_notif_enable(...)

both of them returns NRF_SUCCESS.

I am assuming (for now) Central is "OK"

note: below I am using follow definition: good and bad scenario.

Good scenario means: TX notifications was successfully enabled on the "peripheral side", and "Peripheral" were able to communicate with "Central"

Bad scenario TX notifications was NOT enabled on the "peripheral"side, therefore communication between "Central" and "peripheral" is impossible 

on the "Peripheral" side I added debug printf inside on_write(...) function. I find out that: I am fail first 'if'-statement;

if ( (p_evt_write->handle == p_nus->tx_handles.cccd_handle)
&& (p_evt_write->len == 2))

in "good" and "bad" scenarios length is always equals '2'   (All numbers here and bellow are decimal)

in "good" and "bad" scenarios  p_nus->tx_handles.cccd_handle is always equals '16',

in good case p_evt_write->handle is equals '16', but in bad case p_evt_write->handle is equals 15.

Any word of advise how to address this?

Regards,

Andrew

[Kenneth]

Hi,

As a sniffer you can use any nRF52-DK:
https://www.nordicsemi.com/eng/Products/Bluetooth-low-energy/nRF-Sniffer/(language)/eng-GB

You may reset the discovery module by actively calling ble_db_discovery_close() and ble_db_discovery_init() between connections, but that should not be necessary. Because in ble_db_discovery_on_ble_evt() there is already handling of BLE_GAP_EVT_DISCONNECTED, which calls on_disconnected() and should in essence do the same. Though maybe there is some race condition here in your code. So you may for debugging try to print out when BLE_GAP_EVT_DISCONNECTED and BLE_GAP_EVT_CONNECTED occurs relative to calling ble_db_discovery_start().

Also, I noticed discovery_start() will always return NRF_SUCCESS, even if sd_ble_gattc_primary_services_discover() may return an error code. It would be interesting if you could print out the actual return code from sd_ble_gattc_primary_services_discover() in discovery_start(), and see if there is an error shortly before your problem occurs.

There is no change in project settings moving from S132v5.0->S132v5.1.

Best regards,
Kenneth

[Andrew_Engineer]

Hi Kenneth,

 

Thank you very much for your replay. I did try follow:

 

1. Print error code after calling sd_ble_gattc_primary_services_discover(..) always returns NRF_SUCCESS
2. I also try to re-initialize discovery module by calling db_discovery_close() in BLE_GAP_EVT_DISCONNECTED. Then I called ble_db_discovery_init(…) and nus_c_init(…) before calling start_scan(…)

 Nothing helps…

 I tried to print from function ble_db_discovery_on_ble_evt, case BLE_GATTC_EVT_CHAR_DISC_RESP :

p_ble_evt->evt.gattc_evt.conn_handle and it is always returns 0

 Question if there is chance I can print cccd_handler from ble_db_discovery_on_ble_evt function, if I can please advise…

 

I am going to look at the sniffer tomorrow and adivse

 

 

Regards,

 

Andrew

[Kenneth]

Let me know when you have the sniffer log. Thanks.

[Andrew_Engineer]

bad communication.pcapnggood communcation.pcapng

Hi Kenneth,

 

Attached wireshark logs: for “good” and “bad” communication. I tried to decipher myself, but quickly realized I need expert help, can you please have look and advise.

 

Also, one more question: What is nature of the tx_cccd_handle: ie is it random generated number? Is this number client supposed to communicate to central? Or Central somehow generate this number? Can you please elaborate a bit on this..

 

 

Thank you for all your help.

 

Regards,

 

 

Andrew

[Kenneth]

Hi,

There is something odd happening here:

- It seems that in bad log the peripheral trigger an MTU exchange on connection event, this does not occur in good log. This does not explain your issue, however it is inconsistent behaviour.
- In bad log the peripheral reponse with handles from 0x000b->0x0010, while in good log the peripheral response is 0x000c->0x0011. This does not explain your issue either, however it is inconsistent behaviour. In both cases it's the peripheral that has inconsistent behavior.

It may seem as a bug of some sort, possible because "something" is not initialized/memset() properly. I suggest to use SDKv14.2 and S132v5.1 if you haven't already. Also try to look into why you are sometimes triggering MTU exchange. Not sure what compiler you are using, but possible change optimization is a long shot. 

The handles will be generated sequentially, but for the same firmware they should be the same each time.

Best regards,
Kenneth

[Andrew_Engineer]

Hi Kenneth,

Sorry for the delay with replay. I did upgrade central to SD5.1 SDK14.2 and problem seems to disappear .

Regards,

Andrew

[Kenneth]

Good to hear, let me know if you experience it again with the new SDK+SD.