BLE stream communication LOG errs

[Sam-IIT]

Hi all,

I've been developing a BLE application on my laptop to communicate with the 52840. I manage to understand how to create and run a BLE connection through the really nice tutorial that has been posted a couple of years ago on youtube.
https://www.youtube.com/watch?v=hY_tDext6zA 

Maybe this is nothing or maybe I'm using the system wrong, but I created a specific characteristic for stream data. Whenever I activate it, my terminal gets flooded with the messages in the attached pic.

My question is, are those only related to the Loggin framework and I should not be (at a certain level) worried? is this an issue about streaming too fast? If the latter, maybe this BLE is not indicated for data streams?

thank you all

[EDIT]

some extra info that may be of use.
I am streaming data out from a worker that runs at 1ms and sends a single uint16 packet over a dedicated characteristic. This error occurs when I enable such stream. Writing/reading single characteristics with manual inputs (using the evk buttons) does not give any issues. Ideally I'd like to stream an array of 16 uint16 elements.

This is my current configuration file

CONFIG_GPIO=y
CONFIG_SPI=y
CONFIG_FPU=y
CONFIG_NEWLIB_LIBC=y
CONFIG_CBPRINTF_FP_SUPPORT=y

# Set CONFIG_NEWLIB_LIBC_FLOAT_PRINTF if printf should be able to print float
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y

# Enable DK LED and Buttons library
CONFIG_DK_LIBRARY=y

# Configure logger
CONFIG_LOG=y
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_USE_SEGGER_RTT=n
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_DEFAULT_LEVEL=3
CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=y

# Configure Bluetooth
CONFIG_BT=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="XYZ"
CONFIG_BT_DEVICE_APPEARANCE=0
CONFIG_BT_MAX_CONN=1
CONFIG_BT_LL_SOFTDEVICE=y

CONFIG_ASSERT=y

[Sigurd]

Hi!

You could try to increase some BLE related buffers.

CONFIG_BT_BUF_ACL_RX_SIZE=502
CONFIG_BT_ATT_PREPARE_COUNT=2
CONFIG_BT_ATT_TX_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=498
CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_CONN_TX_MAX=10
CONFIG_BT_BUF_ACL_TX_COUNT=10
CONFIG_BT_BUF_ACL_TX_SIZE=502

CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_PHY_2M=y

[Sam-IIT]

Hi Sigurd,

thanks for the reply. Unfortunately that had no effect, I still have missing data.

[Sigurd]

1) What SDK version are you using?

2) What BLE connection interval are you using?

I am streaming data out from a worker that runs at 1ms and sends a single uint16 packet

3) Just for testing, if you send it at e.g. 200ms instead, do you see the same issue then?

4) For the logs dropped, could you try to increase CONFIG_LOG_BUFFER_SIZE to e.g. 4096?

[Sam-IIT]

I'm using SDK 2.9. I even implemented the full array of 16 uin16_t to be streamed and I have no issues at 200ms. Even at 50ms works fine, but I am unable to reach 1ms.

Incrementing the log buffer didn't change anything in the output and the log prints report the same error.

How can I change the BLE connection interval? 

[Sam-IIT]

I found the setting CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT from other nRF samples.

Since I was not using it, it should have been set to the default of 7.5 ms. I tried to set it to its lower value (2500) but nothing changed.

 

[Sigurd]

Could you post some code snippets that shows how you send your data?

[Sam-IIT]

Hi Sigurd,

sorry for the late reply. Here are some snippets of my code.

prj.conf

CONFIG_GPIO=y
CONFIG_SPI=y
CONFIG_FPU=y
CONFIG_NEWLIB_LIBC=y
CONFIG_CBPRINTF_FP_SUPPORT=y

# Set CONFIG_NEWLIB_LIBC_FLOAT_PRINTF if printf should be able to print float
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y

# Enable DK LED and Buttons library
CONFIG_DK_LIBRARY=y

# Configure logger
CONFIG_LOG=y
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_USE_SEGGER_RTT=n
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_DEFAULT_LEVEL=3
CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BUFFER_SIZE=4096

# Configure Bluetooth
CONFIG_BT=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="XYZ"
CONFIG_BT_MAX_CONN=1
CONFIG_BT_LL_SOFTDEVICE=y
CONFIG_CAF_BLE_USE_LLPM=y

CONFIG_BT_SMP=y
CONFIG_BT_ATT_PREPARE_COUNT=2
CONFIG_BT_ATT_TX_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=498
CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_CONN_TX_MAX=10
CONFIG_BT_BUF_ACL_TX_COUNT=10
CONFIG_BT_BUF_ACL_TX_SIZE=502
CONFIG_BT_BUF_ACL_RX_SIZE=502

CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_PHY_2M=y

CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT=1000

The remote.c file that came with the webinar (edited to accommodate my "stream" characteristic). The send_stream_notification function is the one I use.

#include "comm/remote.h"

#define LOG_MODULE_NAME_REMOTE Remote_BLE
LOG_MODULE_REGISTER(LOG_MODULE_NAME_REMOTE);

/* Declarations */
static K_SEM_DEFINE(bt_init_ok, 1, 1);

#define DEVICE_NAME CONFIG_BT_DEVICE_NAME
#define DEVICE_NAME_LEN (sizeof(DEVICE_NAME) - 1)

static const struct bt_data ad[] = {
    BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
    BT_DATA(BT_DATA_NAME_COMPLETE, DEVICE_NAME, DEVICE_NAME_LEN)};

static const struct bt_data sd[] = {
    BT_DATA_BYTES(BT_DATA_UUID128_ALL, BT_UUID_REMOTE_SERV_VAL),
};

static uint8_t button_value = 0;
static u16_t stream_value[27];
enum bt_notifications_enabled notifications_enabled;
static struct bt_remote_service_cb remote_callbacks;

void on_sent(struct bt_conn *conn, void *user_data);
void on_stream(struct bt_conn *conn, void *user_data);

static ssize_t read_rhd_characteristic_cb(struct bt_conn *conn, const struct bt_gatt_attr *attr,
                                          void *buf, uint16_t len, uint16_t offset);

static ssize_t read_rhd_stream_characteristic_cb(struct bt_conn *conn, const struct bt_gatt_attr *attr,
                                                 void *buf, uint16_t len, uint16_t offset);

void button_chrc_ccc_cfg_changed(const struct bt_gatt_attr *attr, uint16_t value);

void stream_chrc_ccc_cfg_changed(const struct bt_gatt_attr *attr, uint16_t value);

static ssize_t on_write(struct bt_conn *conn, const struct bt_gatt_attr *attr, const void *buf, uint16_t len, uint16_t offset, uint8_t flags);

BT_GATT_SERVICE_DEFINE(rhxRemoteService,
                       BT_GATT_PRIMARY_SERVICE(BT_UUID_REMOTE_SERVICE),
                       BT_GATT_CHARACTERISTIC(BT_UUID_REMOTE_BUTTON_CHRC,
                                              BT_GATT_CHRC_READ | BT_GATT_CHRC_NOTIFY,
                                              BT_GATT_PERM_READ,
                                              read_rhd_characteristic_cb, NULL, NULL),
                       BT_GATT_CCC(button_chrc_ccc_cfg_changed, BT_GATT_PERM_READ | BT_GATT_PERM_WRITE),
                       BT_GATT_CHARACTERISTIC(BT_UUID_REMOTE_STREAM_CHRC,
                                              BT_GATT_CHRC_READ | BT_GATT_CHRC_NOTIFY,
                                              BT_GATT_PERM_READ,
                                              read_rhd_stream_characteristic_cb, NULL, NULL),
                       BT_GATT_CCC(stream_chrc_ccc_cfg_changed, BT_GATT_PERM_READ | BT_GATT_PERM_WRITE),
                       BT_GATT_CHARACTERISTIC(BT_UUID_REMOTE_MESSAGE_CHRC,
                                              BT_GATT_CHRC_WRITE_WITHOUT_RESP,
                                              BT_GATT_PERM_READ | BT_GATT_PERM_WRITE,
                                              NULL, on_write, NULL), );

/* Callbacks */

static ssize_t read_rhd_characteristic_cb(struct bt_conn *conn, const struct bt_gatt_attr *attr,
                                          void *buf, uint16_t len, uint16_t offset)
{
    return bt_gatt_attr_read(conn, attr, buf, len, offset, &button_value,
                             sizeof(button_value));
}

static ssize_t read_rhd_stream_characteristic_cb(struct bt_conn *conn, const struct bt_gatt_attr *attr,
                                                 void *buf, uint16_t len, uint16_t offset)
{
    return bt_gatt_attr_read(conn, attr, buf, len, offset, &stream_value,
                             sizeof(stream_value));
}

void button_chrc_ccc_cfg_changed(const struct bt_gatt_attr *attr, uint16_t value)
{
    bool notif_enabled = (value == BT_GATT_CCC_NOTIFY);
    LOG_INF("Notifications %s (button)", notif_enabled ? "enabled" : "disabled");

    notifications_enabled = notif_enabled ? BT_NOTIFICATIONS_ENABLED : BT_NOTIFICATIONS_DISABLED;
}

void stream_chrc_ccc_cfg_changed(const struct bt_gatt_attr *attr, uint16_t value)
{
    bool notif_enabled = (value == BT_GATT_CCC_NOTIFY);
    LOG_INF("Notifications %s (stream)", notif_enabled ? "enabled" : "disabled");

    notifications_enabled = notif_enabled ? BT_NOTIFICATIONS_ENABLED : BT_NOTIFICATIONS_DISABLED;
}

int send_button_notification(struct bt_conn *conn, uint8_t value)
{
    int err = 0;

    struct bt_gatt_notify_params params = {0};
    const struct bt_gatt_attr *attr = &rhxRemoteService.attrs[2];

    params.attr = attr;
    params.data = &value;
    params.len = 1;
    params.func = on_sent;

    err = bt_gatt_notify_cb(conn, &params);

    return err;
}

int send_stream_notification(struct bt_conn *conn, u16_t* value)
{
    int err = 0;

    struct bt_gatt_notify_params params = {0};
    const struct bt_gatt_attr *attr = &rhxRemoteService.attrs[4];

    params.attr = attr;
    params.data = value;
    params.len = sizeof(u16_t) * 16;
    params.func = on_stream;

    err = bt_gatt_notify_cb(conn, &params);

    return err;
}

static ssize_t on_write(struct bt_conn *conn,
                        const struct bt_gatt_attr *attr,
                        const void *buf,
                        uint16_t len,
                        uint16_t offset,
                        uint8_t flags)
{
    LOG_INF("Received data, handle %d, conn %p",
            attr->handle, (void *)conn);

    if (remote_callbacks.data_received)
    {
        remote_callbacks.data_received(conn, buf, len);
    }
    return len;
}

void on_sent(struct bt_conn *conn, void *user_data)
{
    ARG_UNUSED(user_data);
    LOG_INF("Notification sent on connection %p", (void *)conn);
}

void on_stream(struct bt_conn *conn, void *user_data)
{
    ARG_UNUSED(user_data);
    //LOG_INF("Notification sent on connection %p", (void *)conn); // uncomment for debugging. avoids flooding the log
}

void set_button_value(uint8_t btn_value)
{
    button_value = btn_value;
}

void set_stream_value(u16_t* str_value)
{
    for (int i = 0; i < 27; i++)
    {
        stream_value[i] = str_value[i];
    }
}

void bt_ready(int err)
{
    if (err)
    {
        LOG_ERR("bt_enable returned %d", err);
    }

    k_sem_give(&bt_init_ok);
}

/* Custom functions */

int bluetooth_init(struct bt_conn_cb *bt_cb, struct bt_remote_service_cb *remote_cb)
{
    LOG_INF("Initializing Bluetooth");

    if (bt_cb == NULL || remote_cb == NULL)
    {
        return -NRFX_ERROR_NULL;
    }
    bt_conn_cb_register(bt_cb);
    remote_callbacks.notif_changed = remote_cb->notif_changed;
    remote_callbacks.data_received = remote_cb->data_received;

    int err = bt_enable(bt_ready);
    if (err)
    {
        LOG_ERR("bt_enable returned %d", err);
        return err;
    }

    k_sem_take(&bt_init_ok, K_FOREVER);

    err = bt_le_adv_start(BT_LE_ADV_CONN, ad, ARRAY_SIZE(ad), sd, ARRAY_SIZE(sd));
    if (err)
    {
        LOG_ERR("couldn't start advertising (err = %d", err);
        return err;
    }

    return err;
}

bool STREAM = false;

void enableStream(void)
{
    STREAM = true;
}
void disableStream(void)
{
    STREAM = false;
}
bool isStreamEnabled(void)
{
    return STREAM;
}

and the main.c file where the worker is instantiated and calls the stream function

#include <zephyr/kernel.h>
#include <zephyr/sys/printk.h>
#include <zephyr/device.h>
#include <zephyr/devicetree.h>
#include <zephyr/drivers/gpio.h>
#include <zephyr/drivers/spi.h>
#include <zephyr/logging/log.h>
#include <dk_buttons_and_leds.h>
#include <math.h>

#include "hal/rhd2216.h"
#include "comm/remote.h"

#define LOG_MODULE_NAME_MAIN RHX_comm_main
LOG_MODULE_REGISTER(LOG_MODULE_NAME_MAIN);
#define RUN_STATUS_LED DK_LED1
#define CONN_STATUS_LED DK_LED2
#define RUN_LED_BLINK_INTERVAL 1000

/* Worker */


/*
 * cb function define
 */
// timer cb
// using round-robin fashion ,a timer callback to sample all needed channels
void RHD_handler(struct k_work *work)
{
        u16_t RAMP[16];
        uint64_t stamp;
        stamp = k_uptime_get_32();

        static u16_t count = 0;
        for(u16_t i = 0; i < 16; i++)
        {
                RAMP[i] = count;
        }

        count = (count + 1) % 1000;

        if (isStreamEnabled())
        {

                int err = send_stream_notification(current_conn, RAMP);
                if (err)
                {
                        // LOG_ERR("couldn't send notification (err: %d)", err);
                }
                

        }
}


/* Declarations */

void on_connected(struct bt_conn *conn, uint8_t err);
void on_disconnected(struct bt_conn *conn, uint8_t reason);
void on_notif_changed(enum bt_notifications_enabled status);
void on_data_received(struct bt_conn *conn, const uint8_t *const data, uint16_t len);

static struct bt_conn *current_conn;

struct bt_conn_cb bluetooth_callbacks = {
    .connected = on_connected,
    .disconnected = on_disconnected,
};

struct bt_remote_service_cb remote_callbacks = {
    .notif_changed = on_notif_changed,
    .data_received = on_data_received,
};

/* Callbacks */

void on_data_received(struct bt_conn *conn, const uint8_t *const data, uint16_t len)
{
        uint8_t temp_str[len + 1];
        memcpy(temp_str, data, len);
        temp_str[len] = 0x00;

        LOG_INF("Received data on conn %p. Len: %d", (void *)conn, len);
        LOG_INF("Data: %s", temp_str);
}

void on_notif_changed(enum bt_notifications_enabled status)
{
        if (status == BT_NOTIFICATIONS_ENABLED)
        {
                LOG_INF("Notifications enabled");
        }
        else
        {
                LOG_INF("Notificatons disabled");
        }
}

void on_connected(struct bt_conn *conn, uint8_t err)
{
        if (err)
        {
                LOG_ERR("connection err: %d", err);
                return;
        }
        LOG_INF("Connected.");
        current_conn = bt_conn_ref(conn);
        dk_set_led_on(CONN_STATUS_LED);
}

void on_disconnected(struct bt_conn *conn, uint8_t reason)
{
        LOG_INF("Disconnected (reason: %d)", reason);
        dk_set_led_off(CONN_STATUS_LED);
        if (current_conn)
        {
                bt_conn_unref(current_conn);
                current_conn = NULL;
        }
}

void button_handler(uint32_t button_state, uint32_t has_changed)
{
        int button_pressed = 0;
        if (has_changed & button_state)
        {
                switch (has_changed)
                {
                case DK_BTN1_MSK:
                        button_pressed = 1;
                        enableStream();
                        break;
                case DK_BTN2_MSK:
                        button_pressed = 2;
                        disableStream();
                        break;
                case DK_BTN3_MSK:
                        button_pressed = 3;
                        disableStream();
                        break;
                case DK_BTN4_MSK:
                        button_pressed = 4;
                        disableStream();
                        break;
                default:
                        break;
                }
                LOG_INF("Button %d pressed.", button_pressed);
                set_button_value(button_pressed);
                int err = send_button_notification(current_conn, button_pressed);
                if (err)
                {
                        LOG_ERR("couldn't send notification (err: %d)", err);
                }
        }
}

// timer
struct k_timer RHD_timer;

// LED Blinky
static const struct gpio_dt_spec LED_dev = GPIO_DT_SPEC_GET(LED0_NODE, gpios);
bool led_is_on = true;
int ret_LED;

/*
 * function define
 */

// timer function
K_WORK_DEFINE(work_rhd, RHD_handler); // define RHD_handler as my_work
void rhd_timer_handler(struct k_timer *dummy)
{
        k_work_submit(&work_rhd);
}

static void configure_dk_buttons_leds(void)
{
        int err;

        err = dk_buttons_init(button_handler);
        if (err)
        {
                LOG_ERR("Cannot init buttons (err: %d)", err);
        }
        err = dk_leds_init();
        if (err)
        {
                LOG_ERR("Cannot init LEDs (err: %d)", err);
        }
}

/*
 * main function loop
 */
int main(void)
{

        k_msleep(1000);

        /*
         * setup
         */
        // Buttons sdk EVK
        configure_dk_buttons_leds();

        int err = bluetooth_init(&bluetooth_callbacks, &remote_callbacks);
        if (err)
        {
                LOG_ERR("bt_enable returned %d", err);
                goto _error;
        }

        // timer
        k_timer_init(&RHD_timer, rhd_timer_handler, NULL); // init timer

        // Extract the device driver implementation
        LOG_INF("Extract the device driver implementation");
        if (!gpio_is_ready_dt(&LED_dev))
        {
                LOG_ERR("Issue on device_get_binding\n");
                goto _error;
        }

        // Configure the GPIO pin
        LOG_INF("Configure the GPIO pin");
        err = gpio_pin_configure_dt(&LED_dev, GPIO_OUTPUT_ACTIVE);
        if (err < 0)
        {
                LOG_ERR("Issue on gpio_pin_configure %d", err);
                goto _error;
        }

        // RHD
        LOG_INF("RHD2216_init");
        err = RHD2216_init();
        if (err)
        {
                LOG_ERR("RHD2216 init fail %d", err);
        }
        else
        {
                RHD2216_set_bt_current_conn(current_conn);
                err = RHD2216_start_convert();
                if (err)
                {
                        LOG_ERR("RHD2216 start convert failed %d", err);
                }
                else
                {
                        /* start periodic timer that expires once at 1kHz */
                        k_timer_start(&RHD_timer, K_SECONDS(3), K_MSEC(1)); // first param is timer duration(initial timer duration)
                }
        }

        bool led_state = true;

        while (true)
        {
                int ret = gpio_pin_toggle_dt(&LED_dev);
                if (ret < 0)
                {
                        return 0;
                }

                led_state = !led_state;

                // printf("LED state: %s\n", led_state ? "ON" : "OFF");
                k_msleep(1);
                // printk("This is main loop! \n");
        }

        return 0;
}

Right now the worker just send a 16 uint16_t vector of incrementing values (0-1000) every 1ms. 

On the other side I have a GUI implemented with pyside6 (python-Qt) that uses the onboard bt adapter of my laptop (Bluetooth 5.2). I did a quick experiment by using the nRF52840-Dongle (hci-usb sample project flashed) as adapter but had no improvements.

Thanks again for you time!