Multiple issues with Matter Light Bulb sample connecting to Apple Homekit

[Razorback16]

Hi,

I'm trying out the Matter: Light bulb example using an nrf52840 device on NRF52840-DK. So far, I have managed to build the software, flash the device, provision it into the network using Apple HomeKit at iOS 16.2

But I am facing the following issues

1. After setting a brightness of <100% if I switch off and then switch on I see the old brightness level is not preserved, it shoots up to 100% every time. I see that there are 2 requests coming to the device, 1 -> Turn on, 2 -> Set to 100%, but that's not the case with any other homekit bulbs

2. If I power off the device for more than 5 minutes, and then power on, the device doesn't work anymore, it says it's provisioned and connected from the log but still no response on HomeKit App. If I power off and power on immediately, I see  it's able to connect back to network and works.

3. When I first provision the board in homekit I can't identify the bulb with a blink from HomeKit app.

Are these known issues and in the process of fixing?

[Marte Myrvold]

Hi,

I am not aware of these or similar issues being reported before, but I will check internally.

Which version of the SDK are you using?

Please provide logs from the device showing these issues.

Best regards,

Marte

[Razorback16]

am using NRF Connect SDK v2.2.0. I have attached 3 logs.

1. A log shows factory reset and then provisioning to HomeKit,  

2. A log to show that it's connected to the thread network, but when I try to switch on of the device from homekit it doesn't work

3. A log to show that when it works, changing brightness and then turn off and turn on forces it to 100% brightness

1.factory_reset_and_provisioning.log

2.connected_to_network_but_not_working.log

Fullscreen 3.change_brigntness_then_off_then_on.log Download

picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready
ding Reports for ReadHandler with LastReportGeneration = 37 DirtyGeneration = 37
D: 152575 [DMG]Fetched 0 events
D: 152578 [DMI: 157635 [DMG]Refresh subscribe timer sync after 5 seconds
D: 157640 [DMG]Building Reports for ReadHandler with LastReportGeneration = 37 DirtyGeneration = 37
D: 157655 [DMG]Fetched 0 events
D: 157658 [DMG]<RE> Sending report (payload has 11 bytes)...
D: 157663 [DMG]IM RH moving to [AwaitingReportResponse]
I: 157669 [EM]<<< [E:21394i M:24981931] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 157679 [IN](S) Sending msg 24981931 on secure session with LSID: 4175
I: 157687 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 157694 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 157702 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 157708 [DMG]Unblock report hold after min 0 seconds
I: 157738 [EM]>>> [E:21394i M:239140435 (Ack:24981931)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 157749 [EM]Found matching exchange: 21394i, Delegate: 0x200116e4
D: 157756 [EM]Rxd Ack; Removing MessageCounter:24981931 from Retrans Table on exchange 21394i
I: 157764 [IM]Received status response, status is 0x00
D: 157769 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 157774 [DMG]IM RH moving to [GeneratingReports]
I: 157779 [EM]<<< [E:21394i M:24981932 (Ack:239140435)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 157791 [IN](S) Sending msg 24981932 on secure session with LSID: 4175
D: 157799 [EM]Flushed pending ack for MessageCounter:239140435 on exchange 21394i
D: 157807 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 162135 [EM]>>> [E:60364r M:239140436] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 162147 [EM]Handling via exchange: 60364r, Delegate: 0x2000fc3c
D: 162153 [DMG]Received command for Endpoint=1 Cluster=0x0000_0008 Command=0x0000_0004
I: 162161 [ZCL]0xd3daaMOVE_TO_LEVEL_WITH_ON_OFF 8a  0 0 0
D: 162166 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de1
D: 162173 [DMG]Cannot merge the new path into any existing path, create one.
D: 162180 [DMG]Command handler moving to [ Preparing]
D: 162184 [DMG]Command handler moving to [AddingComm]
D: 162189 [DMG]Command handler moving to [AddedComma]
D: 162194 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 162201 [EM]<<< [E:60364r M:24981933 (Ack:239140436)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 162214 [IN](S) Sending msg 24981933 on secure session with LSID: 4175
D: 162221 [DMG]Command handler moving to [CommandSen]
D: 162226 [DMG]Command handler moving to [AwaitingDe]
I: 162232 [ZCL]Event: move from 254
I: 162235 [ZCL] to 138 
I: 162237 [ZCL](diff -1)
D: 162240 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f1775
D: 162248 [DMG]Cannot merge the new path into any existing path, create one.
I: 162257 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 138
I: Level Action has been initiated
I: Setting brightness level to 138
I: Level Action has been completed
I: 162272 [ZCL]Setting on/off to 0xdc765 due to level change
I: 162278 [ZCL]On/Off set value: 1 1
I: 162281 [ZCL]On/off already set to new value
D: 162285 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f1776
D: 162292 [DMG]Cannot merge the new path into any existing path, create one.
D: 162299 [DMG]Building Reports for ReadHandler with LastReportGeneration = 37 DirtyGeneration = 40
D: 162312 [DMG]<RE:Run> Cluster 6, Attribute 4000 is dirty
D: 162317 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4000 (expanded=1)
D: 162326 [DMG]<RE:Run> Cluster 8, Attribute 0 is dirty
D: 162331 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D: 162341 [DMG]<RE:Run> Cluster 8, Attribute 1 is dirty
D: 162346 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0001 (expanded=1)
D: 162356 [DMG]Fetched 0 events
D: 162359 [DMG]<RE> Sending report (payload has 92 bytes)...
D: 162365 [DMG]IM RH moving to [AwaitingReportResponse]
I: 162371 [EM]<<< [E:21395i M:24981934] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 162381 [IN](S) Sending msg 24981934 on secure session with LSID: 4175
I: 162388 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 162396 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 162404 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 162410 [DMG]Unblock report hold after min 0 seconds
I: 162416 [EM]>>> [E:60364r M:239140437 (Ack:24981933)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 162429 [EM]Found matching exchange: 60364r, Delegate: (nil)
D: 162436 [EM]Rxd Ack; Removing MessageCounter:24981933 from Retrans Table on exchange 60364r
I: 162446 [EM]>>> [E:60365r M:239140438] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 162457 [EM]Handling via exchange: 60365r, Delegate: 0x2000fc3c
D: 162463 [DMG]Received command for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0001
I: 162471 [ZCL]On/Off set value: 1 1
I: 162474 [ZCL]On/off already set to new value
D: 162478 [DMG]Command handler moving to [ Preparing]
D: 162483 [DMG]Command handler moving to [AddingComm]
D: 162488 [DMG]Command handler moving to [AddedComma]
D: 162493 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 162500 [EM]<<< [E:60365r M:24981935 (Ack:239140438)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 162513 [IN](S) Sending msg 24981935 on secure session with LSID: 4175
D: 162520 [DMG]Command handler moving to [CommandSen]
D: 162525 [DMG]Command handler moving to [AwaitingDe]
I: 162532 [EM]>>> [E:21395i M:239140439 (Ack:24981934)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 162544 [EM]Found matching exchange: 21395i, Delegate: 0x200116e4
D: 162552 [EM]Rxd Ack; Removing MessageCounter:24981934 from Retrans Table on exchange 21395i
I: 162560 [IM]Received status response, status is 0x00
D: 162565 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 162570 [DMG]IM RH moving to [GeneratingReports]
I: 162575 [EM]<<< [E:21395i M:24981936 (Ack:239140439)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 162587 [IN](S) Sending msg 24981936 on secure session with LSID: 4175
D: 162595 [EM]Flushed pending ack for MessageCounter:239140439 on exchange 21395i
D: 162603 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 162610 [EM]>>> [E:60365r M:239140440 (Ack:24981935)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 162622 [EM]Found matching exchange: 60365r, Delegate: (nil)
D: 162628 [EM]Rxd Ack; Removing MessageCounter:24981935 from Retrans Table on exchange 60365r
I: 166897 [EM]>>> [E:60366r M:239140441] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 166908 [EM]Handling via exchange: 60366r, Delegate: 0x2000fc3c
D: 166915 [DMG]Received command for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0000
I: 166922 [ZCL]On/Off set value: 1 0
I: 166926 [ZCL]Toggle on/off from 1 to 0
I: 166929 [ZCL]Off Command - OnTime :  0
D: 166933 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de2
D: 166940 [DMG]Cannot merge the new path into any existing path, create one.
D: 166947 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de3
D: 166953 [DMG]Cannot merge the new path into any existing path, create one.
D: 166960 [DMG]Command handler moving to [ Preparing]
D: 166965 [DMG]Command handler moving to [AddingComm]
D: 166970 [DMG]Command handler moving to [AddedComma]
D: 166975 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 166982 [EM]<<< [E:60366r M:24981937 (Ack:239140441)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 166994 [IN](S) Sending msg 24981937 on secure session with LSID: 4175
D: 167002 [DMG]Command handler moving to [CommandSen]
D: 167007 [DMG]Command handler moving to [AwaitingDe]
D: 167013 [DMG]Building Reports for ReadHandler with LastReportGeneration = 40 DirtyGeneration = 42
D: 167026 [DMG]<RE:Run> Cluster 6, Attribute 4000 is dirty
D: 167032 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4000 (expanded=1)
D: 167042 [DMG]<RE:Run> Cluster 6, Attribute 4001 is dirty
D: 167047 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4001 (expanded=1)
D: 167059 [DMG]Fetched 0 events
D: 167063 [DMG]<RE> Sending report (payload has 67 bytes)...
D: 167069 [DMG]IM RH moving to [AwaitingReportResponse]
I: 167075 [EM]<<< [E:21396i M:24981938] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 167084 [IN](S) Sending msg 24981938 on secure session with LSID: 4175
I: 167092 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 167100 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 167108 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 167114 [ZCL]Event: move from 138
I: 167118 [ZCL] to 1 
I: 167120 [ZCL](diff -1)
D: 167122 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f1777
D: 167130 [DMG]Cannot merge the new path into any existing path, create one.
I: 167137 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 167152 [ZCL]Setting on/off to 0xd3dd2 due to level change
I: 167158 [ZCL]On/Off set value: 1 0
I: 167161 [ZCL]Toggle on/off from 1 to 0
I: 167165 [ZCL]Off Command - OnTime :  0
D: 167168 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de4
D: 167175 [DMG]Cannot merge the new path into any existing path, create one.
D: 167198 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de5
D: 167204 [DMG]Cannot merge the new path into any existing path, create one.
I: 167211 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
D: 167223 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f1778
D: 167229 [DMG]Cannot merge the new path into any existing path, create one.
D: 167236 [DMG]Unblock report hold after min 0 seconds
I: 167242 [EM]>>> [E:60366r M:239140442 (Ack:24981937)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 167255 [EM]Found matching exchange: 60366r, Delegate: (nil)
D: 167260 [EM]Rxd Ack; Removing MessageCounter:24981937 from Retrans Table on exchange 60366r
I: 167269 [EM]>>> [E:21396i M:239140443 (Ack:24981938)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 167281 [EM]Found matching exchange: 21396i, Delegate: 0x200116e4
D: 167287 [EM]Rxd Ack; Removing MessageCounter:24981938 from Retrans Table on exchange 21396i
I: 167296 [IM]Received status response, status is 0x00
D: 167301 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 167305 [DMG]IM RH moving to [GeneratingReports]
I: 167311 [EM]<<< [E:21396i M:24981939 (Ack:239140443)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 167323 [IN](S) Sending msg 24981939 on secure session with LSID: 4175
D: 167331 [EM]Flushed pending ack for MessageCounter:239140443 on exchange 21396i
D: 167338 [DMG]Building Reports for ReadHandler with LastReportGeneration = 42 DirtyGeneration = 46
D: 167352 [DMG]<RE:Run> Cluster 6, Attribute 0 is dirty
D: 167357 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D: 167366 [DMG]<RE:Run> Cluster 6, Attribute 4001 is dirty
D: 167372 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4001 (expanded=1)
D: 167381 [DMG]<RE:Run> Cluster 8, Attribute 0 is dirty
D: 167386 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D: 167395 [DMG]<RE:Run> Cluster 8, Attribute 1 is dirty
D: 167400 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0001 (expanded=1)
D: 167411 [DMG]Fetched 0 events
D: 167414 [DMG]<RE> Sending report (payload has 118 bytes)...
D: 167419 [DMG]IM RH moving to [AwaitingReportResponse]
I: 167425 [EM]<<< [E:21397i M:24981940] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 167435 [IN](S) Sending msg 24981940 on secure session with LSID: 4175
I: 167443 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 167450 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 167459 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 167465 [DMG]Unblock report hold after min 0 seconds
I: 167508 [EM]>>> [E:21397i M:239140444 (Ack:24981940)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 167520 [EM]Found matching exchange: 21397i, Delegate: 0x200116e4
D: 167526 [EM]Rxd Ack; Removing MessageCounter:24981940 from Retrans Table on exchange 21397i
I: 167534 [IM]Received status response, status is 0x00
D: 167539 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 167544 [DMG]IM RH moving to [GeneratingReports]
I: 167550 [EM]<<< [E:21397i M:24981941 (Ack:239140444)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 167562 [IN](S) Sending msg 24981941 on secure session with LSID: 4175
D: 167570 [EM]Flushed pending ack for MessageCounter:239140444 on exchange 21397i
D: 167577 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 170494 [EM]>>> [E:60367r M:239140445] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 170506 [EM]Handling via exchange: 60367r, Delegate: 0x2000fc3c
D: 170512 [DMG]Received command for Endpoint=1 Cluster=0x0000_0008 Command=0x0000_0004
I: 170520 [ZCL]0xd3daaMOVE_TO_LEVEL_WITH_ON_OFF fe  0 0 0
I: 170525 [ZCL]Setting on/off to 0xdc765 due to level change
I: 170531 [ZCL]On/Off set value: 1 1
I: 170534 [ZCL]Toggle on/off from 0 to 1
I: 170537 [ZCL]On Command - OffWaitTime :  0
D: 170542 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de6
D: 170548 [DMG]Cannot merge the new path into any existing path, create one.
I: 170555 [ZCL]On/Toggle Command - Stop Timer
D: 170559 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de7
D: 170566 [DMG]Cannot merge the new path into any existing path, create one.
D: 170591 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de8
D: 170597 [DMG]Cannot merge the new path into any existing path, create one.
I: 170604 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
D: 170616 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 7c302de9
D: 170622 [DMG]Command handler moving to [ Preparing]
D: 170627 [DMG]Command handler moving to [AddingComm]
D: 170632 [DMG]Command handler moving to [AddedComma]
D: 170637 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 170644 [EM]<<< [E:60367r M:24981942 (Ack:239140445)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 170657 [IN](S) Sending msg 24981942 on secure session with LSID: 4175
D: 170664 [DMG]Command handler moving to [CommandSen]
D: 170669 [DMG]Command handler moving to [AwaitingDe]
D: 170675 [DMG]Building Reports for ReadHandler with LastReportGeneration = 46 DirtyGeneration = 50
D: 170689 [DMG]<RE:Run> Cluster 6, Attribute 0 is dirty
D: 170694 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D: 170705 [DMG]<RE:Run> Cluster 6, Attribute 4000 is dirty
D: 170712 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4000 (expanded=1)
D: 170721 [DMG]<RE:Run> Cluster 6, Attribute 4002 is dirty
D: 170726 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_4002 (expanded=1)
D: 170738 [DMG]Fetched 0 events
D: 170740 [DMG]<RE> Sending report (payload has 92 bytes)...
D: 170746 [DMG]IM RH moving to [AwaitingReportResponse]
I: 170752 [EM]<<< [E:21398i M:24981943] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 170762 [IN](S) Sending msg 24981943 on secure session with LSID: 4175
I: 170770 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 170777 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 170786 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 170792 [ZCL]Event: move from 1
I: 170795 [ZCL] to 254 
I: 170797 [ZCL](diff +1)
D: 170799 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f1779
D: 170806 [DMG]Cannot merge the new path into any existing path, create one.
I: 170815 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 170830 [ZCL]Setting on/off to 0xdc765 due to level change
I: 170836 [ZCL]On/Off set value: 1 1
I: 170839 [ZCL]On/off already set to new value
D: 170843 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 7a9f177a
D: 170850 [DMG]Cannot merge the new path into any existing path, create one.
D: 170857 [DMG]Unblock report hold after min 0 seconds
I: 170863 [EM]>>> [E:60367r M:239140446 (Ack:24981942)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 170875 [EM]Found matching exchange: 60367r, Delegate: (nil)
D: 170881 [EM]Rxd Ack; Removing MessageCounter:24981942 from Retrans Table on exchange 60367r
I: 170890 [EM]>>> [E:60368r M:239140447] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 170901 [EM]Handling via exchange: 60368r, Delegate: 0x2000fc3c
D: 170908 [DMG]Received command for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0001
I: 170915 [ZCL]On/Off set value: 1 1
I: 170919 [ZCL]On/off already set to new value
D: 170923 [DMG]Command handler moving to [ Preparing]
D: 170928 [DMG]Command handler moving to [AddingComm]
D: 170932 [DMG]Command handler moving to [AddedComma]
D: 170937 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 170945 [EM]<<< [E:60368r M:24981944 (Ack:239140447)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 170957 [IN](S) Sending msg 24981944 on secure session with LSID: 4175
D: 170965 [DMG]Command handler moving to [CommandSen]
D: 170970 [DMG]Command handler moving to [AwaitingDe]
I: 170976 [EM]>>> [E:21398i M:239140448 (Ack:24981943)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 170988 [EM]Found matching exchange: 21398i, Delegate: 0x200116e4
D: 170994 [EM]Rxd Ack; Removing MessageCounter:24981943 from Retrans Table on exchange 21398i
I: 171004 [IM]Received status response, status is 0x00
D: 171009 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 171014 [DMG]IM RH moving to [GeneratingReports]
I: 171019 [EM]<<< [E:21398i M:24981945 (Ack:239140448)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 171032 [IN](S) Sending msg 24981945 on secure session with LSID: 4175
D: 171039 [EM]Flushed pending ack for MessageCounter:239140448 on exchange 21398i
D: 171047 [DMG]Building Reports for ReadHandler with LastReportGeneration = 50 DirtyGeneration = 52
D: 171061 [DMG]<RE:Run> Cluster 8, Attribute 0 is dirty
D: 171066 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D: 171075 [DMG]<RE:Run> Cluster 8, Attribute 1 is dirty
D: 171080 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_0001 (expanded=1)
D: 171091 [DMG]Fetched 0 events
D: 171094 [DMG]<RE> Sending report (payload has 66 bytes)...
D: 171099 [DMG]IM RH moving to [AwaitingReportResponse]
I: 171105 [EM]<<< [E:21399i M:24981946] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0001:05 (IM:ReportData)
I: 171115 [IN](S) Sending msg 24981946 on secure session with LSID: 4175
I: 171123 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 5 seconds
D: 171131 [DMG]<RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
D: 171138 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 171146 [EM]>>> [E:60368r M:239140449 (Ack:24981944)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 171158 [EM]Found matching exchange: 60368r, Delegate: (nil)
D: 171165 [EM]Rxd Ack; Removing MessageCounter:24981944 from Retrans Table on exchange 60368r
D: 171173 [DMG]Unblock report hold after min 0 seconds
I: 171205 [EM]>>> [E:21399i M:239140450 (Ack:24981946)] (S) Msg RX from 1:6F410DEE7E9CE196 [FD25] --- Type 0001:01 (IM:StatusResponse)
D: 171217 [EM]Found matching exchange: 21399i, Delegate: 0x200116e4
D: 171223 [EM]Rxd Ack; Removing MessageCounter:24981946 from Retrans Table on exchange 21399i
I: 171232 [IM]Received status response, status is 0x00
D: 171237 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 171241 [DMG]IM RH moving to [GeneratingReports]
I: 171246 [EM]<<< [E:21399i M:24981947 (Ack:239140450)] (S) Msg TX to 1:6F410DEE7E9CE196 [FD25] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 171259 [IN](S) Sending msg 24981947 on secure session with LSID: 4175
D: 171267 [EM]Flushed pending ack for MessageCounter:239140450 on exchange 21399i
D: 171274 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet

Terminating...
Skipping tty reset...
Thanks for using picocom

[Marte Myrvold]

Hi,

Issue 2 is an expected behavior in Matter 1.0. Matter 1.0 has a backoff mechanism that can take from 30 minutes to 90 minute to re-trigger a CASE session reestablishment if an accessory was not reachable for some time. Rebooting the Homepod will re-trigger the CASE session establishment. This is expected to be fixed in a later version of Matter, but for now rebooting the Homepod is a workaround for this problem.

Best regards,

Marte

[Razorback16]

Hi,

Thanks for the clarification on Issue 2. What about Issue 1? Is it a issue with HomeKit sending multiple commands to nRF chip when turned on to change the brightness to 100%?

[Marte Myrvold]

Hi,

This seems to be related to a small sample configuration problem. The developers will fix it in the Matter upstream, but it might take some time before the changes are in nRF Connect SDK. A workaround in the meantime is to change this value from FE to FF: https://github.com/nrfconnect/sdk-nrf/blob/main/samples/matter/light_bulb/src/zap-generated/endpoint_config.h#L500 and recompiling the target.

Best regards,

Marte

[Razorback16]

This works. Thanks. And what about issue 3. Is the identify functionality not implemented yet?

[Marte Myrvold]

Hi,

The Identify functionality should be implemented in the light bulb. Do you see anything happening on the device when you are trying to send the Identify command, any logs?

Best regards,

Marte