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

[Burt]

Here is one example...with the debug log options I have chosen, it is difficult to know where to start on the controller side...

Fullscreen nrf9160.log Download

*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.281,036] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.281,036] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.281,066] <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=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=00
bt_hci_transport_setup(): draining bytes from uart, c=01
bt_hci_transport_setup(): draining bytes from uart, c=DC
bt_hci_transport_setup(): draining bytes from uart, c=75
bt_hci_transport_setup(): draining bytes from uart, c=A8
bt_hci_transport_setup(): draining bytes from uart, c=FB
bt_hci_transport_setup(): draining bytes from uart, c=70
bt_hci_transport_setup(): draining bytes from uart, c=4A
bt_hci_transport_setup(): draining bytes from uart, c=11
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=1A
bt_hci_transport_setup(): draining bytes from uart, c=02
bt_hci_transport_setup(): draining bytes from uart, c=0A
bt_hci_transport_setup(): draining bytes from uart, c=04
bt_hci_transport_setup(): draining bytes from uart, c=0A
bt_hci_transport_setup(): draining bytes from uart, c=FF
bt_hci_transport_setup(): draining bytes from uart, c=4C
bt_hci_transport_setup(): draining bytes from uart, c=00
bt_hci_transport_setup(): draining bytes from uart, c=10
bt_hci_transport_setup(): draining bytes from uart, c=05
bt_hci_transport_setup(): draining bytes from uart, c=03
bt_hci_transport_setup(): draining bytes from uart, c=18
bt_hci_transport_setup(): draining bytes from uart, c=71
bt_hci_transport_setup(): draining bytes from uart, c=1D
bt_hci_transport_setup(): draining bytes from uart, c=66
bt_hci_transport_setup(): draining bytes from uart, c=A7
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.293,365] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000002
[00:00:10.293,395] <err> os: r3/a4:  0x00000003 r12/ip:  0x200124dc r14/lr:  0x000104c5
[00:00:10.293,395] <err> os:  xpsr:  0x01000000
[00:00:10.293,426] <err> os: Faulting instruction address (r15/pc): 0x000104d4
[00:00:10.293,457] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:00:10.293,487] <err> os: Current thread: 0x2000e7e0 (unknown)
[00:00:10.351,318] <err> os: Halting system

Fullscreen nrf52840.log Download

479,400] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
.479,431] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 33
[00:00:32.479,675] <dbg> lpuart: api_tx: tx len:33
[00:00:32.482,086] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.482,452] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.640,319] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:32.640,380] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:32.640,625] <dbg> lpuart: api_tx: tx len:32
[00:00:32.640,930] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:32.640,960] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:32.642,974] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.643,341] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.643,402] <dbg> lpuart: api_tx: tx len:15
[00:00:32.645,751] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.645,965] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.655,273] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:32.655,303] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:32.655,548] <dbg> lpuart: api_tx: tx len:32
[00:00:32.655,853] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:32.655,883] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:32.657,958] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.658,355] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.658,386] <dbg> lpuart: api_tx: tx len:15
[00:00:32.660,736] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.660,949] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.698,425] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:32.698,455] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 42
[00:00:32.698,699] <dbg> lpuart: api_tx: tx len:42
[00:00:32.701,049] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.701,538] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.821,624] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:32.821,655] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:32.821,868] <dbg> lpuart: api_tx: tx len:32
[00:00:32.824,218] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.824,615] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.828,430] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:32.828,491] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:32.828,704] <dbg> lpuart: api_tx: tx len:32
[00:00:32.829,040] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:32.829,071] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:32.831,146] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.831,512] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:32.831,542] <dbg> lpuart: api_tx: tx len:15
[00:00:32.833,892] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:32.834,106] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.002,807] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.002,868] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:33.003,112] <dbg> lpuart: api_tx: tx len:32
[00:00:33.005,462] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.005,859] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.023,254] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:33.023,284] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 33
[00:00:33.023,559] <dbg> lpuart: api_tx: tx len:33
[00:00:33.023,864] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.023,895] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:33.025,939] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.026,336] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.026,367] <dbg> lpuart: api_tx: tx len:15
[00:00:33.028,717] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.028,930] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.189,056] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.189,117] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:33.189,361] <dbg> lpuart: api_tx: tx len:32
[00:00:33.189,666] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.189,697] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:33.191,711] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.192,077] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.192,108] <dbg> lpuart: api_tx: tx len:15
[00:00:33.194,488] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.194,671] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.201,568] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.201,599] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:33.201,843] <dbg> lpuart: api_tx: tx len:32
[00:00:33.202,148] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.202,178] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:33.204,254] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.204,620] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.204,650] <dbg> lpuart: api_tx: tx len:15
[00:00:33.207,031] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.207,214] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.244,659] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:33.244,689] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 42
[00:00:33.244,934] <dbg> lpuart: api_tx: tx len:42
[00:00:33.247,283] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.247,772] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.299,621] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:33.299,652] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 33
[00:00:33.299,865] <dbg> lpuart: api_tx: tx len:33
[00:00:33.300,201] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.300,262] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:33.302,246] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.302,642] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.302,673] <dbg> lpuart: api_tx: tx len:15
[00:00:33.305,023] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.305,236] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.372,833] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.372,863] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:33.373,107] <dbg> lpuart: api_tx: tx len:32
[00:00:33.374,694] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.374,725] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:33.375,274] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.375,335] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:33.375,488] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.375,854] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.375,885] <dbg> lpuart: api_tx: tx len:32
[00:00:33.378,265] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.378,631] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.378,662] <dbg> lpuart: api_tx: tx len:15
[00:00:33.381,011] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.381,225] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.477,783] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.477,813] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:33.478,057] <dbg> lpuart: api_tx: tx len:32
[00:00:33.480,407] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.480,804] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.555,328] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.555,358] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:33.555,603] <dbg> lpuart: api_tx: tx len:32
[00:00:33.555,938] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.555,969] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:33.557,952] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.558,349] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.558,380] <dbg> lpuart: api_tx: tx len:15
[00:00:33.560,729] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.560,943] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.739,044] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.739,105] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:33.739,349] <dbg> lpuart: api_tx: tx len:32
[00:00:33.739,654] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.739,685] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:33.741,699] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.742,095] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.742,126] <dbg> lpuart: api_tx: tx len:15
[00:00:33.744,476] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.744,689] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.746,643] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.746,704] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:33.746,917] <dbg> lpuart: api_tx: tx len:32
[00:00:33.749,237] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.749,603] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.790,893] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:33.790,954] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:33.791,168] <dbg> lpuart: api_tx: tx len:42
[00:00:33.793,518] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.794,006] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.847,290] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:33.847,320] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 33
[00:00:33.847,564] <dbg> lpuart: api_tx: tx len:33
[00:00:33.847,869] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:33.847,900] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:33.849,914] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.850,311] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.850,341] <dbg> lpuart: api_tx: tx len:15
[00:00:33.852,691] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.852,905] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.854,034] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (20)
[00:00:33.854,064] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 23
[00:00:33.854,309] <dbg> lpuart: api_tx: tx len:23
[00:00:33.856,475] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.856,781] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.920,318] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:33.920,349] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:33.920,593] <dbg> lpuart: api_tx: tx len:32
[00:00:33.922,943] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.923,339] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:33.973,388] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:33.973,449] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:33.973,663] <dbg> lpuart: api_tx: tx len:42
[00:00:33.976,013] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:33.976,501] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.021,575] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:34.021,606] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:34.021,850] <dbg> lpuart: api_tx: tx len:32
[00:00:34.024,200] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.024,597] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.081,481] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (20)
[00:00:34.081,512] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 23
[00:00:34.081,756] <dbg> lpuart: api_tx: tx len:23
[00:00:34.084,106] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.084,381] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.105,316] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:34.105,346] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:34.105,590] <dbg> lpuart: api_tx: tx len:32
[00:00:34.107,971] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.108,367] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.394,744] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:34.394,775] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 33
[00:00:34.395,019] <dbg> lpuart: api_tx: tx len:33
[00:00:34.395,324] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:34.395,355] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:34.397,430] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.397,827] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.397,857] <dbg> lpuart: api_tx: tx len:15
[00:00:34.400,207] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.400,421] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.462,188] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:34.462,219] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:34.462,463] <dbg> lpuart: api_tx: tx len:32
[00:00:34.462,768] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:34.462,799] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:34.464,813] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.465,209] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.465,240] <dbg> lpuart: api_tx: tx len:15
[00:00:34.467,590] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.467,803] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.522,186] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:34.522,216] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:34.522,430] <dbg> lpuart: api_tx: tx len:42
[00:00:34.524,780] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.525,268] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.569,061] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:34.569,091] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:34.569,335] <dbg> lpuart: api_tx: tx len:32
[00:00:34.571,716] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.572,082] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.006,011] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:35.006,042] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:35.006,225] <dbg> lpuart: api_tx: tx len:32
[00:00:35.008,605] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.009,002] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.114,074] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:35.114,105] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:35.114,349] <dbg> lpuart: api_tx: tx len:32
[00:00:35.116,699] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.117,095] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.280,914] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:35.280,975] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:35.281,127] <dbg> lpuart: api_tx: tx len:32
[00:00:35.281,524] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:35.281,555] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:35.283,538] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.283,905] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.283,935] <dbg> lpuart: api_tx: tx len:15
[00:00:35.286,285] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.286,499] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.364,410] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:00:35.364,440] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 46
[00:00:35.364,685] <dbg> lpuart: api_tx: tx len:46
[00:00:35.367,034] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.367,553] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.543,548] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (41)
[00:00:35.543,579] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 44
[00:00:35.543,823] <dbg> lpuart: api_tx: tx len:44
[00:00:35.546,203] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.546,691] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.759,704] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:00:35.759,735] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 45
[00:00:35.759,979] <dbg> lpuart: api_tx: tx len:45
[00:00:35.762,329] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.762,847] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.823,455] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:35.823,486] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:35.823,699] <dbg> lpuart: api_tx: tx len:32
[00:00:35.824,035] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:35.824,066] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:35.826,080] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.826,446] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:35.826,477] <dbg> lpuart: api_tx: tx len:15
[00:00:35.828,857] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:35.829,040] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.204,101] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:36.204,162] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:36.204,406] <dbg> lpuart: api_tx: tx len:32
[00:00:36.206,787] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.207,183] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.357,574] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:36.357,604] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:36.357,849] <dbg> lpuart: api_tx: tx len:42
[00:00:36.360,198] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.360,687] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.369,659] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:36.369,689] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:36.369,934] <dbg> lpuart: api_tx: tx len:32
[00:00:36.370,269] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:36.370,300] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:36.372,375] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.372,741] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.372,802] <dbg> lpuart: api_tx: tx len:15
[00:00:36.375,152] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.375,366] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.490,386] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (20)
[00:00:36.490,417] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 23
[00:00:36.490,661] <dbg> lpuart: api_tx: tx len:23
[00:00:36.493,011] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.493,286] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.542,602] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:36.542,633] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:36.542,877] <dbg> lpuart: api_tx: tx len:42
[00:00:36.545,227] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.545,715] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.605,712] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:36.605,743] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 33
[00:00:36.605,987] <dbg> lpuart: api_tx: tx len:33
[00:00:36.606,323] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:36.606,353] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:36.608,337] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.608,734] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.608,764] <dbg> lpuart: api_tx: tx len:15
[00:00:36.611,114] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.611,328] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.663,787] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:36.663,818] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:36.664,031] <dbg> lpuart: api_tx: tx len:32
[00:00:36.666,412] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.666,809] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.726,348] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:36.726,379] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:36.726,623] <dbg> lpuart: api_tx: tx len:42
[00:00:36.728,973] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.729,461] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.847,534] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:36.847,564] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:36.847,808] <dbg> lpuart: api_tx: tx len:32
[00:00:36.850,158] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.850,555] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.907,592] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:36.907,623] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:36.907,867] <dbg> lpuart: api_tx: tx len:42
[00:00:36.910,217] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.910,705] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.914,672] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:36.914,703] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:36.914,947] <dbg> lpuart: api_tx: tx len:32
[00:00:36.915,283] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:36.915,313] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:36.917,388] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.917,755] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:36.917,785] <dbg> lpuart: api_tx: tx len:15
[00:00:36.920,166] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:36.920,349] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.019,775] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.019,805] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:37.020,050] <dbg> lpuart: api_tx: tx len:32
[00:00:37.020,385] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:37.020,416] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:37.022,430] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.022,796] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.022,827] <dbg> lpuart: api_tx: tx len:15
[00:00:37.025,177] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.025,390] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.028,778] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.028,808] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:37.029,052] <dbg> lpuart: api_tx: tx len:32
[00:00:37.031,463] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.031,860] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.088,836] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:37.088,897] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:37.089,111] <dbg> lpuart: api_tx: tx len:42
[00:00:37.091,461] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.091,949] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.153,350] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:37.153,381] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 33
[00:00:37.153,625] <dbg> lpuart: api_tx: tx len:33
[00:00:37.153,961] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:37.153,991] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:37.155,975] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.156,372] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.156,402] <dbg> lpuart: api_tx: tx len:15
[00:00:37.158,752] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.158,966] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.272,613] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:37.272,644] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 42
[00:00:37.272,796] <dbg> lpuart: api_tx: tx len:42
[00:00:37.275,146] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.275,634] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.399,658] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.399,719] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:37.399,963] <dbg> lpuart: api_tx: tx len:32
[00:00:37.402,313] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.402,679] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.455,902] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.455,932] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:37.456,176] <dbg> lpuart: api_tx: tx len:32
[00:00:37.456,512] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:37.456,542] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 15
[00:00:37.457,611] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:37.457,641] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 42
[00:00:37.458,557] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.458,923] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.458,953] <dbg> lpuart: api_tx: tx len:15
[00:00:37.461,334] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.461,517] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.461,547] <dbg> lpuart: api_tx: tx len:42
[00:00:37.463,928] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:37.464,385] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:37.561,065] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.561,096] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 32
[00:00:37.561,340] <dbg> lpuart: api_tx: tx len:32
[00:00:37.561,645] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:37.561,676] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8a0 len 15
[00:00:37.586,395] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:37.586,425] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8b8 len 32
[00:00:37.638,854] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:37.638,885] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c888 len 42
[00:00:37.699,615] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:00:37.699,645] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8d0 len 33
[00:00:37.820,068] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:37.820,129] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c8e8 len 42
[00:00:38.001,312] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:00:38.001,373] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c900 len 42
[00:00:38.002,166] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:00:38.002,197] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c918 len 32
[00:00:38.002,746] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (12)
[00:00:38.002,777] <dbg> bt_hci_raw: bt_hci_recv: buf 0x2000c930 len 15
[00:00:38.102,325] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)[00:00:00.000,244] <dbg> bt_sdc_hci_driver: configure_memory_usage: BT mempool size: 15910, required: 15112
[00:00:00.000,488] <dbg> lpuart: api_rx_enable: RX: Enabling buf:0x20003fdc len:128
[00:00:00.000,549] <inf> board_control: vcom0_pins_routing is ENABLED
[00:00:00.000,579] <inf> board_control: vcom2_pins_routing is ENABLED
[00:00:00.000,640] <inf> board_control: led1_pin_routing is ENABLED
[00:00:00.000,701] <inf> board_control: led2_pin_routing is ENABLED
[00:00:00.000,762] <inf> board_control: led3_pin_routing is ENABLED
[00:00:00.000,823] <inf> board_control: led4_pin_routing is ENABLED
[00:00:00.000,885] <inf> board_control: switch1_pin_routing is ENABLED
[00:00:00.000,946] <inf> board_control: switch2_pin_routing is ENABLED
[00:00:00.000,976] <inf> board_control: button1_pin_routing is ENABLED
[00:00:00.001,037] <inf> board_control: button2_pin_routing is ENABLED
[00:00:00.001,068] <inf> board_control: nrf_interface_pins_0_2_routing is ENABLED
[00:00:00.001,129] <inf> board_control: nrf_interface_pins_3_5_routing is ENABLED
[00:00:00.001,159] <inf> board_control: nrf_interface_pins_6_8_routing is disabled
[00:00:00.001,220] <inf> board_control: nrf_interface_pin_9_routing is ENABLED
[00:00:00.001,251] <inf> board_control: io_expander_pins_routing is disabled
[00:00:00.001,312] <inf> board_control: external_flash_pins_routing is ENABLED
[00:00:00.001,312] <inf> board_control: Board configured.
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.001,403] <dbg> bt_hci_raw: bt_enable_raw: 
[00:00:00.001,434] <dbg> bt_sdc_hci_driver: hci_driver_open: Open
[00:00:00.001,464] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            fc de 41 eb a2 d1 42 24  00 b5 f8 57 9f ac 9d 9e |..A...B$ ...W....
                                            aa c9 b4 34                                      |...4             
[00:00:00.001,922] <inf> bt_hci_raw: Lower HCI transport: SDC
[00:00:00.001,953] <inf> bt_hci_raw: Bluetooth enabled in RAW mode
[00:00:00.001,953] <dbg> lpuart: api_tx: tx len:1
[00:00:01.002,044] <wrn> lpuart: Tx timeout
[00:00:01.002,044] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:01.002,227] <dbg> lpuart: api_tx: tx len:1
[00:00:02.002,319] <wrn> lpuart: Tx timeout
[00:00:02.002,349] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:02.003,143] <dbg> lpuart: api_tx: tx len:1
[00:00:03.003,204] <wrn> lpuart: Tx timeout
[00:00:03.003,204] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:03.004,211] <dbg> lpuart: api_tx: tx len:1
[00:00:04.004,211] <wrn> lpuart: Tx timeout
[00:00:04.004,241] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:04.005,126] <dbg> lpuart: api_tx: tx len:1
[00:00:05.005,187] <wrn> lpuart: Tx timeout
[00:00:05.005,187] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:05.006,225] <dbg> lpuart: api_tx: tx len:1
[00:00:06.006,256] <wrn> lpuart: Tx timeout
[00:00:06.006,286] <dbg> lpuart: tx_complete: TX completed, pin idle

I have these debug log options on the 52840 side:

CONFIG_HCI_UART_LOG_LEVEL_DBG=y
CONFIG_NRF_SW_LPUART_LOG_LEVEL_DBG=y
CONFIG_BT_HCI_CORE_LOG_LEVEL_DBG=y
CONFIG_BT_HCI_DRIVER_LOG_LEVEL_DBG=y

I hope it helps. Let me know if I should turn off any. Now I will see about testing v2.5.0 and maybe other SDK levels.

Burt

[Burt]

v2.5.0 and v2.5.3 seem to work with no problems. More levels I need to test.

[Burt]

At v2.9.0 something is wrong with my hci_lpuart. When I hit the reset button with the processor switch in the nRF52 position, I only see one '*' on the console. When I try to run the program on the nRF9160, it fails somewhere in bt_enable().

[Burt]

I am pretty sure it is not me doing something stupid, but the code: v3.0.0 and v3.0.2 are working fine, but v3.1.0 and v3.1.1 both screw up.

Burt

[Burt]

Am I close--if git bisect has not failed me then the problem should be

(v3.1.0) burt@P51:~/ncs/testing/nrf$ git bisect good
e7a49bd24f3ecea5b63ef43d097a55b3bc96b4c9 is the first bad commit
commit e7a49bd24f3ecea5b63ef43d097a55b3bc96b4c9
Author: Krzysztof Chruściński <[email protected]>
Date:   Fri Mar 22 10:16:15 2024 +0100

    drivers: uart_nrf_sw_lpuart: Fix interrupt driven case
    
    Driver was calling isr function from unknown context when
    uart_irq_[rx,tx]_enable was called. It could lead to failures
    because driver assumes that isr function won't be interrupt
    by the same isr function.
    
    A solution proposed here is to use k_timer handler context
    which is called from RTC1 interrupt context. Assert is
    ensuring that RTC1 and UART interrupt priorities are the same.
    Timer is called from the shortest possible timeout and from
    that context isr function is called.
    
    Signed-off-by: Krzysztof Chruściński <[email protected]>
    (cherry picked from commit 22790df41c3d91ad47874a1bf8a32a77c4a92b8d)

 drivers/serial/uart_nrf_sw_lpuart.c | 50 ++++++++++++++++++++++++++++---------
 1 file changed, 38 insertions(+), 12 deletions(-)
(v3.1.0) burt@P51:~/ncs/testing/nrf$ 

First time I have ever used git bisect. Each time I updated with git bisect <good | bad> I then did a west update. Then did pristine builds for the two processors and flashed them.

[Vidar Berg]

Sorry for the delay. Thanks for posting the updates. It does seem like you may have found the culprit. However, this commit is quite old an was merged before v3.0.0. Have you tried reverting the changes from this commit in v3.1.1 to see if that alone resolves the issue?

Thanks,

Vidar

[Burt]

Hi Vidar, I did try reverting the changes from the commit in v3.1.1 and found that it resolved the issue. Of course, it is possible that doing that would open up the possibility of other issues arising--whatever Krzysztof Chruściński was trying to solve (not that I have not attempted to learn the details of nrf_sw_lpuart).

I see that the date of the commit is old, but I do not believe that this change was merged at that time. In fact, if I use gitk to look at the nrf repository at 3.1.x (or download the latest from GitHub) I can look at the commit and easily see that it follows v3.1.0-rc1 and precedes v3.1.0-rc2.

Hence, there is no inconsistency that I have only seen the problem in v3.1.0 and v3.1.1 (I have not downloaded release candidates to my build laptop). No inconsistency that the problem disappeared when reverting the change.

Burt

[Burt]

Hi Vidar,

Just to add to the complexity...

What if the nrf_sw_lpuart change was good, but the central_uart sample required changes to make it compatible...

I built samples/cellular/lte_ble_gateway, at v3.1.1, expecting to see the same issue as in central_uart. But it is different. It does not get stuck and timeout. On the other hand, it does start up with a bunch of warnings about req_pin low when expected high on the lpuart, and Empty receiver state:4 on the lpuart. These are when some lower-level code is doing a BT_HCI_OP_RESET. Then everything is fine. So, it just has ugly warnings and errors.

I hope you can go through both samples, along with the lpuart, and come up with something that works for both samples and ideally doesn't show errors and warnings if things are working properly.

Thanks, Vidar.

Burt