ubuntu@ubuntu:~/apps$ sudo rm -rf /tmp/chip_* ubuntu@ubuntu:~/apps$ ./chip-tool pairing code 4 36390931024 --commissioner-name 4 [1660219445.856338][2375:2375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1660219445.856644][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_kvs-GMYZ2k) [1660219445.856836][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1660219445.862417][2375:2375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1660219445.862789][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-aeLO6B) [1660219445.862979][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1660219445.863095][2375:2375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1660219445.863206][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_config.ini-DOzixv) [1660219445.863322][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1660219445.863407][2375:2375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1660219445.863506][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DJvffg) [1660219445.863617][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219445.863826][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-AlLcFC) [1660219445.864367][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1660219445.864428][2375:2375] CHIP:DL: NVS set: chip-factory/unique-id = "1371117C5A072BBC" [1660219445.864602][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-aWGGga) [1660219445.868607][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1660219445.868680][2375:2375] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1660219445.868844][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-K5uvDI) [1660219445.869357][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1660219445.869416][2375:2375] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1660219445.869560][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-PDP7zK) [1660219445.869982][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219445.870133][2375:2375] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1660219445.870297][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-xLrvxO) [1660219445.871013][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219445.871070][2375:2375] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1660219445.871206][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-5PqtNi) [1660219445.871852][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219445.871910][2375:2375] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1660219445.872045][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_config.ini-kqjjzf) [1660219445.872425][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1660219445.872476][2375:2375] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1660219445.872715][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_config.ini-tNDsIw) [1660219445.873570][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1660219445.873631][2375:2375] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2) [1660219445.874630][2375:2375] CHIP:DL: Got Ethernet interface: eth0 [1660219445.875326][2375:2375] CHIP:DL: Found the primary Ethernet interface:eth0 [1660219445.876019][2375:2375] CHIP:DL: Got WiFi interface: wlan0 [1660219445.876105][2375:2375] CHIP:DL: Failed to reset WiFi statistic counts [1660219445.876167][2375:2375] CHIP:IN: UDP::Init bind&listen port=0 [1660219445.876301][2375:2375] CHIP:IN: UDP::Init bound to port=47110 [1660219445.876331][2375:2375] CHIP:IN: BLEBase::Init - setting/overriding transport [1660219445.876356][2375:2375] CHIP:IN: TransportMgr initialized [1660219445.876399][2375:2375] CHIP:FP: Initializing FabricTable from persistent storage [1660219445.876451][2375:2375] CHIP:TS: Last Known Good Time: [unknown] [1660219445.876483][2375:2375] CHIP:TS: Setting Last Known Good Time to firmware build time 2022-08-03T19:41:28 [1660219445.879379][2375:2375] CHIP:ZCL: Using ZAP configuration... [1660219445.884102][2375:2375] CHIP:DL: Avahi client registered [1660219445.885366][2375:2375] CHIP:CTL: System State Initialized... [1660219445.885494][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219445.885534][2375:2375] CHIP:CTL: Setting attestation nonce to random value [1660219445.885574][2375:2375] CHIP:CTL: Setting CSR nonce to random value [1660219445.885688][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219445.885719][2375:2375] CHIP:CTL: Setting attestation nonce to random value [1660219445.885756][2375:2375] CHIP:CTL: Setting CSR nonce to random value [1660219445.886301][2375:2375] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1660219445.887438][2375:2375] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1660219445.889064][2375:2375] CHIP:CTL: Generating RCAC [1660219445.890866][2375:2375] CHIP:CTL: Generating ICAC [1660219445.892151][2375:2375] CHIP:CTL: Generating NOC [1660219445.893039][2375:2375] CHIP:FP: Validating NOC chain [1660219445.895581][2375:2375] CHIP:FP: NOC chain validation successful [1660219445.895811][2375:2375] CHIP:FP: Added new fabric at index: 0x1 [1660219445.895841][2375:2375] CHIP:FP: Assigned compressed fabric ID: 0x863F8D90D715E7ED, node ID: 0x000000000001B669 [1660219445.895873][2375:2375] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219445.895898][2375:2375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219445.895920][2375:2375] CHIP:TS: Retaining current Last Known Good Time [1660219445.898110][2375:2375] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1660219445.902594][2375:2375] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219445.907463][2375:2375] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1660219445.907575][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219445.907616][2375:2375] CHIP:CTL: Setting attestation nonce to random value [1660219445.907673][2375:2375] CHIP:CTL: Setting CSR nonce to random value [1660219445.908926][2375:2375] CHIP:CTL: Generating NOC [1660219445.909782][2375:2375] CHIP:FP: Validating NOC chain [1660219445.911685][2375:2375] CHIP:FP: NOC chain validation successful [1660219445.911870][2375:2375] CHIP:FP: Added new fabric at index: 0x2 [1660219445.911898][2375:2375] CHIP:FP: Assigned compressed fabric ID: 0x3AE8B6BBFFEEF20B, node ID: 0x000000000001B669 [1660219445.911929][2375:2375] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219445.911953][2375:2375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219445.911975][2375:2375] CHIP:TS: Retaining current Last Known Good Time [1660219445.914604][2375:2375] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1660219445.920307][2375:2375] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219445.922904][2375:2375] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1660219445.923031][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219445.923071][2375:2375] CHIP:CTL: Setting attestation nonce to random value [1660219445.923130][2375:2375] CHIP:CTL: Setting CSR nonce to random value [1660219445.924492][2375:2375] CHIP:CTL: Generating NOC [1660219445.925456][2375:2375] CHIP:FP: Validating NOC chain [1660219445.927801][2375:2375] CHIP:FP: NOC chain validation successful [1660219445.928013][2375:2375] CHIP:FP: Added new fabric at index: 0x3 [1660219445.928047][2375:2375] CHIP:FP: Assigned compressed fabric ID: 0x3D3481DC27557ECE, node ID: 0x000000000001B669 [1660219445.928084][2375:2375] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219445.928113][2375:2375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219445.928141][2375:2375] CHIP:TS: Retaining current Last Known Good Time [1660219445.930182][2375:2375] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1660219445.933656][2375:2375] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219445.937381][2375:2375] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1660219445.937517][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219445.937554][2375:2375] CHIP:CTL: Setting attestation nonce to random value [1660219445.937608][2375:2375] CHIP:CTL: Setting CSR nonce to random value [1660219445.938763][2375:2375] CHIP:CTL: Generating NOC [1660219445.939584][2375:2375] CHIP:FP: Validating NOC chain [1660219445.941227][2375:2375] CHIP:FP: NOC chain validation successful [1660219445.941384][2375:2375] CHIP:FP: Added new fabric at index: 0x4 [1660219445.941409][2375:2375] CHIP:FP: Assigned compressed fabric ID: 0xA935DEEAD83BF05E, node ID: 0x000000000001B669 [1660219445.941436][2375:2375] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219445.941457][2375:2375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219445.941477][2375:2375] CHIP:TS: Retaining current Last Known Good Time [1660219445.943823][2375:2375] CHIP:FP: Metadata for Fabric 0x4 persisted to storage. [1660219445.948289][2375:2375] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219445.953171][2375:2375] CHIP:CTL: Joined the fabric at index 4. Compressed fabric ID is: 0x0000000000000000 [1660219446.097212][2375:2380] CHIP:DL: CHIP task running [1660219446.097421][2375:2380] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1660219446.097482][2375:2380] CHIP:CTL: Setting attestation nonce to random value [1660219446.097656][2375:2380] CHIP:CTL: Setting CSR nonce to random value [1660219446.097713][2375:2380] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219446.097737][2375:2380] CHIP:CTL: Starting commissioning discovery over BLE [1660219446.097768][2375:2380] CHIP:CTL: Starting commissioning discovery over DNS-SD [1660219446.099034][2375:2381] CHIP:DL: TRACE: Bluez mainloop starting Thread [1660219446.099391][2375:2378] CHIP:DL: TRACE: Bus acquired for name C-0947 [1660219446.106221][2375:2380] CHIP:DL: PlatformBlueZInit init success [1660219446.112278][2375:2378] CHIP:BLE: BLE removing known devices. [1660219446.114124][2375:2378] CHIP:BLE: BLE initiating scan. [1660219446.117398][2375:2380] CHIP:DL: Avahi browse: cache new [1660219446.117507][2375:2380] CHIP:DL: Avahi browse: cache new [1660219446.117577][2375:2380] CHIP:DL: Avahi browse: cache new [1660219446.117644][2375:2380] CHIP:DL: Avahi browse: cache new [1660219446.117707][2375:2380] CHIP:DL: Avahi browse: cache exhausted [1660219446.123458][2375:2378] CHIP:BLE: Device 13:DE:A2:60:1C:AE does not look like a CHIP device. [1660219446.137208][2375:2378] CHIP:BLE: Device 3F:65:AC:2F:67:30 does not look like a CHIP device. [1660219446.145101][2375:2378] CHIP:BLE: Device 26:84:4B:1D:02:16 does not look like a CHIP device. [1660219446.146897][2375:2378] CHIP:BLE: Device 34:9B:9E:36:E7:53 does not look like a CHIP device. [1660219446.150973][2375:2378] CHIP:BLE: Device 13:11:6A:1C:F3:F5 does not look like a CHIP device. [1660219446.159502][2375:2378] CHIP:BLE: Device 69:4F:07:2C:6A:1A does not look like a CHIP device. [1660219446.165503][2375:2378] CHIP:BLE: Device 35:5E:5F:8D:99:05 does not look like a CHIP device. [1660219446.172743][2375:2378] CHIP:BLE: Device 2D:62:99:49:24:D4 does not look like a CHIP device. [1660219446.194492][2375:2378] CHIP:BLE: Device 59:A0:FD:B8:67:60 does not look like a CHIP device. [1660219446.197738][2375:2378] CHIP:BLE: Device 01:7F:AD:26:FD:55 does not look like a CHIP device. [1660219446.202100][2375:2378] CHIP:BLE: Device 02:C8:59:AD:A3:D3 does not look like a CHIP device. [1660219446.204152][2375:2378] CHIP:BLE: Device 10:03:9D:58:F1:3E does not look like a CHIP device. [1660219446.255644][2375:2378] CHIP:BLE: Device 09:5B:57:7F:39:F7 does not look like a CHIP device. [1660219446.277728][2375:2378] CHIP:BLE: Device 07:9D:35:F5:F7:B1 does not look like a CHIP device. [1660219446.281941][2375:2378] CHIP:BLE: Device C2:4B:50:11:8F:B5 does not look like a CHIP device. [1660219446.334391][2375:2378] CHIP:BLE: Device 7D:FC:08:E6:75:F9 does not look like a CHIP device. [1660219446.335538][2375:2378] CHIP:BLE: Device 18:1E:55:5A:8B:48 does not look like a CHIP device. [1660219446.338732][2375:2378] CHIP:BLE: Device 09:D8:C3:4B:08:44 does not look like a CHIP device. [1660219446.347445][2375:2378] CHIP:BLE: Device 3E:2B:0B:5F:C4:A7 does not look like a CHIP device. [1660219446.425593][2375:2378] CHIP:BLE: Device 68:27:37:08:85:43 does not look like a CHIP device. [1660219446.521143][2375:2378] CHIP:BLE: Device 35:0B:17:B7:8C:03 does not look like a CHIP device. [1660219446.556044][2375:2378] CHIP:BLE: Device 7D:FC:08:E6:75:F9 does not look like a CHIP device. [1660219446.586622][2375:2378] CHIP:BLE: Device 00:04:36:10:5B:7A does not look like a CHIP device. [1660219446.673648][2375:2378] CHIP:BLE: Device 35:62:C5:03:B8:B1 does not look like a CHIP device. [1660219446.683083][2375:2378] CHIP:BLE: Device 72:1F:C8:86:14:F0 does not look like a CHIP device. [1660219446.746324][2375:2378] CHIP:BLE: Device 7C:C1:12:7F:D5:F2 does not look like a CHIP device. [1660219446.748528][2375:2378] CHIP:BLE: Device 41:9B:BE:1A:86:C7 does not look like a CHIP device. [1660219446.788942][2375:2378] CHIP:BLE: Device 7A:19:5B:0C:DF:3E does not look like a CHIP device. [1660219446.791855][2375:2378] CHIP:BLE: Device 1A:5D:E1:60:62:D2 does not look like a CHIP device. [1660219446.814888][2375:2378] CHIP:BLE: Device FA:1B:DE:83:24:10 does not look like a CHIP device. [1660219446.936643][2375:2378] CHIP:BLE: Device 0A:EB:0A:B3:11:3E does not look like a CHIP device. [1660219447.029480][2375:2378] CHIP:BLE: Device 7F:57:49:1F:E1:3F does not look like a CHIP device. [1660219447.051730][2375:2378] CHIP:BLE: Device 7A:19:5B:0C:DF:3E does not look like a CHIP device. [1660219447.073124][2375:2378] CHIP:BLE: Device AC:98:B1:11:1C:6B does not look like a CHIP device. [1660219447.112542][2375:2380] CHIP:DL: Avahi browse: all for now [1660219447.117825][2375:2378] CHIP:BLE: Device 36:4F:0E:A6:17:A0 does not look like a CHIP device. [1660219447.123073][2375:2380] CHIP:DL: Avahi resolve found [1660219447.123158][2375:2380] CHIP:DIS: Discovered node: [1660219447.123182][2375:2380] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219447.123217][2375:2380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219447.123241][2375:2380] CHIP:DIS: Port: 5540 [1660219447.123263][2375:2380] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219447.123285][2375:2380] CHIP:DIS: Mrp Interval active: 300 ms [1660219447.123306][2375:2380] CHIP:DIS: TCP Supported: 1 [1660219447.123347][2375:2380] CHIP:DIS: Vendor ID: 65521 [1660219447.123370][2375:2380] CHIP:DIS: Product ID: 32769 [1660219447.123391][2375:2380] CHIP:DIS: Long Discriminator: 3840 [1660219447.123424][2375:2380] CHIP:DIS: Pairing Hint: 36 [1660219447.123446][2375:2380] CHIP:DIS: Instance Name: 2D45F1503E86B65F [1660219447.123468][2375:2380] CHIP:DIS: Commissioning Mode: 2 [1660219447.123506][2375:2380] CHIP:CTL: Discovered device to be commissioned over DNS-SD [1660219447.123653][2375:2380] CHIP:CTL: Attempting PASE connection to UDP:[fe80::e65f:1ff:fe0e:bf6e%eth0]:5540 [1660219447.123781][2375:2380] CHIP:IN: SecureSession[0xaaaac2134400]: Allocated Type:1 LSID:18866 [1660219447.123827][2375:2380] CHIP:SC: Assigned local session key ID 18866 [1660219447.123886][2375:2380] CHIP:SC: Including MRP parameters in PBKDF param request [1660219447.123973][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff7800b548 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 52857i with MessageCounter:227807188. [1660219447.124019][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff7800b548 with MessageCounter:227807188 to 0x0000000000000000 at monotonic time: 0000000000175D06 msec [1660219447.124190][2375:2380] CHIP:SC: Sent PBKDF param request [1660219447.124221][2375:2380] CHIP:CTL: Commission called for node ID 0x0000000000000004 [1660219447.125110][2375:2380] CHIP:DL: Avahi resolve found [1660219447.125179][2375:2380] CHIP:DIS: Discovered node: [1660219447.125202][2375:2380] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219447.125229][2375:2380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219447.125252][2375:2380] CHIP:DIS: Port: 5540 [1660219447.125273][2375:2380] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219447.125296][2375:2380] CHIP:DIS: Mrp Interval active: 300 ms [1660219447.125332][2375:2380] CHIP:DIS: TCP Supported: 1 [1660219447.125356][2375:2380] CHIP:DIS: Vendor ID: 65521 [1660219447.125377][2375:2380] CHIP:DIS: Product ID: 32769 [1660219447.125399][2375:2380] CHIP:DIS: Long Discriminator: 3840 [1660219447.125430][2375:2380] CHIP:DIS: Pairing Hint: 36 [1660219447.125452][2375:2380] CHIP:DIS: Instance Name: 3A5A81D167FB20DA [1660219447.125474][2375:2380] CHIP:DIS: Commissioning Mode: 2 [1660219447.125509][2375:2380] CHIP:CTL: Discovered device to be commissioned over DNS-SD [1660219447.126344][2375:2380] CHIP:DL: Avahi resolve found [1660219447.126412][2375:2380] CHIP:DIS: Discovered node: [1660219447.126431][2375:2380] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219447.126460][2375:2380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219447.126483][2375:2380] CHIP:DIS: Port: 5540 [1660219447.126505][2375:2380] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219447.126527][2375:2380] CHIP:DIS: Mrp Interval active: 300 ms [1660219447.126549][2375:2380] CHIP:DIS: TCP Supported: 1 [1660219447.126571][2375:2380] CHIP:DIS: Vendor ID: 65521 [1660219447.126593][2375:2380] CHIP:DIS: Product ID: 32769 [1660219447.126615][2375:2380] CHIP:DIS: Long Discriminator: 3840 [1660219447.126649][2375:2380] CHIP:DIS: Pairing Hint: 36 [1660219447.126671][2375:2380] CHIP:DIS: Instance Name: 942E0DADDC258611 [1660219447.126692][2375:2380] CHIP:DIS: Commissioning Mode: 2 [1660219447.126727][2375:2380] CHIP:CTL: Discovered device to be commissioned over DNS-SD [1660219447.127658][2375:2380] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:266514596 on exchange 52857i [1660219447.127702][2375:2380] CHIP:EM: Found matching exchange: 52857i, Delegate: 0xffff7800c0b0 [1660219447.127739][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:227807188 from Retrans Table on exchange 52857i [1660219447.127763][2375:2380] CHIP:EM: Removed CHIP MessageCounter:227807188 from RetransTable on exchange 52857i [1660219447.127798][2375:2380] CHIP:SC: Received PBKDF param response [1660219447.127845][2375:2380] CHIP:SC: Peer assigned session ID 33953 [1660219447.127878][2375:2380] CHIP:SC: Found MRP parameters in the message [1660219447.140120][2375:2380] CHIP:EM: Piggybacking Ack for MessageCounter:266514596 on exchange: 52857i [1660219447.140182][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff7800d9b8 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 52857i with MessageCounter:227807189. [1660219447.140228][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff7800d9b8 with MessageCounter:227807189 to 0x0000000000000000 at monotonic time: 0000000000175D16 msec [1660219447.140409][2375:2380] CHIP:SC: Sent spake2p msg1 [1660219447.140545][2375:2380] CHIP:DL: Avahi resolve found [1660219447.140623][2375:2380] CHIP:DIS: Discovered node: [1660219447.140648][2375:2380] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219447.140680][2375:2380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219447.140706][2375:2380] CHIP:DIS: Port: 5540 [1660219447.140744][2375:2380] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219447.140770][2375:2380] CHIP:DIS: Mrp Interval active: 300 ms [1660219447.140795][2375:2380] CHIP:DIS: TCP Supported: 1 [1660219447.140830][2375:2380] CHIP:DIS: Vendor ID: 65521 [1660219447.140856][2375:2380] CHIP:DIS: Product ID: 32769 [1660219447.140881][2375:2380] CHIP:DIS: Long Discriminator: 3840 [1660219447.140918][2375:2380] CHIP:DIS: Pairing Hint: 33 [1660219447.140943][2375:2380] CHIP:DIS: Instance Name: 7F9229195BB24A18 [1660219447.140967][2375:2380] CHIP:DIS: Commissioning Mode: 1 [1660219447.141008][2375:2380] CHIP:CTL: Discovered device to be commissioned over DNS-SD [1660219447.145789][2375:2380] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:266514597 on exchange 52857i [1660219447.145854][2375:2380] CHIP:EM: Found matching exchange: 52857i, Delegate: 0xffff7800c0b0 [1660219447.145893][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:227807189 from Retrans Table on exchange 52857i [1660219447.145917][2375:2380] CHIP:EM: Removed CHIP MessageCounter:227807189 from RetransTable on exchange 52857i [1660219447.145950][2375:2380] CHIP:SC: Received spake2p msg2 [1660219447.147201][2375:2380] CHIP:EM: Piggybacking Ack for MessageCounter:266514597 on exchange: 52857i [1660219447.147254][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff7800dad8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 52857i with MessageCounter:227807190. [1660219447.147291][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff7800dad8 with MessageCounter:227807190 to 0x0000000000000000 at monotonic time: 0000000000175D1D msec [1660219447.147460][2375:2380] CHIP:SC: Sent spake2p msg3 [1660219447.148767][2375:2380] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:266514598 on exchange 52857i [1660219447.148796][2375:2380] CHIP:EM: Found matching exchange: 52857i, Delegate: 0xffff7800c0b0 [1660219447.148823][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:227807190 from Retrans Table on exchange 52857i [1660219447.148845][2375:2380] CHIP:EM: Removed CHIP MessageCounter:227807190 from RetransTable on exchange 52857i [1660219447.149003][2375:2380] CHIP:SC: SecureSession[0xaaaac2134400]: Moving from state 'kEstablishing' --> 'kActive' [1660219447.149030][2375:2380] CHIP:IN: SecureSession[0xaaaac2134400]: Activated - Type:1 LSID:18866 [1660219447.149050][2375:2380] CHIP:IN: New secure session activated for device , LSID:18866 PSID:33953! [1660219447.149076][2375:2380] CHIP:CTL: Remote device completed SPAKE2+ handshake [1660219447.149098][2375:2380] CHIP:CTL: Stopping commissioning discovery over BLE [1660219447.149118][2375:2380] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1660219447.149137][2375:2380] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219447.149168][2375:2380] CHIP:TOO: Pairing Success [1660219447.149188][2375:2380] CHIP:TOO: PASE establishment successful [1660219447.149210][2375:2380] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1660219447.149244][2375:2380] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1660219447.149264][2375:2380] CHIP:CTL: Sending request for commissioning information [1660219447.149301][2375:2380] CHIP:DMG: SendReadRequest ReadClient[0xffff78004c00]: Sending Read Request [1660219447.149461][2375:2380] CHIP:IN: Prepared secure message 0xffff7800d9b8 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 52858i with MessageCounter:168613820. [1660219447.149496][2375:2380] CHIP:IN: Sending encrypted msg 0xffff7800d9b8 with MessageCounter:168613820 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175D1F msec [1660219447.149629][2375:2380] CHIP:DMG: MoveToState ReadClient[0xffff78004c00]: Moving to [AwaitingIn] [1660219447.149667][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:266514598 on exchange 52857i [1660219447.149698][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff8d0ad968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52857i with MessageCounter:227807191. [1660219447.149731][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff8d0ad968 with MessageCounter:227807191 to 0x0000000000000000 at monotonic time: 0000000000175D1F msec [1660219447.149803][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:266514598 on exchange 52857i [1660219447.156006][2375:2378] CHIP:BLE: Device 70:BE:7E:CB:89:5C does not look like a CHIP device. [1660219447.180168][2375:2378] CHIP:BLE: Device 3F:65:AC:2F:67:30 does not look like a CHIP device. [1660219447.196836][2375:2378] CHIP:BLE: Device 0A:B1:A0:B1:24:6D does not look like a CHIP device. [1660219447.269625][2375:2378] CHIP:BLE: Device 13:DE:A2:60:1C:AE does not look like a CHIP device. [1660219447.284975][2375:2378] CHIP:BLE: Device 13:11:6A:1C:F3:F5 does not look like a CHIP device. [1660219447.349186][2375:2378] CHIP:BLE: Device 70:57:F6:83:67:71 does not look like a CHIP device. [1660219447.357432][2375:2378] CHIP:BLE: Device 14:38:5A:81:C7:B7 does not look like a CHIP device. [1660219447.414639][2375:2378] CHIP:BLE: Device 35:5E:5F:8D:99:05 does not look like a CHIP device. [1660219447.427693][2375:2380] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:108809850 on exchange 52858i [1660219447.427772][2375:2380] CHIP:EM: Found matching exchange: 52858i, Delegate: 0xffff78004c10 [1660219447.427856][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613820 from Retrans Table on exchange 52858i [1660219447.427913][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613820 from RetransTable on exchange 52858i [1660219447.428091][2375:2380] CHIP:DMG: ReportDataMessage = [1660219447.428152][2375:2380] CHIP:DMG: { [1660219447.428230][2375:2380] CHIP:DMG: AttributeReportIBs = [1660219447.428302][2375:2380] CHIP:DMG: [ [1660219447.428383][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.428537][2375:2380] CHIP:DMG: { [1660219447.428603][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.428753][2375:2380] CHIP:DMG: { [1660219447.428845][2375:2380] CHIP:DMG: DataVersion = 0xec712a8a, [1660219447.428971][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.429056][2375:2380] CHIP:DMG: { [1660219447.429150][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.429288][2375:2380] CHIP:DMG: Cluster = 0x31, [1660219447.429418][2375:2380] CHIP:DMG: Attribute = 0x0000_0003, [1660219447.429526][2375:2380] CHIP:DMG: } [1660219447.429656][2375:2380] CHIP:DMG: [1660219447.429754][2375:2380] CHIP:DMG: Data = 0, [1660219447.429803][2375:2380] CHIP:DMG: }, [1660219447.429918][2375:2380] CHIP:DMG: [1660219447.429964][2375:2380] CHIP:DMG: }, [1660219447.430026][2375:2380] CHIP:DMG: [1660219447.430065][2375:2378] CHIP:BLE: Device 2D:62:99:49:24:D4 does not look like a CHIP device. [1660219447.430065][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.430235][2375:2380] CHIP:DMG: { [1660219447.430278][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.430367][2375:2380] CHIP:DMG: { [1660219447.430430][2375:2380] CHIP:DMG: DataVersion = 0xcff9e456, [1660219447.430515][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.430581][2375:2380] CHIP:DMG: { [1660219447.430669][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.430745][2375:2380] CHIP:DMG: Cluster = 0x28, [1660219447.430837][2375:2380] CHIP:DMG: Attribute = 0x0000_0004, [1660219447.430909][2375:2380] CHIP:DMG: } [1660219447.430996][2375:2380] CHIP:DMG: [1660219447.431063][2375:2380] CHIP:DMG: Data = 32769, [1660219447.431144][2375:2380] CHIP:DMG: }, [1660219447.431208][2375:2380] CHIP:DMG: [1660219447.431276][2375:2380] CHIP:DMG: }, [1660219447.431350][2375:2380] CHIP:DMG: [1660219447.431416][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.431478][2375:2380] CHIP:DMG: { [1660219447.431545][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.431608][2375:2380] CHIP:DMG: { [1660219447.431688][2375:2380] CHIP:DMG: DataVersion = 0xcff9e456, [1660219447.431752][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.431822][2375:2380] CHIP:DMG: { [1660219447.431906][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.431991][2375:2380] CHIP:DMG: Cluster = 0x28, [1660219447.432067][2375:2380] CHIP:DMG: Attribute = 0x0000_0002, [1660219447.432151][2375:2380] CHIP:DMG: } [1660219447.432220][2375:2380] CHIP:DMG: [1660219447.432306][2375:2380] CHIP:DMG: Data = 65521, [1660219447.432368][2375:2380] CHIP:DMG: }, [1660219447.432448][2375:2380] CHIP:DMG: [1660219447.432498][2375:2380] CHIP:DMG: }, [1660219447.432581][2375:2380] CHIP:DMG: [1660219447.432629][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.432690][2375:2380] CHIP:DMG: { [1660219447.432756][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.432816][2375:2380] CHIP:DMG: { [1660219447.432894][2375:2380] CHIP:DMG: DataVersion = 0xe323a3d0, [1660219447.432957][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.433040][2375:2380] CHIP:DMG: { [1660219447.433106][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.433189][2375:2380] CHIP:DMG: Cluster = 0x30, [1660219447.433258][2375:2380] CHIP:DMG: Attribute = 0x0000_0003, [1660219447.433341][2375:2380] CHIP:DMG: } [1660219447.433414][2375:2380] CHIP:DMG: [1660219447.433491][2375:2380] CHIP:DMG: Data = 2, [1660219447.433550][2375:2380] CHIP:DMG: }, [1660219447.433613][2375:2380] CHIP:DMG: [1660219447.433685][2375:2380] CHIP:DMG: }, [1660219447.433753][2375:2380] CHIP:DMG: [1660219447.433819][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.433917][2375:2380] CHIP:DMG: { [1660219447.433986][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.434049][2375:2380] CHIP:DMG: { [1660219447.434126][2375:2380] CHIP:DMG: DataVersion = 0xe323a3d0, [1660219447.434190][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.434253][2375:2380] CHIP:DMG: { [1660219447.434336][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.434404][2375:2380] CHIP:DMG: Cluster = 0x30, [1660219447.434489][2375:2380] CHIP:DMG: Attribute = 0x0000_0002, [1660219447.434570][2375:2380] CHIP:DMG: } [1660219447.434646][2375:2380] CHIP:DMG: [1660219447.434734][2375:2380] CHIP:DMG: Data = 0, [1660219447.434795][2375:2380] CHIP:DMG: }, [1660219447.434880][2375:2380] CHIP:DMG: [1660219447.434934][2375:2380] CHIP:DMG: }, [1660219447.435024][2375:2380] CHIP:DMG: [1660219447.435072][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.435150][2375:2380] CHIP:DMG: { [1660219447.435202][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.435269][2375:2380] CHIP:DMG: { [1660219447.435346][2375:2380] CHIP:DMG: DataVersion = 0xe323a3d0, [1660219447.435408][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.435490][2375:2380] CHIP:DMG: { [1660219447.435555][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.435640][2375:2380] CHIP:DMG: Cluster = 0x30, [1660219447.435725][2375:2380] CHIP:DMG: Attribute = 0x0000_0001, [1660219447.435790][2375:2380] CHIP:DMG: } [1660219447.435856][2375:2380] CHIP:DMG: [1660219447.435936][2375:2380] CHIP:DMG: Data = [1660219447.436000][2375:2380] CHIP:DMG: { [1660219447.436129][2375:2380] CHIP:DMG: 0x0 = 60, [1660219447.436215][2375:2380] CHIP:DMG: 0x1 = 900, [1660219447.436300][2375:2380] CHIP:DMG: }, [1660219447.436363][2375:2380] CHIP:DMG: }, [1660219447.436447][2375:2380] CHIP:DMG: [1660219447.436503][2375:2380] CHIP:DMG: }, [1660219447.436572][2375:2380] CHIP:DMG: [1660219447.436637][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.436699][2375:2380] CHIP:DMG: { [1660219447.436767][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.436830][2375:2380] CHIP:DMG: { [1660219447.436911][2375:2380] CHIP:DMG: DataVersion = 0xe323a3d0, [1660219447.436974][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.437057][2375:2380] CHIP:DMG: { [1660219447.437123][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.437212][2375:2380] CHIP:DMG: Cluster = 0x30, [1660219447.437280][2375:2380] CHIP:DMG: Attribute = 0x0000_0000, [1660219447.437362][2375:2380] CHIP:DMG: } [1660219447.437436][2375:2380] CHIP:DMG: [1660219447.437525][2375:2380] CHIP:DMG: Data = 0, [1660219447.437586][2375:2380] CHIP:DMG: }, [1660219447.437672][2375:2380] CHIP:DMG: [1660219447.437727][2375:2380] CHIP:DMG: }, [1660219447.437811][2375:2380] CHIP:DMG: [1660219447.437880][2375:2380] CHIP:DMG: AttributeReportIB = [1660219447.437941][2375:2380] CHIP:DMG: { [1660219447.438013][2375:2380] CHIP:DMG: AttributeDataIB = [1660219447.438072][2375:2380] CHIP:DMG: { [1660219447.438148][2375:2380] CHIP:DMG: DataVersion = 0xec712a8a, [1660219447.438211][2375:2380] CHIP:DMG: AttributePathIB = [1660219447.438288][2375:2380] CHIP:DMG: { [1660219447.438354][2375:2380] CHIP:DMG: Endpoint = 0x0, [1660219447.438437][2375:2380] CHIP:DMG: Cluster = 0x31, [1660219447.438507][2375:2380] CHIP:DMG: Attribute = 0x0000_FFFC, [1660219447.438593][2375:2380] CHIP:DMG: } [1660219447.438661][2375:2380] CHIP:DMG: [1660219447.438746][2375:2380] CHIP:DMG: Data = 4, [1660219447.438808][2375:2380] CHIP:DMG: }, [1660219447.438889][2375:2380] CHIP:DMG: [1660219447.438943][2375:2380] CHIP:DMG: }, [1660219447.439020][2375:2380] CHIP:DMG: [1660219447.439067][2375:2380] CHIP:DMG: ], [1660219447.439188][2375:2380] CHIP:DMG: [1660219447.439238][2375:2380] CHIP:DMG: SuppressResponse = true, [1660219447.439303][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.439349][2375:2380] CHIP:DMG: } [1660219447.440202][2375:2380] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1660219447.440238][2375:2380] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1660219447.440267][2375:2380] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1660219447.440285][2375:2380] CHIP:CTL: Arming failsafe (60 seconds) [1660219447.440351][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.440389][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.440531][2375:2380] CHIP:IN: Prepared secure message 0xffff78001518 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52859i with MessageCounter:168613821. [1660219447.440578][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78001518 with MessageCounter:168613821 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E42 msec [1660219447.440748][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.440786][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809850 on exchange 52858i [1660219447.440840][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52858i with MessageCounter:168613822. [1660219447.440871][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613822 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E43 msec [1660219447.440947][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809850 on exchange 52858i [1660219447.442898][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809851 on exchange 52859i [1660219447.442929][2375:2380] CHIP:EM: Found matching exchange: 52859i, Delegate: 0xaaaac21758c8 [1660219447.442959][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613821 from Retrans Table on exchange 52859i [1660219447.442980][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613821 from RetransTable on exchange 52859i [1660219447.443008][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.443049][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.443081][2375:2380] CHIP:DMG: { [1660219447.443101][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.443130][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.443157][2375:2380] CHIP:DMG: [ [1660219447.443178][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.443217][2375:2380] CHIP:DMG: { [1660219447.443240][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.443279][2375:2380] CHIP:DMG: { [1660219447.443305][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.443342][2375:2380] CHIP:DMG: { [1660219447.443372][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.443411][2375:2380] CHIP:DMG: ClusterId = 0x30, [1660219447.443444][2375:2380] CHIP:DMG: CommandId = 0x1, [1660219447.443481][2375:2380] CHIP:DMG: }, [1660219447.443511][2375:2380] CHIP:DMG: [1660219447.443546][2375:2380] CHIP:DMG: CommandFields = [1660219447.443575][2375:2380] CHIP:DMG: { [1660219447.443616][2375:2380] CHIP:DMG: 0x0 = 0, [1660219447.443657][2375:2380] CHIP:DMG: 0x1 = "" (0 chars), [1660219447.443688][2375:2380] CHIP:DMG: }, [1660219447.443725][2375:2380] CHIP:DMG: }, [1660219447.443756][2375:2380] CHIP:DMG: [1660219447.443785][2375:2380] CHIP:DMG: }, [1660219447.443813][2375:2380] CHIP:DMG: [1660219447.443833][2375:2380] CHIP:DMG: ], [1660219447.443867][2375:2380] CHIP:DMG: [1660219447.443888][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.443908][2375:2380] CHIP:DMG: }, [1660219447.443968][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1660219447.444025][2375:2380] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1660219447.444059][2375:2380] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1660219447.444079][2375:2380] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1660219447.444103][2375:2380] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1660219447.444129][2375:2380] CHIP:CTL: Setting Regulatory Config [1660219447.444148][2375:2380] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1660219447.444208][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.444237][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.444331][2375:2380] CHIP:IN: Prepared secure message 0xffff78001518 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52860i with MessageCounter:168613823. [1660219447.444364][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78001518 with MessageCounter:168613823 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E46 msec [1660219447.444499][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.444547][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.444573][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809851 on exchange 52859i [1660219447.444622][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52859i with MessageCounter:168613824. [1660219447.444661][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613824 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E46 msec [1660219447.444733][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809851 on exchange 52859i [1660219447.448409][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809852 on exchange 52860i [1660219447.448437][2375:2380] CHIP:EM: Found matching exchange: 52860i, Delegate: 0xffff78004808 [1660219447.448464][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613823 from Retrans Table on exchange 52860i [1660219447.448486][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613823 from RetransTable on exchange 52860i [1660219447.448512][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.448549][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.448580][2375:2380] CHIP:DMG: { [1660219447.448602][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.448623][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.448657][2375:2380] CHIP:DMG: [ [1660219447.448678][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.448717][2375:2380] CHIP:DMG: { [1660219447.448740][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.448767][2375:2380] CHIP:DMG: { [1660219447.448798][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.448828][2375:2380] CHIP:DMG: { [1660219447.448861][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.448904][2375:2380] CHIP:DMG: ClusterId = 0x30, [1660219447.448935][2375:2380] CHIP:DMG: CommandId = 0x3, [1660219447.448973][2375:2380] CHIP:DMG: }, [1660219447.449005][2375:2380] CHIP:DMG: [1660219447.449040][2375:2380] CHIP:DMG: CommandFields = [1660219447.449075][2375:2380] CHIP:DMG: { [1660219447.449118][2375:2380] CHIP:DMG: 0x0 = 0, [1660219447.449163][2375:2380] CHIP:DMG: 0x1 = "" (0 chars), [1660219447.449198][2375:2380] CHIP:DMG: }, [1660219447.449232][2375:2380] CHIP:DMG: }, [1660219447.449262][2375:2380] CHIP:DMG: [1660219447.449295][2375:2380] CHIP:DMG: }, [1660219447.449322][2375:2380] CHIP:DMG: [1660219447.449350][2375:2380] CHIP:DMG: ], [1660219447.449378][2375:2380] CHIP:DMG: [1660219447.449399][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.449427][2375:2380] CHIP:DMG: }, [1660219447.449493][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1660219447.449566][2375:2380] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1660219447.449599][2375:2380] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1660219447.449623][2375:2380] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1660219447.449661][2375:2380] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1660219447.449683][2375:2380] CHIP:CTL: Sending request for PAI certificate [1660219447.449701][2375:2380] CHIP:CTL: Sending Certificate Chain request to 0xffff7800c060 device [1660219447.449782][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.449822][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.450038][2375:2380] CHIP:IN: Prepared secure message 0xffff78001518 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52861i with MessageCounter:168613825. [1660219447.450112][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78001518 with MessageCounter:168613825 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E4C msec [1660219447.450228][2375:2378] CHIP:BLE: Device 01:7F:AD:26:FD:55 does not look like a CHIP device. [1660219447.450313][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.450392][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.450435][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809852 on exchange 52860i [1660219447.450516][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52860i with MessageCounter:168613826. [1660219447.450580][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613826 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E4C msec [1660219447.450696][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809852 on exchange 52860i [1660219447.452642][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809853 on exchange 52861i [1660219447.452685][2375:2380] CHIP:EM: Found matching exchange: 52861i, Delegate: 0xaaaac21758c8 [1660219447.452729][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613825 from Retrans Table on exchange 52861i [1660219447.452761][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613825 from RetransTable on exchange 52861i [1660219447.452800][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.452870][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.452902][2375:2380] CHIP:DMG: { [1660219447.452933][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.452979][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.453018][2375:2380] CHIP:DMG: [ [1660219447.453049][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.453104][2375:2380] CHIP:DMG: { [1660219447.453137][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.453192][2375:2380] CHIP:DMG: { [1660219447.453230][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.453290][2375:2380] CHIP:DMG: { [1660219447.453334][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.453390][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219447.453439][2375:2380] CHIP:DMG: CommandId = 0x3, [1660219447.453494][2375:2380] CHIP:DMG: }, [1660219447.453553][2375:2380] CHIP:DMG: [1660219447.453597][2375:2380] CHIP:DMG: CommandFields = [1660219447.453651][2375:2380] CHIP:DMG: { [1660219447.453699][2375:2380] CHIP:DMG: 0x0 = [ [1660219447.453912][2375:2380] CHIP:DMG: 0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1, [1660219447.454025][2375:2380] CHIP:DMG: ] (463 bytes) [1660219447.454075][2375:2380] CHIP:DMG: }, [1660219447.454119][2375:2380] CHIP:DMG: }, [1660219447.454167][2375:2380] CHIP:DMG: [1660219447.454201][2375:2380] CHIP:DMG: }, [1660219447.454259][2375:2380] CHIP:DMG: [1660219447.454292][2375:2380] CHIP:DMG: ], [1660219447.454342][2375:2380] CHIP:DMG: [1660219447.454374][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.454404][2375:2380] CHIP:DMG: }, [1660219447.454489][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1660219447.454545][2375:2380] CHIP:CTL: Received certificate chain from the device [1660219447.454582][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1660219447.454617][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1660219447.454665][2375:2380] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1660219447.454692][2375:2380] CHIP:CTL: Sending request for DAC certificate [1660219447.454717][2375:2380] CHIP:CTL: Sending Certificate Chain request to 0xffff7800c060 device [1660219447.454798][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.454850][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.454970][2375:2380] CHIP:IN: Prepared secure message 0xffff78001518 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52862i with MessageCounter:168613827. [1660219447.455033][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78001518 with MessageCounter:168613827 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E51 msec [1660219447.455208][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.455273][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.455311][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809853 on exchange 52861i [1660219447.455379][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52861i with MessageCounter:168613828. [1660219447.455439][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613828 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E51 msec [1660219447.455542][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809853 on exchange 52861i [1660219447.457263][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809854 on exchange 52862i [1660219447.457302][2375:2380] CHIP:EM: Found matching exchange: 52862i, Delegate: 0xffff78004808 [1660219447.457343][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613827 from Retrans Table on exchange 52862i [1660219447.457374][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613827 from RetransTable on exchange 52862i [1660219447.457410][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.457461][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.457505][2375:2380] CHIP:DMG: { [1660219447.457532][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.457558][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.457608][2375:2380] CHIP:DMG: [ [1660219447.457639][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.457685][2375:2380] CHIP:DMG: { [1660219447.457730][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.457769][2375:2380] CHIP:DMG: { [1660219447.457819][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.457893][2375:2380] CHIP:DMG: { [1660219447.457957][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.458008][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219447.458066][2375:2380] CHIP:DMG: CommandId = 0x3, [1660219447.458108][2375:2380] CHIP:DMG: }, [1660219447.458167][2375:2380] CHIP:DMG: [1660219447.458205][2375:2380] CHIP:DMG: CommandFields = [1660219447.458256][2375:2380] CHIP:DMG: { [1660219447.458307][2375:2380] CHIP:DMG: 0x0 = [ [1660219447.458507][2375:2380] CHIP:DMG: 0x30, 0x82, 0x1, 0xe7, 0x30, 0x82, 0x1, 0x8e, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x69, 0xcd, 0xf1, 0xd, 0xe9, 0xe5, 0x4e, 0xd1, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x46, 0x3a, 0xc6, 0x93, 0x42, 0x91, 0xa, 0xe, 0x55, 0x88, 0xfc, 0x6f, 0xf5, 0x6b, 0xb6, 0x3e, 0x62, 0xec, 0xce, 0xcb, 0x14, 0x8f, 0x7d, 0x4e, 0xb0, 0x3e, 0xe5, 0x52, 0x60, 0x14, 0x15, 0x76, 0x7d, 0x16, 0xa5, 0xc6, 0x63, 0xf7, 0x93, 0xe4, 0x91, 0x23, 0x26, 0xb, 0x82, 0x97, 0xa7, 0xcd, 0x7e, 0x7c, 0xfc, 0x [1660219447.458718][2375:2380] CHIP:DMG: ] (491 bytes) [1660219447.458769][2375:2380] CHIP:DMG: }, [1660219447.458810][2375:2380] CHIP:DMG: }, [1660219447.458871][2375:2380] CHIP:DMG: [1660219447.458909][2375:2380] CHIP:DMG: }, [1660219447.458948][2375:2380] CHIP:DMG: [1660219447.458979][2375:2380] CHIP:DMG: ], [1660219447.459033][2375:2380] CHIP:DMG: [1660219447.459066][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.459109][2375:2380] CHIP:DMG: }, [1660219447.459183][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1660219447.459237][2375:2380] CHIP:CTL: Received certificate chain from the device [1660219447.459273][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1660219447.459305][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1660219447.459352][2375:2380] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1660219447.459380][2375:2380] CHIP:CTL: Sending Attestation Request to the device. [1660219447.459407][2375:2380] CHIP:CTL: Sending Attestation request to 0xffff7800c060 device [1660219447.459486][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.459525][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.459664][2375:2380] CHIP:IN: Prepared secure message 0xffff78001518 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52863i with MessageCounter:168613829. [1660219447.459713][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78001518 with MessageCounter:168613829 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E55 msec [1660219447.459884][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.459938][2375:2380] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1660219447.459988][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.460020][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809854 on exchange 52862i [1660219447.460077][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52862i with MessageCounter:168613830. [1660219447.460203][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613830 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E56 msec [1660219447.460284][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809854 on exchange 52862i [1660219447.462318][2375:2380] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108809855 on exchange 52863i [1660219447.462354][2375:2380] CHIP:EM: Found matching exchange: 52863i, Delegate: 0xaaaac21758c8 [1660219447.462389][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613829 from Retrans Table on exchange 52863i [1660219447.462416][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613829 from RetransTable on exchange 52863i [1660219447.463384][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809856 on exchange 52863i [1660219447.463416][2375:2380] CHIP:EM: Found matching exchange: 52863i, Delegate: 0xaaaac21758c8 [1660219447.463442][2375:2380] CHIP:EM: CHIP MessageCounter:168613829 not in RetransTable on exchange 52863i [1660219447.463475][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.463523][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.463550][2375:2380] CHIP:DMG: { [1660219447.463586][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.463613][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.463647][2375:2380] CHIP:DMG: [ [1660219447.463683][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.463722][2375:2380] CHIP:DMG: { [1660219447.463748][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.463799][2375:2380] CHIP:DMG: { [1660219447.463831][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.463880][2375:2380] CHIP:DMG: { [1660219447.463915][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.463961][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219447.463998][2375:2380] CHIP:DMG: CommandId = 0x1, [1660219447.464031][2375:2380] CHIP:DMG: }, [1660219447.464078][2375:2380] CHIP:DMG: [1660219447.464110][2375:2380] CHIP:DMG: CommandFields = [1660219447.464157][2375:2380] CHIP:DMG: { [1660219447.464192][2375:2380] CHIP:DMG: 0x0 = [ [1660219447.464358][2375:2380] CHIP:DMG: 0x15, 0x31, 0x1, 0x1d, 0x2, 0x30, 0x82, 0x2, 0x19, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x2, 0xa0, 0x82, 0x2, 0xa, 0x30, 0x82, 0x2, 0x6, 0x2, 0x1, 0x3, 0x31, 0xd, 0x30, 0xb, 0x6, 0x9, 0x60, 0x86, 0x48, 0x1, 0x65, 0x3, 0x4, 0x2, 0x1, 0x30, 0x82, 0x1, 0x71, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x1, 0xa0, 0x82, 0x1, 0x62, 0x4, 0x82, 0x1, 0x5e, 0x15, 0x24, 0x0, 0x1, 0x25, 0x1, 0xf1, 0xff, 0x36, 0x2, 0x5, 0x0, 0x80, 0x5, 0x1, 0x80, 0x5, 0x2, 0x80, 0x5, 0x3, 0x80, 0x5, 0x4, 0x80, 0x5, 0x5, 0x80, 0x5, 0x6, 0x80, 0x5, 0x7, 0x80, 0x5, 0x8, 0x80, 0x5, 0x9, 0x80, 0x5, 0xa, 0x80, 0x5, 0xb, 0x80, 0x5, 0xc, 0x80, 0x5, 0xd, 0x80, 0x5, 0xe, 0x80, 0x5, 0xf, 0x80, 0x5, 0x10, 0x80, 0x5, 0x11, 0x80, 0x5, 0x12, 0x80, 0x5, 0x13, 0x80, 0x5, 0x14, 0x80, 0x5, 0x15, 0x80, 0x5, 0x16, 0x80, 0x5, 0x17, 0x80, 0x5, 0x18, 0x80, 0x5, 0x19, 0x80, 0x5, 0x1a, 0x80, 0x5, 0x1b, 0x80, 0x5, 0x1c, 0x80, 0x5, 0x1d, 0x80, 0x5, 0x1e, 0x80, 0x5, 0x1f, 0x80, 0x5, 0x20, 0x80, 0x5, 0x21, 0x80, 0x5, 0x22, 0x80, 0x5, 0x23, 0x80, 0x5, 0x24, 0x80, 0x5, 0x25, 0x80, 0x5, 0x26, 0x80, 0x5, 0x27, 0x80, 0x5, 0x28, 0x80, 0x5, 0x29, 0x80, 0x5, 0x2a, 0x80, 0x5, 0x2b, 0x80, 0x5, 0x2c, 0x80, 0x5, 0x2d, 0x80, 0x5, 0x2e, 0x80, 0x5, 0x2f, 0x80, 0x5, 0x30, 0x80, 0x5, 0x31, 0x80, 0x5, 0x32, 0x80, 0x5, 0x33, 0x80, 0x5, 0x34, 0x80, 0x5, 0x35, 0x80, 0x5, 0x36, 0x80, 0x5, 0x37, 0x80, 0x5, 0x38, 0x80, 0x5, 0x39, 0x80, 0x5, 0x3a, 0x80, 0x5, 0x3b, 0x80, 0x5, 0x3c, 0x80, 0x5, 0x3d, 0x80, 0x5, 0x3e, 0x80, 0x5, 0x3f, 0x80, 0x5, 0x40, 0x80, 0x5, 0x41, 0x80, 0x5, 0x42, 0x80, 0x5, 0x43, 0x80, 0x5, 0x44, 0x80, 0x5, 0x45, 0x80, 0x5, 0x46, 0x80, 0x5, 0x47, 0x80, 0x5, 0x48, 0x80, 0x5, 0x49, 0x80, 0x5, 0x4a, 0x80, 0x5, 0 [1660219447.464457][2375:2380] CHIP:DMG: ] (585 bytes) [1660219447.464493][2375:2380] CHIP:DMG: 0x1 = [ [1660219447.464549][2375:2380] CHIP:DMG: 0xd7, 0x9a, 0x48, 0xe, 0xfe, 0xd3, 0x4, 0x77, 0xb, 0x25, 0xb2, 0x20, 0x5d, 0x27, 0x77, 0xcb, 0xf6, 0xd, 0x58, 0xb, 0x16, 0xfd, 0x84, 0x35, 0xed, 0x81, 0xb8, 0xdd, 0xa6, 0x47, 0x15, 0xb0, 0x61, 0xff, 0x1e, 0x65, 0x15, 0x51, 0x9d, 0x35, 0x54, 0x77, 0xb4, 0x1e, 0xd8, 0x7, 0x63, 0x2b, 0x88, 0xd4, 0xe9, 0xe3, 0x5c, 0x84, 0xd2, 0x54, 0xa6, 0xdf, 0x5d, 0xda, 0x6f, 0x1e, 0x3, 0xc4, [1660219447.464610][2375:2380] CHIP:DMG: ] (64 bytes) [1660219447.464649][2375:2380] CHIP:DMG: }, [1660219447.464694][2375:2380] CHIP:DMG: }, [1660219447.464734][2375:2380] CHIP:DMG: [1660219447.464764][2375:2380] CHIP:DMG: }, [1660219447.464801][2375:2380] CHIP:DMG: [1660219447.464828][2375:2380] CHIP:DMG: ], [1660219447.464862][2375:2380] CHIP:DMG: [1660219447.464889][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.464914][2375:2380] CHIP:DMG: }, [1660219447.464985][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1660219447.465026][2375:2380] CHIP:CTL: Received Attestation Information from the device [1660219447.465059][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1660219447.465120][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1660219447.465152][2375:2380] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1660219447.465172][2375:2380] CHIP:CTL: Verifying attestation [1660219447.465193][2375:2378] CHIP:BLE: Device 02:C8:59:AD:A3:D3 does not look like a CHIP device. [1660219447.480871][2375:2378] CHIP:BLE: Device C0:5D:0A:7D:70:4B does not look like a CHIP device. [1660219447.497560][2375:2380] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1660219447.497645][2375:2380] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1660219447.497668][2375:2380] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1660219447.497698][2375:2380] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1660219447.497720][2375:2380] CHIP:CTL: Sending CSR request to 0xffff7800c060 device [1660219447.497797][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.497850][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.498001][2375:2380] CHIP:IN: Prepared secure message 0xffff7800fa28 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52864i with MessageCounter:168613831. [1660219447.498051][2375:2380] CHIP:IN: Sending encrypted msg 0xffff7800fa28 with MessageCounter:168613831 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E7C msec [1660219447.498231][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.498264][2375:2380] CHIP:CTL: Sent CSR request, waiting for the CSR [1660219447.498313][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.498342][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809856 on exchange 52863i [1660219447.498404][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52863i with MessageCounter:168613832. [1660219447.498436][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613832 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E7C msec [1660219447.498512][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809856 on exchange 52863i [1660219447.499925][2375:2380] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108809857 on exchange 52864i [1660219447.499982][2375:2380] CHIP:EM: Found matching exchange: 52864i, Delegate: 0xffff780368c8 [1660219447.499951][2375:2378] CHIP:BLE: Device 09:5B:57:7F:39:F7 does not look like a CHIP device. [1660219447.500025][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613831 from Retrans Table on exchange 52864i [1660219447.500088][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613831 from RetransTable on exchange 52864i [1660219447.501649][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809858 on exchange 52864i [1660219447.501677][2375:2380] CHIP:EM: Found matching exchange: 52864i, Delegate: 0xffff780368c8 [1660219447.501698][2375:2380] CHIP:EM: CHIP MessageCounter:168613831 not in RetransTable on exchange 52864i [1660219447.501732][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.501777][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.501799][2375:2380] CHIP:DMG: { [1660219447.501888][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.501920][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.501948][2375:2380] CHIP:DMG: [ [1660219447.501979][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.502013][2375:2380] CHIP:DMG: { [1660219447.502043][2375:2380] CHIP:DMG: CommandDataIB = [1660219447.502076][2375:2380] CHIP:DMG: { [1660219447.502110][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.502140][2375:2380] CHIP:DMG: { [1660219447.502179][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.502209][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219447.502246][2375:2380] CHIP:DMG: CommandId = 0x5, [1660219447.502274][2375:2380] CHIP:DMG: }, [1660219447.502310][2375:2380] CHIP:DMG: [1660219447.502340][2375:2380] CHIP:DMG: CommandFields = [1660219447.502375][2375:2380] CHIP:DMG: { [1660219447.502405][2375:2380] CHIP:DMG: 0x0 = [ [1660219447.502517][2375:2380] CHIP:DMG: 0x15, 0x30, 0x1, 0xcb, 0x30, 0x81, 0xc8, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x32, 0x11, 0xe, 0x32, 0xf6, 0x27, 0xac, 0xdb, 0xbb, 0xba, 0xf1, 0xb4, 0xa3, 0x95, 0x26, 0x9d, 0x9b, 0x36, 0xf4, 0x77, 0xa5, 0xd, 0x9c, 0x8f, 0xa, 0x60, 0x9f, 0x98, 0xe2, 0x2e, 0x9c, 0x87, 0xc1, 0x35, 0xe9, 0xcf, 0x2e, 0x83, 0x5c, 0x12, 0xd6, 0xb5, 0xdd, 0x52, 0xda, 0xe6, 0x92, 0xe6, 0xcb, 0x5f, 0x73, 0x9b, 0xb3, 0x41, 0xdb, 0xc3, 0x96, 0xfc, 0x57, 0xa8, 0xc6, 0x13, 0x85, 0x4c, 0xa0, 0x0, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x3, 0x48, 0x0, 0x30, 0x45, 0x2, 0x21, 0x0, 0x90, 0xb1, 0xa, 0x5a, 0x37, 0xf7, 0x3f, 0x33, 0xba, 0xf, 0xa4, 0xb8, 0x2b, 0x5, 0x75, 0x18, 0xa5, 0xe1, 0x8b, 0xd0, 0x7e, 0x94, 0x8c, 0xe3, 0xbd, 0x2e, 0x94, 0xb, 0x4f, 0x53, 0xdc, 0x60, 0x2, 0x20, 0x58, 0x4a, 0xdf, 0x2d, 0x2b, 0x8c, 0x72, 0xa, 0xc6, 0xd3, 0x4f, 0x31, 0x98, 0x5e, 0x2b, 0x97, 0x6e, 0xb3, 0xab, 0x5a, 0xc9, 0x17, 0xe1, 0xc0, 0x7a, 0xe3, 0xbc, 0x3e, 0xa2, 0xc2, 0xaa, 0x89, 0x30, 0x2, 0x20, 0xd3, 0x26, 0x7c, 0x3, 0x11, 0x50, 0xbf, 0x9, 0xb4, 0x33, 0x3f, 0xde, 0x2a, 0xa3, 0xa5, 0x11, 0x9d, 0xf4, 0xc3, 0x71, 0xde, 0x4a, 0x7d, 0x83, 0x7f, 0xc6, 0x0, 0x32, 0xa3, 0x26, 0x2c, 0xf1, 0x18, [1660219447.502586][2375:2380] CHIP:DMG: ] (243 bytes) [1660219447.502619][2375:2380] CHIP:DMG: 0x1 = [ [1660219447.502665][2375:2380] CHIP:DMG: 0xa4, 0x7f, 0x2f, 0x28, 0xf6, 0x20, 0xdc, 0xf7, 0xf7, 0x89, 0xca, 0x2, 0x2b, 0xca, 0xdf, 0xce, 0x77, 0x9a, 0x9e, 0x51, 0xe1, 0x13, 0x1f, 0xe5, 0xa, 0xfc, 0xda, 0x84, 0x4, 0x33, 0x4e, 0x92, 0x6f, 0x6, 0x86, 0x98, 0xb7, 0xb9, 0xdb, 0x93, 0x3d, 0x9e, 0x52, 0xe9, 0x1f, 0x99, 0x62, 0xeb, 0x7, 0x51, 0xce, 0x34, 0x6d, 0x77, 0x33, 0x69, 0x4c, 0x5a, 0x4e, 0xb2, 0x95, 0x33, 0xac, 0x80, [1660219447.502700][2375:2380] CHIP:DMG: ] (64 bytes) [1660219447.502744][2375:2380] CHIP:DMG: }, [1660219447.502771][2375:2380] CHIP:DMG: }, [1660219447.502808][2375:2380] CHIP:DMG: [1660219447.502833][2375:2380] CHIP:DMG: }, [1660219447.502862][2375:2380] CHIP:DMG: [1660219447.502891][2375:2380] CHIP:DMG: ], [1660219447.502917][2375:2380] CHIP:DMG: [1660219447.502948][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.502969][2375:2380] CHIP:DMG: }, [1660219447.503033][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1660219447.503074][2375:2380] CHIP:CTL: Received certificate signing request from the device [1660219447.503105][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1660219447.503128][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1660219447.503163][2375:2380] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1660219447.507792][2375:2380] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1660219447.507868][2375:2380] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1660219447.507899][2375:2380] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1660219447.507926][2375:2380] CHIP:CTL: Getting certificate chain for the device from the issuer [1660219447.512082][2375:2380] CHIP:CTL: Verifying Certificate Signing Request [1660219447.514838][2375:2380] CHIP:CTL: Generating NOC [1660219447.515383][2375:2380] CHIP:CTL: Providing certificate chain to the commissioner [1660219447.515440][2375:2380] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:261: Success [1660219447.515475][2375:2380] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1660219447.515688][2375:2380] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1660219447.515729][2375:2380] CHIP:CTL: Sending root certificate to the device [1660219447.515829][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.515905][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.516072][2375:2380] CHIP:IN: Prepared secure message 0xffff78035dd8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52865i with MessageCounter:168613833. [1660219447.516142][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78035dd8 with MessageCounter:168613833 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E8E msec [1660219447.516363][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.516415][2375:2380] CHIP:CTL: Sent root certificate to the device [1660219447.516920][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.516994][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809858 on exchange 52864i [1660219447.517102][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52864i with MessageCounter:168613834. [1660219447.517150][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613834 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E8F msec [1660219447.517303][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809858 on exchange 52864i [1660219447.517502][2375:2378] CHIP:BLE: Device 3C:39:D9:E2:4C:3E does not look like a CHIP device. [1660219447.518059][2375:2380] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108809859 on exchange 52865i [1660219447.518105][2375:2380] CHIP:EM: Found matching exchange: 52865i, Delegate: 0xaaaac21758c8 [1660219447.518144][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613833 from Retrans Table on exchange 52865i [1660219447.518167][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613833 from RetransTable on exchange 52865i [1660219447.519308][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809860 on exchange 52865i [1660219447.519348][2375:2380] CHIP:EM: Found matching exchange: 52865i, Delegate: 0xaaaac21758c8 [1660219447.519370][2375:2380] CHIP:EM: CHIP MessageCounter:168613833 not in RetransTable on exchange 52865i [1660219447.519404][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219447.519451][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219447.519473][2375:2380] CHIP:DMG: { [1660219447.519506][2375:2380] CHIP:DMG: suppressResponse = false, [1660219447.519528][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219447.519555][2375:2380] CHIP:DMG: [ [1660219447.519585][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219447.519620][2375:2380] CHIP:DMG: { [1660219447.519654][2375:2380] CHIP:DMG: CommandStatusIB = [1660219447.519689][2375:2380] CHIP:DMG: { [1660219447.519726][2375:2380] CHIP:DMG: CommandPathIB = [1660219447.519761][2375:2380] CHIP:DMG: { [1660219447.519803][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219447.519847][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219447.519882][2375:2380] CHIP:DMG: CommandId = 0xb, [1660219447.519924][2375:2380] CHIP:DMG: }, [1660219447.519961][2375:2380] CHIP:DMG: [1660219447.520000][2375:2380] CHIP:DMG: StatusIB = [1660219447.520032][2375:2380] CHIP:DMG: { [1660219447.520076][2375:2380] CHIP:DMG: status = 0x00 (SUCCESS), [1660219447.520119][2375:2380] CHIP:DMG: }, [1660219447.520153][2375:2380] CHIP:DMG: [1660219447.520189][2375:2380] CHIP:DMG: }, [1660219447.520222][2375:2380] CHIP:DMG: [1660219447.520255][2375:2380] CHIP:DMG: }, [1660219447.520284][2375:2380] CHIP:DMG: [1660219447.520313][2375:2380] CHIP:DMG: ], [1660219447.520340][2375:2380] CHIP:DMG: [1660219447.520361][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219447.520390][2375:2380] CHIP:DMG: }, [1660219447.520452][2375:2380] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1660219447.520478][2375:2380] CHIP:CTL: Device confirmed that it has received the root certificate [1660219447.520504][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1660219447.520523][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1660219447.520558][2375:2380] CHIP:CTL: Performing next commissioning step 'SendNOC' [1660219447.520632][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219447.520678][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219447.520810][2375:2380] CHIP:IN: Prepared secure message 0xffff78035dd8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 52866i with MessageCounter:168613835. [1660219447.520858][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78035dd8 with MessageCounter:168613835 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E93 msec [1660219447.521030][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219447.521066][2375:2380] CHIP:CTL: Sent operational certificate to the device [1660219447.521109][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219447.521139][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809860 on exchange 52865i [1660219447.521215][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52865i with MessageCounter:168613836. [1660219447.521252][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613836 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000175E93 msec [1660219447.521347][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809860 on exchange 52865i [1660219447.523462][2375:2380] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108809861 on exchange 52866i [1660219447.523509][2375:2380] CHIP:EM: Found matching exchange: 52866i, Delegate: 0xffff780368c8 [1660219447.523546][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:168613835 from Retrans Table on exchange 52866i [1660219447.523569][2375:2380] CHIP:EM: Removed CHIP MessageCounter:168613835 from RetransTable on exchange 52866i [1660219447.553735][2375:2378] CHIP:BLE: Device 10:3F:56:E8:DD:DB does not look like a CHIP device. [1660219447.563827][2375:2378] CHIP:BLE: Device E4:41:22:A4:EC:B6 does not look like a CHIP device. [1660219447.565245][2375:2378] CHIP:BLE: Device 1D:5E:FC:2C:FE:97 does not look like a CHIP device. [1660219447.587994][2375:2378] CHIP:BLE: Device 18:1E:55:5A:8B:48 does not look like a CHIP device. [1660219447.596896][2375:2378] CHIP:BLE: Device 59:A0:FD:B8:67:60 does not look like a CHIP device. [1660219447.611260][2375:2378] CHIP:BLE: Device 3E:2B:0B:5F:C4:A7 does not look like a CHIP device. [1660219447.623943][2375:2378] CHIP:BLE: Device 07:9D:35:F5:F7:B1 does not look like a CHIP device. [1660219447.631014][2375:2378] CHIP:BLE: Device 00:04:36:10:5B:7A does not look like a CHIP device. [1660219447.649677][2375:2378] CHIP:BLE: Device 7D:FC:08:E6:75:F9 does not look like a CHIP device. [1660219447.667075][2375:2378] CHIP:BLE: Device 68:27:37:08:85:43 does not look like a CHIP device. [1660219447.723992][2375:2378] CHIP:BLE: Device 72:1F:C8:86:14:F0 does not look like a CHIP device. [1660219447.759853][2375:2378] CHIP:BLE: Device C2:4B:50:11:8F:B5 does not look like a CHIP device. [1660219447.782811][2375:2378] CHIP:BLE: Device 35:0B:17:B7:8C:03 does not look like a CHIP device. [1660219447.925147][2375:2378] CHIP:BLE: Device 34:9B:9E:36:E7:53 does not look like a CHIP device. [1660219448.031631][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809862 on exchange 52866i [1660219448.031725][2375:2380] CHIP:EM: Found matching exchange: 52866i, Delegate: 0xffff780368c8 [1660219448.031786][2375:2380] CHIP:EM: CHIP MessageCounter:168613835 not in RetransTable on exchange 52866i [1660219448.031869][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219448.031966][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219448.032019][2375:2380] CHIP:DMG: { [1660219448.032071][2375:2380] CHIP:DMG: suppressResponse = false, [1660219448.032161][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219448.032231][2375:2380] CHIP:DMG: [ [1660219448.032284][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219448.032376][2375:2380] CHIP:DMG: { [1660219448.032432][2375:2380] CHIP:DMG: CommandDataIB = [1660219448.032521][2375:2380] CHIP:DMG: { [1660219448.032593][2375:2380] CHIP:DMG: CommandPathIB = [1660219448.032686][2375:2380] CHIP:DMG: { [1660219448.032769][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219448.032871][2375:2380] CHIP:DMG: ClusterId = 0x3e, [1660219448.032951][2375:2380] CHIP:DMG: CommandId = 0x8, [1660219448.033045][2375:2380] CHIP:DMG: }, [1660219448.033123][2375:2380] CHIP:DMG: [1660219448.033211][2375:2380] CHIP:DMG: CommandFields = [1660219448.033293][2375:2380] CHIP:DMG: { [1660219448.033397][2375:2380] CHIP:DMG: 0x0 = 0, [1660219448.033484][2375:2380] CHIP:DMG: 0x1 = 4, [1660219448.033582][2375:2380] CHIP:DMG: }, [1660219448.033671][2375:2380] CHIP:DMG: }, [1660219448.033756][2375:2380] CHIP:DMG: [1660219448.033931][2375:2380] CHIP:DMG: }, [1660219448.034006][2375:2380] CHIP:DMG: [1660219448.034080][2375:2380] CHIP:DMG: ], [1660219448.034147][2375:2380] CHIP:DMG: [1660219448.034221][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219448.034274][2375:2380] CHIP:DMG: }, [1660219448.034422][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1660219448.034496][2375:2380] CHIP:CTL: Device returned status 0 on receiving the NOC [1660219448.034567][2375:2380] CHIP:CTL: Operational credentials provisioned on device 0xffff7800c060 [1660219448.034616][2375:2380] CHIP:TOO: Secure Pairing Success [1660219448.034659][2375:2380] CHIP:TOO: CASE establishment successful [1660219448.034733][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1660219448.034783][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'FindOperational' [1660219448.034841][2375:2380] CHIP:CTL: Performing next commissioning step 'FindOperational' [1660219448.034891][2375:2380] CHIP:CSM: FindOrEstablishSession: PeerId = [4:0000000000000004] [1660219448.034960][2375:2380] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1660219448.035026][2375:2380] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 1 --> 2 [1660219448.035107][2375:2380] CHIP:DIS: Resolving A935DEEAD83BF05E:0000000000000004 ... [1660219448.037103][2375:2380] CHIP:DIS: OperationalDeviceProxy[4:0000000000000004]: Operational node lookup already in progress. Will NOT start a new one. [1660219448.037234][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219448.037308][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809862 on exchange 52866i [1660219448.037487][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52866i with MessageCounter:168613837. [1660219448.037576][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:168613837 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000176097 msec [1660219448.037732][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:108809862 on exchange 52866i [1660219448.038052][2375:2380] CHIP:IN: Received a duplicate message with MessageCounter:108809860 on exchange 52865i [1660219448.038104][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:108809860 on exchange 52865i [1660219448.038153][2375:2380] CHIP:EM: Generating StandaloneAck via exchange: 52865i [1660219448.038188][2375:2380] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:108809860 on exchange 52865i [1660219448.038222][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:108809860 on exchange 52865i [1660219448.038309][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ada58 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52865i with MessageCounter:168613838. [1660219448.038358][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ada58 with MessageCounter:168613838 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000176098 msec [1660219448.133714][2375:2378] CHIP:BLE: Device 35:62:C5:03:B8:B1 does not look like a CHIP device. [1660219448.137770][2375:2378] CHIP:BLE: Device 26:84:4B:1D:02:16 does not look like a CHIP device. [1660219448.157368][2375:2380] CHIP:DL: Avahi resolve found [1660219448.157457][2375:2380] CHIP:DIS: Node ID resolved for A935DEEAD83BF05E:0000000000000004 [1660219448.157482][2375:2380] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219448.157509][2375:2380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219448.157530][2375:2380] CHIP:DIS: Port: 5540 [1660219448.157549][2375:2380] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219448.157569][2375:2380] CHIP:DIS: Mrp Interval active: 300 ms [1660219448.157589][2375:2380] CHIP:DIS: TCP Supported: 1 [1660219448.157758][2375:2380] CHIP:DIS: UDP:[fe80::e65f:1ff:fe0e:bf6e%eth0]:5540: new best score: 3 [1660219448.157790][2375:2380] CHIP:DIS: Checking node lookup status after 122 ms [1660219448.157820][2375:2380] CHIP:DIS: Keeping DNSSD lookup active [1660219448.235952][2375:2380] CHIP:DIS: Checking node lookup status after 201 ms [1660219448.236269][2375:2380] CHIP:DIS: OperationalDeviceProxy[4:0000000000000004]: Updating device address to UDP:[fe80::e65f:1ff:fe0e:bf6e%eth0]:5540 while in state 2 [1660219448.236343][2375:2380] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 2 --> 3 [1660219448.236563][2375:2380] CHIP:IN: SecureSession[0xffff7800e910]: Allocated Type:2 LSID:18867 [1660219448.236690][2375:2380] CHIP:SC: Initiating session on local FabricIndex 4 from 0x000000000001B669 -> 0x0000000000000004 [1660219448.238630][2375:2380] CHIP:SC: Including MRP parameters [1660219448.239073][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff78036ba8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 52867i with MessageCounter:227807192. [1660219448.239219][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff78036ba8 with MessageCounter:227807192 to 0x0000000000000000 at monotonic time: 0000000000176161 msec [1660219448.239534][2375:2380] CHIP:SC: Sent Sigma1 msg [1660219448.239634][2375:2380] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 3 --> 4 [1660219448.246977][2375:2380] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:266514599 on exchange 52867i [1660219448.247031][2375:2380] CHIP:EM: Found matching exchange: 52867i, Delegate: 0xffff7803b868 [1660219448.247084][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:227807192 from Retrans Table on exchange 52867i [1660219448.247123][2375:2380] CHIP:EM: Removed CHIP MessageCounter:227807192 from RetransTable on exchange 52867i [1660219448.247176][2375:2380] CHIP:SC: Received Sigma2 msg [1660219448.247226][2375:2380] CHIP:SC: Peer assigned session session ID 33952 [1660219448.253537][2375:2380] CHIP:SC: Found MRP parameters in the message [1660219448.253747][2375:2380] CHIP:SC: Sending Sigma3 [1660219448.254831][2375:2380] CHIP:EM: Piggybacking Ack for MessageCounter:266514599 on exchange: 52867i [1660219448.254923][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff7800f158 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 52867i with MessageCounter:227807193. [1660219448.254986][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff7800f158 with MessageCounter:227807193 to 0x0000000000000000 at monotonic time: 0000000000176171 msec [1660219448.255304][2375:2380] CHIP:SC: Sent Sigma3 msg [1660219448.267248][2375:2380] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:266514600 on exchange 52867i [1660219448.267290][2375:2380] CHIP:EM: Found matching exchange: 52867i, Delegate: 0xffff7803b868 [1660219448.267332][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:227807193 from Retrans Table on exchange 52867i [1660219448.267363][2375:2380] CHIP:EM: Removed CHIP MessageCounter:227807193 from RetransTable on exchange 52867i [1660219448.267408][2375:2380] CHIP:SC: Success status report received. Session was established [1660219448.277530][2375:2380] CHIP:SC: SecureSession[0xffff7800e910]: Moving from state 'kEstablishing' --> 'kActive' [1660219448.277745][2375:2380] CHIP:IN: SecureSession[0xffff7800e910]: Activated - Type:2 LSID:18867 [1660219448.277794][2375:2380] CHIP:IN: New secure session activated for device <0000000000000004, 4>, LSID:18867 PSID:33952! [1660219448.277884][2375:2380] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 4 --> 5 [1660219448.277992][2375:2380] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1660219448.278072][2375:2380] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1660219448.278123][2375:2380] CHIP:CTL: Performing next commissioning step 'SendComplete' [1660219448.278256][2375:2380] CHIP:DMG: ICR moving to [AddingComm] [1660219448.278333][2375:2380] CHIP:DMG: ICR moving to [AddedComma] [1660219448.278534][2375:2380] CHIP:IN: Prepared secure message 0xffff78038608 to 0x0000000000000004 (4) of type 0x8 and protocolId (0, 1) on exchange 52868i with MessageCounter:123760447. [1660219448.278631][2375:2380] CHIP:IN: Sending encrypted msg 0xffff78038608 with MessageCounter:123760447 to 0x0000000000000004 (4) at monotonic time: 0000000000176188 msec [1660219448.278909][2375:2380] CHIP:DMG: ICR moving to [CommandSen] [1660219448.278999][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:266514600 on exchange 52867i [1660219448.279068][2375:2380] CHIP:IN: Prepared unauthenticated message 0xffff8d0ad968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 52867i with MessageCounter:227807194. [1660219448.279133][2375:2380] CHIP:IN: Sending unauthenticated msg 0xffff8d0ad968 with MessageCounter:227807194 to 0x0000000000000000 at monotonic time: 0000000000176189 msec [1660219448.279264][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:266514600 on exchange 52867i [1660219448.298387][2375:2380] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:184925266 on exchange 52868i [1660219448.298472][2375:2380] CHIP:EM: Found matching exchange: 52868i, Delegate: 0xffff7803d408 [1660219448.298541][2375:2380] CHIP:EM: Rxd Ack; Removing MessageCounter:123760447 from Retrans Table on exchange 52868i [1660219448.298588][2375:2380] CHIP:EM: Removed CHIP MessageCounter:123760447 from RetransTable on exchange 52868i [1660219448.298649][2375:2380] CHIP:DMG: ICR moving to [ResponseRe] [1660219448.298734][2375:2380] CHIP:DMG: InvokeResponseMessage = [1660219448.298780][2375:2380] CHIP:DMG: { [1660219448.298850][2375:2380] CHIP:DMG: suppressResponse = false, [1660219448.298898][2375:2380] CHIP:DMG: InvokeResponseIBs = [1660219448.298975][2375:2380] CHIP:DMG: [ [1660219448.299024][2375:2380] CHIP:DMG: InvokeResponseIB = [1660219448.299111][2375:2380] CHIP:DMG: { [1660219448.299163][2375:2380] CHIP:DMG: CommandDataIB = [1660219448.299222][2375:2380] CHIP:DMG: { [1660219448.299306][2375:2380] CHIP:DMG: CommandPathIB = [1660219448.299373][2375:2380] CHIP:DMG: { [1660219448.299461][2375:2380] CHIP:DMG: EndpointId = 0x0, [1660219448.299547][2375:2380] CHIP:DMG: ClusterId = 0x30, [1660219448.299616][2375:2380] CHIP:DMG: CommandId = 0x5, [1660219448.299696][2375:2380] CHIP:DMG: }, [1660219448.299847][2375:2380] CHIP:DMG: [1660219448.299911][2375:2380] CHIP:DMG: CommandFields = [1660219448.300001][2375:2380] CHIP:DMG: { [1660219448.300069][2375:2380] CHIP:DMG: 0x0 = 0, [1660219448.300161][2375:2380] CHIP:DMG: 0x1 = "" (0 chars), [1660219448.300229][2375:2380] CHIP:DMG: }, [1660219448.300307][2375:2380] CHIP:DMG: }, [1660219448.300373][2375:2380] CHIP:DMG: [1660219448.300442][2375:2380] CHIP:DMG: }, [1660219448.300502][2375:2380] CHIP:DMG: [1660219448.300564][2375:2380] CHIP:DMG: ], [1660219448.300623][2375:2380] CHIP:DMG: [1660219448.300669][2375:2380] CHIP:DMG: InteractionModelRevision = 1 [1660219448.300732][2375:2380] CHIP:DMG: }, [1660219448.300841][2375:2380] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1660219448.300923][2375:2380] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1660219448.300977][2375:2380] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1660219448.301038][2375:2380] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1660219448.301089][2375:2380] CHIP:CTL: Performing next commissioning step 'Cleanup' [1660219448.301201][2375:2380] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1660219448.301255][2375:2380] CHIP:TOO: Device commissioning completed with success [1660219448.301389][2375:2380] CHIP:DMG: ICR moving to [AwaitingDe] [1660219448.301453][2375:2380] CHIP:EM: Sending Standalone Ack for MessageCounter:184925266 on exchange 52868i [1660219448.301597][2375:2380] CHIP:IN: Prepared secure message 0xffff8d0ad978 to 0x0000000000000004 (4) of type 0x10 and protocolId (0, 0) on exchange 52868i with MessageCounter:123760448. [1660219448.301685][2375:2380] CHIP:IN: Sending encrypted msg 0xffff8d0ad978 with MessageCounter:123760448 to 0x0000000000000004 (4) at monotonic time: 000000000017619F msec [1660219448.301926][2375:2380] CHIP:EM: Flushed pending ack for MessageCounter:184925266 on exchange 52868i [1660219448.302400][2375:2375] CHIP:CTL: Shutting down the commissioner [1660219448.302463][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219448.302510][2375:2375] CHIP:CTL: Shutting down the controller [1660219448.302566][2375:2375] CHIP:IN: Expiring all sessions for fabric 0x4!! [1660219448.302610][2375:2375] CHIP:IN: SecureSession[0xffff7800e910]: MarkForEviction Type:2 LSID:18867 [1660219448.302653][2375:2375] CHIP:SC: SecureSession[0xffff7800e910]: Moving from state 'kActive' --> 'kPendingEviction' [1660219448.302697][2375:2375] CHIP:IN: SecureSession[0xffff7800e910]: Released - Type:2 LSID:18867 [1660219448.302745][2375:2375] CHIP:FP: Forgetting fabric 0x4 [1660219448.302852][2375:2375] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219448.303294][2375:2375] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219448.303346][2375:2375] CHIP:TS: Reverted Last Known Good Time to previous value [1660219448.303422][2375:2375] CHIP:CTL: Shutting down the commissioner [1660219448.303466][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219448.303507][2375:2375] CHIP:CTL: Shutting down the controller [1660219448.303547][2375:2375] CHIP:IN: Expiring all sessions for fabric 0x1!! [1660219448.303587][2375:2375] CHIP:FP: Forgetting fabric 0x1 [1660219448.303635][2375:2375] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219448.303898][2375:2375] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219448.303945][2375:2375] CHIP:TS: Reverted Last Known Good Time to previous value [1660219448.304004][2375:2375] CHIP:CTL: Shutting down the commissioner [1660219448.304048][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219448.304089][2375:2375] CHIP:CTL: Shutting down the controller [1660219448.304127][2375:2375] CHIP:IN: Expiring all sessions for fabric 0x2!! [1660219448.304167][2375:2375] CHIP:FP: Forgetting fabric 0x2 [1660219448.304211][2375:2375] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219448.304466][2375:2375] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219448.304512][2375:2375] CHIP:TS: Reverted Last Known Good Time to previous value [1660219448.304571][2375:2375] CHIP:CTL: Shutting down the commissioner [1660219448.304613][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219448.304653][2375:2375] CHIP:CTL: Shutting down the controller [1660219448.304691][2375:2375] CHIP:IN: Expiring all sessions for fabric 0x3!! [1660219448.304730][2375:2375] CHIP:FP: Forgetting fabric 0x3 [1660219448.304776][2375:2375] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219448.305024][2375:2375] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219448.305069][2375:2375] CHIP:TS: Reverted Last Known Good Time to previous value [1660219448.305127][2375:2375] CHIP:CTL: Shutting down the commissioner [1660219448.305171][2375:2375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219448.305211][2375:2375] CHIP:CTL: Shutting down the controller [1660219448.305249][2375:2375] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1660219448.306840][2375:2375] CHIP:DMG: IM WH moving to [Uninitialized] [1660219448.306905][2375:2375] CHIP:DMG: IM WH moving to [Uninitialized] [1660219448.306946][2375:2375] CHIP:DMG: IM WH moving to [Uninitialized] [1660219448.306986][2375:2375] CHIP:DMG: IM WH moving to [Uninitialized] [1660219448.307026][2375:2375] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1660219448.307164][2375:2375] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1660219448.307592][2375:2375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hlOwhN) [1660219448.308789][2375:2375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219448.308920][2375:2375] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1660219448.308970][2375:2375] CHIP:DL: Inet Layer shutdown [1660219448.309011][2375:2375] CHIP:DL: BLE shutdown [1660219448.313397][2375:2378] CHIP:CTL: Commissioning discovery over BLE failed: ../../src/platform/Linux/BLEManagerImpl.cpp:808: CHIP Error 0x00000032: Timeout [1660219448.313458][2375:2378] CHIP:-: ../../src/platform/Linux/BLEManagerImpl.cpp:808: CHIP Error 0x00000032: Timeout at ../../src/controller/SetUpCodePairer.cpp:277 [1660219448.316667][2375:2375] CHIP:DL: System Layer shutdown [1660219448.316807][2375:2375] CHIP:IN: SecureSession[0xaaaac2134400]: MarkForEviction Type:1 LSID:18866 [1660219448.316846][2375:2375] CHIP:SC: SecureSession[0xaaaac2134400]: Moving from state 'kActive' --> 'kPendingEviction' [1660219448.316871][2375:2375] CHIP:IN: SecureSession[0xaaaac2134400]: Released - Type:1 LSID:18866 ubuntu@ubuntu:~/apps$ ./chip-tool interactive start [1660219452.379141][2383:2383] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1660219452.385018][2383:2383] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1660219452.385382][2383:2383] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1660219452.385550][2383:2383] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1660219452.385985][2383:2383] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CmZ5bw) [1660219452.386699][2383:2383] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219452.386784][2383:2383] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1660219452.387708][2383:2383] CHIP:DL: Got Ethernet interface: eth0 [1660219452.388361][2383:2383] CHIP:DL: Found the primary Ethernet interface:eth0 [1660219452.389045][2383:2383] CHIP:DL: Got WiFi interface: wlan0 [1660219452.389139][2383:2383] CHIP:DL: Failed to reset WiFi statistic counts [1660219452.389198][2383:2383] CHIP:IN: UDP::Init bind&listen port=0 [1660219452.389325][2383:2383] CHIP:IN: UDP::Init bound to port=49534 [1660219452.389352][2383:2383] CHIP:IN: BLEBase::Init - setting/overriding transport [1660219452.389382][2383:2383] CHIP:IN: TransportMgr initialized [1660219452.389421][2383:2383] CHIP:FP: Initializing FabricTable from persistent storage [1660219452.389684][2383:2383] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219452.391474][2383:2383] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x863F8D90D715E7ED, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219452.392092][2383:2383] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x3AE8B6BBFFEEF20B, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219452.392717][2383:2383] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3481DC27557ECE, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219452.393239][2383:2383] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xA935DEEAD83BF05E, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219452.403476][2383:2383] CHIP:ZCL: Using ZAP configuration... [1660219452.407963][2383:2383] CHIP:DL: Avahi client registered [1660219452.409320][2383:2383] CHIP:CTL: System State Initialized... [1660219452.409452][2383:2383] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219452.409491][2383:2383] CHIP:CTL: Setting attestation nonce to random value [1660219452.409528][2383:2383] CHIP:CTL: Setting CSR nonce to random value [1660219452.409625][2383:2383] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219452.409655][2383:2383] CHIP:CTL: Setting attestation nonce to random value [1660219452.409688][2383:2383] CHIP:CTL: Setting CSR nonce to random value [1660219452.410708][2383:2383] CHIP:CTL: Generating NOC [1660219452.412018][2383:2383] CHIP:FP: Validating NOC chain [1660219452.413699][2383:2383] CHIP:FP: NOC chain validation successful [1660219452.413986][2383:2383] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1660219452.414027][2383:2383] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219452.414049][2383:2383] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219452.414067][2383:2383] CHIP:TS: Retaining current Last Known Good Time [1660219452.419658][2383:2383] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1660219452.435026][2383:2383] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219452.450383][2383:2383] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1660219452.450598][2383:2383] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219452.450666][2383:2383] CHIP:CTL: Setting attestation nonce to random value [1660219452.450757][2383:2383] CHIP:CTL: Setting CSR nonce to random value [1660219452.452390][2383:2383] CHIP:CTL: Generating NOC [1660219452.454734][2383:2383] CHIP:FP: Validating NOC chain [1660219452.458167][2383:2383] CHIP:FP: NOC chain validation successful [1660219452.458477][2383:2383] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1660219452.458562][2383:2383] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219452.458608][2383:2383] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219452.458651][2383:2383] CHIP:TS: Retaining current Last Known Good Time [1660219452.465556][2383:2383] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1660219452.481050][2383:2383] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219452.496154][2383:2383] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1660219452.496306][2383:2383] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219452.496350][2383:2383] CHIP:CTL: Setting attestation nonce to random value [1660219452.496409][2383:2383] CHIP:CTL: Setting CSR nonce to random value [1660219452.497419][2383:2383] CHIP:CTL: Generating NOC [1660219452.498843][2383:2383] CHIP:FP: Validating NOC chain [1660219452.500868][2383:2383] CHIP:FP: NOC chain validation successful [1660219452.501189][2383:2383] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1660219452.501238][2383:2383] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219452.501264][2383:2383] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219452.501287][2383:2383] CHIP:TS: Retaining current Last Known Good Time [1660219452.511478][2383:2383] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1660219452.526732][2383:2383] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219452.542048][2383:2383] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1660219452.697628][2383:2389] CHIP:DL: CHIP task running [1660219452.697905][2383:2389] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ^C ubuntu@ubuntu:~/apps$ ./chip-tool basic write node-id 1 4 1 --commissioner-name 4 [1660219577.963976][2398:2398] CHIP:TOO: Unknown attribute: node-id Usage: ./chip-tool basic write attribute-name [param1 param2 ...] +-------------------------------------------------------------------------------------+ | Attributes: | +-------------------------------------------------------------------------------------+ | * node-label | | * location | | * local-config-disabled | +-------------------------------------------------------------------------------------+ [1660219577.964299][2398:2398] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/Commands.cpp:137: Error 0x0000002F ubuntu@ubuntu:~/apps$ ./chip-tool basic write node-label 1 4 1 --commissioner-name 4 [1660219584.698321][2399:2399] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1660219584.703849][2399:2399] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1660219584.704233][2399:2399] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1660219584.704349][2399:2399] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1660219584.704708][2399:2399] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-IF9o7J) [1660219584.705335][2399:2399] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219584.705396][2399:2399] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1660219584.706454][2399:2399] CHIP:DL: Got Ethernet interface: eth0 [1660219584.707214][2399:2399] CHIP:DL: Found the primary Ethernet interface:eth0 [1660219584.707889][2399:2399] CHIP:DL: Got WiFi interface: wlan0 [1660219584.707967][2399:2399] CHIP:DL: Failed to reset WiFi statistic counts [1660219584.708024][2399:2399] CHIP:IN: UDP::Init bind&listen port=0 [1660219584.708147][2399:2399] CHIP:IN: UDP::Init bound to port=34974 [1660219584.708175][2399:2399] CHIP:IN: BLEBase::Init - setting/overriding transport [1660219584.708206][2399:2399] CHIP:IN: TransportMgr initialized [1660219584.708243][2399:2399] CHIP:FP: Initializing FabricTable from persistent storage [1660219584.708507][2399:2399] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219584.710488][2399:2399] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x863F8D90D715E7ED, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219584.711113][2399:2399] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x3AE8B6BBFFEEF20B, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219584.711682][2399:2399] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3481DC27557ECE, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219584.712225][2399:2399] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xA935DEEAD83BF05E, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219584.716201][2399:2399] CHIP:ZCL: Using ZAP configuration... [1660219584.720111][2399:2399] CHIP:DL: Avahi client registered [1660219584.721362][2399:2399] CHIP:CTL: System State Initialized... [1660219584.721479][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219584.721516][2399:2399] CHIP:CTL: Setting attestation nonce to random value [1660219584.721549][2399:2399] CHIP:CTL: Setting CSR nonce to random value [1660219584.721635][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219584.721660][2399:2399] CHIP:CTL: Setting attestation nonce to random value [1660219584.721690][2399:2399] CHIP:CTL: Setting CSR nonce to random value [1660219584.722615][2399:2399] CHIP:CTL: Generating NOC [1660219584.723959][2399:2399] CHIP:FP: Validating NOC chain [1660219584.725590][2399:2399] CHIP:FP: NOC chain validation successful [1660219584.725740][2399:2399] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1660219584.725770][2399:2399] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219584.725790][2399:2399] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219584.725809][2399:2399] CHIP:TS: Retaining current Last Known Good Time [1660219584.729683][2399:2399] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1660219584.733368][2399:2399] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219584.736905][2399:2399] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1660219584.737058][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219584.737106][2399:2399] CHIP:CTL: Setting attestation nonce to random value [1660219584.737168][2399:2399] CHIP:CTL: Setting CSR nonce to random value [1660219584.738208][2399:2399] CHIP:CTL: Generating NOC [1660219584.739419][2399:2399] CHIP:FP: Validating NOC chain [1660219584.741042][2399:2399] CHIP:FP: NOC chain validation successful [1660219584.741236][2399:2399] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1660219584.741266][2399:2399] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219584.741286][2399:2399] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219584.741305][2399:2399] CHIP:TS: Retaining current Last Known Good Time [1660219584.744356][2399:2399] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1660219584.747459][2399:2399] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219584.750834][2399:2399] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1660219584.750962][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219584.750998][2399:2399] CHIP:CTL: Setting attestation nonce to random value [1660219584.751050][2399:2399] CHIP:CTL: Setting CSR nonce to random value [1660219584.751822][2399:2399] CHIP:CTL: Generating NOC [1660219584.752935][2399:2399] CHIP:FP: Validating NOC chain [1660219584.754697][2399:2399] CHIP:FP: NOC chain validation successful [1660219584.754853][2399:2399] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1660219584.754884][2399:2399] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219584.754902][2399:2399] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219584.754917][2399:2399] CHIP:TS: Retaining current Last Known Good Time [1660219584.758252][2399:2399] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1660219584.761189][2399:2399] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219584.764012][2399:2399] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1660219584.764150][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219584.764187][2399:2399] CHIP:CTL: Setting attestation nonce to random value [1660219584.764239][2399:2399] CHIP:CTL: Setting CSR nonce to random value [1660219584.765061][2399:2399] CHIP:CTL: Generating NOC [1660219584.766353][2399:2399] CHIP:FP: Validating NOC chain [1660219584.768059][2399:2399] CHIP:FP: NOC chain validation successful [1660219584.768317][2399:2399] CHIP:FP: Updated fabric at index: 0x4, Node ID: 0x000000000001B669 [1660219584.768351][2399:2399] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219584.768372][2399:2399] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219584.768391][2399:2399] CHIP:TS: Retaining current Last Known Good Time [1660219584.776352][2399:2399] CHIP:FP: Metadata for Fabric 0x4 persisted to storage. [1660219584.782313][2399:2399] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219584.785086][2399:2399] CHIP:CTL: Joined the fabric at index 4. Compressed fabric ID is: 0x0000000000000000 [1660219584.844452][2399:2404] CHIP:DL: CHIP task running [1660219584.844678][2399:2404] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1660219584.844710][2399:2404] CHIP:TOO: Sending command to node 0x4 [1660219584.844749][2399:2404] CHIP:CSM: FindOrEstablishSession: PeerId = [4:0000000000000004] [1660219584.844773][2399:2404] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1660219584.844807][2399:2404] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 1 --> 2 [1660219584.844835][2399:2404] CHIP:DIS: Resolving A935DEEAD83BF05E:0000000000000004 ... [1660219584.954214][2399:2404] CHIP:DL: Avahi resolve found [1660219584.954308][2399:2404] CHIP:DIS: Node ID resolved for A935DEEAD83BF05E:0000000000000004 [1660219584.954335][2399:2404] CHIP:DIS: Hostname: E45F010EBF6E0000 [1660219584.954361][2399:2404] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe0e:bf6e [1660219584.954382][2399:2404] CHIP:DIS: Port: 5540 [1660219584.954402][2399:2404] CHIP:DIS: Mrp Interval idle: 5000 ms [1660219584.954422][2399:2404] CHIP:DIS: Mrp Interval active: 300 ms [1660219584.954441][2399:2404] CHIP:DIS: TCP Supported: 1 [1660219584.954597][2399:2404] CHIP:DIS: UDP:[fe80::e65f:1ff:fe0e:bf6e%eth0]:5540: new best score: 3 [1660219584.954635][2399:2404] CHIP:DIS: Checking node lookup status after 109 ms [1660219584.954656][2399:2404] CHIP:DIS: Keeping DNSSD lookup active [1660219585.045804][2399:2404] CHIP:DIS: Checking node lookup status after 200 ms [1660219585.046147][2399:2404] CHIP:DIS: OperationalDeviceProxy[4:0000000000000004]: Updating device address to UDP:[fe80::e65f:1ff:fe0e:bf6e%eth0]:5540 while in state 2 [1660219585.046220][2399:2404] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 2 --> 3 [1660219585.046765][2399:2404] CHIP:IN: SecureSession[0xffff98001d70]: Allocated Type:2 LSID:43042 [1660219585.046860][2399:2404] CHIP:SC: Initiating session on local FabricIndex 4 from 0x000000000001B669 -> 0x0000000000000004 [1660219585.048640][2399:2404] CHIP:SC: Including MRP parameters [1660219585.049076][2399:2404] CHIP:IN: Prepared unauthenticated message 0xffff98000f48 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 20414i with MessageCounter:80486408. [1660219585.049213][2399:2404] CHIP:IN: Sending unauthenticated msg 0xffff98000f48 with MessageCounter:80486408 to 0x0000000000000000 at monotonic time: 00000000001977CB msec [1660219585.049581][2399:2404] CHIP:SC: Sent Sigma1 msg [1660219585.049656][2399:2404] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 3 --> 4 [1660219585.058221][2399:2404] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:266514601 on exchange 20414i [1660219585.058311][2399:2404] CHIP:EM: Found matching exchange: 20414i, Delegate: 0xffff980011a8 [1660219585.058397][2399:2404] CHIP:EM: Rxd Ack; Removing MessageCounter:80486408 from Retrans Table on exchange 20414i [1660219585.058460][2399:2404] CHIP:EM: Removed CHIP MessageCounter:80486408 from RetransTable on exchange 20414i [1660219585.058543][2399:2404] CHIP:SC: Received Sigma2 msg [1660219585.058663][2399:2404] CHIP:SC: Peer assigned session session ID 33954 [1660219585.065368][2399:2404] CHIP:SC: Found MRP parameters in the message [1660219585.065454][2399:2404] CHIP:SC: Sending Sigma3 [1660219585.066492][2399:2404] CHIP:EM: Piggybacking Ack for MessageCounter:266514601 on exchange: 20414i [1660219585.066584][2399:2404] CHIP:IN: Prepared unauthenticated message 0xffff98002508 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 20414i with MessageCounter:80486409. [1660219585.066647][2399:2404] CHIP:IN: Sending unauthenticated msg 0xffff98002508 with MessageCounter:80486409 to 0x0000000000000000 at monotonic time: 00000000001977DC msec [1660219585.066872][2399:2404] CHIP:SC: Sent Sigma3 msg [1660219585.076885][2399:2404] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:266514602 on exchange 20414i [1660219585.076936][2399:2404] CHIP:EM: Found matching exchange: 20414i, Delegate: 0xffff980011a8 [1660219585.076984][2399:2404] CHIP:EM: Rxd Ack; Removing MessageCounter:80486409 from Retrans Table on exchange 20414i [1660219585.077021][2399:2404] CHIP:EM: Removed CHIP MessageCounter:80486409 from RetransTable on exchange 20414i [1660219585.077074][2399:2404] CHIP:SC: Success status report received. Session was established [1660219585.083731][2399:2404] CHIP:SC: SecureSession[0xffff98001d70]: Moving from state 'kEstablishing' --> 'kActive' [1660219585.083804][2399:2404] CHIP:IN: SecureSession[0xffff98001d70]: Activated - Type:2 LSID:43042 [1660219585.083833][2399:2404] CHIP:IN: New secure session activated for device <0000000000000004, 4>, LSID:43042 PSID:33954! [1660219585.083868][2399:2404] CHIP:CTL: OperationalDeviceProxy[4:0000000000000004]: State change 4 --> 5 [1660219585.083983][2399:2404] CHIP:TOO: cluster 0x0000_0028, attribute: 0x0000_0005, endpoint 1 [1660219585.084073][2399:2404] CHIP:DMG: WriteClient moving to [AddAttribu] [1660219585.084234][2399:2404] CHIP:IN: Prepared secure message 0xaaab24c9ab98 to 0x0000000000000004 (4) of type 0x6 and protocolId (0, 1) on exchange 20415i with MessageCounter:71201418. [1660219585.084289][2399:2404] CHIP:IN: Sending encrypted msg 0xaaab24c9ab98 with MessageCounter:71201418 to 0x0000000000000004 (4) at monotonic time: 00000000001977EE msec [1660219585.084482][2399:2404] CHIP:DMG: WriteClient moving to [AwaitingRe] [1660219585.084533][2399:2404] CHIP:EM: Sending Standalone Ack for MessageCounter:266514602 on exchange 20414i [1660219585.084579][2399:2404] CHIP:IN: Prepared unauthenticated message 0xffff9fffd968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 20414i with MessageCounter:80486410. [1660219585.084622][2399:2404] CHIP:IN: Sending unauthenticated msg 0xffff9fffd968 with MessageCounter:80486410 to 0x0000000000000000 at monotonic time: 00000000001977EE msec [1660219585.084710][2399:2404] CHIP:EM: Flushed pending ack for MessageCounter:266514602 on exchange 20414i [1660219585.086219][2399:2404] CHIP:EM: Received message of type 0x7 with protocolId (0, 1) and MessageCounter:255583001 on exchange 20415i [1660219585.086268][2399:2404] CHIP:EM: Found matching exchange: 20415i, Delegate: 0xffff980047e0 [1660219585.086314][2399:2404] CHIP:EM: Rxd Ack; Removing MessageCounter:71201418 from Retrans Table on exchange 20415i [1660219585.086347][2399:2404] CHIP:EM: Removed CHIP MessageCounter:71201418 from RetransTable on exchange 20415i [1660219585.086387][2399:2404] CHIP:DMG: WriteClient moving to [ResponseRe] [1660219585.086450][2399:2404] CHIP:DMG: WriteResponseMessage = [1660219585.086482][2399:2404] CHIP:DMG: { [1660219585.086510][2399:2404] CHIP:DMG: AttributeStatusIBs = [1660219585.086550][2399:2404] CHIP:DMG: [ [1660219585.086582][2399:2404] CHIP:DMG: AttributeStatusIB = [1660219585.086632][2399:2404] CHIP:DMG: { [1660219585.086665][2399:2404] CHIP:DMG: AttributePathIB = [1660219585.086708][2399:2404] CHIP:DMG: { [1660219585.086750][2399:2404] CHIP:DMG: Endpoint = 0x1, [1660219585.086799][2399:2404] CHIP:DMG: Cluster = 0x28, [1660219585.086843][2399:2404] CHIP:DMG: Attribute = 0x0000_0005, [1660219585.086883][2399:2404] CHIP:DMG: } [1660219585.086933][2399:2404] CHIP:DMG: [1660219585.086974][2399:2404] CHIP:DMG: StatusIB = [1660219585.087019][2399:2404] CHIP:DMG: { [1660219585.087061][2399:2404] CHIP:DMG: status = 0xc3 (UNSUPPORTED_CLUSTER), [1660219585.087108][2399:2404] CHIP:DMG: }, [1660219585.087148][2399:2404] CHIP:DMG: [1660219585.087182][2399:2404] CHIP:DMG: }, [1660219585.087219][2399:2404] CHIP:DMG: [1660219585.087250][2399:2404] CHIP:DMG: ], [1660219585.087288][2399:2404] CHIP:DMG: [1660219585.087319][2399:2404] CHIP:DMG: InteractionModelRevision = 1 [1660219585.087349][2399:2404] CHIP:DMG: } [1660219585.087434][2399:2404] CHIP:DMG: WriteClient moving to [AwaitingDe] [1660219585.087475][2399:2404] CHIP:TOO: Response Failure: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1660219585.087548][2399:2404] CHIP:EM: Sending Standalone Ack for MessageCounter:255583001 on exchange 20415i [1660219585.087639][2399:2404] CHIP:IN: Prepared secure message 0xffff9fffd978 to 0x0000000000000004 (4) of type 0x10 and protocolId (0, 0) on exchange 20415i with MessageCounter:71201419. [1660219585.087687][2399:2404] CHIP:IN: Sending encrypted msg 0xffff9fffd978 with MessageCounter:71201419 to 0x0000000000000004 (4) at monotonic time: 00000000001977F1 msec [1660219585.087817][2399:2404] CHIP:EM: Flushed pending ack for MessageCounter:255583001 on exchange 20415i [1660219585.088037][2399:2399] CHIP:CTL: Shutting down the commissioner [1660219585.088079][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219585.088110][2399:2399] CHIP:CTL: Shutting down the controller [1660219585.088149][2399:2399] CHIP:IN: Expiring all sessions for fabric 0x4!! [1660219585.088178][2399:2399] CHIP:IN: SecureSession[0xffff98001d70]: MarkForEviction Type:2 LSID:43042 [1660219585.088207][2399:2399] CHIP:SC: SecureSession[0xffff98001d70]: Moving from state 'kActive' --> 'kPendingEviction' [1660219585.088236][2399:2399] CHIP:IN: SecureSession[0xffff98001d70]: Released - Type:2 LSID:43042 [1660219585.088268][2399:2399] CHIP:FP: Forgetting fabric 0x4 [1660219585.088310][2399:2399] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219585.088571][2399:2399] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219585.088604][2399:2399] CHIP:TS: Reverted Last Known Good Time to previous value [1660219585.088652][2399:2399] CHIP:CTL: Shutting down the commissioner [1660219585.088684][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219585.088713][2399:2399] CHIP:CTL: Shutting down the controller [1660219585.088739][2399:2399] CHIP:IN: Expiring all sessions for fabric 0x1!! [1660219585.088766][2399:2399] CHIP:FP: Forgetting fabric 0x1 [1660219585.088797][2399:2399] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219585.088978][2399:2399] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219585.089009][2399:2399] CHIP:TS: Reverted Last Known Good Time to previous value [1660219585.089049][2399:2399] CHIP:CTL: Shutting down the commissioner [1660219585.089079][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219585.089106][2399:2399] CHIP:CTL: Shutting down the controller [1660219585.089133][2399:2399] CHIP:IN: Expiring all sessions for fabric 0x2!! [1660219585.089159][2399:2399] CHIP:FP: Forgetting fabric 0x2 [1660219585.089189][2399:2399] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219585.089328][2399:2399] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219585.089426][2399:2399] CHIP:TS: Reverted Last Known Good Time to previous value [1660219585.089457][2399:2399] CHIP:CTL: Shutting down the commissioner [1660219585.089478][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219585.089497][2399:2399] CHIP:CTL: Shutting down the controller [1660219585.089516][2399:2399] CHIP:IN: Expiring all sessions for fabric 0x3!! [1660219585.089534][2399:2399] CHIP:FP: Forgetting fabric 0x3 [1660219585.089557][2399:2399] CHIP:TS: Pending Last Known Good Time: 2022-08-03T19:41:28 [1660219585.089686][2399:2399] CHIP:TS: Previous Last Known Good Time: 2022-08-03T19:41:28 [1660219585.089708][2399:2399] CHIP:TS: Reverted Last Known Good Time to previous value [1660219585.089736][2399:2399] CHIP:CTL: Shutting down the commissioner [1660219585.089756][2399:2399] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219585.089775][2399:2399] CHIP:CTL: Shutting down the controller [1660219585.089794][2399:2399] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1660219585.090797][2399:2399] CHIP:DMG: IM WH moving to [Uninitialized] [1660219585.090838][2399:2399] CHIP:DMG: IM WH moving to [Uninitialized] [1660219585.090858][2399:2399] CHIP:DMG: IM WH moving to [Uninitialized] [1660219585.090876][2399:2399] CHIP:DMG: IM WH moving to [Uninitialized] [1660219585.090897][2399:2399] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1660219585.090977][2399:2399] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1660219585.091266][2399:2399] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-pxrl5W) [1660219585.091998][2399:2399] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219585.092072][2399:2399] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1660219585.092097][2399:2399] CHIP:DL: Inet Layer shutdown [1660219585.092117][2399:2399] CHIP:DL: BLE shutdown [1660219585.092138][2399:2399] CHIP:DL: System Layer shutdown [1660219585.092264][2399:2399] CHIP:TOO: Run command failure: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) ubuntu@ubuntu:~/apps$ ./chip-tool interactive start [1660219599.507090][2405:2405] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1660219599.512781][2405:2405] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1660219599.513138][2405:2405] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1660219599.513264][2405:2405] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1660219599.513654][2405:2405] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-uGtIkU) [1660219599.514505][2405:2405] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219599.514589][2405:2405] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4) [1660219599.515489][2405:2405] CHIP:DL: Got Ethernet interface: eth0 [1660219599.516272][2405:2405] CHIP:DL: Found the primary Ethernet interface:eth0 [1660219599.516926][2405:2405] CHIP:DL: Got WiFi interface: wlan0 [1660219599.517008][2405:2405] CHIP:DL: Failed to reset WiFi statistic counts [1660219599.517067][2405:2405] CHIP:IN: UDP::Init bind&listen port=0 [1660219599.517184][2405:2405] CHIP:IN: UDP::Init bound to port=40561 [1660219599.517209][2405:2405] CHIP:IN: BLEBase::Init - setting/overriding transport [1660219599.517229][2405:2405] CHIP:IN: TransportMgr initialized [1660219599.517265][2405:2405] CHIP:FP: Initializing FabricTable from persistent storage [1660219599.517521][2405:2405] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219599.519303][2405:2405] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x863F8D90D715E7ED, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219599.519968][2405:2405] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x3AE8B6BBFFEEF20B, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219599.520568][2405:2405] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3481DC27557ECE, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219599.521097][2405:2405] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xA935DEEAD83BF05E, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219599.524725][2405:2405] CHIP:ZCL: Using ZAP configuration... [1660219599.529169][2405:2405] CHIP:DL: Avahi client registered [1660219599.530566][2405:2405] CHIP:CTL: System State Initialized... [1660219599.530693][2405:2405] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219599.530732][2405:2405] CHIP:CTL: Setting attestation nonce to random value [1660219599.530767][2405:2405] CHIP:CTL: Setting CSR nonce to random value [1660219599.530860][2405:2405] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219599.530889][2405:2405] CHIP:CTL: Setting attestation nonce to random value [1660219599.530920][2405:2405] CHIP:CTL: Setting CSR nonce to random value [1660219599.531845][2405:2405] CHIP:CTL: Generating NOC [1660219599.533119][2405:2405] CHIP:FP: Validating NOC chain [1660219599.534853][2405:2405] CHIP:FP: NOC chain validation successful [1660219599.535092][2405:2405] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1660219599.535132][2405:2405] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219599.535153][2405:2405] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219599.535172][2405:2405] CHIP:TS: Retaining current Last Known Good Time [1660219599.538849][2405:2405] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1660219599.544799][2405:2405] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219599.548101][2405:2405] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1660219599.548246][2405:2405] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219599.548287][2405:2405] CHIP:CTL: Setting attestation nonce to random value [1660219599.548348][2405:2405] CHIP:CTL: Setting CSR nonce to random value [1660219599.549355][2405:2405] CHIP:CTL: Generating NOC [1660219599.550686][2405:2405] CHIP:FP: Validating NOC chain [1660219599.552542][2405:2405] CHIP:FP: NOC chain validation successful [1660219599.552715][2405:2405] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1660219599.552748][2405:2405] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219599.552773][2405:2405] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219599.552795][2405:2405] CHIP:TS: Retaining current Last Known Good Time [1660219599.556441][2405:2405] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1660219599.559586][2405:2405] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219599.562379][2405:2405] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1660219599.562486][2405:2405] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219599.562521][2405:2405] CHIP:CTL: Setting attestation nonce to random value [1660219599.562572][2405:2405] CHIP:CTL: Setting CSR nonce to random value [1660219599.563347][2405:2405] CHIP:CTL: Generating NOC [1660219599.564556][2405:2405] CHIP:FP: Validating NOC chain [1660219599.566227][2405:2405] CHIP:FP: NOC chain validation successful [1660219599.566381][2405:2405] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1660219599.566412][2405:2405] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219599.566433][2405:2405] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219599.566451][2405:2405] CHIP:TS: Retaining current Last Known Good Time [1660219599.569919][2405:2405] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1660219599.575740][2405:2405] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219599.578954][2405:2405] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1660219599.624700][2405:2410] CHIP:DL: CHIP task running [1660219599.624941][2405:2410] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 basic write node-label 1 4 1 --commissioner-name 4 [1660219617.385099][2405:2410] CHIP:TOO: Sending command to node 0x4 Segmentation fault (core dumped) ubuntu@ubuntu:~/apps$ ./chip-tool interactive start [1660219624.306617][2412:2412] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1660219624.312219][2412:2412] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1660219624.312507][2412:2412] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1660219624.312630][2412:2412] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1660219624.313015][2412:2412] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-aE5FEP) [1660219624.313648][2412:2412] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1660219624.313706][2412:2412] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5) [1660219624.314574][2412:2412] CHIP:DL: Got Ethernet interface: eth0 [1660219624.315129][2412:2412] CHIP:DL: Found the primary Ethernet interface:eth0 [1660219624.315683][2412:2412] CHIP:DL: Got WiFi interface: wlan0 [1660219624.315753][2412:2412] CHIP:DL: Failed to reset WiFi statistic counts [1660219624.315806][2412:2412] CHIP:IN: UDP::Init bind&listen port=0 [1660219624.315911][2412:2412] CHIP:IN: UDP::Init bound to port=39781 [1660219624.315935][2412:2412] CHIP:IN: BLEBase::Init - setting/overriding transport [1660219624.315954][2412:2412] CHIP:IN: TransportMgr initialized [1660219624.315989][2412:2412] CHIP:FP: Initializing FabricTable from persistent storage [1660219624.316229][2412:2412] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219624.318051][2412:2412] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x863F8D90D715E7ED, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219624.318633][2412:2412] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x3AE8B6BBFFEEF20B, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219624.319145][2412:2412] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3481DC27557ECE, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219624.319631][2412:2412] CHIP:FP: Fabric index 0x4 was retrieved from storage. Compressed FabricId 0xA935DEEAD83BF05E, FabricId 0x0000000000000004, NodeId 0x000000000001B669, VendorId 0xFFF1 [1660219624.322987][2412:2412] CHIP:ZCL: Using ZAP configuration... [1660219624.326922][2412:2412] CHIP:DL: Avahi client registered [1660219624.328090][2412:2412] CHIP:CTL: System State Initialized... [1660219624.328208][2412:2412] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219624.328245][2412:2412] CHIP:CTL: Setting attestation nonce to random value [1660219624.328280][2412:2412] CHIP:CTL: Setting CSR nonce to random value [1660219624.328370][2412:2412] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219624.328397][2412:2412] CHIP:CTL: Setting attestation nonce to random value [1660219624.328427][2412:2412] CHIP:CTL: Setting CSR nonce to random value [1660219624.329346][2412:2412] CHIP:CTL: Generating NOC [1660219624.330644][2412:2412] CHIP:FP: Validating NOC chain [1660219624.332324][2412:2412] CHIP:FP: NOC chain validation successful [1660219624.332489][2412:2412] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1660219624.332521][2412:2412] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219624.332543][2412:2412] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219624.332563][2412:2412] CHIP:TS: Retaining current Last Known Good Time [1660219624.335975][2412:2412] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1660219624.339336][2412:2412] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219624.342571][2412:2412] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1660219624.342712][2412:2412] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219624.342753][2412:2412] CHIP:CTL: Setting attestation nonce to random value [1660219624.342812][2412:2412] CHIP:CTL: Setting CSR nonce to random value [1660219624.343693][2412:2412] CHIP:CTL: Generating NOC [1660219624.345113][2412:2412] CHIP:FP: Validating NOC chain [1660219624.347116][2412:2412] CHIP:FP: NOC chain validation successful [1660219624.347304][2412:2412] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1660219624.347339][2412:2412] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219624.347364][2412:2412] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219624.347386][2412:2412] CHIP:TS: Retaining current Last Known Good Time [1660219624.350942][2412:2412] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1660219624.354371][2412:2412] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219624.360561][2412:2412] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1660219624.360697][2412:2412] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1660219624.360735][2412:2412] CHIP:CTL: Setting attestation nonce to random value [1660219624.360788][2412:2412] CHIP:CTL: Setting CSR nonce to random value [1660219624.361713][2412:2412] CHIP:CTL: Generating NOC [1660219624.362931][2412:2412] CHIP:FP: Validating NOC chain [1660219624.364585][2412:2412] CHIP:FP: NOC chain validation successful [1660219624.364740][2412:2412] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1660219624.364771][2412:2412] CHIP:TS: Last Known Good Time: 2022-08-03T19:41:28 [1660219624.364793][2412:2412] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1660219624.364813][2412:2412] CHIP:TS: Retaining current Last Known Good Time [1660219624.368437][2412:2412] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1660219624.371901][2412:2412] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-03T19:41:28 [1660219624.375134][2412:2412] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1660219624.424672][2412:2417] CHIP:DL: CHIP task running [1660219624.424919][2412:2417] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 >>> basic write node-label 1 4 0 [1660219925.154097][2412:2417] CHIP:TOO: Sending command to node 0x4 [1660219925.154148][2412:2417] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000004] [1660219925.154173][2412:2417] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1660219925.154212][2412:2417] CHIP:CTL: OperationalDeviceProxy[1:0000000000000004]: State change 1 --> 2 [1660219925.154241][2412:2417] CHIP:DIS: Resolving 863F8D90D715E7ED:0000000000000004 ... [1660219925.354753][2412:2417] CHIP:DIS: Checking node lookup status after 200 ms [1660219930.158924][2412:2417] CHIP:DL: Re-trying resolve [1660219935.154202][2412:2412] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:416: CHIP Error 0x00000032: Timeout [1660219935.163959][2412:2417] CHIP:DL: Re-trying resolve [1660219940.160296][2412:2417] CHIP:DIS: Checking node lookup status after 15006 ms [1660219940.160433][2412:2417] CHIP:DIS: OperationalDeviceProxy[1:0000000000000004]: operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout [1660219940.160503][2412:2417] CHIP:CTL: OperationalDeviceProxy[1:0000000000000004]: State change 2 --> 1 [1660219940.168708][2412:2417] CHIP:DL: Re-trying resolve basic write node-label 1 4 0 --commissioner-name 4 [1660219942.484520][2412:2417] CHIP:TOO: Sending command to node 0x4 Segmentation fault (core dumped)