Softdevice S112 Incorrect Packet Length with new NRF52SDK

[snoopy20]

Upgraded from v16.0.0 to v17.1.0 and have a truncation issue. It only occurs after the first send. Reverted back to v16.0.0 and all ok.

No other code change other than the fixes to RAM1 and FLASH1.

static uint32_t BLUETOOTH_Push (uint16_t len, uint8_t *data, uint16_t handle) {

    if (m_conn_handle == BLE_CONN_HANDLE_INVALID) {
      return 0;
    }

    ble_gatts_hvx_params_t params;

    memset(&params, 0, sizeof(params));
    params.type   = BLE_GATT_HVX_NOTIFICATION;
    params.handle = handle;
    params.p_data = data;
    params.offset = 0;
    params.p_len  = &len;

    return sd_ble_gatts_hvx(m_conn_handle, &params);
}

uint32_t BLUETOOTH_PushStatus(void) {

    return BLUETOOTH_Push(sizeof(status), (uint8_t *) &status, m_lbs.status_char_handles.value_handle);
}

The bluetooth phone app shows the following being passed - 

LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 5, 0, 0, 0, 0, 0, 25, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 30, 60, 101, 0, 0, 18, 19, 102, 10], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}
LOG {"data": [0, 0, 3, 0, 0, 0, 0, 0, 0, 10, 0, 0, 0, 0, 0, 20, 0, 0, 0, 1], "type": "Buffer"}

There should only but the one and then a long delay but it looks that as well as the truncation the softdevice is in a loop.

[Einar Thorsrud]

Hi,

This seems odd. i think it is worth debugging a bit more in your application first before concluding that the issue resides in the SoftDevice. Have you checked with a debugger or logging that sd_ble_gatts_hvx() is only called once? Could it be that you call it from somewhere else?

Are you able to reproduce this on a DK? If so, can you upload a project that I can use to test on my end?

[snoopy20]

Hi,

It's not softdevice but with the later SDK. Version 16 works (also with the new softdevice 7.2). There is a bug for sure, I have changed nothing else.

Here's the code which does the send:

static uint32_t BLUETOOTH_Push (uint16_t len, uint8_t *data, uint16_t handle) {

    if (m_conn_handle == BLE_CONN_HANDLE_INVALID) {
      return 0;
    }

    ble_gatts_hvx_params_t params;

    memset(&params, 0, sizeof(params));
    params.type   = BLE_GATT_HVX_NOTIFICATION;
    params.handle = handle;
    params.p_data = data;
    params.p_len  = &len;

    return sd_ble_gatts_hvx(m_conn_handle, &params);
}

uint32_t BLUETOOTH_PushStatus(void) {

    return BLUETOOTH_Push(sizeof(status), (uint8_t *) &status, m_lbs.status_char_handles.value_handle);
}

I can see that 

sd_ble_gatts_hvx is a macro call for

SVCALL(SD_BLE_GATTS_HVX, uint32_t, sd_ble_gatts_hvx(uint16_t conn_handle, ble_gatts_hvx_params_t const *p_hvx_params));

And that ble_gatts.h hasn't changed at all from v16.0.0 to v17.1.0. Given either s112 softdevice version work on v16.0.0 I'm now thinking it has to be set up during the characteristic which has changed for v17.1.0.

Here's my code for that:

/**@brief Function for application main entry.
 */
inline void BLUETOOTH_Init (void) {

    ret_code_t err_code;

    err_code = app_timer_init();
    APP_ERROR_CHECK(err_code);

    // power management init
    //err_code = nrf_pwr_mgmt_init();
    //APP_ERROR_CHECK(err_code);

    // enable softdevice
    err_code = nrf_sdh_enable_request();
    APP_ERROR_CHECK(err_code);

    // Configure the BLE stack using the default settings.
    // Fetch the start address of the application RAM.
    uint32_t ram_start = 0;
    err_code = nrf_sdh_ble_default_cfg_set(APP_BLE_CONN_CFG_TAG, &ram_start);
    APP_ERROR_CHECK(err_code);

    // Enable BLE stack.
    err_code = nrf_sdh_ble_enable(&ram_start);
    APP_ERROR_CHECK(err_code);

    // Register a handler for BLE events.
    NRF_SDH_BLE_OBSERVER(m_ble_observer, APP_BLE_OBSERVER_PRIO, BLUETOOTH_EventHandler, NULL);

    // GAP init
    ble_gap_conn_params_t   gap_conn_params;
    ble_gap_conn_sec_mode_t sec_mode;
    BLE_GAP_CONN_SEC_MODE_SET_OPEN(&sec_mode);
    err_code = sd_ble_gap_device_name_set(&sec_mode, (const uint8_t *)DEVICE_NAME, strlen(DEVICE_NAME));
    APP_ERROR_CHECK(err_code);
    memset(&gap_conn_params, 0, sizeof(gap_conn_params));
    gap_conn_params.min_conn_interval = MIN_CONN_INTERVAL;
    gap_conn_params.max_conn_interval = MAX_CONN_INTERVAL;
    gap_conn_params.slave_latency     = SLAVE_LATENCY;
    gap_conn_params.conn_sup_timeout  = CONN_SUP_TIMEOUT;
    err_code = sd_ble_gap_ppcp_set(&gap_conn_params);
    APP_ERROR_CHECK(err_code);

    // gatt init
    err_code = nrf_ble_gatt_init(&m_gatt, NULL);
    APP_ERROR_CHECK(err_code);

    // services init
      nrf_ble_qwr_init_t qwr_init = {0};

      // Initialize Queued Write Module.
      qwr_init.error_handler = nrf_qwr_error_handler;

      err_code = nrf_ble_qwr_init(&m_qwr, &qwr_init);
      APP_ERROR_CHECK(err_code);

      ble_uuid_t            ble_uuid;
      ble_add_char_params_t add_char_params;

      // Add service.
      ble_uuid128_t base_uuid = {LBS_UUID_BASE};
      err_code = sd_ble_uuid_vs_add(&base_uuid, &m_lbs.uuid_type);
      VERIFY_SUCCESS(err_code);
      ble_uuid.type = m_lbs.uuid_type;
      ble_uuid.uuid = LBS_UUID_SERVICE;
      err_code = sd_ble_gatts_service_add(BLE_GATTS_SRVC_TYPE_PRIMARY, &ble_uuid, &m_lbs.service_handle);
      VERIFY_SUCCESS(err_code);

      // Add Device characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_DEVICE_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &device;
      add_char_params.init_len          = sizeof(device);
      add_char_params.max_len           = sizeof(device);
      add_char_params.char_props.read   = 1;
      add_char_params.char_props.write  = 0;
      add_char_params.char_props.notify = 1;
      add_char_params.read_access       = SEC_OPEN;
      //add_char_params.write_access      = SEC_NO_ACCESS;
      add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.device_char_handles);

      // Add Status characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_STATUS_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &status;
      add_char_params.init_len          = sizeof(status);
      add_char_params.max_len           = sizeof(status);
      add_char_params.char_props.read   = 1;
      //add_char_params.char_props.write  = 0;
      add_char_params.char_props.notify = 1;
      add_char_params.read_access       = SEC_OPEN;
      //add_char_params.write_access      = SEC_NO_ACCESS;
      add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.status_char_handles);

      // Add Control characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_CONTROL_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &control;
      add_char_params.init_len          = sizeof(control);
      add_char_params.max_len           = sizeof(control);
      add_char_params.char_props.read   = 1;
      add_char_params.char_props.write  = 1;
      add_char_params.char_props.notify = 0;
      add_char_params.read_access       = SEC_OPEN;
      add_char_params.write_access      = SEC_OPEN;
      //add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.control_char_handles);

      // Add Command characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_COMMAND_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &command;
      add_char_params.init_len          = sizeof(command);
      add_char_params.max_len           = sizeof(command);
      add_char_params.char_props.read   = 1;
      add_char_params.char_props.write  = 1;
      add_char_params.char_props.notify = 1;
      add_char_params.read_access       = SEC_OPEN;
      add_char_params.write_access      = SEC_OPEN;
      add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.command_char_handles);

      // Add Config characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_CONFIG_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &config.settings;
      add_char_params.init_len          = sizeof(config.settings);
      add_char_params.max_len           = sizeof(config.settings);
      add_char_params.char_props.read   = 1;
      add_char_params.char_props.write  = 1;
      add_char_params.char_props.notify = 1;
      add_char_params.read_access       = SEC_OPEN;
      add_char_params.write_access      = SEC_OPEN;
      add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.config_char_handles);

      // Add Logs characteristic.
      memset(&add_char_params, 0, sizeof(add_char_params));
      add_char_params.uuid              = LBS_UUID_LOGS_CHAR;
      add_char_params.uuid_type         = m_lbs.uuid_type;
      add_char_params.p_init_value      = (uint8_t*) &powerManager.logs;
      add_char_params.init_len          = sizeof(powerManager.logs);
      add_char_params.max_len           = sizeof(powerManager.logs);
      add_char_params.char_props.read   = 1;
      //add_char_params.char_props.write  = 1;
      add_char_params.char_props.notify = 1;
      add_char_params.read_access       = SEC_OPEN;
      //add_char_params.write_access      = SEC_NO_ACCESS;
      add_char_params.cccd_write_access = SEC_OPEN;
      characteristic_add(m_lbs.service_handle, &add_char_params, &m_lbs.logs_char_handles);

    // advertising init
      ble_advdata_t advdata;
      ble_advdata_t srdata;
      ble_uuid_t adv_uuids[] = {{LBS_UUID_SERVICE, m_lbs.uuid_type}};
      // Build and set advertising data.
      memset(&advdata, 0, sizeof(advdata));
      advdata.name_type          = BLE_ADVDATA_FULL_NAME;
      advdata.include_appearance = true;
      advdata.flags              = BLE_GAP_ADV_FLAGS_LE_ONLY_GENERAL_DISC_MODE;
      memset(&srdata, 0, sizeof(srdata));
      srdata.uuids_complete.uuid_cnt = sizeof(adv_uuids) / sizeof(adv_uuids[0]);
      srdata.uuids_complete.p_uuids  = adv_uuids;
      err_code = ble_advdata_encode(&advdata, m_adv_data.adv_data.p_data, &m_adv_data.adv_data.len);
      APP_ERROR_CHECK(err_code);
      err_code = ble_advdata_encode(&srdata, m_adv_data.scan_rsp_data.p_data, &m_adv_data.scan_rsp_data.len);
      APP_ERROR_CHECK(err_code);
      // Set advertising parameters.
      ble_gap_adv_params_t adv_params;
      memset(&adv_params, 0, sizeof(adv_params));
      adv_params.primary_phy     = BLE_GAP_PHY_1MBPS;
      adv_params.duration        = APP_ADV_DURATION;
      adv_params.properties.type = BLE_GAP_ADV_TYPE_CONNECTABLE_SCANNABLE_UNDIRECTED;
      adv_params.p_peer_addr     = NULL;
      adv_params.filter_policy   = BLE_GAP_ADV_FP_ANY;
      adv_params.interval        = APP_ADV_INTERVAL;
      err_code = sd_ble_gap_adv_set_configure(&m_adv_handle, &m_adv_data, &adv_params);
      APP_ERROR_CHECK(err_code);

    // initializing the Connection Parameters module.
      ble_conn_params_init_t cp_init;
      memset(&cp_init, 0, sizeof(cp_init));
      cp_init.p_conn_params                  = NULL;
      cp_init.first_conn_params_update_delay  = FIRST_CONN_PARAMS_UPDATE_DELAY;
      cp_init.next_conn_params_update_delay  = NEXT_CONN_PARAMS_UPDATE_DELAY;
      cp_init.max_conn_params_update_count   = MAX_CONN_PARAMS_UPDATE_COUNT;
      cp_init.start_on_notify_cccd_handle    = BLE_GATT_HANDLE_INVALID;
      cp_init.disconnect_on_fail             = true;
      cp_init.evt_handler                    = on_conn_params_evt;
      cp_init.error_handler                  = conn_params_error_handler;

      err_code = ble_conn_params_init(&cp_init);
      APP_ERROR_CHECK(err_code);
}

Andrew

[Einar Thorsrud]

HI Andrew,

I agree there is a bug somewhere, but we need to investigate more in order to understand what and where. Please check what I suggested. If you can reproduce this on a DK I can also test on my end.

Einar

[snoopy20]

Hi, I added a lot more to the above post.

I have changed nothing, only the SDK has changed.

BLUETOOTH_Push() is only called once. The phone app makes a command request of 'status' and then the status is sent and the command on the characteristic reset (so it knows it's been actioned). When the App gets a confirmation it waits 750ms before requesting another update. It only makes the one call and then exits however gatt is indicating multiple notifications.

Given it's truncated and the length is always supplied my thoughts are around the max_len changing after the characteristic has been read. I've no idea why though.

add_char_params.init_len          = sizeof(status);
add_char_params.max_len           = sizeof(status);

[Einar Thorsrud]

snoopy20 said:

I have changed nothing, only the SDK has changed.

Which major SDK version number changes there are API changes, so you need to handle those (if any relevant).

snoopy20 said:

The phone app makes a command request of 'status' and then the status is sent and the command on the characteristic reset (so it knows it's been actioned). When the App gets a confirmation it waits 750ms before requesting another update.

This is new information, I assume BLUETOOTH_Push() is not relevant for the issue, then. How does the app request an update? Is it by reading the same characteristic? Or another characeristic? How is it read? I as Please elaborate. And please commend on how you have debugged on the nRF and what you have found from that.