Zigbee traces use the wrong log level

[mytzyiay]

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.

[Edvin]

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

[mytzyiay]

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

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

Edvin 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?

[Edvin]

Hello,

mytzyiay said:

Unfortunately this isn't really what's needed.  In this application (a SED light switch) we have somewhere between 1-3 devices in the binding table.

What about the multi-endpoint switch device? Each endpoint would have it's own set of devices that it controls and all of that is done through the binding table.
From application point of view:

• on button press, the packet e.g. TOGGLE is sent to a binding table
• assuming that binding table has 3 entries, one for every switch endpoint
• the device a packet is sent to is selected by setting correct source endpoint (endpoint of the switch device that the packet is sent from)
• packet sent "from button0" would be sent from first switch endpoint with destination addresses set to a binding table. Zigbee stack would then search for an entry with corresponding source address and endpoint (...) and from existing 3 entries select only one because only one matches the source endpoint.
• similarly: button1, button2 would sent packets with source endpoints set to second and third switch endpoint respectively.

 

When it comes to notifying ZC about changes, configuring reporting is definitely less hacky method as this mechanism was designed just for this job.

[mytzyiay]

Edvin said:

What about the multi-endpoint switch device? Each endpoint would have it's own set of devices that it controls and all of that is done through the binding table.

Appreciate the suggestion.  I will try implementing the multiple source endpoints and let you know what happens.

Edvin said:

When it comes to notifying ZC about changes, configuring reporting is definitely less hacky method as this mechanism was designed just for this job.

Could you please provide sample code for getting my switch to automatically configure reporting to the ZC?  I'm not clear on which API to use or what parameters it needs.

[Edvin]

Hello,

Please refer to the SDK v4.2 examples\multiprotocol\ble_zigbee\ble_zigbee_dynamic_light_switch_nus, which is quite similar to what you want to achieve.

It has 3 endpoints on the switch.

On/Off and level commands are sent to the binding table and those commands may be sent from different endpoints.

One note: This example "cycles" through endpoints, so it is not the exact logic that you have described, but you should get the idea.

When it comes to reporting:

Configure the bulb (or any other devices that are controlled by the switch) to report attribute changes for cluster 0x0006 (On/Off):

• Create a binding from the Bulb to the ZC by for example sending a binding request to the bulb device. zb_zdo_mgmt_bind_req() is the API that can be used to send such requests. An example implementation can be found in the Zigbee shell (NCS\nrf\samples\zigbee\shell zdo mgmt_bind cmd:
  cmd_zb_mgmt_bind() function in subsys\zigbee\lib\zigbee_shell\src\zigbee_shell_cmd_zdo.c.
• Configure reporting to your liking - Send Configure Reporting command to the Bulb device:
  • You can follow ZBOSS documentation: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/zboss/3.11.1.0/group__cfg__reporting__cmd.html
  • Or you can use the Zigbee Shell command zcl subscribe on implementation:  Get a free buffer, init request in the buffer qith ZB_ZCL_GENERAL_INIT_CONFIGRE_REPORTING_SRV_REQ0 macro. For every attribute, add reporting configuration with ZB_ZCL_GENERAL_ADD_SEND_REPORT_CONFIGURE_REPORTING_REQ() and send the packet using zb_zcl_finish_and_send_packet_new() function.
    The implementation of the command in the Zigbee Shell sample can be found in cmd_zb_subscribe_on() function in subsys\zigbee\lib\zigbee_shell\src\zigbee_shell_cmd_attr_report.c.

Best regards,

Edvin

[mytzyiay]

Edvin said:

Configure the bulb (or any other devices that are controlled by the switch) to report attribute changes for cluster 0x0006 (On/Off):

My switch works in two different ways:

1. It can be optionally bound to a bulb/switch/etc. so that it can control that device independent of anything else going on in the Zigbee network (even if the ZC is down)
2. It has a Multistate Input cluster so that separately from #1, it will report button presses to the ZC.  This way, if one of the switches is not bound to a bulb/switch/etc. it can trigger more advanced, programmable event sequences with the help of the ZC

I'm stumped on how to set up reporting for the #2 case.  I want my switch to always report multistate input changes to the ZC, even if the ZC never configured reporting.  Currently I'm doing this by manually constructing and sending the packets.

Is there an API that lets me tell the ZBOSS stack to send a report any time my code updates the attribute?

[Edvin]

Hello,

You can use the already existing reporting mechanism:

If the multistate input cluster was implemented correctly (!), the reporting can be configured locally at the device and the reports should be automatically sent whenever the value of the attribute changes (taking into account the reporting intervals):

• The binding must be created locally at the switch, from the switch to the ZC for the Multistate Input cluster.
• The reporting configuration can be adjusted to differ from the default configuration (configuration for the PresentValue attribute)
• The reporting mechanism would work only if the value of PresentValue attribute is changed using ZB_ZCL_SET_ATTRIBUTE() so the ZBOSS stack is informed about the attribute's value change.