Is bluetooth sample "peripheral" still working well?


Li, Jun R
 

Hi there,

I’m trying to rebase my project which is based on NRF51822 SoC from V1.13 to the latest version but found the application doesn’t work anymore. It seems the application suffers from some issues related to BT settings. To identify the issue, I tried the BLE sample “sample/Bluetooth/peripheral” with the board “nrf51_pca10028” which is the one I’m using. The build process ran well, and flashing was good. However, I found the sample application also suffers from the same issue I found on my project, as shown below:

 

***** Booting Zephyr OS zephyr-v1.13.0-2303-g55f091f *****

Bluetooth initialized

Advertising successfully started

[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)

[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Variant: nRF51x (0x0001)

[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 1.13 Build 99

[00:00:00.000,000] <wrn> bt_hci_core.bt_init: No ID address. Expecting one to come from storage.

[00:00:00.000,000] <inf> bt_hci_core.bt_dev_show_info: Identity: <log_strdup alloc failed>

[00:00:00.000,000] <inf> bt_hci_core.bt_dev_show_info: HCI: version 5.0 (0x09) revision 0x0000, manufacturer 0x05f1

[00:00:00.000,000] <inf> bt_hci_core.bt_dev_show_info: LMP: version 5.0 (0x09) subver 0xffff

 

 

I found two issues:

  1. There are about 9 seconds delay between the first message “Bluetooth initialized” and the second one “Advertising successfully started” every time when the board restarts. Not sure what is blocking the booting process.
  2. I got a “No ID address” warning which is highlighted in red above. The problem never happened before. Is it a new feature? And Does any board need to be provisioned with an ID address before being used from now on?

 

Does anyone know if I’m missing something for correctly using this sample?

 

Thank you!

 

Jun Li @ Intel Corporation

 


Johan Hedberg
 

Hi,


On 3 Dec 2018, at 22.03, Li, Jun R <jun.r.li@intel.com> wrote:
[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Variant: nRF51x (0x0001)
[00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 1.13 Build 99
[00:00:00.000,000] <wrn> bt_hci_core.bt_init: No ID address. Expecting one to come from storage.
This is normal when CONFIG_BT_SETTINGS=y is enabled. In such a case the identity address isn’t initialised until the app calls settings_load(), since the identity may be stored in flash.

[00:00:00.000,000] <inf> bt_hci_core.bt_dev_show_info: Identity: <log_strdup alloc failed>
This shows that the identity has been successfully initialised as a consequence of calling settings_load(), however apparently there are too few log buffers available to log the string-format address.

• There are about 9 seconds delay between the first message “Bluetooth initialized” and the second one “Advertising successfully started” every time when the board restarts. Not sure what is blocking the booting process.
You’re not the first one to report something like this - it needs to be investigated.

• I got a “No ID address” warning which is highlighted in red above. The problem never happened before. Is it a new feature? And Does any board need to be provisioned with an ID address before being used from now on?
As I mentioned earlier this is a non-issue. The identity does get loaded properly but there’s an issue allocating a log buffer for its string representation. In general I have a slight suspicion that all these issues could somehow be related to the new logging subsystem.

Johan


Li, Jun R
 

Hi Johan,
Thanks for the quick reply! Is there an issue addressing the 9 second delay problem during the booting process? It seems the issue #11780 (https://github.com/zephyrproject-rtos/zephyr/issues/11780) is similar though it is using mesh network stack.

And how can I get rid of the warning "No ID address"? It always happens on every booting up process.

Actually, I found another "HARD FAULT" issue if I don't erase all of the flash memory after flashing the firmware built from the latest master. I'll try to identify if the is caused by my app or just a generic one. But basically, this never happened before I rebased the app.

Thank you!

Regards,
Jun

On 12/3/18, 13:16, "Hedberg, Johan" <johan.hedberg@intel.com> wrote:

Hi,


> On 3 Dec 2018, at 22.03, Li, Jun R <jun.r.li@intel.com> wrote:
> [00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
> [00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: HW Variant: nRF51x (0x0001)
> [00:00:00.000,000] <inf> bt_hci_core.hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 1.13 Build 99
> [00:00:00.000,000] <wrn> bt_hci_core.bt_init: No ID address. Expecting one to come from storage.

This is normal when CONFIG_BT_SETTINGS=y is enabled. In such a case the identity address isn’t initialised until the app calls settings_load(), since the identity may be stored in flash.

> [00:00:00.000,000] <inf> bt_hci_core.bt_dev_show_info: Identity: <log_strdup alloc failed>

This shows that the identity has been successfully initialised as a consequence of calling settings_load(), however apparently there are too few log buffers available to log the string-format address.

> • There are about 9 seconds delay between the first message “Bluetooth initialized” and the second one “Advertising successfully started” every time when the board restarts. Not sure what is blocking the booting process.

You’re not the first one to report something like this - it needs to be investigated.

> • I got a “No ID address” warning which is highlighted in red above. The problem never happened before. Is it a new feature? And Does any board need to be provisioned with an ID address before being used from now on?

As I mentioned earlier this is a non-issue. The identity does get loaded properly but there’s an issue allocating a log buffer for its string representation. In general I have a slight suspicion that all these issues could somehow be related to the new logging subsystem.

Johan


Johan Hedberg
 

Hi Jun,

On 4 Dec 2018, at 0.08, Li, Jun R <jun.r.li@intel.com> wrote:
Thanks for the quick reply! Is there an issue addressing the 9 second delay problem during the booting process? It seems the issue #11780 (https://github.com/zephyrproject-rtos/zephyr/issues/11780) is similar though it is using mesh network stack.
Based on bisecting it seems commit 4d94257162b22f37104e9f85238ed7c3486c5a1c is introducing the issue. Reverting it made the delay and log_strdup failure go away for me. It also fixed the timestamps (they shouldn’t be all zero).

And how can I get rid of the warning "No ID address"? It always happens on every booting up process.
Why do you want to get rid of it? It’s there to remind app writers that they need to do something extra (i.e. call settings_load) after calling bt_enable().

Actually, I found another "HARD FAULT" issue if I don't erase all of the flash memory after flashing the firmware built from the latest master. I'll try to identify if the is caused by my app or just a generic one. But basically, this never happened before I rebased the app.
This is something I haven’t seen. What do you mean by not erasing all flash memory? Which parts don’t you erase? What was there from before? You might have uncovered some issue with the settings subsystem if there’s some garbage data there. It’s also worth excluding the possibility of stack overflow, since the settings code increases stack usage. So try increasing your stack sizes before anything else.

Johan


frv
 

Hi Johan,

Is it correct to say that no public address is set by Nordic for BT HW? Thus probably it is normal this warning "No ID address" is shown. 

Sometime ago this topic was published:
https://lists.zephyrproject.org/g/devel/topic/28283753#5452

I'm wondering if my proposal is valid regarding how to set a public address in case of NRF HW. I didn't investigate myself further but probably Zephyr's "load_settings" function gets its stored info from UICR in case of Nordic HW.


thanks,
Best regards,
Frank


Johan Hedberg
 

Hi Frank,

On 4 Dec 2018, at 17.52, frv <F.Vieren@televic.com> wrote:
Is it correct to say that no public address is set by Nordic for BT HW? Thus probably it is normal this warning "No ID address" is shown.
Not quite. An Identity Address can be either a public address or a static random address. In most cases nRF boards only have a static random address but no public address. In this case the warning just means that at that point the stack has neither one of those addresses, and is waiting for settings_load() to read one from flash (if nothing is found in flash then the stack will go ahead and try to use our HCI vendor extensions to read the static random address from the controller).

Sometime ago this topic was published:
https://lists.zephyrproject.org/g/devel/topic/28283753#5452

I'm wondering if my proposal is valid regarding how to set a public address in case of NRF HW. I didn't investigate myself further but probably Zephyr's "load_settings" function gets its stored info from UICR in case of Nordic HW.
I assume you mean settings_load()? That reads the storage partition in flash, i.e. it’s not related to the FICR or UICR registers.

Johan


Li, Jun R
 

Hi Johan,
Actually, the function "settings_load" is called in the sample "peripheral" which you can take a look at. I assume an random address will be written to the settings after the first booting, right? However, I still see the message "NO ID address" showing up every time when the board reboots. Should I do extra work to generate a random mac and write it to the settings?

I'll try increasing the stack size to see if it is helpful to resolve "HARD FAULT". Specifically, in which thread you want to increase its stack size, settings or Bluetooth?

Thank you!
Jun



On 12/4/18, 01:51, "Hedberg, Johan" <johan.hedberg@intel.com> wrote:

Hi Jun,

> On 4 Dec 2018, at 0.08, Li, Jun R <jun.r.li@intel.com> wrote:
> Thanks for the quick reply! Is there an issue addressing the 9 second delay problem during the booting process? It seems the issue #11780 (https://github.com/zephyrproject-rtos/zephyr/issues/11780) is similar though it is using mesh network stack.

Based on bisecting it seems commit 4d94257162b22f37104e9f85238ed7c3486c5a1c is introducing the issue. Reverting it made the delay and log_strdup failure go away for me. It also fixed the timestamps (they shouldn’t be all zero).

> And how can I get rid of the warning "No ID address"? It always happens on every booting up process.

Why do you want to get rid of it? It’s there to remind app writers that they need to do something extra (i.e. call settings_load) after calling bt_enable().

> Actually, I found another "HARD FAULT" issue if I don't erase all of the flash memory after flashing the firmware built from the latest master. I'll try to identify if the is caused by my app or just a generic one. But basically, this never happened before I rebased the app.

This is something I haven’t seen. What do you mean by not erasing all flash memory? Which parts don’t you erase? What was there from before? You might have uncovered some issue with the settings subsystem if there’s some garbage data there. It’s also worth excluding the possibility of stack overflow, since the settings code increases stack usage. So try increasing your stack sizes before anything else.

Johan


frv
 

Hi Johan,

Thanks for this useful feedback, clarifying a few things more, much appreciated! 

Best regards,
Frank


Johan Hedberg
 

Hi Jun,

On 4 Dec 2018, at 18.13, Li, Jun R <jun.r.li@intel.com> wrote:
Actually, the function "settings_load" is called in the sample "peripheral" which you can take a look at.
I know.

I assume an random address will be written to the settings after the first booting, right? However, I still see the message "NO ID address" showing up every time when the board reboots. Should I do extra work to generate a random mac and write it to the settings?
No. The warning comes before settings_load() to indicate to the app developer that settings_load() will need to be called, i.e. the warning is not supposed to go away. I think everything is working fine with regard to this - you’re just getting distracted with this benign warning message :)

I'll try increasing the stack size to see if it is helpful to resolve "HARD FAULT". Specifically, in which thread you want to increase its stack size, settings or Bluetooth?
Usually it’s the thread that calls settings_load() that ends up having an increase in stack usage. In the case of the peripheral app it’s the system workqueue (which calls bt_ready which calls settings_load). However, you should analyse the stack usage of all stacks to to decide whether they’re the right size for your application.

Are you seeing this fault with an unmodified upstream peripheral app? If so we need to fix this upstream. That said, I didn’t see such an issue when running this app on both nRF52 and nRF51 boards today.

Johan