uart:~$ *** Booting Zephyr OS build v3.2.99-ncs1 *** I: GPIO Button Initialization Initialization done I: Low Power UART Initialization init done I: Init CHIP stack D: Moving 32768, len 2 D: Moving 32776, len 7 D: Moving 49160, len 12 D: Moving 32773, len 7 D: Adding gc done ate at fd0 D: Erasing flash at fc000, len 4096 I: 478 [DL]BLE address: D5:7D:87:14:C7:1E 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: 500 [DL]OpenThread SED interval set to 500ms I: 510 [DL]OpenThread started: OK I: 513 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE I: 520 [SVR]Server initializing... I: 524 [TS]Last Known Good Time: [unknown] I: 528 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13 I: 541 [DMG]AccessControl: initializing I: 544 [DMG]Examples::AccessControlDelegate::Init I: 549 [DMG]AccessControl: setting I: 552 [DMG]DefaultAclStorage: initializing I: 556 [DMG]DefaultAclStorage: 0 entries loaded E: 560 [IN]SO_REUSEPORT failed: 109 I: 579 [ZCL]Using ZAP configuration... I: 597 [DMG]AccessControlCluster: initializing I: 601 [ZCL]Initiating Admin Commissioning cluster. I: 606 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1 I: 613 [DIS]Updating services using commissioning mode 0 I: 619 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 628 [DIS]Failed to advertise extended commissionable node: 3 E: 634 [DIS]Failed to finalize service update: 1c I: 638 [DIS]Delaying proxy of operational discovery: missing delegate I: 644 [IN]CASE Server enabling CASE session setups I: 649 [SVR]Joining Multicast groups I: 653 [SVR]Server Listening... I: 656 [DL]Device Configuration: I: 659 [DL] Serial Number: 11223344556677889900 I: 664 [DL] Vendor Id: 65521 (0xFFF1) I: 667 [DL] Product Id: 32784 (0x8010) I: 672 [DL] Hardware Version: 0 I: 675 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 682 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 689 [DL] Manufacturing Date: (not set) I: 693 [DL] Device Type: 65535 (0xFFFF) I: 698 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00] I: 703 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 709 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00 I: 718 [SVR]Manual pairing code: [34970112332] I: 723 [DL]CHIP task running I: 726 [DIS]Updating services using commissioning mode 0 I: 732 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 741 [DIS]Failed to advertise extended commissionable node: 3 E: 747 [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: 3588 [DIS]Updating services using commissioning mode 1 I: 3594 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1 E: 3603 [DIS]Failed to advertise commissionable node: 3 E: 3608 [DIS]Failed to finalize service update: 1c I: 3615 [DL]CHIPoBLE advertising started I: BLE advertising is enabled I: 13619 [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: 34234 [DL]BLE connection established (ConnId: 0x00) I: 34239 [DL]Current number of connections: 1/1 I: 34243 [DL]CHIPoBLE advertising stopped I: BLE advertising is disabled I: Updated MTU: TX: 131 RX: 131 bytes I: 35430 [BLE]local and remote recv window sizes = 5 I: 35435 [BLE]selected BTP version 4 I: 35438 [BLE]using BTP fragment sizes rx 128 / tx 128. I: 35453 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) I: kCHIPoBLEConnectionEstablished I: 35507 [EM]>>> [E:6356r M:184105677] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 35520 [EM]<<< [E:6356r M:213354608] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 35531 [IN](U) Sending msg 213354608 to IP address 'BLE' I: 35731 [EM]>>> [E:6356r M:184105678] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 37744 [EM]<<< [E:6356r M:213354609] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 37755 [IN](U) Sending msg 213354609 to IP address 'BLE' E: 37761 [DL]Long dispatch time: 2030 ms, for event type 16388 I: 38026 [EM]>>> [E:6356r M:184105679] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 38038 [EM]<<< [E:6356r M:213354610] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 38049 [IN](U) Sending msg 213354610 to IP address 'BLE' I: 38055 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive' I: 38063 [SVR]Commissioning completed session establishment step I: 38069 [DIS]Updating services using commissioning mode 0 I: 38076 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 E: 38086 [DIS]Failed to advertise extended commissionable node: 3 E: 38092 [DIS]Failed to finalize service update: 1c I: 38096 [SVR]Device completed Rendezvous process I: 38117 [EM]>>> [E:6357r M:163203305] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38129 [EM]<<< [E:6357r M:225510285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38139 [IN](S) Sending msg 225510285 on secure session with LSID: 58234 I: 38207 [EM]>>> [E:6358r M:163203306] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38219 [EM]<<< [E:6358r M:225510286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38229 [IN](S) Sending msg 225510286 on secure session with LSID: 58234 I: 38297 [EM]>>> [E:6359r M:163203307] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38309 [EM]<<< [E:6359r M:225510287] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38319 [IN](S) Sending msg 225510287 on secure session with LSID: 58234 I: 38387 [EM]>>> [E:6360r M:163203308] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38399 [EM]<<< [E:6360r M:225510288] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38409 [IN](S) Sending msg 225510288 on secure session with LSID: 58234 I: 38477 [EM]>>> [E:6361r M:163203309] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38489 [EM]<<< [E:6361r M:225510289] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38499 [IN](S) Sending msg 225510289 on secure session with LSID: 58234 I: 38567 [EM]>>> [E:6362r M:163203310] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 38581 [EM]<<< [E:6362r M:225510290] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38590 [IN](S) Sending msg 225510290 on secure session with LSID: 58234 I: 39062 [EM]>>> [E:6363r M:163203311] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 39073 [EM]<<< [E:6363r M:225510291] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 39083 [IN](S) Sending msg 225510291 on secure session with LSID: 58234 I: 40231 [EM]>>> [E:6364r M:163203312] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 40242 [EM]<<< [E:6364r M:225510292] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 40253 [IN](S) Sending msg 225510292 on secure session with LSID: 58234 I: 40322 [EM]>>> [E:6364r M:163203313] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 40333 [FS]GeneralCommissioning: Received ArmFailSafe (120s) I: 40340 [EM]<<< [E:6364r M:225510293] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40351 [IN](S) Sending msg 225510293 on secure session with LSID: 58234 I: 40412 [EM]>>> [E:6365r M:163203314] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I: 40424 [EM]<<< [E:6365r M:225510294] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 40434 [IN](S) Sending msg 225510294 on secure session with LSID: 58234 I: 40502 [EM]>>> [E:6366r M:163203315] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) I: 40513 [EM]<<< [E:6366r M:225510295] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 40523 [IN](S) Sending msg 225510295 on secure session with LSID: 58234 I: 40592 [EM]>>> [E:6366r M:163203316] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 40612 [EM]<<< [E:6366r M:225510296] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40623 [IN](S) Sending msg 225510296 on secure session with LSID: 58234 I: 40682 [EM]>>> [E:6367r M:163203317] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 40693 [ZCL]OpCreds: Certificate Chain request received for DAC I: 40703 [EM]<<< [E:6367r M:225510297] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40713 [IN](S) Sending msg 225510297 on secure session with LSID: 58234 I: 41132 [EM]>>> [E:6368r M:163203318] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 41143 [ZCL]OpCreds: Certificate Chain request received for PAI I: 41152 [EM]<<< [E:6368r M:225510298] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 41163 [IN](S) Sending msg 225510298 on secure session with LSID: 58234 I: 41582 [EM]>>> [E:6369r M:163203319] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 41594 [ZCL]OpCreds: Received an AttestationRequest command I: 41630 [ZCL]OpCreds: AttestationRequest successful. I: 41639 [EM]<<< [E:6369r M:225510299] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 41650 [IN](S) Sending msg 225510299 on secure session with LSID: 58234 I: 42167 [EM]>>> [E:6370r M:163203320] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 42179 [ZCL]OpCreds: Received a CSRRequest command I: 42381 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 42417 [ZCL]OpCreds: CSRRequest successful. I: 42424 [EM]<<< [E:6370r M:225510300] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 42435 [IN](S) Sending msg 225510300 on secure session with LSID: 58234 E: 42442 [DL]Long dispatch time: 276 ms, for event type 16388 I: 44554 [EM]>>> [E:6371r M:163203321] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 44565 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 44629 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 44635 [EM]<<< [E:6371r M:225510301] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 44646 [IN](S) Sending msg 225510301 on secure session with LSID: 58234 E: 44653 [DL]Long dispatch time: 102 ms, for event type 16388 I: 45185 [EM]>>> [E:6372r M:163203322] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 45196 [ZCL]OpCreds: Received an AddNOC command I: 45205 [FP]Validating NOC chain I: 45323 [FP]NOC chain validation successful I: 45327 [FP]Added new fabric at index: 0x1 I: 45331 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x00000000271F26F2 I: 45340 [TS]Last Known Good Time: 2022-12-18T20:04:13 I: 45345 [TS]New proposed Last Known Good Time: 2023-01-17T10:58:53 I: 45351 [TS]Updating pending Last Known Good Time to 2023-01-17T10:58:53 I: 45380 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001 I: 45389 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2 I: 45396 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 45403 [EM]<<< [E:6372r M:225510302] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 45414 [IN](S) Sending msg 225510302 on secure session with LSID: 58234 E: 45421 [DL]Long dispatch time: 240 ms, for event type 16388 I: 45588 [EM]>>> [E:6373r M:163203323] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 45605 [EM]<<< [E:6373r M:225510303] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 45616 [IN](S) Sending msg 225510303 on secure session with LSID: 58234 I: 45677 [EM]>>> [E:6374r M:163203324] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest) I: 45689 [EM]<<< [E:6374r M:225510304] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData) I: 45699 [IN](S) Sending msg 225510304 on secure session with LSID: 58234 I: 45768 [EM]>>> [E:6375r M:163203325] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest) I: 47418 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be I: 47433 [EM]<<< [E:6375r M:225510305] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse) I: 47444 [IN](S) Sending msg 225510305 on secure session with LSID: 58234 I: 47451 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2 I: 47457 [SVR]Operational advertising enabled I: 47902 [DIS]Setting operational delegate post init I: 47911 [SWU]Stopping the watchdog timer I: 47915 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 47921 [DIS]Updating services using commissioning mode 0 I: 47927 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2 I: 47934 [DL]advertising srp service: 86ACCD207670D93A-00000000271F26F2._matter._tcp I: 47942 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0 I: 47952 [DL]advertising srp service: E013E1AB4B9A6BD5._matterc._udp I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19) I: 56302 [DL]BLE GAP connection terminated (reason 0x13) I: 56307 [DL]Current number of connections: 0/1 I: kCHIPoBLEConnectionClosed E: 57626 [DL]BLEManagerImpl::SendIndication() failed: 2f I: 57631 [BLE]Releasing end point's BLE connection back to application. I: 57637 [DL]Closing BLE GATT connection (ConnId 00) I: STATE CHANGING HERE I: doAction nRFState = IDLE nRFdoAction = nRF_IDLE