Connected via Serial Port with settings /dev/ttyACM0 115200 8n1 rtscts:off ~x~~x~: command not found uart:~$ uart:~$ I: 100495 [DL]BLE connection established (ConnId: 0x00) I: 100500 [DL]Current number of connections: 1/1 I: 100504 [DL]CHIPoBLE advertising stopped I: 100508 [DL]NFC Tag emulation stopped I: 102232 [BLE]local and remote recv window sizes = 5 I: 102236 [BLE]selected BTP version 4 I: 102240 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 102322 [IN]BLE EndPoint 0x200124d8 Connection Complete I: 102327 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) I: 102413 [EM]>>> [E:40953r M:43039066] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 102426 [EM]<<< [E:40953r M:257634583] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 102437 [IN](U) Sending msg 257634583 to IP address 'BLE' I: 102548 [EM]>>> [E:40953r M:43039067] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 104454 [EM]<<< [E:40953r M:257634584] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 104465 [IN](U) Sending msg 257634584 to IP address 'BLE' E: 104470 [DL]Long dispatch time: 1922 ms, for event type 16388 I: 104573 [EM]>>> [E:40953r M:43039068] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 104584 [EM]<<< [E:40953r M:257634585] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 104595 [IN](U) Sending msg 257634585 to IP address 'BLE' I: 104602 [SC]SecureSession[0x20003568]: Moving from state 'kEstablishing' --> 'kActive' D: 104609 [IN]SecureSession[0x20003568]: Activated - Type:1 LSID:29298 D: 104616 [IN]New secure session activated for device , LSID:29298 PSID:26634! I: 104625 [SVR]Commissioning completed session establishment step I: 104631 [DIS]Updating services using commissioning mode 0 I: 104637 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 104647 [DIS]Failed to advertise extended commissionable node: 3 D: 104652 [DIS]Scheduling extended discovery timeout in 900s E: 104658 [DIS]Failed to finalize service update: 1c I: 104663 [SVR]Device completed Rendezvous process I: 104710 [EM]>>> [E:40954r M:217898161] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 104720 [IM]Received Read request I: 104729 [EM]<<< [E:40954r M:208773525] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 104739 [IN](S) Sending msg 208773525 on secure session with LSID: 29298 I: 104979 [EM]>>> [E:40955r M:217898162] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 104990 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 104997 [EM]<<< [E:40955r M:208773526] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 105008 [IN](S) Sending msg 208773526 on secure session with LSID: 29298 I: 105069 [EM]>>> [E:40956r M:217898163] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 105083 [EM]<<< [E:40956r M:208773527] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 105094 [IN](S) Sending msg 208773527 on secure session with LSID: 29298 I: 105159 [EM]>>> [E:40957r M:217898164] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 105170 [ZCL]OpCreds: Certificate Chain request received for PAI I: 105179 [EM]<<< [E:40957r M:208773528] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 105190 [IN](S) Sending msg 208773528 on secure session with LSID: 29298 I: 105474 [EM]>>> [E:40958r M:217898165] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 105485 [ZCL]OpCreds: Certificate Chain request received for DAC I: 105494 [EM]<<< [E:40958r M:208773529] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 105505 [IN](S) Sending msg 208773529 on secure session with LSID: 29298 I: 105744 [EM]>>> [E:40959r M:217898166] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 105756 [ZCL]OpCreds: Received an AttestationRequest command I: 105792 [ZCL]OpCreds: AttestationRequest successful. I: 105800 [EM]<<< [E:40959r M:208773530] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 105811 [IN](S) Sending msg 208773530 on secure session with LSID: 29298 I: 106194 [EM]>>> [E:40960r M:217898167] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 106205 [ZCL]OpCreds: Received a CSRRequest command I: 106396 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 106432 [ZCL]OpCreds: CSRRequest successful. I: 106438 [EM]<<< [E:40960r M:208773531] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 106449 [IN](S) Sending msg 208773531 on secure session with LSID: 29298 E: 106456 [DL]Long dispatch time: 263 ms, for event type 16388 I: 106779 [EM]>>> [E:40961r M:217898168] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 106791 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 106853 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 106859 [EM]<<< [E:40961r M:208773532] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 106871 [IN](S) Sending msg 208773532 on secure session with LSID: 29298 I: 107276 [EM]>>> [E:40962r M:217898169] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 107287 [ZCL]OpCreds: Received an AddNOC command I: 107295 [FP]Validating NOC chain I: 107411 [FP]NOC chain validation successful I: 107415 [FP]Added new fabric at index: 0x1 I: 107419 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001 I: 107427 [TS]Last Known Good Time: 2023-03-19T22:11:21 I: 107432 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 107438 [TS]Retaining current Last Known Good Time I: 107465 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I: 107474 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 107480 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 107488 [EM]<<< [E:40962r M:208773533] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 107499 [IN](S) Sending msg 208773533 on secure session with LSID: 29298 E: 107506 [DL]Long dispatch time: 233 ms, for event type 16388 I: 107591 [EM]>>> [E:40963r M:217898170] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest) I: 107608 [EM]<<< [E:40963r M:208773534] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 107619 [IN](S) Sending msg 208773534 on secure session with LSID: 29298 I: 107679 [EM]>>> [E:40964r M:217898171] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest) I: 108701 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2 I: 108714 [EM]<<< [E:40964r M:208773535] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 108725 [IN](S) Sending msg 208773535 on secure session with LSID: 29298 I: 108732 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 108739 [SVR]Operational advertising enabled I: 109112 [DIS]Setting operational delegate post init I: 109121 [SWU]Stopping the watchdog timer I: 109125 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 109131 [DIS]Updating services using commissioning mode 0 I: 109137 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 109144 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 109152 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 I: 109162 [DL]advertising srp service: 39C191837C681C04._matterc._udp I: 111155 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 111166 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e98 I: 111174 [IN]CASE Server disabling CASE session setups I: 111179 [EM]<<< [E:40965r M:257634586 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 111192 [IN](U) Sending msg 257634586 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 111202 [SC]Received Sigma1 msg I: 111210 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 I: 111438 [EM]<<< [E:40965r M:257634587 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) I: 111450 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 111462 [SC]Sent Sigma2 msg D: 112271 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r I: 112279 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 112291 [EM]<<< [E:40965r M:257634588 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 112303 [IN](U) Sending msg 257634588 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 112339 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 113200 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' D: 113477 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r I: 113486 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 113497 [EM]<<< [E:40965r M:257634589 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 113510 [IN](U) Sending msg 257634589 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 114291 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' I: 115693 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' D: 115939 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r I: 115947 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 115959 [EM]<<< [E:40965r M:257634590 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 115972 [IN](U) Sending msg 257634590 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' E: 117693 [EM]Failed to Send CHIP MessageCounter:257634587 on exchange 40965r sendCount: 4 max retries: 4 D: 118817 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r I: 118825 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 118837 [EM]<<< [E:40965r M:257634591 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 118850 [IN](U) Sending msg 257634591 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038' D: 127026 [IN]Clearing BLE pending packets. I: 127030 [BLE]Releasing end point's BLE connection back to application. I: 127037 [DL]Closing BLE GATT connection (ConnId 00) I: 127161 [DL]BLE GAP connection terminated (reason 0x16) I: 127166 [DL]Current number of connections: 0/1 E: 148162 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2 E: 148171 [IN]CASE Session establishment failed: 32 I: 148176 [IN]CASE Server enabling CASE session setups D: 148181 [IN]SecureSession[0x20003620]: Released - Type:2 LSID:29299 D: 148187 [IN]SecureSession[0x20003620]: Allocated Type:2 LSID:29300 I: 164996 [FS]Fail-safe timer expired E: 165000 [SVR]Failsafe timer expired D: 165003 [IN]SecureSession[0x20003568]: MarkForEviction Type:1 LSID:29298 I: 165010 [SC]SecureSession[0x20003568]: Moving from state 'kActive' --> 'kPendingEviction' D: 165018 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29298 E: 165024 [SVR]Commissioning failed (attempt 1): 32 D: 165031 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:29301 I: 165037 [DIS]Updating services using commissioning mode 1 I: 165043 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 165051 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 I: 165060 [DL]advertising srp service: 39C191837C681C04._matterc._udp E: 165067 [ZCL]OpCreds: Got FailSafeTimerExpired E: 165071 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 165078 [IN]Expiring all sessions for fabric 0x1!! E: 165082 [FP]Reverting pending fabric data for fabric 0x1 E: 165089 [FP]Warning: metadata not found during delete of fabric 0x1 I: 165100 [FP]Fabric (0x1) deleted. I: 165103 [ZCL]OpCreds: Fabric index 0x1 was removed I: 165108 [DIS]Updating services using commissioning mode 1 I: 165114 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 I: 165124 [DL]advertising srp service: 39C191837C681C04._matterc._udp I: 165130 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 165293 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21 I: 165300 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21 I: 165306 [TS]Reverted Last Known Good Time to previous value E: 165313 [FP]Warning: metadata not found during delete of fabric 0x1 E: 165323 [ZCL]OpCreds: failed to delete fabric at index 1: d8 I: 165330 [NP]Reverting Thread operational dataset E: 165342 [DL]Long dispatch time: 342 ms, for event type 32782 I: 165348 [FS]Fail-safe cleanly disarmed I: 165353 [DL]CHIPoBLE advertising started I: 165360 [DL]NFC Tag emulation started I: 195357 [DL]CHIPoBLE advertising mode changed to slow I: 195364 [DL]CHIPoBLE advertising started I: 900328 [SVR]Closing pairing window D: 900332 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29301 I: 900338 [DIS]Updating services using commissioning mode 0 I: 900344 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 I: 900353 [DL]advertising srp service: 39C191837C681C04._matterc._udp D: 900359 [DIS]Scheduling extended discovery timeout in 900s I: 900365 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 900372 [DL]CHIPoBLE advertising stopped I: 900376 [DL]NFC Tag emulation stopped D: 1800365 [DIS]Extended discovery timed out I: 1800369 [DIS]Updating services using commissioning mode 0 I: 1800374 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 1800382 [DL]removing srp service: 39C191837C681C04._matterc._udp I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 1, e68 I: data wra: 1, 2a8 uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 *** I: Init CHIP stack I: 223 [DL]BLE address: C4:59:9B:B5:0D:6F I: 234 [DL]OpenThread started: OK I: 237 [DL]Setting OpenThread device type to MINIMAL END DEVICE I: 242 [SVR]Server initializing... I: 246 [TS]Last Known Good Time: 2023-03-19T22:11:21 I: 252 [DMG]AccessControl: initializing I: 255 [DMG]Examples::AccessControlDelegate::Init I: 260 [DMG]AccessControl: setting I: 263 [DMG]DefaultAclStorage: initializing I: 266 [DMG]DefaultAclStorage: 0 entries loaded D: 271 [IN]UDP::Init bind&listen port=5540 E: 275 [IN]SO_REUSEPORT failed: 109 D: 278 [IN]UDP::Init bound to port=5540 D: 281 [IN]BLEBase::Init - setting/overriding transport D: 286 [IN]TransportMgr initialized I: 296 [ZCL]Using ZAP configuration... I: 301 [DMG]AccessControlCluster: initializing I: 305 [ZCL]Initiating Admin Commissioning cluster. D: 312 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26314 I: 318 [DIS]Updating services using commissioning mode 1 I: 324 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E: 333 [DIS]Failed to advertise commissionable node: 3 E: 338 [DIS]Failed to finalize service update: 1c I: 342 [DIS]Updating services using commissioning mode 1 I: 349 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E: 358 [DIS]Failed to advertise commissionable node: 3 E: 362 [DIS]Failed to finalize service update: 1c I: 367 [DIS]Delaying proxy of operational discovery: missing delegate I: 373 [IN]CASE Server enabling CASE session setups D: 378 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26315 I: 383 [SVR]Joining Multicast groups I: 387 [SVR]Server Listening... I: 390 [DL]Device Configuration: I: 393 [DL] Serial Number: 11223344556677889900 I: 397 [DL] Vendor Id: 65521 (0xFFF1) I: 401 [DL] Product Id: 32768 (0x8000) I: 405 [DL] Hardware Version: 0 I: 408 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 414 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 421 [DL] Manufacturing Date: (not set) I: 425 [DL] Device Type: 65535 (0xFFFF) I: 430 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00] I: 434 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 440 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00 I: 449 [SVR]Manual pairing code: [34970112332] I: 454 [DL]CHIP task running I: 459 [DL]CHIPoBLE advertising started I: 30463 [DL]CHIPoBLE advertising mode changed to slow I: 30470 [DL]CHIPoBLE advertising started I: 96070 [DL]BLE connection established (ConnId: 0x00) I: 96075 [DL]Current number of connections: 1/1 I: 96079 [DL]CHIPoBLE advertising stopped I: 97625 [BLE]local and remote recv window sizes = 5 I: 97630 [BLE]selected BTP version 4 I: 97633 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 97715 [IN]BLE EndPoint 0x2000fd28 Connection Complete I: 97720 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) I: 97807 [EM]>>> [E:5139r M:223393267] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 97819 [EM]<<< [E:5139r M:49097240] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 97831 [IN](U) Sending msg 49097240 to IP address 'BLE' I: 97942 [EM]>>> [E:5139r M:223393268] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 99819 [EM]<<< [E:5139r M:49097241] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 99830 [IN](U) Sending msg 49097241 to IP address 'BLE' E: 99835 [DL]Long dispatch time: 1894 ms, for event type 16388 I: 99966 [EM]>>> [E:5139r M:223393269] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 99978 [EM]<<< [E:5139r M:49097242] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 99989 [IN](U) Sending msg 49097242 to IP address 'BLE' I: 99995 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive' D: 100003 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:26314 D: 100009 [IN]New secure session activated for device , LSID:26314 PSID:55740! I: 100018 [SVR]Commissioning completed session establishment step I: 100024 [DIS]Updating services using commissioning mode 0 I: 100031 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 E: 100040 [DIS]Failed to advertise extended commissionable node: 3 D: 100046 [DIS]Scheduling extended discovery timeout in 900s E: 100051 [DIS]Failed to finalize service update: 1c I: 100057 [SVR]Device completed Rendezvous process I: 100063 [EM]>>> [E:5140r M:155586262] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 100073 [IM]Received Read request I: 100082 [EM]<<< [E:5140r M:227813834] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 100092 [IN](S) Sending msg 227813834 on secure session with LSID: 26314 I: 100238 [EM]>>> [E:5141r M:155586263] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 100249 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 100255 [EM]<<< [E:5141r M:227813835] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 100266 [IN](S) Sending msg 227813835 on secure session with LSID: 26314 I: 100372 [EM]>>> [E:5142r M:155586264] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 100386 [EM]<<< [E:5142r M:227813836] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 100397 [IN](S) Sending msg 227813836 on secure session with LSID: 26314 I: 100462 [EM]>>> [E:5143r M:155586265] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 100474 [ZCL]OpCreds: Certificate Chain request received for PAI I: 100483 [EM]<<< [E:5143r M:227813837] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 100493 [IN](S) Sending msg 227813837 on secure session with LSID: 26314 I: 100732 [EM]>>> [E:5144r M:155586266] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 100744 [ZCL]OpCreds: Certificate Chain request received for DAC I: 100753 [EM]<<< [E:5144r M:227813838] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 100764 [IN](S) Sending msg 227813838 on secure session with LSID: 26314 I: 101003 [EM]>>> [E:5145r M:155586267] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 101014 [ZCL]OpCreds: Received an AttestationRequest command I: 101051 [ZCL]OpCreds: AttestationRequest successful. I: 101059 [EM]<<< [E:5145r M:227813839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 101070 [IN](S) Sending msg 227813839 on secure session with LSID: 26314 I: 101407 [EM]>>> [E:5146r M:155586268] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 101419 [ZCL]OpCreds: Received a CSRRequest command I: 101609 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 101645 [ZCL]OpCreds: CSRRequest successful. I: 101652 [EM]<<< [E:5146r M:227813840] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 101662 [IN](S) Sending msg 227813840 on secure session with LSID: 26314 E: 101669 [DL]Long dispatch time: 263 ms, for event type 16388 I: 101993 [EM]>>> [E:5147r M:155586269] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 102004 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 102067 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 102074 [EM]<<< [E:5147r M:227813841] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 102085 [IN](S) Sending msg 227813841 on secure session with LSID: 26314 E: 102092 [DL]Long dispatch time: 101 ms, for event type 16388 I: 102444 [EM]>>> [E:5148r M:155586270] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 102456 [ZCL]OpCreds: Received an AddNOC command I: 102463 [FP]Validating NOC chain I: 102581 [FP]NOC chain validation successful I: 102585 [FP]Added new fabric at index: 0x1 I: 102589 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001 I: 102597 [TS]Last Known Good Time: 2023-03-19T22:11:21 I: 102602 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 102609 [TS]Retaining current Last Known Good Time I: 102633 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I: 102642 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 102649 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 102656 [EM]<<< [E:5148r M:227813842] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 102667 [IN](S) Sending msg 227813842 on secure session with LSID: 26314 E: 102674 [DL]Long dispatch time: 233 ms, for event type 16388 I: 102760 [EM]>>> [E:5149r M:155586271] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest) I: 102777 [EM]<<< [E:5149r M:227813843] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 102787 [IN](S) Sending msg 227813843 on secure session with LSID: 26314 I: 102848 [EM]>>> [E:5150r M:155586272] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest) I: 106165 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2 I: 106178 [EM]<<< [E:5150r M:227813844] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse) I: 106189 [IN](S) Sending msg 227813844 on secure session with LSID: 26314 I: 106195 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 106202 [SVR]Operational advertising enabled I: 106835 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 106847 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e80 I: 106854 [IN]CASE Server disabling CASE session setups I: 106861 [EM]<<< [E:5151r M:49097243 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 106873 [IN](U) Sending msg 49097243 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 106884 [SC]Received Sigma1 msg I: 106891 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 I: 106946 [DIS]Setting operational delegate post init I: 107123 [EM]<<< [E:5151r M:49097244 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) I: 107136 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 107146 [SC]Sent Sigma2 msg I: 107153 [SWU]Stopping the watchdog timer I: 107158 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 107165 [DIS]Updating services using commissioning mode 0 I: 107171 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 107179 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 107188 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 I: 107198 [DL]advertising srp service: 44619005BF223B89._matterc._udp D: 107935 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r I: 107944 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 107955 [EM]<<< [E:5151r M:49097245 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 107968 [IN](U) Sending msg 49097245 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 108049 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 108918 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' D: 109167 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r I: 109175 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 109187 [EM]<<< [E:5151r M:49097246 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 109200 [IN](U) Sending msg 49097246 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 109962 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' D: 111030 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r I: 111039 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 111050 [EM]<<< [E:5151r M:49097247 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 111063 [IN](U) Sending msg 49097247 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' I: 111405 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' E: 113538 [EM]Failed to Send CHIP MessageCounter:49097244 on exchange 5151r sendCount: 4 max retries: 4 D: 114123 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r I: 114131 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) I: 114143 [EM]<<< [E:5151r M:49097248 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 114156 [IN](U) Sending msg 49097248 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647' D: 122735 [IN]Clearing BLE pending packets. I: 122739 [BLE]Releasing end point's BLE connection back to application. I: 122745 [DL]Closing BLE GATT connection (ConnId 00) I: 122870 [DL]BLE GAP connection terminated (reason 0x16) I: 122875 [DL]Current number of connections: 0/1 E: 143847 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2 E: 143856 [IN]CASE Session establishment failed: 32 I: 143860 [IN]CASE Server enabling CASE session setups D: 143865 [IN]SecureSession[0x20003608]: Released - Type:2 LSID:26315 D: 143872 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26316 I: 160254 [FS]Fail-safe timer expired E: 160257 [SVR]Failsafe timer expired D: 160261 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:26314 I: 160267 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction' D: 160276 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:26314 E: 160282 [SVR]Commissioning failed (attempt 1): 32 D: 160289 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26317 I: 160295 [DIS]Updating services using commissioning mode 1 I: 160300 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001 I: 160308 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I: 160318 [DL]advertising srp service: 44619005BF223B89._matterc._udp E: 160324 [ZCL]OpCreds: Got FailSafeTimerExpired E: 160329 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 160335 [IN]Expiring all sessions for fabric 0x1!! E: 160340 [FP]Reverting pending fabric data for fabric 0x1 E: 160346 [FP]Warning: metadata not found during delete of fabric 0x1 I: 160357 [FP]Fabric (0x1) deleted. I: 160361 [ZCL]OpCreds: Fabric index 0x1 was removed I: 160365 [DIS]Updating services using commissioning mode 1 I: 160372 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I: 160381 [DL]advertising srp service: 44619005BF223B89._matterc._udp I: 160388 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp I: 160509 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21 I: 160515 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21 I: 160521 [TS]Reverted Last Known Good Time to previous value E: 160527 [FP]Warning: metadata not found during delete of fabric 0x1 E: 160536 [ZCL]OpCreds: failed to delete fabric at index 1: d8 I: 160542 [NP]Reverting Thread operational dataset E: 160554 [DL]Long dispatch time: 297 ms, for event type 32782 I: 160559 [FS]Fail-safe cleanly disarmed I: 160565 [DL]CHIPoBLE advertising started I: 190569 [DL]CHIPoBLE advertising mode changed to slow I: 190576 [DL]CHIPoBLE advertising started