6431.central_uart program from Vidar Berg with updates not working reliably in v3.1.1

[Burt]

We are using Vidar's program that is the basic samples/bluetooth/central_uart sample but with 3 board files so the program can be run on the nrf9160dk/nrf9160/ns board, in conjunction with bluetooth/samples/nci_lpuart running on the nRF52840 on the nRF9160DK board.

Depending upon when I reset the nrf9160, I frequently see the following, where I have added a few printk's to the code. I will show here the successful run followed by a failure. Please ignore the ECC key errors--they can be fixed with two extra config options. To make the error happen frequently, in pracitice I am push button resetting the nRF9160 soon after
Starting Bluetooth Central UART sample
Each time I see the "draining bytes from the uart" printk's that I added to bt_hci_transport_setup(), that's when the program times out and crashes.

*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.382,415] <err> bt_hci_core: HCI driver is not ready
[00:00:00.382,446] <err> central_uart: Bluetooth init failed (err -19)
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.285,797] <err> bt_hci_core: HCI driver is not ready
[00:00:00.285,827] <err> central_uart: Bluetooth init failed (err -19)
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.286,865] <err> bt_hci_core: HCI driver is not ready
[00:00:00.286,895] <err> central_uart: Bluetooth init failed (err -19)
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.479,858] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.479,858] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.479,888] <inf> fs_nvs: data wra: 0, 0
h4_open() entered...
bt_hci_transport_setup() entered...
bt_hci_transport_setup() about to gpio_pin_set(port, RESET_GPIO_PIN=24, 0)
bt_hci_transport_setup() exit success
h4_open() exit
bt_init() entered...
hci_init() entered...
common_init() entered...
common_init() about to  BT_HCI_OP_RESET
[00:00:01.192,993] <err> bt_driver: Unknown H:4 type 0x00
[00:00:01.193,084] <wrn> lpuart: RX: End detected at unexpected state (1).
common_init() after BT_HCI_OP_RESET
common_init() after drv_quirk_no_reset()
common_init() after read_local_ver_complete()
common_init() exit, good
hci_init() just finished common_init()
hci_init() just finished le_init()
[00:00:01.225,341] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:01.225,372] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:01.225,433] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 252.16862 Build 1121034987
hci_init() exit, no error
bt_init() line:4260
bt_init() line:4268
bt_init() line:4276
[00:00:01.227,966] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:01.227,996] <inf> central_uart: Bluetooth initialized
[00:00:01.228,363] <err> bt_ecc: Failed to generate ECC key -134
[00:00:01.228,363] <wrn> bt_smp: Public key not available
[00:00:01.231,567] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.231,658] <inf> bt_hci_core: Identity: F1:B2:BA:28:C5:6D (random)
[00:00:01.231,689] <inf> bt_hci_core: HCI: version 6.1 (0x0f) revision 0x1069, manufacturer 0x0059
[00:00:01.231,719] <inf> bt_hci_core: LMP: version 6.1 (0x0f) subver 0x1069
[00:00:01.231,842] <err> bt_gatt: Unable to import the key for AES CMAC -134
[00:00:01.231,964] <inf> central_uart: NUS Client module initialized
[00:00:01.231,994] <inf> central_uart: Scan module initialized
[00:00:01.237,304] <inf> central_uart: Scan started
Starting Bluetooth Central UART sample
[00:00:01.238,098] <err> bt_gatt: Unable to import the key for AES CMAC -134
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.287,353] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.287,353] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.287,384] <inf> fs_nvs: data wra: 0, 1c
h4_open() entered...
bt_hci_transport_setup() entered...
bt_hci_transport_setup(): draining bytes from uart, c=04
bt_hci_transport_setup(): draining bytes from uart, c=3E
bt_hci_transport_setup(): draining bytes from uart, c=29
bt_hci_transport_setup(): draining bytes from uart, c=02
bt_hci_transport_setup(): draining bytes from uart, c=01
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=A4
bt_hci_transport_setup(): draining bytes from uart, c=FA
bt_hci_transport_setup(): draining bytes from uart, c=2A
bt_hci_transport_setup(): draining bytes from uart, c=6A
bt_hci_transport_setup(): draining bytes from uart, c=B4
bt_hci_transport_setup(): draining bytes from uart, c=FA
bt_hci_transport_setup(): draining bytes from uart, c=1D
bt_hci_transport_setup(): draining bytes from uart, c=02
bt_hci_transport_setup(): draining bytes from uart, c=01
bt_hci_transport_setup(): draining bytes from uart, c=06
bt_hci_transport_setup(): draining bytes from uart, c=19
bt_hci_transport_setup(): draining bytes from uart, c=16
bt_hci_transport_setup(): draining bytes from uart, c=F7
bt_hci_transport_setup(): draining bytes from uart, c=FD
bt_hci_transport_setup(): draining bytes from uart, c=01
bt_hci_transport_setup(): draining bytes from uart, c=DF
bt_hci_transport_setup(): draining bytes from uart, c=FF
bt_hci_transport_setup(): draining bytes from uart, c=7D
bt_hci_transport_setup(): draining bytes from uart, c=84
bt_hci_transport_setup(): draining bytes from uart, c=DB
bt_hci_transport_setup(): draining bytes from uart, c=25
bt_hci_transport_setup(): draining bytes from uart, c=54
bt_hci_transport_setup(): draining bytes from uart, c=F4
bt_hci_transport_setup(): draining bytes from uart, c=1B
bt_hci_transport_setup(): draining bytes from uart, c=D0
bt_hci_transport_setup(): draining bytes from uart, c=77
bt_hci_transport_setup(): draining bytes from uart, c=2D
bt_hci_transport_setup(): draining bytes from uart, c=0F
bt_hci_transport_setup(): draining bytes from uart, c=45
bt_hci_transport_setup(): draining bytes from uart, c=C3
bt_hci_transport_setup(): draining bytes from uart, c=65
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=03
bt_hci_transport_setup(): draining bytes from uart, c=A6
bt_hci_transport_setup() about to gpio_pin_set(port, RESET_GPIO_PIN=24, 0)
bt_hci_transport_setup() exit success
h4_open() exit
bt_init() entered...
hci_init() entered...
common_init() entered...
common_init() about to  BT_HCI_OP_RESET
ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:505
        Controller unresponsive, command opcode 0x0c03 timeout with err -11
[00:00:10.300,109] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000002
[00:00:10.300,140] <err> os: r3/a4:  0x00000003 r12/ip:  0x200124dc r14/lr:  0x000104c5
[00:00:10.300,140] <err> os:  xpsr:  0x01000000
[00:00:10.300,170] <err> os: Faulting instruction address (r15/pc): 0x000104d4
[00:00:10.300,201] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:00:10.300,231] <err> os: Current thread: 0x2000e7e0 (unknown)
[00:00:10.358,123] <err> os: Halting system

The central_uart code and prj.conf have no changes I am aware of other than the CONFIG_LOG... options added for BACKEND_UART.

The board files are modified from the original Vidar code like follows

(v3.1.1) burt@P51:~/ncs/v3.1.1/nrf/samples/bluetooth/central_uart$  diff -rw ~/6431.central_uart/boards boards
Only in boards: nrf5340dk_nrf5340_cpuapp.conf
Only in boards: nrf54h20dk_nrf54h20_cpuapp.conf
Only in boards: nrf54h20dk_nrf54h20_cpuapp.overlay
Only in boards: nrf54l15dk_nrf54l05_cpuapp.conf
Only in boards: nrf54l15dk_nrf54l05_cpuapp.overlay
Only in boards: nrf54l15dk_nrf54l10_cpuapp.conf
Only in boards: nrf54l15dk_nrf54l10_cpuapp.overlay
Only in boards: nrf54l15dk_nrf54l15_cpuapp.conf
Only in boards: nrf54l15dk_nrf54l15_cpuapp.overlay
Only in boards: nrf54lm20dk_nrf54lm20a_cpuapp.conf
Only in boards: nrf54lm20dk_nrf54lm20a_cpuapp.overlay
Only in boards: nrf54lm20pdk_nrf54lm20a_cpuapp.conf
Only in boards: nrf54lm20pdk_nrf54lm20a_cpuapp.overlay
Only in boards: nrf54lv10dk_nrf54lv10a_cpuapp.conf
Only in boards: nrf54lv10dk_nrf54lv10a_cpuapp.overlay
diff -rw /home/burt/6431.central_uart/boards/nrf9160dk_nrf9160_ns_0_14_0.overlay boards/nrf9160dk_nrf9160_ns_0_14_0.overlay
2c2
< #include <nrf9160dk_nrf52840_reset_on_if9.dtsi>
---
> #include <nrf9160/nrf9160dk_nrf52840_reset_on_if9.dtsi>
diff -rw /home/burt/6431.central_uart/boards/nrf9160dk_nrf9160_ns.conf boards/nrf9160dk_nrf9160_ns.conf
10a11,13
> 
> #BMS CONFIG_TFM_PROFILE_TYPE_MINIMAL=n
> #BMS CONFIG_TFM_PROFILE_TYPE_NOT_SET=y
diff -rw /home/burt/6431.central_uart/boards/nrf9160dk_nrf9160_ns.overlay boards/nrf9160dk_nrf9160_ns.overlay
1c1
< #include <nrf9160dk_nrf52840_reset_on_if5.dtsi>
---
> #include <nrf9160/nrf9160dk_nrf52840_reset_on_if5.dtsi>
6a7,8
>         zephyr,bt-hci = &bt_hci_uart;
> 
26a29,34
>               //following 4 lines are added from lte_ble_gateway
>                 bt_hci_uart: bt_hci_uart {
>                         compatible = "zephyr,bt-hci-uart";
>                         status = "okay";
>                 };
> 

Thank you for help with this. Note that I am testing with my external custom nRF52832 board off. That board runs bluetooth/samples/peripheral_uart normally.

Burt Silverman

[Burt]

Vidar, have you tested with including debug.conf when building hci_lpuart? I always enable that when things don't work out the very first time without it. That path needs to be tested given that the debug.conf file exists. I will try again now without using that debug.conf.

Burt

[Burt]

I just turned off debug.conf when building hci_lpuart sample, and I am getting some build garbage when doing a pristine build in v3.2.0-rc2:

warning: BT_BUF_EVT_DISCARDABLE_SIZE (defined at subsys/bluetooth/host/Kconfig:172,
drivers/bluetooth/hci/Kconfig.nxp:60, subsys/bluetooth/host/Kconfig:172) was assigned the value
'255' but got the value ''. Check these unsatisfied dependencies: ((BT_HCI_HOST && BT_RPC_STACK) ||
(BT_NXP && BT_HCI && BT_DRIVERS) || (BT_HCI_HOST && BT_HCI && BT)) (=n). See
docs.zephyrproject.org/.../kconfig.html and/or look up
BT_BUF_EVT_DISCARDABLE_SIZE in the menuconfig/guiconfig interface. The Application Development
Primer, Setting Configuration Values, and Kconfig - Tips and Best Practices sections of the manual
might be helpful too.


warning: BT_CTLR_DTM_HCI (defined at subsys/bluetooth/controller/Kconfig.dtm:14) was assigned the
value 'y' but got the value 'n'. Check these unsatisfied dependencies: BT_CTLR_DTM_HCI_SUPPORT (=n).
See docs.zephyrproject.org/.../kconfig.html and/or look up
BT_CTLR_DTM_HCI in the menuconfig/guiconfig interface. The Application Development Primer, Setting
Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be helpful
too.

[Burt]

There were bugs in the .conf files so I had to do something like:

(v3.2.0-rc2) burt@P51:~/ncs/v3.2.0-rc2/nrf/samples/bluetooth/hci_lpuart$ git diff .
diff --git a/samples/bluetooth/hci_lpuart/boards/nrf9160dk_nrf52840.conf b/samples/bluetooth/hci_lpuart/boards/nrf9160dk_nrf52840.conf
index c6a0424420..f611f52b2e 100644
--- a/samples/bluetooth/hci_lpuart/boards/nrf9160dk_nrf52840.conf
+++ b/samples/bluetooth/hci_lpuart/boards/nrf9160dk_nrf52840.conf
@@ -3,7 +3,7 @@
 CONFIG_GPIO=y
 CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=512
 CONFIG_BT_MAX_CONN=16
-CONFIG_BT_CTLR_DTM_HCI=y
+#CONFIG_BT_CTLR_DTM_HCI=y
 CONFIG_BT_CTLR_ASSERT_HANDLER=y
 
 CONFIG_UART_1_ASYNC=y
diff --git a/samples/bluetooth/hci_lpuart/prj.conf b/samples/bluetooth/hci_lpuart/prj.conf
index 1997b45e3a..6371f8e11c 100644
--- a/samples/bluetooth/hci_lpuart/prj.conf
+++ b/samples/bluetooth/hci_lpuart/prj.conf
@@ -5,4 +5,5 @@ CONFIG_BT_HCI_RAW=y
 CONFIG_BT_HCI_RAW_H4=y
 CONFIG_BT_HCI_RAW_H4_ENABLE=y
 CONFIG_BT_BUF_ACL_RX_SIZE=251
-CONFIG_BT_BUF_EVT_DISCARDABLE_SIZE=255
+#CONFIG_BT_BUF_EVT_DISCARDABLE_SIZE=255

Still nothing works for me.

[Vidar Berg]

I tested with the last release candidate now and found that I had to add CONFIG_BT_BUF_ACL_RX_SIZE=251 to the application configuration to align the buffer ACL sizes between host and controller (controller does not support reassembly like a generic controller, hence this requirement), and also uncomment the CONFIG_NRFX_UARTE0=y line. But it worked after making these two changes. Can you check if the controller board is reset when bt_enable is called or if the custom bt_hci_transport_setup() from nrf52840_reset.c is being called at all? This resetting of the controller is needed to ensure the host and controller are in sync before performing the initialisation.

[Burt]

Hi Vidar,

I was almost ready to say "it works," but after more tries I have to modify that to "it works, quite often."

The CONFIG_BT_BUF_ACL_RX_SIZE=251 definitely is what made it work "quite often." And the CONFIG_NRFX_UARTE0=y line I do not see in v3.2.0-rc2. I do see CONFIG_NRFX_UARTE=y uncommented in prj.conf. But I did see it in v3.1.1. Now, it is defined in zephyr/drivers/serial/Kconfig.nrfx_uart_instance and is not user configurable

config NRFX_UARTE$(nrfx_uart_num)
        def_bool y if HAS_HW_NRF_UARTE$(nrfx_uart_num) && !UART_NRFX_UARTE_LEGACY_SHIM

so it should not show up in prj.conf. Nevertheless, I do see

CONFIG_HAS_HW_NRF_UARTE0=y
CONFIG_HAS_HW_NRF_UARTE2=y

in build/central_uart/zephyr/.config, but I also see 

CONFIG_UART_NRFX_UARTE_LEGACY_SHIM=y

in that file. I could set CONFIG_UART_NRFX_UARTE_LEGACY_SHIM=n but according to zephyr/drivers/serial/Kconfig.nrfx, doing that is deprecated. So we are in limbo--can you take another look at what is really needed for CONFIG_NRFX_UARTE0?

Having talked about these details, and yes, I do see that the controller board is reset after I start central_uart, the problem I am having is that eventually something gets out of sync and the system does not come up to Bluetooth initialized. You may have to try it quite a few times, but it is happening for me within a minute or two of continued resets. The strange thing is that once it happens, something is stuck in memory so that it usually stays out of sync until doing a power on reset (rather than push button reset).

Burt