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

Parents
  • Hi,

    Can you double check which SDK version you are using, and if you have any changes on your end? I ask as there is no assert on line 335 in zephyr/subsys/bluetooth/host/hci_core.c in nRF Connect SDK 2.2.0.

    That said, it looks like communication issues with the network core. Do you have logs for the network core as well? If so, can you share those?

    Br,

    Einar

  • Sorry, we added a function in hci_core.c that resulted in incorrect numbering.
    I have re-downloaded Version SDK 2.2.0. We have retested and there are still issues.
    In this test, We did not make any modifications to the prj.conf file and overlay file. Keeping UART at the default rate of 1000000 and not modifying the ACL_SX size. To avoid the influence of LTE modems, we have comments the LTE section.

    Test condition:
    -SDK version: v2.2.0
    -tools: nrf9160dk, hardware version: v1.1.3
    -hci_lpuart:
    * not change prj.conf and overlay file
    -lte_ble_gateway
    * replace the ble.c file
    * comments the lte code
    void main(void)
    {
    LOG_INF("LTE Sensor Gateway sample started");

    buttons_leds_init();
    ble_init();

    //work_init();
    //cloud_init();
    //modem_configure();
    //cloud_connect(NULL);
    }

    Error log on sdk 2.2:

    sdk2.2_error_log.txt

    We also conducted a test on SDK 2.6. We did not make any modifications to the prj.conf file and overlay file. Keeping UART at the default rate of 1000000 and not modifying the ACL_SX size, but kept the LTE code. During testing, some errors were also encountered.

    Test condition:
    -SDK version: v2.6.0
    -tools: nrf9160dk, hardware version: v1.1.3
    -hci_lpuart:
    * not change prj.conf and overlay file
    -lte_ble_gateway
    * replace the ble.c file

    Error log on SDK2.6.0:

    1. Test condition:
    ----------------------------
    -SDK version: v2.6.0
    -tools: nrf9160dk, hardware version: v1.1.3
    -lte_ble_gateway: 
      *not change prj.conf and overlay file.
      *only replace ble.c.
      
    -hci_lpuart:(no change) 
      *not change prj.conf and overlay file.
    
    
    2. Test Log on lte_ble_gateway:
    ----------------------------------------------
    [09:18:02.179]收←◆*** Booting nRF Connect SDK v3.5.99-ncs1-1-1-g02ae5d8ded21 ***
    [00:00:00.363,922] <inf> lte_ble_gw: LTE Sensor Gateway sample started
    [00:00:00.364,135] <inf> lte_ble_gw: Initializing Bluetooth..
    
    [09:18:02.932]收←◆[00:00:00.617,889] <inf> lte_ble_gw: Establishing LTE link (this may take some time) ...
    [00:00:01.067,382] <wrn> bt_hci_core: opcode 0x0000 pool id 3 pool 0x2000d040 != &hci_cmd_pool 0x2000d0a8
    [00:00:01.109,497] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:01.109,527] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    [00:00:01.109,558] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    [00:00:01.118,194] <inf> bt_hci_core: Identity: D4:CB:39:15:51:B3 (random)
    [00:00:01.118,225] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    [00:00:01.118,255] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    [00:00:01.118,255] <inf> lte_ble_gw: Bluetooth ready
    [00:00:01.118,316] <inf> lte_ble_gw: Scanning...
    
    [09:18:08.940]收←◆[00:00:06.125,854] <inf> lte_ble_gw: start scan success
    [00:00:06.209,716] <inf> lte_ble_gw: Stop scan success:33, num:2
    
    [09:18:10.031]收←◆[00:00:07.215,820] <inf> lte_ble_gw: start scan success
    [00:00:07.299,743] <inf> lte_ble_gw: Stop scan success:30, num:4
    
    [09:18:11.119]收←◆[00:00:08.305,847] <inf> lte_ble_gw: start scan success
    [00:00:08.391,448] <inf> lte_ble_gw: Stop scan success:30, num:6
    
    [09:18:12.210]收←◆[00:00:09.395,874] <inf> lte_ble_gw: start scan success
    [00:00:09.479,980] <inf> lte_ble_gw: Stop scan success:30, num:8
    
    [09:18:13.299]收←◆[00:00:10.485,870] <inf> lte_ble_gw: start scan success
    [00:00:10.569,824] <inf> lte_ble_gw: Stop scan success:29, num:10
    
    [09:18:14.389]收←◆[00:00:11.575,927] <inf> lte_ble_gw: start scan success
    [00:00:11.659,851] <inf> lte_ble_gw: Stop scan success:27, num:12
    
    [09:18:15.480]收←◆[00:00:12.665,985] <inf> lte_ble_gw: start scan success
    [00:00:12.749,908] <inf> lte_ble_gw: Stop scan success:28, num:14
    
    [09:18:16.570]收←◆[00:00:13.755,950] <inf> lte_ble_gw: start scan success
    [00:00:13.839,904] <inf> lte_ble_gw: Stop scan success:21, num:16
    
    [09:18:17.659]收←◆[00:00:14.846,008] <inf> lte_ble_gw: start scan success
    [00:00:14.930,603] <inf> lte_ble_gw: Stop scan success:27, num:18
    
    [09:18:18.750]收←◆[00:00:15.936,035] <inf> lte_ble_gw: start scan success
    [00:00:16.020,019] <inf> lte_ble_gw: Stop scan success:24, num:20
    
    [09:18:19.840]收←◆[00:00:17.026,062] <inf> lte_ble_gw: start scan success
    [00:00:17.110,046] <inf> lte_ble_gw: Stop scan success:31, num:22
    
    [09:18:20.930]收←◆[00:00:18.116,088] <inf> lte_ble_gw: start scan success
    [00:00:18.200,286] <inf> lte_ble_gw: Stop scan success:23, num:24
    
    [09:18:22.021]收←◆[00:00:19.206,146] <inf> lte_ble_gw: start scan success
    [00:00:19.290,039] <inf> lte_ble_gw: Stop scan success:26, num:26
    
    [09:18:23.110]收←◆[00:00:20.296
    [09:18:23.133]收←◆,142] <inf> lte_ble_gw: start scan success
    [00:00:20.380,065] <inf> lte_ble_gw: Stop scan success:25, num:28
    
    [09:18:24.200]收←◆[00:00:21.386,199] <inf> lte_ble_gw: start scan success
    [00:00:21.471,008] <inf> lte_ble_gw: Stop scan success:34, num:30
    
    [09:18:25.291]收←◆[00:00:22.476,196] <inf> lte_ble_gw: start scan success
    [00:00:22.560,119] <inf> lte_ble_gw: Stop scan success:29, num:32
    
    [09:18:26.380]收←◆[00:00:23.566,223] <inf> lte_ble_gw: start scan success
    [00:00:23.650,146] <inf> lte_ble_gw: Stop scan success:22, num:34
    
    [09:18:27.470]收←◆[00:00:24.656
    [09:18:27.487]收←◆,250] <inf> lte_ble_gw: start scan success
    [00:00:24.740,173] <inf> lte_ble_gw: Stop scan success:21, num:36
    
    [09:18:28.560]收←◆[00:00:
    [09:18:28.581]收←◆25.746,307] <inf> lte_ble_gw: start scan success
    [00:00:25.830,383] <inf> lte_ble_gw: Stop scan success:36, num:38
    
    [09:18:29.650]收←◆[00:00:26.836,303] <inf> lte_ble_gw: start scan success
    [00:00:26.921,112] <inf> lte_ble_gw: Stop scan success:25, num:40
    
    [09:18:30.740]收←◆[00:00:27.926,330] <inf> lte_ble_gw: start scan success
    [00:00:28.010,253] <inf> lte_ble_gw: Stop scan success:22, num:42
    
    [09:18:31.830]收←◆[00:00:29.016,387] <inf> lte_ble_gw: start scan success
    [00:00:29.100,372] <inf> lte_ble_gw: Stop scan success:21, num:44
    
    [09:18:32.920]收←◆[00:00:30.106,384] <inf> lte_ble_gw: start scan success
    [00:00:30.190,307] <inf> lte_ble_gw: Stop scan success:37, num:46
    
    [09:18:34.010]收←◆[00:00:31.196,380] <inf> lte_ble_gw: start scan success
    [00:00:31.280,792] <inf> lte_ble_gw: Stop scan success:27, num:48
    
    [09:18:35.100]收←◆[00:00:32.286,437] <inf> lte_ble_gw: start scan success
    [00:00:32.370,361] <inf> lte_ble_gw: Stop scan success:34, num:50
    
    [09:18:36.190]收←◆[00:00:33.376,464] <inf> lte_ble_gw: start scan success
    [00:00:33.460,388] <inf> lte_ble_gw: Stop scan success:34, num:52
    
    [09:18:37.280]收←◆[00:00:34.466,491] <inf> lte_ble_gw: start scan success
    [00:00:34.550,750] <inf> lte_ble_gw: Stop scan success:29, num:54
    
    [09:18:38.370]收←◆[00:00:35.556,549] <inf> lte_ble_gw: start scan success
    [00:00:35.640,441] <inf> lte_ble_gw: Stop scan success:39, num:56
    
    [09:18:39.460]收←◆[00:00:36.646,545] <inf> lte_ble_gw: start scan success
    [00:00:36.730,560] <inf> lte_ble_gw: Stop scan success:30, num:58
    
    [09:18:40.550]收←◆[00:00:37.736,572] <inf> lte_ble_gw: start scan success
    [00:00:37.820,495] <inf> lte_ble_gw: Stop scan success:26, num:60
    
    [09:18:41.640]收←◆[00:00:38.826,629] <inf> lte_ble_gw: start scan success
    [00:00:38.910,705] <inf> lte_ble_gw: Stop scan success:36, num:62
    
    [09:18:42.731]收←◆[00:00:39.916,625] <inf> lte_ble_gw: start scan success
    [00:00:40.000,579] <inf> lte_ble_gw: Stop scan success:28, num:64
    
    [09:18:43.820]收←◆[00:00:41.006,652] <inf> lte_ble_gw: start scan success
    [00:00:41.091,918] <inf> lte_ble_gw: Stop scan success:28, num:66
    
    [09:18:44.910]收←◆[00:00:42.096,679] <inf> lte_ble_gw: start scan success
    [00:00:42.181,518] <inf> lte_ble_gw: Stop scan success:28, num:68
    
    [09:18:46.000]收←◆[00:00:43.186,706] <inf> lte_ble_gw: start scan success
    [00:00:43.271,209] <inf> lte_ble_gw: Stop scan success:27, num:70
    
    [09:18:47.090]收←◆[00:00:44.276,733] <inf> lte_ble_gw: start scan success
    [00:00:44.361,663] <inf> lte_ble_gw: Stop scan success:29, num:72
    
    [09:18:48.181]收←◆[00:00:45.366,760] <inf> lte_ble_gw: start scan success
    [00:00:45.450,897] <inf> lte_ble_gw: Stop scan success:28, num:74
    
    [09:18:49.270]收←◆[00:00:46.456,787] <inf> lte_ble_gw: start scan success
    [00:00:46.541,717] <inf> lte_ble_gw: Stop scan success:23, num:76
    
    [09:18:50.360]收←◆[00:00:47.546,813] <inf> lte_ble_gw: start scan success
    [00:00:47.631,652] <inf> lte_ble_gw: Stop scan success:32, num:78
    
    [09:18:51.449]收←◆[00:00:48.636,871] <inf> lte_ble_gw: start scan success
    [00:00:48.720,794] <inf> lte_ble_gw: Stop scan success:33, num:80
    
    [09:18:52.542]收←◆[00:00:49.726,867] <inf> lte_ble_gw: start scan success
    [00:00:49.811,737] <inf> lte_ble_gw: Stop scan success:30, num:82
    
    [09:18:53.631]收←◆[00:00:50.816,894] <inf> lte_ble_gw: start scan success
    [00:00:50.900,817] <inf> lte_ble_gw: Stop scan success:29, num:84
    
    [09:18:54.721]收←◆[00:00:51.906,951] <inf> lte_ble_gw: start scan success
    [00:00:51.991,394] <inf> lte_ble_gw: Stop scan success:25, num:86
    
    [09:18:55.811]收←◆[00:00:52.996,
    [09:18:55.832]收←◆948] <inf> lte_ble_gw: start scan success
    [00:00:53.080,871] <inf> lte_ble_gw: Stop scan success:26, num:88
    
    [09:18:56.901]收←◆[00:00:54.086,944] <inf> lte_ble_gw: start scan success
    [00:00:54.171,752] <inf> lte_ble_gw: Stop scan success:27, num:90
    
    [09:18:57.993]收←◆[00:00:55.177,001] <inf> lte_ble_gw: start scan success
    [00:00:55.260,925] <inf> lte_ble_gw: Stop scan success:27, num:92
    
    [09:18:59.080]收←◆[00:00:56.267,028] <inf> lte_ble_gw: start scan success
    [00:00:56.352,020] <inf> lte_ble_gw: Stop scan success:31, num:94
    
    [09:19:00.171]收←◆[00:00:57.357,055] <inf> lte_ble_gw: start scan success
    [00:00:57.440,979] <inf> lte_ble_gw: Stop scan success:25, num:96
    
    [09:19:01.260]收←◆[00:00:58.447,113] <inf> lte_ble_gw: start scan success
    [00:00:58.531,494] <inf> lte_ble_gw: Stop scan success:31, num:98
    
    [09:19:02.350]收←◆[00:00:59.537,109] <inf> lte_ble_gw: start scan success
    [00:00:59.621,032] <inf> lte_ble_gw: Stop scan success:37, num:100
    
    [09:19:03.440]收←◆[00:01:00.627,136] <inf> lte_ble_gw: start scan success
    [00:01:00.711,975] <inf> lte_ble_gw: Stop scan success:34, num:102
    
    [09:19:04.531]收←◆[00:01:01.717,163] <inf> lte_ble_gw: start scan success
    [00:01:01.801,849] <inf> lte_ble_gw: Stop scan success:27, num:104
    
    [09:19:05.621]收←◆[00:01:02.807,189] <inf> lte_ble_gw: start scan success
    [00:01:02.892,089] <inf> lte_ble_gw: Stop scan success:28, num:106
    
    [09:19:06.711]收←◆[00:01:03.897,216] <inf> lte_ble_gw: start scan success
    [00:01:03.981,140] <inf> lte_ble_gw: Stop scan success:31, num:108
    
    [09:19:07.801]收←◆[00:01:04.987,274] <inf> lte_ble_gw: start scan success
    [00:01:05.071,166] <inf> lte_ble_gw: Stop scan success:29, num:110
    
    [09:19:08.891]收←◆[00:01:
    [09:19:08.912]收←◆06.077,270] <inf> lte_ble_gw: start scan success
    [00:01:06.161,193] <inf> lte_ble_gw: Stop scan success:28, num:112
    
    [09:19:09.981]收←◆[00:01:07.167,297] <inf> lte_ble_gw: start scan success
    [00:01:07.251,464] <inf> lte_ble_gw: Stop scan success:27, num:114
    
    [09:19:11.071]收←◆[00:01:08.257,354] <inf> lte_ble_gw: start scan success
    [00:01:08.341,247] <inf> lte_ble_gw: Stop scan success:24, num:116
    
    [09:19:12.161]收←◆[00:01:09.347,351] <inf> lte_ble_gw: start scan success
    [00:01:09.431,274] <inf> lte_ble_gw: Stop scan success:30, num:118
    
    [09:19:13.252]收←◆[00:01:10.437,377] <inf> lte_ble_gw: start scan success
    [00:01:10.521,301] <inf> lte_ble_gw: Stop scan success:24, num:120
    
    [09:19:14.341]收←◆[00:01:11.527,435] <inf> lte_ble_gw: start scan success
    [00:01:11.611,328] <inf> lte_ble_gw: Stop scan success:29, num:122
    
    [09:19:15.431]收←◆[00:01:12.617,431] <inf> lte_ble_gw: start scan success
    [00:01:12.701,934] <inf> lte_ble_gw: Stop scan success:25, num:124
    
    [09:19:16.521]收←◆[00:01:13.707,458] <inf> lte_ble_gw: start scan success
    [00:01:13.791,595] <inf> lte_ble_gw: Stop scan success:30, num:126
    
    [09:19:17.611]收←◆[00:01:14.797,515] <inf> lte_ble_gw: start scan success
    [00:01:14.881,408] <inf> lte_ble_gw: Stop scan success:19, num:128
    
    [09:19:18.701]收←◆[00:01:1
    [09:19:18.722]收←◆5.887,512] <inf> lte_ble_gw: start scan success
    [00:01:15.971,618] <inf> lte_ble_gw: Stop scan success:23, num:130
    
    [09:19:19.792]收←◆[00:01:16.977,508] <inf> lte_ble_gw: start scan success
    [00:01:17.061,492] <inf> lte_ble_gw: Stop scan success:27, num:132
    
    [09:19:20.882]收←◆[00:01:18.067,596] <inf> lte_ble_gw: start scan success
    [00:01:18.151,489] <inf> lte_ble_gw: Stop scan success:25, num:134
    
    [09:19:21.972]收←◆[00:01:19.157,592] <inf> lte_ble_gw: start scan success
    [00:01:19.242,584] <inf> lte_ble_gw: Stop scan success:25, num:136
    
    [09:19:23.062]收←◆[00:01:20.247,619] <inf> lte_ble_gw: start scan success
    [00:01:20.332,122] <inf> lte_ble_gw: Stop scan success:24, num:138
    
    [09:19:24.151]收←◆[00:01:21.337,646] <inf> lte_ble_gw: start scan success
    [00:01:21.421,569] <inf> lte_ble_gw: Stop scan success:35, num:140
    
    [09:19:25.241]收←◆[00:01:22.427,642] <inf> lte_ble_gw: start scan success
    [00:01:22.511,993] <inf> lte_ble_gw: Stop scan success:33, num:142
    
    [09:19:26.331]收←◆[00:01:23.517,700] <inf> lte_ble_gw: start scan success
    [00:01:23.601,623] <inf> lte_ble_gw: Stop scan success:35, num:144
    
    [09:19:27.422]收←◆[00:01:24.607
    [09:19:27.440]收←◆,757] <inf> lte_ble_gw: start scan success
    [00:01:24.691,986] <inf> lte_ble_gw: Stop scan success:32, num:146
    
    [09:19:28.511]收←◆[00:01:25.697,753] <inf> lte_ble_gw: start scan success
    [00:01:25.781,951] <inf> lte_ble_gw: Stop scan success:30, num:148
    
    [09:19:29.602]收←◆[00:01:26.787,811] <inf> lte_ble_gw: start scan success
    [00:01:26.872,711] <inf> lte_ble_gw: Stop scan success:31, num:150
    
    [09:19:30.692]收←◆[00:01:27.877,807] <inf> lte_ble_gw: start scan success
    [00:01:27.961,822] <inf> lte_ble_gw: Stop scan success:27, num:152
    
    [09:19:31.781]收←◆[00:01:28.967,834] <inf> lte_ble_gw: start scan success
    [00:01:29.052,551] <inf> lte_ble_gw: Stop scan success:30, num:154
    
    [09:19:32.871]收←◆[00:01:30.057,861] <inf> lte_ble_gw: start scan success
    [00:01:30.141,906] <inf> lte_ble_gw: Stop scan success:31, num:156
    
    [09:19:33.961]收←◆[00:01:31.147,857] <inf> lte_ble_gw: start scan success
    [00:01:31.231,872] <inf> lte_ble_gw: Stop scan success:27, num:158
    
    [09:19:35.052]收←◆[00:01:32.237,945] <inf> lte_ble_gw: start scan success
    [00:01:32.321,960] <inf> lte_ble_gw: Stop scan success:27
    [09:19:35.082]收←◆, num:160
    
    [09:19:36.142]收←◆[00:01:33.327,941] <inf> lte_ble_gw: start scan success
    [00:01:33.412,200] <inf> lte_ble_gw: Stop scan success:25, num:162
    
    [09:19:37.232]收←◆[00:01:34.417,968] <inf> lte_ble_gw: start scan success
    [00:01:34.501,892] <inf> lte_ble_gw: Stop scan success:30, num:164
    
    [09:19:38.322]收←◆[00:01:35.508,026] <inf> lte_ble_gw: start scan success
    [00:01:35.593,109] <inf> lte_ble_gw: Stop scan success:30, num:166
    
    [09:19:39.411]收←◆[00:01:36.597,991] <inf> lte_ble_gw: start scan success
    [00:01:36.682,403] <inf> lte_ble_gw: Stop scan success:28, num:168
    
    [09:19:40.501]收←◆[00:01:37.688,049] <inf> lte_ble_gw: start scan success
    [00:01:37.772,155] <inf> lte_ble_gw: Stop scan success:32, num:170
    
    [09:19:41.592]收←◆[00:01:38.778,106] <inf> lte_ble_gw: start scan success
    [00:01:38.861,999] <inf> lte_ble_gw: Stop scan success:23, num:172
    
    [09:19:42.682]收←◆[00:01:39.868,103] <inf> lte_ble_gw: start scan success
    [00:01:39.952,209] <inf> lte_ble_gw: Stop scan success:37, num:174
    
    [09:19:43.771]收←◆[00:01:40.958,129] <inf> lte_ble_gw: start scan success
    [00:01:41.042,053] <inf> lte_ble_gw: Stop scan success:28, num:176
    
    [09:19:44.862]收←◆[00:01:42.048,187] <inf> lte_ble_gw: start scan success
    [00:01:42.132,080] <inf> lte_ble_gw: Stop scan success:24, num:178
    
    [09:19:45.952]收←◆[00:01:43.138,183] <inf> lte_ble_gw: start scan success
    [00:01:43.222,106] <inf> lte_ble_gw: Stop scan success:23, num:180
    
    [09:19:47.041]收←◆[00:01:44.228,210] <inf> lte_ble_gw: start scan success
    [00:01:44.312,133] <inf> lte_ble_gw: Stop scan success:25, num:182
    
    [09:19:48.132]收←◆[00:01:45.318,267] <inf> lte_ble_gw: start scan success
    [00:01:45.402,160] <inf> lte_ble_gw: Stop scan success:23, num:184
    
    [09:19:49.222]收←◆[00:01:46.408,264] <inf> lte_ble_gw: start scan success
    [00:01:46.492,187] <inf> lte_ble_gw: Stop scan success:31, num:186
    
    [09:19:50.312]收←◆[00:01:47.498,291] <inf> lte_ble_gw: start scan success
    [00:01:47.582,305] <inf> lte_ble_gw: Stop scan success:28, num:188
    
    [09:19:51.402]收←◆[00:01:48.588,348] <inf> lte_ble_gw: start scan success
    [00:01:48.672,241] <inf> lte_ble_gw: Stop scan success:22, num:190
    
    [09:19:52.493]收←◆[00:01:49.678,344] <inf> lte_ble_gw: start scan success
    [00:01:49.762,420] <inf> lte_ble_gw: Stop scan success:37, num:192
    
    [09:19:53.582]收←◆[00:01:50.768,341] <inf> lte_ble_gw: start scan success
    [00:01:50.852,325] <inf> lte_ble_gw: Stop scan success:34, num:194
    
    [09:19:54.672]收←◆[00:01:51.858,428] <inf> lte_ble_gw: start scan success
    [00:01:51.942,535] <inf> lte_ble_gw: Stop scan success:30, num:196
    
    [09:19:55.762]收←◆[00:01:52.948,425] <inf> lte_ble_gw: start scan success
    [00:01:53.032,379] <inf> lte_ble_gw: Stop scan success:24, num:198
    
    [09:19:56.852]收←◆[00:01:54.038,452] <inf> lte_ble_gw: start scan success
    [00:01:54.123,260] <inf> lte_ble_gw: Stop scan success:30, num:200
    
    [09:19:57.942]收←◆[00:01:55.128,479] <inf> lte_ble_gw: start scan success
    [00:01:55.212,402] <inf> lte_ble_gw: Stop scan success:24, num:202
    
    [09:19:59.032]收←◆[00:01:56.218,505] <inf> lte_ble_gw: start scan success
    [00:01:56.303,283] <inf> lte_ble_gw: Stop scan success:23, num:204
    
    [09:20:00.122]收←◆[00:01:57.308,532] <inf> lte_ble_gw: start scan success
    [00:01:57.392,486] <inf> lte_ble_gw: Stop scan success:31, num:206
    
    [09:20:01.219]收←◆[00:01:58.404,968] <inf> lte_ble_gw: start scan success
    [00:01:58.482,574] <inf> lte_ble_gw: Stop scan success:30, num:208
    
    [09:20:02.303]收←◆[00:01:59.488,555] <inf> lte_ble_gw: start scan success
    [00:01:59.572,509] <inf> lte_ble_gw: Stop scan success:27, num:210
    
    [09:20:03.392]收←◆[00:02:00.578,613] <inf> lte_ble_gw: start scan success
    [00:02:00.662,719] <inf> lte_ble_gw: Stop scan success:28, num:212
    
    [09:20:04.482]收←◆[00:02:01.668,640] <inf> lte_ble_gw: start scan success
    [00:02:01.752,685] <inf> lte_ble_gw: Stop scan success:34, num:214
    
    [09:20:05.572]收←◆[00:02:02.758,697] <inf> lte_ble_gw: start scan success
    [00:02:02.842,590] <inf> lte_ble_gw: Stop scan success:27, num:216
    
    [09:20:06.662]收←◆[00:02:03.848,693] <inf> lte_ble_gw: start scan success
    [00:02:03.933,349] <inf> lte_ble_gw: Stop scan success:34, num:218
    
    [09:20:07.752]收←◆[00:02:04.938,690] <inf> lte_ble_gw: start scan success
    [00:02:05.022,766] <inf> lte_ble_gw: Stop scan success:26, num:220
    
    [09:20:08.849]收←◆[00:02:06.035,095] <inf> lte_ble_gw: start scan success
    [00:02:06.123,321] <inf> lte_ble_gw: Stop scan success:22, num:222
    
    [09:20:09.939]收←◆[00:02:07.125,091] <inf> lte_ble_gw: start scan success
    [00:02:07.207,580] <inf> lte_ble_gw: Stop scan success:25, num:224
    
    [09:20:11.023]收←◆[00:02:08.208,801] <inf> lte_ble_gw: start scan success
    +CEREG: 2,"7859","0779FC51",9
    [00:02:08.292,785] <inf> lte_ble_gw: Stop scan success:29, num:226
    
    [09:20:12.119]收←◆[00:02:09.305,145] <inf> lte_ble_gw: start scan success
    [00:02:09.392,425] <inf> lte_ble_gw: Stop scan success:24, num:228
    
    [09:20:13.203]收←◆[00:02:10.388,885] <inf> lte_ble_gw: start scan success
    [00:02:10.472,900] <inf> lte_ble_gw: Stop scan success:30, num:230
    
    [09:20:14.299]收←◆[00:02:11.485,198] <inf> lte_ble_gw: start scan success
    [00:02:11.580,383] <inf> lte_ble_gw: Stop scan success:30, num:232
    
    [09:20:15.389]收←◆[00:02:12
    [09:20:15.409]收←◆.575,256] <inf> lte_ble_gw: start scan success
    [00:02:12.659,362] <inf> lte_ble_gw: Stop scan success:29, num:234
    
    [09:20:16.478]收←◆[00:02:13.665,252] <inf> lte_ble_gw: start scan success
    [00:02:13.745,117] <inf> lte_ble_gw: Stop scan success:24, num:236
    
    [09:20:17.569]收←◆[00:02:14.755,279] <inf> lte_ble_gw: start scan success
    [00:02:14.842,895] <inf> lte_ble_gw: Stop scan success:28, num:238
    
    [09:20:18.660]收←◆[00:02:15.845,336] <inf> lte_ble_gw: start scan success
    [00:02:15.928,405] <inf> lte_ble_gw: Stop scan success:24, num:240
    
    [09:20:19.749]收←◆[00:02:16.935,333] <inf> lte_ble_gw: start scan success
    [00:02:17.028,259] <inf> lte_ble_gw: Stop scan success:28, num:242
    
    [09:20:20.833]收←◆[00:02:18.019,042] <inf> lte_ble_gw: start scan success
    [00:02:18.103,179] <inf> lte_ble_gw: Stop scan success:31, num:244
    
    [09:20:21.929]收←◆[00:02:19.115,386] <inf> lte_ble_gw: start scan success
    [00:02:19.196,472] <inf> lte_ble_gw: Stop scan success:24, num:246
    
    [09:20:23.020]收←◆[00:02:20.205,413] <inf> lte_ble_gw: start scan success
    [00:02:20.290,283] <inf> lte_ble_gw: Stop scan success:29, num:248
    
    [09:20:24.110]收←◆[00:02:21.295,
    [09:20:24.128]收←◆471] <inf> lte_ble_gw: start scan success
    [00:02:21.377,624] <inf> lte_ble_gw: Stop scan success:22, num:250
    
    [09:20:25.199]收←◆[00:02:22.385,498] <inf> lte_ble_gw: start scan success
    [00:02:22.473,571] <inf> lte_ble_gw: Stop scan success:23, num:252
    
    [09:20:26.289]收←◆[00:02:23.475,494] <inf> lte_ble_gw: start scan success
    [00:02:23.560,302] <inf> lte_ble_gw: Stop scan success:26, num:254
    
    [09:20:27.378]收←◆[00:02:24.565,551] <inf> lte_ble_gw: start scan success
    [00:02:24.648,132] <inf> lte_ble_gw: Stop scan success:23, num:256
    
    [09:20:28.463]收←◆[00:02:25.649,230] <inf> lte_ble_gw: start scan success
    [00:02:25.733,154] <inf> lte_ble_gw: Stop scan success:25, num:258
    
    [09:20:29.559]收←◆[00:02:26.745,574] <inf> lte_ble_gw: start scan success
    [00:02:26.831,390] <inf> lte_ble_gw: Stop scan success:27, num:260
    
    [09:20:30.649]收←◆[00:02:27.835,601] <inf> lte_ble_gw: start scan success
    [00:02:27.926,666] <inf> lte_ble_gw: Stop scan success:29, num:262
    
    [09:20:31.740]收←◆[00:02:28.925,628] <inf> lte_ble_gw: start scan success
    [00:02:29.006,164] <inf> lte_ble_gw: Stop scan success:26, num:264
    
    [09:20:32.830]收←◆[00:02:30.015,686] <inf> lte_ble_gw: start scan success
    [00:02:30.099,578] <inf> lte_ble_gw: Stop scan success:24, num:266
    
    [09:20:33.920]收←◆[00:02:31.105,743] <inf> lte_ble_gw: start scan success
    [00:02:31.208,862] <inf> lte_ble_gw: Stop scan success:34, num:268
    
    [09:20:35.010]收←◆[00:02:32.195,709] <inf> lte_ble_gw: start scan success
    [00:02:32.287,750] <inf> lte_ble_gw: Stop scan success:30, num:270
    
    [09:20:36.099]收←◆[00:02:33.285,705] <inf> lte_ble_gw: start scan success
    [00:02:33.363,342] <inf> lte_ble_gw: Stop scan success:24, num:272
    
    [09:20:37.189]收←◆[00:02:34.375,762] <inf> lte_ble_gw: start scan success
    [00:02:34.466,766] <inf> lte_ble_gw: Stop scan success:28, num:274
    
    [09:20:38.280]收←◆[00:02:35.465,789
    [09:20:38.301]收←◆] <inf> lte_ble_gw: start scan success
    [00:02:35.559,539] <inf> lte_ble_gw: Stop scan success:32, num:276
    
    [09:20:39.370]收←◆[00:02:36.555,847] <inf> lte_ble_gw: start scan success
    [00:02:36.648,529] <inf> lte_ble_gw: Stop scan success:31, num:278
    
    [09:20:40.459]收←◆[00:02:37.645,843] <inf> lte_ble_gw: start scan success
    [00:02:37.730,865] <inf> lte_ble_gw: Stop scan success:23, num:280
    
    [09:20:41.550]收←◆[00:02:38.735,900] <inf> lte_ble_gw: start scan success
    [00:02:38.819,885] <inf> lte_ble_gw: Stop scan success:27, num:282
    
    [09:20:42.640]收←◆[00:02:39.825,927] <inf> lte_ble_gw: start scan success
    [00:02:39.913,574] <inf> lte_ble_gw: Stop scan success:30, num:284
    
    [09:20:43.729]收←◆[00:02:40.915,954] <inf> lte_ble_gw: start scan success
    [00:02:40.994,445] <inf> lte_ble_gw: Stop scan success:24, num:286
    
    [09:20:44.820]收←◆[00:02:42.005,950] <inf> lte_ble_gw: start scan success
    [00:02:42.092,254] <inf> lte_ble_gw: Stop scan success:26, num:288
    
    [09:20:45.910]收←◆[00:02:43.096,008] <inf> lte_ble_gw: start scan success
    [00:02:43.183,563] <inf> lte_ble_gw: Stop scan success:30, num:290
    
    [09:20:47.000]收←◆[00:02:44.186,035] <inf> lte_ble_gw: start scan success
    [00:02:44.271,392] <inf> lte_ble_gw: Stop scan success:28, num:292
    
    [09:20:48.091]收←◆[00:02:45.276,031] <inf> lte_ble_gw: start scan success
    [00:02:45.359,344] <inf> lte_ble_gw: Stop scan success:27, num:294
    
    [09:20:49.180]收←◆[00:02:46.366,088] <inf> lte_ble_gw: start scan success
    [00:02:46.447,845] <inf> lte_ble_gw: Stop scan success:18, num:296
    
    [09:20:50.270]收←◆[00:02:47.456,085] <inf> lte_ble_gw: start scan success
    [00:02:47.546,356] <inf> lte_ble_gw: Stop scan success:27, num:298
    
    [09:20:51.360]收←◆[00:02:48.546,142] <inf> lte_ble_gw: start scan success
    [00:02:48.638,671] <inf> lte_ble_gw: Stop scan success:32, num:300
    
    [09:20:52.450]收←◆[00:02:49.636,169] <inf> lte_ble_gw: start scan success
    [00:02:49.720,336] <inf> lte_ble_gw: Stop scan success:27, num:302
    
    [09:20:53.540]收←◆[00:02:50.726,165] <inf> lte_ble_gw: start scan success
    [00:02:50.817,687] <inf> lte_ble_gw: Stop scan success:26, num:304
    
    [09:20:54.630]收←◆[00:02:51.816,192] <inf> lte_ble_gw: start scan success
    [00:02:51.898,986] <inf> lte_ble_gw: Stop scan success:24, num:306
    
    [09:20:55.720]收←◆[00:02:52.906,219] <inf> lte_ble_gw: start scan success
    [00:02:53.008,056] <inf> lte_ble_gw: Stop scan success:35, num:308
    
    [09:20:56.804]收←◆[00:02:53.989,959] <inf> lte_ble_gw: start scan success
    [00:02:54.080,871] <inf> lte_ble_gw: Stop scan success:26, num:310
    
    [09:20:57.900]收←◆[00:02:55.086,273] <inf> lte_ble_gw: start scan success
    [00:02:55.185,852] <inf> lte_ble_gw: Stop scan success:29, num:312
    
    [09:20:58.990]收←◆[00:02:56.176,330] <inf> lte_ble_gw: start scan success
    [00:02:56.269,805] <inf> lte_ble_gw: Stop scan success:30, num:314
    
    [09:21:00.080]收←◆[00:02:57.266,326] <inf> lte_ble_gw: start scan success
    [00:02:57.353,973] <inf> lte_ble_gw: Stop scan success:25, num:316
    
    [09:21:01.170]收←◆[00:02:58.356,445] <inf> lte_ble_gw: start scan success
    [00:02:58.456,512] <inf> lte_ble_gw: Stop scan success:34, num:318
    
    [09:21:02.197]收←◆+CEREG: 2,"7859","01824ADC",9
    [00:02:59.440,093] <inf> lte_ble_gw: start scan success
    [00:02:59.526,245] <inf> lte_ble_gw: Stop scan success:36, num:320
    
    [09:21:03.350]收←◆[00:03:00.536,407] <inf> lte_ble_gw: start scan success
    [00:03:00.647,125] <inf> lte_ble_gw: Stop scan success:36, num:322
    
    [09:21:04.434]收←◆[00:03:01.620,117] <inf> lte_ble_gw: start scan success
    [00:03:01.704,071] <inf> lte_ble_gw: Stop scan success:37, num:324
    
    [09:21:05.530]收←◆[00:03:02.716,461] <inf> lte_ble_gw: start scan success
    [00:03:02.813,262] <inf> lte_ble_gw: Stop scan success:26, num:326
    
    [09:21:06.621]收←◆[00:03:03.806,518] <inf> lte_ble_gw: start scan success
    [00:03:03.883,178] <wrn> bt_driver: Unable to send H:4 type
    
    [09:21:15.697]收←◆ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:331
    	command opcode 0x200c timeout with err -11
    [00:03:13.883,056] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000002
    [00:03:13.883,056] <err> os: r3/a4:  0x2000d2f8 r12/ip:  0x00000010 r14/lr:  0x0000ee11
    [00:03:13.883,087] <err> os:  xpsr:  0x41000000
    [00:03:13.883,087] <err> os: Faulting instruction address (r15/pc): 0x0000ee1c
    [00:03:13.883,117] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
    [00:03:13.883,148] <err> os: Current thread: 0x2000f8c8 (unknown)
    [00:03:13.939,361] <err> fatal_error: Resetting system\0
    [09:21:16.295]收←◆*** Booting nRF Connect SDK v3.5.99-ncs1-1-1-g02ae5d8ded21 ***
    [00:00:00.260,223] <inf> lte_ble_gw: LTE Sensor Gateway sample started
    [00:00:00.260,437] <inf> lte_ble_gw: Initializing Bluetooth..
    [00:00:00.262,298] <wrn> lpuart: req pin low when expected high
    [00:00:00.262,420] <err> lpuart: Empty receiver state:4
    
    [09:21:17.050]收←◆[00:00:00.514,221] <inf> lte_ble_gw: Establishing LTE link (this may take some time) ...
    [00:00:00.963,745] <wrn> bt_hci_core: opcode 0x0000 pool id 3 pool 0x2000d040 != &hci_cmd_pool 0x2000d0a8
    [00:00:01.005,798] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:01.005,828] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    [00:00:01.005,859] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    [00:00:01.014,495] <inf> bt_hci_core: Identity: D4:CB:39:15:51:B3 (random)
    [00:00:01.014,526] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    [00:00:01.014,556] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    [00:00:01.014,556] <inf> lte_ble_gw: Bluetooth ready
    [00:00:01.014,617] <inf> lte_ble_gw: Scanning...
    
    [09:21:42.683]收←◆5.642,578] <inf> lte_ble_gw: start scan success
    [00:00:25.727,539] <inf> lte_ble_gw: Stop scan success:32, num:38
    
    [09:21:43.767]收←◆[00:00:26.732,604] <inf> lte_ble_gw: start scan success
    [00:00:26.816,528] <inf> lte_ble_gw: Stop scan success:33, num:40
    
    [09:21:44.857]收←◆[00:00:27.822,662] <inf> lte_ble_gw: start scan success
    [00:00:27.906,555] <inf> lte_ble_gw: Stop scan success:29, num:42
    
    [09:21:45.947]收←◆[00:00:28.912,628] <inf> lte_ble_gw: start scan success
    [00:00:28.997,467] <inf> lte_ble_gw: Stop scan success:28, num:44
    
    [09:21:47.037]收←◆[00:00:30.002,685] <inf> lte_ble_gw: start scan success
    [00:00:30.086,914] <inf> lte_ble_gw: Stop scan success:27, num:46
    
    [09:21:48.127]收←◆[00:00:31.092,742] <inf> lte_ble_gw: start scan success
    [00:00:31.177,398] <inf> lte_ble_gw: Stop scan success:25, num:48
    
    [09:21:49.217]收←◆[00:00:32.182,739] <inf> lte_ble_gw: start scan success
    [00:00:32.267,395] <inf> lte_ble_gw: Stop scan success:27, num:50
    
    [09:21:50.307]收←◆[00:00:33.272,766] <inf> lte_ble_gw: start scan success
    [00:00:33.357,116] <inf> lte_ble_gw: Stop scan success:29, num:52
    
    [09:21:51.397]收←◆[00:00:34.362,762] <inf> lte_ble_gw: start scan success
    [00:00:34.446,777] <inf> lte_ble_gw: Stop scan success:27, num:54
    
    [09:21:52.487]收←◆[00:00:35.452,819] <inf> lte_ble_gw: start scan success
    [00:00:35.536,743] <inf> lte_ble_gw: Stop scan success:25, num:56
    
    [09:21:53.577]收←◆[00:00:36.542,846] <inf> lte_ble_gw: start scan success
    [00:00:36.626,983] <inf> lte_ble_gw: Stop scan success:24, num:58
    
    [09:21:54.668]收←◆[00:00:37.632,904] <inf> lte_ble_gw: start scan success
    [00:00:37.716,796] <inf> lte_ble_gw: Stop scan success:34, num:60
    
    [09:21:55.758]收←◆[00:00:38.722,900] <inf> lte_ble_gw: start scan success
    [00:00:38.806,823] <inf> lte_ble_gw: Stop scan success:28, num:62
    
    [09:21:56.847]收←◆[00:00:39.812,927] <inf> lte_ble_gw: start scan success
    [00:00:39.896,881] <inf> lte_ble_gw: Stop scan success:25, num:64
    
    [09:21:57.937]收←◆[00:00:40.902,984] <inf> lte_ble_gw: start scan success
    [00:00:40.987,548] <inf> lte_ble_gw: Stop scan success:36, num:66
    
    [09:21:59.028]收←◆[00:00:41.992,980] <inf> lte_ble_gw: start scan success
    [00:00:42.078,002] <inf> lte_ble_gw: Stop scan success:24, num:68
    
    [09:22:00.118]收←◆[00:00:43.083,007] <inf> lte_ble_gw: start scan success
    [00:00:43.166,931] <inf> lte_ble_gw: Stop scan success:24, num:70
    
    [09:22:01.207]收←◆[00:00:44.173,065] <inf> lte_ble_gw: start scan success
    [00:00:44.257,080] <inf> lte_ble_gw: Stop scan success:31, num:72
    
    [09:22:02.297]收←◆[00:00:45.263,061] <inf> lte_ble_gw: start scan success
    [00:00:45.347,198] <inf> lte_ble_gw: Stop scan success:27, num:74
    
    [09:22:03.388]收←◆[00:00:46.353,088] <inf> lte_ble_gw: start scan success
    [00:00:46.437,255] <inf> lte_ble_gw: Stop scan success:29, num:76
    
    [09:22:04.478]收←◆[00:00:47.443,145] <inf> lte_ble_gw: start scan success
    [00:00:47.527,160] <inf> lte_ble_gw: Stop scan success:26, num:78
    
    [09:22:05.568]收←◆[00:00:48.533,142] <inf> lte_ble_gw: start scan success
    [00:00:48.617,065] <inf> lte_ble_gw: Stop scan success:22, num:80
    
    [09:22:06.657]收←◆[00:00:49.623,168] <inf> lte_ble_gw: start scan success
    [00:00:49.707,092] <inf> lte_ble_gw: Stop scan success:27, num:82
    
    [09:22:07.749]收←◆[00:00:50.713,226] <inf> lte_ble_gw: start scan success
    [00:00:50.797,119] <inf> lte_ble_gw: Stop scan success:32, num:84
    
    [09:22:08.838]收←◆[00:00:51.803,222] <inf> lte_ble_gw: start scan success
    [00:00:51.887,237] <inf> lte_ble_gw: Stop scan success:28, num:86
    
    [09:22:09.012]收←◆[00:00:52.893,249] <inf> lte_ble_gw: start scan success
    [00:00:52.978,790] <err> os: ***** SECURE FAULT *****
    [00:00:52.978,790] <err> os:   Address: 0xc
    [00:00:52.978,820] <err> os:   Attribution unit violation
    [00:00:52.978,820] <err> os: r0/a1:  0x00000001  r1/a2:  0x00000057  r2/a3:  0x40031000
    [00:00:52.978,851] <err> os: r3/a4:  0x00000000 r12/ip:  0x2000f858 r14/lr:  0x000250d9
    [00:00:52.978,881] <err> os:  xpsr:  0x61000000
    [00:00:52.978,881] <err> os: Faulting instruction address (r15/pc): 0x00016110
    [00:00:52.978,912] <err> os: >>> ZEPHYR FATAL ERROR 41: Unknown error on CPU 0
    [00:00:52.978,942] <err> os: Current thread: 0x2000d868 (unknown)
    [00:00:53.046,997] <err> fatal_error: Resetting system\0
    [09:22:09.622]收←◆*** Booting nRF Connect SDK v3.5.99-ncs1-1-1-g02ae5d8ded21 ***
    [00:00:00.260,070] <inf> lte_ble_gw: LTE Sensor Gateway sample started
    [00:00:00.260,528] <inf> lte_ble_gw: Initializing Bluetooth..
    [00:00:00.270,874] <wrn> lpuart: req pin low when expected high
    [00:00:00.270,965] <err> lpuart: Empty receiver state:4
    
    [09:22:10.377]收←◆[00:00:00.512
    [09:22:10.397]收←◆,390] <inf> lte_ble_gw: Establishing LTE link (this may take some time) ...
    [00:00:00.963,775] <wrn> bt_hci_core: opcode 0x0000 pool id 3 pool 0x2000d040 != &hci_cmd_pool 0x2000d0a8
    [00:00:01.005,828] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:01.005,859] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    [00:00:01.005,889] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    [00:00:01.014,495] <inf> bt_hci_core: Identity: D4:CB:39:15:51:B3 (random)
    [00:00:01.014,526] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    [00:00:01.014,587] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    [00:00:01.014,587] <inf> lte_ble_gw: Bluetooth ready
    [00:00:01.014,617] <inf> lte_ble_gw: Scanning...
    
    [09:22:16.385]收←◆[00:00:06.022,186] <inf> lte_ble_gw: start scan success
    [00:00:06.106,048] <inf> lte_ble_gw: Stop scan success:30, num:2
    
    

  • Hi,

    I am sorry for the delay.

    The log here shows an assert that also indicate a problem on the controller side (nrf52). Have you been able to enable logging on that side? It may be simplest to enable debugging of the nRF and select RTT as logg backend in this case. The question is what happens on the nRF52 side and next, what we can do about it.

    PS: the nRF52840 on the nRF9160 DK mainly functions as a board controller, and the gateway sample was made as a demo for the Thingy:91 that can also be built on the DK. So it should be regarded more as a proof of concept than anything else.

  • Thank you for your suggestion. I have change the prj file of the hci_lpuart project like follow:
    # Segger RTT enable
    CONFIG_LOG=y
    CONFIG_USE_SEGGER_RTT=y
    CONFIG_RTT_CONSOLE=y
    CONFIG_LOG_BACKEND_RTT=y

    I have enabled UART log tracking for hci_lpuart, but I found that when there is an exception in the lte_ble_gateway, hci_lpuart only has one restart log. I think this is because the lte-ble_gateway reset it. Do I need to enable the debug log for hci_lpuart?

    the log of hci_lpuart 

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

    [09:10:36.310] RX←◆[00:00:00.000,152] [0m<inf> board_control: vcom0_pins_routing is ENABLED[0m
    [00:00:00.000,213] [0m<inf> board_control: vcom2_pins_routing is ENABLED[0m
    [00:00:00.000,244] [0m<inf> board_control: led1_pin_routing is ENABLED[0m
    [00:00:00.000,305] [0m<inf> board_control: led2_pin_routing is ENABLED[0m
    [00:00:00.000,335] [0m<inf> board_control: led3_pin_routing is ENABLED[0m
    [00:00:00.000,366] [0m<inf> board_control: led4_pin_routing is ENABLED[0m
    [00:00:00.000,427] [0m<inf> board_control: switch1_pin_routing is ENABLED[0m
    [00:00:00.000,457] [0m<inf> board_control: switch2_pin_routing is ENABLED[0m
    [00:00:00.000,518] [0m<inf> board_control: button1_pin_routing is ENABLED[0m
    [00:00:00.000,549] [0m<inf> board_control: button2_pin_routing is ENABLED[0m
    [00:00:00.000,610] [0m<inf> board_control: nrf_interface_pins_0_2_routing is ENABLED[0m
    [00:00:00.000,640] [0m<inf> board_control: nrf_interface_pins_3_5_routing is ENABLED[0m
    [00:00:00.000,701] [0m<inf> board_control: nrf_interface_pins_6_8_routing is disabled[0m
    [00:00:00.000,732] [0m<inf> board_control: GPIO reset line enabled on pin P1.02, holding...[0m
    [00:00:00.000,762] [0m<inf> board_control: Board configured.[0m
    *** Booting Zephyr OS build v3.2.99-ncs1 ***
    [00:00:00.001,251] [0m<inf> sdc_hci_driver: SoftDevice Controller build revision:
    6d 90 41 2a 38 e8 ad 17 29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..
    1f 85 d8 e1 |.... [0m
    [00:00:00.001,861] [0m<inf> bt_hci_raw: Bluetooth enabled in RAW mode[0m

    [09:26:50.049]RX←◆[00:00:00.000,152] [0m<inf> board_control: vcom0_pins_routing is ENABLED[0m
    [00:00:00.000,213] [0m<inf> board_control: vcom2_pins_routing is ENABLED[0m
    [00:00:00.000,274] [0m<inf> board_control: led1_pin_routing is ENABLED[0m
    [00:00:00.000,305] [0m<inf> board_control: led2_pin_routing is ENABLED[0m
    [00:00:00.000,335] [0m<inf> board_control: led3_pin_routing is ENABLED[0m
    [00:00:00.000,396] [0m<inf> board_control: led4_pin_routing is ENABLED[0m
    [00:00:00.000,427] [0m<inf> board_control: switch1_pin_routing is ENABLED[0m
    [00:00:00.000,488] [0m<inf> board_control: switch2_pin_routing is ENABLED[0m
    [00:00:00.000,518] [0m<inf> board_control: button1_pin_routing is ENABLED[0m
    [00:00:00.000,579] [0m<inf> board_control: button2_pin_routing is ENABLED[0m
    [00:00:00.000,610] [0m<inf> board_control: nrf_interface_pins_0_2_routing is ENABLED[0m
    [00:00:00.000,671] [0m<inf> board_control: nrf_interface_pins_3_5_routing is ENABLED[0m
    [00:00:00.000,701] [0m<inf> board_control: nrf_interface_pins_6_8_routing is disabled[0m
    [00:00:00.000,732] [0m<inf> board_control: GPIO reset line enabled on pin P1.02, holding...[0m
    [00:00:00.000,762] [0m<inf> board_control: Board configured.[0m
    *** Booting Zephyr OS build v3.2.99-ncs1 ***
    [00:00:00.001,251] [0m<inf> sdc_hci_driver: SoftDevice Controller build revision:
    6d 90 41 2a 38 e8 ad 17 29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..
    1f 85 d8 e1 |.... [0m
    [00:00:00.001,861] [0m<inf> bt_hci_raw: Bluetooth enabled in RAW mode[0m

    the log of lte_ble_gateway

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


    [09:10:32.618]RX←◆*** Booting Zephyr OS build v3.2.99-ncs1 ***

    [09:10:33.623]RX←◆[00:00:00.543,884] [0m<inf> lte_ble_gw: LTE Sensor Gateway sample started[0m
    [00:00:00.544,097] [0m<inf> lte_ble_gw: Initializing Bluetooth..[0m

    [09:10:37.327]RX←◆[00:00:04.250,335] [1;33m<wrn> bt_hci_core: opcode 0x0000 pool id 3 pool 0x2000de4c != &hci_cmd_pool 0x2000deb4[0m
    [00:00:04.346,374] [0m<inf> lte_ble_gw: Bluetooth ready[0m
    [00:00:04.346,405] [0m<inf> lte_ble_gw: Scanning...[0m

    [09:10:42.437]RX←◆[00:00:09.359,863] [0m<inf> lte_ble_gw: start scan success[0m
    [00:00:09.449,188] [0m<inf> lte_ble_gw: Stop scan success:28, num:2[0m

    [09:10:43.526]RX←◆[00:00:10.449,920] [0m<inf> lte_ble_gw: start scan success[0m
    [00:00:10.540,069] [0m<inf> lte_ble_gw: Stop scan success:31, num:4[0m

    [09:10:44.616]RX←◆[00:00:11.539,886] [0m<inf> lte_ble_gw: start scan success[0m
    [00:00:11.637,542] [0m<inf> lte_ble_gw: Stop scan success:28, num:6[0m

    [09:10:45.706]RX←◆[00:00:12.629,943] [0m<inf> lte_ble_gw: start scan success[0m
    [00:00:12.713,134] [0m<inf> lte_ble_gw: Stop scan success:27, num:8[0m

    ... I have omitted some same logs

    ..............................................................

    [09:26:29.630]RX←◆[00:15:56.593,475] [0m<inf> lte_ble_gw: start scan success[0m
    [00:15:56.676,361] [0m<inf> lte_ble_gw: Stop scan success:21, num:1740[0m

    [09:26:30.720]RX←◆[00:15:57.683,502] [0m<inf> lte_ble_gw: start scan success[0m
    [00:15:57.787,109] [0m<inf> lte_ble_gw: Stop scan success:34, num:1742[0m

    [09:26:31.812]RX←◆[00:15:58.773,529] [0m<inf> lte_ble_gw: start scan success[0m
    [00:15:58.857,940] [0m<inf> lte_ble_gw: Stop scan success:21, num:1744[0m

    [09:26:32.901]RX←◆[00:15:59.86
    [09:26:32.940]RX←◆3,525] [0m<inf> lte_ble_gw: start scan success[0m
    [00:15:59.971,649] [0m<inf> lte_ble_gw: Stop scan success:37, num:1746[0m

    [09:26:33.991]RX←◆[00:16:00.953,613] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:01.041,534] [0m<inf> lte_ble_gw: Stop scan success:28, num:1748[0m

    [09:26:35.081]RX←◆[00:16:02.043,640] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:02.140,380] [0m<inf> lte_ble_gw: Stop scan success:31, num:1750[0m

    [09:26:36.171]RX←◆[00:16:03.133,636] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:03.221,740] [0m<inf> lte_ble_gw: Stop scan success:29, num:1752[0m

    [09:26:37.260]RX←◆[00:16:04.223,663] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:04.311,218] [0m<inf> lte_ble_gw: Stop scan success:26, num:1754[0m

    [09:26:38.352]RX←◆[00:16:05.313,781] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:05.400,054] [0m<inf> lte_ble_gw: Stop scan success:26, num:1756[0m

    [09:26:39.440]RX←◆[00:16:06.403,686] [0m<inf> lte_ble_gw: start scan success[0m
    [00:16:06.480,438] [1;31m<err> bt_driver: TX interrupt but no pending buffer![0m
    [00:16:06.480,438] [1;31m<err> bt_driver: TX interrupt but no pending buffer![0m

    [09:26:48.518]RX←◆ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:329
    k_sem_take failed with err -11
    [00:16:16.489,959] [1;33m<wrn> bt_driver: Discarding event 0x3e[0m
    [00:16:16.491,088] [1;31m<err> os: r0/a1: 0x00000003 r1/a2: 0x00000000 r2/a3: 0x00000000[0m
    [00:16:16.491,088] [1;31m<err> os: r3/a4: 0x00016e71 r12/ip: 0x00000000 r14/lr: 0x00010677[0m
    [00:16:16.491,119] [1;31m<err> os: xpsr: 0x41000000[0m
    [00:16:16.491,119] [1;31m<err> os: Faulting instruction address (r15/pc): 0x00010682[0m
    [00:16:16.491,149] [1;31m<err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0[0m
    [00:16:16.491,180] [1;31m<err> os: Current thread: 0x200108f8 (unknown)[0m
    [00:16:16.542,175] [1;31m<err> fatal_error: Resetting system[0m\0
    [09:26:49.351]RX←◆*** Booting Zep
    [09:26:49.384]RX←◆hyr OS build v3.2.99-ncs1 ***

    [09:26:50.354]RX←◆[00:00:00
    [09:26:50.376]RX←◆.501,708] [0m<inf> lte_ble_gw: LTE Sensor Gateway sample started[0m

  • 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.

Reply
  • 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.

Children
  • 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.

  • Hi,

    I am sorry for the delay. I have not made much progress on my end. This is n old demo that is a bit unstable under load, and that seems to have always been the case. I am continuing to look into it, but it may take some time. Please let me know if you have any progress on your end as well.

    Br,

    Einar

  • Hi, Thank you for your efforts.

    I'll try to reduce the scan window to test and see if I can reduce the probability of the problem happening.

Related