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

[Vidar Berg]

Hi Burt,

Is it possible to get logging from the nRF52832 hci controller as well, and if not, are you able to probe the PINRESET input on it do see if it's driven low by the 9160 on startup? Also, I don't remember when I created this sample, do you have a link to that case? And did this work reliably in a previous SDK version? 

Thanks,

Vidar

[Burt]

Hi Vidar, thank you for getting involved. The original ticket where you provided 6431.central_uart to us is (+) BLE communication between a nRF52 DK board and a nRF9160 DK board - Nordic Q&A - Nordic DevZone - Nordic DevZone. I need to try the code on some older versions of SDK such as v2.5.0; I believe that is where we started. I was not involved until very recently, when the project was moved from back burner to front burner. I know that the nRF52840 on the nRF9160DK is getting reset because I can go to its console and see boot messages after I reset the nRF9160. I will try to get logging from the nRF52840 controller. Will get back to you on that.

Burt

[Vidar Berg]

Unfortunately, I have spent some time trying to set the configuration up again from scratch but having problems with "Tx timeout"s from the controller after sending the first command responses. This leads to a bt_enable() timing out on the host as well. I need to spend more time on it to find out why.

[Burt]

Thank you, Vidar. Towards the end of my nRF52840 log near the middle of this ticket, the controller Tx timeouts appear, too. Sounds like we are seeing consistent results. Note that my nRF52840 log started before the problem started, according to my notes near the log, in this ticket (so we only see the bad stuff near the end).

Burt

[Vidar Berg]

Hi Burt,

I'm still struggling with getting this to work on my end, unfortunately. I hit the ASSERT(!arch_is_in_isr() in z_sched_lock() while executing bt_enable() because the host tries to acquire a scheduler lock within the UART IRQ context. I have forwarded this issue to the developers and hope they will provide some insights.

[Burt]

Thank you, Vidar.

Burt

[Vidar Berg]

Hi Burt,

Unfortunately, I haven’t been able to work around this, so I’ll need to file it as an internal bug report for the developers to investigate further. The assertion I encountered is also something that needs to be addressed in the Zephyr bluetooth host. If version 3.0.x is working for you, I recommend you stay on that version for now.

[Burt]

Okay, thank you for filing the internal bug report, Vidar. Hopefully the developers will figure out why the change in lpuart code has led to Tx timeouts and come up with something in a newer release.

Burt

[Vidar Berg]

Proposed fix for the Zephyr BLE host assert mentioned earlier: https://github.com/zephyrproject-rtos/zephyr/pull/100308 

[Burt]

Thanks so much, Vidar. I will try it out as soon as I get a chance and let you know my results.

Burt

[Burt]

Hi Vidar, have you tried the fix? I am not having luck although it's possible my testing procedure is not good. I didn't know how to merge the change, so I used the latest git for https://github.com/nrfconnect/sdk-nrf.git and after west update, Zephyr is from https://github.com/nrfconnect/sdk-zephyr. And I just overwrote the 3 files with Pavel changes (buf.h, buf.c, iso.c). I was able to get a successful build, but I am not seeing promising results. I have not been able to see any stupid mistakes that I made other than how I chose to incorporate the Pavel change. I also tried modifying west.yml in nrf to get zephyr from  url-base: https://github.com/PavelVPV but I ended up with an unusable mess when I tried to build.

Burt

[Vidar Berg]

Hi Burt,

I have now. Yes, after the fix I was able to make it work. To apply the commit I opened the terminal, CDed to the v3.1.1/zephyr folder, then ran the following commands:

git remote add upstream https://github.com/zephyrproject-rtos/zephyr.git
git fetch upstream
git cherry-pick 9227a7c131a6763dfaa298e8c833373fe8c1623e

The fix will also be included in the upcoming SDK v3.2.0 release. It's currently available in v3.2.0-rc2. 

Log output host:

[00:00:00.407,440] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.407,470] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.407,470] <inf> fs_nvs: data wra: 0, 0
[00:00:01.184,692] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:01.184,722] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:01.184,753] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 252.16862 Build 1121034987
[00:00:01.189,300] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:01.189,331] <inf> central_uart: Bluetooth initialized
[00:00:01.197,082] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.197,204] <inf> bt_hci_core: Identity: F3:2D:57:2C:CF:0B (random)
[00:00:01.197,235] <inf> bt_hci_core: HCI: version 6.1 (0x0f) revision 0x1069, manufacturer 0x0059
[00:00:01.197,265] <inf> bt_hci_core: LMP: version 6.1 (0x0f) subver 0x1069
[00:00:01.220,977] <inf> cened
[00:00:00.401,550] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.401,580] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.401,580] <inf> fs_nvs: data wra: 0, 1c
[00:00:01.146,392] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:01.146,423] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:01.146,453] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 252.16862 Build 1121034987
[00:00:01.148,925] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:01.148,925] <inf> central_uart: Bluetooth initialized
[00:00:01.152,679] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.152,770] <inf> bt_hci_core: Identity: F3:2D:57:2C:CF:0B (random)
[00:00:01.152,801] <inf> bt_hci_core: HCI: version 6.1 (0x0f) revision 0x1069, manufacturer 0x0059
[00:00:01.152,832] <inf> bt_hci_core: LMP: version 6.1 (0x0f) subver 0x1069
[00:00:01.179,931] <inf> central_uart: NUS Client module initialized
[00:00:01.179,962] <inf> central_uart: Scan module initialized
[00:00:01.185,424] <inf> central_uart: Scan started

Project used (configured for 52840 DK + 9151 DK)

central_uart_nrf91.zip

Best regards,

Vidar