ooting Zephyr OS build v3.2.99-ncs1 *** I: GPIO Button Initialization Initialization done I: Low Power UART Initialization init done I: Init CHIP stack 32muart:~$ I: 251 [DL]BLE address: F9:BA:7F:51:82:1B I: SoftDevice Controller build revision: I: 6d 90 41 2a 38 e8 ad 17 |m.A*8... I: 29 a5 03 38 39 27 d7 85 |)..89'.. I: 1f 85 d8 e1 |.... I: 273 [DL]OpenThread SED interval set to 500ms I: 283 [DL]OpenThread started: OK I: 286 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE I: 294 [SVR]Server initializing... I: 298 [TS]Last Known Good Time: [unknown] I: 302 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13 I: 314 [DMG]AccessControl: initializing I: 318 [DMG]Examples::AccessControlDelegate::Init I: 322 [DMG]AccessControl: setting I: 325 [DMG]DefaultAclStorage: initializing I: 329 [DMG]DefaultAclStorage: 0 entries loaded E: 334 [IN]SO_REUSEPORT failed: 109 I: 353 [ZCL]Using ZAP configuration... I: 373 [DMG]AccessControlCluster: initializing I: 377 [ZCL]Initiating Admin Commissioning cluster. I: 382 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1 I: 389 [DIS]Updating services using commissioning mode 0 I: 395 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 404 [DIS]Failed to advertise extended commissionable node: 3 E: 410 [DIS]Failed to finalize service update: 1c I: 414 [DIS]Delaying proxy of operational discovery: missing delegate I: 420 [IN]CASE Server enabling CASE session setups I: 425 [SVR]Joining Multicast groups I: 429 [SVR]Server Listening... I: 431 [DL]Device Configuration: I: 435 [DL] Serial Number: 11223344556677889900 I: 440 [DL] Vendor Id: 65521 (0xFFF1) I: 443 [DL] Product Id: 32784 (0x8010) I: 448 [DL] Hardware Version: 0 I: 452 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 458 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 465 [DL] Manufacturing Date: (not set) I: 469 [DL] Device Type: 65535 (0xFFFF) I: 475 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00] I: 479 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 485 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00 I: 494 [SVR]Manual pairing code: [34970112332] I: 500 [DL]CHIP task running I: 502 [DIS]Updating services using commissioning mode 0 I: 509 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 518 [DIS]Failed to advertise extended commissionable node: 3 E: 524 [DIS]Failed to finalize service update: 1c I: build time: Dec 18 2022 20:04:16 I: Bluetooth initialized D: set-value OK. key: bt/name D: set-value OK. key: bt/hash I: Dendo BLE services initialized I: doAction nRFState = PRE_START nRFdoAction = nRF_START I: Matter not Commissioned!!! I: doAction nRFState = PRE_START nRFdoAction = nRF_IDLE I: ActionTimeoutLEDStatus nRFState = IDLE nRFdoAction = nRF_IDLE I: doAction nRFState = PRE_SHUT nRFdoAction = nRF_SHUTDOWN I: doAction nRFState = PRE_SHUT nRFdoAction = nRF_IDLE I: ActionTimeoutLEDStatus nRFState = SLEEP nRFdoAction = nRF_IDLE I: Unknow Short Press nRFState = SLEEP nRFdoAction = nRF_IDLE I: doAction nRFState = PRE_START nRFdoAction = nRF_START I: Matter not Commissioned!!! I: doAction nRFState = MT_COMMIS nRFdoAction = MATTER_COMMIS_OPEN I: 95796 [DIS]Updating services using commissioning mode 1 I: 95802 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1 E: 95812 [DIS]Failed to advertise commissionable node: 3 E: 95817 [DIS]Failed to finalize service update: 1c I: 95824 [DL]CHIPoBLE advertising started I: BLE advertising is enabled I: 105828 [DL]CHIPoBLE advertising mode changed to slow I: Updated MTU: TX: 23 RX: 23 bytes I: Connected 65:73:16:34:B9:00 (random) I: 123005 [DL]BLE connection established (ConnId: 0x00) I: 123010 [DL]Current number of connections: 1/1 I: 123014 [DL]CHIPoBLE advertising stopped I: BLE advertising is disabled I: Updated MTU: TX: 131 RX: 131 bytes I: 124030 [BLE]local and remote recv window sizes = 5 I: 124034 [BLE]selected BTP version 4 I: 124038 [BLE]using BTP fragment sizes rx 128 / tx 128. I: 124045 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) I: kCHIPoBLEConnectionEstablished I: 124106 [EM]>>> [E:6280r M:184105635] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 124119 [EM]<<< [E:6280r M:9310781] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 124131 [IN](U) Sending msg 9310781 to IP address 'BLE' I: 124466 [EM]>>> [E:6280r M:184105636] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 126489 [EM]<<< [E:6280r M:9310782] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 126500 [IN](U) Sending msg 9310782 to IP address 'BLE' E: 126505 [DL]Long dispatch time: 2040 ms, for event type 16388 I: 126671 [EM]>>> [E:6280r M:184105637] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 126683 [EM]<<< [E:6280r M:9310783] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 126693 [IN](U) Sending msg 9310783 to IP address 'BLE' I: 126700 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive' I: 126708 [SVR]Commissioning completed session establishment step I: 126714 [DIS]Updating services using commissioning mode 0 I: 126721 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 126731 [DIS]Failed to advertise extended commissionable node: 3 E: 126736 [DIS]Failed to finalize service update: 1c I: 126741 [SVR]Device completed Rendezvous process I: 126761 [EM]>>> [E:6281r M:7556274] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 126773 [EM]<<< [E:6281r M:21205970] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 126783 [IN](S) Sending msg 21205970 on secure session with LSID: 55695 I: 126896 [EM]>>> [E:6282r M:7556275] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 126908 [EM]<<< [E:6282r M:21205971] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 126918 [IN](S) Sending msg 21205971 on secure session with LSID: 55695 I: 126986 [EM]>>> [E:6283r M:7556276] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 126998 [EM]<<< [E:6283r M:21205972] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 127008 [IN](S) Sending msg 21205972 on secure session with LSID: 55695 I: 127076 [EM]>>> [E:6284r M:7556277] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 127088 [EM]<<< [E:6284r M:21205973] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 127098 [IN](S) Sending msg 21205973 on secure session with LSID: 55695 I: 127166 [EM]>>> [E:6285r M:7556278] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 127178 [EM]<<< [E:6285r M:21205974] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 127188 [IN](S) Sending msg 21205974 on secure session with LSID: 55695 I: 127256 [EM]>>> [E:6286r M:7556279] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 127270 [EM]<<< [E:6286r M:21205975] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 127280 [IN](S) Sending msg 21205975 on secure session with LSID: 55695 I: 127751 [EM]>>> [E:6287r M:7556280] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 127763 [EM]<<< [E:6287r M:21205976] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 127773 [IN](S) Sending msg 21205976 on secure session with LSID: 55695 I: 128831 [EM]>>> [E:6288r M:7556281] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 128842 [EM]<<< [E:6288r M:21205977] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 128852 [IN](S) Sending msg 21205977 on secure session with LSID: 55695 I: 128922 [EM]>>> [E:6288r M:7556282] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 128933 [FS]GeneralCommissioning: Received ArmFailSafe (120s) I: 128940 [EM]<<< [E:6288r M:21205978] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 128950 [IN](S) Sending msg 21205978 on secure session with LSID: 55695 I: 129011 [EM]>>> [E:6289r M:7556283] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 129023 [EM]<<< [E:6289r M:21205979] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 129033 [IN](S) Sending msg 21205979 on secure session with LSID: 55695 I: 129101 [EM]>>> [E:6290r M:7556284] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 129112 [EM]<<< [E:6290r M:21205980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 129122 [IN](S) Sending msg 21205980 on secure session with LSID: 55695 I: 129192 [EM]>>> [E:6290r M:7556285] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 129212 [EM]<<< [E:6290r M:21205981] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 129223 [IN](S) Sending msg 21205981 on secure session with LSID: 55695 I: 129282 [EM]>>> [E:6291r M:7556286] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 129293 [ZCL]OpCreds: Certificate Chain request received for DAC I: 129302 [EM]<<< [E:6291r M:21205982] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 129313 [IN](S) Sending msg 21205982 on secure session with LSID: 55695 I: 129732 [EM]>>> [E:6292r M:7556287] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 129743 [ZCL]OpCreds: Certificate Chain request received for PAI I: 129752 [EM]<<< [E:6292r M:21205983] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 129763 [IN](S) Sending msg 21205983 on secure session with LSID: 55695 I: 130182 [EM]>>> [E:6293r M:7556288] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 130193 [ZCL]OpCreds: Received an AttestationRequest command I: 130230 [ZCL]OpCreds: AttestationRequest successful. I: 130239 [EM]<<< [E:6293r M:21205984] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 130249 [IN](S) Sending msg 21205984 on secure session with LSID: 55695 I: 130767 [EM]>>> [E:6294r M:7556289] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 130778 [ZCL]OpCreds: Received a CSRRequest command I: 130981 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 131018 [ZCL]OpCreds: CSRRequest successful. I: 131024 [EM]<<< [E:6294r M:21205985] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 131035 [IN](S) Sending msg 21205985 on secure session with LSID: 55695 E: 131042 [DL]Long dispatch time: 276 ms, for event type 16388 I: 133558 [EM]>>> [E:6295r M:7556290] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 133569 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 133633 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 133640 [EM]<<< [E:6295r M:21205986] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 133651 [IN](S) Sending msg 21205986 on secure session with LSID: 55695 E: 133658 [DL]Long dispatch time: 102 ms, for event type 16388 I: 134190 [EM]>>> [E:6296r M:7556291] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 134201 [ZCL]OpCreds: Received an AddNOC command I: 134210 [FP]Validating NOC chain I: 134329 [FP]NOC chain validation successful I: 134333 [FP]Added new fabric at index: 0x1 I: 134337 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x000000007A661996 I: 134345 [TS]Last Known Good Time: 2022-12-18T20:04:13 I: 134350 [TS]New proposed Last Known Good Time: 2023-01-17T10:52:05 I: 134356 [TS]Updating pending Last Known Good Time to 2023-01-17T10:52:05 I: 134386 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001 I: 134395 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996 I: 134402 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 134409 [EM]<<< [E:6296r M:21205987] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 134420 [IN](S) Sending msg 21205987 on secure session with LSID: 55695 E: 134427 [DL]Long dispatch time: 241 ms, for event type 16388 I: 134592 [EM]>>> [E:6297r M:7556292] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 134610 [EM]<<< [E:6297r M:21205988] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 134621 [IN](S) Sending msg 21205988 on secure session with LSID: 55695 I: 134682 [EM]>>> [E:6298r M:7556293] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest) I: 134694 [EM]<<< [E:6298r M:21205989] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData) I: 134703 [IN](S) Sending msg 21205989 on secure session with LSID: 55695 I: 134772 [EM]>>> [E:6299r M:7556294] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 135824 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be I: 135839 [EM]<<< [E:6299r M:21205990] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 135850 [IN](S) Sending msg 21205990 on secure session with LSID: 55695 I: 135857 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996 I: 135863 [SVR]Operational advertising enabled I: 136605 [DIS]Setting operational delegate post init I: 136616 [SWU]Stopping the watchdog timer I: 136620 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 136626 [DIS]Updating services using commissioning mode 0 I: 136632 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996 I: 136639 [DL]advertising srp service: 86ACCD207670D93A-000000007A661996._matter._tcp I: 136647 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 I: 136657 [DL]advertising srp service: 5A393C33336681F1._matterc._udp I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19) I: 144811 [DL]BLE GAP connection terminated (reason 0x13) I: 144817 [DL]Current number of connections: 0/1 I: kCHIPoBLEConnectionClosed E: 146047 [DL]BLEManagerImpl::SendIndication() failed: 2f I: 146052 [BLE]Releasing end point's BLE connection back to application. I: 146058 [DL]Closing BLE GATT connection (ConnId 00) I: STATE CHANGING HERE I: doAction nRFState = IDLE nRFdoAction = nRF_IDLE I: doAction nRFState = PRE_SHUT nRFdoAction = nRF_SHUTDOWN E: 176994 [FP]Reverting pending fabric data for fabric 0x1 E: 177001 [FP]Warning: metadata not found during delete of fabric 0x1 I: 177019 [FP]Fabric (0x1) deleted. I: 177022 [ZCL]OpCreds: Fabric index 0x1 was removed I: 177053 [TS]Pending Last Known Good Time: 2023-01-17T10:52:05 I: 177060 [TS]Previous Last Known Good Time: 2022-12-18T20:04:13 I: 177066 [TS]Reverted Last Known Good Time to previous value I: 177072 [DL]Performing factory reset I: 177098 [DL]Erasing Thread persistent info... I: nRF5 802154 radio initialized E: JEDEC id [00 00 00] expect [c2 28 17] D: Recovering last ate from sector 2 I: 4 Sectors of 4096 bytes I: alloc wra: 2, a70 I: data wra: 2, 3e4 D: Initialized ooting Zephyr OS build v3.2.99-ncs1 *** I: GPIO Button Initialization Initialization done I: Low Power UART Initialization init done I: Init CHIP stack 32muart:~$ I: 250 [DL]BLE address: DC:4B:4D:80:0C:BF I: SoftDevice Controller build revision: I: 6d 90 41 2a 38 e8 ad 17 |m.A*8... I: 29 a5 03 38 39 27 d7 85 |)..89'.. I: 1f 85 d8 e1 |.... I: 272 [DL]OpenThread SED interval set to 500ms I: 282 [DL]OpenThread started: OK I: 285 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE I: 293 [SVR]Server initializing... I: 297 [TS]Last Known Good Time: [unknown] I: 301 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13 I: 313 [DMG]AccessControl: initializing I: 317 [DMG]Examples::AccessControlDelegate::Init I: 321 [DMG]AccessControl: setting I: 324 [DMG]DefaultAclStorage: initializing I: 328 [DMG]DefaultAclStorage: 0 entries loaded E: 333 [IN]SO_REUSEPORT failed: 109 I: 351 [ZCL]Using ZAP configuration... I: 371 [DMG]AccessControlCluster: initializing I: 376 [ZCL]Initiating Admin Commissioning cluster. I: 381 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1 I: 387 [DIS]Updating services using commissioning mode 0 I: 394 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 403 [DIS]Failed to advertise extended commissionable node: 3 E: 408 [DIS]Failed to finalize service update: 1c I: 413 [DIS]Delaying proxy of operational discovery: missing delegate I: 419 [IN]CASE Server enabling CASE session setups I: 424 [SVR]Joining Multicast groups I: 427 [SVR]Server Listening... I: 430 [DL]Device Configuration: I: 434 [DL] Serial Number: 11223344556677889900 I: 438 [DL] Vendor Id: 65521 (0xFFF1) I: 442 [DL] Product Id: 32784 (0x8010) I: 446 [DL] Hardware Version: 0 I: 450 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 456 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 464 [DL] Manufacturing Date: (not set) I: 468 [DL] Device Type: 65535 (0xFFFF) I: 473 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00] I: 478 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 484 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00 I: 493 [SVR]Manual pairing code: [34970112332] I: 498 [DL]CHIP task running I: 501 [DIS]Updating services using commissioning mode 0 I: 507 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 516 [DIS]Failed to advertise extended commissionable node: 3 E: 522 [DIS]Failed to finalize service update: 1c I: build time: Dec 18 2022 20:04:16 I: Bluetooth initialized D: set-value OK. key: bt/name D: set-value OK. key: bt/hash I: Dendo BLE services initialized I: doAction nRFState = PRE_START nRFdoAction = nRF_START I: Matter not Commissioned!!! I: doAction nRFState = MT_COMMIS nRFdoAction = MATTER_COMMIS_OPEN I: 4046 [DIS]Updating services using commissioning mode 1 I: 4052 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1 E: 4061 [DIS]Failed to advertise commissionable node: 3 E: 4066 [DIS]Failed to finalize service update: 1c I: 4073 [DL]CHIPoBLE advertising started I: BLE advertising is enabled I: 14078 [DL]CHIPoBLE advertising mode changed to slow I: Updated MTU: TX: 23 RX: 23 bytes I: Connected 65:73:16:34:B9:00 (random) I: 45857 [DL]BLE connection established (ConnId: 0x00) I: 45862 [DL]Current number of connections: 1/1 I: 45866 [DL]CHIPoBLE advertising stopped I: BLE advertising is disabled I: Updated MTU: TX: 131 RX: 131 bytes I: 46931 [BLE]local and remote recv window sizes = 5 I: 46935 [BLE]selected BTP version 4 I: 46939 [BLE]using BTP fragment sizes rx 128 / tx 128. I: 46976 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) I: kCHIPoBLEConnectionEstablished I: 47202 [EM]>>> [E:6326r M:184105664] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 47214 [EM]<<< [E:6326r M:6302907] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 47226 [IN](U) Sending msg 6302907 to IP address 'BLE' I: 47427 [EM]>>> [E:6326r M:184105665] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 49437 [EM]<<< [E:6326r M:6302908] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 49447 [IN](U) Sending msg 6302908 to IP address 'BLE' E: 49453 [DL]Long dispatch time: 2027 ms, for event type 16388 I: 49722 [EM]>>> [E:6326r M:184105666] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 49734 [EM]<<< [E:6326r M:6302909] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 49744 [IN](U) Sending msg 6302909 to IP address 'BLE' I: 49751 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive' I: 49758 [SVR]Commissioning completed session establishment step I: 49764 [DIS]Updating services using commissioning mode 0 I: 49772 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 49781 [DIS]Failed to advertise extended commissionable node: 3 E: 49787 [DIS]Failed to finalize service update: 1c I: 49791 [SVR]Device completed Rendezvous process I: 49812 [EM]>>> [E:6327r M:236808937] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 49824 [EM]<<< [E:6327r M:192161873] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 49834 [IN](S) Sending msg 192161873 on secure session with LSID: 6040 I: 49902 [EM]>>> [E:6328r M:236808938] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 49914 [EM]<<< [E:6328r M:192161874] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 49924 [IN](S) Sending msg 192161874 on secure session with LSID: 6040 I: 49992 [EM]>>> [E:6329r M:236808939] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 50004 [EM]<<< [E:6329r M:192161875] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 50014 [IN](S) Sending msg 192161875 on secure session with LSID: 6040 I: 50082 [EM]>>> [E:6330r M:236808940] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 50094 [EM]<<< [E:6330r M:192161876] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 50104 [IN](S) Sending msg 192161876 on secure session with LSID: 6040 I: 50172 [EM]>>> [E:6331r M:236808941] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 50184 [EM]<<< [E:6331r M:192161877] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 50194 [IN](S) Sending msg 192161877 on secure session with LSID: 6040 I: 50262 [EM]>>> [E:6332r M:236808942] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 50276 [EM]<<< [E:6332r M:192161878] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 50286 [IN](S) Sending msg 192161878 on secure session with LSID: 6040 I: 50712 [EM]>>> [E:6333r M:236808943] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 50724 [EM]<<< [E:6333r M:192161879] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 50734 [IN](S) Sending msg 192161879 on secure session with LSID: 6040 I: 51972 [EM]>>> [E:6334r M:236808944] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 51983 [EM]<<< [E:6334r M:192161880] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 51993 [IN](S) Sending msg 192161880 on secure session with LSID: 6040 I: 52063 [EM]>>> [E:6334r M:236808945] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 52074 [FS]GeneralCommissioning: Received ArmFailSafe (120s) I: 52081 [EM]<<< [E:6334r M:192161881] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 52092 [IN](S) Sending msg 192161881 on secure session with LSID: 6040 I: 52153 [EM]>>> [E:6335r M:236808946] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 52164 [EM]<<< [E:6335r M:192161882] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 52174 [IN](S) Sending msg 192161882 on secure session with LSID: 6040 I: 52242 [EM]>>> [E:6336r M:236808947] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 52253 [EM]<<< [E:6336r M:192161883] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 52264 [IN](S) Sending msg 192161883 on secure session with LSID: 6040 I: 52333 [EM]>>> [E:6336r M:236808948] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 52353 [EM]<<< [E:6336r M:192161884] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 52364 [IN](S) Sending msg 192161884 on secure session with LSID: 6040 I: 52423 [EM]>>> [E:6337r M:236808949] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 52434 [ZCL]OpCreds: Certificate Chain request received for DAC I: 52443 [EM]<<< [E:6337r M:192161885] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 52454 [IN](S) Sending msg 192161885 on secure session with LSID: 6040 I: 52873 [EM]>>> [E:6338r M:236808950] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 52884 [ZCL]OpCreds: Certificate Chain request received for PAI I: 52893 [EM]<<< [E:6338r M:192161886] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 52904 [IN](S) Sending msg 192161886 on secure session with LSID: 6040 I: 53323 [EM]>>> [E:6339r M:236808951] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 53334 [ZCL]OpCreds: Received an AttestationRequest command I: 53371 [ZCL]OpCreds: AttestationRequest successful. I: 53379 [EM]<<< [E:6339r M:192161887] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 53390 [IN](S) Sending msg 192161887 on secure session with LSID: 6040 I: 53908 [EM]>>> [E:6340r M:236808952] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 53919 [ZCL]OpCreds: Received a CSRRequest command I: 54120 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 54156 [ZCL]OpCreds: CSRRequest successful. I: 54163 [EM]<<< [E:6340r M:192161888] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 54174 [IN](S) Sending msg 192161888 on secure session with LSID: 6040 E: 54181 [DL]Long dispatch time: 274 ms, for event type 16388 I: 56249 [EM]>>> [E:6341r M:236808953] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 56261 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 56324 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 56331 [EM]<<< [E:6341r M:192161889] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 56342 [IN](S) Sending msg 192161889 on secure session with LSID: 6040 E: 56349 [DL]Long dispatch time: 102 ms, for event type 16388 I: 56881 [EM]>>> [E:6342r M:236808954] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 56892 [ZCL]OpCreds: Received an AddNOC command I: 56901 [FP]Validating NOC chain I: 57019 [FP]NOC chain validation successful I: 57023 [FP]Added new fabric at index: 0x1 I: 57027 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x000000002EFEEE7A I: 57035 [TS]Last Known Good Time: 2022-12-18T20:04:13 I: 57040 [TS]New proposed Last Known Good Time: 2023-01-17T10:53:47 I: 57046 [TS]Updating pending Last Known Good Time to 2023-01-17T10:53:47 I: 57076 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001 I: 57085 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A I: 57092 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 57099 [EM]<<< [E:6342r M:192161890] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 57110 [IN](S) Sending msg 192161890 on secure session with LSID: 6040 E: 57117 [DL]Long dispatch time: 240 ms, for event type 16388 I: 57283 [EM]>>> [E:6343r M:236808955] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 57301 [EM]<<< [E:6343r M:192161891] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 57312 [IN](S) Sending msg 192161891 on secure session with LSID: 6040 I: 57373 [EM]>>> [E:6344r M:236808956] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest) I: 57385 [EM]<<< [E:6344r M:192161892] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData) I: 57395 [IN](S) Sending msg 192161892 on secure session with LSID: 6040 I: 57463 [EM]>>> [E:6345r M:236808957] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 58834 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be I: 58849 [EM]<<< [E:6345r M:192161893] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 58860 [IN](S) Sending msg 192161893 on secure session with LSID: 6040 I: 58866 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A I: 58873 [SVR]Operational advertising enabled I: 59818 [DIS]Setting operational delegate post init I: 59828 [SWU]Stopping the watchdog timer I: 59832 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 59838 [DIS]Updating services using commissioning mode 0 I: 59844 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A I: 59851 [DL]advertising srp service: 86ACCD207670D93A-000000002EFEEE7A._matter._tcp I: 59860 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 I: 59869 [DL]advertising srp service: 44C0CF57F9788AC6._matterc._udp I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19) I: 80283 [DL]BLE GAP connection terminated (reason 0x13) I: 80289 [DL]Current number of connections: 0/1 I: kCHIPoBLEConnectionClosed I: STATE CHANGING HERE I: doAction nRFState = IDLE nRFdoAction = nRF_IDLE