Hi - I have implemented a custom Matter device using the Matter template sample based on the WindowCovering cluster. I am able to build/flash and run my custom code on a custom board (NRF5340; SDK 2.5.0). I can successfully commission my device to Apple Home using custom factory data.
The device works, but I am experiencing some strange operational behavior and I am wondering if it is related to the following error messages: “Error retrieving data from clusterId: 0x0000_0028, err = b” and others like it (relevant log output below).
I also get a “WindowCovering has no delegate set for endpoint:1”, but as far as I can tell, I have implemented the zcl_callbacks correctly and configured the .zap file correctly using the Zap tool (version 2023.4.27 that is supposed to be paired with NRF SDK 2.5.0). I include a code snippet from my zcl_callbacks below.
Welcome any thoughts or guidance on what could be causing this. Thanks! Dan.
uart:~$ *** Booting nRF Connect SDK v2.5.0 *** I: Init CHIP stack I: 30174 [DL]BLE address: CA:EF:A7:0B:60:9E I: 30211 [DL]OpenThread ifconfig up and thread start I: 30218 [DL]OpenThread started: OK I: 30221 [DL]Setting OpenThread device type to MINIMAL END DEVICE I: 30227 [SVR]Subscription persistence not supported I: 30232 [SVR]Server initializing... I: 30236 [TS]Last Known Good Time: 2024-01-29T00:09:00 I: 30244 [FP]Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7FCB547C65239FBB, FabricId 0x0000000000000001, NodeId 0x000000002A2665C1, VendorId 0x1349 I: 30261 [FP]Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x4444B5466504D146, FabricId 0x0000000000000002, NodeId 0x00000000C44D730C, VendorId 0x1384 I: 30277 [DMG]AccessControl: initializing I: 30281 [DMG]Examples::AccessControlDelegate::Init I: 30286 [DMG]AccessControl: setting I: 30289 [DMG]DefaultAclStorage: initializing I: 30296 [DMG]DefaultAclStorage: 2 entries loaded E: 30301 [IN]SO_REUSEPORT failed: 109 I: 30310 [ZCL]Using ZAP configuration... I: 30322 [DMG]AccessControlCluster: initializing I: 30326 [ZCL]Initiating Admin Commissioning cluster. I: 30331 [SVR]Fabric already commissioned. Disabling BLE advertisement I: 30337 [DIS]Updating services using commissioning mode 0 E: 30343 [DIS]Failed to remove advertised services: 3 I: 30348 [DIS]Advertise operational node 7FCB547C65239FBB-000000002A2665C1 E: 30354 [DIS]Failed to advertise operational node: 3 E: 30359 [DIS]Failed to finalize service update: 3 I: 30363 [DIS]Delaying proxy of operational discovery: missing delegate I: 30370 [IN]CASE Server enabling CASE session setups I: 30375 [SVR]Joining Multicast groups I: 30380 [SVR]Server Listening... I: 30383 [DL]Device Configuration: [** I deleted factory data info **] : 30450 [DL]CHIP task running I: 30515 [DL]SRP Client was started, detected server: fd7b:8b83:4c15:0000:0000:00ff:fe00:fc11 I: 31107 [DIS]Setting operational delegate post init I: 31117 [SWU]Stopping the watchdog timer I: 31121 [SWU]Starting the periodic query timer, timeout: 86400 seconds E: 31127 [SVR]Server initialization complete I: 31131 [DIS]Updating services using commissioning mode 0 I: 31136 [DIS]Advertise operational node 7FCB547C65239FBB-000000002A2665C1 I: 31143 [DL]advertising srp service: 7FCB547C65239FBB-000000002A2665C1._matter._tcp I: 31151 [DIS]Advertise operational node 4444B5466504D146-00000000C44D730C I: 31158 [DL]advertising srp service: 4444B5466504D146-00000000C44D730C._matter._tcp I: Init: Read Featuremap: 0 I: 32566 [ZCL]Window covering cluster ID: 0x0000_FFFC Type: 27 Value: 5, length: 4 I: Init: Updated Featuremap: 5 I: Init: Read ConfigStatus: 47 I: 32579 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 47, length: 1 I: Init: Set ConfigStatus: 47 I: Init: Read Mode: 1 I: 32591 [ZCL]Window covering cluster ID: 0x0000_0017 Type: 24 Value: 0, length: 1 I: 48563 [EM]>>> [E:43627r S:0 M:5934894] (U) Msg RX from 0:957BCF2FEA0FC2F8 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 48575 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005d88 I: 48582 [IN]CASE Server disabling CASE session setups I: 48587 [EM]<<< [E:43627r S:0 M:122654070 (Ack:5934894)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 48600 [IN](U) Sending msg 122654070 to IP address 'UDP:[fd86:d57c:7973:0:1fc1:dcd8:6658:603b]:52310' I: 48610 [SC]Received Sigma1 msg I: 48617 [EM]<<< [E:43627r S:0 M:122654071 (Ack:5934894)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) I: 48632 [IN](U) Sending msg 122654071 to IP address 'UDP:[fd86:d57c:7973:0:1fc1:dcd8:6658:603b]:52310' I: 48675 [EM]>>> [E:43627r S:0 M:5934895 (Ack:122654071)] (U) Msg RX from 0:957BCF2FEA0FC2F8 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 48690 [SC]Success status report received. Session was established I: 48707 [SC]SecureSession[0x200043c8]: Moving from state 'kEstablishing' --> 'kActive' I: 48717 [IN]CASE Session established to peer: <726F18663821C3E7, 1> I: 48723 [IN]CASE Server enabling CASE session setups I: 48729 [EM]<<< [E:43627r S:0 M:122654072 (Ack:5934895)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 48741 [IN](U) Sending msg 122654072 to IP address 'UDP:[fd86:d57c:7973:0:1fc1:dcd8:6658:603b]:52310' I: 48755 [EM]>>> [E:43628r S:26320 M:98394820] (S) Msg RX from 1:726F18663821C3E7 [9FBB] --- Type 0001:03 (IM:SubscribeRequest) I: 48772 [DMG]Final negotiated min/max parameters: Min = 0s, Max = 60s E: 48787 [DMG]Error retrieving data from clusterId: 0x0000_0028, err = b I: 48800 [EM]<<< [E:43628r S:26320 M:171747804 (Ack:98394820)] (S) Msg TX to 1:726F18663821C3E7 [9FBB] --- Type 0001:05 (IM:ReportData) I: 48812 [IN](S) Sending msg 171747804 on secure session with LSID: 26320 I: 48953 [EM]>>> [E:43628r S:26320 M:98394821 (Ack:171747804)] (S) Msg RX from 1:726F18663821C3E7 [9FBB] --- Type 0001:01 (IM:StatusResponse) I: 48966 [IM]Received status response, status is 0x00 E: 48977 [DMG]Error retrieving data from clusterId: 0x0000_0033, err = b I: 48990 [EM]<<< [E:43628r S:26320 M:171747805 (Ack:98394821)] (S) Msg TX to 1:726F18663821C3E7 [9FBB] --- Type 0001:05 (IM:ReportData) I: 49002 [IN](S) Sending msg 171747805 on secure session with LSID: 26320 I: 49141 [EM]>>> [E:43628r S:26320 M:98394822 (Ack:171747805)] (S) Msg RX from 1:726F18663821C3E7 [9FBB] --- Type 0001:01 (IM:StatusResponse) I: 49153 [IM]Received status response, status is 0x00 E: 49163 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B E: 49171 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b I: 49184 [EM]<<< [E:43628r S:26320 M:171747806 (Ack:98394822)] (S) Msg TX to 1:726F18663821C3E7 [9FBB] --- Type 0001:05 (IM:ReportData) I: 49196 [IN](S) Sending msg 171747806 on secure session with LSID: 26320 I: 49354 [EM]>>> [E:43628r S:26320 M:98394823 (Ack:171747806)] (S) Msg RX from 1:726F18663821C3E7 [9FBB] --- Type 0001:01 (IM:StatusResponse) I: 49367 [IM]Received status response, status is 0x00 E: 49384 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B E: 49392 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b I: 49405 [EM]<<< [E:43628r S:26320 M:171747807 (Ack:98394823)] (S) Msg TX to 1:726F18663821C3E7 [9FBB] --- Type 0001:05 (IM:ReportData) I: 49417 [IN](S) Sending msg 171747807 on secure session with LSID: 26320 I: 49564 [EM]>>> [E:43628r S:26320 M:98394824 (Ack:171747807)] (S) Msg RX from 1:726F18663821C3E7 [9FBB] --- Type 0001:01 (IM:StatusResponse) [... I deleted a bunch of stuff…] I: 674501 [ZCL]GoToLiftPercentage 1900 command received I: 674506 [ZCL]Window covering cluster ID: 0x0000_000B Type: 231 Value: 108, length: 2 I: ZCL Callback: Target Position changed: 1900 I: 674518 [ZCL]WindowCovering has no delegate set for endpoint:1
memory reports from my build process:
-- Zephyr version: 3.4.99 (/opt/nordic/ncs/v2.5.0/zephyr), build: v3.4.99-ncs1
[139/139] Linking C executable zephyr/zephyr.elf
Memory region Used Size Region Size %age Used
FLASH: 23410 B 34176 B 68.50%
RAM: 3500 B 64 KB 5.34%
SRAM1: 0 GB 64 KB 0.00%
IDT_LIST: 0 GB 2 KB 0.00%
Generating files from /Users/ydr/dev/nordic/wb/build/multiprotocol_rpmsg/b0n/zephyr/zephyr.elf for board: wb_nrf5340_cpunet
[278/282] Linking C executable zephyr/zephyr.elf
Memory region Used Size Region Size %age Used
FLASH: 212184 B 222 KB 93.34%
RAM: 53704 B 64 KB 81.95%
SRAM1: 0 GB 64 KB 0.00%
IDT_LIST: 0 GB 2 KB 0.00%
Generating files from /Users/ydr/dev/nordic/wb/build/multiprotocol_rpmsg/zephyr/zephyr.elf for board: wb_nrf5340_cpunet
-- Zephyr version: 3.4.99 (/opt/nordic/ncs/v2.5.0/zephyr), build: v3.4.99-ncs1
[259/259] Linking C executable zephyr/zephyr.elf
Memory region Used Size Region Size %age Used
FLASH: 32872 B 48 KB 66.88%
RAM: 290948 B 440 KB 64.57%
IDT_LIST: 0 GB 2 KB 0.00%
Generating files from /Users/ydr/dev/nordic/wb/build/mcuboot/zephyr/zephyr.elf for board: wb_nrf5340_cpuapp
[11/22] Linking CXX executable zephyr/zephyr.elf
Memory region Used Size Region Size %age Used
FLASH: 801440 B 978432 B 81.91%
RAM: 186556 B 440 KB 41.41%
IDT_LIST: 0 GB 2 KB 0.00%
Generating files from /Users/ydr/dev/nordic/wb/build/zephyr/zephyr.elf for board: wb_nrf5340_cpuapp
excerpt from zcl_callbacks
void MatterWindowCoveringClusterServerAttributeChangedCallback(const app::ConcreteAttributePath &attributePath)
{
NPercent100ths value{};
chip::BitMask<Mode> modeValue;
AppEvent event;
if (attributePath.mEndpointId == MotorController::Endpoint()) {
switch (attributePath.mAttributeId) {
// Target Position changed
case Attributes::TargetPositionLiftPercent100ths::Id:
Attributes::TargetPositionLiftPercent100ths::Get((chip::EndpointId)1, value);
LOG_INF("ZCL Callback: Target Position changed: %d", value.Value());
event.Type = AppEventType::MotorMotion;
event.Handler = AppTask::MotorMotionHandler;
AppTask::Instance().PostEvent(event);
break;
// Current Position Changed
case Attributes::CurrentPositionLiftPercent100ths::Id:
Attributes::CurrentPositionLiftPercent100ths::Get((chip::EndpointId)1, value);
LOG_INF("ZCL Callback: Current Position changed: %d", value.Value());
event.Type = AppEventType::CurrentPositionChanged;
event.Handler = AppTask::MotorCurrentPositionChangedHandler;
AppTask::Instance().PostEvent(event);
break;
default:
MotorController::Instance().SchedulePostAttributeChange(attributePath.mEndpointId,
attributePath.mAttributeId);
break;
};
}
}
