Advertising failed to start (err -120)

[dlewis]

I am running into an issue (title), where I am attempting to switch the advertising interval to a slower interval after a set period of advertising in order to save power. Advertising is being successfully started the first time, I then start a timer. In the timer expiration handler, I call bt_le_adv_stop(), and then initialize advertising again, this time with a different set of min and max intervals. The second time around, bt_le_adv_start() returns -120 (EALREADY). I have tried adding a delay in between the stop and start functions in case it takes longer than expected for advertising to stop, but this did not change the outcome. Also, bt_le_adv_stop() is returning 0 which I believes implies the action was successful. Any help would be appreciated, thanks!

I am using:
NCS v2.6
nRF52832

[Edvin]

Hello,

Is the behavior consistent, meaning does the EALREADY return every time you test this (the second time you try to start advertising)? Or only from time to time?

I suspect it has to do with scheduling. From where do you call advertising stop and advertising start? Is it possible to upload the application so that I can build it and run it on an nRF52832 DK?

Best regards,

Edvin

[dlewis]

Below is the project and board files. The board file has been modified to work with nrf52dk. 
RES-BPB-TEST.zip
6505.centurion_anywhere_button.zip

[dlewis]

Attached below is a zip of the ble lbs example with my ported problematic code. A fault still occurs at a similar spot as with my custom project, but the error is different in this case.
The print output looks as follows:

Advertising Started
slow_adv_timer EXPIRED
ASSERTION FAIL @ WEST_TOPDIR/zephyr/kernel/sem.c:136
E: r0/a1: 0x00000004 r1/a2: 0x00000088 r2/a3: 0x00000001
E: r3/a4: 0x0001be65 r12/ip: 0x00000000 r14/lr: 0x000202f7
E: xpsr: 0x61000021
E: Faulting instruction address (r15/pc): 0x00023a7c
E: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
E: Fault during interrupt handling

E: Current thread: 0x20002558 (unknown)

This time, instruction address 0x000023a7c correlates to assert_post_action() as opposed to sys_dlist_remove() from my custom project. 

ble_adv_bug_test.zip

[dlewis]

Hi, do you have any updates on your end? I have been trying to debug on my end over the last week and still have not made any progress. 

[Edvin]

Hello,

I am terribly sorry for the late reply. I had to work on some non-DevZone related things the last week and a half. I tried to run through my tickets today, but I wasn't able to cover them all. I promise I will give your application another look tomorrow. 

I am sorry for the inconvenience.

Best regards,
Edvin

[Edvin]

Hello,

So I managed to reproduce the issue you were seeing on the ble_adv_bug_test.zip:

Please try the attached app_ble.c:

Fullscreen app_ble.c Download

#include <zephyr/types.h>
#include <stddef.h>
#include <string.h>
#include <errno.h>
#include <zephyr/sys/util.h>	//added from button sample
#include <zephyr/sys/printk.h>
#include <zephyr/sys/byteorder.h>
#include <zephyr/kernel.h>
#include <zephyr/device.h>	//added from button sample
#include <zephyr/devicetree.h>
#include <zephyr/drivers/gpio.h>
#include <soc.h>
#include <inttypes.h> //added from button sample

#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/hci.h>
#include <zephyr/bluetooth/conn.h>
#include <zephyr/bluetooth/uuid.h>
#include <zephyr/bluetooth/gatt.h>

#include <zephyr/bluetooth/services/bas.h>
#include <zephyr/settings/settings.h>
#include <zephyr/logging/log.h>

// #include "cab_emergency.h"
// #include "cab_ble_service.h"
// #include "genkey.h" 
#include "app_ble.h"

LOG_MODULE_DECLARE(APP_BLE);

#define SLOW_ADV_STACK_SIZE 4096
#define SLOW_ADV_THREAD_PRIORITY 8
K_THREAD_STACK_DEFINE(slow_adv_thread_stack, SLOW_ADV_STACK_SIZE);
struct k_thread slow_adv_thread_data;

#define DEVICE_NAME             CONFIG_BT_DEVICE_NAME
#define DEVICE_NAME_LEN         (sizeof(DEVICE_NAME) - 1)
#define DEVICE_NAME_DYNAMIC_MAX 8
// #define MY_MTU_SIZE		247
static bool is_connected = false;

// static struct bt_data ad[]; 
static uint8_t custom_adv_info[ADV_CUSTOM_INFO_SIZE];
struct bt_conn *my_connection;

//Fast and Slow ADV params 
static const struct bt_le_adv_param fast_adv_param = {
    .options = BT_LE_ADV_OPT_CONNECTABLE,
    .interval_min = 750,  // Fast advertising interval min (500 ms)
    .interval_max = 850,  // Fast advertising interval max (500 ms)
};

static const struct bt_le_adv_param slow_adv_param = {
    .options = BT_LE_ADV_OPT_CONNECTABLE,
    .interval_min = 3150,  // Slow advertising interval min (2000 ms)
    .interval_max = 3250,  // Slow advertising interval max (2000 ms)
};

#define BT_LE_ADV_CONN_CUSTOM_FAST \
    BT_LE_ADV_PARAM(BT_LE_ADV_OPT_CONNECTABLE, \
                    750, \
                    850, \
                    NULL)

#define BT_LE_ADV_CONN_CUSTOM_SLOW \
    BT_LE_ADV_PARAM(BT_LE_ADV_OPT_CONNECTABLE, \
                    3150, \
                    3250, \
                    NULL)


static void mtu_exchange_cb(struct bt_conn *conn, uint8_t err, struct bt_gatt_exchange_params *params)
{
    if (err) {
        printk("MTU exchange failed (err %d)\n", err);
    } else {
        uint16_t mtu = bt_gatt_get_mtu(conn);
        printk("MTU exchange successful, new MTU: %d\n", mtu);
    }
}

static struct bt_gatt_exchange_params mtu_params;

static void set_connection_params(struct bt_conn *conn)
{
    struct bt_le_conn_param conn_params = {
        .interval_min = 330, // Minimum connection interval in 1.25 ms units
        .interval_max = 360, // Maximum connection interval in 1.25 ms units
        .latency = 3, // Connection latency
        .timeout = 600 // Supervision timeout in 10 ms units
    };

    int err = bt_conn_le_param_update(conn, &conn_params);
    if (err) {
        printk("Failed to update connection parameters (err %d)\n", err);
    } else {
        printk("Connection parameters update requested\n");
    }
}


static void connected(struct bt_conn *conn, uint8_t err)
{
    if (err) {
        printk("Connection failed (err %u)\n", err);
        return;
    }

    my_connection = conn;

    printk("Connected\n");
    is_connected = true;

    set_connection_params(conn);

    // Set up MTU exchange parameters
    mtu_params.func = mtu_exchange_cb;

    // Initiate MTU exchange
    int mtu_err = bt_gatt_exchange_mtu(conn, &mtu_params);
    if (mtu_err) {
        printk("MTU exchange initiation failed (err %d)\n", mtu_err);
    } else {
        printk("MTU exchange initiated\n");
    }
}

static void disconnected(struct bt_conn *conn, uint8_t reason)
{
	printk("Disconnected (reason %u)\n", reason);
    is_connected = false;
	// dk_set_led_off(CON_STATUS_LED);
}

// #ifdef CONFIG_BT_LBS_SECURITY_ENABLED
// static void security_changed(struct bt_conn *conn, bt_security_t level,
// 			     enum bt_security_err err)
// {
// 	char addr[BT_ADDR_LE_STR_LEN];

// 	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

// 	if (!err) {
// 		printk("Security changed: %s level %u\n", addr, level);
// 	} else {
// 		printk("Security failed: %s level %u err %d\n", addr, level,
// 			err);
// 	}
// }
// #endif

BT_CONN_CB_DEFINE(conn_callbacks) = {
	.connected        = connected,
	.disconnected     = disconnected,
// #ifdef CONFIG_BT_LBS_SECURITY_ENABLED
// 	.security_changed = security_changed,
// #endif
};

#if defined(CONFIG_BT_LBS_SECURITY_ENABLED)
static void auth_passkey_display(struct bt_conn *conn, unsigned int passkey)
{
	char addr[BT_ADDR_LE_STR_LEN];

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	printk("Passkey for %s: %06u\n", addr, passkey);
}

static void auth_cancel(struct bt_conn *conn)
{
	char addr[BT_ADDR_LE_STR_LEN];

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	printk("Pairing cancelled: %s\n", addr);
}

static void pairing_complete(struct bt_conn *conn, bool bonded)
{
	char addr[BT_ADDR_LE_STR_LEN];

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	printk("Pairing completed: %s, bonded: %d\n", addr, bonded);
}

static void pairing_failed(struct bt_conn *conn, enum bt_security_err reason)
{
	char addr[BT_ADDR_LE_STR_LEN];

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	printk("Pairing failed conn: %s, reason %d\n", addr, reason);
}

static struct bt_conn_auth_cb conn_auth_callbacks = {
	.passkey_display = auth_passkey_display,
	.cancel = auth_cancel,
};

static struct bt_conn_auth_info_cb conn_auth_info_callbacks = {
	.pairing_complete = pairing_complete,
	.pairing_failed = pairing_failed
};
#else
static struct bt_conn_auth_cb conn_auth_callbacks;
static struct bt_conn_auth_info_cb conn_auth_info_callbacks;
#endif

static void get_mac_address(uint8_t *mac_addr)
{
    size_t count = 1;  // Number of addresses to get
    bt_addr_le_t addrs[1]; // Array to hold the address

    // Get the identity address
    bt_id_get(addrs, &count);

    // Check if an address was retrieved
    if (count > 0) {
        memcpy(mac_addr, addrs[0].a.val, 6);  // Copy the MAC address
        printk("MAC Address: %02X:%02X:%02X:%02X:%02X:%02X\n",
                mac_addr[5], mac_addr[4], mac_addr[3],
                mac_addr[2], mac_addr[1], mac_addr[0]);
    } else {
        printk("Failed to get MAC address\n");
    }
}

void populate_custom_adv_info(void)
{
    bool emergency_state = true;
    // Populate Company Identifier
    custom_adv_info[ADV_COMPANY_ID_0] = (uint8_t)ADV_COMPANY_ID;  
    custom_adv_info[ADV_COMPANY_ID_1] = (uint8_t)(ADV_COMPANY_ID >> 8);  

    // Populate App Version and Header Version
    custom_adv_info[ADV_APP_VER_3_AND_HEADER] = (TEST_APP_VERSION >> 24) & 0xFF;    // FV
    custom_adv_info[ADV_APP_VER_3_AND_HEADER] = (custom_adv_info[ADV_APP_VER_3_AND_HEADER] & 0xF0) | (HEADER_VERSION & 0x0F); // Add Header Version

    custom_adv_info[ADV_APP_VER_2] = (TEST_APP_VERSION >> 16) & 0xFF; // FF
    custom_adv_info[ADV_APP_VER_1] = (TEST_APP_VERSION >> 8) & 0xFF;  // FF
    
    custom_adv_info[ADV_APP_VER_0_AND_SENKIND] = (TEST_APP_VERSION & 0xFF); // FK
    custom_adv_info[ADV_APP_VER_0_AND_SENKIND] = (custom_adv_info[ADV_APP_VER_0_AND_SENKIND] & 0xF0) | (SENKIND & 0x0F); // Add Sensor Kind

    // Populate Emergency and Battery
    custom_adv_info[ADV_EMERGENCY] = (uint8_t)emergency_state;
    custom_adv_info[ADV_BATTERY] = TEST_BATTERY_ADV & 0xFF;

    // Populate Public Key CRC
    if(emergency_state)
    {
        uint32_t pubkey_crc = 0x12345678;
        custom_adv_info[ADV_PUBLIC_KEY_3] = (pubkey_crc >> 24) & 0xFF;
        custom_adv_info[ADV_PUBLIC_KEY_2] = (pubkey_crc >> 16) & 0xFF;
        custom_adv_info[ADV_PUBLIC_KEY_1] = (pubkey_crc >> 8) & 0xFF;
        custom_adv_info[ADV_PUBLIC_KEY_0] = (pubkey_crc) & 0xFF;
    }else{
        custom_adv_info[ADV_PUBLIC_KEY_3] = 0x00;
        custom_adv_info[ADV_PUBLIC_KEY_2] = 0x00;
        custom_adv_info[ADV_PUBLIC_KEY_1] = 0x00;
        custom_adv_info[ADV_PUBLIC_KEY_0] = 0x00;
    }
    
    printk("Custom Advertising Info: ");
    for (size_t i = 0; i < sizeof(custom_adv_info); i++) {
        printk("%02X ", custom_adv_info[i]);
    }
    printk("\n");
}

int advertising_init(struct bt_le_adv_param *param_to_use)
{
    uint8_t mac_addr[6];
    get_mac_address(mac_addr);

    // Allocate memory for the device name
    char device_name[DEVICE_NAME_DYNAMIC_MAX + 1];
    
    // Format the device name as "AnyXXYY" where XXYY are the last two bytes of the MAC address
    snprintf(device_name, sizeof(device_name), "Any%02X%02X", mac_addr[1], mac_addr[0]);

    // Set the device name
    int err = bt_set_name(device_name);
    if (err) {
        printk("Failed to set device name (err %d)\n", err);
    } else {
        printk("Device name set to: %s\n", device_name);
    }

	populate_custom_adv_info();

    // struct bt_le_ext_adv *adv;
    // struct bt_le_adv_param param = {
    //     .options = BT_LE_ADV_OPT_EXT_ADV | BT_LE_ADV_OPT_CONNECTABLE,
    //     .interval_min = 0x0020,
    //     .interval_max = 0x0040,
    //     .peer = NULL,
    //     .sid = 0,
    // };

    //Define UUIDs as arrays of bytes
    uint8_t dis_uuid[] = { (BT_UUID_DIS_VAL >> 8) & 0xFF, BT_UUID_DIS_VAL & 0xFF };
    uint8_t bas_uuid[] = { (BT_UUID_BAS_VAL >> 8) & 0xFF, BT_UUID_BAS_VAL & 0xFF };
    uint8_t custom_service_uuid[] = {0x2c, 0x38, 0x37, 0x3c, 0x8a, 0x24, 0x7a, 0xa5, 0x55, 0x4a, 0xdd, 0x3e, 0x01, 0x00, 0x2e, 0x4d};



    struct bt_data ad[] = {
        BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
        BT_DATA(BT_DATA_MANUFACTURER_DATA, custom_adv_info, sizeof(custom_adv_info)),
        BT_DATA(BT_DATA_NAME_COMPLETE, device_name, DEVICE_NAME_DYNAMIC_MAX),
    };

    // struct bt_data ad[] = {
    //     BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
    //     BT_DATA(BT_DATA_MANUFACTURER_DATA, custom_adv_info, sizeof(custom_adv_info)),
    //     BT_DATA(BT_DATA_NAME_COMPLETE, device_name, DEVICE_NAME_DYNAMIC_MAX),
    //     BT_DATA(BT_DATA_UUID16_ALL, BT_UUID_DIS_VAL, sizeof(BT_UUID_DIS_VAL)),
    //     BT_DATA(BT_DATA_UUID16_ALL, BT_UUID_BAS_VAL, sizeof(BT_UUID_BAS_VAL)),
    //     BT_DATA(BT_DATA_UUID128_ALL, BT_UUID_CAB, sizeof(BT_UUID_CAB))
    // };

    struct bt_data sd[] = {
        // BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
        // BT_DATA(BT_DATA_MANUFACTURER_DATA, custom_adv_info, sizeof(custom_adv_info)),
        // BT_DATA(BT_DATA_NAME_COMPLETE, device_name, DEVICE_NAME_DYNAMIC_MAX)/*,
        BT_DATA(BT_DATA_UUID16_ALL, dis_uuid, sizeof(dis_uuid)),
        BT_DATA(BT_DATA_UUID16_ALL, bas_uuid, sizeof(bas_uuid)),
        BT_DATA(BT_DATA_UUID128_ALL, custom_service_uuid, sizeof(custom_service_uuid))
    };

    // //EXTENDED ADVERTISING INIT
    // err = bt_le_ext_adv_create(&param, NULL, &adv);
    // if (err) {
    //     printk("Failed to create extended advertising set (err %d)\n", err);
    //     return 0;
    // }

    // err = bt_le_ext_adv_set_data(adv, ad, ARRAY_SIZE(ad), sd, ARRAY_SIZE(sd));
    // if (err) {
    //     printk("Failed to set extended advertising data (err %d)\n", err);
    //     return 0;
    // }

    // err = bt_le_ext_adv_start(adv, BT_LE_EXT_ADV_START_DEFAULT);
    // if (err) {
    //     printk("Failed to start extended advertising (err %d)\n", err);
    //     return 0;
    // }
    // printk("Extended advertising started\n");

    //REGULAR ADVERTISING INIT
    err = bt_le_adv_start(param_to_use, ad, ARRAY_SIZE(ad),
			      sd, ARRAY_SIZE(sd));
	if (err) {
		printk("Advertising failed to start (err %d)\n", err);
		return 0;
	}
	printk("Advertising Started\n");

	return 1;
}

extern void slow_adv(void *p1, void *p2, void *p3)
{
    printk("SLOW ADV THREAD CALLED\n");
    if(!is_connected)
    {
        // k_sleep(K_MSEC(500));  // Adjust the delay as necessary
        advertising_init(BT_LE_ADV_CONN_CUSTOM_SLOW);
    }else{
        //do nothing
    }
}

static void slow_adv_timer_cancelled_handler(struct k_timer *dummy)
{
    printk("slow_adv_timer CANCELLED\n");
    //do nothing
}

void my_advertising_work_handler(struct k_work *work)
{
    // Do stuff here. 
    printk("slow_adv_timer EXPIRED \n");
    int err = bt_le_adv_stop();
    if (err) {
        printk("Failed to stop advertising (err %d)\n", err);
        return;
    }else{
        printk("Successfuly stopped advertising (err %d)\n", err);
    }

    if(!is_connected)
    {
        // k_sleep(K_MSEC(500));  // Adjust the delay as necessary
        advertising_init(BT_LE_ADV_CONN_CUSTOM_SLOW);
    }else{
        //do nothing
    }

    // k_tid_t tid = k_thread_create(&slow_adv_thread_stack, slow_adv_thread_stack, SLOW_ADV_STACK_SIZE,
    //                               slow_adv, NULL, NULL, NULL,
    //                               SLOW_ADV_THREAD_PRIORITY, 0, K_NO_WAIT);

    // if (tid == NULL) {
    //     printk("Failed to create thread\n");
    // } else {
    //     printk("Thread created with id %p, starting thread\n", tid);
    //     k_thread_start(tid);
	// }

}

K_WORK_DEFINE(my_advertising_work, my_advertising_work_handler);


static void slow_adv_timer_expired_handler(struct k_timer *dummy)
{
    k_work_submit(&my_advertising_work);
    // printk("slow_adv_timer EXPIRED \n");
    // int err = bt_le_adv_stop();
    // if (err) {
    //     printk("Failed to stop advertising (err %d)\n", err);
    //     return;
    // }else{
    //     printk("Successfuly stopped advertising (err %d)\n", err);
    // }

    // if(!is_connected)
    // {
    //     // k_sleep(K_MSEC(500));  // Adjust the delay as necessary
    //     advertising_init(BT_LE_ADV_CONN_CUSTOM_SLOW);
    // }else{
    //     //do nothing
    // }

    // // k_tid_t tid = k_thread_create(&slow_adv_thread_stack, slow_adv_thread_stack, SLOW_ADV_STACK_SIZE,
    // //                               slow_adv, NULL, NULL, NULL,
    // //                               SLOW_ADV_THREAD_PRIORITY, 0, K_NO_WAIT);

    // // if (tid == NULL) {
    // //     printk("Failed to create thread\n");
    // // } else {
    // //     printk("Thread created with id %p, starting thread\n", tid);
    // //     k_thread_start(tid);
	// // }
}

static K_TIMER_DEFINE(slow_adv_timer, slow_adv_timer_expired_handler, slow_adv_timer_cancelled_handler);

int Init_App_Ble(void)
{
    int err;

    // if (IS_ENABLED(CONFIG_BT_LBS_SECURITY_ENABLED)) {
	// 	err = bt_conn_auth_cb_register(&conn_auth_callbacks);
	// 	if (err) {
	// 		printk("Failed to register authorization callbacks.\n");
	// 		return 0;
	// 	}

	// 	err = bt_conn_auth_info_cb_register(&conn_auth_info_callbacks);
	// 	if (err) {
	// 		printk("Failed to register authorization info callbacks.\n");
	// 		return 0;
	// 	}
	// }

	err = bt_enable(NULL);
	if (err) {
		printk("Bluetooth init failed (err %d)\n", err);
		return 0;
	}

	printk("Bluetooth initialized\n");

	if (IS_ENABLED(CONFIG_SETTINGS)) {
		settings_load();
	}

    advertising_init(BT_LE_ADV_CONN_CUSTOM_FAST);
    k_timer_start(&slow_adv_timer, K_MSEC(15000), K_NO_WAIT);

	return 1;
}

// int Update_Advertising_Info(void)
// {
//     printk("Update_Advertising_Info");
//     int err;
//     err = bt_le_adv_stop();
//     if (err) {
//         printk("Advertising failed to stop (err %d)\n", err);
//         return 0;
//     }else{
//         printk("Successfuly stopped advertising (err %d)\n", err);
//     }
//     if(!is_connected)
//     {

//         // k_sleep(K_MSEC(500));  // Adjust the delay as necessary
//         advertising_init(BT_LE_ADV_CONN_CUSTOM_FAST);
//         k_timer_start(&slow_adv_timer, K_MSEC(15000), K_NO_WAIT);
//     }else{
//         //do nothing
//     }
//     return 1;
// }

The only difference is that I offloaded the actual starting stopping of the advertisement to a k_work instance, so that it doesn't try to do it in the interrupt itself, but leaves the interrupt, and the work handler will take care of it. 

With the other application I struggled to make the compiler include my custom board folder. It showed as an option under custom boards in VS code, but the board was still not found when building, and not included in my list of available boards. I guess I have not played around with custom boards that much. 

The advertising stopping and re-starting looks similar in your original question, so I guess the issue could be the same. 

The usage of k_work and k_timer is described here:

https://docs.nordicsemi.com/bundle/ncs-latest/page/zephyr/kernel/services/timing/timers.html#using_a_timer_expiry_function

Give it a go, and let me know if it doesn't work.

Best regards,

Edvin

[dlewis]

Hi Edvin, thanks for the suggestion, it appears to fix the issue in both the example code and my custom application! Do you know why this would work, but why when I tried moving the advertise stop and start functions to a thread, that did not work? 

[Edvin]

It has to do with interrupt priorities. The error message is a bit misleading, and difficult to understand, but the issue is that stopping and starting the advertisements are dependent on interrupts from the SoftDevice controller. When it is trying to do this, while already being in a timeout interrupt, you will enter a deadlock. The SoftDevice controller can't tell the application that it has stopped, and the application is waiting for it to stop. 

So what we are doing with the work handler is basically to queue up the advertising actions (stop -> start), so that it can execute outside the interrupt when you are done in the current interrupt (the timeout handler).

Hope that made some sense.

Best regards,

Edvin

[dlewis]

That makes sense, thank you!