BLE scanning base on lte_ble_gateway and app crash

Hello, I made modifications based on the nrf9160 lte_ble_gateway demo. I modified the BLE.c file and changed the BLE connection to BLE scanning.
The scanning algorithm is as follows: idle for 1000ms, then scan for 90ms, and repeat the cycle. To ensure that the BLE scan time is not delayed for a long time, I use the K_TIMER timer. I submit work in the K_TIMER callback, and then start and stop Bluetooth scanning in the work.

I found that after scanning for a period of time, about 10-20 minutes, the application may crash.
In addition, there are many Bluetooth devices in my surrounding environment. Approximately 20 broadcast messages can be scanned within 90ms.

My own product has encountered this issue. I also reproduced this issue on the nrf9160dk_nrf9160(PCA10090 1.0.0) development board, with NCS version 2.2. The LTE modem version is 1.3.6.

Modify on lte_ble_gateway:

1. Modify the ble.c file, please see the attachment.

2. Add define in prj.conf. (CONFIG_BT_BUF_ACL_RX_SIZE=251)

3. Change the uart speed from 1000000 to 115200. (current-speed = <115200> in nrf9160dk_nrf9160_ns.overlay)

 52840 is based on hci_lpuart and only modifies the UART rate to 115200.

I tried to increase CONFIG_BT_BUF_ACL_RX_SIZE, but still encountered a crash. I am trying to reduce the number of BLE devices in the surrounding area, which will lower the probability of this problem occurring.  I speculate that it may be due to receiving a large number of Bluetooth broadcasts that the internal cache of the HCI driver is insufficient?

I hope you can help. thank you!

------------------------------

The crush log on nrf9160dk was:
[00:13:32.103,240] [1;31m<err> bt_driver: TX interrupt but no pending buffer![0m
[22:32:38.840]收←◆ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:335
k_sem_take failed with err -11
[00:13:42.115,631] [1;31m<err> os: r0/a1: 0x00000003 r1/a2: 0x00000000 r2/a3: 0x00000000[0m
[00:13:42.115,661] [1;31m<err> os: r3/a4: 0x00018b61 r12/ip: 0x00000000 r14/lr: 0x000119d7[0m
[00:13:42.115,661] [1;31m<err> os: xpsr: 0x41000000[0m
[00:13:42.115,692] [1;31m<err> os: Faulting instruction address (r15/pc): 0x000119e2[0m
[00:13:42.115,722] [1;31m<err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0[0m
[00:13:42.115,753] [1;31m<err> os: Current thread: 0x2000ef20 (unknown)[0m
[00:13:42.160,675] [1;31m<err> fatal_error: Resetting system[0m\0
[22:32:39.667]收←◆*** Booting Zephyr OS build v3.2.99-ncs1 ***

/*
 * Copyright (c) 2018 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */

#include <zephyr/kernel.h>

#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/gatt.h>
#include <zephyr/bluetooth/uuid.h>
#include <bluetooth/gatt_dm.h>
#include <bluetooth/scan.h>

#include <dk_buttons_and_leds.h>
#include <zephyr/sys/byteorder.h>

#include <net/nrf_cloud.h>
#include <zephyr/logging/log.h>
#include "aggregator.h"

LOG_MODULE_DECLARE(lte_ble_gw);


static void connected(struct bt_conn *conn, uint8_t conn_err)
{
}

static struct bt_conn_cb conn_callbacks = {
	.connected = connected,
};


static int gap_scan_num = 0;
static void ble_scan_no_filter_match(struct bt_scan_device_info *device_info, bool connectable)
{
	gap_scan_num++;
}

static void scan_timer_handler(struct k_timer *dummy);

BT_SCAN_CB_INIT(scan_cb, NULL, ble_scan_no_filter_match, NULL, NULL);
K_TIMER_DEFINE(scan_timer_id, scan_timer_handler, NULL);
static struct k_work gap_scan_worker;
static void scan_work_callback(struct k_work *work);

bool gap_is_scanning = false;
#define SCAN_INTERVAL_MS 1000

static void scan_timer_handler(struct k_timer *dummy)
{
	if (gap_is_scanning)
    {
    	k_timer_start(&scan_timer_id, K_MSEC(SCAN_INTERVAL_MS), K_NO_WAIT);
    }
    else
    {
        k_timer_start(&scan_timer_id, K_MSEC(90), K_NO_WAIT);
    }
    
	k_work_submit(&gap_scan_worker);
}


static struct bt_le_scan_param gap_scan_param =
{
	.type = BT_LE_SCAN_TYPE_PASSIVE,
	.options = (BT_LE_SCAN_OPT_FILTER_DUPLICATE),
	.interval = 0x10,
	.window = 0x10,
};

static struct bt_scan_init_param gap_scan_init =
{
	.connect_if_match = 0,
	.scan_param = &gap_scan_param,
	.conn_param = BT_LE_CONN_PARAM_DEFAULT,
};


static void scan_start(void)
{
	bt_scan_init(&gap_scan_init);
	bt_scan_cb_register(&scan_cb);

	k_timer_start(&scan_timer_id, K_MSEC(5000), K_NO_WAIT);
	LOG_INF("Scanning...");
}

static void ble_ready(int err)
{
	LOG_INF("Bluetooth ready");
	bt_conn_cb_register(&conn_callbacks);
	scan_start();
}

static void scan_work_callback(struct k_work *work)
{    	
	static uint32_t gap_total_start = 0;

	gap_total_start++;
    if (gap_is_scanning)
    {   
        int err = bt_scan_stop();
        if (err)
	    {
	        LOG_ERR("Fail to stop scan, err %d", err);
	        return;
	    }
	    else
	    {
	    	LOG_INF("Stop scan success:%d, num:%d", gap_scan_num, gap_total_start);
	    }
	    gap_is_scanning = false;
    }
    else
    {	
		gap_scan_num = 0;
        //check if need refresh scannning cfg before start scanning
        int err = bt_scan_start(BT_SCAN_TYPE_SCAN_PASSIVE);
	    if (err)
	    {
	    	LOG_ERR("Fail to start scan, err %d", err);
	    	return;
	    }
	    else
	    {
	    	LOG_INF("start scan success");
	    }
	    gap_is_scanning = true;
    }
}

/*
void nrf_ble_hardware_reset(void)
{
}
*/

void ble_init(void)
{
	int err;

	LOG_INF("Initializing Bluetooth..");
	err = bt_enable(ble_ready);
	if (err) {
		LOG_ERR("Bluetooth init failed (err %d)", err);
		return;
	}
	
    k_work_init(&gap_scan_worker, scan_work_callback);
}
9160dk_crash_log.txt

  • Hi,

    I am sorry for the late reply. I am looking into this and will get back to you tomorrow.

  • dHi,

    If the reset you shows in the nRF52840 (the BT Controller) is expected, then there is nothing specificaly indicating an issue on that side. But both asserts you get on the nRF91 are caused by communication issues, where the BT host implementation on the nRF91 is not ablet o communicate with the BT controller. The samples for both deviceds use LPUART with ASYNC uart with HW byte counting (CONFIG_UART_x_NRF_HW_ASYNC), so the UART communication should be stable in itself.

    Then there is the fact that you see this issue more often when there are more BT devices, which points in a different direction. Perhaps soem buffer or queue gets full and that is not handled properly. Based on the asserts you see on the 91, this points to the nRF52. So it would be interestin to add some BT debug logging on the nRF52840 and see if that will tell us more. Do you see anything interesting if you add CONFIG_BT_DEBUG_LOG=y to the hci_lpuart prj.conf? You can refer to or use the debug configuration for the sample.

  • Hi, I'm sorry for the delay in responding due to my vacation.
    I have add the configuration you suggested in the 52840 and test it again. In this test, 9160 starts a 90ms scan every 3000ms. From the log, we can see the nrf9160 starts scan every 3000ms, and the nrf52840 also has some LOG every 3000ms. 

    1. The following log is the last normal scan before reset.  I found every time a peripherial was scanned, nrf52840 will print the following log.
    -event_packet_process: LE Meta Event (0x02), len...

    From nrf9160 log, we can see it start scan and the stop scan normal. The log indication that it scaned 16 packet.
    ----------------------------------------------------------------------------------------------------------
    [01:24:54.855,285] [0m<inf> lte_ble_gw: scan_work_callback: start scan success[0m
    [01:24:54.935,363] [0m<inf> lte_ble_gw: scan_work_callback: Stop scan success:16, num:3298[0m

    From nrf52840 log, it also indication that it scaned 16 packet.
    -----------------------------------------------------------------
    [01:24:50.418,792] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.410,034] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.410,491] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.410,552] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.410,675] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    [01:24:53.410,705] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.410,736] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.410,766] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.410,797] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.411,132] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.411,285] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.411,407] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 9
    [01:24:53.411,499] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.411,529] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.411,529] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.411,590] <dbg> bt_hci_raw: bt_send: buf 0x2000da04 len 9
    [01:24:53.411,590] <dbg> sdc_hci_driver: hci_driver_send:
    [01:24:53.411,621] <dbg> sdc_hci_driver: cmd_handle:
    [01:24:53.411,682] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
    [01:24:53.411,712] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x2005) status: 0x00, ncmd: 1, len 4
    [01:24:53.411,743] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 6
    [01:24:53.412,048] <dbg> lpuart: api_tx: tx len:7
    [01:24:53.414,367] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.414,489] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.414,886] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.415,191] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.415,252] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.415,374] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    [01:24:53.415,405] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.415,435] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.415,435] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.415,496] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.415,802] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.415,954] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.416,076] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 10
    [01:24:53.416,137] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.416,168] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.416,198] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.416,229] <dbg> bt_hci_raw: bt_send: buf 0x2000da04 len 10
    [01:24:53.416,259] <dbg> sdc_hci_driver: hci_driver_send:
    [01:24:53.416,259] <dbg> sdc_hci_driver: cmd_handle:
    [01:24:53.416,320] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
    [01:24:53.416,381] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x200b) status: 0x00, ncmd: 1, len 4
    [01:24:53.416,412] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 6
    [01:24:53.416,717] <dbg> lpuart: api_tx: tx len:7
    [01:24:53.418,945] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.419,036] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.419,433] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.419,738] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.419,799] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.419,921] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    [01:24:53.419,952] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.419,982] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.419,982] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.420,043] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.420,349] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.420,471] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.420,562] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 5
    [01:24:53.420,623] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.420,654] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.420,684] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.420,745] <dbg> bt_hci_raw: bt_send: buf 0x2000da04 len 5
    [01:24:53.420,776] <dbg> sdc_hci_driver: hci_driver_send:
    [01:24:53.420,776] <dbg> sdc_hci_driver: cmd_handle:
    [01:24:53.420,928] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
    [01:24:53.420,959] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x200c) status: 0x00, ncmd: 1, len 4
    [01:24:53.420,989] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 6
    [01:24:53.421,295] <dbg> lpuart: api_tx: tx len:7
    [01:24:53.423,553] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.423,675] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.425,384] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (37)
    [01:24:53.425,415] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 39
    [01:24:53.425,689] <dbg> lpuart: api_tx: tx len:40
    [01:24:53.427,886] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.428,314] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.428,680] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.428,710] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.428,985] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.429,718] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
    [01:24:53.429,748] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 45
    [01:24:53.431,152] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.431,640] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.431,701] <dbg> lpuart: api_tx: tx len:46
    [01:24:53.434,051] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.434,539] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.435,699] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
    [01:24:53.435,729] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 45
    [01:24:53.436,004] <dbg> lpuart: api_tx: tx len:46
    [01:24:53.438,201] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.438,690] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.445,373] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.445,404] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.445,678] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.446,105] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (37)
    [01:24:53.446,136] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 39
    [01:24:53.448,028] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.448,547] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.448,577] <dbg> lpuart: api_tx: tx len:40
    [01:24:53.449,645] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.449,676] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.450,927] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.451,385] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.451,416] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.453,796] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.454,284] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.457,794] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (37)
    [01:24:53.457,824] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 39
    [01:24:53.458,099] <dbg> lpuart: api_tx: tx len:40
    [01:24:53.460,479] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.460,906] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.462,249] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.462,310] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.462,585] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.464,752] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.465,240] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.466,339] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (36)
    [01:24:53.466,400] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 38
    [01:24:53.466,674] <dbg> lpuart: api_tx: tx len:39
    [01:24:53.468,841] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.469,207] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.469,268] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.469,299] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.469,573] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.471,740] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.472,229] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.479,858] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
    [01:24:53.479,888] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 32
    [01:24:53.480,163] <dbg> lpuart: api_tx: tx len:33
    [01:24:53.482,543] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.482,910] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.484,283] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (37)
    [01:24:53.484,313] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 39
    [01:24:53.484,588] <dbg> lpuart: api_tx: tx len:40
    [01:24:53.486,785] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.487,213] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.487,945] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
    [01:24:53.487,976] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 44
    [01:24:53.488,281] <dbg> lpuart: api_tx: tx len:45
    [01:24:53.490,447] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.490,936] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.495,056] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
    [01:24:53.495,086] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 45
    [01:24:53.495,361] <dbg> lpuart: api_tx: tx len:46
    [01:24:53.497,711] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.498,229] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.498,291] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (38)
    [01:24:53.498,321] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 40
    [01:24:53.498,596] <dbg> lpuart: api_tx: tx len:41
    [01:24:53.498,687] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.498,779] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.498,870] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.498,962] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    [01:24:53.498,992] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.499,023] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.499,053] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.499,084] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:53.499,145] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:53.499,237] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:53.499,359] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 5
    [01:24:53.499,420] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:53.499,450] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:53.499,481] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:53.499,542] <dbg> bt_hci_raw: bt_send: buf 0x2000da04 len 5
    [01:24:53.499,542] <dbg> sdc_hci_driver: hci_driver_send:
    [01:24:53.499,572] <dbg> sdc_hci_driver: cmd_handle:
    [01:24:53.499,694] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
    [01:24:53.499,786] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x200c) status: 0x00, ncmd: 1, len 4
    [01:24:53.499,816] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 6
    [01:24:53.500,762] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.501,220] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:53.501,251] <dbg> lpuart: api_tx: tx len:7
    [01:24:53.503,631] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:53.503,753] <dbg> lpuart: tx_complete: TX completed, pin idle

    2. The following logs shows that nrf9160 encountered error and reset.
    nrf9160 log
    ---------------------------
    [01:24:57.945,251] [0m<inf> lte_ble_gw: scan_work_callback: start scan success[0m
    [01:24:58.019,958] [1;31m<err> bt_driver: process_tx: TX interrupt but no pending buffer![0m
    ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:329

    The following is the corresponding log for nrf52840. It seens that NRF52840 received a start scan request and start scan success.
    It shows that nrf52840 has been scanning continuously and scaned 187 peripherial packet. I thins it because 52840 does not receive stop scan request from nrf9160.

    Also In this log, a large number of logs were dropped, I thorough it may because 9160 was reset. I tried manually resetting 9160 during the 52840 scanning process, there will also be a large number of dropped log.
    -----------------------------------------------------------------
    [01:24:56.499,969] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:56.500,427] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:56.500,488] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:56.500,610] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    [01:24:56.500,640] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:56.500,671] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:56.500,701] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:56.500,732] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:56.501,037] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:56.501,220] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:56.501,342] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 9
    [01:24:56.501,403] <dbg> lpuart: uart_callback: Rx buf released
    [01:24:56.501,434] <dbg> lpuart: uart_callback: Rx disabled
    [01:24:56.501,464] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
    [01:24:56.501,495] <dbg> bt_hci_raw: bt_send: buf 0x2000da04 len 9
    [01:24:56.501,525] <dbg> sdc_hci_driver: hci_driver_send:
    [01:24:56.501,525] <dbg> sdc_hci_driver: cmd_handle:
    [01:24:56.501,586] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
    [01:24:56.501,647] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x2005) status: 0x00, ncmd: 1, len 4
    [01:24:56.501,678] <dbg> bt_hci_raw: bt_recv: buf 0x2000dc50 len 6
    [01:24:56.501,953] <dbg> lpuart: api_tx: tx len:7
    [01:24:56.504,302] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
    [01:24:56.504,394] <dbg> lpuart: tx_complete: TX completed, pin idle
    [01:24:56.504,791] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
    [01:24:56.505,096] <dbg> lpuart: activate_rx: RX: Ready
    [01:24:56.505,157] <dbg> lpuart: rdy_pin_handler: RX: End detected.
    [01:24:56.505,279] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    --- 19 messages dropped ---
    [01:24:56.509,826] <dbg> lpuart: uart_callback: RX: Ready buf:0x20004bb4, offset: 0,len: 1
    --- 17 messages dropped ---
    [01:24:56.511,230] <dbg> lpuart: api_tx: tx len:7
    --- 13 messages dropped ---
    [01:24:56.523,651] <dbg> lpuart: tx_complete: TX completed, pin idle
    --- 15 messages dropped ---
    [01:24:56.535,247] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
    --- 21 messages dropped ---
    [01:24:56.547,668] <dbg> lpuart: tx_complete: TX completed, pin idle
    --- 9 messages dropped ---
    [01:24:56.554,779] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.

    The attachment are the log file of 52840 and 9160, lpuart prj file, and the project of lte_ble_gateway.  The log file for 52840 is quite large, so I have cropped the rest of the content.

    test_log.zip

  • Hi,

    I am sorry for the delay. I will look into this and get bac to you next week.

  • Hi,

    A short update from my. Using  your project and nRF Connect SDK 2.2.0 I am able to reproduce the issue, but I do not have an explanation for the cause. I will continue to look into it.

Related