Softdevice Controller: TX with 100% duty cycle scanning in v2.3

[JordanYates]

After updating to the softdevice controller included with NCS v2.3.0 (nrfxlib 6d0f58448fae164cfa4d28c494d6bddf5d0d0224), I have noticed what appears to be a behaviour change.

Previously, when configuring Zephyr to scan on Bluetooth with 100% duty cycle (interval == window), extended advertising packets that were scheduled for transmission by my application would be received on a secondary device reliably. After updating, I am seeing approximately 0% of these packets (maybe 1 packet every minutes at 1Hz transmission). If I update my scanning window from 100% to 99%, the secondary device is again receiving the vast majority of the packets. In both cases, I receive no errors from the Bluetooth stack and all expected events are generated (TX done callback called with num_sent == 1).

Has there been some internal change to TX or RX scheduling in v2.3 that could account for this change in behaviour?
Perhaps related to the experimental PAwR or PAST support added?

[Hung Bui]

Hi Jordan, 

Have you managed to reproduce the issue with one of our samples in the SDK ? 
I did a quick test with the central_hr_coded and it seems to work just fine. The scan window and scan interval was set to the same.

[JordanYates]

I can have a go trying to reproduce this in the SDK tomorrow.

The sample you linked is not particularly relevant AFAICT as it doesn't attempt to advertise at all, only scan.
It also only scans at 50% duty cycle when attempting to find devices, the line you linked is for the connection initiation phase (BT_GAP_SCAN_FAST_INTERVAL/BT_GAP_SCAN_FAST_WINDOW).

[Hung Bui]

Hi Jordan, 

You are right. Sorry about that. Let me know if you can reproduce the issue on a simple application. 

[JordanYates]

Sorry about the delay, but I have been able to reproduce the issue (or at least one that appears very similar).

The reproduction is not dependent on the simultaneous scanning, but instead on attempting to setup an extended advertising packet for a single transmission.

I modified the standard `zephyr/samples/bluetooth/scan_adv` to TX a single packet once a second.
The application is flashed onto a nrf9160dk_nrf52840 (not ideal but what I have on hand).
I am observing the packets with the nRF Connect app on a "Pixel 3a XL".
The attached application works as expected (advertising packets seen on phone) when built on NCS v2.1.4, but not on v2.2 or v2.3.

Packets can be observed on the phone on the newer versions if the advertising set is configured to transmit twice instead of once (`BT_LE_EXT_ADV_START_PARAM(0, 2)`)

Changing the transmission to twice also resolves the issue with my original application on a custom board scanning at 100% duty cycle.

2287.scan_adv.zip

[Hung Bui]

Hi Jordan, 

Thanks for the code. I did a quick test here and I found that even if I comment out bt_le_scan_start() I still don't see the advertising packet very often. 

But if I don't delete the advertising set. I can have a reliable result: 
Here is my modification : 

printk("Bluetooth initialized\n");

	err = bt_le_scan_start(&scan_param, scan_cb);
	if (err) {
		printk("Starting scanning failed (err %d)\n", err);
		return;
	}

	struct bt_le_adv_param *adv_param = BT_LE_ADV_PARAM(BT_LE_ADV_OPT_USE_IDENTITY | BT_LE_ADV_OPT_EXT_ADV, 
														BT_GAP_ADV_FAST_INT_MIN_1, BT_GAP_ADV_FAST_INT_MAX_1, NULL);
	struct bt_le_ext_adv *adv;

	struct bt_le_ext_adv_cb adv_cb = {
		.sent = bt_adv_done
	};
		printk("TX: %d\n", mfg_data[2]);

		/* Create advertising set */
		err = bt_le_ext_adv_create(adv_param, &adv_cb, &adv);
		if (err) {
			printk("Failed to create advertising set (err %d)\n", err);
			return;
		}

		/* Set the advertising data */
	
do {
		/* Start advertising */
		mfg_data[0]++;
		err = bt_le_ext_adv_set_data(adv, ad, ARRAY_SIZE(ad), NULL, 0);
		if (err) {
			printk("Failed to set advertising data (err %d)\n", err);
			return;
		}

		err = bt_le_ext_adv_start(adv, BT_LE_EXT_ADV_START_PARAM(0, 1));
		if (err) {
			printk("Advertising failed to start (err %d)\n", err);
			return;
		}

		/* Wait for advertising to complete */
		
		if (k_sem_take(&adv_done, K_SECONDS(1)) != 0) {
			printk("Advertising failed to complete)\n");
			return;
		}

// don't delete the advertising set

/*		err = bt_le_ext_adv_delete(adv);
		if (err) {
			printk("Failed to delete set (err %d)\n", err);
			return;
		}*/

		k_sleep(K_MSEC(1000));
	} while (1);

So instead of deleting the advertising set, I simply modify the advertising data and call bt_le_ext_adv_set_data() to update it. Then start advertising again. 
I can see that the advertising is reliable: 

You can see that the sniffer can capture the advertising packet every 1 seconds (almost). 
I would suggest to use the nRF sniffer to track the advertising packet because the phone may not be able to do scanning at 100% duty cycle. 

[JordanYates]

Thanks for the suggestion. Unfortunately on my side it looks like re-using the advertising set simply shifts the problem around. While most packets are indeed received reliably now, there are others that are never being seen by my second device (which uses 100% duty cycle scanning).

This isn't surprising IMO as your suggestion is not really a fix. There is no reason why the first time an advertising set is used data should not be transmitted (as you saw). This configuration worked until v2.2, and implies some internal logic error has been introduced, which I am hitting in different scenarios as we play with configurations. I am also still seeing this issue on the most up to date version of sdk-nrfxlib (c856a2e1).

The original reason for creating/deleting the set each time was as a workaround to https://devzone.nordicsemi.com/f/nordic-q-a/79398/softdevice-hard-fault-advertising-flash-contents-on-extended-advertising

[JordanYates]

In addition to my earlier comment, I am providing a slightly modified main.c file that demonstrates the issues I describe.

The advertising set is only created once, but on each iteration the length of the manufacturer data is swapped between 4 and 7 bytes. As you can see from the attached wireshark screenshot, only the shorter packets are ever received.

Fullscreen 7367.main.c Download

/* main.c - Application main entry point */

/*
 * Copyright (c) 2015-2016 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/types.h>
#include <stddef.h>
#include <zephyr/sys/printk.h>
#include <zephyr/sys/util.h>

#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/controller.h>
#include <zephyr/bluetooth/hci.h>

static uint8_t mfg_data[] = { 0xff, 0xff, 0x00, 0x11, 0x22, 0x33, 0x44 };

static 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, mfg_data, sizeof(mfg_data)),
};

static K_SEM_DEFINE(adv_done, 0, 1);

static void bt_adv_done(struct bt_le_ext_adv *adv,
			struct bt_le_ext_adv_sent_info *info)
{
	ARG_UNUSED(adv);
	ARG_UNUSED(info);

	k_sem_give(&adv_done);
}

void main(void)
{
	int err;

	printk("Starting Advertiser Demo\n");

	/* Initialize the Bluetooth Subsystem */
	err = bt_enable(NULL);
	if (err) {
		printk("Bluetooth init failed (err %d)\n", err);
		return;
	}

	printk("Bluetooth initialized\n");

	struct bt_le_adv_param *adv_param = BT_LE_ADV_PARAM(BT_LE_ADV_OPT_USE_IDENTITY | BT_LE_ADV_OPT_EXT_ADV, 
														BT_GAP_ADV_FAST_INT_MIN_1, BT_GAP_ADV_FAST_INT_MAX_1, NULL);
	struct bt_le_ext_adv *adv;
	struct bt_le_ext_adv_cb adv_cb = {
		.sent = bt_adv_done
	};

	/* Create advertising set */
	err = bt_le_ext_adv_create(adv_param, &adv_cb, &adv);
	if (err) {
		printk("Failed to create advertising set (err %d)\n", err);
		return;
	}

	do {
		printk("TX: %d\n", mfg_data[2]);

		/* Swap between different lengths */
		if (ad[1].data_len % 2) {
			ad[1].data_len = 4;
		} else {
			ad[1].data_len = 7;
		}

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

		/* Start advertising */
		err = bt_le_ext_adv_start(adv, BT_LE_EXT_ADV_START_PARAM(0, 1));
		if (err) {
			printk("Advertising failed to start (err %d)\n", err);
			return;
		}

		/* Wait for advertising to complete */
		if (k_sem_take(&adv_done, K_SECONDS(1)) != 0) {
			printk("Advertising failed to complete)\n");
			return;
		}

		mfg_data[2]++;

		k_sleep(K_MSEC(1000));
	} while (1);
}