The RTT log crashes frequently

[yuanFang]

Dear:

  I am useing NCSv2.6.0 version.On the basis of my project, adding RTT printing of Bluetooth scan packet and scan response packet will frequently appear Log crash.

  The following is the crash information

  00> [00:07:11.561,035] <inf> app: Filters matched. Address: F6:17:78:AB:28:49 (random) connectable: 1
00>
00> [00:07:11.637,664] [1;31m<err> os: r0/a1: 0x00000004 r1/a2: 0x0000007d r2/a3: 0x00000000
00> [00:07:11.637,664] [1;31m<err> os: r3/a4: 0x000386d5 r12/ip: 0x0002c291 r14/lr: 0x00029bf9[0m
00> [00:07:11.637,695] [1;31m<err> os: xpsr: 0x61000000[0m
00> [00:07:11.637,695] [1;31m<err> os: Faulting instruction address (r15/pc): 0x00043422
00> [00:07:11.637,756] [1;31m<err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0[0m
00> [00:07:11.637,786] [1;31m<err> os: Current thread: 0x20002548 (logging)[0m
00> [00:07:21.406,677] [1;31m<err> fatal_error: Resetting system
00> [00:00:00.004,821] <inf> app: The resume reason: 0x00000004, 0x0

 Here is prj.conf

# Config logger

CONFIG_LOG=y

CONFIG_USE_SEGGER_RTT=y

CONFIG_LOG_BACKEND_RTT=y

CONFIG_LOG_BACKEND_UART=n

CONFIG_LOG_PRINTK=n

CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=2048

CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=2048

CONFIG_LOG_PROCESS_THREAD_STARTUP_DELAY_MS=100

CONFIG_LOG_BUFFER_SIZE=4096

CONFIG_LOG_MODE_OVERFLOW=y

CONFIG_LOG_BACKEND_RTT_MODE_DROP=y

CONFIG_LOG_BACKEND_RTT_MODE_BLOCK=n

CONFIG_LOG_MODE_DEFERRED=y

CONFIG_LOG_BACKEND_SHOW_COLOR=y

CONFIG_LOG_TIMESTAMP_64BIT=y

CONFIG_LOG_MEM_UTILIZATION=y

Add LOG_INF("Filters matched. Address: %s connectable: %d ",addr, connectable); This line of code will cause frequent Log crashes，Delete and it won't crash.

static void scan_filter_match(struct bt_scan_device_info *device_info,

                struct bt_scan_filter_match *filter_match,

                bool connectable)

{

    char addr[BT_ADDR_LE_STR_LEN];

    bt_addr_le_to_str(device_info->recv_info->addr, addr, sizeof(addr));

    LOG_INF("Filters matched. Address: %s connectable: %d ",addr, connectable);

    if(device_info->recv_info->adv_type == BT_GAP_ADV_TYPE_ADV_SCAN_IND)

    {

        // LOG_HEXDUMP_INF(device_info->adv_data->data,device_info->adv_data->len,"scan:");

    }

}

While monitoring the log buf space with a period of one second, it crashes when the value of buf_use starts to increase from 0 and exceeds buf_size.The value of buf_use is always 0 in normal operation.

void ptint_log_buff_size()

{

    log_mem_get_usage(&buf_size,&buf_use);

    log_mem_get_max_usage(&max_buf);

    pf_log_raw(1,"log buf size==========>>>>>>>>>>>>(%d|%d|%d|%d)",buf_size,buf_use,max_buf,log_buffered_cnt());

}

Here's how I rewrote the print

#define NCS_LOG_FLUSH()         while(log_process())

#define pf_log_raw(onoff, ...) do {if (onoff) {LOG_INF(__VA_ARGS__);NCS_LOG_FLUSH();}} while (0);

Please help to solve this problem

Thanks

[Einar Thorsrud]

Hi,

I do not immediately have an explaantion for this. Can you check the faulting address from the log with addr2line and see in which file and line number this is? (0x00043422 in this case but it will change if you make any modifications and re-build)

[yuanFang]

hello,

Do you have any good suggestions?

The project is about to be done, and it has been delayed for a long time by the log problem.

looking forward to your reply.

Thanks

[Einar Thorsrud]

Hi,

It seems the assert at line 125 detected an issue (I expect you will get the exact line number if you test with a debug buidl without optimization):

static int line_out_drop_mode(void)
{
	/* line cannot be empty */
	__ASSERT_NO_MSG(line_pos > line_buf);
...

So something is wrong internally as it is attempting to write an empty line (there is nothing left to write). I have not found any other references for this though I am not sure how you can end up in this state. Is it so that this only happens when you call your pf_log_raw() function? Does it matter from where you call it (thread or ISR, and if a thread, the priority of the thread)?

[yuanFang]

Hi,

Without Bluetooth, the pf_log_raw() function ran for three days without problems.

Using LOG_INF() to print broadcast packets and BROADCAST RESPONSE packets causes frequent crashes when Bluetooth is on.

static void scan_filter_match(struct bt_scan_device_info *device_info,
                struct bt_scan_filter_match *filter_match,
                bool connectable)
{
    char addr[BT_ADDR_LE_STR_LEN];

    bt_addr_le_to_str(device_info->recv_info->addr, addr, sizeof(addr));

    LOG_INF("Filters matched. Address: %s connectable: %d ",addr, connectable);

    if(device_info->recv_info->adv_type == BT_GAP_ADV_TYPE_ADV_SCAN_IND)
    {
        // LOG_HEXDUMP_INF(device_info->adv_data->data,device_info->adv_data->len,"scan:");
    }
}

looking forward to your reply.

Thanks

[yuanFang]

Hi,

Do you have any good ways to circumvent this problem?

When I use the pf_log_raw() function to print, each statement has a newline. Could it have something to do with that?

Something like that.

00> [00:00:13.221,008] <inf> app: CT75 Temp: tmpVar = 18c0, temp = 247
00> 
00> [00:00:13.221,466] <inf> app: AccWorkingMode(0) accWakeEventMask(0x0)
00> 
00> [00:00:13.221,923] <inf> app: Main(0x0:0 mv) Bat(0x578:4424 mv) isBatteryValid(1)
00> 
00> [00:00:13.222,473] <inf> app: Bat2(0x581:4452 mv) Select bat(1)
00> 
00> [00:00:13.222,900] <inf> app: vCheck(0:0 mv) Low(0) High(0).
00> 
00> [00:00:13.224,578] <inf> app: MCU Temperature: 23, ACC Temperature: 24
00> 
00> [00:00:13.259,887] <inf> app: Pressure (Pa) 10236
00> 
00> [00:00:13.317,993] <inf> app: IO_CMD(0xcf) len(1) Value:
00> 
00> [00:00:13.318,450] <inf> app: 07 
00> 
00> [00:00:13.318,786] <inf> app: .  
00> 
00> [00:00:13.319,305] <inf> app: 24 08 cf 07 f0 00 e6 00 f7 00 5c 0d 
00> 
00> [00:00:13.319,793] <inf> app: $  .  .  .  .  .  .  .  .  .  \  .  
00> 
00> [00:00:13.320,465] <inf> app: IO_CMD(0xba) len(0) Value:

Thanks