Homekit stops responding after reboot Apple TV

[SunHuang]

Hi,

I use an Apple TV 4K which is acting as my Homekit hub.

There is an issue, matter lock can’t activate after reboot Apple TV and reconnect matter lock,  hence, matter lock can’t work and no response.

App is on busy status and shows "locking"

lf I delete the device in Home App and restore DK to factory settings do a fresh pair it works fine…

The log list is as follows:

Fullscreen lock_log.txt Download

===========================Apple TV power off===========================

I: 1166139 [DMG]Refresh subscribe timer sync after 60 seconds
I: 1166156 [EM]<<< [E:31166i S:35635 M:37142774] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1166167 [IN](S) Sending msg 37142774 on secure session with LSID: 35635
E: 1166174 [DMG]<RE> Error sending out report data with 2000073!


===========================Apple TV restart===========================

I: 1416303 [DL]SRP Client was stopped, because current server is no longer detected.
I: 1416310 [DL]SRP Client was started, detected server: fd53:816d:3a22:eb7e:0000:00ff:fe00:fc11
D: 1416319 [DL]OpenThread State Changed (Flags: 0x200002a4)
D: 1416324 [DL]   Device Role: CHILD
D: 1416328 [DL]   Partition Id: 0x3D697F9
D: 1417509 [DL]SRP update succeeded
I: 1418519 [EM]>>> [E:47002r S:0 M:7972370] (U) Msg RX from 0:F78CFD0041C0DE19 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 1418530 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20006128
I: 1418538 [IN]CASE Server disabling CASE session setups
I: 1418543 [EM]<<< [E:47002r S:0 M:255169215 (Ack:7972370)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1418556 [IN](U) Sending msg 255169215 to IP address 'UDP:[fd92:ed99:90ff:0:58e9:2e55:66b2:ef80]:55127'
I: 1418567 [SC]Received Sigma1 msg
I: 1418575 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000076959E9A
I: 1418755 [EM]<<< [E:47002r S:0 M:255169216 (Ack:7972370)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 1418768 [IN](U) Sending msg 255169216 to IP address 'UDP:[fd92:ed99:90ff:0:58e9:2e55:66b2:ef80]:55127'
I: 1418779 [DL]OpenThread SED interval is 200ms
I: 1418784 [SC]Sent Sigma2 msg
I: 1419062 [EM]>>> [E:47002r S:0 M:7972371 (Ack:255169216)] (U) Msg RX from 0:F78CFD0041C0DE19 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 1419075 [EM]<<< [E:47002r S:0 M:255169217 (Ack:7972371)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1419088 [IN](U) Sending msg 255169217 to IP address 'UDP:[fd92:ed99:90ff:0:58e9:2e55:66b2:ef80]:55127'
I: 1419098 [SC]Received Sigma3 msg
E: 1419106 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 1419224 [DL]Long dispatch time: 107 ms, for event type 2
I: 1419234 [EM]<<< [E:47002r S:0 M:255169218 (Ack:7972371)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1419248 [IN](U) Sending msg 255169218 to IP address 'UDP:[fd92:ed99:90ff:0:58e9:2e55:66b2:ef80]:55127'
I: 1419260 [SC]SecureSession[0x20004b00]: Moving from state 'kEstablishing' --> 'kActive'
D: 1419268 [IN]SecureSession[0x20004b00]: Activated - Type:2 LSID:35636
D: 1419275 [IN]New secure session activated for device <00000000FE2354B8, 1>, LSID:35636 PSID:32690!
I: 1419285 [IN]CASE Session established to peer: <00000000FE2354B8, 1>
I: 1419292 [IN]CASE Server enabling CASE session setups
D: 1419297 [IN]SecureSession[0x20004bb8]: Allocated Type:2 LSID:35637
I: 1419474 [EM]>>> [E:47003r S:35636 M:10087130] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1419488 [IM]Received Read request
I: 1419493 [EM]<<< [E:47003r S:35636 M:193811316 (Ack:10087130)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1419505 [IN](S) Sending msg 193811316 on secure session with LSID: 35636
I: 1419514 [EM]>>> [E:47004r S:35636 M:10087131] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:03 (IM:SubscribeRequest)
D: 1419526 [IM]Received Subscribe request
I: 1419530 [DMG]Final negotiated min/max parameters: Min = 0s, Max = 60s
E: 1419547 [DMG]Error retrieving data from clusterId: 0x0000_0028, err = b
I: 1419560 [EM]<<< [E:47004r S:35636 M:193811317 (Ack:10087131)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1419572 [IN](S) Sending msg 193811317 on secure session with LSID: 35636
I: 1419616 [EM]>>> [E:47002r S:0 M:7972372 (Ack:255169218)] (U) Msg RX from 0:F78CFD0041C0DE19 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1419646 [EM]>>> [E:47005r S:35636 M:10087132] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1419657 [IM]Received Read request
I: 1419664 [EM]<<< [E:47005r S:35636 M:193811318 (Ack:10087132)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1419679 [IN](S) Sending msg 193811318 on secure session with LSID: 35636
I: 1419687 [EM]>>> [E:47003r S:35636 M:10087133 (Ack:193811316)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1419808 [EM]>>> [E:47006r S:35636 M:10087134] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1419820 [IM]Received Read request
I: 1419826 [EM]<<< [E:47006r S:35636 M:193811319 (Ack:10087134)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1419839 [IN](S) Sending msg 193811319 on secure session with LSID: 35636
I: 1419962 [EM]>>> [E:47004r S:35636 M:10087135 (Ack:193811317)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1419976 [IM]Received status response, status is 0x00
E: 1419993 [DMG]Error retrieving data from clusterId: 0x0000_0031, err = b
I: 1420010 [EM]<<< [E:47004r S:35636 M:193811320 (Ack:10087135)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420024 [IN](S) Sending msg 193811320 on secure session with LSID: 35636
I: 1420035 [EM]>>> [E:47005r S:35636 M:10087136 (Ack:193811318)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420052 [EM]>>> [E:47007r S:35636 M:10087137] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1420063 [IM]Received Read request
I: 1420070 [EM]<<< [E:47007r S:35636 M:193811321 (Ack:10087137)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420083 [IN](S) Sending msg 193811321 on secure session with LSID: 35636
I: 1420092 [EM]>>> [E:47006r S:35636 M:10087138 (Ack:193811319)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420122 [EM]>>> [E:47008r S:35636 M:10087139] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1420133 [IM]Received Read request
I: 1420139 [EM]<<< [E:47008r S:35636 M:193811322 (Ack:10087139)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420152 [IN](S) Sending msg 193811322 on secure session with LSID: 35636
I: 1420258 [EM]>>> [E:47004r S:35636 M:10087140 (Ack:193811320)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1420271 [IM]Received status response, status is 0x00
E: 1420282 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
E: 1420290 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 1420305 [EM]<<< [E:47004r S:35636 M:193811323 (Ack:10087140)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420319 [IN](S) Sending msg 193811323 on secure session with LSID: 35636
I: 1420330 [EM]>>> [E:47007r S:35636 M:10087141 (Ack:193811321)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420347 [EM]>>> [E:47009r S:35636 M:10087142] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1420359 [IM]Received Read request
I: 1420365 [EM]<<< [E:47009r S:35636 M:193811324 (Ack:10087142)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420379 [IN](S) Sending msg 193811324 on secure session with LSID: 35636
I: 1420388 [EM]>>> [E:47008r S:35636 M:10087143 (Ack:193811322)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420512 [EM]>>> [E:47010r S:35636 M:10087144] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1420524 [IM]Received Read request
I: 1420530 [EM]<<< [E:47010r S:35636 M:193811325 (Ack:10087144)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420543 [IN](S) Sending msg 193811325 on secure session with LSID: 35636
I: 1420655 [EM]>>> [E:47004r S:35636 M:10087145 (Ack:193811323)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1420671 [IM]Received status response, status is 0x00
E: 1420679 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
E: 1420687 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 1420700 [EM]<<< [E:47004r S:35636 M:193811326 (Ack:10087145)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420713 [IN](S) Sending msg 193811326 on secure session with LSID: 35636
I: 1420722 [EM]>>> [E:47009r S:35636 M:10087146 (Ack:193811324)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420798 [EM]>>> [E:47010r S:35636 M:10087147 (Ack:193811325)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1420828 [EM]>>> [E:47011r S:35636 M:10087148] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1420840 [IM]Received Read request
I: 1420846 [EM]<<< [E:47011r S:35636 M:193811327 (Ack:10087148)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1420859 [IN](S) Sending msg 193811327 on secure session with LSID: 35636
I: 1420970 [EM]>>> [E:47004r S:35636 M:10087149 (Ack:193811326)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1420984 [IM]Received status response, status is 0x00
E: 1421003 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 1421015 [EM]<<< [E:47004r S:35636 M:193811328 (Ack:10087149)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1421028 [IN](S) Sending msg 193811328 on secure session with LSID: 35636
I: 1421113 [EM]>>> [E:47011r S:35636 M:10087150 (Ack:193811327)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1421142 [EM]>>> [E:47012r S:35636 M:10087151] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1421154 [IM]Received Read request
I: 1421160 [EM]<<< [E:47012r S:35636 M:193811329 (Ack:10087151)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1421173 [IN](S) Sending msg 193811329 on secure session with LSID: 35636
I: 1421290 [EM]>>> [E:47004r S:35636 M:10087152 (Ack:193811328)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1421304 [IM]Received status response, status is 0x00
I: 1421312 [ZCL]The WiFi interface is not currently connected.
I: 1421318 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421326 [ZCL]The current 802.11 standard version in use by the Node is not available
I: 1421334 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421341 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421348 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421355 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421362 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421369 [ZCL]The WiFi interface is not currently configured or operational.
I: 1421376 [ZCL]The WiFi interface is not currently configured or operational.
E: 1421386 [DMG]Error retrieving data from clusterId: 0x0000_003E, err = b
I: 1421400 [EM]<<< [E:47004r S:35636 M:193811330 (Ack:10087152)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1421412 [IN](S) Sending msg 193811330 on secure session with LSID: 35636
I: 1421422 [EM]>>> [E:47012r S:35636 M:10087153 (Ack:193811329)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1421706 [EM]>>> [E:47004r S:35636 M:10087154 (Ack:193811330)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1421719 [IM]Received status response, status is 0x00
E: 1421727 [DMG]Error retrieving data from clusterId: 0x0000_003E, err = b
I: 1421741 [EM]<<< [E:47004r S:35636 M:193811331 (Ack:10087154)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1421753 [IN](S) Sending msg 193811331 on secure session with LSID: 35636
I: 1421908 [EM]>>> [E:47004r S:35636 M:10087155 (Ack:193811331)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1421921 [IM]Received status response, status is 0x00
E: 1421932 [DMG]Error retrieving data from clusterId: 0x0000_001D, err = b
I: 1421945 [EM]<<< [E:47004r S:35636 M:193811332 (Ack:10087155)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1421957 [IN](S) Sending msg 193811332 on secure session with LSID: 35636
I: 1422304 [EM]>>> [E:47004r S:35636 M:10087156 (Ack:193811332)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1422317 [IM]Received status response, status is 0x00
E: 1422325 [DMG]Error retrieving data from clusterId: 0x0000_0101, err = b
I: 1422339 [EM]<<< [E:47004r S:35636 M:193811333 (Ack:10087156)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1422351 [IN](S) Sending msg 193811333 on secure session with LSID: 35636
I: 1422506 [EM]>>> [E:47004r S:35636 M:10087157 (Ack:193811333)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1422518 [IM]Received status response, status is 0x00
I: 1422537 [EM]<<< [E:47004r S:35636 M:193811334 (Ack:10087157)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1422549 [IN](S) Sending msg 193811334 on secure session with LSID: 35636
I: 1422705 [EM]>>> [E:47004r S:35636 M:10087158 (Ack:193811334)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1422718 [IM]Received status response, status is 0x00
I: 1422737 [EM]<<< [E:47004r S:35636 M:193811335 (Ack:10087158)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1422749 [IN](S) Sending msg 193811335 on secure session with LSID: 35636
I: 1422906 [EM]>>> [E:47004r S:35636 M:10087159 (Ack:193811335)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:01 (IM:StatusResponse)
I: 1422919 [IM]Received status response, status is 0x00
I: 1422924 [DMG]Refresh Subscribe Sync Timer with min 0 seconds and max 60 seconds
I: 1422932 [EM]<<< [E:47004r S:35636 M:193811336 (Ack:10087159)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:04 (IM:SubscribeResponse)
I: 1422945 [IN](S) Sending msg 193811336 on secure session with LSID: 35636
I: 1423115 [EM]>>> [E:47004r S:35636 M:10087160 (Ack:193811336)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1423132 [DL]OpenThread SED interval is 1000ms
I: 1423137 [EM]>>> [E:47013r S:35636 M:10087161] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1423148 [IM]Received Read request
I: 1423152 [DL]OpenThread SED interval is 200ms
I: 1423159 [EM]<<< [E:47013r S:35636 M:193811337 (Ack:10087161)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1423171 [IN](S) Sending msg 193811337 on secure session with LSID: 35636
I: 1423449 [EM]>>> [E:47013r S:35636 M:10087162 (Ack:193811337)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1423462 [DL]OpenThread SED interval is 1000ms
I: 1436449 [EM]>>> [E:47014r S:35636 M:10087163] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0001:02 (IM:ReadRequest)
D: 1436460 [IM]Received Read request
I: 1436464 [DL]OpenThread SED interval is 200ms
I: 1436470 [EM]<<< [E:47014r S:35636 M:193811338 (Ack:10087163)] (S) Msg TX to 1:00000000FE2354B8 [146E] --- Type 0001:05 (IM:ReportData)
I: 1436482 [IN](S) Sending msg 193811338 on secure session with LSID: 35636
I: 1436650 [EM]>>> [E:47014r S:35636 M:10087164 (Ack:193811338)] (S) Msg RX from 1:00000000FE2354B8 [146E] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1436663 [DL]OpenThread SED interval is 1000ms

Deice:Apple TV 4K (3rd generation)(A2843)
tvOS: 17.1(21k69)
Hardware used: nrf5340 dk
example:C:\ncs\v2.4.1\nrf\samples\matter\lock

[Kenneth]

Hello,

I am not aware of any issue, I will see if I can test myself this weekend. Maybe you can also test light bulb example following this guide for comparison:
https://devzone.nordicsemi.com/nordic/nordic-blog/b/blog/posts/matter-testing-nrf-connect-sdk-platform-with-apple-google-and-samsung-ecosystems-218911247

When having issues it always is worth trying the latest tagged release for comparison:
https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.5.0/nrf/index.html 

Kenneth

[SunHuang]

Hi Kenneth

This issue in the matter1.2 release has been improved,thanks