Hi,
I'm doing a test with a test harness.
An error occurs in test case TC-CNET-4.16.
I would like to know how to solve this problem.
environment
・TH
raspberry pi 4
Version: v2.11+fall2024
Sha: 8f86ccd
・DUT
nrf52840 custom board
ncsv2.9.0
sample code : matter lock
・TH log
TC-CNET-4_16_2025_02_04_23_53_37_TH_Log.log
・DUT Log
uart:~$ *** Booting My Application v2.9.0 - unknown commit *** *** Using nRF Connect SDK v2.9.0-7787b2649840 *** *** Using Zephyr OS v3.7.99-1f8f3dc29142 *** I: 34 [DL]BLE address: C9:19:25:77:B5:20 I: No users indexes stored I: No stored indexes for credential of type: 1 I: 51 [DL]CHIP task running I: Init CHIP stack I: 56 [DL]OpenThread started: OK I: 59 [DL]Setting OpenThread device type to SLEEPY END DEVICE I: 66 [SVR]Subscription persistence not supported I: 71 [SVR]Server initializing... I: 74 [TS]Last Known Good Time: 2023-10-14T01:16:48 I: 79 [DMG]AccessControl: initializing I: 83 [DMG]Examples::AccessControlDelegate::Init I: 87 [DMG]AccessControl: setting I: 90 [DMG]DefaultAclStorage: initializing I: 94 [DMG]DefaultAclStorage: 0 entries loaded E: 98 [IN]IPV6_PKTINFO failed: 109 I: 106 [ZCL]Using ZAP configuration... I: 111 [DMG]AccessControlCluster: initializing I: 115 [ZCL]Initiating Admin Commissioning cluster. I: 120 [ZCL]Door Lock server initialized I: 124 [ZCL]Door Lock cluster initialized at endpoint #1 I: 129 [ZCL]0xbff35 ep 1 clus 0x0000_0101 attr 0x0000_0013 not supported E: 136 [ZCL]Failed to set DoorLock number of RFID users: 86 I: 141 [DIS]Updating services using commissioning mode 0 E: 146 [DIS]Failed to remove advertised services: 3 E: 151 [DIS]Failed to finalize service update: 3 I: 155 [IN]CASE Server enabling CASE session setups I: 160 [SVR]Joining Multicast groups I: 164 [SVR]Server Listening... I: 166 [DL]Device Configuration: I: 169 [DL] Serial Number: 11223344556677889900 I: 174 [DL] Vendor Id: 65521 (0xFFF1) I: 177 [DL] Product Id: 32774 (0x8006) I: 181 [DL] Product Name: not-specified I: 185 [DL] Hardware Version: 0 I: 188 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 193 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 200 [DL] Manufacturing Date: 2022-01-01 I: 203 [DL] Device Type: 65535 (0xFFFF) I: 207 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00] I: 212 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 218 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00 I: 227 [SVR]Manual pairing code: [34970112332] E: 231 [DL]Long dispatch time: 178 ms, for event type 2 I: 3979 [DIS]Updating services using commissioning mode 1 E: 3984 [DIS]Failed to remove advertised services: 3 I: 3989 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1 cp=0 E: 3999 [DIS]Failed to advertise commissionable node: 3 E: 4004 [DIS]Failed to finalize service update: 3 I: 4010 [DL]CHIPoBLE advertising started I: 4014 [DL]NFC Tag emulation started I: 34014 [DL]CHIPoBLE advertising mode changed to slow I: 34021 [DL]CHIPoBLE advertising started I: 37420 [DL]Current number of connections: 1/1 I: 37424 [DL]BLE connection established (ConnId: 0x00) I: 37429 [DL]CHIPoBLE advertising stopped I: 37433 [DL]NFC Tag emulation stopped I: 39029 [BLE]local and remote recv window sizes = 5 I: 39034 [BLE]selected BTP version 4 I: 39037 [BLE]using BTP fragment sizes rx 244 / tx 244. I: 39119 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) I: 39211 [EM]>>> [E:35071r S:0 M:138682911] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98) I: 39226 [EM]<<< [E:35071r S:0 M:168082796] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:154) I: 39242 [SVR]Commissioning session establishment step started I: 39300 [EM]>>> [E:35071r S:0 M:138682912] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92) I: 39442 [EM]<<< [E:35071r S:0 M:168082797] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127) E: 39457 [DL]Long dispatch time: 157 ms, for event type 16388 I: 39525 [EM]>>> [E:35071r S:0 M:138682913] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59) I: 39540 [EM]<<< [E:35071r S:0 M:168082798] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30) I: 39557 [SC]SecureSession[0x20004448, LSID:18601]: State change 'kEstablishing' --> 'kActive' I: 39566 [SVR]Commissioning completed session establishment step I: 39572 [DIS]Updating services using commissioning mode 0 E: 39577 [DIS]Failed to remove advertised services: 3 E: 39582 [DIS]Failed to finalize service update: 3 I: 39587 [SVR]Device completed Rendezvous process I: 39617 [EM]>>> [E:35072r S:18601 M:87993479] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:131) I: 39640 [EM]<<< [E:35072r S:18601 M:154240679] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:258) I: 39841 [EM]>>> [E:35073r S:18601 M:87993480] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:106) E: 39858 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 586 E: 39869 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 586 I: 39882 [EM]<<< [E:35073r S:18601 M:154240680] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:191) I: 39976 [EM]>>> [E:35074r S:18601 M:87993481] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65) I: 39991 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 39998 [EM]<<< [E:35074r S:18601 M:154240681] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66) I: 40066 [EM]>>> [E:35075r S:18601 M:87993482] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70) I: 40086 [EM]<<< [E:35075r S:18601 M:154240682] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66) I: 40156 [EM]>>> [E:35076r S:18601 M:87993483] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) I: 40171 [ZCL]OpCreds: Certificate Chain request received for PAI I: 40180 [EM]<<< [E:35076r S:18601 M:154240683] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:527) I: 40426 [EM]>>> [E:35077r S:18601 M:87993484] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) I: 40441 [ZCL]OpCreds: Certificate Chain request received for DAC I: 40450 [EM]<<< [E:35077r S:18601 M:154240684] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:555) I: 40696 [EM]>>> [E:35078r S:18601 M:87993485] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) I: 40711 [ZCL]OpCreds: Received an AttestationRequest command I: 40749 [ZCL]OpCreds: AttestationRequest successful. I: 40758 [EM]<<< [E:35078r S:18601 M:154240685] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:716) I: 41101 [EM]>>> [E:35079r S:18601 M:87993486] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) I: 41116 [ZCL]OpCreds: Received a CSRRequest command I: 41182 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 41219 [ZCL]OpCreds: CSRRequest successful. I: 41225 [EM]<<< [E:35079r S:18601 M:154240686] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:392) E: 41241 [DL]Long dispatch time: 142 ms, for event type 16388 I: 41506 [EM]>>> [E:35080r S:18601 M:87993487] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:293) I: 41521 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 41584 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 41591 [EM]<<< [E:35080r S:18601 M:154240687] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63) E: 41607 [DL]Long dispatch time: 102 ms, for event type 16388 I: 41912 [EM]>>> [E:35081r S:18601 M:87993488] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:573) I: 41928 [ZCL]OpCreds: Received an AddNOC command I: 41934 [FP]Validating NOC chain I: 42053 [FP]NOC chain validation successful I: 42057 [FP]Added new fabric at index: 0x1 I: 42061 [FP]Assigned compressed fabric ID: 0x63FF53EC0BE1FEC7, node ID: 0x785F8DDA442DE7F7 I: 42069 [TS]Last Known Good Time: 2023-10-14T01:16:48 I: 42074 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 42080 [TS]Retaining current Last Known Good Time I: 42109 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I: 42118 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7 E: 42125 [SVR]Operational advertising failed: 3 I: 42129 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 42137 [EM]<<< [E:35081r S:18601 M:154240688] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66) E: 42152 [DL]Long dispatch time: 243 ms, for event type 16388 I: 42227 [EM]>>> [E:35082r S:18601 M:87993489] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:160) I: 42249 [EM]<<< [E:35082r S:18601 M:154240689] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66) I: 42316 [EM]>>> [E:35083r S:18601 M:87993490] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65) I: 42331 [FS]GeneralCommissioning: Received ArmFailSafe (108s) I: 42338 [EM]<<< [E:35083r S:18601 M:154240690] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66) I: 42406 [EM]>>> [E:35084r S:18601 M:87993491] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73) I: 44116 [ZCL]ThreadDiagnosticsDelegate: OnConnectionStatusChanged I: 44126 [EM]<<< [E:35084r S:18601 M:154240691] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65) I: 44141 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7 E: 44148 [SVR]Operational advertising failed: 3 I: 47165 [DL]SRP Client was started, detected server: fd57:436d:21ec:9665:fbaf:1e56:d0bc:ed80 I: 54587 [SVR]Server initialization complete I: 54591 [DIS]Updating services using commissioning mode 0 I: 54597 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7 I: 54604 [DL]advertising srp service: 63FF53EC0BE1FEC7-785F8DDA442DE7F7._matter._tcp I: 54615 [SWU]Stopping the watchdog timer I: 54619 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 56565 [EM]>>> [E:35085r S:0 M:138682914] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196) I: 56580 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20006148 I: 56588 [EM]<<< [E:35085r S:0 M:168082799 (Ack:138682914)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) I: 56608 [SC]Received Sigma1 msg I: 56618 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x785F8DDA442DE7F7 I: 56712 [EM]<<< [E:35085r S:0 M:168082800 (Ack:138682914)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:758) I: 56733 [EM]??1 [E:35085r S:0 M:168082800] (U) Msg Retransmission to 0:0000000000000000 in 2074ms [State:Active II:500 AI:300 AT:4000] I: 56749 [SC]Sent Sigma2 msg I: 57055 [EM]>>> [E:35085r S:0 M:138682915 (Ack:168082800)] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:598) I: 57071 [EM]<<< [E:35085r S:0 M:168082801 (Ack:138682915)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) I: 57092 [SC]Received Sigma3 msg E: 57100 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time E: 57284 [DL]Long dispatch time: 173 ms, for event type 2 I: 57313 [EM]<<< [E:35085r S:0 M:168082802 (Ack:138682915)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:40 (SecureChannel:StatusReport) (B:34) I: 57333 [EM]??1 [E:35085r S:0 M:168082802] (U) Msg Retransmission to 0:0000000000000000 in 2103ms [State:Active II:500 AI:300 AT:4000] I: 57349 [SC]SecureSession[0x20004370, LSID:18600]: State change 'kEstablishing' --> 'kActive' I: 57357 [IN]CASE Session established to peer: <000000000001B669, 1> I: 57457 [EM]>>> [E:35086r S:18600 M:92332627] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59) I: 57475 [FS]GeneralCommissioning: Received CommissioningComplete I: 57490 [FP]Metadata for Fabric 0x1 persisted to storage. I: 57524 [TS]Committing Last Known Good Time to storage: 2023-10-14T01:16:48 I: 57536 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x63FF53EC0BE1FEC7, FabricId 0000000000000001, NodeId 785F8DDA442DE7F7, VendorId 0xFFF1 I: 57553 [FS]GeneralCommissioning: Successfully commited pending fabric data I: 57560 [FS]Fail-safe cleanly disarmed I: 57565 [EM]<<< [E:35086r S:18600 M:107865625 (Ack:92332627)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) I: 57586 [EM]??1 [E:35086r S:18600 M:107865625] (S) Msg Retransmission to 1:000000000001B669 in 2068ms [State:Active II:500 AI:300 AT:4000] I: 57599 [SWU]Device commissioned, schedule a default provider query I: 57606 [SVR]Commissioning completed successfully I: 57610 [DIS]Updating services using commissioning mode 0 I: 57616 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7 I: 57624 [SC]SecureSession[0x20004448, LSID:18601]: State change 'kActive' --> 'kPendingEviction' I: 57632 [BLE]Releasing end point's BLE connection back to application. I: 57639 [DL]Closing BLE GATT connection (ConnId 00) I: 57646 [EM]>>> [E:35085r S:0 M:138682916 (Ack:168082802)] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) I: 57748 [DL]Current number of connections: 0/1 I: 57752 [DL]BLE GAP connection terminated (reason 0x16) I: 58070 [EM]>>> [E:35086r S:18600 M:92332628 (Ack:107865625)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 66070 [EM]>>> [E:35087r S:18600 M:92332629] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:52) I: 66085 [EM]<<< [E:35087r S:18600 M:107865626 (Ack:92332629)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:71) I: 66105 [EM]??1 [E:35087r S:18600 M:107865626] (S) Msg Retransmission to 1:000000000001B669 in 2053ms [State:Active II:500 AI:300 AT:4000] I: 66269 [EM]>>> [E:35087r S:18600 M:92332630 (Ack:107865626)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 67271 [EM]>>> [E:35088r S:18600 M:92332631] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:51) I: 67287 [EM]<<< [E:35088r S:18600 M:107865627 (Ack:92332631)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:70) I: 67307 [EM]??1 [E:35088r S:18600 M:107865627] (S) Msg Retransmission to 1:000000000001B669 in 2048ms [State:Active II:500 AI:300 AT:4000] I: 67471 [EM]>>> [E:35088r S:18600 M:92332632 (Ack:107865627)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 68471 [EM]>>> [E:35089r S:18600 M:92332633] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:66) I: 68486 [FS]GeneralCommissioning: Received ArmFailSafe (900s) I: 68493 [EM]<<< [E:35089r S:18600 M:107865628 (Ack:92332633)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) I: 68514 [EM]??1 [E:35089r S:18600 M:107865628] (S) Msg Retransmission to 1:000000000001B669 in 2087ms [State:Active II:500 AI:300 AT:4000] I: 68668 [EM]>>> [E:35089r S:18600 M:92332634 (Ack:107865628)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 69071 [EM]>>> [E:35090r S:18600 M:92332635] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73) I: 69093 [EM]<<< [E:35090r S:18600 M:107865629 (Ack:92332635)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) I: 69114 [EM]??1 [E:35090r S:18600 M:107865629] (S) Msg Retransmission to 1:000000000001B669 in 2079ms [State:Active II:500 AI:300 AT:4000] I: 69269 [EM]>>> [E:35090r S:18600 M:92332636 (Ack:107865629)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 69674 [EM]>>> [E:35091r S:18600 M:92332637] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73) I: 69692 [EM]<<< [E:35091r S:18600 M:107865630 (Ack:92332637)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) I: 69712 [EM]??1 [E:35091r S:18600 M:107865630] (S) Msg Retransmission to 1:000000000001B669 in 2103ms [State:Active II:500 AI:300 AT:4000] I: 69868 [EM]>>> [E:35091r S:18600 M:92332638 (Ack:107865630)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 72473 [EM]>>> [E:35092r S:18600 M:92332639] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:51) I: 72488 [EM]<<< [E:35092r S:18600 M:107865631 (Ack:92332639)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:70) I: 72509 [EM]??1 [E:35092r S:18600 M:107865631] (S) Msg Retransmission to 1:000000000001B669 in 2067ms [State:Active II:500 AI:300 AT:4000] I: 72674 [EM]>>> [E:35093r S:18600 M:92332640] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) I: 72692 [ZCL]OpCreds: Received a RemoveFabric Command for FabricIndex 0x1 I: 72700 [EM]<<< [E:35093r S:18600 M:107865632 (Ack:92332640)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 72735 [FP]Fabric (0x1) deleted. I: 72738 [ZCL][OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1] E: 72749 [ZCL][clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1] I: 72765 [ZCL]OpCreds: Fabric index 0x1 was removed I: 72770 [DIS]Updating services using commissioning mode 0 I: 72775 [DL]removing srp service: 63FF53EC0BE1FEC7-785F8DDA442DE7F7._matter._tcp I: 72813 [ZCL]OpCreds: RemoveFabric successful I: 72818 [SC]SecureSession[0x20004370, LSID:18600]: State change 'kActive' --> 'kPendingEviction' I: 72828 [EM]<<< [E:35093r S:18600 M:107865633 (Ack:92332640)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) I: 72848 [EM]??1 [E:35093r S:18600 M:107865633] (S) Msg Retransmission to 1:000000000001B669 in 2060ms [State:Active II:500 AI:300 AT:4000] I: 72863 [EM]>>> [E:35092r S:18600 M:92332641 (Ack:107865631)] (S) Msg RX from 1:000000000001B669 [0000] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 72880 [EM]Dropping message on inactive session that does not match an existing exchange I: 72891 [EM]>>> [E:35093r S:18600 M:92332642 (Ack:107865633)] (S) Msg RX from 1:000000000001B669 [0000] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) I: 73739 [TS]Pending Last Known Good Time: 2023-10-14T01:16:48 I: 73745 [TS]Previous Last Known Good Time: 2023-10-14T01:16:48 I: 73751 [TS]Reverted Last Known Good Time to previous value I: 73757 [DL]Performing factory reset E: 75702 [DL]SRP update error: timed out waiting on server response I: 76337 [DL]Erasing Thread persistent info... uart:~$ *** Booting My Application v2.9.0 - unknown commit *** *** Using nRF Connect SDK v2.9.0-7787b2649840 *** *** Using Zephyr OS v3.7.99-1f8f3dc29142 *** I: 41 [DL]BLE address: D5:E6:12:62:E5:D9 I: No users indexes stored I: No stored indexes for credential of type: 1 I: 59 [DL]CHIP task running I: Init CHIP stack I: 64 [DL]OpenThread started: OK I: 67 [DL]Setting OpenThread device type to SLEEPY END DEVICE I: 73 [SVR]Subscription persistence not supported I: 78 [SVR]Server initializing... I: 81 [TS]Last Known Good Time: [unknown] I: 85 [TS]Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48 I: 96 [DMG]AccessControl: initializing I: 100 [DMG]Examples::AccessControlDelegate::Init I: 104 [DMG]AccessControl: setting I: 107 [DMG]DefaultAclStorage: initializing I: 111 [DMG]DefaultAclStorage: 0 entries loaded E: 116 [IN]IPV6_PKTINFO failed: 109 I: 131 [ZCL]Using ZAP configuration... I: 136 [DMG]AccessControlCluster: initializing I: 141 [ZCL]Initiating Admin Commissioning cluster. I: 145 [ZCL]Door Lock server initialized I: 149 [ZCL]Door Lock cluster initialized at endpoint #1 I: 154 [ZCL]0xbff35 ep 1 clus 0x0000_0101 attr 0x0000_0013 not supported E: 161 [ZCL]Failed to set DoorLock number of RFID users: 86 I: 166 [DIS]Updating services using commissioning mode 0 E: 171 [DIS]Failed to remove advertised services: 3 E: 176 [DIS]Failed to finalize service update: 3 I: 180 [IN]CASE Server enabling CASE session setups I: 185 [SVR]Joining Multicast groups I: 189 [SVR]Server Listening... I: 192 [DL]Device Configuration: I: 195 [DL] Serial Number: 11223344556677889900 I: 199 [DL] Vendor Id: 65521 (0xFFF1) I: 203 [DL] Product Id: 32774 (0x8006) I: 206 [DL] Product Name: not-specified I: 210 [DL] Hardware Version: 0 I: 213 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 218 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 225 [DL] Manufacturing Date: 2022-01-01 I: 229 [DL] Device Type: 65535 (0xFFFF) I: 232 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00] I: 237 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 243 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00 I: 252 [SVR]Manual pairing code: [34970112332] E: 256 [DL]Long dispatch time: 195 ms, for event type 2
Best regards,
Hiroki
