This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

CC2564C: advertising stops after some connection attemps

Part Number: CC2564C

Hello,

I've been investigating an issue with a PAN1326C (contains CC2564C, Firmware v1.1) which spuriously stopped advertising in an automated test setup after a lot of BLE connect/disconnect cycles.

The BT module is still communicating via HCI and it behaves like normal but the advertisements cannot be received anymore.

I was able to track this down to a setup where this state can be reproduced within a few seconds just by

- (A) Initializing the device

- (B) setting up advertisement data and then

- (C) enabling advertisements in a loop (see attached file bttest.c)

- (D) concurrently connect and disconnect from a remote machine:

while true; do sudo hcitool lecc B0:91:22:BC:C2:17; sudo hcitool ledc 3585; done

The remote connect loop (D) starts at
22077    6    11:51:06.708

bttest.zip

#include <errno.h>
#include <signal.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/ioctl.h>
#include <sys/prctl.h>
#include <unistd.h>
#include <time.h>
#include <stdbool.h>

#include <bluetooth/bluetooth.h>
#include <bluetooth/hci.h>
#include <bluetooth/hci_lib.h>

//#include "utility.h"

static volatile int lastSignal = 0;

static void signalHandler(int signal) {
  lastSignal = signal;
}

int hci_le_set_advertising_data(int dd, uint8_t* data, uint8_t length, int to)
{
  struct hci_request rq;
  le_set_advertising_data_cp data_cp;
  uint8_t status;

  memset(&data_cp, 0, sizeof(data_cp));
  data_cp.length = length <= sizeof(data_cp.data) ? length : sizeof(data_cp.data);
  memcpy(&data_cp.data, data, data_cp.length);

  memset(&rq, 0, sizeof(rq));
  rq.ogf = OGF_LE_CTL;
  rq.ocf = OCF_LE_SET_ADVERTISING_DATA;
  rq.cparam = &data_cp;
  rq.clen = LE_SET_ADVERTISING_DATA_CP_SIZE;
  rq.rparam = &status;
  rq.rlen = 1;

  if (hci_send_req(dd, &rq, to) < 0)
    return -1;

  if (status) {
    errno = EIO;
    return -1;
  }

  return 0;
}

int hci_le_set_scan_response_data(int dd, uint8_t* data, uint8_t length, int to)
{
  struct hci_request rq;
  le_set_scan_response_data_cp data_cp;
  uint8_t status;

  memset(&data_cp, 0, sizeof(data_cp));
  data_cp.length = length <= sizeof(data_cp.data) ? length : sizeof(data_cp.data);
  memcpy(&data_cp.data, data, data_cp.length);

  memset(&rq, 0, sizeof(rq));
  rq.ogf = OGF_LE_CTL;
  rq.ocf = OCF_LE_SET_SCAN_RESPONSE_DATA;
  rq.cparam = &data_cp;
  rq.clen = LE_SET_SCAN_RESPONSE_DATA_CP_SIZE;
  rq.rparam = &status;
  rq.rlen = 1;

  if (hci_send_req(dd, &rq, to) < 0)
    return -1;

  if (status) {
    errno = EIO;
    return -1;
  }

  return 0;
}

// Set advertising interval to 100 ms
// Note: 0x00A0 * 0.625ms = 100ms
int hci_le_set_advertising_parameters(int dd, int to, int interval)
{
  struct hci_request rq;
  le_set_advertising_parameters_cp adv_params_cp;
  uint8_t status;

  memset(&adv_params_cp, 0, sizeof(adv_params_cp));
  adv_params_cp.min_interval = htobs(interval);
  adv_params_cp.max_interval = htobs(interval);
  adv_params_cp.chan_map = 7;

  memset(&rq, 0, sizeof(rq));
  rq.ogf = OGF_LE_CTL;
  rq.ocf = OCF_LE_SET_ADVERTISING_PARAMETERS;
  rq.cparam = &adv_params_cp;
  rq.clen = LE_SET_ADVERTISING_PARAMETERS_CP_SIZE;
  rq.rparam = &status;
  rq.rlen = 1;

  if (hci_send_req(dd, &rq, to) < 0)
    return -1;

  if (status) {
    errno = EIO;
    return -1;
  }

  return 0;
}

int main(int argc, const char* argv[])
{
  char *hciDeviceIdOverride = NULL;
  int hciDeviceId = 0;
  int hciSocket;
  struct hci_dev_info hciDevInfo;
  char address[18];

  int previousAdapterState = -1;
  int currentAdapterState;
  const char* adapterState = NULL;

  fd_set rfds;
  struct timeval tv;
  int selectRetval;

  char stdinBuf[256 * 2 + 1];
  char advertisementDataBuf[256];
  int advertisementDataLen = 0;
  char scanDataBuf[256];
  int scanDataLen = 0;
  int len;
  int i;

  memset(&hciDevInfo, 0x00, sizeof(hciDevInfo));

  hciDeviceIdOverride = getenv("BLENO_HCI_DEVICE_ID");
  if (hciDeviceIdOverride != NULL) {
    hciDeviceId = atoi(hciDeviceIdOverride);
  } else {
    // if no env variable given, use the first available device
    hciDeviceId = hci_get_route(NULL);
  }

  if (hciDeviceId < 0) {
    hciDeviceId = 0; // use device 0, if device id is invalid
  }

  // setup HCI socket
  hciSocket = hci_open_dev(hciDeviceId);
  hciDevInfo.dev_id = hciDeviceId;

  if (hciSocket == -1) {
    printf("adapterState unsupported\n");
    return -1;
  }

  // setup signal handlers
  signal(SIGINT, signalHandler);

    // set scan data
    hci_le_set_scan_response_data(hciSocket, (uint8_t*)&scanDataBuf, scanDataLen, 1000);

    // set advertisement data
    hci_le_set_advertising_data(hciSocket, (uint8_t*)&advertisementDataBuf, advertisementDataLen, 1000);

    // set advertisement parameters, mostly to set the advertising interval to 100ms
    hci_le_set_advertising_parameters(hciSocket, 1000, 0xA0);

  while(lastSignal == 0)
  {    
    // start advertising
    hci_le_set_advertise_enable(hciSocket, 1, 1000);

    usleep (100000);
  }

  // stop advertising
  hci_le_set_advertise_enable(hciSocket, 0, 1000);


  close(hciSocket);

  return 0;
}

  • I recorded a log using the instructions on http://processors.wiki.ti.com/index.php/CC256x_Logger_User_Guide

    It actually may be similar to https://e2e.ti.com/support/wireless-connectivity/bluetooth/f/538/p/615843/2268180.

    From the logs I suspect there is a race condition between the explicit enabling of advertisements and the disabling of avertisements triggered by connect but also visible in the logs is a assymetry between connect and disconnect event reported.

    I've been using TI Linux 3.14 kernel and bluez 4.101 but by now I doubt that this is BT stack related.

    Device Initialization (A) starts at

    21589    2    11:50:11.557

    The Setup and enabling of Advertisements (B+C)  starts at 

    21941    2    11:51:05.853

    The remote connect loop (D) starts at
    22077    6    11:51:06.708

  • Bastian,

    The attached BT firmware logs (test1.lgr) do not have the complete capture. Like explained in the User's guide linked above, please make sure that the complete logs from both BT Logger 1 and HCI/LMP viewer 1 ports of the logger are captured.

    The connection is being terminated right after it is being established. When a new connection is established, the advertisement is expected to stop. But the incomplete capture is not much useful in understanding the reason for the disconnect at 22327.

    Best regards,

    Vihang

  • Hi Vihang,

    sorry about that. I re-recorded the log with correct settings and verified that the conditions captured are very similar to the previous one (it just took a little longer).

    Best Regards,

    Bastian

    bttest2.zip

  • Hi Vihang,

    can I help you in any way with this issue? I'm currently working around this by performing a hci reset and a complete reinitialization (except firmware loading) after every BLE disconnect.

    I'd like to hear from you.

    Best regards,

    Bastian

  • Bastian,

    Sorry it took a while to analyse the logs. Please see my comments below.

    From the logs:

    • #237715 and #237717 - the scan response data and advertise data are set to NULL (data length of 0x00). Not sure if all scanners would be able to see the advertisement packets with data set to null. 
    • #237719 - the max and min advertising interval are set to 100ms (0x00a0).
    • #237721 - the host enables the advertisements by sending the HCI_LE_Write_Advertise_Enable command. However, the host keeps sending this command every 100ms.

    This repetition is unnecessary, and in this case counter productive. Normally, these repeated HCI_LE_Write_Advertise_Enable commands are rejected by the controller (e.g. #237754 in the logs), if the advertisement is already enabled. However, these repeated commands might be causing some race condition that results in the unreliable behavior that you are observing. 

    Please let us know exactly what is your use-case. Are you intentionally trying to send repeated HCI_LE_Write_Advertise_Enable command in your implementation? If yes, why?

    Best regards,

    Vihang

  • Vihang,

    thanks for having a look into this. I'll try to answer you questions.

    || Please let us know exactly what is your use-case

    Our high level use case is to have a linux based BLE peripheral that is connectable by Android or Iphones (just one at a time)

    I tried to generate a minimal setup to reproduce a condition where in rare cases the BLE advertisement is not enabled after a BLE disconnect.

    The original fault happened at a customer setup in field, but just a few times. BLE scanning with a smartphone at that time showed that the advertisements were actually not on the air.

    My colleagues were able to reproduce it in a lab setup to occur about once a day by continuously connecting, transmitting some data and disconnecting. hci logging (on the CPU) indicated that the command to enable advertisements was actually sent to the BT module and got a positive response.

    In order to analyze this better and finally report it to you, I tried to create a setup in which this is easier and faster to reproduce. I created the setup described in the first post and recorded the debug logs from the BT module.

    || Are you intentionally trying to send repeated HCI_LE_Write_Advertise_Enable command in your implementation? If yes, why?

    As said above - in order to reproduce the condition when the BT module actually responds that it enables advertising but nothing happens on the air. My hypothesis is that this is what actually happened in the customer's place and in my colleague's setup, but just less often. In production the HCI_LE_Write_Advertise_Enable command is only sent three times after a BLE disconnect (enable, disable, enable, which is redundant but I wasn't aware that this actually happened until then).

    || #237715 and #237717 - the scan response data and advertise data are set to NULL (data length of 0x00). Not sure if all scanners would be able to see the advertisement packets with data set to null.

    I verified this. The advertisements were seen initially by the scanner until they stopped. I did just care about the MAC address in the advertisements.

    So what I'm supposed to do is to find a way to stop this from happening at our customer.

    So I'm offering you a way to reproduce this behavior by yourself and trying to convince you that is a problem that also occurs in reality and not only in artificial lab conditions.

    And finally I'd like to have some help to find a quick (to implement) way to reliably work around this. I already had some ideas:

    • Enable the BLE Advertisements only *once* after a BLE disconnect
    • Enable the BLE Advertisements only *once* after a BLE disconnect after a certain delay (e.g. 0.5s)
    • Perform a HW reset and reload the entire bluetooth stack and firmware after every BLE disconnect. (takes a few seconds)
    • Perform a HCI reset  and re-initialization of the BT stack after every BLE disconnect
    • Periodically to one of the above if no BLE connection is present
    • Trying to get an indication that advertisements are not being transmitted by looking for patterns in the responses of HCI commands that report the module's state
    • Trying to scan for own advertisements (either not possible physically or filtered out by the BT firmware/BT spec)

    Best regards,

    Bastian

  • Hi Bastian,

    Thanks for adding clarification about the logs.

    Bastian Schmitz said:

    So what I'm supposed to do is to find a way to stop this from happening at our customer.

    So I'm offering you a way to reproduce this behavior by yourself and trying to convince you that is a problem that also occurs in reality and not only in artificial lab conditions.

    I agree with the goal that we must be able to reproduce this issue locally in order to further debug. However, I have doubts about the current test method. If the issue indeed occurs in the field without unnecessary HCI_LE_Write_Advertise_Enable commands, it makes more sense to reproduce this scenario without changing the use-case from the controller's perspective (i.e. constantly pinging the controller with unnecessary HCI_LE_Write_Advertise_Enable commands).

    One more suggestion about this setup: Can the same condition be reproduced in your current minimal setup if a valid advertisement data (for advertisement length greater than 0 and non-null advertisement data)?

    Bastian Schmitz said:

    I already had some ideas:

    • Enable the BLE Advertisements only *once* after a BLE disconnect
    • Enable the BLE Advertisements only *once* after a BLE disconnect after a certain delay (e.g. 0.5s)
    • Perform a HW reset and reload the entire bluetooth stack and firmware after every BLE disconnect. (takes a few seconds)
    • Perform a HCI reset  and re-initialization of the BT stack after every BLE disconnect
    • Periodically to one of the above if no BLE connection is present

    These all seem like great ideas. One more that you can add to a possible workaround is to disable just the BLE using the HCI_VS_LE_Enable (0xFD5B) command and download the BLE add-on (initscripts-TIInit_6.12.26_ble_add-on.bts) to enable the BLE. In addition to the HCI_Reset, this option may save you some reset time when the LE is enabled and disabled this way instead of a full re-initialization.

    Best regards,

    Vihang