ubuntu@ubuntu:~/apps$ ./chip-tool pairing ble-thread 1 hex:0e08000000000001000035060004001fffe00708fd7bcb94a212d2600c0402a0f7f8051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f0410445f2b5ca6f2a93a55ce570a70efeecb000300000f0208111111112222222201021234 92646874 3423 --paa-trust-store-path /var/paa-root-certs/ [1745220770.508307][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1745220770.510096][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1745220770.510145][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1745220770.515389][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1745220770.515649][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1745220770.515766][6511:6511] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1745220770.516104][6511:6511] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-FyZlrq) [1745220770.516696][6511:6511] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745220770.516751][6511:6511] CHIP:DL: NVS set: chip-counters/reboot-count = 257 (0x101) [1745220770.517615][6511:6511] CHIP:DL: Got Ethernet interface: eth0 [1745220770.518209][6511:6511] CHIP:DL: Found the primary Ethernet interface:eth0 [1745220770.518837][6511:6511] CHIP:DL: Got WiFi interface: wlan0 [1745220770.518904][6511:6511] CHIP:DL: Failed to reset WiFi statistic counts [1745220770.518956][6511:6511] CHIP:IN: UDP::Init bind&listen port=0 [1745220770.519062][6511:6511] CHIP:IN: UDP::Init bound to port=34701 [1745220770.519083][6511:6511] CHIP:IN: BLEBase::Init - setting/overriding transport [1745220770.519099][6511:6511] CHIP:IN: TransportMgr initialized [1745220770.519149][6511:6511] CHIP:FP: Initializing FabricTable from persistent storage [1745220770.519501][6511:6511] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745220770.521486][6511:6511] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1CB8E8FD2A1604E0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.522324][6511:6511] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE7FC514BD95AD5D2, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.523114][6511:6511] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x831C65382602B3B5, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.523902][6511:6511] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xD9D01CB0D050EB4D, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.524662][6511:6511] CHIP:FP: Fabric index 0x5 was retrieved from storage. Compressed FabricId 0x0B7BB6E8F0F51EC7, FabricId 0x0000000000000005, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.525430][6511:6511] CHIP:FP: Fabric index 0x6 was retrieved from storage. Compressed FabricId 0x46A3CEF59284B985, FabricId 0x0000000000000006, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220770.530270][6511:6511] CHIP:ZCL: Using ZAP configuration... [1745220770.533806][6511:6511] CHIP:DL: Avahi client registered [1745220770.533927][6511:6511] CHIP:CTL: System State Initialized... [1745220770.903577][6511:6511] CHIP:CTL: Setting attestation nonce to random value [1745220770.903667][6511:6511] CHIP:CTL: Setting CSR nonce to random value [1745220770.903741][6511:6511] CHIP:IN: UDP::Init bind&listen port=5550 [1745220770.903861][6511:6511] CHIP:IN: UDP::Init bound to port=5550 [1745220770.903881][6511:6511] CHIP:IN: TransportMgr initialized [1745220770.904137][6511:6513] CHIP:DL: CHIP task running [1745220770.904319][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1745220770.904625][6511:6513] CHIP:CTL: Setting attestation nonce to random value [1745220770.904776][6511:6513] CHIP:CTL: Setting CSR nonce to random value [1745220770.905530][6511:6513] CHIP:CTL: Generating NOC [1745220770.906952][6511:6513] CHIP:FP: Validating NOC chain [1745220770.908563][6511:6513] CHIP:FP: NOC chain validation successful [1745220770.908715][6511:6513] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1745220770.908744][6511:6513] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745220770.908764][6511:6513] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1745220770.908781][6511:6513] CHIP:TS: Retaining current Last Known Good Time [1745220770.922697][6511:6513] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1745220770.926828][6511:6513] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1745220770.931224][6511:6513] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1CB8E8FD2A1604E0) [1745220770.931281][6511:6513] CHIP:IN: UDP::Init bind&listen port=5550 [1745220770.931389][6511:6513] CHIP:IN: UDP::Init bound to port=5550 [1745220770.931410][6511:6513] CHIP:IN: TransportMgr initialized [1745220770.964921][6511:6513] CHIP:CTL: Setting thread operational dataset from parameters [1745220770.964967][6511:6513] CHIP:CTL: Setting attestation nonce to random value [1745220770.965003][6511:6513] CHIP:CTL: Setting CSR nonce to random value [1745220770.965033][6511:6513] CHIP:CTL: Checking ICD registration parameters [1745220770.965059][6511:6513] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1745220770.976628][6511:6513] CHIP:DL: BlueZ integration init success [1745220770.983872][6511:6512] CHIP:BLE: BLE removing known devices. [1745220770.985717][6511:6512] CHIP:BLE: BLE initiating scan. [1745220770.988589][6511:6513] CHIP:BLE: ChipDeviceScanner has started scanning! [1745220771.003323][6511:6512] CHIP:BLE: New device scanned: EC:74:A1:89:2E:2A [1745220771.003397][6511:6512] CHIP:BLE: Device discriminator match. Attempting to connect. [1745220771.008197][6511:6512] CHIP:BLE: ChipDeviceScanner has stopped scanning! [1745220771.372242][6511:6512] CHIP:DL: FAIL: ConnectDevice: GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36) [1745220771.372339][6511:6512] CHIP:DL: ConnectDevice retry: 1 out of 4 [1745220771.540914][6511:6512] CHIP:DL: ConnectDevice complete [1745220771.541021][6511:6512] CHIP:BLE: New device connected: EC:74:A1:89:2E:2A [1745220773.649532][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649590][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649619][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649641][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649665][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649686][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649712][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0011 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649732][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0011 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649754][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0011 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649773][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0011 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649796][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service000c on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649815][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service000c on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649840][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0001 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649861][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0001 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649888][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649908][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0017 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649929][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0024 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649950][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0024 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649971][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.649994][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.650015][6511:6512] CHIP:DL: Char /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 on service /org/bluez/hci0/dev_EC_74_A1_89_2E_2A/service0028 [1745220773.650065][6511:6512] CHIP:DL: New BLE connection: conn 0xffff70044f40, device EC:74:A1:89:2E:2A, path /org/bluez/hci0/dev_EC_74_A1_89_2E_2A [1745220773.650175][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1745220773.650208][6511:6513] CHIP:DIS: Closing all BLE connections [1745220773.650301][6511:6513] CHIP:IN: BleConnectionComplete: endPoint 0xaaaabb2cc358 [1745220773.650846][6511:6513] CHIP:IN: SecureSession[0xffff780132b0]: Allocated Type:1 LSID:8617 [1745220773.650906][6511:6513] CHIP:SC: Assigned local session key ID 8617 [1745220773.651115][6511:6513] CHIP:EM: <<< [E:3071i S:0 M:213619076] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1745220773.651162][6511:6513] CHIP:IN: Message appended to BLE send queue [1745220773.651183][6511:6513] CHIP:SC: Sent PBKDF param request [1745220774.046832][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.227562][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1745220774.227643][6511:6513] CHIP:BLE: subscribe complete, ep = 0xaaaabb2cc358 [1745220774.227872][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.228071][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.228137][6511:6513] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1745220774.228184][6511:6513] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1745220774.228226][6511:6513] CHIP:BLE: local and remote recv window size = 5 [1745220774.228950][6511:6513] CHIP:IN: BLE EndPoint 0xaaaabb2cc358 Connection Complete [1745220774.316702][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.319362][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.319828][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.320038][6511:6513] CHIP:EM: >>> [E:3071i S:0 M:74494550] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1745220774.320106][6511:6513] CHIP:EM: Found matching exchange: 3071i, Delegate: 0xffff7801b5d0 [1745220774.320190][6511:6513] CHIP:SC: Received PBKDF param response [1745220774.320275][6511:6513] CHIP:SC: Peer assigned session ID 24071 [1745220774.320341][6511:6513] CHIP:SC: Found MRP parameters in the message [1745220774.330020][6511:6513] CHIP:EM: <<< [E:3071i S:0 M:213619077] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1745220774.330601][6511:6513] CHIP:SC: Sent spake2p msg1 [1745220774.407041][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.498953][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.499240][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.499472][6511:6513] CHIP:EM: >>> [E:3071i S:0 M:74494551] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1745220774.499583][6511:6513] CHIP:EM: Found matching exchange: 3071i, Delegate: 0xffff7801b5d0 [1745220774.499682][6511:6513] CHIP:SC: Received spake2p msg2 [1745220774.503226][6511:6513] CHIP:EM: <<< [E:3071i S:0 M:213619078] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1745220774.504005][6511:6513] CHIP:SC: Sent spake2p msg3 [1745220774.587083][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.588461][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.588985][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.589219][6511:6513] CHIP:EM: >>> [E:3071i S:0 M:74494552] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745220774.589297][6511:6513] CHIP:EM: Found matching exchange: 3071i, Delegate: 0xffff7801b5d0 [1745220774.589702][6511:6513] CHIP:SC: SecureSession[0xffff780132b0, LSID:8617]: State change 'kEstablishing' --> 'kActive' [1745220774.589782][6511:6513] CHIP:IN: SecureSession[0xffff780132b0]: Activated - Type:1 LSID:8617 [1745220774.589830][6511:6513] CHIP:IN: New secure session activated for device , LSID:8617 PSID:24071! [1745220774.589900][6511:6513] CHIP:CTL: Remote device completed SPAKE2+ handshake [1745220774.589958][6511:6513] CHIP:TOO: Pairing Success [1745220774.590005][6511:6513] CHIP:TOO: PASE establishment successful [1745220774.590059][6511:6513] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1745220774.590117][6511:6513] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1745220774.590166][6511:6513] CHIP:CTL: Sending read request for commissioning information [1745220774.590255][6511:6513] CHIP:DMG: SendReadRequest ReadClient[0xffff78009390]: Sending Read Request [1745220774.590689][6511:6513] CHIP:EM: <<< [E:3072i S:8617 M:163405014] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1745220774.591658][6511:6513] CHIP:DMG: MoveToState ReadClient[0xffff78009390]: Moving to [AwaitingIn] [1745220774.676961][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.680404][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.680666][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.767927][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.768197][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.768480][6511:6513] CHIP:EM: >>> [E:3072i S:8617 M:17184610] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1745220774.768562][6511:6513] CHIP:EM: Found matching exchange: 3072i, Delegate: 0xffff780093a0 [1745220774.768775][6511:6513] CHIP:DMG: ReportDataMessage = [1745220774.768835][6511:6513] CHIP:DMG: { [1745220774.768885][6511:6513] CHIP:DMG: AttributeReportIBs = [1745220774.768961][6511:6513] CHIP:DMG: [ [1745220774.769020][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.769099][6511:6513] CHIP:DMG: { [1745220774.769160][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.769236][6511:6513] CHIP:DMG: { [1745220774.769308][6511:6513] CHIP:DMG: DataVersion = 0x9adc0688, [1745220774.769378][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.769459][6511:6513] CHIP:DMG: { [1745220774.769534][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.769607][6511:6513] CHIP:DMG: Cluster = 0x31, [1745220774.769678][6511:6513] CHIP:DMG: Attribute = 0x0000_0003, [1745220774.769751][6511:6513] CHIP:DMG: } [1745220774.769832][6511:6513] CHIP:DMG: [1745220774.769912][6511:6513] CHIP:DMG: Data = 20, [1745220774.769983][6511:6513] CHIP:DMG: }, [1745220774.770058][6511:6513] CHIP:DMG: [1745220774.770119][6511:6513] CHIP:DMG: }, [1745220774.770206][6511:6513] CHIP:DMG: [1745220774.770263][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.770339][6511:6513] CHIP:DMG: { [1745220774.770453][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.770526][6511:6513] CHIP:DMG: { [1745220774.770596][6511:6513] CHIP:DMG: DataVersion = 0x83b08e5c, [1745220774.770661][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.770734][6511:6513] CHIP:DMG: { [1745220774.770811][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.770900][6511:6513] CHIP:DMG: Cluster = 0x28, [1745220774.770983][6511:6513] CHIP:DMG: Attribute = 0x0000_0004, [1745220774.771055][6511:6513] CHIP:DMG: } [1745220774.771133][6511:6513] CHIP:DMG: [1745220774.771210][6511:6513] CHIP:DMG: Data = 1, [1745220774.771288][6511:6513] CHIP:DMG: }, [1745220774.771362][6511:6513] CHIP:DMG: [1745220774.771422][6511:6513] CHIP:DMG: }, [1745220774.771508][6511:6513] CHIP:DMG: [1745220774.771565][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.771640][6511:6513] CHIP:DMG: { [1745220774.771702][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.771772][6511:6513] CHIP:DMG: { [1745220774.771842][6511:6513] CHIP:DMG: DataVersion = 0x83b08e5c, [1745220774.771911][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.771981][6511:6513] CHIP:DMG: { [1745220774.772056][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.772135][6511:6513] CHIP:DMG: Cluster = 0x28, [1745220774.772210][6511:6513] CHIP:DMG: Attribute = 0x0000_0002, [1745220774.772293][6511:6513] CHIP:DMG: } [1745220774.772372][6511:6513] CHIP:DMG: [1745220774.772448][6511:6513] CHIP:DMG: Data = 5547, [1745220774.772518][6511:6513] CHIP:DMG: }, [1745220774.772593][6511:6513] CHIP:DMG: [1745220774.772653][6511:6513] CHIP:DMG: }, [1745220774.772737][6511:6513] CHIP:DMG: [1745220774.772795][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.772870][6511:6513] CHIP:DMG: { [1745220774.772931][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.772997][6511:6513] CHIP:DMG: { [1745220774.773066][6511:6513] CHIP:DMG: DataVersion = 0xfcbef001, [1745220774.773139][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.773219][6511:6513] CHIP:DMG: { [1745220774.773296][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.773372][6511:6513] CHIP:DMG: Cluster = 0x30, [1745220774.773443][6511:6513] CHIP:DMG: Attribute = 0x0000_0003, [1745220774.773518][6511:6513] CHIP:DMG: } [1745220774.773597][6511:6513] CHIP:DMG: [1745220774.773670][6511:6513] CHIP:DMG: Data = 0, [1745220774.773739][6511:6513] CHIP:DMG: }, [1745220774.773811][6511:6513] CHIP:DMG: [1745220774.773870][6511:6513] CHIP:DMG: }, [1745220774.773956][6511:6513] CHIP:DMG: [1745220774.774013][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.774088][6511:6513] CHIP:DMG: { [1745220774.774149][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.774218][6511:6513] CHIP:DMG: { [1745220774.774287][6511:6513] CHIP:DMG: DataVersion = 0xfcbef001, [1745220774.774358][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.774462][6511:6513] CHIP:DMG: { [1745220774.774538][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.774619][6511:6513] CHIP:DMG: Cluster = 0x30, [1745220774.774699][6511:6513] CHIP:DMG: Attribute = 0x0000_0002, [1745220774.774770][6511:6513] CHIP:DMG: } [1745220774.774848][6511:6513] CHIP:DMG: [1745220774.774925][6511:6513] CHIP:DMG: Data = 0, [1745220774.774995][6511:6513] CHIP:DMG: }, [1745220774.775070][6511:6513] CHIP:DMG: [1745220774.775131][6511:6513] CHIP:DMG: }, [1745220774.775220][6511:6513] CHIP:DMG: [1745220774.775277][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.775356][6511:6513] CHIP:DMG: { [1745220774.775417][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.775484][6511:6513] CHIP:DMG: { [1745220774.775552][6511:6513] CHIP:DMG: DataVersion = 0xfcbef001, [1745220774.775623][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.775701][6511:6513] CHIP:DMG: { [1745220774.775776][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.775851][6511:6513] CHIP:DMG: Cluster = 0x30, [1745220774.775925][6511:6513] CHIP:DMG: Attribute = 0x0000_0001, [1745220774.776004][6511:6513] CHIP:DMG: } [1745220774.776079][6511:6513] CHIP:DMG: [1745220774.776151][6511:6513] CHIP:DMG: Data = [1745220774.776225][6511:6513] CHIP:DMG: { [1745220774.776353][6511:6513] CHIP:DMG: 0x0 = 60, [1745220774.776432][6511:6513] CHIP:DMG: 0x1 = 900, [1745220774.776511][6511:6513] CHIP:DMG: }, [1745220774.776581][6511:6513] CHIP:DMG: }, [1745220774.776658][6511:6513] CHIP:DMG: [1745220774.776714][6511:6513] CHIP:DMG: }, [1745220774.776797][6511:6513] CHIP:DMG: [1745220774.776854][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.776929][6511:6513] CHIP:DMG: { [1745220774.776990][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.777057][6511:6513] CHIP:DMG: { [1745220774.777125][6511:6513] CHIP:DMG: DataVersion = 0xfcbef001, [1745220774.777201][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.777276][6511:6513] CHIP:DMG: { [1745220774.777350][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.777428][6511:6513] CHIP:DMG: Cluster = 0x30, [1745220774.777507][6511:6513] CHIP:DMG: Attribute = 0x0000_0000, [1745220774.777582][6511:6513] CHIP:DMG: } [1745220774.777657][6511:6513] CHIP:DMG: [1745220774.777732][6511:6513] CHIP:DMG: Data = 0, [1745220774.777803][6511:6513] CHIP:DMG: }, [1745220774.777876][6511:6513] CHIP:DMG: [1745220774.777935][6511:6513] CHIP:DMG: }, [1745220774.778023][6511:6513] CHIP:DMG: [1745220774.778079][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.778153][6511:6513] CHIP:DMG: { [1745220774.778213][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.778279][6511:6513] CHIP:DMG: { [1745220774.778348][6511:6513] CHIP:DMG: DataVersion = 0x9adc0688, [1745220774.778444][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.778522][6511:6513] CHIP:DMG: { [1745220774.778598][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.778676][6511:6513] CHIP:DMG: Cluster = 0x31, [1745220774.778755][6511:6513] CHIP:DMG: Attribute = 0x0000_FFFC, [1745220774.778827][6511:6513] CHIP:DMG: } [1745220774.778904][6511:6513] CHIP:DMG: [1745220774.778980][6511:6513] CHIP:DMG: Data = 2, [1745220774.779045][6511:6513] CHIP:DMG: }, [1745220774.779116][6511:6513] CHIP:DMG: [1745220774.779159][6511:6513] CHIP:DMG: }, [1745220774.779193][6511:6513] CHIP:DMG: [1745220774.779213][6511:6513] CHIP:DMG: ], [1745220774.779263][6511:6513] CHIP:DMG: [1745220774.779292][6511:6513] CHIP:DMG: SuppressResponse = true, [1745220774.779323][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220774.779344][6511:6513] CHIP:DMG: } [1745220774.779994][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1745220774.780025][6511:6513] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2' [1745220774.780052][6511:6513] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo2' [1745220774.780086][6511:6513] CHIP:DMG: SendReadRequest ReadClient[0xffff78009390]: Sending Read Request [1745220774.780231][6511:6513] CHIP:EM: <<< [E:3073i S:8617 M:163405015] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1745220774.780635][6511:6513] CHIP:DMG: MoveToState ReadClient[0xffff78009390]: Moving to [AwaitingIn] [1745220774.856979][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.859605][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.860162][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.860489][6511:6513] CHIP:EM: >>> [E:3073i S:8617 M:17184611] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1745220774.860601][6511:6513] CHIP:EM: Found matching exchange: 3073i, Delegate: 0xffff780093a0 [1745220774.860770][6511:6513] CHIP:DMG: ReportDataMessage = [1745220774.860833][6511:6513] CHIP:DMG: { [1745220774.860885][6511:6513] CHIP:DMG: AttributeReportIBs = [1745220774.860960][6511:6513] CHIP:DMG: [ [1745220774.861017][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.861120][6511:6513] CHIP:DMG: { [1745220774.861181][6511:6513] CHIP:DMG: AttributeStatusIB = [1745220774.861274][6511:6513] CHIP:DMG: { [1745220774.861340][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.861501][6511:6513] CHIP:DMG: { [1745220774.861659][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.861764][6511:6513] CHIP:DMG: Cluster = 0x46, [1745220774.861883][6511:6513] CHIP:DMG: Attribute = 0x0000_0007, [1745220774.861975][6511:6513] CHIP:DMG: } [1745220774.862088][6511:6513] CHIP:DMG: [1745220774.862189][6511:6513] CHIP:DMG: StatusIB = [1745220774.862276][6511:6513] CHIP:DMG: { [1745220774.862360][6511:6513] CHIP:DMG: status = 0x86 (UNSUPPORTED_ATTRIBUTE), [1745220774.862439][6511:6513] CHIP:DMG: }, [1745220774.862481][6511:6513] CHIP:DMG: [1745220774.862528][6511:6513] CHIP:DMG: }, [1745220774.862571][6511:6513] CHIP:DMG: [1745220774.862602][6511:6513] CHIP:DMG: }, [1745220774.862646][6511:6513] CHIP:DMG: [1745220774.862675][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.862712][6511:6513] CHIP:DMG: { [1745220774.862742][6511:6513] CHIP:DMG: AttributeStatusIB = [1745220774.862780][6511:6513] CHIP:DMG: { [1745220774.862816][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.862860][6511:6513] CHIP:DMG: { [1745220774.862906][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.862954][6511:6513] CHIP:DMG: Cluster = 0x46, [1745220774.863002][6511:6513] CHIP:DMG: Attribute = 0x0000_0006, [1745220774.863047][6511:6513] CHIP:DMG: } [1745220774.863096][6511:6513] CHIP:DMG: [1745220774.863139][6511:6513] CHIP:DMG: StatusIB = [1745220774.863183][6511:6513] CHIP:DMG: { [1745220774.863229][6511:6513] CHIP:DMG: status = 0x86 (UNSUPPORTED_ATTRIBUTE), [1745220774.863273][6511:6513] CHIP:DMG: }, [1745220774.863319][6511:6513] CHIP:DMG: [1745220774.863355][6511:6513] CHIP:DMG: }, [1745220774.863395][6511:6513] CHIP:DMG: [1745220774.863425][6511:6513] CHIP:DMG: }, [1745220774.863469][6511:6513] CHIP:DMG: [1745220774.863497][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.863535][6511:6513] CHIP:DMG: { [1745220774.863565][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.863603][6511:6513] CHIP:DMG: { [1745220774.863643][6511:6513] CHIP:DMG: DataVersion = 0x1ab19381, [1745220774.863686][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.863730][6511:6513] CHIP:DMG: { [1745220774.863775][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.863822][6511:6513] CHIP:DMG: Cluster = 0x46, [1745220774.863869][6511:6513] CHIP:DMG: Attribute = 0x0000_FFFC, [1745220774.863913][6511:6513] CHIP:DMG: } [1745220774.863960][6511:6513] CHIP:DMG: [1745220774.864007][6511:6513] CHIP:DMG: Data = 0, [1745220774.864049][6511:6513] CHIP:DMG: }, [1745220774.864091][6511:6513] CHIP:DMG: [1745220774.864121][6511:6513] CHIP:DMG: }, [1745220774.864163][6511:6513] CHIP:DMG: [1745220774.864192][6511:6513] CHIP:DMG: AttributeReportIB = [1745220774.864229][6511:6513] CHIP:DMG: { [1745220774.864260][6511:6513] CHIP:DMG: AttributeDataIB = [1745220774.864296][6511:6513] CHIP:DMG: { [1745220774.864336][6511:6513] CHIP:DMG: DataVersion = 0xfcbef001, [1745220774.864379][6511:6513] CHIP:DMG: AttributePathIB = [1745220774.864423][6511:6513] CHIP:DMG: { [1745220774.864468][6511:6513] CHIP:DMG: Endpoint = 0x0, [1745220774.864780][6511:6513] CHIP:DMG: Cluster = 0x30, [1745220774.864835][6511:6513] CHIP:DMG: Attribute = 0x0000_0004, [1745220774.864882][6511:6513] CHIP:DMG: } [1745220774.864929][6511:6513] CHIP:DMG: [1745220774.864976][6511:6513] CHIP:DMG: Data = true, [1745220774.865032][6511:6513] CHIP:DMG: }, [1745220774.865074][6511:6513] CHIP:DMG: [1745220774.865118][6511:6513] CHIP:DMG: }, [1745220774.865154][6511:6513] CHIP:DMG: [1745220774.865193][6511:6513] CHIP:DMG: ], [1745220774.865246][6511:6513] CHIP:DMG: [1745220774.865275][6511:6513] CHIP:DMG: SuppressResponse = true, [1745220774.865317][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220774.865344][6511:6513] CHIP:DMG: } [1745220774.865982][6511:6513] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0 [1745220774.866050][6511:6513] CHIP:SVR: OnReadCommissioningInfo - vendorId=0x15AB productId=0x0001 [1745220774.866094][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo2' [1745220774.866129][6511:6513] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo2' -> 'ArmFailSafe' [1745220774.866165][6511:6513] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1745220774.866198][6511:6513] CHIP:CTL: Arming failsafe (60 seconds) [1745220774.866316][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220774.866395][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220774.866591][6511:6513] CHIP:EM: <<< [E:3074i S:8617 M:163405016] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220774.867110][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220774.947010][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220774.948504][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220774.948748][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220774.949095][6511:6513] CHIP:EM: >>> [E:3074i S:8617 M:17184612] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220774.949176][6511:6513] CHIP:EM: Found matching exchange: 3074i, Delegate: 0xffff7800f5e8 [1745220774.949284][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220774.949390][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220774.949563][6511:6513] CHIP:DMG: { [1745220774.949622][6511:6513] CHIP:DMG: suppressResponse = false, [1745220774.949679][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220774.949754][6511:6513] CHIP:DMG: [ [1745220774.949834][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220774.949912][6511:6513] CHIP:DMG: { [1745220774.950062][6511:6513] CHIP:DMG: CommandDataIB = [1745220774.950203][6511:6513] CHIP:DMG: { [1745220774.950294][6511:6513] CHIP:DMG: CommandPathIB = [1745220774.950417][6511:6513] CHIP:DMG: { [1745220774.950525][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220774.950605][6511:6513] CHIP:DMG: ClusterId = 0x30, [1745220774.950765][6511:6513] CHIP:DMG: CommandId = 0x1, [1745220774.950864][6511:6513] CHIP:DMG: }, [1745220774.950945][6511:6513] CHIP:DMG: [1745220774.951081][6511:6513] CHIP:DMG: CommandFields = [1745220774.951159][6511:6513] CHIP:DMG: { [1745220774.951258][6511:6513] CHIP:DMG: 0x0 = 0, [1745220774.951426][6511:6513] CHIP:DMG: 0x1 = "" (0 chars), [1745220774.951512][6511:6513] CHIP:DMG: }, [1745220774.951601][6511:6513] CHIP:DMG: }, [1745220774.951743][6511:6513] CHIP:DMG: [1745220774.951828][6511:6513] CHIP:DMG: }, [1745220774.951904][6511:6513] CHIP:DMG: [1745220774.951982][6511:6513] CHIP:DMG: ], [1745220774.952059][6511:6513] CHIP:DMG: [1745220774.952114][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220774.952190][6511:6513] CHIP:DMG: }, [1745220774.952370][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1745220774.952640][6511:6513] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1745220774.952719][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1745220774.952799][6511:6513] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1745220774.952859][6511:6513] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1745220774.952903][6511:6513] CHIP:CTL: Setting Regulatory Config [1745220774.952950][6511:6513] CHIP:CTL: Device does not support configurable regulatory location [1745220774.953172][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220774.953259][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220774.953647][6511:6513] CHIP:EM: <<< [E:3075i S:8617 M:163405017] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220774.954563][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220774.954756][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220775.036981][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220775.038716][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.038972][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.039318][6511:6513] CHIP:EM: >>> [E:3075i S:8617 M:17184613] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220775.039400][6511:6513] CHIP:EM: Found matching exchange: 3075i, Delegate: 0xffff7800fba8 [1745220775.039508][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220775.039614][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220775.039670][6511:6513] CHIP:DMG: { [1745220775.039863][6511:6513] CHIP:DMG: suppressResponse = false, [1745220775.039928][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220775.040093][6511:6513] CHIP:DMG: [ [1745220775.040192][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220775.040273][6511:6513] CHIP:DMG: { [1745220775.040358][6511:6513] CHIP:DMG: CommandDataIB = [1745220775.040499][6511:6513] CHIP:DMG: { [1745220775.040586][6511:6513] CHIP:DMG: CommandPathIB = [1745220775.040662][6511:6513] CHIP:DMG: { [1745220775.040761][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220775.040843][6511:6513] CHIP:DMG: ClusterId = 0x30, [1745220775.040953][6511:6513] CHIP:DMG: CommandId = 0x3, [1745220775.041030][6511:6513] CHIP:DMG: }, [1745220775.041128][6511:6513] CHIP:DMG: [1745220775.041195][6511:6513] CHIP:DMG: CommandFields = [1745220775.041269][6511:6513] CHIP:DMG: { [1745220775.041369][6511:6513] CHIP:DMG: 0x0 = 0, [1745220775.041454][6511:6513] CHIP:DMG: 0x1 = "" (0 chars), [1745220775.041556][6511:6513] CHIP:DMG: }, [1745220775.041627][6511:6513] CHIP:DMG: }, [1745220775.041727][6511:6513] CHIP:DMG: [1745220775.041788][6511:6513] CHIP:DMG: }, [1745220775.041861][6511:6513] CHIP:DMG: [1745220775.041940][6511:6513] CHIP:DMG: ], [1745220775.042014][6511:6513] CHIP:DMG: [1745220775.042092][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220775.042150][6511:6513] CHIP:DMG: }, [1745220775.042327][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1745220775.042467][6511:6513] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1745220775.042564][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1745220775.042619][6511:6513] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1745220775.042683][6511:6513] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1745220775.042734][6511:6513] CHIP:CTL: Sending request for PAI certificate [1745220775.042784][6511:6513] CHIP:CTL: Sending Certificate Chain request to 0xffff7801b580 device [1745220775.042933][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220775.043050][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220775.043312][6511:6513] CHIP:EM: <<< [E:3076i S:8617 M:163405018] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220775.044082][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220775.044241][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220775.126645][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220775.129992][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.130184][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.220234][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.220528][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.307099][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.307331][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.307635][6511:6513] CHIP:EM: >>> [E:3076i S:8617 M:17184614] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220775.307727][6511:6513] CHIP:EM: Found matching exchange: 3076i, Delegate: 0xffff7800f5e8 [1745220775.307810][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220775.307902][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220775.307950][6511:6513] CHIP:DMG: { [1745220775.308017][6511:6513] CHIP:DMG: suppressResponse = false, [1745220775.308067][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220775.308132][6511:6513] CHIP:DMG: [ [1745220775.308200][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220775.308269][6511:6513] CHIP:DMG: { [1745220775.308321][6511:6513] CHIP:DMG: CommandDataIB = [1745220775.308403][6511:6513] CHIP:DMG: { [1745220775.308459][6511:6513] CHIP:DMG: CommandPathIB = [1745220775.308542][6511:6513] CHIP:DMG: { [1745220775.308609][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220775.308697][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220775.308767][6511:6513] CHIP:DMG: CommandId = 0x3, [1745220775.308832][6511:6513] CHIP:DMG: }, [1745220775.308920][6511:6513] CHIP:DMG: [1745220775.308979][6511:6513] CHIP:DMG: CommandFields = [1745220775.309062][6511:6513] CHIP:DMG: { [1745220775.309127][6511:6513] CHIP:DMG: 0x0 = [ [1745220775.309446][6511:6513] CHIP:DMG: 0x30, 0x82, 0x01, 0xa7, 0x30, 0x82, 0x01, 0x4e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x23, 0x2a, 0x42, 0x94, 0xda, 0x1e, 0x61, 0xa4, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x1a, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x31, 0x30, 0x36, 0x32, 0x38, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x35, 0x41, 0x42, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0xc0, 0xe2, 0xc1, 0xd8, 0x49, 0xb6, 0x3f, 0x1a, 0xee, 0xfe, 0xe0, 0xa8, 0xfa, 0x01, 0xa4, 0xd9, 0xed, 0x2a, 0x90, 0x04, 0x10, 0x7f, 0xc1, 0x74, 0x31, 0x10, 0xa4, 0x7e, 0xad, 0xf6, 0x6c, 0xa5, 0x5c, 0x99, 0xe5, 0x57, 0xb6, 0x35, 0x4e, 0x21, 0xeb, 0xb2, 0xdd, 0xbc, 0xa0, 0x15, 0x2b, 0xa5, 0xe7, 0xab, 0x73, 0x2d, 0xc0, 0xaf, 0x3f, 0x92, 0x0b, 0x69, 0xd8, 0xd5, 0x08, 0x84, 0xc0, 0xc4, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x13, 0x01, 0x01, 0xff, 0x04, 0x08, 0x30, 0x06, 0x01, 0x01, 0xff, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x06, 0x03, 0x55, 0x1d, 0x0f, 0x01, 0x01, 0xff, 0x04, 0x04, 0x03, 0x02, 0x01, 0x06, 0x30, 0x1d, 0x06, 0x03, 0x55, 0x [1745220775.309618][6511:6513] CHIP:DMG: ] (427 bytes) [1745220775.309687][6511:6513] CHIP:DMG: }, [1745220775.309748][6511:6513] CHIP:DMG: }, [1745220775.309835][6511:6513] CHIP:DMG: [1745220775.309888][6511:6513] CHIP:DMG: }, [1745220775.309951][6511:6513] CHIP:DMG: [1745220775.309998][6511:6513] CHIP:DMG: ], [1745220775.310062][6511:6513] CHIP:DMG: [1745220775.310112][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220775.310160][6511:6513] CHIP:DMG: }, [1745220775.310674][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1745220775.310756][6511:6513] CHIP:CTL: Received certificate chain from the device [1745220775.310820][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1745220775.310896][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1745220775.310953][6511:6513] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1745220775.310996][6511:6513] CHIP:CTL: Sending request for DAC certificate [1745220775.311060][6511:6513] CHIP:CTL: Sending Certificate Chain request to 0xffff7801b580 device [1745220775.311177][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220775.311255][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220775.311471][6511:6513] CHIP:EM: <<< [E:3077i S:8617 M:163405019] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220775.312148][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220775.312288][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220775.396697][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220775.399773][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.400108][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.490285][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.490633][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.623400][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.623676][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.623990][6511:6513] CHIP:EM: >>> [E:3077i S:8617 M:17184615] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220775.624073][6511:6513] CHIP:EM: Found matching exchange: 3077i, Delegate: 0xffff7800fba8 [1745220775.624162][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220775.624271][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220775.624328][6511:6513] CHIP:DMG: { [1745220775.624378][6511:6513] CHIP:DMG: suppressResponse = false, [1745220775.624436][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220775.624511][6511:6513] CHIP:DMG: [ [1745220775.624569][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220775.624647][6511:6513] CHIP:DMG: { [1745220775.624708][6511:6513] CHIP:DMG: CommandDataIB = [1745220775.624776][6511:6513] CHIP:DMG: { [1745220775.624835][6511:6513] CHIP:DMG: CommandPathIB = [1745220775.624903][6511:6513] CHIP:DMG: { [1745220775.624969][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220775.625048][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220775.625115][6511:6513] CHIP:DMG: CommandId = 0x3, [1745220775.625176][6511:6513] CHIP:DMG: }, [1745220775.625240][6511:6513] CHIP:DMG: [1745220775.625293][6511:6513] CHIP:DMG: CommandFields = [1745220775.625350][6511:6513] CHIP:DMG: { [1745220775.625412][6511:6513] CHIP:DMG: 0x0 = [ [1745220775.625698][6511:6513] CHIP:DMG: 0x30, 0x82, 0x01, 0xd1, 0x30, 0x82, 0x01, 0x78, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x36, 0x90, 0xd3, 0xa9, 0xe6, 0xf1, 0x7b, 0x39, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x35, 0x41, 0x42, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x35, 0x30, 0x33, 0x32, 0x36, 0x31, 0x34, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x4a, 0x31, 0x1c, 0x30, 0x1a, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x13, 0x41, 0x63, 0x63, 0x75, 0x72, 0x61, 0x74, 0x65, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x44, 0x41, 0x43, 0x20, 0x32, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x35, 0x41, 0x42, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x30, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x4b, 0xd1, 0x60, 0x8b, 0x51, 0x8b, 0xc8, 0xeb, 0x04, 0xed, 0xf2, 0xca, 0x7d, 0x49, 0x7b, 0xc8, 0x40, 0x26, 0x5a, 0x8d, 0x67, 0xf6, 0xc6, 0xd8, 0xe2, 0x61, 0xb6, 0xaa, 0x2c, 0x97, 0x1c, 0xa2, 0x94, 0xa2, 0xa5, 0x1b, 0x36, 0xd3, 0xae, 0x1c, 0xc5, 0x8c, 0xdf, 0xc2, 0x1d, 0xc9, 0x4d, 0x61, 0xff, 0x93, 0x9e, 0x93, 0xc2, 0x7e, 0xe2, 0xf7, 0x1c, 0xe7, 0xe5, 0x65, 0x8d, 0x [1745220775.625849][6511:6513] CHIP:DMG: ] (469 bytes) [1745220775.625921][6511:6513] CHIP:DMG: }, [1745220775.625982][6511:6513] CHIP:DMG: }, [1745220775.626048][6511:6513] CHIP:DMG: [1745220775.626099][6511:6513] CHIP:DMG: }, [1745220775.626162][6511:6513] CHIP:DMG: [1745220775.626210][6511:6513] CHIP:DMG: ], [1745220775.626273][6511:6513] CHIP:DMG: [1745220775.626322][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220775.626422][6511:6513] CHIP:DMG: }, [1745220775.626567][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1745220775.626646][6511:6513] CHIP:CTL: Received certificate chain from the device [1745220775.626709][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1745220775.626761][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1745220775.626816][6511:6513] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1745220775.626859][6511:6513] CHIP:CTL: Sending Attestation Request to the device. [1745220775.626903][6511:6513] CHIP:CTL: Sending Attestation request to 0xffff7801b580 device [1745220775.627020][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220775.627081][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220775.627273][6511:6513] CHIP:EM: <<< [E:3078i S:8617 M:163405020] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220775.627943][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220775.628008][6511:6513] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1745220775.628134][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220775.712074][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220775.715604][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.715871][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.804674][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220775.804935][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220775.805227][6511:6513] CHIP:EM: >>> [E:3078i S:8617 M:17184616] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220775.805309][6511:6513] CHIP:EM: Found matching exchange: 3078i, Delegate: 0xffff7800f5e8 [1745220775.805400][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220775.805505][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220775.805560][6511:6513] CHIP:DMG: { [1745220775.805615][6511:6513] CHIP:DMG: suppressResponse = false, [1745220775.805668][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220775.805743][6511:6513] CHIP:DMG: [ [1745220775.805800][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220775.805878][6511:6513] CHIP:DMG: { [1745220775.805939][6511:6513] CHIP:DMG: CommandDataIB = [1745220775.806013][6511:6513] CHIP:DMG: { [1745220775.806077][6511:6513] CHIP:DMG: CommandPathIB = [1745220775.806153][6511:6513] CHIP:DMG: { [1745220775.806229][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220775.806309][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220775.806430][6511:6513] CHIP:DMG: CommandId = 0x1, [1745220775.806516][6511:6513] CHIP:DMG: }, [1745220775.806593][6511:6513] CHIP:DMG: [1745220775.806661][6511:6513] CHIP:DMG: CommandFields = [1745220775.806734][6511:6513] CHIP:DMG: { [1745220775.806810][6511:6513] CHIP:DMG: 0x0 = [ [1745220775.807131][6511:6513] CHIP:DMG: 0x15, 0x30, 0x01, 0xec, 0x30, 0x81, 0xe9, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x81, 0xdb, 0x30, 0x81, 0xd8, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x44, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x37, 0x04, 0x35, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xab, 0x15, 0x36, 0x02, 0x04, 0x01, 0x18, 0x25, 0x03, 0x34, 0x12, 0x2c, 0x04, 0x13, 0x5a, 0x49, 0x47, 0x32, 0x30, 0x31, 0x34, 0x31, 0x5a, 0x42, 0x33, 0x33, 0x30, 0x30, 0x30, 0x31, 0x2d, 0x32, 0x34, 0x24, 0x05, 0x00, 0x24, 0x06, 0x00, 0x25, 0x07, 0x76, 0x98, 0x24, 0x08, 0x00, 0x18, 0x31, 0x7e, 0x30, 0x7c, 0x02, 0x01, 0x03, 0x80, 0x14, 0x62, 0xfa, 0x82, 0x33, 0x59, 0xac, 0xfa, 0xa9, 0x96, 0x3e, 0x1c, 0xfa, 0x14, 0x0a, 0xdd, 0xf5, 0x04, 0xf3, 0x71, 0x60, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x04, 0x48, 0x30, 0x46, 0x02, 0x21, 0x00, 0xd3, 0x41, 0x8f, 0xc8, 0x43, 0xc7, 0x7a, 0x6f, 0xb7, 0x9c, 0xc3, 0xe9, 0x30, 0x20, 0xf0, 0x9d, 0xd4, 0xa9, 0xad, 0x3e, 0x33, 0x46, 0x8b, 0x15, 0x1b, 0x62, 0x4c, 0x95, 0x1a, 0x98, 0x93, 0xfd, 0x02, 0x21, 0x00, 0xd4, 0x1c, 0x88, 0x78, 0x0e, 0xca, 0xd2, 0x57, 0xbf, 0x06, 0x7d, 0x5b, 0xc4, 0xaa, 0xf3, 0x06, 0x88, 0xb9, 0x57, 0x98, 0x3d, 0x75, 0x7b, 0xdd, 0x41, 0x59, 0x5b, 0x8b, 0x38, 0xa2, 0x71, 0xc9, 0x30, 0x02, 0x20, 0xe0, 0x80, 0xc6, 0x73, 0x77, 0x67, 0x24, 0xf5, 0xae, 0xfb, 0x20, 0x57, 0xda, 0x68, 0xbe, 0x53, 0x20, 0xf1, 0x79, 0x18, 0x68, 0xa0, 0x09, 0x20, 0xbb, 0xc5, 0xfc, 0x7d, 0x31, 0x30, 0x3d, 0xeb, 0x24, 0x03, 0x00, 0x18, [1745220775.807305][6511:6513] CHIP:DMG: ] (279 bytes) [1745220775.807386][6511:6513] CHIP:DMG: 0x1 = [ [1745220775.807515][6511:6513] CHIP:DMG: 0x13, 0xfa, 0x2d, 0xad, 0xec, 0xa6, 0x81, 0x37, 0xb0, 0xf8, 0x4a, 0xa4, 0x2a, 0xe4, 0xba, 0xf8, 0xe2, 0x02, 0xd6, 0x31, 0x1d, 0x74, 0xc1, 0xcb, 0x3b, 0x81, 0xac, 0x7b, 0x90, 0x84, 0x3c, 0x69, 0x7b, 0xa2, 0xf3, 0xbb, 0xc7, 0x4d, 0xe6, 0x02, 0xa7, 0x38, 0x9f, 0x34, 0x7c, 0x08, 0xb1, 0xc5, 0xa0, 0xbe, 0x87, 0x3a, 0x2f, 0x69, 0xfa, 0x31, 0xb4, 0xf5, 0x22, 0xc5, 0x6b, 0x5b, 0x9f, 0xdd, [1745220775.807616][6511:6513] CHIP:DMG: ] (64 bytes) [1745220775.807695][6511:6513] CHIP:DMG: }, [1745220775.807766][6511:6513] CHIP:DMG: }, [1745220775.807846][6511:6513] CHIP:DMG: [1745220775.807906][6511:6513] CHIP:DMG: }, [1745220775.807981][6511:6513] CHIP:DMG: [1745220775.808036][6511:6513] CHIP:DMG: ], [1745220775.808110][6511:6513] CHIP:DMG: [1745220775.808166][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220775.808221][6511:6513] CHIP:DMG: }, [1745220775.808382][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1745220775.808476][6511:6513] CHIP:CTL: Received Attestation Information from the device [1745220775.808546][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1745220775.808602][6511:6513] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 279/279 [1745220775.808711][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1745220775.808780][6511:6513] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1745220775.808831][6511:6513] CHIP:CTL: Verifying attestation [1745220775.903956][6511:6513] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1745220775.904034][6511:6513] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1745220775.904057][6511:6513] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1745220775.904085][6511:6513] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1745220775.904105][6511:6513] CHIP:CTL: Sending CSR request to 0xffff7801b580 device [1745220775.904181][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220775.904211][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220775.904370][6511:6513] CHIP:EM: <<< [E:3079i S:8617 M:163405021] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220775.904748][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220775.904782][6511:6513] CHIP:CTL: Sent CSR request, waiting for the CSR [1745220775.904853][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220775.981300][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.120219][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220776.120501][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220776.209023][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220776.209275][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220776.209441][6511:6513] CHIP:EM: >>> [E:3079i S:8617 M:17184617] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220776.209476][6511:6513] CHIP:EM: Found matching exchange: 3079i, Delegate: 0xffff7800fba8 [1745220776.209515][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220776.209562][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220776.209582][6511:6513] CHIP:DMG: { [1745220776.209600][6511:6513] CHIP:DMG: suppressResponse = false, [1745220776.209620][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220776.209646][6511:6513] CHIP:DMG: [ [1745220776.209666][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220776.209693][6511:6513] CHIP:DMG: { [1745220776.209714][6511:6513] CHIP:DMG: CommandDataIB = [1745220776.209737][6511:6513] CHIP:DMG: { [1745220776.209759][6511:6513] CHIP:DMG: CommandPathIB = [1745220776.209795][6511:6513] CHIP:DMG: { [1745220776.209823][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220776.209855][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220776.209886][6511:6513] CHIP:DMG: CommandId = 0x5, [1745220776.209916][6511:6513] CHIP:DMG: }, [1745220776.209944][6511:6513] CHIP:DMG: [1745220776.209967][6511:6513] CHIP:DMG: CommandFields = [1745220776.209997][6511:6513] CHIP:DMG: { [1745220776.210024][6511:6513] CHIP:DMG: 0x0 = [ [1745220776.210128][6511:6513] CHIP:DMG: 0x15, 0x30, 0x01, 0xdd, 0x30, 0x81, 0xda, 0x30, 0x81, 0x81, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0b, 0x0c, 0x03, 0x43, 0x53, 0x41, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0xd6, 0xbb, 0xfb, 0xd3, 0x41, 0xa7, 0x41, 0xc7, 0x7c, 0xb6, 0xc7, 0x23, 0xce, 0x0d, 0x32, 0x9d, 0xea, 0x77, 0x78, 0x9a, 0xce, 0xcc, 0xc1, 0xf5, 0xd2, 0x82, 0xf3, 0x62, 0xed, 0x9b, 0xad, 0xa8, 0x96, 0xc0, 0xf7, 0x29, 0x20, 0x18, 0x4c, 0xf0, 0xe1, 0x05, 0x22, 0xdc, 0x13, 0xfc, 0xae, 0x6a, 0xfa, 0x64, 0xb4, 0xd6, 0x7d, 0x98, 0x2d, 0x18, 0x14, 0x11, 0x37, 0x44, 0x66, 0xe6, 0x30, 0xb4, 0xa0, 0x11, 0x30, 0x0f, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x09, 0x0e, 0x31, 0x02, 0x30, 0x00, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x03, 0x48, 0x00, 0x30, 0x45, 0x02, 0x21, 0x00, 0xef, 0x9b, 0x0b, 0x9b, 0x0e, 0x83, 0x88, 0xe5, 0xd0, 0x6a, 0x44, 0x2c, 0x27, 0xce, 0x6f, 0x77, 0xf3, 0x70, 0x3e, 0x16, 0xe0, 0x1e, 0x84, 0x5a, 0x57, 0x71, 0xf8, 0x7f, 0x26, 0x8c, 0x6d, 0x62, 0x02, 0x20, 0x0a, 0x8e, 0x0d, 0x5b, 0x2f, 0x9f, 0x32, 0xae, 0x6c, 0x8a, 0x5a, 0x11, 0x88, 0x1b, 0xf4, 0xa2, 0x71, 0x21, 0xd6, 0xdd, 0xe4, 0x5b, 0xe0, 0xf5, 0x5e, 0x05, 0x15, 0xdb, 0x35, 0xc1, 0x50, 0x53, 0x30, 0x02, 0x20, 0x06, 0x92, 0x85, 0x5d, 0x01, 0x81, 0xac, 0x3d, 0x71, 0xcb, 0x6d, 0x62, 0x13, 0xfb, 0xdd, 0xb2, 0x65, 0x4e, 0x86, 0x16, 0x67, 0x6d, 0x3c, 0x07, 0x17, 0x7c, 0xe5, 0x60, 0xd9, 0x32, 0x7e, 0x7b, 0x18, [1745220776.210190][6511:6513] CHIP:DMG: ] (261 bytes) [1745220776.210221][6511:6513] CHIP:DMG: 0x1 = [ [1745220776.210268][6511:6513] CHIP:DMG: 0xb5, 0xae, 0xb5, 0x65, 0x6d, 0x92, 0xfb, 0x75, 0xc6, 0x1b, 0x89, 0xd9, 0xdb, 0x74, 0x63, 0xbe, 0xc3, 0xad, 0x71, 0xf4, 0xc5, 0x7f, 0x0c, 0x38, 0x24, 0x3a, 0x3b, 0x71, 0xbf, 0x29, 0xc1, 0xb3, 0x33, 0x71, 0x07, 0x2a, 0xa7, 0x58, 0x5b, 0xa2, 0x7f, 0x6d, 0x53, 0xab, 0x49, 0x89, 0x40, 0x91, 0x12, 0x36, 0x73, 0xad, 0xa2, 0xe6, 0xdc, 0xe2, 0xc9, 0x37, 0x90, 0xdd, 0x82, 0x38, 0xa2, 0xde, [1745220776.210307][6511:6513] CHIP:DMG: ] (64 bytes) [1745220776.210338][6511:6513] CHIP:DMG: }, [1745220776.210363][6511:6513] CHIP:DMG: }, [1745220776.210480][6511:6513] CHIP:DMG: [1745220776.210502][6511:6513] CHIP:DMG: }, [1745220776.210527][6511:6513] CHIP:DMG: [1745220776.210546][6511:6513] CHIP:DMG: ], [1745220776.210573][6511:6513] CHIP:DMG: [1745220776.210592][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220776.210611][6511:6513] CHIP:DMG: }, [1745220776.210673][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1745220776.210713][6511:6513] CHIP:CTL: Received certificate signing request from the device [1745220776.210743][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1745220776.210763][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1745220776.210790][6511:6513] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1745220776.213864][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1745220776.213926][6511:6513] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1745220776.213952][6511:6513] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1745220776.213973][6511:6513] CHIP:CTL: Getting certificate chain for the device from the issuer [1745220776.216305][6511:6513] CHIP:CTL: Verifying Certificate Signing Request [1745220776.218108][6511:6513] CHIP:CTL: Generating NOC [1745220776.218472][6511:6513] CHIP:CTL: Providing certificate chain to the commissioner [1745220776.218512][6511:6513] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:395: Success [1745220776.218544][6511:6513] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1745220776.218700][6511:6513] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1745220776.218724][6511:6513] CHIP:CTL: Sending root certificate to the device [1745220776.218800][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220776.218828][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220776.218956][6511:6513] CHIP:EM: <<< [E:3080i S:8617 M:163405022] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220776.219355][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220776.219387][6511:6513] CHIP:CTL: Sent root certificate to the device [1745220776.219872][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220776.297034][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.387025][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.432824][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220776.433060][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220776.433347][6511:6513] CHIP:EM: >>> [E:3080i S:8617 M:17184618] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220776.433420][6511:6513] CHIP:EM: Found matching exchange: 3080i, Delegate: 0xffff7800f5e8 [1745220776.433491][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220776.433581][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220776.433630][6511:6513] CHIP:DMG: { [1745220776.433676][6511:6513] CHIP:DMG: suppressResponse = false, [1745220776.433726][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220776.433790][6511:6513] CHIP:DMG: [ [1745220776.433839][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220776.433905][6511:6513] CHIP:DMG: { [1745220776.433958][6511:6513] CHIP:DMG: CommandStatusIB = [1745220776.434028][6511:6513] CHIP:DMG: { [1745220776.434086][6511:6513] CHIP:DMG: CommandPathIB = [1745220776.434148][6511:6513] CHIP:DMG: { [1745220776.434213][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220776.434281][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220776.434348][6511:6513] CHIP:DMG: CommandId = 0xb, [1745220776.434462][6511:6513] CHIP:DMG: }, [1745220776.434539][6511:6513] CHIP:DMG: [1745220776.434596][6511:6513] CHIP:DMG: StatusIB = [1745220776.434661][6511:6513] CHIP:DMG: { [1745220776.434727][6511:6513] CHIP:DMG: status = 0x00 (SUCCESS), [1745220776.434792][6511:6513] CHIP:DMG: }, [1745220776.434858][6511:6513] CHIP:DMG: [1745220776.434912][6511:6513] CHIP:DMG: }, [1745220776.434978][6511:6513] CHIP:DMG: [1745220776.435029][6511:6513] CHIP:DMG: }, [1745220776.435090][6511:6513] CHIP:DMG: [1745220776.435137][6511:6513] CHIP:DMG: ], [1745220776.435198][6511:6513] CHIP:DMG: [1745220776.435245][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220776.435292][6511:6513] CHIP:DMG: }, [1745220776.435422][6511:6513] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1745220776.435483][6511:6513] CHIP:CTL: Device confirmed that it has received the root certificate [1745220776.435540][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1745220776.435584][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1745220776.435636][6511:6513] CHIP:CTL: Performing next commissioning step 'SendNOC' [1745220776.435764][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220776.435837][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220776.436068][6511:6513] CHIP:EM: <<< [E:3081i S:8617 M:163405023] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220776.436728][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220776.436798][6511:6513] CHIP:CTL: Sent operational certificate to the device [1745220776.436925][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220776.522148][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.612355][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.701999][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.883104][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220776.883379][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220776.883702][6511:6513] CHIP:EM: >>> [E:3081i S:8617 M:17184619] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220776.883785][6511:6513] CHIP:EM: Found matching exchange: 3081i, Delegate: 0xffff7800fba8 [1745220776.883869][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220776.883971][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220776.884027][6511:6513] CHIP:DMG: { [1745220776.884082][6511:6513] CHIP:DMG: suppressResponse = false, [1745220776.884136][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220776.884209][6511:6513] CHIP:DMG: [ [1745220776.884266][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220776.884343][6511:6513] CHIP:DMG: { [1745220776.884403][6511:6513] CHIP:DMG: CommandDataIB = [1745220776.884478][6511:6513] CHIP:DMG: { [1745220776.884543][6511:6513] CHIP:DMG: CommandPathIB = [1745220776.884617][6511:6513] CHIP:DMG: { [1745220776.884691][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220776.884774][6511:6513] CHIP:DMG: ClusterId = 0x3e, [1745220776.884853][6511:6513] CHIP:DMG: CommandId = 0x8, [1745220776.884926][6511:6513] CHIP:DMG: }, [1745220776.885006][6511:6513] CHIP:DMG: [1745220776.885074][6511:6513] CHIP:DMG: CommandFields = [1745220776.885147][6511:6513] CHIP:DMG: { [1745220776.885225][6511:6513] CHIP:DMG: 0x0 = 0, [1745220776.885307][6511:6513] CHIP:DMG: 0x1 = 1, [1745220776.885387][6511:6513] CHIP:DMG: }, [1745220776.885456][6511:6513] CHIP:DMG: }, [1745220776.885531][6511:6513] CHIP:DMG: [1745220776.885591][6511:6513] CHIP:DMG: }, [1745220776.885664][6511:6513] CHIP:DMG: [1745220776.885719][6511:6513] CHIP:DMG: ], [1745220776.885791][6511:6513] CHIP:DMG: [1745220776.885848][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220776.885903][6511:6513] CHIP:DMG: }, [1745220776.886060][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1745220776.886203][6511:6513] CHIP:CTL: Device returned status 0 on receiving the NOC [1745220776.886263][6511:6513] CHIP:CTL: Operational credentials provisioned on device 0xffff7801b580 [1745220776.886315][6511:6513] CHIP:TOO: Secure Pairing Success [1745220776.886361][6511:6513] CHIP:TOO: CASE establishment successful [1745220776.886486][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1745220776.886542][6511:6513] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [1745220776.886594][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup' [1745220776.886655][6511:6513] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup' [1745220776.886792][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220776.886866][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220776.887089][6511:6513] CHIP:EM: <<< [E:3082i S:8617 M:163405024] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220776.887832][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220776.887994][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220776.971777][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220776.973341][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220776.973555][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220776.973829][6511:6513] CHIP:EM: >>> [E:3082i S:8617 M:17184620] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220776.973899][6511:6513] CHIP:EM: Found matching exchange: 3082i, Delegate: 0xffff7800f5e8 [1745220776.973969][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220776.974049][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220776.974093][6511:6513] CHIP:DMG: { [1745220776.974133][6511:6513] CHIP:DMG: suppressResponse = false, [1745220776.974176][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220776.974230][6511:6513] CHIP:DMG: [ [1745220776.974273][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220776.974331][6511:6513] CHIP:DMG: { [1745220776.974416][6511:6513] CHIP:DMG: CommandDataIB = [1745220776.974474][6511:6513] CHIP:DMG: { [1745220776.974522][6511:6513] CHIP:DMG: CommandPathIB = [1745220776.974581][6511:6513] CHIP:DMG: { [1745220776.974636][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220776.974696][6511:6513] CHIP:DMG: ClusterId = 0x31, [1745220776.974755][6511:6513] CHIP:DMG: CommandId = 0x5, [1745220776.974811][6511:6513] CHIP:DMG: }, [1745220776.974870][6511:6513] CHIP:DMG: [1745220776.974924][6511:6513] CHIP:DMG: CommandFields = [1745220776.974980][6511:6513] CHIP:DMG: { [1745220776.975038][6511:6513] CHIP:DMG: 0x0 = 0, [1745220776.975098][6511:6513] CHIP:DMG: 0x2 = 0, [1745220776.975157][6511:6513] CHIP:DMG: }, [1745220776.975210][6511:6513] CHIP:DMG: }, [1745220776.975266][6511:6513] CHIP:DMG: [1745220776.975310][6511:6513] CHIP:DMG: }, [1745220776.975362][6511:6513] CHIP:DMG: [1745220776.975400][6511:6513] CHIP:DMG: ], [1745220776.975450][6511:6513] CHIP:DMG: [1745220776.975488][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220776.975526][6511:6513] CHIP:DMG: }, [1745220776.975647][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1745220776.975719][6511:6513] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1745220776.975774][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup' [1745220776.975815][6511:6513] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'FailsafeBeforeThreadEnable' [1745220776.975864][6511:6513] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeThreadEnable' [1745220776.975924][6511:6513] CHIP:CTL: Arming failsafe (132 seconds) [1745220776.976032][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220776.976086][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220776.976253][6511:6513] CHIP:EM: <<< [E:3083i S:8617 M:163405025] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220776.976989][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220776.977128][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220777.061613][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220777.063093][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220777.063280][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220777.063536][6511:6513] CHIP:EM: >>> [E:3083i S:8617 M:17184621] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220777.063593][6511:6513] CHIP:EM: Found matching exchange: 3083i, Delegate: 0xffff7800fba8 [1745220777.063651][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220777.063722][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220777.063763][6511:6513] CHIP:DMG: { [1745220777.063800][6511:6513] CHIP:DMG: suppressResponse = false, [1745220777.063840][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220777.063891][6511:6513] CHIP:DMG: [ [1745220777.063930][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220777.063983][6511:6513] CHIP:DMG: { [1745220777.064024][6511:6513] CHIP:DMG: CommandDataIB = [1745220777.064069][6511:6513] CHIP:DMG: { [1745220777.064112][6511:6513] CHIP:DMG: CommandPathIB = [1745220777.064163][6511:6513] CHIP:DMG: { [1745220777.064215][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220777.064269][6511:6513] CHIP:DMG: ClusterId = 0x30, [1745220777.064321][6511:6513] CHIP:DMG: CommandId = 0x1, [1745220777.064371][6511:6513] CHIP:DMG: }, [1745220777.064422][6511:6513] CHIP:DMG: [1745220777.064466][6511:6513] CHIP:DMG: CommandFields = [1745220777.064515][6511:6513] CHIP:DMG: { [1745220777.064568][6511:6513] CHIP:DMG: 0x0 = 0, [1745220777.064626][6511:6513] CHIP:DMG: 0x1 = "" (0 chars), [1745220777.064679][6511:6513] CHIP:DMG: }, [1745220777.064726][6511:6513] CHIP:DMG: }, [1745220777.064778][6511:6513] CHIP:DMG: [1745220777.064818][6511:6513] CHIP:DMG: }, [1745220777.064864][6511:6513] CHIP:DMG: [1745220777.064898][6511:6513] CHIP:DMG: ], [1745220777.064944][6511:6513] CHIP:DMG: [1745220777.064981][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220777.065018][6511:6513] CHIP:DMG: }, [1745220777.065127][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1745220777.065194][6511:6513] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1745220777.065243][6511:6513] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeThreadEnable' [1745220777.065278][6511:6513] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeThreadEnable' -> 'ThreadNetworkEnable' [1745220777.065322][6511:6513] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable' [1745220777.065429][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220777.065482][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220777.065638][6511:6513] CHIP:EM: <<< [E:3084i S:8617 M:163405026] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220777.066242][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220777.066363][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220777.151914][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220778.097110][6511:6512] CHIP:DL: Indication received, conn = 0xffff70044f40 [1745220778.097245][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1745220778.097441][6511:6513] CHIP:EM: >>> [E:3084i S:8617 M:17184622] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220778.097486][6511:6513] CHIP:EM: Found matching exchange: 3084i, Delegate: 0xffff7800f5e8 [1745220778.097532][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220778.097591][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220778.097620][6511:6513] CHIP:DMG: { [1745220778.097648][6511:6513] CHIP:DMG: suppressResponse = false, [1745220778.097677][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220778.097715][6511:6513] CHIP:DMG: [ [1745220778.097744][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220778.097784][6511:6513] CHIP:DMG: { [1745220778.097814][6511:6513] CHIP:DMG: CommandDataIB = [1745220778.097851][6511:6513] CHIP:DMG: { [1745220778.097885][6511:6513] CHIP:DMG: CommandPathIB = [1745220778.097924][6511:6513] CHIP:DMG: { [1745220778.097961][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220778.098000][6511:6513] CHIP:DMG: ClusterId = 0x31, [1745220778.098039][6511:6513] CHIP:DMG: CommandId = 0x7, [1745220778.098078][6511:6513] CHIP:DMG: }, [1745220778.098118][6511:6513] CHIP:DMG: [1745220778.098156][6511:6513] CHIP:DMG: CommandFields = [1745220778.098198][6511:6513] CHIP:DMG: { [1745220778.098239][6511:6513] CHIP:DMG: 0x0 = 0, [1745220778.098278][6511:6513] CHIP:DMG: 0x2 = NULL [1745220778.098319][6511:6513] CHIP:DMG: }, [1745220778.098355][6511:6513] CHIP:DMG: }, [1745220778.098438][6511:6513] CHIP:DMG: [1745220778.098471][6511:6513] CHIP:DMG: }, [1745220778.098507][6511:6513] CHIP:DMG: [1745220778.098535][6511:6513] CHIP:DMG: ], [1745220778.098571][6511:6513] CHIP:DMG: [1745220778.098599][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220778.098627][6511:6513] CHIP:DMG: }, [1745220778.098713][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1745220778.098767][6511:6513] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0 [1745220778.098808][6511:6513] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable' [1745220778.098838][6511:6513] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational' [1745220778.098872][6511:6513] CHIP:CTL: Performing next commissioning step 'FindOperational' [1745220778.098897][6511:6513] CHIP:IN: Expiring all sessions for node <0000000000000001, 1>!! [1745220778.098925][6511:6513] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745220778.098953][6511:6513] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745220778.098993][6511:6513] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1745220778.099030][6511:6513] CHIP:DIS: Resolving 1CB8E8FD2A1604E0:0000000000000001 ... [1745220778.100299][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220778.298785][6511:6513] CHIP:DIS: Checking node lookup status after 200 ms [1745220780.662100][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1745220781.110532][6511:6513] CHIP:DL: Avahi resolve found [1745220781.110692][6511:6513] CHIP:DIS: Node ID resolved for 1CB8E8FD2A1604E0:0000000000000001 [1745220781.110754][6511:6513] CHIP:DIS: Hostname: 2E4E2FDC6206DD75 [1745220781.110822][6511:6513] CHIP:DIS: IP Address #1: fd11:22::c163:73cb:f8c5:2cad [1745220781.110878][6511:6513] CHIP:DIS: Port: 5540 [1745220781.110932][6511:6513] CHIP:DIS: Mrp Interval idle: 5000 ms [1745220781.110988][6511:6513] CHIP:DIS: Mrp Interval active: 2500 ms [1745220781.111043][6511:6513] CHIP:DIS: Mrp Active Threshold: 500 ms [1745220781.111095][6511:6513] CHIP:DIS: TCP Supported: 0 [1745220781.111149][6511:6513] CHIP:DIS: ICD: not present [1745220781.112957][6511:6513] CHIP:DIS: Lookup clearing interface for non LL address [1745220781.113175][6511:6513] CHIP:DIS: UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540: new best score: 3 [1745220781.113237][6511:6513] CHIP:DIS: Checking node lookup status after 3014 ms [1745220781.115447][6511:6513] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540 while in state 2 [1745220781.115492][6511:6513] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1745220781.115632][6511:6513] CHIP:IN: SecureSession[0xffff78007db0]: Allocated Type:2 LSID:8618 [1745220781.115683][6511:6513] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1745220781.117494][6511:6513] CHIP:EM: <<< [E:3085i S:0 M:213619079] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1745220781.117849][6511:6513] CHIP:SC: Sent Sigma1 msg [1745220781.117894][6511:6513] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1745220781.522550][6511:6513] CHIP:EM: >>> [E:3085i S:0 M:74494553 (Ack:213619079)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220781.522641][6511:6513] CHIP:EM: Found matching exchange: 3085i, Delegate: 0xffff7801ccb8 [1745220781.522716][6511:6513] CHIP:EM: Rxd Ack; Removing MessageCounter:213619079 from Retrans Table on exchange 3085i [1745220781.674595][6511:6513] CHIP:EM: >>> [E:3085i S:0 M:74494554 (Ack:213619079)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1745220781.674684][6511:6513] CHIP:EM: Found matching exchange: 3085i, Delegate: 0xffff7801ccb8 [1745220781.674740][6511:6513] CHIP:EM: CHIP MessageCounter:213619079 not in RetransTable on exchange 3085i [1745220781.674834][6511:6513] CHIP:SC: Received Sigma2 msg [1745220781.674910][6511:6513] CHIP:SC: Peer assigned session session ID 24070 [1745220781.683943][6511:6513] CHIP:SC: Found MRP parameters in the message [1745220781.684071][6511:6513] CHIP:SC: Sending Sigma3 [1745220781.686251][6511:6513] CHIP:EM: <<< [E:3085i S:0 M:213619080 (Ack:74494554)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1745220781.686588][6511:6513] CHIP:SC: Sent Sigma3 msg [1745220782.221529][6511:6513] CHIP:EM: >>> [E:3085i S:0 M:74494555 (Ack:213619080)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220782.221605][6511:6513] CHIP:EM: Found matching exchange: 3085i, Delegate: 0xffff7801ccb8 [1745220782.221667][6511:6513] CHIP:EM: Rxd Ack; Removing MessageCounter:213619080 from Retrans Table on exchange 3085i [1745220782.424436][6511:6513] CHIP:EM: >>> [E:3085i S:0 M:74494556 (Ack:213619080)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745220782.424541][6511:6513] CHIP:EM: Found matching exchange: 3085i, Delegate: 0xffff7801ccb8 [1745220782.424604][6511:6513] CHIP:EM: CHIP MessageCounter:213619080 not in RetransTable on exchange 3085i [1745220782.424713][6511:6513] CHIP:SC: Success status report received. Session was established [1745220782.439523][6511:6513] CHIP:SC: SecureSession[0xffff78007db0, LSID:8618]: State change 'kEstablishing' --> 'kActive' [1745220782.439579][6511:6513] CHIP:IN: SecureSession[0xffff78007db0]: Activated - Type:2 LSID:8618 [1745220782.439603][6511:6513] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:8618 PSID:24070! [1745220782.439632][6511:6513] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1745220782.439707][6511:6513] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1745220782.439731][6511:6513] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1745220782.439764][6511:6513] CHIP:CTL: Performing next commissioning step 'SendComplete' [1745220782.439838][6511:6513] CHIP:DMG: ICR moving to [AddingComm] [1745220782.439867][6511:6513] CHIP:DMG: ICR moving to [AddedComma] [1745220782.440091][6511:6513] CHIP:EM: <<< [E:3086i S:8618 M:36185368] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220782.440349][6511:6513] CHIP:DMG: ICR moving to [AwaitingRe] [1745220782.440517][6511:6513] CHIP:EM: <<< [E:3085i S:0 M:213619081 (Ack:74494556)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220782.440675][6511:6513] CHIP:EM: Flushed pending ack for MessageCounter:74494556 on exchange 3085i [1745220783.052834][6511:6513] CHIP:EM: >>> [E:3086i S:8618 M:89771225 (Ack:36185368)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220783.052955][6511:6513] CHIP:EM: Found matching exchange: 3086i, Delegate: 0xffff7800f5e8 [1745220783.053044][6511:6513] CHIP:EM: Rxd Ack; Removing MessageCounter:36185368 from Retrans Table on exchange 3086i [1745220783.053137][6511:6513] CHIP:DMG: ICR moving to [ResponseRe] [1745220783.053249][6511:6513] CHIP:DMG: InvokeResponseMessage = [1745220783.053307][6511:6513] CHIP:DMG: { [1745220783.053363][6511:6513] CHIP:DMG: suppressResponse = false, [1745220783.053423][6511:6513] CHIP:DMG: InvokeResponseIBs = [1745220783.053502][6511:6513] CHIP:DMG: [ [1745220783.053560][6511:6513] CHIP:DMG: InvokeResponseIB = [1745220783.053640][6511:6513] CHIP:DMG: { [1745220783.053702][6511:6513] CHIP:DMG: CommandDataIB = [1745220783.053775][6511:6513] CHIP:DMG: { [1745220783.053840][6511:6513] CHIP:DMG: CommandPathIB = [1745220783.053916][6511:6513] CHIP:DMG: { [1745220783.053994][6511:6513] CHIP:DMG: EndpointId = 0x0, [1745220783.054073][6511:6513] CHIP:DMG: ClusterId = 0x30, [1745220783.054148][6511:6513] CHIP:DMG: CommandId = 0x5, [1745220783.054259][6511:6513] CHIP:DMG: }, [1745220783.054344][6511:6513] CHIP:DMG: [1745220783.054494][6511:6513] CHIP:DMG: CommandFields = [1745220783.054576][6511:6513] CHIP:DMG: { [1745220783.054655][6511:6513] CHIP:DMG: 0x0 = 0, [1745220783.054738][6511:6513] CHIP:DMG: 0x1 = "" (0 chars), [1745220783.054816][6511:6513] CHIP:DMG: }, [1745220783.054884][6511:6513] CHIP:DMG: }, [1745220783.054962][6511:6513] CHIP:DMG: [1745220783.055022][6511:6513] CHIP:DMG: }, [1745220783.055097][6511:6513] CHIP:DMG: [1745220783.055153][6511:6513] CHIP:DMG: ], [1745220783.055228][6511:6513] CHIP:DMG: [1745220783.055282][6511:6513] CHIP:DMG: InteractionModelRevision = 11 [1745220783.055333][6511:6513] CHIP:DMG: }, [1745220783.055494][6511:6513] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1745220783.055589][6511:6513] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1745220783.055662][6511:6513] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1745220783.055715][6511:6513] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1745220783.055793][6511:6513] CHIP:CTL: Performing next commissioning step 'Cleanup' [1745220783.055855][6511:6513] CHIP:DIS: Closing all BLE connections [1745220783.055916][6511:6513] CHIP:IN: Clearing BLE pending packets. [1745220783.056651][6511:6513] CHIP:BLE: Auto-closing end point's BLE connection. [1745220783.056729][6511:6513] CHIP:DL: Closing BLE GATT connection (con 0xffff70044f40) [1745220783.056932][6511:6512] CHIP:DL: BluezDisconnect peer=EC:74:A1:89:2E:2A [1745220783.228775][6511:6513] CHIP:IN: SecureSession[0xffff780132b0]: MarkForEviction Type:1 LSID:8617 [1745220783.228877][6511:6513] CHIP:SC: SecureSession[0xffff780132b0, LSID:8617]: State change 'kActive' --> 'kPendingEviction' [1745220783.229019][6511:6513] CHIP:IN: SecureSession[0xffff780132b0]: Released - Type:1 LSID:8617 [1745220783.229110][6511:6513] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1745220783.229185][6511:6513] CHIP:TOO: Device commissioning completed with success [1745220783.229377][6511:6513] CHIP:DMG: ICR moving to [AwaitingDe] [1745220783.229820][6511:6513] CHIP:EM: <<< [E:3086i S:8618 M:36185369 (Ack:89771225)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220783.230151][6511:6512] CHIP:DL: Bluez disconnected [1745220783.230272][6511:6512] CHIP:DL: Bluez notify CHIPoBluez connection disconnected [1745220783.230227][6511:6513] CHIP:EM: Flushed pending ack for MessageCounter:89771225 on exchange 3086i [1745220783.230520][6511:6513] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1745220783.230591][6511:6513] CHIP:BLE: no endpoint for unsub complete [1745220783.231223][6511:6511] CHIP:CTL: Shutting down the commissioner [1745220783.231438][6511:6511] CHIP:CTL: Shutting down the controller [1745220783.231506][6511:6511] CHIP:IN: Expiring all sessions for fabric 0x1!! [1745220783.231561][6511:6511] CHIP:IN: SecureSession[0xffff78007db0]: MarkForEviction Type:2 LSID:8618 [1745220783.231619][6511:6511] CHIP:SC: SecureSession[0xffff78007db0, LSID:8618]: State change 'kActive' --> 'kPendingEviction' [1745220783.231770][6511:6511] CHIP:IN: SecureSession[0xffff78007db0]: Released - Type:2 LSID:8618 [1745220783.231929][6511:6511] CHIP:FP: Forgetting fabric 0x1 [1745220783.232091][6511:6511] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745220783.233111][6511:6511] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745220783.233181][6511:6511] CHIP:TS: Reverted Last Known Good Time to previous value [1745220783.233281][6511:6511] CHIP:CTL: Shutting down the commissioner [1745220783.233461][6511:6511] CHIP:CTL: Shutting down the controller [1745220783.233517][6511:6511] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1745220783.233836][6511:6511] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1745220783.234047][6511:6511] CHIP:FP: Shutting down FabricTable [1745220783.234126][6511:6511] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745220783.234934][6511:6511] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745220783.235017][6511:6511] CHIP:TS: Reverted Last Known Good Time to previous value [1745220783.235493][6511:6511] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-3hfBs1) [1745220783.236799][6511:6511] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745220783.236938][6511:6511] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1745220783.237001][6511:6511] CHIP:DL: Inet Layer shutdown [1745220783.237050][6511:6511] CHIP:DL: BLE shutdown [1745220783.240633][6511:6511] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool pairing open-commissioning-window 1 1 900 1000 3423 [1745220789.541483][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1745220789.543293][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1745220789.543333][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1745220789.548512][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1745220789.548775][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1745220789.548894][6521:6521] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1745220789.549207][6521:6521] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-9WoZ27) [1745220789.549796][6521:6521] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745220789.549852][6521:6521] CHIP:DL: NVS set: chip-counters/reboot-count = 258 (0x102) [1745220789.550774][6521:6521] CHIP:DL: Got Ethernet interface: eth0 [1745220789.551367][6521:6521] CHIP:DL: Found the primary Ethernet interface:eth0 [1745220789.551950][6521:6521] CHIP:DL: Got WiFi interface: wlan0 [1745220789.552013][6521:6521] CHIP:DL: Failed to reset WiFi statistic counts [1745220789.552063][6521:6521] CHIP:IN: UDP::Init bind&listen port=0 [1745220789.552165][6521:6521] CHIP:IN: UDP::Init bound to port=56232 [1745220789.552186][6521:6521] CHIP:IN: BLEBase::Init - setting/overriding transport [1745220789.552204][6521:6521] CHIP:IN: TransportMgr initialized [1745220789.552257][6521:6521] CHIP:FP: Initializing FabricTable from persistent storage [1745220789.552613][6521:6521] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745220789.554649][6521:6521] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1CB8E8FD2A1604E0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.555607][6521:6521] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE7FC514BD95AD5D2, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.556471][6521:6521] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x831C65382602B3B5, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.557281][6521:6521] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xD9D01CB0D050EB4D, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.558048][6521:6521] CHIP:FP: Fabric index 0x5 was retrieved from storage. Compressed FabricId 0x0B7BB6E8F0F51EC7, FabricId 0x0000000000000005, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.558862][6521:6521] CHIP:FP: Fabric index 0x6 was retrieved from storage. Compressed FabricId 0x46A3CEF59284B985, FabricId 0x0000000000000006, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745220789.563733][6521:6521] CHIP:ZCL: Using ZAP configuration... [1745220789.567387][6521:6521] CHIP:DL: Avahi client registered [1745220789.567514][6521:6521] CHIP:CTL: System State Initialized... [1745220789.567670][6521:6521] CHIP:CTL: Setting attestation nonce to random value [1745220789.567708][6521:6521] CHIP:CTL: Setting CSR nonce to random value [1745220789.567778][6521:6521] CHIP:IN: UDP::Init bind&listen port=5550 [1745220789.567899][6521:6521] CHIP:IN: UDP::Init bound to port=5550 [1745220789.567920][6521:6521] CHIP:IN: TransportMgr initialized [1745220789.568172][6521:6523] CHIP:DL: CHIP task running [1745220789.568348][6521:6523] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1745220789.568654][6521:6523] CHIP:CTL: Setting attestation nonce to random value [1745220789.568813][6521:6523] CHIP:CTL: Setting CSR nonce to random value [1745220789.569606][6521:6523] CHIP:CTL: Generating NOC [1745220789.571176][6521:6523] CHIP:FP: Validating NOC chain [1745220789.573201][6521:6523] CHIP:FP: NOC chain validation successful [1745220789.573385][6521:6523] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1745220789.573422][6521:6523] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745220789.573449][6521:6523] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1745220789.573471][6521:6523] CHIP:TS: Retaining current Last Known Good Time [1745220789.585919][6521:6523] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1745220789.590270][6521:6523] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1745220789.594773][6521:6523] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1CB8E8FD2A1604E0) [1745220789.594832][6521:6523] CHIP:IN: UDP::Init bind&listen port=5550 [1745220789.594946][6521:6523] CHIP:IN: UDP::Init bound to port=5550 [1745220789.594966][6521:6523] CHIP:IN: TransportMgr initialized [1745220789.633940][6521:6523] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745220789.633995][6521:6523] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745220789.634028][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1745220789.634060][6521:6523] CHIP:DIS: Resolving 1CB8E8FD2A1604E0:0000000000000001 ... [1745220789.635697][6521:6523] CHIP:DL: Avahi resolve found [1745220789.635770][6521:6523] CHIP:DIS: Node ID resolved for 1CB8E8FD2A1604E0:0000000000000001 [1745220789.635791][6521:6523] CHIP:DIS: Hostname: 2E4E2FDC6206DD75 [1745220789.635814][6521:6523] CHIP:DIS: IP Address #1: fd11:22::c163:73cb:f8c5:2cad [1745220789.635834][6521:6523] CHIP:DIS: Port: 5540 [1745220789.635853][6521:6523] CHIP:DIS: Mrp Interval idle: 5000 ms [1745220789.635871][6521:6523] CHIP:DIS: Mrp Interval active: 2500 ms [1745220789.635890][6521:6523] CHIP:DIS: Mrp Active Threshold: 500 ms [1745220789.635908][6521:6523] CHIP:DIS: TCP Supported: 0 [1745220789.635926][6521:6523] CHIP:DIS: ICD: not present [1745220789.636646][6521:6523] CHIP:DIS: Lookup clearing interface for non LL address [1745220789.636737][6521:6523] CHIP:DIS: UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540: new best score: 3 [1745220789.636760][6521:6523] CHIP:DIS: Checking node lookup status after 3 ms [1745220789.636778][6521:6523] CHIP:DIS: Keeping DNSSD lookup active [1745220789.834237][6521:6523] CHIP:DIS: Checking node lookup status after 200 ms [1745220789.834420][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540 while in state 2 [1745220789.834484][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1745220789.834800][6521:6523] CHIP:IN: SecureSession[0xffff9c00bd10]: Allocated Type:2 LSID:48998 [1745220789.834898][6521:6523] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1745220789.838070][6521:6523] CHIP:EM: <<< [E:14990i S:0 M:125890539] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1745220789.838632][6521:6523] CHIP:SC: Sent Sigma1 msg [1745220789.838702][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1745220792.598159][6521:6523] CHIP:EM: >>> [E:14990i S:0 M:74494557 (Ack:125890539)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220792.598254][6521:6523] CHIP:EM: Found matching exchange: 14990i, Delegate: 0xffff9c00ecd8 [1745220792.598330][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:125890539 from Retrans Table on exchange 14990i [1745220792.745469][6521:6523] CHIP:EM: >>> [E:14990i S:0 M:74494558 (Ack:125890539)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1745220792.745564][6521:6523] CHIP:EM: Found matching exchange: 14990i, Delegate: 0xffff9c00ecd8 [1745220792.745620][6521:6523] CHIP:EM: CHIP MessageCounter:125890539 not in RetransTable on exchange 14990i [1745220792.745716][6521:6523] CHIP:SC: Received Sigma2 msg [1745220792.745791][6521:6523] CHIP:SC: Peer assigned session session ID 24072 [1745220792.755269][6521:6523] CHIP:SC: Found MRP parameters in the message [1745220792.755398][6521:6523] CHIP:SC: Sending Sigma3 [1745220792.756890][6521:6523] CHIP:EM: <<< [E:14990i S:0 M:125890540 (Ack:74494558)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1745220792.757199][6521:6523] CHIP:SC: Sent Sigma3 msg [1745220793.186088][6521:6523] CHIP:EM: >>> [E:14990i S:0 M:74494559 (Ack:125890540)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220793.186182][6521:6523] CHIP:EM: Found matching exchange: 14990i, Delegate: 0xffff9c00ecd8 [1745220793.186257][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:125890540 from Retrans Table on exchange 14990i [1745220793.372649][6521:6523] CHIP:EM: >>> [E:14990i S:0 M:74494560 (Ack:125890540)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745220793.372702][6521:6523] CHIP:EM: Found matching exchange: 14990i, Delegate: 0xffff9c00ecd8 [1745220793.372732][6521:6523] CHIP:EM: CHIP MessageCounter:125890540 not in RetransTable on exchange 14990i [1745220793.372785][6521:6523] CHIP:SC: Success status report received. Session was established [1745220793.380050][6521:6523] CHIP:SC: SecureSession[0xffff9c00bd10, LSID:48998]: State change 'kEstablishing' --> 'kActive' [1745220793.380107][6521:6523] CHIP:IN: SecureSession[0xffff9c00bd10]: Activated - Type:2 LSID:48998 [1745220793.380127][6521:6523] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:48998 PSID:24072! [1745220793.380154][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1745220793.380247][6521:6523] CHIP:DMG: SendReadRequest ReadClient[0xffff9c00aa00]: Sending Read Request [1745220793.380539][6521:6523] CHIP:EM: <<< [E:14991i S:48998 M:246514773] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745220793.380800][6521:6523] CHIP:DMG: MoveToState ReadClient[0xffff9c00aa00]: Moving to [AwaitingIn] [1745220793.380978][6521:6523] CHIP:EM: <<< [E:14990i S:0 M:125890541 (Ack:74494560)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220793.381126][6521:6523] CHIP:EM: Flushed pending ack for MessageCounter:74494560 on exchange 14990i [1745220793.704704][6521:6523] CHIP:EM: >>> [E:14991i S:48998 M:106343063 (Ack:246514773)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745220793.704775][6521:6523] CHIP:EM: Found matching exchange: 14991i, Delegate: 0xffff9c00aa10 [1745220793.704832][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:246514773 from Retrans Table on exchange 14991i [1745220793.704923][6521:6523] CHIP:DMG: ReportDataMessage = [1745220793.704962][6521:6523] CHIP:DMG: { [1745220793.704993][6521:6523] CHIP:DMG: AttributeReportIBs = [1745220793.705039][6521:6523] CHIP:DMG: [ [1745220793.705074][6521:6523] CHIP:DMG: AttributeReportIB = [1745220793.705121][6521:6523] CHIP:DMG: { [1745220793.705159][6521:6523] CHIP:DMG: AttributeDataIB = [1745220793.705208][6521:6523] CHIP:DMG: { [1745220793.705253][6521:6523] CHIP:DMG: DataVersion = 0x83b08e5c, [1745220793.705298][6521:6523] CHIP:DMG: AttributePathIB = [1745220793.705343][6521:6523] CHIP:DMG: { [1745220793.705390][6521:6523] CHIP:DMG: Endpoint = 0x0, [1745220793.705438][6521:6523] CHIP:DMG: Cluster = 0x28, [1745220793.705488][6521:6523] CHIP:DMG: Attribute = 0x0000_0002, [1745220793.705533][6521:6523] CHIP:DMG: } [1745220793.705582][6521:6523] CHIP:DMG: [1745220793.705630][6521:6523] CHIP:DMG: Data = 5547, [1745220793.705672][6521:6523] CHIP:DMG: }, [1745220793.705719][6521:6523] CHIP:DMG: [1745220793.705755][6521:6523] CHIP:DMG: }, [1745220793.705803][6521:6523] CHIP:DMG: [1745220793.705837][6521:6523] CHIP:DMG: ], [1745220793.705879][6521:6523] CHIP:DMG: [1745220793.705915][6521:6523] CHIP:DMG: SuppressResponse = true, [1745220793.705951][6521:6523] CHIP:DMG: InteractionModelRevision = 11 [1745220793.705984][6521:6523] CHIP:DMG: } [1745220793.706186][6521:6523] CHIP:CTL: Received VID for the device. Value 5547 [1745220793.706222][6521:6523] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745220793.706257][6521:6523] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745220793.706304][6521:6523] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1745220793.706343][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1745220793.706472][6521:6523] CHIP:DMG: SendReadRequest ReadClient[0xffff9c00be50]: Sending Read Request [1745220793.706800][6521:6523] CHIP:EM: <<< [E:14992i S:48998 M:246514774] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745220793.707126][6521:6523] CHIP:DMG: MoveToState ReadClient[0xffff9c00be50]: Moving to [AwaitingIn] [1745220793.707411][6521:6523] CHIP:EM: <<< [E:14991i S:48998 M:246514775 (Ack:106343063)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220793.707621][6521:6523] CHIP:EM: Flushed pending ack for MessageCounter:106343063 on exchange 14991i [1745220794.217514][6521:6523] CHIP:EM: >>> [E:14992i S:48998 M:106343064 (Ack:246514774)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745220794.217608][6521:6523] CHIP:EM: Found matching exchange: 14992i, Delegate: 0xffff9c00be60 [1745220794.217684][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:246514774 from Retrans Table on exchange 14992i [1745220794.217803][6521:6523] CHIP:DMG: ReportDataMessage = [1745220794.217858][6521:6523] CHIP:DMG: { [1745220794.217901][6521:6523] CHIP:DMG: AttributeReportIBs = [1745220794.217967][6521:6523] CHIP:DMG: [ [1745220794.218017][6521:6523] CHIP:DMG: AttributeReportIB = [1745220794.218084][6521:6523] CHIP:DMG: { [1745220794.218137][6521:6523] CHIP:DMG: AttributeDataIB = [1745220794.218204][6521:6523] CHIP:DMG: { [1745220794.218269][6521:6523] CHIP:DMG: DataVersion = 0x83b08e5c, [1745220794.218355][6521:6523] CHIP:DMG: AttributePathIB = [1745220794.218473][6521:6523] CHIP:DMG: { [1745220794.218539][6521:6523] CHIP:DMG: Endpoint = 0x0, [1745220794.218603][6521:6523] CHIP:DMG: Cluster = 0x28, [1745220794.218673][6521:6523] CHIP:DMG: Attribute = 0x0000_0004, [1745220794.218739][6521:6523] CHIP:DMG: } [1745220794.218810][6521:6523] CHIP:DMG: [1745220794.218878][6521:6523] CHIP:DMG: Data = 1, [1745220794.218940][6521:6523] CHIP:DMG: }, [1745220794.219008][6521:6523] CHIP:DMG: [1745220794.219060][6521:6523] CHIP:DMG: }, [1745220794.219122][6521:6523] CHIP:DMG: [1745220794.219170][6521:6523] CHIP:DMG: ], [1745220794.219238][6521:6523] CHIP:DMG: [1745220794.219288][6521:6523] CHIP:DMG: SuppressResponse = true, [1745220794.219339][6521:6523] CHIP:DMG: InteractionModelRevision = 11 [1745220794.219389][6521:6523] CHIP:DMG: } [1745220794.219595][6521:6523] CHIP:CTL: Received PID for the device. Value 1 [1745220794.219646][6521:6523] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745220794.219694][6521:6523] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745220794.219757][6521:6523] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1745220794.219811][6521:6523] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1745220794.219872][6521:6523] CHIP:CTL: OpenCommissioningWindow for device ID 0x0000000000000001 [1745220794.220037][6521:6523] CHIP:DMG: ICR moving to [AddingComm] [1745220794.220156][6521:6523] CHIP:DMG: ICR moving to [AddedComma] [1745220794.220535][6521:6523] CHIP:EM: <<< [E:14993i S:48998 M:246514776] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:0A (IM:TimedRequest) [1745220794.220942][6521:6523] CHIP:DMG: ICR moving to [AwaitingTi] [1745220794.221320][6521:6523] CHIP:EM: <<< [E:14992i S:48998 M:246514777 (Ack:106343064)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220794.221597][6521:6523] CHIP:EM: Flushed pending ack for MessageCounter:106343064 on exchange 14992i [1745220794.726228][6521:6523] CHIP:EM: >>> [E:14993i S:48998 M:106343065 (Ack:246514776)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:01 (IM:StatusResponse) [1745220794.726284][6521:6523] CHIP:EM: Found matching exchange: 14993i, Delegate: 0xffff9c00f5d8 [1745220794.726326][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:246514776 from Retrans Table on exchange 14993i [1745220794.726427][6521:6523] CHIP:DMG: StatusResponseMessage = [1745220794.726455][6521:6523] CHIP:DMG: { [1745220794.726478][6521:6523] CHIP:DMG: Status = 0x00 (SUCCESS), [1745220794.726503][6521:6523] CHIP:DMG: InteractionModelRevision = 11 [1745220794.726525][6521:6523] CHIP:DMG: } [1745220794.726550][6521:6523] CHIP:IM: Received status response, status is 0x00 (SUCCESS) [1745220794.726766][6521:6523] CHIP:EM: <<< [E:14993i S:48998 M:246514778 (Ack:106343065)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1745220794.727012][6521:6523] CHIP:DMG: ICR moving to [AwaitingRe] [1745220795.261019][6521:6523] CHIP:EM: >>> [E:14993i S:48998 M:106343066 (Ack:246514778)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:09 (IM:InvokeCommandResponse) [1745220795.261070][6521:6523] CHIP:EM: Found matching exchange: 14993i, Delegate: 0xffff9c00f5d8 [1745220795.261105][6521:6523] CHIP:EM: Rxd Ack; Removing MessageCounter:246514778 from Retrans Table on exchange 14993i [1745220795.261140][6521:6523] CHIP:DMG: ICR moving to [ResponseRe] [1745220795.261187][6521:6523] CHIP:DMG: InvokeResponseMessage = [1745220795.261207][6521:6523] CHIP:DMG: { [1745220795.261226][6521:6523] CHIP:DMG: suppressResponse = false, [1745220795.261245][6521:6523] CHIP:DMG: InvokeResponseIBs = [1745220795.261271][6521:6523] CHIP:DMG: [ [1745220795.261290][6521:6523] CHIP:DMG: InvokeResponseIB = [1745220795.261336][6521:6523] CHIP:DMG: { [1745220795.261357][6521:6523] CHIP:DMG: CommandStatusIB = [1745220795.261390][6521:6523] CHIP:DMG: { [1745220795.261413][6521:6523] CHIP:DMG: CommandPathIB = [1745220795.261442][6521:6523] CHIP:DMG: { [1745220795.261480][6521:6523] CHIP:DMG: EndpointId = 0x0, [1745220795.261508][6521:6523] CHIP:DMG: ClusterId = 0x3c, [1745220795.261543][6521:6523] CHIP:DMG: CommandId = 0x0, [1745220795.261568][6521:6523] CHIP:DMG: }, [1745220795.261606][6521:6523] CHIP:DMG: [1745220795.261630][6521:6523] CHIP:DMG: StatusIB = [1745220795.261671][6521:6523] CHIP:DMG: { [1745220795.261711][6521:6523] CHIP:DMG: status = 0x00 (SUCCESS), [1745220795.261760][6521:6523] CHIP:DMG: }, [1745220795.261799][6521:6523] CHIP:DMG: [1745220795.261833][6521:6523] CHIP:DMG: }, [1745220795.262041][6521:6523] CHIP:DMG: [1745220795.262073][6521:6523] CHIP:DMG: }, [1745220795.262110][6521:6523] CHIP:DMG: [1745220795.262138][6521:6523] CHIP:DMG: ], [1745220795.262186][6521:6523] CHIP:DMG: [1745220795.262215][6521:6523] CHIP:DMG: InteractionModelRevision = 11 [1745220795.262244][6521:6523] CHIP:DMG: }, [1745220795.262335][6521:6523] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1745220795.262478][6521:6523] CHIP:CTL: Successfully opened pairing window on the device [1745220795.262566][6521:6523] CHIP:CTL: Manual pairing code: [33153621619] [1745220795.262617][6521:6523] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ427D1AS7GS00] [1745220795.262722][6521:6523] CHIP:DMG: ICR moving to [AwaitingDe] [1745220795.263063][6521:6523] CHIP:EM: <<< [E:14993i S:48998 M:246514779 (Ack:106343066)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745220795.263310][6521:6523] CHIP:EM: Flushed pending ack for MessageCounter:106343066 on exchange 14993i [1745220795.263574][6521:6521] CHIP:CTL: Shutting down the commissioner [1745220795.263692][6521:6521] CHIP:CTL: Shutting down the controller [1745220795.263729][6521:6521] CHIP:IN: Expiring all sessions for fabric 0x1!! [1745220795.263757][6521:6521] CHIP:IN: SecureSession[0xffff9c00bd10]: MarkForEviction Type:2 LSID:48998 [1745220795.263786][6521:6521] CHIP:SC: SecureSession[0xffff9c00bd10, LSID:48998]: State change 'kActive' --> 'kPendingEviction' [1745220795.263813][6521:6521] CHIP:IN: SecureSession[0xffff9c00bd10]: Released - Type:2 LSID:48998 [1745220795.263845][6521:6521] CHIP:FP: Forgetting fabric 0x1 [1745220795.263888][6521:6521] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745220795.264416][6521:6521] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745220795.264461][6521:6521] CHIP:TS: Reverted Last Known Good Time to previous value [1745220795.264525][6521:6521] CHIP:CTL: Shutting down the commissioner [1745220795.264632][6521:6521] CHIP:CTL: Shutting down the controller [1745220795.264660][6521:6521] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1745220795.264856][6521:6521] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1745220795.264973][6521:6521] CHIP:FP: Shutting down FabricTable [1745220795.265015][6521:6521] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745220795.265429][6521:6521] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745220795.265472][6521:6521] CHIP:TS: Reverted Last Known Good Time to previous value [1745220795.265808][6521:6521] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-VEHQDu) [1745220795.266664][6521:6521] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745220795.266748][6521:6521] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1745220795.266780][6521:6521] CHIP:DL: Inet Layer shutdown [1745220795.266805][6521:6521] CHIP:DL: BLE shutdown [1745220795.266836][6521:6521] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool administratorcommissioning read window-status 1 0 [1745221701.869006][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1745221701.870802][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1745221701.870840][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1745221701.876036][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1745221701.876292][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1745221701.876398][6566:6566] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1745221701.876736][6566:6566] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DE3bXw) [1745221701.877311][6566:6566] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221701.877362][6566:6566] CHIP:DL: NVS set: chip-counters/reboot-count = 259 (0x103) [1745221701.878231][6566:6566] CHIP:DL: Got Ethernet interface: eth0 [1745221701.878864][6566:6566] CHIP:DL: Found the primary Ethernet interface:eth0 [1745221701.879455][6566:6566] CHIP:DL: Got WiFi interface: wlan0 [1745221701.879519][6566:6566] CHIP:DL: Failed to reset WiFi statistic counts [1745221701.879573][6566:6566] CHIP:IN: UDP::Init bind&listen port=0 [1745221701.879676][6566:6566] CHIP:IN: UDP::Init bound to port=59653 [1745221701.879697][6566:6566] CHIP:IN: BLEBase::Init - setting/overriding transport [1745221701.879714][6566:6566] CHIP:IN: TransportMgr initialized [1745221701.879762][6566:6566] CHIP:FP: Initializing FabricTable from persistent storage [1745221701.880116][6566:6566] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221701.882112][6566:6566] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1CB8E8FD2A1604E0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.882971][6566:6566] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE7FC514BD95AD5D2, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.883733][6566:6566] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x831C65382602B3B5, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.884485][6566:6566] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xD9D01CB0D050EB4D, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.885227][6566:6566] CHIP:FP: Fabric index 0x5 was retrieved from storage. Compressed FabricId 0x0B7BB6E8F0F51EC7, FabricId 0x0000000000000005, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.885968][6566:6566] CHIP:FP: Fabric index 0x6 was retrieved from storage. Compressed FabricId 0x46A3CEF59284B985, FabricId 0x0000000000000006, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221701.890842][6566:6566] CHIP:ZCL: Using ZAP configuration... [1745221701.894425][6566:6566] CHIP:DL: Avahi client registered [1745221701.894550][6566:6566] CHIP:CTL: System State Initialized... [1745221701.894719][6566:6566] CHIP:CTL: Setting attestation nonce to random value [1745221701.894757][6566:6566] CHIP:CTL: Setting CSR nonce to random value [1745221701.894826][6566:6566] CHIP:IN: UDP::Init bind&listen port=5550 [1745221701.894946][6566:6566] CHIP:IN: UDP::Init bound to port=5550 [1745221701.894966][6566:6566] CHIP:IN: TransportMgr initialized [1745221701.895215][6566:6568] CHIP:DL: CHIP task running [1745221701.895408][6566:6568] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1745221701.895717][6566:6568] CHIP:CTL: Setting attestation nonce to random value [1745221701.895874][6566:6568] CHIP:CTL: Setting CSR nonce to random value [1745221701.896663][6566:6568] CHIP:CTL: Generating NOC [1745221701.898133][6566:6568] CHIP:FP: Validating NOC chain [1745221701.900059][6566:6568] CHIP:FP: NOC chain validation successful [1745221701.900234][6566:6568] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1745221701.900268][6566:6568] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221701.900292][6566:6568] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1745221701.900312][6566:6568] CHIP:TS: Retaining current Last Known Good Time [1745221701.912741][6566:6568] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1745221701.916975][6566:6568] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1745221701.921619][6566:6568] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1CB8E8FD2A1604E0) [1745221701.921680][6566:6568] CHIP:IN: UDP::Init bind&listen port=5550 [1745221701.921794][6566:6568] CHIP:IN: UDP::Init bound to port=5550 [1745221701.921816][6566:6568] CHIP:IN: TransportMgr initialized [1745221701.957761][6566:6568] CHIP:TOO: Sending command to node 0x1 [1745221701.961021][6566:6568] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745221701.961065][6566:6568] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745221701.961101][6566:6568] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1745221701.961134][6566:6568] CHIP:DIS: Resolving 1CB8E8FD2A1604E0:0000000000000001 ... [1745221702.069180][6566:6568] CHIP:DL: Avahi resolve found [1745221702.069338][6566:6568] CHIP:DIS: Node ID resolved for 1CB8E8FD2A1604E0:0000000000000001 [1745221702.069398][6566:6568] CHIP:DIS: Hostname: 2E4E2FDC6206DD75 [1745221702.069466][6566:6568] CHIP:DIS: IP Address #1: fd11:22::c163:73cb:f8c5:2cad [1745221702.069525][6566:6568] CHIP:DIS: Port: 5540 [1745221702.069581][6566:6568] CHIP:DIS: Mrp Interval idle: 5000 ms [1745221702.069635][6566:6568] CHIP:DIS: Mrp Interval active: 2500 ms [1745221702.069690][6566:6568] CHIP:DIS: Mrp Active Threshold: 500 ms [1745221702.069744][6566:6568] CHIP:DIS: TCP Supported: 0 [1745221702.069797][6566:6568] CHIP:DIS: ICD: not present [1745221702.071573][6566:6568] CHIP:DIS: Lookup clearing interface for non LL address [1745221702.071799][6566:6568] CHIP:DIS: UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540: new best score: 3 [1745221702.071861][6566:6568] CHIP:DIS: Checking node lookup status after 111 ms [1745221702.071913][6566:6568] CHIP:DIS: Keeping DNSSD lookup active [1745221702.161017][6566:6568] CHIP:DIS: Checking node lookup status after 200 ms [1745221702.161137][6566:6568] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540 while in state 2 [1745221702.161189][6566:6568] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1745221702.161466][6566:6568] CHIP:IN: SecureSession[0xffffac00d570]: Allocated Type:2 LSID:26219 [1745221702.161552][6566:6568] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1745221702.164546][6566:6568] CHIP:EM: <<< [E:52067i S:0 M:201387566] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1745221702.165059][6566:6568] CHIP:SC: Sent Sigma1 msg [1745221702.165134][6566:6568] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1745221704.866006][6566:6568] CHIP:EM: >>> [E:52067i S:0 M:74494561 (Ack:201387566)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221704.866099][6566:6568] CHIP:EM: Found matching exchange: 52067i, Delegate: 0xffffac014bd8 [1745221704.866174][6566:6568] CHIP:EM: Rxd Ack; Removing MessageCounter:201387566 from Retrans Table on exchange 52067i [1745221705.008449][6566:6568] CHIP:EM: >>> [E:52067i S:0 M:74494562 (Ack:201387566)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1745221705.008544][6566:6568] CHIP:EM: Found matching exchange: 52067i, Delegate: 0xffffac014bd8 [1745221705.008599][6566:6568] CHIP:EM: CHIP MessageCounter:201387566 not in RetransTable on exchange 52067i [1745221705.008696][6566:6568] CHIP:SC: Received Sigma2 msg [1745221705.008771][6566:6568] CHIP:SC: Peer assigned session session ID 24073 [1745221705.017201][6566:6568] CHIP:SC: Found MRP parameters in the message [1745221705.017288][6566:6568] CHIP:SC: Sending Sigma3 [1745221705.018606][6566:6568] CHIP:EM: <<< [E:52067i S:0 M:201387567 (Ack:74494562)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1745221705.018932][6566:6568] CHIP:SC: Sent Sigma3 msg [1745221705.447785][6566:6568] CHIP:EM: >>> [E:52067i S:0 M:74494563 (Ack:201387567)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221705.447845][6566:6568] CHIP:EM: Found matching exchange: 52067i, Delegate: 0xffffac014bd8 [1745221705.447890][6566:6568] CHIP:EM: Rxd Ack; Removing MessageCounter:201387567 from Retrans Table on exchange 52067i [1745221705.633573][6566:6568] CHIP:EM: >>> [E:52067i S:0 M:74494564 (Ack:201387567)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745221705.633674][6566:6568] CHIP:EM: Found matching exchange: 52067i, Delegate: 0xffffac014bd8 [1745221705.633736][6566:6568] CHIP:EM: CHIP MessageCounter:201387567 not in RetransTable on exchange 52067i [1745221705.633844][6566:6568] CHIP:SC: Success status report received. Session was established [1745221705.647814][6566:6568] CHIP:SC: SecureSession[0xffffac00d570, LSID:26219]: State change 'kEstablishing' --> 'kActive' [1745221705.647870][6566:6568] CHIP:IN: SecureSession[0xffffac00d570]: Activated - Type:2 LSID:26219 [1745221705.647889][6566:6568] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:26219 PSID:24073! [1745221705.647918][6566:6568] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1745221705.647989][6566:6568] CHIP:TOO: Sending ReadAttribute to: [1745221705.648058][6566:6568] CHIP:TOO: cluster 0x0000_003C, attribute: 0x0000_0000, endpoint 0 [1745221705.648096][6566:6568] CHIP:DMG: SendReadRequest ReadClient[0xffffac00f800]: Sending Read Request [1745221705.648373][6566:6568] CHIP:EM: <<< [E:52068i S:26219 M:89646574] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745221705.648637][6566:6568] CHIP:DMG: MoveToState ReadClient[0xffffac00f800]: Moving to [AwaitingIn] [1745221705.648810][6566:6568] CHIP:EM: <<< [E:52067i S:0 M:201387568 (Ack:74494564)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221705.648959][6566:6568] CHIP:EM: Flushed pending ack for MessageCounter:74494564 on exchange 52067i [1745221705.959275][6566:6568] CHIP:EM: >>> [E:52068i S:26219 M:58917237 (Ack:89646574)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745221705.959359][6566:6568] CHIP:EM: Found matching exchange: 52068i, Delegate: 0xffffac00f810 [1745221705.959426][6566:6568] CHIP:EM: Rxd Ack; Removing MessageCounter:89646574 from Retrans Table on exchange 52068i [1745221705.959534][6566:6568] CHIP:DMG: ReportDataMessage = [1745221705.959581][6566:6568] CHIP:DMG: { [1745221705.959620][6566:6568] CHIP:DMG: AttributeReportIBs = [1745221705.959677][6566:6568] CHIP:DMG: [ [1745221705.959721][6566:6568] CHIP:DMG: AttributeReportIB = [1745221705.959781][6566:6568] CHIP:DMG: { [1745221705.959828][6566:6568] CHIP:DMG: AttributeDataIB = [1745221705.959880][6566:6568] CHIP:DMG: { [1745221705.959938][6566:6568] CHIP:DMG: DataVersion = 0xc76fd7de, [1745221705.959993][6566:6568] CHIP:DMG: AttributePathIB = [1745221705.960049][6566:6568] CHIP:DMG: { [1745221705.960106][6566:6568] CHIP:DMG: Endpoint = 0x0, [1745221705.960173][6566:6568] CHIP:DMG: Cluster = 0x3c, [1745221705.960233][6566:6568] CHIP:DMG: Attribute = 0x0000_0000, [1745221705.960287][6566:6568] CHIP:DMG: } [1745221705.960347][6566:6568] CHIP:DMG: [1745221705.960407][6566:6568] CHIP:DMG: Data = 0, [1745221705.960459][6566:6568] CHIP:DMG: }, [1745221705.960515][6566:6568] CHIP:DMG: [1745221705.960561][6566:6568] CHIP:DMG: }, [1745221705.960620][6566:6568] CHIP:DMG: [1745221705.960662][6566:6568] CHIP:DMG: ], [1745221705.960716][6566:6568] CHIP:DMG: [1745221705.960760][6566:6568] CHIP:DMG: SuppressResponse = true, [1745221705.960804][6566:6568] CHIP:DMG: InteractionModelRevision = 11 [1745221705.960846][6566:6568] CHIP:DMG: } [1745221705.961088][6566:6568] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003C Attribute 0x0000_0000 DataVersion: 3345995742 [1745221705.961211][6566:6568] CHIP:TOO: WindowStatus: 0 [1745221705.961617][6566:6568] CHIP:EM: <<< [E:52068i S:26219 M:89646575 (Ack:58917237)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221705.961925][6566:6568] CHIP:EM: Flushed pending ack for MessageCounter:58917237 on exchange 52068i [1745221705.962284][6566:6566] CHIP:CTL: Shutting down the commissioner [1745221705.962483][6566:6566] CHIP:CTL: Shutting down the controller [1745221705.962571][6566:6566] CHIP:IN: Expiring all sessions for fabric 0x1!! [1745221705.962615][6566:6566] CHIP:IN: SecureSession[0xffffac00d570]: MarkForEviction Type:2 LSID:26219 [1745221705.962658][6566:6566] CHIP:SC: SecureSession[0xffffac00d570, LSID:26219]: State change 'kActive' --> 'kPendingEviction' [1745221705.962723][6566:6566] CHIP:IN: SecureSession[0xffffac00d570]: Released - Type:2 LSID:26219 [1745221705.962856][6566:6566] CHIP:FP: Forgetting fabric 0x1 [1745221705.962922][6566:6566] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221705.963779][6566:6566] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221705.963836][6566:6566] CHIP:TS: Reverted Last Known Good Time to previous value [1745221705.963914][6566:6566] CHIP:CTL: Shutting down the commissioner [1745221705.964061][6566:6566] CHIP:CTL: Shutting down the controller [1745221705.964103][6566:6566] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1745221705.964405][6566:6566] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1745221705.964589][6566:6566] CHIP:FP: Shutting down FabricTable [1745221705.964656][6566:6566] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221705.965275][6566:6566] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221705.965334][6566:6566] CHIP:TS: Reverted Last Known Good Time to previous value [1745221705.965823][6566:6566] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GqUnor) [1745221705.966919][6566:6566] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221705.967029][6566:6566] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1745221705.967076][6566:6566] CHIP:DL: Inet Layer shutdown [1745221705.967114][6566:6566] CHIP:DL: BLE shutdown [1745221705.967158][6566:6566] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool pairing open-commissioning-window 1 1 901 2000 3423 [1745221715.589595][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1745221715.591461][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1745221715.591498][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1745221715.596788][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1745221715.597061][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1745221715.597174][6570:6570] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1745221715.597489][6570:6570] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-XWEUSb) [1745221715.598086][6570:6570] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221715.598140][6570:6570] CHIP:DL: NVS set: chip-counters/reboot-count = 260 (0x104) [1745221715.599054][6570:6570] CHIP:DL: Got Ethernet interface: eth0 [1745221715.599625][6570:6570] CHIP:DL: Found the primary Ethernet interface:eth0 [1745221715.600207][6570:6570] CHIP:DL: Got WiFi interface: wlan0 [1745221715.600269][6570:6570] CHIP:DL: Failed to reset WiFi statistic counts [1745221715.600320][6570:6570] CHIP:IN: UDP::Init bind&listen port=0 [1745221715.600425][6570:6570] CHIP:IN: UDP::Init bound to port=49712 [1745221715.600445][6570:6570] CHIP:IN: BLEBase::Init - setting/overriding transport [1745221715.600462][6570:6570] CHIP:IN: TransportMgr initialized [1745221715.600509][6570:6570] CHIP:FP: Initializing FabricTable from persistent storage [1745221715.600863][6570:6570] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221715.602917][6570:6570] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1CB8E8FD2A1604E0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.603767][6570:6570] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE7FC514BD95AD5D2, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.604536][6570:6570] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x831C65382602B3B5, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.605304][6570:6570] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xD9D01CB0D050EB4D, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.606060][6570:6570] CHIP:FP: Fabric index 0x5 was retrieved from storage. Compressed FabricId 0x0B7BB6E8F0F51EC7, FabricId 0x0000000000000005, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.606834][6570:6570] CHIP:FP: Fabric index 0x6 was retrieved from storage. Compressed FabricId 0x46A3CEF59284B985, FabricId 0x0000000000000006, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221715.611782][6570:6570] CHIP:ZCL: Using ZAP configuration... [1745221715.615503][6570:6570] CHIP:DL: Avahi client registered [1745221715.615627][6570:6570] CHIP:CTL: System State Initialized... [1745221715.615781][6570:6570] CHIP:CTL: Setting attestation nonce to random value [1745221715.615818][6570:6570] CHIP:CTL: Setting CSR nonce to random value [1745221715.615888][6570:6570] CHIP:IN: UDP::Init bind&listen port=5550 [1745221715.616004][6570:6570] CHIP:IN: UDP::Init bound to port=5550 [1745221715.616024][6570:6570] CHIP:IN: TransportMgr initialized [1745221715.616273][6570:6572] CHIP:DL: CHIP task running [1745221715.616446][6570:6572] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1745221715.616779][6570:6572] CHIP:CTL: Setting attestation nonce to random value [1745221715.616959][6570:6572] CHIP:CTL: Setting CSR nonce to random value [1745221715.617872][6570:6572] CHIP:CTL: Generating NOC [1745221715.619489][6570:6572] CHIP:FP: Validating NOC chain [1745221715.621372][6570:6572] CHIP:FP: NOC chain validation successful [1745221715.621539][6570:6572] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1745221715.621572][6570:6572] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221715.621594][6570:6572] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1745221715.621615][6570:6572] CHIP:TS: Retaining current Last Known Good Time [1745221715.634353][6570:6572] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1745221715.639049][6570:6572] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1745221715.644155][6570:6572] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1CB8E8FD2A1604E0) [1745221715.644215][6570:6572] CHIP:IN: UDP::Init bind&listen port=5550 [1745221715.644324][6570:6572] CHIP:IN: UDP::Init bound to port=5550 [1745221715.644344][6570:6572] CHIP:IN: TransportMgr initialized [1745221715.687892][6570:6572] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745221715.687945][6570:6572] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745221715.687978][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1745221715.688011][6570:6572] CHIP:DIS: Resolving 1CB8E8FD2A1604E0:0000000000000001 ... [1745221715.689678][6570:6572] CHIP:DL: Avahi resolve found [1745221715.689750][6570:6572] CHIP:DIS: Node ID resolved for 1CB8E8FD2A1604E0:0000000000000001 [1745221715.689771][6570:6572] CHIP:DIS: Hostname: 2E4E2FDC6206DD75 [1745221715.689794][6570:6572] CHIP:DIS: IP Address #1: fd11:22::c163:73cb:f8c5:2cad [1745221715.689813][6570:6572] CHIP:DIS: Port: 5540 [1745221715.689832][6570:6572] CHIP:DIS: Mrp Interval idle: 5000 ms [1745221715.689850][6570:6572] CHIP:DIS: Mrp Interval active: 2500 ms [1745221715.689868][6570:6572] CHIP:DIS: Mrp Active Threshold: 500 ms [1745221715.689887][6570:6572] CHIP:DIS: TCP Supported: 0 [1745221715.689904][6570:6572] CHIP:DIS: ICD: not present [1745221715.690697][6570:6572] CHIP:DIS: Lookup clearing interface for non LL address [1745221715.690786][6570:6572] CHIP:DIS: UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540: new best score: 3 [1745221715.690808][6570:6572] CHIP:DIS: Checking node lookup status after 3 ms [1745221715.690825][6570:6572] CHIP:DIS: Keeping DNSSD lookup active [1745221715.888217][6570:6572] CHIP:DIS: Checking node lookup status after 200 ms [1745221715.888359][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540 while in state 2 [1745221715.888420][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1745221715.888734][6570:6572] CHIP:IN: SecureSession[0xffffa40145e0]: Allocated Type:2 LSID:15835 [1745221715.888836][6570:6572] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1745221715.892341][6570:6572] CHIP:EM: <<< [E:24158i S:0 M:221831374] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1745221715.892971][6570:6572] CHIP:SC: Sent Sigma1 msg [1745221715.893061][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1745221718.602104][6570:6572] CHIP:EM: >>> [E:24158i S:0 M:74494565 (Ack:221831374)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221718.602168][6570:6572] CHIP:EM: Found matching exchange: 24158i, Delegate: 0xffffa4014798 [1745221718.602215][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:221831374 from Retrans Table on exchange 24158i [1745221718.745456][6570:6572] CHIP:EM: >>> [E:24158i S:0 M:74494566 (Ack:221831374)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1745221718.745549][6570:6572] CHIP:EM: Found matching exchange: 24158i, Delegate: 0xffffa4014798 [1745221718.745606][6570:6572] CHIP:EM: CHIP MessageCounter:221831374 not in RetransTable on exchange 24158i [1745221718.745702][6570:6572] CHIP:SC: Received Sigma2 msg [1745221718.745777][6570:6572] CHIP:SC: Peer assigned session session ID 24075 [1745221718.754838][6570:6572] CHIP:SC: Found MRP parameters in the message [1745221718.754965][6570:6572] CHIP:SC: Sending Sigma3 [1745221718.757094][6570:6572] CHIP:EM: <<< [E:24158i S:0 M:221831375 (Ack:74494566)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1745221718.757406][6570:6572] CHIP:SC: Sent Sigma3 msg [1745221719.184193][6570:6572] CHIP:EM: >>> [E:24158i S:0 M:74494567 (Ack:221831375)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221719.184284][6570:6572] CHIP:EM: Found matching exchange: 24158i, Delegate: 0xffffa4014798 [1745221719.184358][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:221831375 from Retrans Table on exchange 24158i [1745221719.370873][6570:6572] CHIP:EM: >>> [E:24158i S:0 M:74494568 (Ack:221831375)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745221719.370974][6570:6572] CHIP:EM: Found matching exchange: 24158i, Delegate: 0xffffa4014798 [1745221719.371035][6570:6572] CHIP:EM: CHIP MessageCounter:221831375 not in RetransTable on exchange 24158i [1745221719.371144][6570:6572] CHIP:SC: Success status report received. Session was established [1745221719.385439][6570:6572] CHIP:SC: SecureSession[0xffffa40145e0, LSID:15835]: State change 'kEstablishing' --> 'kActive' [1745221719.385500][6570:6572] CHIP:IN: SecureSession[0xffffa40145e0]: Activated - Type:2 LSID:15835 [1745221719.385530][6570:6572] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:15835 PSID:24075! [1745221719.385558][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1745221719.385654][6570:6572] CHIP:DMG: SendReadRequest ReadClient[0xffffa400e8a0]: Sending Read Request [1745221719.385953][6570:6572] CHIP:EM: <<< [E:24159i S:15835 M:98357585] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745221719.386354][6570:6572] CHIP:DMG: MoveToState ReadClient[0xffffa400e8a0]: Moving to [AwaitingIn] [1745221719.386644][6570:6572] CHIP:EM: <<< [E:24158i S:0 M:221831376 (Ack:74494568)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221719.386829][6570:6572] CHIP:EM: Flushed pending ack for MessageCounter:74494568 on exchange 24158i [1745221719.696625][6570:6572] CHIP:EM: >>> [E:24159i S:15835 M:106900471 (Ack:98357585)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745221719.696718][6570:6572] CHIP:EM: Found matching exchange: 24159i, Delegate: 0xffffa400e8b0 [1745221719.696793][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:98357585 from Retrans Table on exchange 24159i [1745221719.696913][6570:6572] CHIP:DMG: ReportDataMessage = [1745221719.696966][6570:6572] CHIP:DMG: { [1745221719.697010][6570:6572] CHIP:DMG: AttributeReportIBs = [1745221719.697074][6570:6572] CHIP:DMG: [ [1745221719.697124][6570:6572] CHIP:DMG: AttributeReportIB = [1745221719.697190][6570:6572] CHIP:DMG: { [1745221719.697243][6570:6572] CHIP:DMG: AttributeDataIB = [1745221719.697311][6570:6572] CHIP:DMG: { [1745221719.697373][6570:6572] CHIP:DMG: DataVersion = 0x83b08e5c, [1745221719.697482][6570:6572] CHIP:DMG: AttributePathIB = [1745221719.697549][6570:6572] CHIP:DMG: { [1745221719.697614][6570:6572] CHIP:DMG: Endpoint = 0x0, [1745221719.697686][6570:6572] CHIP:DMG: Cluster = 0x28, [1745221719.697756][6570:6572] CHIP:DMG: Attribute = 0x0000_0002, [1745221719.697822][6570:6572] CHIP:DMG: } [1745221719.697898][6570:6572] CHIP:DMG: [1745221719.697966][6570:6572] CHIP:DMG: Data = 5547, [1745221719.698025][6570:6572] CHIP:DMG: }, [1745221719.698089][6570:6572] CHIP:DMG: [1745221719.698142][6570:6572] CHIP:DMG: }, [1745221719.698203][6570:6572] CHIP:DMG: [1745221719.698251][6570:6572] CHIP:DMG: ], [1745221719.698312][6570:6572] CHIP:DMG: [1745221719.698362][6570:6572] CHIP:DMG: SuppressResponse = true, [1745221719.698480][6570:6572] CHIP:DMG: InteractionModelRevision = 11 [1745221719.698535][6570:6572] CHIP:DMG: } [1745221719.698818][6570:6572] CHIP:CTL: Received VID for the device. Value 5547 [1745221719.698870][6570:6572] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745221719.698918][6570:6572] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745221719.698983][6570:6572] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1745221719.699038][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1745221719.699154][6570:6572] CHIP:DMG: SendReadRequest ReadClient[0xffffa400cd70]: Sending Read Request [1745221719.699593][6570:6572] CHIP:EM: <<< [E:24160i S:15835 M:98357586] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745221719.700007][6570:6572] CHIP:DMG: MoveToState ReadClient[0xffffa400cd70]: Moving to [AwaitingIn] [1745221719.700422][6570:6572] CHIP:EM: <<< [E:24159i S:15835 M:98357587 (Ack:106900471)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221719.700704][6570:6572] CHIP:EM: Flushed pending ack for MessageCounter:106900471 on exchange 24159i [1745221720.207948][6570:6572] CHIP:EM: >>> [E:24160i S:15835 M:106900472 (Ack:98357586)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745221720.208010][6570:6572] CHIP:EM: Found matching exchange: 24160i, Delegate: 0xffffa400cd80 [1745221720.208055][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:98357586 from Retrans Table on exchange 24160i [1745221720.208129][6570:6572] CHIP:DMG: ReportDataMessage = [1745221720.208158][6570:6572] CHIP:DMG: { [1745221720.208182][6570:6572] CHIP:DMG: AttributeReportIBs = [1745221720.208217][6570:6572] CHIP:DMG: [ [1745221720.208244][6570:6572] CHIP:DMG: AttributeReportIB = [1745221720.208280][6570:6572] CHIP:DMG: { [1745221720.208308][6570:6572] CHIP:DMG: AttributeDataIB = [1745221720.208348][6570:6572] CHIP:DMG: { [1745221720.208382][6570:6572] CHIP:DMG: DataVersion = 0x83b08e5c, [1745221720.208414][6570:6572] CHIP:DMG: AttributePathIB = [1745221720.208448][6570:6572] CHIP:DMG: { [1745221720.208483][6570:6572] CHIP:DMG: Endpoint = 0x0, [1745221720.208520][6570:6572] CHIP:DMG: Cluster = 0x28, [1745221720.208556][6570:6572] CHIP:DMG: Attribute = 0x0000_0004, [1745221720.208591][6570:6572] CHIP:DMG: } [1745221720.208628][6570:6572] CHIP:DMG: [1745221720.208664][6570:6572] CHIP:DMG: Data = 1, [1745221720.208697][6570:6572] CHIP:DMG: }, [1745221720.208731][6570:6572] CHIP:DMG: [1745221720.208759][6570:6572] CHIP:DMG: }, [1745221720.208792][6570:6572] CHIP:DMG: [1745221720.208818][6570:6572] CHIP:DMG: ], [1745221720.208851][6570:6572] CHIP:DMG: [1745221720.208878][6570:6572] CHIP:DMG: SuppressResponse = true, [1745221720.208909][6570:6572] CHIP:DMG: InteractionModelRevision = 11 [1745221720.208935][6570:6572] CHIP:DMG: } [1745221720.209053][6570:6572] CHIP:CTL: Received PID for the device. Value 1 [1745221720.209081][6570:6572] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745221720.209106][6570:6572] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745221720.209143][6570:6572] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1745221720.209174][6570:6572] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1745221720.209212][6570:6572] CHIP:CTL: OpenCommissioningWindow for device ID 0x0000000000000001 [1745221720.209324][6570:6572] CHIP:DMG: ICR moving to [AddingComm] [1745221720.209392][6570:6572] CHIP:DMG: ICR moving to [AddedComma] [1745221720.209658][6570:6572] CHIP:EM: <<< [E:24161i S:15835 M:98357588] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:0A (IM:TimedRequest) [1745221720.209934][6570:6572] CHIP:DMG: ICR moving to [AwaitingTi] [1745221720.210236][6570:6572] CHIP:EM: <<< [E:24160i S:15835 M:98357589 (Ack:106900472)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221720.210437][6570:6572] CHIP:EM: Flushed pending ack for MessageCounter:106900472 on exchange 24160i [1745221720.721961][6570:6572] CHIP:EM: >>> [E:24161i S:15835 M:106900473 (Ack:98357588)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:01 (IM:StatusResponse) [1745221720.722027][6570:6572] CHIP:EM: Found matching exchange: 24161i, Delegate: 0xffffa400f5e8 [1745221720.722075][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:98357588 from Retrans Table on exchange 24161i [1745221720.722141][6570:6572] CHIP:DMG: StatusResponseMessage = [1745221720.722172][6570:6572] CHIP:DMG: { [1745221720.722199][6570:6572] CHIP:DMG: Status = 0x00 (SUCCESS), [1745221720.722227][6570:6572] CHIP:DMG: InteractionModelRevision = 11 [1745221720.722253][6570:6572] CHIP:DMG: } [1745221720.722281][6570:6572] CHIP:IM: Received status response, status is 0x00 (SUCCESS) [1745221720.722599][6570:6572] CHIP:EM: <<< [E:24161i S:15835 M:98357590 (Ack:106900473)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1745221720.722908][6570:6572] CHIP:DMG: ICR moving to [AwaitingRe] [1745221721.361161][6570:6572] CHIP:EM: >>> [E:24161i S:15835 M:106900474 (Ack:98357590)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:09 (IM:InvokeCommandResponse) [1745221721.361241][6570:6572] CHIP:EM: Found matching exchange: 24161i, Delegate: 0xffffa400f5e8 [1745221721.361303][6570:6572] CHIP:EM: Rxd Ack; Removing MessageCounter:98357590 from Retrans Table on exchange 24161i [1745221721.361362][6570:6572] CHIP:DMG: ICR moving to [ResponseRe] [1745221721.361450][6570:6572] CHIP:DMG: InvokeResponseMessage = [1745221721.361496][6570:6572] CHIP:DMG: { [1745221721.361562][6570:6572] CHIP:DMG: suppressResponse = false, [1745221721.361629][6570:6572] CHIP:DMG: InvokeResponseIBs = [1745221721.361703][6570:6572] CHIP:DMG: [ [1745221721.361761][6570:6572] CHIP:DMG: InvokeResponseIB = [1745221721.361878][6570:6572] CHIP:DMG: { [1745221721.361951][6570:6572] CHIP:DMG: CommandStatusIB = [1745221721.362017][6570:6572] CHIP:DMG: { [1745221721.362101][6570:6572] CHIP:DMG: CommandPathIB = [1745221721.362171][6570:6572] CHIP:DMG: { [1745221721.362247][6570:6572] CHIP:DMG: EndpointId = 0x0, [1745221721.362345][6570:6572] CHIP:DMG: ClusterId = 0x3c, [1745221721.362506][6570:6572] CHIP:DMG: CommandId = 0x0, [1745221721.362578][6570:6572] CHIP:DMG: }, [1745221721.362781][6570:6572] CHIP:DMG: [1745221721.362844][6570:6572] CHIP:DMG: StatusIB = [1745221721.362919][6570:6572] CHIP:DMG: { [1745221721.362993][6570:6572] CHIP:DMG: status = 0x00 (SUCCESS), [1745221721.363060][6570:6572] CHIP:DMG: }, [1745221721.363151][6570:6572] CHIP:DMG: [1745221721.363228][6570:6572] CHIP:DMG: }, [1745221721.363302][6570:6572] CHIP:DMG: [1745221721.363380][6570:6572] CHIP:DMG: }, [1745221721.363451][6570:6572] CHIP:DMG: [1745221721.363503][6570:6572] CHIP:DMG: ], [1745221721.363571][6570:6572] CHIP:DMG: [1745221721.363622][6570:6572] CHIP:DMG: InteractionModelRevision = 11 [1745221721.363674][6570:6572] CHIP:DMG: }, [1745221721.363822][6570:6572] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1745221721.363885][6570:6572] CHIP:CTL: Successfully opened pairing window on the device [1745221721.364004][6570:6572] CHIP:CTL: Manual pairing code: [32539460103] [1745221721.364073][6570:6572] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ4275.2823320] [1745221721.364261][6570:6572] CHIP:DMG: ICR moving to [AwaitingDe] [1745221721.364742][6570:6572] CHIP:EM: <<< [E:24161i S:15835 M:98357591 (Ack:106900474)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221721.365169][6570:6572] CHIP:EM: Flushed pending ack for MessageCounter:106900474 on exchange 24161i [1745221721.365620][6570:6570] CHIP:CTL: Shutting down the commissioner [1745221721.365835][6570:6570] CHIP:CTL: Shutting down the controller [1745221721.365902][6570:6570] CHIP:IN: Expiring all sessions for fabric 0x1!! [1745221721.365954][6570:6570] CHIP:IN: SecureSession[0xffffa40145e0]: MarkForEviction Type:2 LSID:15835 [1745221721.366010][6570:6570] CHIP:SC: SecureSession[0xffffa40145e0, LSID:15835]: State change 'kActive' --> 'kPendingEviction' [1745221721.366075][6570:6570] CHIP:IN: SecureSession[0xffffa40145e0]: Released - Type:2 LSID:15835 [1745221721.366137][6570:6570] CHIP:FP: Forgetting fabric 0x1 [1745221721.366224][6570:6570] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221721.367262][6570:6570] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221721.367341][6570:6570] CHIP:TS: Reverted Last Known Good Time to previous value [1745221721.367446][6570:6570] CHIP:CTL: Shutting down the commissioner [1745221721.367640][6570:6570] CHIP:CTL: Shutting down the controller [1745221721.367695][6570:6570] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1745221721.368020][6570:6570] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1745221721.368227][6570:6570] CHIP:FP: Shutting down FabricTable [1745221721.368303][6570:6570] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221721.369035][6570:6570] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221721.369114][6570:6570] CHIP:TS: Reverted Last Known Good Time to previous value [1745221721.369669][6570:6570] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JZ4KO2) [1745221721.371038][6570:6570] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221721.371177][6570:6570] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1745221721.371236][6570:6570] CHIP:DL: Inet Layer shutdown [1745221721.371286][6570:6570] CHIP:DL: BLE shutdown [1745221721.371343][6570:6570] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool administratorcommissioning read window-status 1 0 [1745221729.144405][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1745221729.146183][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1745221729.146219][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1745221729.151507][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1745221729.151779][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1745221729.151882][6573:6573] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1745221729.152220][6573:6573] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ljZwZR) [1745221729.152818][6573:6573] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221729.152871][6573:6573] CHIP:DL: NVS set: chip-counters/reboot-count = 261 (0x105) [1745221729.153841][6573:6573] CHIP:DL: Got Ethernet interface: eth0 [1745221729.154449][6573:6573] CHIP:DL: Found the primary Ethernet interface:eth0 [1745221729.155043][6573:6573] CHIP:DL: Got WiFi interface: wlan0 [1745221729.155105][6573:6573] CHIP:DL: Failed to reset WiFi statistic counts [1745221729.155158][6573:6573] CHIP:IN: UDP::Init bind&listen port=0 [1745221729.155266][6573:6573] CHIP:IN: UDP::Init bound to port=53705 [1745221729.155286][6573:6573] CHIP:IN: BLEBase::Init - setting/overriding transport [1745221729.155303][6573:6573] CHIP:IN: TransportMgr initialized [1745221729.155351][6573:6573] CHIP:FP: Initializing FabricTable from persistent storage [1745221729.155705][6573:6573] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221729.157708][6573:6573] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1CB8E8FD2A1604E0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.158595][6573:6573] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE7FC514BD95AD5D2, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.159384][6573:6573] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x831C65382602B3B5, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.160148][6573:6573] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xD9D01CB0D050EB4D, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.160905][6573:6573] CHIP:FP: Fabric index 0x5 was retrieved from storage. Compressed FabricId 0x0B7BB6E8F0F51EC7, FabricId 0x0000000000000005, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.161671][6573:6573] CHIP:FP: Fabric index 0x6 was retrieved from storage. Compressed FabricId 0x46A3CEF59284B985, FabricId 0x0000000000000006, NodeId 0x000000000001B669, VendorId 0xFFF1 [1745221729.166643][6573:6573] CHIP:ZCL: Using ZAP configuration... [1745221729.170151][6573:6573] CHIP:DL: Avahi client registered [1745221729.170275][6573:6573] CHIP:CTL: System State Initialized... [1745221729.170476][6573:6573] CHIP:CTL: Setting attestation nonce to random value [1745221729.170519][6573:6573] CHIP:CTL: Setting CSR nonce to random value [1745221729.170587][6573:6573] CHIP:IN: UDP::Init bind&listen port=5550 [1745221729.170707][6573:6573] CHIP:IN: UDP::Init bound to port=5550 [1745221729.170727][6573:6573] CHIP:IN: TransportMgr initialized [1745221729.170997][6573:6575] CHIP:DL: CHIP task running [1745221729.171209][6573:6575] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1745221729.171509][6573:6575] CHIP:CTL: Setting attestation nonce to random value [1745221729.171665][6573:6575] CHIP:CTL: Setting CSR nonce to random value [1745221729.172452][6573:6575] CHIP:CTL: Generating NOC [1745221729.174035][6573:6575] CHIP:FP: Validating NOC chain [1745221729.175955][6573:6575] CHIP:FP: NOC chain validation successful [1745221729.176126][6573:6575] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1745221729.176160][6573:6575] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1745221729.176184][6573:6575] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1745221729.176205][6573:6575] CHIP:TS: Retaining current Last Known Good Time [1745221729.188947][6573:6575] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1745221729.193529][6573:6575] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1745221729.198327][6573:6575] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1CB8E8FD2A1604E0) [1745221729.198456][6573:6575] CHIP:IN: UDP::Init bind&listen port=5550 [1745221729.198566][6573:6575] CHIP:IN: UDP::Init bound to port=5550 [1745221729.198588][6573:6575] CHIP:IN: TransportMgr initialized [1745221729.232528][6573:6575] CHIP:TOO: Sending command to node 0x1 [1745221729.235653][6573:6575] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1745221729.235685][6573:6575] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1745221729.235719][6573:6575] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1745221729.235751][6573:6575] CHIP:DIS: Resolving 1CB8E8FD2A1604E0:0000000000000001 ... [1745221729.237328][6573:6575] CHIP:DL: Avahi resolve found [1745221729.237398][6573:6575] CHIP:DIS: Node ID resolved for 1CB8E8FD2A1604E0:0000000000000001 [1745221729.237419][6573:6575] CHIP:DIS: Hostname: 2E4E2FDC6206DD75 [1745221729.237443][6573:6575] CHIP:DIS: IP Address #1: fd11:22::c163:73cb:f8c5:2cad [1745221729.237462][6573:6575] CHIP:DIS: Port: 5540 [1745221729.237480][6573:6575] CHIP:DIS: Mrp Interval idle: 5000 ms [1745221729.237499][6573:6575] CHIP:DIS: Mrp Interval active: 2500 ms [1745221729.237517][6573:6575] CHIP:DIS: Mrp Active Threshold: 500 ms [1745221729.237535][6573:6575] CHIP:DIS: TCP Supported: 0 [1745221729.237553][6573:6575] CHIP:DIS: ICD: not present [1745221729.238277][6573:6575] CHIP:DIS: Lookup clearing interface for non LL address [1745221729.238365][6573:6575] CHIP:DIS: UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540: new best score: 3 [1745221729.238426][6573:6575] CHIP:DIS: Checking node lookup status after 3 ms [1745221729.238443][6573:6575] CHIP:DIS: Keeping DNSSD lookup active [1745221729.435833][6573:6575] CHIP:DIS: Checking node lookup status after 200 ms [1745221729.435963][6573:6575] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540 while in state 2 [1745221729.436017][6573:6575] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1745221729.436296][6573:6575] CHIP:IN: SecureSession[0xffff74010560]: Allocated Type:2 LSID:44063 [1745221729.436382][6573:6575] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1745221729.439868][6573:6575] CHIP:EM: <<< [E:54736i S:0 M:73660204] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1745221729.440424][6573:6575] CHIP:SC: Sent Sigma1 msg [1745221729.440505][6573:6575] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1745221729.619709][6573:6575] CHIP:EM: >>> [E:54736i S:0 M:74494569 (Ack:73660204)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221729.619801][6573:6575] CHIP:EM: Found matching exchange: 54736i, Delegate: 0xffff7400dc68 [1745221729.619877][6573:6575] CHIP:EM: Rxd Ack; Removing MessageCounter:73660204 from Retrans Table on exchange 54736i [1745221729.858088][6573:6575] CHIP:EM: >>> [E:54736i S:0 M:74494570 (Ack:73660204)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1745221729.858154][6573:6575] CHIP:EM: Found matching exchange: 54736i, Delegate: 0xffff7400dc68 [1745221729.858191][6573:6575] CHIP:EM: CHIP MessageCounter:73660204 not in RetransTable on exchange 54736i [1745221729.858259][6573:6575] CHIP:SC: Received Sigma2 msg [1745221729.858311][6573:6575] CHIP:SC: Peer assigned session session ID 24076 [1745221729.864361][6573:6575] CHIP:SC: Found MRP parameters in the message [1745221729.864461][6573:6575] CHIP:SC: Sending Sigma3 [1745221729.865944][6573:6575] CHIP:EM: <<< [E:54736i S:0 M:73660205 (Ack:74494570)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1745221729.866274][6573:6575] CHIP:SC: Sent Sigma3 msg [1745221730.297841][6573:6575] CHIP:EM: >>> [E:54736i S:0 M:74494571 (Ack:73660205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221730.297933][6573:6575] CHIP:EM: Found matching exchange: 54736i, Delegate: 0xffff7400dc68 [1745221730.298009][6573:6575] CHIP:EM: Rxd Ack; Removing MessageCounter:73660205 from Retrans Table on exchange 54736i [1745221730.485107][6573:6575] CHIP:EM: >>> [E:54736i S:0 M:74494572 (Ack:73660205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1745221730.485221][6573:6575] CHIP:EM: Found matching exchange: 54736i, Delegate: 0xffff7400dc68 [1745221730.485305][6573:6575] CHIP:EM: CHIP MessageCounter:73660205 not in RetransTable on exchange 54736i [1745221730.485418][6573:6575] CHIP:SC: Success status report received. Session was established [1745221730.500646][6573:6575] CHIP:SC: SecureSession[0xffff74010560, LSID:44063]: State change 'kEstablishing' --> 'kActive' [1745221730.500704][6573:6575] CHIP:IN: SecureSession[0xffff74010560]: Activated - Type:2 LSID:44063 [1745221730.500724][6573:6575] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:44063 PSID:24076! [1745221730.500752][6573:6575] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1745221730.500826][6573:6575] CHIP:TOO: Sending ReadAttribute to: [1745221730.500895][6573:6575] CHIP:TOO: cluster 0x0000_003C, attribute: 0x0000_0000, endpoint 0 [1745221730.500934][6573:6575] CHIP:DMG: SendReadRequest ReadClient[0xffff740195a0]: Sending Read Request [1745221730.501219][6573:6575] CHIP:EM: <<< [E:54737i S:44063 M:191092628] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1745221730.501482][6573:6575] CHIP:DMG: MoveToState ReadClient[0xffff740195a0]: Moving to [AwaitingIn] [1745221730.501655][6573:6575] CHIP:EM: <<< [E:54736i S:0 M:73660206 (Ack:74494572)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221730.501793][6573:6575] CHIP:EM: Flushed pending ack for MessageCounter:74494572 on exchange 54736i [1745221730.818957][6573:6575] CHIP:EM: >>> [E:54737i S:44063 M:15269508 (Ack:191092628)] (S) Msg RX from 1:0000000000000001 [04E0] --- Type 0001:05 (IM:ReportData) [1745221730.819051][6573:6575] CHIP:EM: Found matching exchange: 54737i, Delegate: 0xffff740195b0 [1745221730.819126][6573:6575] CHIP:EM: Rxd Ack; Removing MessageCounter:191092628 from Retrans Table on exchange 54737i [1745221730.819245][6573:6575] CHIP:DMG: ReportDataMessage = [1745221730.819299][6573:6575] CHIP:DMG: { [1745221730.819343][6573:6575] CHIP:DMG: AttributeReportIBs = [1745221730.819407][6573:6575] CHIP:DMG: [ [1745221730.819456][6573:6575] CHIP:DMG: AttributeReportIB = [1745221730.819554][6573:6575] CHIP:DMG: { [1745221730.819608][6573:6575] CHIP:DMG: AttributeDataIB = [1745221730.819667][6573:6575] CHIP:DMG: { [1745221730.819753][6573:6575] CHIP:DMG: DataVersion = 0xc76fd7e1, [1745221730.819817][6573:6575] CHIP:DMG: AttributePathIB = [1745221730.819902][6573:6575] CHIP:DMG: { [1745221730.819970][6573:6575] CHIP:DMG: Endpoint = 0x0, [1745221730.820060][6573:6575] CHIP:DMG: Cluster = 0x3c, [1745221730.820131][6573:6575] CHIP:DMG: Attribute = 0x0000_0000, [1745221730.820197][6573:6575] CHIP:DMG: } [1745221730.820289][6573:6575] CHIP:DMG: [1745221730.820358][6573:6575] CHIP:DMG: Data = 1, [1745221730.820441][6573:6575] CHIP:DMG: }, [1745221730.820510][6573:6575] CHIP:DMG: [1745221730.820761][6573:6575] CHIP:DMG: }, [1745221730.820828][6573:6575] CHIP:DMG: [1745221730.820877][6573:6575] CHIP:DMG: ], [1745221730.820939][6573:6575] CHIP:DMG: [1745221730.821010][6573:6575] CHIP:DMG: SuppressResponse = true, [1745221730.821062][6573:6575] CHIP:DMG: InteractionModelRevision = 11 [1745221730.821173][6573:6575] CHIP:DMG: } [1745221730.821484][6573:6575] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003C Attribute 0x0000_0000 DataVersion: 3345995745 [1745221730.821624][6573:6575] CHIP:TOO: WindowStatus: 1 [1745221730.822111][6573:6575] CHIP:EM: <<< [E:54737i S:44063 M:191092629 (Ack:15269508)] (S) Msg TX to 1:0000000000000001 [04E0] [UDP:[fd11:22::c163:73cb:f8c5:2cad%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1745221730.822653][6573:6575] CHIP:EM: Flushed pending ack for MessageCounter:15269508 on exchange 54737i [1745221730.823288][6573:6573] CHIP:CTL: Shutting down the commissioner [1745221730.823520][6573:6573] CHIP:CTL: Shutting down the controller [1745221730.823618][6573:6573] CHIP:IN: Expiring all sessions for fabric 0x1!! [1745221730.823750][6573:6573] CHIP:IN: SecureSession[0xffff74010560]: MarkForEviction Type:2 LSID:44063 [1745221730.824045][6573:6573] CHIP:SC: SecureSession[0xffff74010560, LSID:44063]: State change 'kActive' --> 'kPendingEviction' [1745221730.824106][6573:6573] CHIP:IN: SecureSession[0xffff74010560]: Released - Type:2 LSID:44063 [1745221730.824164][6573:6573] CHIP:FP: Forgetting fabric 0x1 [1745221730.824231][6573:6573] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221730.825013][6573:6573] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221730.825070][6573:6573] CHIP:TS: Reverted Last Known Good Time to previous value [1745221730.825155][6573:6573] CHIP:CTL: Shutting down the commissioner [1745221730.825318][6573:6573] CHIP:CTL: Shutting down the controller [1745221730.825365][6573:6573] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1745221730.825647][6573:6573] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1745221730.825828][6573:6573] CHIP:FP: Shutting down FabricTable [1745221730.825893][6573:6573] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1745221730.826594][6573:6573] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1745221730.826668][6573:6573] CHIP:TS: Reverted Last Known Good Time to previous value [1745221730.827148][6573:6573] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-k8XziS) [1745221730.828369][6573:6573] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1745221730.828487][6573:6573] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1745221730.828539][6573:6573] CHIP:DL: Inet Layer shutdown [1745221730.828581][6573:6573] CHIP:DL: BLE shutdown [1745221730.828629][6573:6573] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$