keanhinlim@Keans-Mac connectedhomeip % ./out/debug/chip-tool pairing ble-wifi 4 "Casa Lim" CoHab_1020! 20202021 3840 --paa-trust-store-path ./credentials/development/paa-root-certs [1649174229005] [52091:542909] CHIP: [DL] KVS will be written to: file:///tmp/chip_kvs [1649174229031] [52091:542909] CHIP: [DL] _Init [1649174229031] [52091:542909] CHIP: [IN] UDP::Init bind&listen port=0 [1649174229031] [52091:542909] CHIP: [IN] UDP::Init bound to port=64264 [1649174229031] [52091:542909] CHIP: [IN] UDP::Init bind&listen port=0 [1649174229031] [52091:542909] CHIP: [IN] UDP::Init bound to port=61547 [1649174229031] [52091:542909] CHIP: [IN] BLEBase::Init - setting/overriding transport [1649174229031] [52091:542909] CHIP: [IN] TransportMgr initialized [1649174229031] [52091:542909] CHIP: [DIS] Init fabric pairing table with server storage [1649174229031] [52091:542909] CHIP: [IN] Loading from storage for fabric index 1 [1649174229036] [52091:542909] CHIP: [IN] Loading from storage for fabric index 2 [1649174229036] [52091:542909] CHIP: [IN] Loading from storage for fabric index 3 [1649174229037] [52091:542909] CHIP: [DIS] Add fabric pairing table delegate [1649174229040] [52091:542909] CHIP: [ZCL] Using ZAP configuration... [1649174229040] [52091:542909] CHIP: [CTL] System State Initialized... [1649174229042] [52091:542909] CHIP: [CTL] Setting attestation nonce to random value [1649174229042] [52091:542909] CHIP: [CTL] Setting CSR nonce to random value [1649174229042] [52091:542909] CHIP: [CTL] Setting attestation nonce to random value [1649174229042] [52091:542909] CHIP: [CTL] Setting CSR nonce to random value [1649174229044] [52091:542909] CHIP: [CTL] Generating NOC [1649174229045] [52091:542909] CHIP: [DIS] Verifying the received credentials [1649174229045] [52091:542909] CHIP: [DIS] Added new fabric at index: 1, Initialized: 1 [1649174229045] [52091:542909] CHIP: [DIS] Assigned compressed fabric ID: 0x69C3DC2BC37CDB06, node ID: 0x000000000001B669 [1649174229045] [52091:542909] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x69C3DC2BC37CDB06 [1649174229045] [52091:542909] CHIP: [CTL] Setting attestation nonce to random value [1649174229045] [52091:542909] CHIP: [CTL] Setting CSR nonce to random value [1649174229046] [52091:542909] CHIP: [CTL] Generating NOC [1649174229047] [52091:542909] CHIP: [DIS] Verifying the received credentials [1649174229047] [52091:542909] CHIP: [DIS] Added new fabric at index: 2, Initialized: 1 [1649174229047] [52091:542909] CHIP: [DIS] Assigned compressed fabric ID: 0xB0301176A56E7A91, node ID: 0x000000000001B669 [1649174229047] [52091:542909] CHIP: [CTL] Joined the fabric at index 2. Compressed fabric ID is: 0xB0301176A56E7A91 [1649174229047] [52091:542909] CHIP: [CTL] Setting attestation nonce to random value [1649174229047] [52091:542909] CHIP: [CTL] Setting CSR nonce to random value [1649174229048] [52091:542909] CHIP: [CTL] Generating NOC [1649174229048] [52091:542909] CHIP: [DIS] Verifying the received credentials [1649174229048] [52091:542909] CHIP: [DIS] Added new fabric at index: 3, Initialized: 1 [1649174229048] [52091:542909] CHIP: [DIS] Assigned compressed fabric ID: 0x48793717F188D7BA, node ID: 0x000000000001B669 [1649174229048] [52091:542909] CHIP: [CTL] Joined the fabric at index 3. Compressed fabric ID is: 0x48793717F188D7BA [1649174229072] [52091:542911] CHIP: [DL] _OnPlatformEvent [1649174229072] [52091:542911] CHIP: [BLE] NewConnection [1649174229073] [52091:542911] CHIP: [SC] Assigned local session key ID 56295 [1649174229073] [52091:542911] CHIP: [SC] Including MRP parameters in PBKDF param request [1649174229073] [52091:542911] CHIP: [IN] Prepared unauthenticated message 0x700007d89760 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 40865i with MessageCounter:2500073253. [1649174229073] [52091:542911] CHIP: [IN] Sending unauthenticated msg 0x700007d89760 with MessageCounter:2500073253 to 0x0000000000000000 at monotonic time: 00000000035AE0F7 msec [1649174229073] [52091:542911] CHIP: [IN] Message appended to BLE send queue [1649174229073] [52091:542911] CHIP: [SC] Sent PBKDF param request [1649174229073] [52091:542911] CHIP: [CTL] Setting wifi credentials from parameters [1649174229073] [52091:542911] CHIP: [CTL] Setting attestation nonce to random value [1649174229073] [52091:542911] CHIP: [CTL] Setting CSR nonce to random value [1649174229073] [52091:542911] CHIP: [CTL] Commission called for node ID 0x0000000000000004 [1649174229100] [52091:542911] CHIP: [BLE] CBManagerState: ON [1649174229382] [52091:542911] CHIP: [BLE] Connecting to device with discriminator: 3840 [1649174230263] [52091:542912] CHIP: [IN] BleConnectionComplete: endPoint 0x10d9622b0 [1649174230263] [52091:542912] CHIP: [BLE] ATT MTU = 256 [1649174230503] [52091:542912] CHIP: [BLE] subscribe complete, ep = 0x10d9622b0 [1649174230505] [52091:542912] CHIP: [BLE] peripheral chose BTP version 4; central expected between 4 and 4 [1649174230505] [52091:542912] CHIP: [BLE] using BTP fragment sizes rx 244 / tx 244. [1649174230505] [52091:542912] CHIP: [BLE] local and remote recv window size = 5 [1649174230505] [52091:542912] CHIP: [IN] BLE EndPoint 0x10d9622b0 Connection Complete [1649174230659] [52091:542912] CHIP: [EM] Received message of type 0x21 with protocolId (0, 0) and MessageCounter:2300470090 on exchange 40865i [1649174230659] [52091:542912] CHIP: [EM] Found matching exchange: 40865i, Delegate: 0x7fd071ce3058 [1649174230659] [52091:542912] CHIP: [SC] Received PBKDF param response [1649174230659] [52091:542912] CHIP: [SC] Peer assigned session ID 4139 [1649174230659] [52091:542912] CHIP: [SC] Found MRP parameters in the message [1649174230662] [52091:542912] CHIP: [IN] Prepared unauthenticated message 0x700007e0bf20 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 40865i with MessageCounter:2500073254. [1649174230662] [52091:542912] CHIP: [IN] Sending unauthenticated msg 0x700007e0bf20 with MessageCounter:2500073254 to 0x0000000000000000 at monotonic time: 00000000035AE72D msec [1649174230662] [52091:542912] CHIP: [SC] Sent spake2p msg1 [1649174233266] [52091:542912] CHIP: [EM] Received message of type 0x23 with protocolId (0, 0) and MessageCounter:2300470091 on exchange 40865i [1649174233266] [52091:542912] CHIP: [EM] Found matching exchange: 40865i, Delegate: 0x7fd071ce3058 [1649174233266] [52091:542912] CHIP: [SC] Received spake2p msg2 [1649174233267] [52091:542912] CHIP: [IN] Prepared unauthenticated message 0x700007e0c330 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 40865i with MessageCounter:2500073255. [1649174233267] [52091:542912] CHIP: [IN] Sending unauthenticated msg 0x700007e0c330 with MessageCounter:2500073255 to 0x0000000000000000 at monotonic time: 00000000035AF159 msec [1649174233267] [52091:542912] CHIP: [SC] Sent spake2p msg3 [1649174233385] [52091:542911] CHIP: [EM] Received message of type 0x40 with protocolId (0, 0) and MessageCounter:2300470092 on exchange 40865i [1649174233386] [52091:542911] CHIP: [EM] Found matching exchange: 40865i, Delegate: 0x7fd071ce3058 [1649174233386] [52091:542911] CHIP: [IN] New secure session created for device 0x0000000000000004, LSID:56295 PSID:4139! [1649174233386] [52091:542911] CHIP: [CTL] Remote device completed SPAKE2+ handshake [1649174233386] [52091:542911] CHIP: [TOO] Pairing Success [1649174233386] [52091:542911] CHIP: [CTL] Going from commissioning step 'SecurePairing' with lastErr = '../../src/controller/AutoCommissioner.cpp:262: Success' --> 'ReadCommissioningInfo' [1649174233386] [52091:542911] CHIP: [CTL] Performing next commissioning step 'ReadCommissioningInfo' with completion status = '../../src/controller/CommissioningDelegate.h:72: Success' [1649174233386] [52091:542911] CHIP: [CTL] Sending request for commissioning information [1649174233387] [52091:542911] CHIP: [DMG] SendReadRequest ReadClient[0x600002e28000]: Sending Read Request [1649174233387] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d87950 to 0x0000000000000004 (1) of type 0x2 and protocolId (0, 1) on exchange 40866i with MessageCounter:2560135. [1649174233387] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d87950 with MessageCounter:2560135 to 0x0000000000000004 (1) at monotonic time: 00000000035AF1D2 msec [1649174233388] [52091:542911] CHIP: [DMG] MoveToState ReadClient[0x600002e28000]: Moving to [AwaitingIn] [1649174234135] [52091:542912] CHIP: [EM] Received message of type 0x5 with protocolId (0, 1) and MessageCounter:4253246 on exchange 40866i [1649174234135] [52091:542912] CHIP: [EM] Found matching exchange: 40866i, Delegate: 0x600002e28000 [1649174234135] [52091:542912] CHIP: [DMG] ReportDataMessage = [1649174234135] [52091:542912] CHIP: [DMG] { [1649174234135] [52091:542912] CHIP: [DMG] AttributeReportIBs = [1649174234135] [52091:542912] CHIP: [DMG] [ [1649174234135] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234135] [52091:542912] CHIP: [DMG] { [1649174234135] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234135] [52091:542912] CHIP: [DMG] { [1649174234135] [52091:542912] CHIP: [DMG] DataVersion = 0xc7361704, [1649174234135] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234135] [52091:542912] CHIP: [DMG] { [1649174234135] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234135] [52091:542912] CHIP: [DMG] Cluster = 0x31, [1649174234135] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0003, [1649174234135] [52091:542912] CHIP: [DMG] } [1649174234135] [52091:542912] CHIP: [DMG] [1649174234135] [52091:542912] CHIP: [DMG] Data = 30, [1649174234135] [52091:542912] CHIP: [DMG] }, [1649174234135] [52091:542912] CHIP: [DMG] [1649174234135] [52091:542912] CHIP: [DMG] }, [1649174234135] [52091:542912] CHIP: [DMG] [1649174234135] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234135] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] DataVersion = 0x87880af4, [1649174234136] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234136] [52091:542912] CHIP: [DMG] Cluster = 0x28, [1649174234136] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0004, [1649174234136] [52091:542912] CHIP: [DMG] } [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] Data = 32769, [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] DataVersion = 0x87880af4, [1649174234136] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234136] [52091:542912] CHIP: [DMG] Cluster = 0x28, [1649174234136] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0002, [1649174234136] [52091:542912] CHIP: [DMG] } [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] Data = 65521, [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] DataVersion = 0x79738af9, [1649174234136] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234136] [52091:542912] CHIP: [DMG] Cluster = 0x30, [1649174234136] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0003, [1649174234136] [52091:542912] CHIP: [DMG] } [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] Data = 0, [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] DataVersion = 0x79738af9, [1649174234136] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234136] [52091:542912] CHIP: [DMG] { [1649174234136] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234136] [52091:542912] CHIP: [DMG] Cluster = 0x30, [1649174234136] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0002, [1649174234136] [52091:542912] CHIP: [DMG] } [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] Data = 0, [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234136] [52091:542912] CHIP: [DMG] }, [1649174234136] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] DataVersion = 0x79738af9, [1649174234137] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234137] [52091:542912] CHIP: [DMG] Cluster = 0x30, [1649174234137] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0001, [1649174234137] [52091:542912] CHIP: [DMG] } [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] Data = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] 0x0 = 60, [1649174234137] [52091:542912] CHIP: [DMG] }, [1649174234137] [52091:542912] CHIP: [DMG] }, [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] }, [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] DataVersion = 0x79738af9, [1649174234137] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234137] [52091:542912] CHIP: [DMG] Cluster = 0x30, [1649174234137] [52091:542912] CHIP: [DMG] Attribute = 0x0000_0000, [1649174234137] [52091:542912] CHIP: [DMG] } [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] Data = 0, [1649174234137] [52091:542912] CHIP: [DMG] }, [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] }, [1649174234137] [52091:542912] CHIP: [DMG] [1649174234137] [52091:542912] CHIP: [DMG] AttributeReportIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] AttributeDataIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] DataVersion = 0xc7361704, [1649174234137] [52091:542912] CHIP: [DMG] AttributePathIB = [1649174234137] [52091:542912] CHIP: [DMG] { [1649174234137] [52091:542912] CHIP: [DMG] Endpoint = 0x0, [1649174234137] [52091:542912] CHIP: [DMG] Cluster = 0x31, [1649174234137] [52091:542912] CHIP: [DMG] Attribute = 0x0000_FFFC, [1649174234137] [52091:542912] CHIP: [DMG] } [1649174234138] [52091:542912] CHIP: [DMG] [1649174234138] [52091:542912] CHIP: [DMG] Data = 1, [1649174234138] [52091:542912] CHIP: [DMG] }, [1649174234138] [52091:542912] CHIP: [DMG] [1649174234138] [52091:542912] CHIP: [DMG] }, [1649174234138] [52091:542912] CHIP: [DMG] [1649174234138] [52091:542912] CHIP: [DMG] ], [1649174234138] [52091:542912] CHIP: [DMG] [1649174234138] [52091:542912] CHIP: [DMG] SuppressResponse = true, [1649174234138] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174234138] [52091:542912] CHIP: [DMG] } [1649174234140] [52091:542912] CHIP: [CTL] Finished commissioning step 'ReadCommissioningInfo' with error '../../src/controller/CHIPDeviceController.cpp:1541: Success' [1649174234140] [52091:542912] CHIP: [CTL] Going from commissioning step 'ReadCommissioningInfo' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1541: Success' --> 'ArmFailSafe' [1649174234140] [52091:542912] CHIP: [CTL] Performing next commissioning step 'ArmFailSafe' with completion status = '../../src/controller/CHIPDeviceController.cpp:1541: Success' [1649174234140] [52091:542912] CHIP: [CTL] Arming failsafe (60 seconds) [1649174234140] [52091:542912] CHIP: [DMG] ICR moving to [AddingComm] [1649174234140] [52091:542912] CHIP: [DMG] ICR moving to [AddedComma] [1649174234140] [52091:542912] CHIP: [IN] Prepared secure message 0x700007e0a510 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40867i with MessageCounter:2560136. [1649174234140] [52091:542912] CHIP: [IN] Sending encrypted msg 0x700007e0a510 with MessageCounter:2560136 to 0x0000000000000004 (1) at monotonic time: 00000000035AF4C3 msec [1649174234140] [52091:542912] CHIP: [DMG] ICR moving to [CommandSen] [1649174234406] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253247 on exchange 40867i [1649174234406] [52091:542911] CHIP: [EM] Found matching exchange: 40867i, Delegate: 0x7fd07254c130 [1649174234406] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174234406] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174234406] [52091:542911] CHIP: [DMG] { [1649174234406] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174234406] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174234406] [52091:542911] CHIP: [DMG] [ [1649174234406] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174234406] [52091:542911] CHIP: [DMG] { [1649174234406] [52091:542911] CHIP: [DMG] CommandDataIB = [1649174234406] [52091:542911] CHIP: [DMG] { [1649174234406] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174234406] [52091:542911] CHIP: [DMG] { [1649174234406] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174234406] [52091:542911] CHIP: [DMG] ClusterId = 0x30, [1649174234406] [52091:542911] CHIP: [DMG] CommandId = 0x1, [1649174234406] [52091:542911] CHIP: [DMG] }, [1649174234406] [52091:542911] CHIP: [DMG] [1649174234406] [52091:542911] CHIP: [DMG] CommandData = [1649174234406] [52091:542911] CHIP: [DMG] { [1649174234406] [52091:542911] CHIP: [DMG] 0x0 = 0, [1649174234406] [52091:542911] CHIP: [DMG] 0x1 = "", [1649174234406] [52091:542911] CHIP: [DMG] }, [1649174234406] [52091:542911] CHIP: [DMG] }, [1649174234406] [52091:542911] CHIP: [DMG] [1649174234406] [52091:542911] CHIP: [DMG] }, [1649174234407] [52091:542911] CHIP: [DMG] [1649174234407] [52091:542911] CHIP: [DMG] ], [1649174234407] [52091:542911] CHIP: [DMG] [1649174234407] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174234407] [52091:542911] CHIP: [DMG] }, [1649174234407] [52091:542911] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1649174234408] [52091:542911] CHIP: [CTL] Received ArmFailSafe response [1649174234408] [52091:542911] CHIP: [CTL] Finished commissioning step 'ArmFailSafe' with error '../../src/controller/CHIPDeviceController.cpp:1693: Success' [1649174234408] [52091:542911] CHIP: [CTL] Going from commissioning step 'ArmFailSafe' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1693: Success' --> 'ConfigRegulatory' [1649174234408] [52091:542911] CHIP: [CTL] Performing next commissioning step 'ConfigRegulatory' with completion status = '../../src/controller/CHIPDeviceController.cpp:1693: Success' [1649174234408] [52091:542911] CHIP: [CTL] Setting Regulatory Config [1649174234408] [52091:542911] CHIP: [CTL] Device does not support configurable regulatory location [1649174234408] [52091:542911] CHIP: [CTL] Unable to find country code, defaulting to XX [1649174234408] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174234408] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174234408] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d86d10 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40868i with MessageCounter:2560137. [1649174234408] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d86d10 with MessageCounter:2560137 to 0x0000000000000004 (1) at monotonic time: 00000000035AF5CF msec [1649174234409] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174234409] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174234765] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253248 on exchange 40868i [1649174234765] [52091:542911] CHIP: [EM] Found matching exchange: 40868i, Delegate: 0x7fd072194650 [1649174234765] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174234765] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174234765] [52091:542911] CHIP: [DMG] { [1649174234765] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174234765] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174234765] [52091:542911] CHIP: [DMG] [ [1649174234765] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174234765] [52091:542911] CHIP: [DMG] { [1649174234765] [52091:542911] CHIP: [DMG] CommandDataIB = [1649174234765] [52091:542911] CHIP: [DMG] { [1649174234765] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174234765] [52091:542911] CHIP: [DMG] { [1649174234765] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174234765] [52091:542911] CHIP: [DMG] ClusterId = 0x30, [1649174234765] [52091:542911] CHIP: [DMG] CommandId = 0x3, [1649174234765] [52091:542911] CHIP: [DMG] }, [1649174234765] [52091:542911] CHIP: [DMG] [1649174234765] [52091:542911] CHIP: [DMG] CommandData = [1649174234765] [52091:542911] CHIP: [DMG] { [1649174234765] [52091:542911] CHIP: [DMG] 0x0 = 0, [1649174234765] [52091:542911] CHIP: [DMG] 0x1 = "", [1649174234765] [52091:542911] CHIP: [DMG] }, [1649174234765] [52091:542911] CHIP: [DMG] }, [1649174234765] [52091:542911] CHIP: [DMG] [1649174234765] [52091:542911] CHIP: [DMG] }, [1649174234765] [52091:542911] CHIP: [DMG] [1649174234765] [52091:542911] CHIP: [DMG] ], [1649174234765] [52091:542911] CHIP: [DMG] [1649174234765] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174234765] [52091:542911] CHIP: [DMG] }, [1649174234765] [52091:542911] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1649174234765] [52091:542911] CHIP: [CTL] Received SetRegulatoryConfig response [1649174234765] [52091:542911] CHIP: [CTL] Finished commissioning step 'ConfigRegulatory' with error '../../src/controller/CHIPDeviceController.cpp:1702: Success' [1649174234765] [52091:542911] CHIP: [CTL] Going from commissioning step 'ConfigRegulatory' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1702: Success' --> 'SendPAICertificateRequest' [1649174234765] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendPAICertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1702: Success' [1649174234765] [52091:542911] CHIP: [CTL] Sending request for PAI certificate [1649174234765] [52091:542911] CHIP: [CTL] Sending Certificate Chain request to 0x7fd071ce3000 device [1649174234765] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174234766] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174234766] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d86c40 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40869i with MessageCounter:2560138. [1649174234766] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d86c40 with MessageCounter:2560138 to 0x0000000000000004 (1) at monotonic time: 00000000035AF735 msec [1649174234766] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174234766] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174235124] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253249 on exchange 40869i [1649174235124] [52091:542911] CHIP: [EM] Found matching exchange: 40869i, Delegate: 0x7fd07200d130 [1649174235124] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174235124] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174235124] [52091:542911] CHIP: [DMG] { [1649174235124] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174235124] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174235124] [52091:542911] CHIP: [DMG] [ [1649174235124] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174235124] [52091:542911] CHIP: [DMG] { [1649174235124] [52091:542911] CHIP: [DMG] CommandDataIB = [1649174235124] [52091:542911] CHIP: [DMG] { [1649174235124] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174235124] [52091:542911] CHIP: [DMG] { [1649174235124] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174235124] [52091:542911] CHIP: [DMG] ClusterId = 0x3e, [1649174235124] [52091:542911] CHIP: [DMG] CommandId = 0x3, [1649174235124] [52091:542911] CHIP: [DMG] }, [1649174235124] [52091:542911] CHIP: [DMG] [1649174235124] [52091:542911] CHIP: [DMG] CommandData = [1649174235124] [52091:542911] CHIP: [DMG] { [1649174235124] [52091:542911] CHIP: [DMG] 0x0 = [ [1649174235124] [52091:542911] CHIP: [DMG] ... (byte string too long) ... [1649174235124] [52091:542911] CHIP: [DMG] ] [1649174235124] [52091:542911] CHIP: [DMG] }, [1649174235124] [52091:542911] CHIP: [DMG] }, [1649174235124] [52091:542911] CHIP: [DMG] [1649174235124] [52091:542911] CHIP: [DMG] }, [1649174235124] [52091:542911] CHIP: [DMG] [1649174235124] [52091:542911] CHIP: [DMG] ], [1649174235124] [52091:542911] CHIP: [DMG] [1649174235124] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174235125] [52091:542911] CHIP: [DMG] }, [1649174235125] [52091:542911] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1649174235126] [52091:542911] CHIP: [CTL] Received certificate chain from the device [1649174235126] [52091:542911] CHIP: [CTL] Finished commissioning step 'SendPAICertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:933: Success' [1649174235126] [52091:542911] CHIP: [CTL] Going from commissioning step 'SendPAICertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:933: Success' --> 'SendDACCertificateRequest' [1649174235126] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendDACCertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:933: Success' [1649174235126] [52091:542911] CHIP: [CTL] Sending request for DAC certificate [1649174235126] [52091:542911] CHIP: [CTL] Sending Certificate Chain request to 0x7fd071ce3000 device [1649174235126] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174235126] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174235126] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d86bd0 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40870i with MessageCounter:2560139. [1649174235126] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d86bd0 with MessageCounter:2560139 to 0x0000000000000004 (1) at monotonic time: 00000000035AF89C msec [1649174235126] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174235126] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174235484] [52091:542912] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253250 on exchange 40870i [1649174235484] [52091:542912] CHIP: [EM] Found matching exchange: 40870i, Delegate: 0x7fd072065300 [1649174235484] [52091:542912] CHIP: [DMG] ICR moving to [ResponseRe] [1649174235484] [52091:542912] CHIP: [DMG] InvokeResponseMessage = [1649174235484] [52091:542912] CHIP: [DMG] { [1649174235484] [52091:542912] CHIP: [DMG] suppressResponse = false, [1649174235484] [52091:542912] CHIP: [DMG] InvokeResponseIBs = [1649174235484] [52091:542912] CHIP: [DMG] [ [1649174235484] [52091:542912] CHIP: [DMG] InvokeResponseIB = [1649174235484] [52091:542912] CHIP: [DMG] { [1649174235484] [52091:542912] CHIP: [DMG] CommandDataIB = [1649174235484] [52091:542912] CHIP: [DMG] { [1649174235484] [52091:542912] CHIP: [DMG] CommandPathIB = [1649174235484] [52091:542912] CHIP: [DMG] { [1649174235484] [52091:542912] CHIP: [DMG] EndpointId = 0x0, [1649174235484] [52091:542912] CHIP: [DMG] ClusterId = 0x3e, [1649174235484] [52091:542912] CHIP: [DMG] CommandId = 0x3, [1649174235484] [52091:542912] CHIP: [DMG] }, [1649174235484] [52091:542912] CHIP: [DMG] [1649174235484] [52091:542912] CHIP: [DMG] CommandData = [1649174235484] [52091:542912] CHIP: [DMG] { [1649174235484] [52091:542912] CHIP: [DMG] 0x0 = [ [1649174235484] [52091:542912] CHIP: [DMG] ... (byte string too long) ... [1649174235484] [52091:542912] CHIP: [DMG] ] [1649174235484] [52091:542912] CHIP: [DMG] }, [1649174235484] [52091:542912] CHIP: [DMG] }, [1649174235484] [52091:542912] CHIP: [DMG] [1649174235484] [52091:542912] CHIP: [DMG] }, [1649174235484] [52091:542912] CHIP: [DMG] [1649174235484] [52091:542912] CHIP: [DMG] ], [1649174235484] [52091:542912] CHIP: [DMG] [1649174235484] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174235484] [52091:542912] CHIP: [DMG] }, [1649174235484] [52091:542912] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1649174235484] [52091:542912] CHIP: [CTL] Received certificate chain from the device [1649174235484] [52091:542912] CHIP: [CTL] Finished commissioning step 'SendDACCertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:933: Success' [1649174235484] [52091:542912] CHIP: [CTL] Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:933: Success' --> 'SendAttestationRequest' [1649174235484] [52091:542912] CHIP: [CTL] Performing next commissioning step 'SendAttestationRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:933: Success' [1649174235484] [52091:542912] CHIP: [CTL] Sending Attestation Request to the device. [1649174235484] [52091:542912] CHIP: [CTL] Sending Attestation request to 0x7fd071ce3000 device [1649174235486] [52091:542912] CHIP: [DMG] ICR moving to [AddingComm] [1649174235486] [52091:542912] CHIP: [DMG] ICR moving to [AddedComma] [1649174235486] [52091:542912] CHIP: [IN] Prepared secure message 0x700007e09b90 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40871i with MessageCounter:2560140. [1649174235486] [52091:542912] CHIP: [IN] Sending encrypted msg 0x700007e09b90 with MessageCounter:2560140 to 0x0000000000000004 (1) at monotonic time: 00000000035AFA04 msec [1649174235486] [52091:542912] CHIP: [DMG] ICR moving to [CommandSen] [1649174235486] [52091:542912] CHIP: [CTL] Sent Attestation request, waiting for the Attestation Information [1649174235486] [52091:542912] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174236360] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253251 on exchange 40871i [1649174236360] [52091:542911] CHIP: [EM] Found matching exchange: 40871i, Delegate: 0x7fd072204080 [1649174236360] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174236360] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174236360] [52091:542911] CHIP: [DMG] { [1649174236360] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174236360] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174236360] [52091:542911] CHIP: [DMG] [ [1649174236360] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174236360] [52091:542911] CHIP: [DMG] { [1649174236360] [52091:542911] CHIP: [DMG] CommandDataIB = [1649174236360] [52091:542911] CHIP: [DMG] { [1649174236360] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174236360] [52091:542911] CHIP: [DMG] { [1649174236360] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174236360] [52091:542911] CHIP: [DMG] ClusterId = 0x3e, [1649174236360] [52091:542911] CHIP: [DMG] CommandId = 0x1, [1649174236360] [52091:542911] CHIP: [DMG] }, [1649174236360] [52091:542911] CHIP: [DMG] [1649174236360] [52091:542911] CHIP: [DMG] CommandData = [1649174236360] [52091:542911] CHIP: [DMG] { [1649174236360] [52091:542911] CHIP: [DMG] 0x0 = [ [1649174236360] [52091:542911] CHIP: [DMG] ... (byte string too long) ... [1649174236360] [52091:542911] CHIP: [DMG] ] [1649174236360] [52091:542911] CHIP: [DMG] 0x1 = [ [1649174236360] [52091:542911] CHIP: [DMG] 0xd8, 0xcd, 0xdc, 0xd7, 0x8a, 0xc2, 0xd1, 0x63, 0xa4, 0x1a, 0x68, 0x3a, 0x7d, 0xf6, 0x94, 0xec, 0x5f, 0x41, 0xe5, 0x45, 0xb0, 0xab, 0x2a, 0xdb, 0xe2, 0x51, 0xc4, 0x8, 0x3a, 0xf5, 0x88, 0x9c, 0xda, 0xf6, 0x9 [1649174236360] [52091:542911] CHIP: [DMG] ] [1649174236360] [52091:542911] CHIP: [DMG] }, [1649174236360] [52091:542911] CHIP: [DMG] }, [1649174236360] [52091:542911] CHIP: [DMG] [1649174236360] [52091:542911] CHIP: [DMG] }, [1649174236360] [52091:542911] CHIP: [DMG] [1649174236360] [52091:542911] CHIP: [DMG] ], [1649174236360] [52091:542911] CHIP: [DMG] [1649174236360] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174236360] [52091:542911] CHIP: [DMG] }, [1649174236360] [52091:542911] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1649174236360] [52091:542911] CHIP: [CTL] Received Attestation Information from the device [1649174236360] [52091:542911] CHIP: [CTL] Finished commissioning step 'SendAttestationRequest' with error '../../src/controller/CHIPDeviceController.cpp:968: Success' [1649174236360] [52091:542911] CHIP: [CTL] Going from commissioning step 'SendAttestationRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:968: Success' --> 'AttestationVerification' [1649174236361] [52091:542911] CHIP: [CTL] Performing next commissioning step 'AttestationVerification' with completion status = '../../src/controller/CHIPDeviceController.cpp:968: Success' [1649174236361] [52091:542911] CHIP: [CTL] Verifying attestation [1649174236368] [52091:542911] CHIP: [CTL] Successfully validated 'Attestation Information' command received from the device. [1649174236368] [52091:542911] CHIP: [CTL] Finished commissioning step 'AttestationVerification' with error '../../src/controller/CHIPDeviceController.cpp:1000: Success' [1649174236368] [52091:542911] CHIP: [CTL] Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1000: Success' --> 'SendOpCertSigningRequest' [1649174236368] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendOpCertSigningRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1000: Success' [1649174236368] [52091:542911] CHIP: [CTL] Sending CSR request to 0x7fd071ce3000 device [1649174236368] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174236368] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174236369] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d84920 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40872i with MessageCounter:2560141. [1649174236369] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d84920 with MessageCounter:2560141 to 0x0000000000000004 (1) at monotonic time: 00000000035AFD77 msec [1649174236369] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174236369] [52091:542911] CHIP: [CTL] Sent CSR request, waiting for the CSR [1649174236369] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174238670] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253252 on exchange 40872i [1649174238670] [52091:542911] CHIP: [EM] Found matching exchange: 40872i, Delegate: 0x7fd07254c130 [1649174238670] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174238670] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174238670] [52091:542911] CHIP: [DMG] { [1649174238670] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174238670] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174238670] [52091:542911] CHIP: [DMG] [ [1649174238670] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174238670] [52091:542911] CHIP: [DMG] { [1649174238670] [52091:542911] CHIP: [DMG] CommandDataIB = [1649174238670] [52091:542911] CHIP: [DMG] { [1649174238670] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174238670] [52091:542911] CHIP: [DMG] { [1649174238670] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174238670] [52091:542911] CHIP: [DMG] ClusterId = 0x3e, [1649174238670] [52091:542911] CHIP: [DMG] CommandId = 0x5, [1649174238670] [52091:542911] CHIP: [DMG] }, [1649174238670] [52091:542911] CHIP: [DMG] [1649174238670] [52091:542911] CHIP: [DMG] CommandData = [1649174238670] [52091:542911] CHIP: [DMG] { [1649174238670] [52091:542911] CHIP: [DMG] 0x0 = [ [1649174238671] [52091:542911] CHIP: [DMG] 0x15, 0x30, 0x1, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, [1649174238671] [52091:542911] CHIP: [DMG] ] [1649174238671] [52091:542911] CHIP: [DMG] 0x1 = [ [1649174238671] [52091:542911] CHIP: [DMG] 0xa, 0xc6, 0x23, 0x79, 0xcf, 0x5c, 0xa4, 0xc5, 0x74, 0xf1, 0x88, 0x80, 0x1c, 0x87, 0x4, 0x5c, 0x42, 0x3d, 0x94, 0xe1, 0x7c, 0x43, 0xeb, 0xc3, 0xb6, 0x7a, 0x72, 0xba, 0x8, 0x9e, 0x33, 0xd6, 0x94, 0xba, 0x43, [1649174238671] [52091:542911] CHIP: [DMG] ] [1649174238671] [52091:542911] CHIP: [DMG] }, [1649174238671] [52091:542911] CHIP: [DMG] }, [1649174238671] [52091:542911] CHIP: [DMG] [1649174238671] [52091:542911] CHIP: [DMG] }, [1649174238671] [52091:542911] CHIP: [DMG] [1649174238671] [52091:542911] CHIP: [DMG] ], [1649174238671] [52091:542911] CHIP: [DMG] [1649174238671] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174238671] [52091:542911] CHIP: [DMG] }, [1649174238671] [52091:542911] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1649174238671] [52091:542911] CHIP: [CTL] Received certificate signing request from the device [1649174238671] [52091:542911] CHIP: [CTL] Finished commissioning step 'SendOpCertSigningRequest' with error '../../src/controller/CHIPDeviceController.cpp:1069: Success' [1649174238671] [52091:542911] CHIP: [CTL] Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1069: Success' --> 'ValidateCSR' [1649174238671] [52091:542911] CHIP: [CTL] Performing next commissioning step 'ValidateCSR' with completion status = '../../src/controller/CHIPDeviceController.cpp:1069: Success' [1649174238672] [52091:542911] CHIP: [CTL] Finished commissioning step 'ValidateCSR' with error '../../src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1649174238672] [52091:542911] CHIP: [CTL] Going from commissioning step 'ValidateCSR' with lastErr = '../../src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' --> 'GenerateNOCChain' [1649174238672] [52091:542911] CHIP: [CTL] Performing next commissioning step 'GenerateNOCChain' with completion status = '../../src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1649174238672] [52091:542911] CHIP: [CTL] Getting certificate chain for the device from the issuer [1649174238672] [52091:542911] CHIP: [CTL] Verifying Certificate Signing Request [1649174238672] [52091:542911] CHIP: [CTL] Generating NOC [1649174238673] [52091:542911] CHIP: [CTL] Providing certificate chain to the commissioner [1649174238673] [52091:542911] CHIP: [CTL] Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success [1649174238673] [52091:542911] CHIP: [CTL] Finished commissioning step 'GenerateNOCChain' with error '../../src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success' [1649174238673] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendTrustedRootCert' with completion status = '../../src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1649174238673] [52091:542911] CHIP: [CTL] Sending root certificate to the device [1649174238673] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174238673] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174238673] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d82d80 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40873i with MessageCounter:2560142. [1649174238673] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d82d80 with MessageCounter:2560142 to 0x0000000000000004 (1) at monotonic time: 00000000035B0677 msec [1649174238673] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174238673] [52091:542911] CHIP: [CTL] Sent root certificate to the device [1649174238673] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174239087] [52091:542911] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253253 on exchange 40873i [1649174239087] [52091:542911] CHIP: [EM] Found matching exchange: 40873i, Delegate: 0x7fd07200d130 [1649174239087] [52091:542911] CHIP: [DMG] ICR moving to [ResponseRe] [1649174239087] [52091:542911] CHIP: [DMG] InvokeResponseMessage = [1649174239087] [52091:542911] CHIP: [DMG] { [1649174239087] [52091:542911] CHIP: [DMG] suppressResponse = false, [1649174239087] [52091:542911] CHIP: [DMG] InvokeResponseIBs = [1649174239087] [52091:542911] CHIP: [DMG] [ [1649174239087] [52091:542911] CHIP: [DMG] InvokeResponseIB = [1649174239087] [52091:542911] CHIP: [DMG] { [1649174239087] [52091:542911] CHIP: [DMG] CommandStatusIB = [1649174239088] [52091:542911] CHIP: [DMG] { [1649174239088] [52091:542911] CHIP: [DMG] CommandPathIB = [1649174239088] [52091:542911] CHIP: [DMG] { [1649174239088] [52091:542911] CHIP: [DMG] EndpointId = 0x0, [1649174239088] [52091:542911] CHIP: [DMG] ClusterId = 0x3e, [1649174239088] [52091:542911] CHIP: [DMG] CommandId = 0xb, [1649174239088] [52091:542911] CHIP: [DMG] }, [1649174239088] [52091:542911] CHIP: [DMG] [1649174239088] [52091:542911] CHIP: [DMG] StatusIB = [1649174239088] [52091:542911] CHIP: [DMG] { [1649174239088] [52091:542911] CHIP: [DMG] status = 0x00 (SUCCESS), [1649174239088] [52091:542911] CHIP: [DMG] }, [1649174239088] [52091:542911] CHIP: [DMG] [1649174239088] [52091:542911] CHIP: [DMG] }, [1649174239088] [52091:542911] CHIP: [DMG] [1649174239088] [52091:542911] CHIP: [DMG] }, [1649174239088] [52091:542911] CHIP: [DMG] [1649174239088] [52091:542911] CHIP: [DMG] ], [1649174239088] [52091:542911] CHIP: [DMG] [1649174239088] [52091:542911] CHIP: [DMG] InteractionModelRevision = 1 [1649174239088] [52091:542911] CHIP: [DMG] }, [1649174239088] [52091:542911] CHIP: [DMG] Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1649174239088] [52091:542911] CHIP: [CTL] Device confirmed that it has received the root certificate [1649174239088] [52091:542911] CHIP: [CTL] Finished commissioning step 'SendTrustedRootCert' with error '../../src/controller/CHIPDeviceController.cpp:1239: Success' [1649174239088] [52091:542911] CHIP: [CTL] Going from commissioning step 'SendTrustedRootCert' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1239: Success' --> 'SendNOC' [1649174239088] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendNOC' with completion status = '../../src/controller/CHIPDeviceController.cpp:1239: Success' [1649174239088] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174239088] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174239088] [52091:542911] CHIP: [IN] Prepared secure message 0x700007d86c40 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40874i with MessageCounter:2560143. [1649174239088] [52091:542911] CHIP: [IN] Sending encrypted msg 0x700007d86c40 with MessageCounter:2560143 to 0x0000000000000004 (1) at monotonic time: 00000000035B0817 msec [1649174239088] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174239088] [52091:542911] CHIP: [CTL] Sent operational certificate to the device [1649174239088] [52091:542911] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174241817] [52091:542912] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253254 on exchange 40874i [1649174241818] [52091:542912] CHIP: [EM] Found matching exchange: 40874i, Delegate: 0x7fd07254c130 [1649174241818] [52091:542912] CHIP: [DMG] ICR moving to [ResponseRe] [1649174241818] [52091:542912] CHIP: [DMG] InvokeResponseMessage = [1649174241818] [52091:542912] CHIP: [DMG] { [1649174241818] [52091:542912] CHIP: [DMG] suppressResponse = false, [1649174241818] [52091:542912] CHIP: [DMG] InvokeResponseIBs = [1649174241818] [52091:542912] CHIP: [DMG] [ [1649174241818] [52091:542912] CHIP: [DMG] InvokeResponseIB = [1649174241818] [52091:542912] CHIP: [DMG] { [1649174241818] [52091:542912] CHIP: [DMG] CommandDataIB = [1649174241818] [52091:542912] CHIP: [DMG] { [1649174241818] [52091:542912] CHIP: [DMG] CommandPathIB = [1649174241818] [52091:542912] CHIP: [DMG] { [1649174241818] [52091:542912] CHIP: [DMG] EndpointId = 0x0, [1649174241818] [52091:542912] CHIP: [DMG] ClusterId = 0x3e, [1649174241818] [52091:542912] CHIP: [DMG] CommandId = 0x8, [1649174241818] [52091:542912] CHIP: [DMG] }, [1649174241818] [52091:542912] CHIP: [DMG] [1649174241818] [52091:542912] CHIP: [DMG] CommandData = [1649174241818] [52091:542912] CHIP: [DMG] { [1649174241818] [52091:542912] CHIP: [DMG] 0x0 = 0, [1649174241818] [52091:542912] CHIP: [DMG] 0x1 = 1, [1649174241818] [52091:542912] CHIP: [DMG] }, [1649174241818] [52091:542912] CHIP: [DMG] }, [1649174241818] [52091:542912] CHIP: [DMG] [1649174241818] [52091:542912] CHIP: [DMG] }, [1649174241818] [52091:542912] CHIP: [DMG] [1649174241818] [52091:542912] CHIP: [DMG] ], [1649174241818] [52091:542912] CHIP: [DMG] [1649174241818] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174241818] [52091:542912] CHIP: [DMG] }, [1649174241818] [52091:542912] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1649174241818] [52091:542912] CHIP: [CTL] Device returned status 0 on receiving the NOC [1649174241818] [52091:542912] CHIP: [CTL] Operational credentials provisioned on device 0x7fd071ce3000 [1649174241818] [52091:542912] CHIP: [TOO] Secure Pairing Success [1649174241818] [52091:542912] CHIP: [CTL] Finished commissioning step 'SendNOC' with error '../../src/controller/CHIPDeviceController.cpp:1265: Success' [1649174241818] [52091:542912] CHIP: [CTL] Going from commissioning step 'SendNOC' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1265: Success' --> 'WiFiNetworkSetup' [1649174241818] [52091:542912] CHIP: [CTL] Performing next commissioning step 'WiFiNetworkSetup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1265: Success' [1649174241819] [52091:542912] CHIP: [DMG] ICR moving to [AddingComm] [1649174241819] [52091:542912] CHIP: [DMG] ICR moving to [AddedComma] [1649174241819] [52091:542912] CHIP: [IN] Prepared secure message 0x700007e09b60 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40875i with MessageCounter:2560144. [1649174241819] [52091:542912] CHIP: [IN] Sending encrypted msg 0x700007e09b60 with MessageCounter:2560144 to 0x0000000000000004 (1) at monotonic time: 00000000035B12C1 msec [1649174241819] [52091:542912] CHIP: [DMG] ICR moving to [CommandSen] [1649174241819] [52091:542912] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174242086] [52091:542912] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253255 on exchange 40875i [1649174242086] [52091:542912] CHIP: [EM] Found matching exchange: 40875i, Delegate: 0x7fd072194650 [1649174242086] [52091:542912] CHIP: [DMG] ICR moving to [ResponseRe] [1649174242086] [52091:542912] CHIP: [DMG] InvokeResponseMessage = [1649174242086] [52091:542912] CHIP: [DMG] { [1649174242086] [52091:542912] CHIP: [DMG] suppressResponse = false, [1649174242086] [52091:542912] CHIP: [DMG] InvokeResponseIBs = [1649174242086] [52091:542912] CHIP: [DMG] [ [1649174242086] [52091:542912] CHIP: [DMG] InvokeResponseIB = [1649174242086] [52091:542912] CHIP: [DMG] { [1649174242086] [52091:542912] CHIP: [DMG] CommandDataIB = [1649174242086] [52091:542912] CHIP: [DMG] { [1649174242086] [52091:542912] CHIP: [DMG] CommandPathIB = [1649174242086] [52091:542912] CHIP: [DMG] { [1649174242086] [52091:542912] CHIP: [DMG] EndpointId = 0x0, [1649174242086] [52091:542912] CHIP: [DMG] ClusterId = 0x31, [1649174242086] [52091:542912] CHIP: [DMG] CommandId = 0x5, [1649174242086] [52091:542912] CHIP: [DMG] }, [1649174242086] [52091:542912] CHIP: [DMG] [1649174242086] [52091:542912] CHIP: [DMG] CommandData = [1649174242086] [52091:542912] CHIP: [DMG] { [1649174242086] [52091:542912] CHIP: [DMG] 0x0 = 0, [1649174242086] [52091:542912] CHIP: [DMG] 0x2 = 0, [1649174242086] [52091:542912] CHIP: [DMG] }, [1649174242086] [52091:542912] CHIP: [DMG] }, [1649174242086] [52091:542912] CHIP: [DMG] [1649174242086] [52091:542912] CHIP: [DMG] }, [1649174242086] [52091:542912] CHIP: [DMG] [1649174242086] [52091:542912] CHIP: [DMG] ], [1649174242086] [52091:542912] CHIP: [DMG] [1649174242086] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174242086] [52091:542912] CHIP: [DMG] }, [1649174242086] [52091:542912] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1649174242086] [52091:542912] CHIP: [CTL] Received NetworkConfig response [1649174242086] [52091:542912] CHIP: [CTL] Finished commissioning step 'WiFiNetworkSetup' with error '../../src/controller/CHIPDeviceController.cpp:1711: Success' [1649174242086] [52091:542912] CHIP: [CTL] Going from commissioning step 'WiFiNetworkSetup' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1711: Success' --> 'WiFiNetworkEnable' [1649174242086] [52091:542912] CHIP: [CTL] Setting wifi connection time min = 30 [1649174242086] [52091:542912] CHIP: [CTL] Performing next commissioning step 'WiFiNetworkEnable' with completion status = '../../src/controller/CHIPDeviceController.cpp:1711: Success' [1649174242086] [52091:542912] CHIP: [DMG] ICR moving to [AddingComm] [1649174242086] [52091:542912] CHIP: [DMG] ICR moving to [AddedComma] [1649174242086] [52091:542912] CHIP: [IN] Prepared secure message 0x700007e09d00 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40876i with MessageCounter:2560145. [1649174242086] [52091:542912] CHIP: [IN] Sending encrypted msg 0x700007e09d00 with MessageCounter:2560145 to 0x0000000000000004 (1) at monotonic time: 00000000035B13CC msec [1649174242086] [52091:542912] CHIP: [DMG] ICR moving to [CommandSen] [1649174242086] [52091:542912] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174243495] [52091:542912] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4253256 on exchange 40876i [1649174243495] [52091:542912] CHIP: [EM] Found matching exchange: 40876i, Delegate: 0x7fd07200d130 [1649174243495] [52091:542912] CHIP: [DMG] ICR moving to [ResponseRe] [1649174243495] [52091:542912] CHIP: [DMG] InvokeResponseMessage = [1649174243495] [52091:542912] CHIP: [DMG] { [1649174243495] [52091:542912] CHIP: [DMG] suppressResponse = false, [1649174243495] [52091:542912] CHIP: [DMG] InvokeResponseIBs = [1649174243495] [52091:542912] CHIP: [DMG] [ [1649174243495] [52091:542912] CHIP: [DMG] InvokeResponseIB = [1649174243495] [52091:542912] CHIP: [DMG] { [1649174243495] [52091:542912] CHIP: [DMG] CommandDataIB = [1649174243495] [52091:542912] CHIP: [DMG] { [1649174243495] [52091:542912] CHIP: [DMG] CommandPathIB = [1649174243495] [52091:542912] CHIP: [DMG] { [1649174243495] [52091:542912] CHIP: [DMG] EndpointId = 0x0, [1649174243495] [52091:542912] CHIP: [DMG] ClusterId = 0x31, [1649174243495] [52091:542912] CHIP: [DMG] CommandId = 0x7, [1649174243495] [52091:542912] CHIP: [DMG] }, [1649174243495] [52091:542912] CHIP: [DMG] [1649174243495] [52091:542912] CHIP: [DMG] CommandData = [1649174243495] [52091:542912] CHIP: [DMG] { [1649174243495] [52091:542912] CHIP: [DMG] 0x0 = 0, [1649174243495] [52091:542912] CHIP: [DMG] 0x2 = NULL [1649174243495] [52091:542912] CHIP: [DMG] }, [1649174243495] [52091:542912] CHIP: [DMG] }, [1649174243495] [52091:542912] CHIP: [DMG] [1649174243495] [52091:542912] CHIP: [DMG] }, [1649174243495] [52091:542912] CHIP: [DMG] [1649174243495] [52091:542912] CHIP: [DMG] ], [1649174243495] [52091:542912] CHIP: [DMG] [1649174243495] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174243495] [52091:542912] CHIP: [DMG] }, [1649174243495] [52091:542912] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1649174243496] [52091:542912] CHIP: [CTL] Received ConnectNetwork response [1649174243496] [52091:542912] CHIP: [CTL] Finished commissioning step 'WiFiNetworkEnable' with error '../../src/controller/CHIPDeviceController.cpp:1720: Success' [1649174243496] [52091:542912] CHIP: [CTL] Going from commissioning step 'WiFiNetworkEnable' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1720: Success' --> 'FindOperational' [1649174243496] [52091:542912] CHIP: [CTL] Performing next commissioning step 'FindOperational' with completion status = '../../src/controller/CHIPDeviceController.cpp:1720: Success' [1649174243496] [52091:542912] CHIP: [CSM] FindOrEstablishSession: PeerId = 69C3DC2BC37CDB06:0000000000000004, NodeIdWasResolved = 0 [1649174243496] [52091:542912] CHIP: [CSM] FindOrEstablishSession: No existing session found [1649174243496] [52091:542912] CHIP: [DIS] Resolving 69C3DC2BC37CDB06:0000000000000004 ... [1649174243496] [52091:542912] CHIP: [DIS] Operational node lookup already in progress. Will NOT start a new one. [1649174243496] [52091:542912] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174243697] [52091:542912] CHIP: [DIS] Checking node lookup status after 202 ms [1649174246495] [52091:542912] CHIP: [DL] Resolved interface id: 7 [1649174246497] [52091:542912] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174246497] [52091:542912] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174246497] [52091:542912] CHIP: [DIS] Node ID resolved for 69C3DC2BC37CDB06:0000000000000004 [1649174246497] [52091:542912] CHIP: [DIS] Addr 0: [fe80::8eaa:b5ff:fe80:4b4c]:5540 [1649174246497] [52091:542912] CHIP: [DIS] Addr 1: [192.168.7.145]:5540 [1649174246498] [52091:542912] CHIP: [DIS] UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540: new best score: 3 [1649174246498] [52091:542912] CHIP: [DIS] UDP:192.168.7.145%en0:5540: score has not improved: 2 [1649174246498] [52091:542912] CHIP: [DIS] Checking node lookup status after 3002 ms [1649174246498] [52091:542912] CHIP: [CTL] Updating device address to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 while in state 1 [1649174246498] [52091:542912] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 1 --> 2 [1649174246498] [52091:542912] CHIP: [SC] Establishing CASE session to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 [1649174246499] [52091:542912] CHIP: [SC] RecoverInitiatorIpk: GroupDataProvider 0x7fd072008590, Got IPK for FabricIndex 1 [1649174246499] [52091:542912] CHIP: [SC] 0xa9, 0x3d, 0xad, 0x9a, 0xbe, 0x9e, 0x7d, 0x41, [1649174246499] [52091:542912] CHIP: [SC] 0x08, 0x5d, 0xb3, 0xfc, 0xcb, 0xa0, 0x0f, 0x9e, [1649174246499] [52091:542912] CHIP: [SC] Including MRP parameters [1649174246499] [52091:542912] CHIP: [IN] Prepared unauthenticated message 0x7fd073093268 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 40877i with MessageCounter:2500073256. [1649174246499] [52091:542912] CHIP: [IN] Sending unauthenticated msg 0x7fd073093268 with MessageCounter:2500073256 to 0x0000000000000000 at monotonic time: 00000000035B250A msec [1649174246499] [52091:542912] CHIP: [SC] Sent Sigma1 msg [1649174246499] [52091:542912] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 2 --> 3 [1649174246499] [52091:542912] CHIP: [DIS] Discovery does not require any more timeouts [1649174248600] [52091:542912] CHIP: [EM] Received message of type 0x31 with protocolId (0, 0) and MessageCounter:2300470093 on exchange 40877i [1649174248600] [52091:542912] CHIP: [EM] Found matching exchange: 40877i, Delegate: 0x7fd074047a38 [1649174248600] [52091:542912] CHIP: [EM] Rxd Ack; Removing MessageCounter:2500073256 from Retrans Table on exchange 40877i [1649174248600] [52091:542912] CHIP: [EM] Removed CHIP MessageCounter:2500073256 from RetransTable on exchange 40877i [1649174248600] [52091:542912] CHIP: [SC] Received Sigma2 msg [1649174248600] [52091:542912] CHIP: [SC] Peer assigned session session ID 4140 [1649174248601] [52091:542912] CHIP: [SC] The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1649174248604] [52091:542912] CHIP: [SC] Found MRP parameters in the message [1649174248604] [52091:542912] CHIP: [SC] Sending Sigma3 [1649174248604] [52091:542912] CHIP: [EM] Piggybacking Ack for MessageCounter:2300470093 on exchange: 40877i [1649174248604] [52091:542912] CHIP: [IN] Prepared unauthenticated message 0x7fd073093268 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 40877i with MessageCounter:2500073257. [1649174248604] [52091:542912] CHIP: [IN] Sending unauthenticated msg 0x7fd073093268 with MessageCounter:2500073257 to 0x0000000000000000 at monotonic time: 00000000035B2D43 msec [1649174248604] [52091:542912] CHIP: [SC] Sent Sigma3 msg [1649174252111] [52091:542911] CHIP: [EM] Received message of type 0x40 with protocolId (0, 0) and MessageCounter:2300470094 on exchange 40877i [1649174252111] [52091:542911] CHIP: [EM] Found matching exchange: 40877i, Delegate: 0x7fd074047a38 [1649174252111] [52091:542911] CHIP: [EM] Rxd Ack; Removing MessageCounter:2500073257 from Retrans Table on exchange 40877i [1649174252111] [52091:542911] CHIP: [EM] Removed CHIP MessageCounter:2500073257 from RetransTable on exchange 40877i [1649174252111] [52091:542911] CHIP: [SC] Success status report received. Session was established [1649174252111] [52091:542911] CHIP: [IN] New secure session created for device 0x0000000000000004, LSID:56296 PSID:4140! [1649174252111] [52091:542911] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 3 --> 4 [1649174252111] [52091:542911] CHIP: [CTL] Finished commissioning step 'FindOperational' with error '../../src/controller/CHIPDeviceController.cpp:1485: Success' [1649174252111] [52091:542911] CHIP: [CTL] Going from commissioning step 'FindOperational' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1485: Success' --> 'SendComplete' [1649174252111] [52091:542911] CHIP: [CTL] Performing next commissioning step 'SendComplete' with completion status = '../../src/controller/CHIPDeviceController.cpp:1485: Success' [1649174252111] [52091:542911] CHIP: [DMG] ICR moving to [AddingComm] [1649174252111] [52091:542911] CHIP: [DMG] ICR moving to [AddedComma] [1649174252111] [52091:542911] CHIP: [IN] Prepared secure message 0x7fd073093268 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 40878i with MessageCounter:3274790. [1649174252111] [52091:542911] CHIP: [IN] Sending encrypted msg 0x7fd073093268 with MessageCounter:3274790 to 0x0000000000000004 (1) at monotonic time: 00000000035B3AF5 msec [1649174252111] [52091:542911] CHIP: [DMG] ICR moving to [CommandSen] [1649174252111] [52091:542911] CHIP: [EM] Sending Standalone Ack for MessageCounter:2300470094 on exchange 40877i [1649174252111] [52091:542911] CHIP: [IN] Prepared unauthenticated message 0x700007d894e0 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 40877i with MessageCounter:2500073258. [1649174252111] [52091:542911] CHIP: [IN] Sending unauthenticated msg 0x700007d894e0 with MessageCounter:2500073258 to 0x0000000000000000 at monotonic time: 00000000035B3AF6 msec [1649174252111] [52091:542911] CHIP: [EM] Flushed pending ack for MessageCounter:2300470094 on exchange 40877i [1649174252436] [52091:542912] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:13262706 on exchange 40878i [1649174252436] [52091:542912] CHIP: [EM] Found matching exchange: 40878i, Delegate: 0x7fd07200d130 [1649174252436] [52091:542912] CHIP: [EM] Rxd Ack; Removing MessageCounter:3274790 from Retrans Table on exchange 40878i [1649174252436] [52091:542912] CHIP: [EM] Removed CHIP MessageCounter:3274790 from RetransTable on exchange 40878i [1649174252436] [52091:542912] CHIP: [DMG] ICR moving to [ResponseRe] [1649174252436] [52091:542912] CHIP: [DMG] InvokeResponseMessage = [1649174252436] [52091:542912] CHIP: [DMG] { [1649174252436] [52091:542912] CHIP: [DMG] suppressResponse = false, [1649174252436] [52091:542912] CHIP: [DMG] InvokeResponseIBs = [1649174252436] [52091:542912] CHIP: [DMG] [ [1649174252436] [52091:542912] CHIP: [DMG] InvokeResponseIB = [1649174252436] [52091:542912] CHIP: [DMG] { [1649174252436] [52091:542912] CHIP: [DMG] CommandDataIB = [1649174252436] [52091:542912] CHIP: [DMG] { [1649174252436] [52091:542912] CHIP: [DMG] CommandPathIB = [1649174252436] [52091:542912] CHIP: [DMG] { [1649174252436] [52091:542912] CHIP: [DMG] EndpointId = 0x0, [1649174252436] [52091:542912] CHIP: [DMG] ClusterId = 0x30, [1649174252436] [52091:542912] CHIP: [DMG] CommandId = 0x5, [1649174252437] [52091:542912] CHIP: [DMG] }, [1649174252437] [52091:542912] CHIP: [DMG] [1649174252437] [52091:542912] CHIP: [DMG] CommandData = [1649174252437] [52091:542912] CHIP: [DMG] { [1649174252437] [52091:542912] CHIP: [DMG] 0x0 = 0, [1649174252437] [52091:542912] CHIP: [DMG] 0x1 = "", [1649174252437] [52091:542912] CHIP: [DMG] }, [1649174252437] [52091:542912] CHIP: [DMG] }, [1649174252437] [52091:542912] CHIP: [DMG] [1649174252437] [52091:542912] CHIP: [DMG] }, [1649174252437] [52091:542912] CHIP: [DMG] [1649174252437] [52091:542912] CHIP: [DMG] ], [1649174252437] [52091:542912] CHIP: [DMG] [1649174252437] [52091:542912] CHIP: [DMG] InteractionModelRevision = 1 [1649174252437] [52091:542912] CHIP: [DMG] }, [1649174252437] [52091:542912] CHIP: [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1649174252437] [52091:542912] CHIP: [CTL] Received CommissioningComplete response [1649174252437] [52091:542912] CHIP: [CTL] Finished commissioning step 'SendComplete' with error '../../src/controller/CHIPDeviceController.cpp:1729: Success' [1649174252437] [52091:542912] CHIP: [CTL] Going from commissioning step 'SendComplete' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1729: Success' --> 'Cleanup' [1649174252437] [52091:542912] CHIP: [CTL] Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1729: Success' [1649174252437] [52091:542912] CHIP: [CTL] Finished commissioning step 'Cleanup' with error '../../src/controller/CHIPDeviceController.cpp:1372: Success' [1649174252437] [52091:542912] CHIP: [TOO] Device commissioning completed with success [1649174252437] [52091:542912] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174252437] [52091:542912] CHIP: [EM] Sending Standalone Ack for MessageCounter:13262706 on exchange 40878i [1649174252437] [52091:542912] CHIP: [IN] Prepared secure message 0x700007e0c4e0 to 0x0000000000000004 (1) of type 0x10 and protocolId (0, 0) on exchange 40878i with MessageCounter:3274791. [1649174252437] [52091:542912] CHIP: [IN] Sending encrypted msg 0x700007e0c4e0 with MessageCounter:3274791 to 0x0000000000000004 (1) at monotonic time: 00000000035B3C3C msec [1649174252437] [52091:542912] CHIP: [EM] Flushed pending ack for MessageCounter:13262706 on exchange 40878i [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the commissioner [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the controller [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the commissioner [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the controller [1649174252438] [52091:542909] CHIP: [IN] Expiring all connections for fabric 1!! [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the commissioner [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the controller [1649174252438] [52091:542909] CHIP: [IN] Expiring all connections for fabric 2!! [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the commissioner [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the controller [1649174252438] [52091:542909] CHIP: [IN] Expiring all connections for fabric 3!! [1649174252438] [52091:542909] CHIP: [CTL] Shutting down the System State, this will teardown the CHIP Stack [1649174252438] [52091:542909] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174252438] [52091:542909] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174252438] [52091:542909] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174252438] [52091:542909] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174252438] [52091:542909] CHIP: [DMG] All ReadHandler-s are clean, clear GlobalDirtySet [1649174252439] [52091:542909] CHIP: [BLE] CancelConnection [1649174252439] [52091:542909] CHIP: [IN] Clearing BLE pending packets. [1649174252439] [52091:542909] CHIP: [BLE] BtpEngine unsub failed [1649174252439] [52091:542909] CHIP: [BLE] Auto-closing end point's BLE connection. [1649174252439] [52091:542909] CHIP: [DL] Inet Layer shutdown [1649174252439] [52091:542909] CHIP: [DL] BLE shutdown [1649174252439] [52091:542909] CHIP: [DL] System Layer shutdown keanhinlim@Keans-Mac connectedhomeip % keanhinlim@Keans-Mac connectedhomeip % time ./out/debug/chip-tool onoff toggle 4 1 --paa-trust-store-path ./credentials/development/paa-root-certs [1649174271657] [52095:545396] CHIP: [DL] KVS will be written to: file:///tmp/chip_kvs [1649174271667] [52095:545396] CHIP: [DL] _Init [1649174271667] [52095:545396] CHIP: [IN] UDP::Init bind&listen port=0 [1649174271667] [52095:545396] CHIP: [IN] UDP::Init bound to port=52721 [1649174271667] [52095:545396] CHIP: [IN] UDP::Init bind&listen port=0 [1649174271667] [52095:545396] CHIP: [IN] UDP::Init bound to port=62939 [1649174271667] [52095:545396] CHIP: [IN] BLEBase::Init - setting/overriding transport [1649174271667] [52095:545396] CHIP: [IN] TransportMgr initialized [1649174271667] [52095:545396] CHIP: [DIS] Init fabric pairing table with server storage [1649174271668] [52095:545396] CHIP: [IN] Loading from storage for fabric index 1 [1649174271669] [52095:545396] CHIP: [IN] Loading from storage for fabric index 2 [1649174271669] [52095:545396] CHIP: [IN] Loading from storage for fabric index 3 [1649174271669] [52095:545396] CHIP: [DIS] Add fabric pairing table delegate [1649174271672] [52095:545396] CHIP: [ZCL] Using ZAP configuration... [1649174271672] [52095:545396] CHIP: [CTL] System State Initialized... [1649174271672] [52095:545396] CHIP: [CTL] Setting attestation nonce to random value [1649174271672] [52095:545396] CHIP: [CTL] Setting CSR nonce to random value [1649174271672] [52095:545396] CHIP: [CTL] Setting attestation nonce to random value [1649174271672] [52095:545396] CHIP: [CTL] Setting CSR nonce to random value [1649174271672] [52095:545396] CHIP: [CTL] Generating NOC [1649174271673] [52095:545396] CHIP: [DIS] Verifying the received credentials [1649174271673] [52095:545396] CHIP: [DIS] Added new fabric at index: 1, Initialized: 1 [1649174271673] [52095:545396] CHIP: [DIS] Assigned compressed fabric ID: 0x69C3DC2BC37CDB06, node ID: 0x000000000001B669 [1649174271673] [52095:545396] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x69C3DC2BC37CDB06 [1649174271673] [52095:545396] CHIP: [CTL] Setting attestation nonce to random value [1649174271673] [52095:545396] CHIP: [CTL] Setting CSR nonce to random value [1649174271673] [52095:545396] CHIP: [CTL] Generating NOC [1649174271674] [52095:545396] CHIP: [DIS] Verifying the received credentials [1649174271674] [52095:545396] CHIP: [DIS] Added new fabric at index: 2, Initialized: 1 [1649174271674] [52095:545396] CHIP: [DIS] Assigned compressed fabric ID: 0xB0301176A56E7A91, node ID: 0x000000000001B669 [1649174271674] [52095:545396] CHIP: [CTL] Joined the fabric at index 2. Compressed fabric ID is: 0xB0301176A56E7A91 [1649174271674] [52095:545396] CHIP: [CTL] Setting attestation nonce to random value [1649174271674] [52095:545396] CHIP: [CTL] Setting CSR nonce to random value [1649174271674] [52095:545396] CHIP: [CTL] Generating NOC [1649174271675] [52095:545396] CHIP: [DIS] Verifying the received credentials [1649174271675] [52095:545396] CHIP: [DIS] Added new fabric at index: 3, Initialized: 1 [1649174271675] [52095:545396] CHIP: [DIS] Assigned compressed fabric ID: 0x48793717F188D7BA, node ID: 0x000000000001B669 [1649174271675] [52095:545396] CHIP: [CTL] Joined the fabric at index 3. Compressed fabric ID is: 0x48793717F188D7BA [1649174271698] [52095:545397] CHIP: [DL] _OnPlatformEvent [1649174271698] [52095:545397] CHIP: [TOO] Sending command to node 0x4 [1649174271698] [52095:545397] CHIP: [CSM] FindOrEstablishSession: PeerId = 69C3DC2BC37CDB06:0000000000000004, NodeIdWasResolved = 0 [1649174271698] [52095:545397] CHIP: [CSM] FindOrEstablishSession: No existing session found [1649174271698] [52095:545397] CHIP: [DIS] Resolving 69C3DC2BC37CDB06:0000000000000004 ... [1649174271699] [52095:545398] CHIP: [DL] Resolved interface id: 7 [1649174271699] [52095:545398] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174271699] [52095:545398] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174271700] [52095:545398] CHIP: [DIS] Node ID resolved for 69C3DC2BC37CDB06:0000000000000004 [1649174271700] [52095:545398] CHIP: [DIS] Addr 0: [fe80::8eaa:b5ff:fe80:4b4c]:5540 [1649174271700] [52095:545398] CHIP: [DIS] Addr 1: [192.168.7.145]:5540 [1649174271700] [52095:545398] CHIP: [DIS] UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540: new best score: 3 [1649174271700] [52095:545398] CHIP: [DIS] UDP:192.168.7.145%en0:5540: score has not improved: 2 [1649174271700] [52095:545398] CHIP: [DIS] Checking node lookup status after 1 ms [1649174271700] [52095:545398] CHIP: [DIS] Keeping DNSSD lookup active [1649174271899] [52095:545398] CHIP: [DIS] Checking node lookup status after 201 ms [1649174271900] [52095:545398] CHIP: [CTL] Updating device address to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 while in state 1 [1649174271900] [52095:545398] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 1 --> 2 [1649174271901] [52095:545398] CHIP: [SC] Establishing CASE session to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 [1649174271901] [52095:545398] CHIP: [SC] RecoverInitiatorIpk: GroupDataProvider 0x7f77af09a8e0, Got IPK for FabricIndex 1 [1649174271901] [52095:545398] CHIP: [SC] 0xa9, 0x3d, 0xad, 0x9a, 0xbe, 0x9e, 0x7d, 0x41, [1649174271901] [52095:545398] CHIP: [SC] 0x08, 0x5d, 0xb3, 0xfc, 0xcb, 0xa0, 0x0f, 0x9e, [1649174271901] [52095:545398] CHIP: [SC] Including MRP parameters [1649174271902] [52095:545398] CHIP: [IN] Prepared unauthenticated message 0x7f77ae8c6468 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 60998i with MessageCounter:3971630463. [1649174271902] [52095:545398] CHIP: [IN] Sending unauthenticated msg 0x7f77ae8c6468 with MessageCounter:3971630463 to 0x0000000000000000 at monotonic time: 00000000035B8844 msec [1649174271902] [52095:545398] CHIP: [SC] Sent Sigma1 msg [1649174271902] [52095:545398] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 2 --> 3 [1649174271902] [52095:545398] CHIP: [DIS] Discovery does not require any more timeouts [1649174273068] [52095:545397] CHIP: [EM] Received message of type 0x31 with protocolId (0, 0) and MessageCounter:2300470095 on exchange 60998i [1649174273068] [52095:545397] CHIP: [EM] Found matching exchange: 60998i, Delegate: 0x7f77b2008238 [1649174273068] [52095:545397] CHIP: [EM] Rxd Ack; Removing MessageCounter:3971630463 from Retrans Table on exchange 60998i [1649174273068] [52095:545397] CHIP: [EM] Removed CHIP MessageCounter:3971630463 from RetransTable on exchange 60998i [1649174273068] [52095:545397] CHIP: [SC] Received Sigma2 msg [1649174273068] [52095:545397] CHIP: [SC] Peer assigned session session ID 4141 [1649174273069] [52095:545397] CHIP: [SC] The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1649174273070] [52095:545397] CHIP: [SC] Found MRP parameters in the message [1649174273070] [52095:545397] CHIP: [SC] Sending Sigma3 [1649174273071] [52095:545397] CHIP: [EM] Piggybacking Ack for MessageCounter:2300470095 on exchange: 60998i [1649174273071] [52095:545397] CHIP: [IN] Prepared unauthenticated message 0x7f77ae8c6468 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 60998i with MessageCounter:3971630464. [1649174273071] [52095:545397] CHIP: [IN] Sending unauthenticated msg 0x7f77ae8c6468 with MessageCounter:3971630464 to 0x0000000000000000 at monotonic time: 00000000035B8CD5 msec [1649174273071] [52095:545397] CHIP: [SC] Sent Sigma3 msg [1649174275271] [52095:545397] CHIP: [EM] Received message of type 0x40 with protocolId (0, 0) and MessageCounter:2300470096 on exchange 60998i [1649174275271] [52095:545397] CHIP: [EM] Found matching exchange: 60998i, Delegate: 0x7f77b2008238 [1649174275272] [52095:545397] CHIP: [EM] Rxd Ack; Removing MessageCounter:3971630464 from Retrans Table on exchange 60998i [1649174275272] [52095:545397] CHIP: [EM] Removed CHIP MessageCounter:3971630464 from RetransTable on exchange 60998i [1649174275272] [52095:545397] CHIP: [SC] Success status report received. Session was established [1649174275272] [52095:545397] CHIP: [IN] New secure session created for device 0x0000000000000004, LSID:56044 PSID:4141! [1649174275272] [52095:545397] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 3 --> 4 [1649174275272] [52095:545397] CHIP: [TOO] Sending cluster (0x00000006) command (0x00000002) on endpoint 1 [1649174275272] [52095:545397] CHIP: [DMG] ICR moving to [AddingComm] [1649174275273] [52095:545397] CHIP: [DMG] ICR moving to [AddedComma] [1649174275273] [52095:545397] CHIP: [IN] Prepared secure message 0x7f77ae8c6468 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 60999i with MessageCounter:1489587. [1649174275273] [52095:545397] CHIP: [IN] Sending encrypted msg 0x7f77ae8c6468 with MessageCounter:1489587 to 0x0000000000000004 (1) at monotonic time: 00000000035B9570 msec [1649174275273] [52095:545397] CHIP: [DMG] ICR moving to [CommandSen] [1649174275273] [52095:545397] CHIP: [EM] Sending Standalone Ack for MessageCounter:2300470096 on exchange 60998i [1649174275274] [52095:545397] CHIP: [IN] Prepared unauthenticated message 0x7000025024e0 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 60998i with MessageCounter:3971630465. [1649174275274] [52095:545397] CHIP: [IN] Sending unauthenticated msg 0x7000025024e0 with MessageCounter:3971630465 to 0x0000000000000000 at monotonic time: 00000000035B9570 msec [1649174275274] [52095:545397] CHIP: [EM] Flushed pending ack for MessageCounter:2300470096 on exchange 60998i [1649174275724] [52095:545398] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5226639 on exchange 60999i [1649174275724] [52095:545398] CHIP: [EM] Found matching exchange: 60999i, Delegate: 0x7f77ae795f20 [1649174275724] [52095:545398] CHIP: [EM] Rxd Ack; Removing MessageCounter:1489587 from Retrans Table on exchange 60999i [1649174275724] [52095:545398] CHIP: [EM] Removed CHIP MessageCounter:1489587 from RetransTable on exchange 60999i [1649174275724] [52095:545398] CHIP: [DMG] ICR moving to [ResponseRe] [1649174275724] [52095:545398] CHIP: [DMG] InvokeResponseMessage = [1649174275724] [52095:545398] CHIP: [DMG] { [1649174275724] [52095:545398] CHIP: [DMG] suppressResponse = false, [1649174275724] [52095:545398] CHIP: [DMG] InvokeResponseIBs = [1649174275724] [52095:545398] CHIP: [DMG] [ [1649174275724] [52095:545398] CHIP: [DMG] InvokeResponseIB = [1649174275724] [52095:545398] CHIP: [DMG] { [1649174275724] [52095:545398] CHIP: [DMG] CommandStatusIB = [1649174275724] [52095:545398] CHIP: [DMG] { [1649174275724] [52095:545398] CHIP: [DMG] CommandPathIB = [1649174275724] [52095:545398] CHIP: [DMG] { [1649174275724] [52095:545398] CHIP: [DMG] EndpointId = 0x1, [1649174275724] [52095:545398] CHIP: [DMG] ClusterId = 0x6, [1649174275724] [52095:545398] CHIP: [DMG] CommandId = 0x2, [1649174275724] [52095:545398] CHIP: [DMG] }, [1649174275724] [52095:545398] CHIP: [DMG] [1649174275724] [52095:545398] CHIP: [DMG] StatusIB = [1649174275724] [52095:545398] CHIP: [DMG] { [1649174275724] [52095:545398] CHIP: [DMG] status = 0x00 (SUCCESS), [1649174275724] [52095:545398] CHIP: [DMG] }, [1649174275724] [52095:545398] CHIP: [DMG] [1649174275724] [52095:545398] CHIP: [DMG] }, [1649174275724] [52095:545398] CHIP: [DMG] [1649174275724] [52095:545398] CHIP: [DMG] }, [1649174275724] [52095:545398] CHIP: [DMG] [1649174275724] [52095:545398] CHIP: [DMG] ], [1649174275724] [52095:545398] CHIP: [DMG] [1649174275724] [52095:545398] CHIP: [DMG] InteractionModelRevision = 1 [1649174275724] [52095:545398] CHIP: [DMG] }, [1649174275724] [52095:545398] CHIP: [DMG] Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0 [1649174275724] [52095:545398] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174275724] [52095:545398] CHIP: [EM] Sending Standalone Ack for MessageCounter:5226639 on exchange 60999i [1649174275724] [52095:545398] CHIP: [IN] Prepared secure message 0x7000025854e0 to 0x0000000000000004 (1) of type 0x10 and protocolId (0, 0) on exchange 60999i with MessageCounter:1489588. [1649174275724] [52095:545398] CHIP: [IN] Sending encrypted msg 0x7000025854e0 with MessageCounter:1489588 to 0x0000000000000004 (1) at monotonic time: 00000000035B9733 msec [1649174275724] [52095:545398] CHIP: [EM] Flushed pending ack for MessageCounter:5226639 on exchange 60999i [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the commissioner [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the controller [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the commissioner [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the controller [1649174275725] [52095:545396] CHIP: [IN] Expiring all connections for fabric 1!! [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the commissioner [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the controller [1649174275725] [52095:545396] CHIP: [IN] Expiring all connections for fabric 2!! [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the commissioner [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the controller [1649174275725] [52095:545396] CHIP: [IN] Expiring all connections for fabric 3!! [1649174275725] [52095:545396] CHIP: [CTL] Shutting down the System State, this will teardown the CHIP Stack [1649174275725] [52095:545396] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174275725] [52095:545396] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174275725] [52095:545396] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174275725] [52095:545396] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174275725] [52095:545396] CHIP: [DMG] All ReadHandler-s are clean, clear GlobalDirtySet [1649174275725] [52095:545396] CHIP: [BLE] CancelConnection [1649174275725] [52095:545396] CHIP: [DL] Inet Layer shutdown [1649174275725] [52095:545396] CHIP: [DL] BLE shutdown [1649174275725] [52095:545396] CHIP: [DL] System Layer shutdown ./out/debug/chip-tool onoff toggle 4 1 --paa-trust-store-path 0.18s user 0.04s system 5% cpu 4.251 total keanhinlim@Keans-Mac connectedhomeip % keanhinlim@Keans-Mac connectedhomeip % keanhinlim@Keans-Mac connectedhomeip % ./out/debug/chip-tool pairing open-commissioning-window 4 1 600 1000 3840 --paa-trust-store-path ./credentials/development/paa-root-certs [1649174288684] [52126:545917] CHIP: [DL] KVS will be written to: file:///tmp/chip_kvs [1649174288693] [52126:545917] CHIP: [DL] _Init [1649174288693] [52126:545917] CHIP: [IN] UDP::Init bind&listen port=0 [1649174288693] [52126:545917] CHIP: [IN] UDP::Init bound to port=54121 [1649174288693] [52126:545917] CHIP: [IN] UDP::Init bind&listen port=0 [1649174288693] [52126:545917] CHIP: [IN] UDP::Init bound to port=50886 [1649174288693] [52126:545917] CHIP: [IN] BLEBase::Init - setting/overriding transport [1649174288693] [52126:545917] CHIP: [IN] TransportMgr initialized [1649174288693] [52126:545917] CHIP: [DIS] Init fabric pairing table with server storage [1649174288693] [52126:545917] CHIP: [IN] Loading from storage for fabric index 1 [1649174288694] [52126:545917] CHIP: [IN] Loading from storage for fabric index 2 [1649174288694] [52126:545917] CHIP: [IN] Loading from storage for fabric index 3 [1649174288695] [52126:545917] CHIP: [DIS] Add fabric pairing table delegate [1649174288697] [52126:545917] CHIP: [ZCL] Using ZAP configuration... [1649174288697] [52126:545917] CHIP: [CTL] System State Initialized... [1649174288697] [52126:545917] CHIP: [CTL] Setting attestation nonce to random value [1649174288697] [52126:545917] CHIP: [CTL] Setting CSR nonce to random value [1649174288697] [52126:545917] CHIP: [CTL] Setting attestation nonce to random value [1649174288697] [52126:545917] CHIP: [CTL] Setting CSR nonce to random value [1649174288698] [52126:545917] CHIP: [CTL] Generating NOC [1649174288698] [52126:545917] CHIP: [DIS] Verifying the received credentials [1649174288698] [52126:545917] CHIP: [DIS] Added new fabric at index: 1, Initialized: 1 [1649174288698] [52126:545917] CHIP: [DIS] Assigned compressed fabric ID: 0x69C3DC2BC37CDB06, node ID: 0x000000000001B669 [1649174288698] [52126:545917] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x69C3DC2BC37CDB06 [1649174288698] [52126:545917] CHIP: [CTL] Setting attestation nonce to random value [1649174288698] [52126:545917] CHIP: [CTL] Setting CSR nonce to random value [1649174288699] [52126:545917] CHIP: [CTL] Generating NOC [1649174288699] [52126:545917] CHIP: [DIS] Verifying the received credentials [1649174288699] [52126:545917] CHIP: [DIS] Added new fabric at index: 2, Initialized: 1 [1649174288699] [52126:545917] CHIP: [DIS] Assigned compressed fabric ID: 0xB0301176A56E7A91, node ID: 0x000000000001B669 [1649174288699] [52126:545917] CHIP: [CTL] Joined the fabric at index 2. Compressed fabric ID is: 0xB0301176A56E7A91 [1649174288699] [52126:545917] CHIP: [CTL] Setting attestation nonce to random value [1649174288699] [52126:545917] CHIP: [CTL] Setting CSR nonce to random value [1649174288700] [52126:545917] CHIP: [CTL] Generating NOC [1649174288700] [52126:545917] CHIP: [DIS] Verifying the received credentials [1649174288700] [52126:545917] CHIP: [DIS] Added new fabric at index: 3, Initialized: 1 [1649174288700] [52126:545917] CHIP: [DIS] Assigned compressed fabric ID: 0x48793717F188D7BA, node ID: 0x000000000001B669 [1649174288700] [52126:545917] CHIP: [CTL] Joined the fabric at index 3. Compressed fabric ID is: 0x48793717F188D7BA [1649174288722] [52126:545918] CHIP: [DL] _OnPlatformEvent [1649174288724] [52126:545918] CHIP: [CSM] FindOrEstablishSession: PeerId = 69C3DC2BC37CDB06:0000000000000004, NodeIdWasResolved = 0 [1649174288724] [52126:545918] CHIP: [CSM] FindOrEstablishSession: No existing session found [1649174288724] [52126:545918] CHIP: [DIS] Resolving 69C3DC2BC37CDB06:0000000000000004 ... [1649174288724] [52126:545918] CHIP: [DL] Resolved interface id: 7 [1649174288725] [52126:545918] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174288725] [52126:545918] CHIP: [DL] Mdns: OnGetAddrInfo hostname:8CAAB5804B4C.local. [1649174288725] [52126:545918] CHIP: [DIS] Node ID resolved for 69C3DC2BC37CDB06:0000000000000004 [1649174288725] [52126:545918] CHIP: [DIS] Addr 0: [fe80::8eaa:b5ff:fe80:4b4c]:5540 [1649174288725] [52126:545918] CHIP: [DIS] Addr 1: [192.168.7.145]:5540 [1649174288725] [52126:545918] CHIP: [DIS] UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540: new best score: 3 [1649174288725] [52126:545918] CHIP: [DIS] UDP:192.168.7.145%en0:5540: score has not improved: 2 [1649174288725] [52126:545918] CHIP: [DIS] Checking node lookup status after 2 ms [1649174288725] [52126:545918] CHIP: [DIS] Keeping DNSSD lookup active [1649174288924] [52126:545918] CHIP: [DIS] Checking node lookup status after 201 ms [1649174288925] [52126:545918] CHIP: [CTL] Updating device address to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 while in state 1 [1649174288925] [52126:545918] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 1 --> 2 [1649174288925] [52126:545918] CHIP: [SC] Establishing CASE session to UDP:[fe80::8eaa:b5ff:fe80:4b4c%en0]:5540 [1649174288926] [52126:545918] CHIP: [SC] RecoverInitiatorIpk: GroupDataProvider 0x7f99c070d9d0, Got IPK for FabricIndex 1 [1649174288926] [52126:545918] CHIP: [SC] 0xa9, 0x3d, 0xad, 0x9a, 0xbe, 0x9e, 0x7d, 0x41, [1649174288926] [52126:545918] CHIP: [SC] 0x08, 0x5d, 0xb3, 0xfc, 0xcb, 0xa0, 0x0f, 0x9e, [1649174288926] [52126:545918] CHIP: [SC] Including MRP parameters [1649174288926] [52126:545918] CHIP: [IN] Prepared unauthenticated message 0x7f99c2238668 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 45305i with MessageCounter:3861627158. [1649174288926] [52126:545918] CHIP: [IN] Sending unauthenticated msg 0x7f99c2238668 with MessageCounter:3861627158 to 0x0000000000000000 at monotonic time: 00000000035BCAC5 msec [1649174288927] [52126:545918] CHIP: [SC] Sent Sigma1 msg [1649174288927] [52126:545918] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 2 --> 3 [1649174288927] [52126:545918] CHIP: [DIS] Discovery does not require any more timeouts [1649174290072] [52126:545918] CHIP: [EM] Received message of type 0x31 with protocolId (0, 0) and MessageCounter:2300470097 on exchange 45305i [1649174290072] [52126:545918] CHIP: [EM] Found matching exchange: 45305i, Delegate: 0x7f99c281d638 [1649174290072] [52126:545918] CHIP: [EM] Rxd Ack; Removing MessageCounter:3861627158 from Retrans Table on exchange 45305i [1649174290072] [52126:545918] CHIP: [EM] Removed CHIP MessageCounter:3861627158 from RetransTable on exchange 45305i [1649174290072] [52126:545918] CHIP: [SC] Received Sigma2 msg [1649174290072] [52126:545918] CHIP: [SC] Peer assigned session session ID 4142 [1649174290073] [52126:545918] CHIP: [SC] The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1649174290074] [52126:545918] CHIP: [SC] Found MRP parameters in the message [1649174290074] [52126:545918] CHIP: [SC] Sending Sigma3 [1649174290075] [52126:545918] CHIP: [EM] Piggybacking Ack for MessageCounter:2300470097 on exchange: 45305i [1649174290075] [52126:545918] CHIP: [IN] Prepared unauthenticated message 0x7f99c2238668 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 45305i with MessageCounter:3861627159. [1649174290075] [52126:545918] CHIP: [IN] Sending unauthenticated msg 0x7f99c2238668 with MessageCounter:3861627159 to 0x0000000000000000 at monotonic time: 00000000035BCF41 msec [1649174290075] [52126:545918] CHIP: [SC] Sent Sigma3 msg [1649174292270] [52126:545918] CHIP: [EM] Received message of type 0x40 with protocolId (0, 0) and MessageCounter:2300470098 on exchange 45305i [1649174292270] [52126:545918] CHIP: [EM] Found matching exchange: 45305i, Delegate: 0x7f99c281d638 [1649174292270] [52126:545918] CHIP: [EM] Rxd Ack; Removing MessageCounter:3861627159 from Retrans Table on exchange 45305i [1649174292270] [52126:545918] CHIP: [EM] Removed CHIP MessageCounter:3861627159 from RetransTable on exchange 45305i [1649174292270] [52126:545918] CHIP: [SC] Success status report received. Session was established [1649174292270] [52126:545918] CHIP: [IN] New secure session created for device 0x0000000000000004, LSID:49978 PSID:4142! [1649174292270] [52126:545918] CHIP: [CTL] OperationalDeviceProxy[69C3DC2BC37CDB06:0000000000000004]: State change 3 --> 4 [1649174292270] [52126:545918] CHIP: [DMG] SendReadRequest ReadClient[0x6000001f8690]: Sending Read Request [1649174292271] [52126:545918] CHIP: [IN] Prepared secure message 0x7f99c2238668 to 0x0000000000000004 (1) of type 0x2 and protocolId (0, 1) on exchange 45306i with MessageCounter:8251757. [1649174292271] [52126:545918] CHIP: [IN] Sending encrypted msg 0x7f99c2238668 with MessageCounter:8251757 to 0x0000000000000004 (1) at monotonic time: 00000000035BD7D5 msec [1649174292271] [52126:545918] CHIP: [DMG] MoveToState ReadClient[0x6000001f8690]: Moving to [AwaitingIn] [1649174292271] [52126:545918] CHIP: [EM] Sending Standalone Ack for MessageCounter:2300470098 on exchange 45305i [1649174292271] [52126:545918] CHIP: [IN] Prepared unauthenticated message 0x70000b2134e0 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 45305i with MessageCounter:3861627160. [1649174292271] [52126:545918] CHIP: [IN] Sending unauthenticated msg 0x70000b2134e0 with MessageCounter:3861627160 to 0x0000000000000000 at monotonic time: 00000000035BD7D5 msec [1649174292271] [52126:545918] CHIP: [EM] Flushed pending ack for MessageCounter:2300470098 on exchange 45305i [1649174292577] [52126:545919] CHIP: [EM] Received message of type 0x5 with protocolId (0, 1) and MessageCounter:7015384 on exchange 45306i [1649174292577] [52126:545919] CHIP: [EM] Found matching exchange: 45306i, Delegate: 0x6000001f8690 [1649174292577] [52126:545919] CHIP: [EM] Rxd Ack; Removing MessageCounter:8251757 from Retrans Table on exchange 45306i [1649174292577] [52126:545919] CHIP: [EM] Removed CHIP MessageCounter:8251757 from RetransTable on exchange 45306i [1649174292578] [52126:545919] CHIP: [DMG] ReportDataMessage = [1649174292578] [52126:545919] CHIP: [DMG] { [1649174292578] [52126:545919] CHIP: [DMG] AttributeReportIBs = [1649174292578] [52126:545919] CHIP: [DMG] [ [1649174292578] [52126:545919] CHIP: [DMG] AttributeReportIB = [1649174292578] [52126:545919] CHIP: [DMG] { [1649174292578] [52126:545919] CHIP: [DMG] AttributeDataIB = [1649174292578] [52126:545919] CHIP: [DMG] { [1649174292578] [52126:545919] CHIP: [DMG] DataVersion = 0x87880af4, [1649174292578] [52126:545919] CHIP: [DMG] AttributePathIB = [1649174292578] [52126:545919] CHIP: [DMG] { [1649174292578] [52126:545919] CHIP: [DMG] Endpoint = 0x0, [1649174292578] [52126:545919] CHIP: [DMG] Cluster = 0x28, [1649174292578] [52126:545919] CHIP: [DMG] Attribute = 0x0000_0002, [1649174292578] [52126:545919] CHIP: [DMG] } [1649174292578] [52126:545919] CHIP: [DMG] [1649174292578] [52126:545919] CHIP: [DMG] Data = 65521, [1649174292578] [52126:545919] CHIP: [DMG] }, [1649174292578] [52126:545919] CHIP: [DMG] [1649174292578] [52126:545919] CHIP: [DMG] }, [1649174292578] [52126:545919] CHIP: [DMG] [1649174292578] [52126:545919] CHIP: [DMG] ], [1649174292578] [52126:545919] CHIP: [DMG] [1649174292578] [52126:545919] CHIP: [DMG] SuppressResponse = true, [1649174292578] [52126:545919] CHIP: [DMG] InteractionModelRevision = 1 [1649174292578] [52126:545919] CHIP: [DMG] } [1649174292578] [52126:545919] CHIP: [CTL] Received VID for the device. Value 65521 [1649174292578] [52126:545919] CHIP: [CSM] FindOrEstablishSession: PeerId = 69C3DC2BC37CDB06:0000000000000004, NodeIdWasResolved = 0 [1649174292578] [52126:545919] CHIP: [DMG] SendReadRequest ReadClient[0x6000001f0000]: Sending Read Request [1649174292578] [52126:545919] CHIP: [IN] Prepared secure message 0x7f99c2238668 to 0x0000000000000004 (1) of type 0x2 and protocolId (0, 1) on exchange 45307i with MessageCounter:8251758. [1649174292578] [52126:545919] CHIP: [IN] Sending encrypted msg 0x7f99c2238668 with MessageCounter:8251758 to 0x0000000000000004 (1) at monotonic time: 00000000035BD909 msec [1649174292579] [52126:545919] CHIP: [DMG] MoveToState ReadClient[0x6000001f0000]: Moving to [AwaitingIn] [1649174292579] [52126:545919] CHIP: [EM] Sending Standalone Ack for MessageCounter:7015384 on exchange 45306i [1649174292579] [52126:545919] CHIP: [IN] Prepared secure message 0x70000b2964e0 to 0x0000000000000004 (1) of type 0x10 and protocolId (0, 0) on exchange 45306i with MessageCounter:8251759. [1649174292579] [52126:545919] CHIP: [IN] Sending encrypted msg 0x70000b2964e0 with MessageCounter:8251759 to 0x0000000000000004 (1) at monotonic time: 00000000035BD909 msec [1649174292579] [52126:545919] CHIP: [EM] Flushed pending ack for MessageCounter:7015384 on exchange 45306i [1649174292883] [52126:545918] CHIP: [EM] Received message of type 0x5 with protocolId (0, 1) and MessageCounter:7015385 on exchange 45307i [1649174292883] [52126:545918] CHIP: [EM] Found matching exchange: 45307i, Delegate: 0x6000001f0000 [1649174292883] [52126:545918] CHIP: [EM] Rxd Ack; Removing MessageCounter:8251758 from Retrans Table on exchange 45307i [1649174292883] [52126:545918] CHIP: [EM] Removed CHIP MessageCounter:8251758 from RetransTable on exchange 45307i [1649174292883] [52126:545918] CHIP: [DMG] ReportDataMessage = [1649174292883] [52126:545918] CHIP: [DMG] { [1649174292883] [52126:545918] CHIP: [DMG] AttributeReportIBs = [1649174292883] [52126:545918] CHIP: [DMG] [ [1649174292883] [52126:545918] CHIP: [DMG] AttributeReportIB = [1649174292883] [52126:545918] CHIP: [DMG] { [1649174292883] [52126:545918] CHIP: [DMG] AttributeDataIB = [1649174292883] [52126:545918] CHIP: [DMG] { [1649174292883] [52126:545918] CHIP: [DMG] DataVersion = 0x87880af4, [1649174292883] [52126:545918] CHIP: [DMG] AttributePathIB = [1649174292883] [52126:545918] CHIP: [DMG] { [1649174292883] [52126:545918] CHIP: [DMG] Endpoint = 0x0, [1649174292883] [52126:545918] CHIP: [DMG] Cluster = 0x28, [1649174292883] [52126:545918] CHIP: [DMG] Attribute = 0x0000_0004, [1649174292883] [52126:545918] CHIP: [DMG] } [1649174292883] [52126:545918] CHIP: [DMG] [1649174292883] [52126:545918] CHIP: [DMG] Data = 32769, [1649174292883] [52126:545918] CHIP: [DMG] }, [1649174292883] [52126:545918] CHIP: [DMG] [1649174292883] [52126:545918] CHIP: [DMG] }, [1649174292883] [52126:545918] CHIP: [DMG] [1649174292883] [52126:545918] CHIP: [DMG] ], [1649174292883] [52126:545918] CHIP: [DMG] [1649174292883] [52126:545918] CHIP: [DMG] SuppressResponse = true, [1649174292883] [52126:545918] CHIP: [DMG] InteractionModelRevision = 1 [1649174292883] [52126:545918] CHIP: [DMG] } [1649174292883] [52126:545918] CHIP: [CTL] Received PID for the device. Value 32769 [1649174292883] [52126:545918] CHIP: [CSM] FindOrEstablishSession: PeerId = 69C3DC2BC37CDB06:0000000000000004, NodeIdWasResolved = 0 [1649174292883] [52126:545918] CHIP: [CTL] OpenCommissioningWindow for device ID 4 [1649174292883] [52126:545918] CHIP: [DMG] ICR moving to [AddingComm] [1649174292883] [52126:545918] CHIP: [DMG] ICR moving to [AddedComma] [1649174292884] [52126:545918] CHIP: [IN] Prepared secure message 0x7f99c2238668 to 0x0000000000000004 (1) of type 0xa and protocolId (0, 1) on exchange 45308i with MessageCounter:8251760. [1649174292884] [52126:545918] CHIP: [IN] Sending encrypted msg 0x7f99c2238668 with MessageCounter:8251760 to 0x0000000000000004 (1) at monotonic time: 00000000035BDA3A msec [1649174292884] [52126:545918] CHIP: [DMG] ICR moving to [AwaitingTi] [1649174292885] [52126:545918] CHIP: [CTL] Manual pairing code: [36403511353] [1649174292885] [52126:545918] CHIP: [CTL] SetupQRCode: [MT:-24J0AFN00CQSP7ZE00] [1649174292885] [52126:545918] CHIP: [EM] Sending Standalone Ack for MessageCounter:7015385 on exchange 45307i [1649174292885] [52126:545918] CHIP: [IN] Prepared secure message 0x70000b2134e0 to 0x0000000000000004 (1) of type 0x10 and protocolId (0, 0) on exchange 45307i with MessageCounter:8251761. [1649174292885] [52126:545918] CHIP: [IN] Sending encrypted msg 0x70000b2134e0 with MessageCounter:8251761 to 0x0000000000000004 (1) at monotonic time: 00000000035BDA3B msec [1649174292885] [52126:545918] CHIP: [EM] Flushed pending ack for MessageCounter:7015385 on exchange 45307i [1649174293028] [52126:545918] CHIP: [EM] Received message of type 0x1 with protocolId (0, 1) and MessageCounter:7015386 on exchange 45308i [1649174293028] [52126:545918] CHIP: [EM] Found matching exchange: 45308i, Delegate: 0x7f99c1386aa0 [1649174293028] [52126:545918] CHIP: [EM] Rxd Ack; Removing MessageCounter:8251760 from Retrans Table on exchange 45308i [1649174293028] [52126:545918] CHIP: [EM] Removed CHIP MessageCounter:8251760 from RetransTable on exchange 45308i [1649174293029] [52126:545918] CHIP: [DMG] StatusResponseMessage = [1649174293029] [52126:545918] CHIP: [DMG] { [1649174293029] [52126:545918] CHIP: [DMG] Status = 0x0, [1649174293029] [52126:545918] CHIP: [DMG] InteractionModelRevision = 1 [1649174293029] [52126:545918] CHIP: [DMG] } [1649174293029] [52126:545918] CHIP: [IM] Received status response, status is 0x00 (SUCCESS) [1649174293029] [52126:545918] CHIP: [EM] Piggybacking Ack for MessageCounter:7015386 on exchange: 45308i [1649174293029] [52126:545918] CHIP: [IN] Prepared secure message 0x7f99c2238668 to 0x0000000000000004 (1) of type 0x8 and protocolId (0, 1) on exchange 45308i with MessageCounter:8251762. [1649174293029] [52126:545918] CHIP: [IN] Sending encrypted msg 0x7f99c2238668 with MessageCounter:8251762 to 0x0000000000000004 (1) at monotonic time: 00000000035BDACB msec [1649174293029] [52126:545918] CHIP: [DMG] ICR moving to [CommandSen] [1649174293448] [52126:545918] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:7015387 on exchange 45308i [1649174293448] [52126:545918] CHIP: [EM] Found matching exchange: 45308i, Delegate: 0x7f99c1386aa0 [1649174293448] [52126:545918] CHIP: [EM] Rxd Ack; Removing MessageCounter:8251762 from Retrans Table on exchange 45308i [1649174293448] [52126:545918] CHIP: [EM] Removed CHIP MessageCounter:8251762 from RetransTable on exchange 45308i [1649174293448] [52126:545918] CHIP: [DMG] ICR moving to [ResponseRe] [1649174293448] [52126:545918] CHIP: [DMG] InvokeResponseMessage = [1649174293448] [52126:545918] CHIP: [DMG] { [1649174293448] [52126:545918] CHIP: [DMG] suppressResponse = false, [1649174293448] [52126:545918] CHIP: [DMG] InvokeResponseIBs = [1649174293448] [52126:545918] CHIP: [DMG] [ [1649174293448] [52126:545918] CHIP: [DMG] InvokeResponseIB = [1649174293448] [52126:545918] CHIP: [DMG] { [1649174293448] [52126:545918] CHIP: [DMG] CommandStatusIB = [1649174293448] [52126:545918] CHIP: [DMG] { [1649174293448] [52126:545918] CHIP: [DMG] CommandPathIB = [1649174293448] [52126:545918] CHIP: [DMG] { [1649174293448] [52126:545918] CHIP: [DMG] EndpointId = 0x0, [1649174293448] [52126:545918] CHIP: [DMG] ClusterId = 0x3c, [1649174293448] [52126:545918] CHIP: [DMG] CommandId = 0x0, [1649174293448] [52126:545918] CHIP: [DMG] }, [1649174293448] [52126:545918] CHIP: [DMG] [1649174293448] [52126:545918] CHIP: [DMG] StatusIB = [1649174293448] [52126:545918] CHIP: [DMG] { [1649174293448] [52126:545918] CHIP: [DMG] status = 0x00 (SUCCESS), [1649174293448] [52126:545918] CHIP: [DMG] }, [1649174293449] [52126:545918] CHIP: [DMG] [1649174293449] [52126:545918] CHIP: [DMG] }, [1649174293449] [52126:545918] CHIP: [DMG] [1649174293449] [52126:545918] CHIP: [DMG] }, [1649174293449] [52126:545918] CHIP: [DMG] [1649174293449] [52126:545918] CHIP: [DMG] ], [1649174293449] [52126:545918] CHIP: [DMG] [1649174293449] [52126:545918] CHIP: [DMG] InteractionModelRevision = 1 [1649174293449] [52126:545918] CHIP: [DMG] }, [1649174293449] [52126:545918] CHIP: [DMG] Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1649174293449] [52126:545918] CHIP: [CTL] Successfully opened pairing window on the device [1649174293449] [52126:545918] CHIP: [DMG] ICR moving to [AwaitingDe] [1649174293449] [52126:545918] CHIP: [EM] Sending Standalone Ack for MessageCounter:7015387 on exchange 45308i [1649174293449] [52126:545918] CHIP: [IN] Prepared secure message 0x70000b2134e0 to 0x0000000000000004 (1) of type 0x10 and protocolId (0, 0) on exchange 45308i with MessageCounter:8251763. [1649174293449] [52126:545918] CHIP: [IN] Sending encrypted msg 0x70000b2134e0 with MessageCounter:8251763 to 0x0000000000000004 (1) at monotonic time: 00000000035BDC6F msec [1649174293449] [52126:545918] CHIP: [EM] Flushed pending ack for MessageCounter:7015387 on exchange 45308i [1649174293449] [52126:545917] CHIP: [CTL] Shutting down the commissioner [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the controller [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the commissioner [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the controller [1649174293450] [52126:545917] CHIP: [IN] Expiring all connections for fabric 1!! [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the commissioner [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the controller [1649174293450] [52126:545917] CHIP: [IN] Expiring all connections for fabric 2!! [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the commissioner [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the controller [1649174293450] [52126:545917] CHIP: [IN] Expiring all connections for fabric 3!! [1649174293450] [52126:545917] CHIP: [CTL] Shutting down the System State, this will teardown the CHIP Stack [1649174293450] [52126:545917] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174293450] [52126:545917] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174293450] [52126:545917] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174293450] [52126:545917] CHIP: [DMG] IM WH moving to [Uninitialized] [1649174293450] [52126:545917] CHIP: [DMG] All ReadHandler-s are clean, clear GlobalDirtySet [1649174293450] [52126:545917] CHIP: [BLE] CancelConnection [1649174293450] [52126:545917] CHIP: [DL] Inet Layer shutdown [1649174293450] [52126:545917] CHIP: [DL] BLE shutdown [1649174293450] [52126:545917] CHIP: [DL] System Layer shutdown