• State Not Answered
  • Replies 2 replies
  • Subscribers 25 subscribers
  • Views 111 views
  • Users 0 members are here
Attachments (0)
Nordic Case Info
  • Case ID: 290426
Options

Zigbee traces use the wrong log level

user113934

I am using the light_bulb sample from NCS v2.0.0 with an nRF52840 DK board.  I changed prj.conf to enable Warning traces from ZBOSS:

+# Enable traces on UART_1 (P1.02) @ 115200bps
+CONFIG_ZIGBEE_ENABLE_TRACES=y
+CONFIG_ZBOSS_TRACE_MASK=0x0003
+CONFIG_ZBOSS_TRACE_LOG_LEVEL_WRN=y
+CONFIG_ZBOSS_TRACE_BINARY_LOGGING=y
+CONFIG_ZBOSS_TRACE_LOGGER_DEVICE_NAME="UART_1"

I added test code to the app to verify that the correct loglevel setting was being applied and that the filters are working as intended:

 extern int zb_trace_check(zb_uint_t level, zb_uint_t mask);
 LOG_INF("TRACE: %d: %d %d %d %d %d", g_trace_level,
  zb_trace_check(0, 1),
  zb_trace_check(1, 1),
  zb_trace_check(2, 1),
  zb_trace_check(3, 1),
  zb_trace_check(4, 1));
 LOG_INF("TRACE: %d: %d %d %d %d %d", g_trace_level,
  zb_trace_check(0, 0x100),
  zb_trace_check(1, 0x100),
  zb_trace_check(2, 0x100),
  zb_trace_check(3, 0x100),
  zb_trace_check(4, 0x100));

The output was:

I: TRACE: 2: 1 1 1 0 0
I: TRACE: 2: 0 0 0 0 0

Unfortunately this still generates a massive amount of binary log data on UART1.  All of these look to be extremely mundane operations that hardly merit the Warning loglevel:

2022-06-09 16:23:23,115 RAW [de,ad,0e,02,9a,00,3d,07,18,00,77,02,06,00,00,00]
2022-06-09 16:23:23,115 ts=009a m=0x0002 lev=1 zb_buf_begin_func:631 data=[06,00,00,00]
2022-06-09 16:23:23,115 RAW [de,ad,0e,02,9a,00,3e,07,18,00,17,05,06,00,00,00]
2022-06-09 16:23:23,115 ts=009a m=0x0002 lev=1 zb_buf_get_status_func:1303 data=[06,00,00,00]
2022-06-09 16:23:23,115 RAW [de,ad,0e,02,9a,00,3f,07,18,00,1e,05,00,00,00,00]
2022-06-09 16:23:23,115 ts=009a m=0x0002 lev=1 zb_buf_get_status_func:1310 data=[00,00,00,00]
2022-06-09 16:23:23,120 RAW [de,ad,0e,02,9a,00,40,07,18,00,a1,02,06,00,00,00]
2022-06-09 16:23:23,120 ts=009a m=0x0002 lev=1 zb_buf_len_func:673 data=[06,00,00,00]
2022-06-09 16:23:23,120 RAW [de,ad,0e,02,9a,00,41,07,18,00,a1,02,06,00,00,00]
2022-06-09 16:23:23,120 ts=009a m=0x0002 lev=1 zb_buf_len_func:673 data=[06,00,00,00]
2022-06-09 16:23:23,121 RAW [de,ad,0e,02,9a,00,42,07,18,00,77,02,06,00,00,00]
2022-06-09 16:23:23,121 ts=009a m=0x0002 lev=1 zb_buf_begin_func:631 data=[06,00,00,00]
2022-06-09 16:23:23,121 RAW [de,ad,0e,02,9a,00,43,07,18,00,17,05,06,00,00,00]
2022-06-09 16:23:23,121 ts=009a m=0x0002 lev=1 zb_buf_get_status_func:1303 data=[06,00,00,00]
2022-06-09 16:23:23,136 RAW [de,ad,0e,02,9a,00,44,07,18,00,1e,05,00,00,00,00]

For instance, zb_buf_get_tail_func() is logging at the Error level even when no errors are occurring.

The reason why I worry about this is because I'm trying to capture information about an actual ZBOSS failure, and there is so much data coming out of this UART that it's dropping/corrupting frames.

I see similar issues when using other trace masks too.

  • 0

    Hello,

    Sorry for the basic questions, but what is the logging supposed to output?

    I: TRACE: 2: 1 1 1 0 0
    I: TRACE: 2: 0 0 0 0 0

    The zboss trace log is meant to log a bit, but unless they changed anything, the logs are encrypted, and they need to be sent to the company who provided the zboss stack (via us). Is there somethign particular you want to debug? 

    Best regards,

    Edvin

  • 0 in reply to user26071
    user26071 said:
    what is the logging supposed to output?

    I'm calling the function that ZBOSS uses to figure out whether to log a given message to the trace output:

    extern int zb_trace_check(zb_uint_t level, zb_uint_t mask);

    My test shows that the log mask and log level set in Kconfig are being respected by ZBOSS.  The problem is that the callers to zb_trace_msg_port() are specifying unreasonably high log level parameters, like logging routine buffer allocation events as errors.

    user26071 said:
    The zboss trace log is meant to log a bit, but unless they changed anything, the logs are encrypted, and they need to be sent to the company who provided the zboss stack (via us).

    They are not encrypted.  The binary format is trivial to decode; I wrote a couple of simple python scripts to work with them.

    user26071 said:
    Is there somethign particular you want to debug? 

    Yes, I'd like to reduce the trace log output volume because it's generating output faster than the serial/CDC output can handle it.  I'm troubleshooting a couple of different ZBOSS issues right now and this bug is potentially an impediment.

    Could you please ask DSR to fix the logging levels so that configuring e.g. CONFIG_ZBOSS_TRACE_LOG_LEVEL_WRN=y only outputs warnings rather than spewing debug traces into the binary trace log?

Related
Terms of service