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]

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!

[Sigurd]

Hi!

1) Could you print the return value of send_stream_notification() ?

2) Try also setting BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT to e.g. 30000

3) Could you capture a sniffer trace ? https://www.nordicsemi.com/Products/Development-tools/nrf-sniffer-for-bluetooth-le

[Sam-IIT]

Hi SIgurd,

1) The err value is actually always 0

2) I tried it also with 30000 and 40000 but had no effect.

3) I never did that, please allow me some time to learn it and test it! (I'll be back with possible results next week due to holidays)

Thanks a lot!

[Sam-IIT]

Hi Sigurd,

I mistakenly debugged the err value and it actually returns -12 (ENOMEM).
I'm trying the sniffer but I have issues on filtering through wireshark since I cannot see the UUID.

[Sam-IIT]

here's also the log of the captured stream.

the UUID of the characteristic used for streaming is (0xf26200f3, 0xbcb8, 0x4366, 0x9a9b, 0xa757edad68dc)

3617.capture.pcapng

I see holes in the actual stream too.

[Sam-IIT]

After searching around and testing different solutions, I still haven't found anything useful unfortunately.
I tested my worked and found out that can reach 25 ms stream (sill using a 16 element u16 array since this will be my actual output structure). below 25 ms the errors will start to arise. 

Any help would be much appreciated.

[Sigurd]

Hi!

At the start of the connection event, you as the peripheral have packets queued up, and the MD bit is set. But after a sending a few packets, the packet queue is empty, you don't have more data to send, and the connection event ends. Then you need to wait until the next connect event starts to send data. The connection interval is 45ms. Maybe you can try requesting a lower connection interval.

[Sam-IIT]

Hi Sigurd,

thank you for taking the time to go through the log. I tried editing the connection interval through code and that actually brought some improvements (min 7.5ms max 10ms)

bt_conn_le_param_update(current_conn, BT_LE_CONN_PARAM(6, 8, 0, 20));

which brings me to the question why editing CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT didn't gave me the same effect?

given this behavior I went through implementing a manual MTU negotiation right before updating the parameters above 

// full callback on connection

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);

        /* maximize ATT MTU at peer side (CONFIG_BT_L2CAP_TX_MTU)*/
	static struct bt_gatt_exchange_params exchange_params;
        exchange_params.func = exchange_func;

        LOG_INF("sending ATT MTU to peer..");
        int rc = bt_gatt_exchange_mtu(current_conn, &exchange_params);
        if (rc)
        {
                LOG_ERR("failed to negotiate maximum mtu with peer [%d]", rc);
        }

        bt_conn_le_param_update(current_conn, BT_LE_CONN_PARAM(6, 8, 0, 20));
        
        dk_set_led_on(CONN_STATUS_LED);
}

in combination with the following prj.conf, I managed to have a stable stream of 1khz for 32 bytes with a worker running at 15 ms

CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT=7500

CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_ATT_PREPARE_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=1024
CONFIG_BT_BUF_ACL_TX_SIZE=512
CONFIG_BT_BUF_ACL_RX_SIZE=512
CONFIG_BT_BUF_ACL_TX_COUNT=10
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_PHY_2M=y

But the question is the same as above, why didn't CONFIG_BT_L2CAP_TX_MTU allowed a higher MTU buffer? Also the negotiated MTU is 505, not 1024. 

Of course I managed this with a nrf52840 Dongle with the hci_usb project and the prj.conf edited to resemble the one of my project.