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]

Hi Burt,

Good news, one of the developers identified the problem and made the fix here: https://github.com/nrfconnect/sdk-nrf/pull/27571/changes/0752528c1ae88cb1532b90b81325a89a6f089824. I verified the fix with SDK v3.2.4. 

central_uart_nrf91 1.zip5807.hci_lpuart.zip

uart_central_91_merged.hex

hci_lpuart_nrf52840.hex

Best regards,

Vidar

[Burt]

Excellent, Vidar. I hope to try it reasonably soon--then I can close the ticket.

Burt

[Burt]

Hi Vidar,

I tried the fix along with v3.2.0 code. The short answer is that it is fixed (yea!). Now, I tried with some newer v3.2.x, but I'm going to assume I have something wrong there in my tree, as I wasn't seeing any printing and I wasn't seeing the nRF52840 get reset when I reset the nRF9160. So let's assume that's my bug.

Now, the long story for v3.2.0: when I enabled serial port logging...wait

Actually, the medium story: v3.2.0 central_uart, I find that I need to have

#next line BT_BUF_ACL_RX_SIZE to match the controller
CONFIG_BT_BUF_ACL_RX_SIZE=251

in prj.conf, which I think you told me to do earlier, but I don't see it in the latest code you zipped up. Is there an issue because I am using v3.2.0 rather than v3.2.4?

Getting back to "when I enabled serial port logging"... using this change

-CONFIG_LOG_BACKEND_UART=n
+CONFIG_LOG_BACKEND_UART=y

I get something like this

[00:00:00.312,561] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.312,591] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.312,591] <inf> fs_nvs: data wra: 0, 1c
[00:00:00.323,181] <wrn> lpuart: req pin low when expected high
[00:00:00.323,303] <err> lpuart: Empty receiver state:4

or

[00:00:00.297,210] <wrn> lpuart: RX: End detected at unexpected state (1).
[00:00:00.313,476] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.313,476] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.313,507] <inf> fs_nvs: data wra: 0, 1c
[00:00:00.324,066] <wrn> lpuart: req pin low when expected high
[00:00:00.324,157] <err> lpuart: Empty receiver state:4

But it always keeps going to "Scan started" with no problem. I can push button reset over an over and not see a problem.

I see that my central_uart src/main.c is not pure--I should try changing it back to pure.

It's always comforting to see no errors or warnings, so I have presented the long story, even though the code works AOK.

Burt

[Vidar Berg]

Hi Burt,

Burt said:

in prj.conf, which I think you told me to do earlier, but I don't see it in the latest code you zipped up. Is there an issue because I am using v3.2.0 rather than v3.2.4?

They should still be aligned. I have these configurations in the board specific Kconfig fragment. I.e.  central_uart_nrf91/boards/nrf9160dk_nrf9160_ns.conf

Burt said:

[00:00:00.297,210] <wrn> lpuart: RX: End detected at unexpected state (1).
[00:00:00.313,476] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.313,476] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.313,507] <inf> fs_nvs: data wra: 0, 1c
[00:00:00.324,066] <wrn> lpuart: req pin low when expected high
[00:00:00.324,157] <err> lpuart: Empty receiver state:4

I did not see this with my sample. I tried again with Logging enabled on SDK v3.2.0.  Attached below is the hex file I used. Maybe you can try the same just to ensure the warning isn't due to some HW differences.

4670.central_uart_nrf91_w_logging.hex

Best regards,

Vidar

[Burt]

Vidar,

I tried your hex file. I get the same warning and error messages, but again, everything works despite that. I will go ahead and close the ticket--I suppose if anybody else sees the messages and are bothered by that, they will open a ticket to address that. Thanks so much for seeing this through to the point of "function working."

Burt