`chip-tool` built with commit SHA: `fa5561c23d8c1f9464da8669931affbae0660f51` Pairing: Over Ble-Wifi to chip-tool Lines of Interest: ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool pairing ble-wifi 1234 SSID SSIDpwd 20202021 3840 ... [1650657604.415678][3870:3875] CHIP:TOO: Device commissioning completed with success 1st Attempt to Read Attribute: Success ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 1234 1 ... [1650657650.054116][3880:3885] CHIP:TOO: ClusterRevision: 3 2nd Attempt to Read Attribute: Fail (Invalid CASE parameter) ... [1650657980.921764][3898:3898] CHIP:TOO: Run command failure: ../../../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/CASESession.cpp:1479: CHIP Error 0x00000054: Invalid CASE parameter 3rd Attempt to Read Attribute: Fail (Timeout) [1650658795.688720][3936:3936] CHIP:TOO: Run command failure: ../../../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout Full Logs: ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool pairing ble-wifi 1234 SSID SSIDpwd 20202021 3840 [1650657596.170715][3870:3870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650657596.170982][3870:3870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650657596.171438][3870:3870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650657596.171619][3870:3870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650657596.171759][3870:3870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650657596.172077][3870:3870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JTicCf) [1650657596.172690][3870:3870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657596.172741][3870:3870] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1650657596.173692][3870:3870] CHIP:DL: Got Ethernet interface: eth0 [1650657596.174342][3870:3870] CHIP:DL: Found the primary Ethernet interface:eth0 [1650657596.174996][3870:3870] CHIP:DL: Got WiFi interface: wlan0 [1650657596.175072][3870:3870] CHIP:DL: Failed to reset WiFi statistic counts [1650657596.175177][3870:3870] CHIP:IN: UDP::Init bind&listen port=0 [1650657596.175334][3870:3870] CHIP:IN: UDP::Init bound to port=48511 [1650657596.175362][3870:3870] CHIP:IN: UDP::Init bind&listen port=0 [1650657596.175469][3870:3870] CHIP:IN: UDP::Init bound to port=40128 [1650657596.175493][3870:3870] CHIP:IN: BLEBase::Init - setting/overriding transport [1650657596.175515][3870:3870] CHIP:IN: TransportMgr initialized [1650657596.175563][3870:3870] CHIP:DIS: Init fabric pairing table with server storage [1650657596.175690][3870:3870] CHIP:IN: Loading from storage for fabric index 1 [1650657596.178194][3870:3870] CHIP:IN: Loading from storage for fabric index 2 [1650657596.178916][3870:3870] CHIP:IN: Loading from storage for fabric index 3 [1650657596.179466][3870:3870] CHIP:DIS: Add fabric pairing table delegate [1650657596.179738][3870:3870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-exU8sG) [1650657596.180416][3870:3870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657596.180472][3870:3870] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 2000 (0x7D0) [1650657596.183324][3870:3870] CHIP:ZCL: Using ZAP configuration... [1650657596.186740][3870:3870] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.194334][3870:3870] CHIP:DL: MDNS failed to join multicast group on vethf98e81b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.196073][3870:3870] CHIP:DL: MDNS failed to join multicast group on veth49716b3 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.197871][3870:3870] CHIP:DL: MDNS failed to join multicast group on veth817a68d for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.199580][3870:3870] CHIP:DL: MDNS failed to join multicast group on veth4ef2089 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.201401][3870:3870] CHIP:DL: MDNS failed to join multicast group on vethb5a3c32 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657596.201736][3870:3870] CHIP:CTL: System State Initialized... [1650657596.201828][3870:3870] CHIP:CTL: Setting attestation nonce to random value [1650657596.201917][3870:3870] CHIP:CTL: Setting CSR nonce to random value [1650657596.201996][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.202110][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.202136][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.202246][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.202270][3870:3870] CHIP:IN: TransportMgr initialized [1650657596.202325][3870:3870] CHIP:CTL: Setting attestation nonce to random value [1650657596.202385][3870:3870] CHIP:CTL: Setting CSR nonce to random value [1650657596.203312][3870:3870] CHIP:CTL: Generating NOC [1650657596.204234][3870:3870] CHIP:DIS: Verifying the received credentials [1650657596.206098][3870:3870] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650657596.206140][3870:3870] CHIP:DIS: Assigned compressed fabric ID: 0x0BA7B4D5E28EA581, node ID: 0x000000000001B669 [1650657596.206165][3870:3870] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0BA7B4D5E28EA581 [1650657596.206207][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.206347][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.206383][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.206472][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.206505][3870:3870] CHIP:IN: TransportMgr initialized [1650657596.206619][3870:3870] CHIP:CTL: Setting attestation nonce to random value [1650657596.206679][3870:3870] CHIP:CTL: Setting CSR nonce to random value [1650657596.207524][3870:3870] CHIP:CTL: Generating NOC [1650657596.208407][3870:3870] CHIP:DIS: Verifying the received credentials [1650657596.210139][3870:3870] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650657596.210208][3870:3870] CHIP:DIS: Assigned compressed fabric ID: 0xC1CCD686519F7E0B, node ID: 0x000000000001B669 [1650657596.210234][3870:3870] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xC1CCD686519F7E0B [1650657596.210275][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.210434][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.210462][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.210561][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.210585][3870:3870] CHIP:IN: TransportMgr initialized [1650657596.210694][3870:3870] CHIP:CTL: Setting attestation nonce to random value [1650657596.210753][3870:3870] CHIP:CTL: Setting CSR nonce to random value [1650657596.211593][3870:3870] CHIP:CTL: Generating NOC [1650657596.212494][3870:3870] CHIP:DIS: Verifying the received credentials [1650657596.214209][3870:3870] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650657596.214241][3870:3870] CHIP:DIS: Assigned compressed fabric ID: 0xBA470D9A0C420C73, node ID: 0x000000000001B669 [1650657596.214265][3870:3870] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xBA470D9A0C420C73 [1650657596.214305][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.214448][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.214484][3870:3870] CHIP:IN: UDP::Init bind&listen port=5550 [1650657596.214586][3870:3870] CHIP:IN: UDP::Init bound to port=5550 [1650657596.214610][3870:3870] CHIP:IN: TransportMgr initialized [1650657596.255087][3870:3875] CHIP:DL: CHIP task running [1650657596.255643][3870:3875] CHIP:SC: Assigned local session key ID 60057 [1650657596.255732][3870:3875] CHIP:SC: Including MRP parameters in PBKDF param request [1650657596.255804][3870:3875] CHIP:IN: Prepared unauthenticated message 0xffffa48ebcd8 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 10902i with MessageCounter:3540746946. [1650657596.255859][3870:3875] CHIP:IN: Sending unauthenticated msg 0xffffa48ebcd8 with MessageCounter:3540746946 to 0x0000000000000000 at monotonic time: 0000000000C1E18E msec [1650657596.255900][3870:3875] CHIP:IN: Message appended to BLE send queue [1650657596.255945][3870:3875] CHIP:SC: Sent PBKDF param request [1650657596.255981][3870:3875] CHIP:CTL: Setting wifi credentials from parameters [1650657596.256009][3870:3875] CHIP:CTL: Setting attestation nonce to random value [1650657596.256065][3870:3875] CHIP:CTL: Setting CSR nonce to random value [1650657596.256123][3870:3875] CHIP:CTL: Commission called for node ID 0x00000000000004D2 [1650657596.256518][3870:3876] CHIP:DL: TRACE: Bluez mainloop starting Thread [1650657596.256680][3870:3873] CHIP:DL: TRACE: Bus acquired for name C-0f1e [1650657596.266301][3870:3875] CHIP:DL: PlatformBlueZInit init success [1650657596.274120][3870:3873] CHIP:BLE: BLE removing known devices. [1650657596.295002][3870:3873] CHIP:BLE: BLE initiating scan. [1650657596.326516][3870:3873] CHIP:BLE: Device 48:54:8A:2E:0E:B0 does not look like a CHIP device. [1650657596.329006][3870:3873] CHIP:BLE: Device F2:AD:96:EE:50:8A does not look like a CHIP device. [1650657596.336241][3870:3873] CHIP:BLE: Device BE:FF:E5:01:27:E7 does not look like a CHIP device. [1650657596.337799][3870:3873] CHIP:BLE: Device 30:49:7E:C7:49:AD does not look like a CHIP device. [1650657596.356892][3870:3873] CHIP:BLE: Device 6B:9B:9B:C5:27:43 does not look like a CHIP device. [1650657596.392727][3870:3873] CHIP:BLE: Device 1C:1A:C0:8B:EC:F0 does not look like a CHIP device. [1650657596.407198][3870:3873] CHIP:BLE: Device F8:04:2E:BA:2D:A3 does not look like a CHIP device. [1650657596.420343][3870:3873] CHIP:BLE: Device 44:5C:E9:BA:EE:27 does not look like a CHIP device. [1650657596.450120][3870:3873] CHIP:BLE: Device 40:5B:21:23:3A:9B does not look like a CHIP device. [1650657596.504084][3870:3873] CHIP:BLE: Device C4:50:FE:77:4E:8B does not look like a CHIP device. [1650657596.507545][3870:3873] CHIP:BLE: Device 47:2E:DB:6C:5E:42 does not look like a CHIP device. [1650657596.553285][3870:3873] CHIP:BLE: Device 1C:9D:C2:25:8B:1A does not look like a CHIP device. [1650657596.555360][3870:3873] CHIP:BLE: Device 3A:2C:17:5F:E7:52 does not look like a CHIP device. [1650657596.557527][3870:3873] CHIP:BLE: Device 37:BE:32:DB:50:87 does not look like a CHIP device. [1650657596.587501][3870:3873] CHIP:BLE: Device C8:84:47:55:2D:32 does not look like a CHIP device. [1650657596.594535][3870:3873] CHIP:BLE: Device BE:FF:E5:01:27:E7 does not look like a CHIP device. [1650657596.611767][3870:3873] CHIP:BLE: Device 3F:6E:FC:28:AB:6B does not look like a CHIP device. [1650657596.641728][3870:3873] CHIP:BLE: Device 1C:13:93:F7:13:98 does not look like a CHIP device. [1650657596.646014][3870:3873] CHIP:BLE: Device 37:FF:52:7E:11:71 does not look like a CHIP device. [1650657596.718471][3870:3873] CHIP:BLE: Device C8:69:CD:60:77:4E does not look like a CHIP device. [1650657596.757883][3870:3873] CHIP:BLE: Device 6F:A9:7F:66:E7:E7 does not look like a CHIP device. [1650657596.788624][3870:3873] CHIP:BLE: Device 6C:4A:85:3C:36:3C does not look like a CHIP device. [1650657596.791164][3870:3873] CHIP:BLE: Device 79:FF:45:2E:48:93 does not look like a CHIP device. [1650657596.805741][3870:3873] CHIP:BLE: Device 5C:D9:38:92:5C:AC does not look like a CHIP device. [1650657596.807914][3870:3873] CHIP:BLE: Device 00:41:BA:21:CD:32 does not look like a CHIP device. [1650657596.821282][3870:3873] CHIP:BLE: Device 06:27:EE:7F:D0:B5 does not look like a CHIP device. [1650657596.829670][3870:3873] CHIP:BLE: Device C2:1E:0F:1D:85:1D does not look like a CHIP device. [1650657596.857216][3870:3873] CHIP:BLE: Device 48:54:8A:2E:0E:B0 does not look like a CHIP device. [1650657596.903805][3870:3873] CHIP:BLE: Device EC:65:EA:B6:CA:9F does not look like a CHIP device. [1650657596.988477][3870:3873] CHIP:BLE: Device F9:37:51:C2:3B:97 does not look like a CHIP device. [1650657596.991343][3870:3873] CHIP:BLE: New device scanned: DC:A6:32:8D:2B:A1 [1650657596.991421][3870:3873] CHIP:BLE: Device discriminator match. Attempting to connect. [1650657596.996351][3870:3873] CHIP:BLE: Scan complete notification without an active scan. [1650657599.683141][3870:3873] CHIP:DL: ConnectDevice complete [1650657601.112646][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112702][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112737][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.112760][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112786][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.112808][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112832][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.112853][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112882][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.112904][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.112928][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.113010][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113036][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.113068][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113104][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.113135][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113160][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.113190][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113215][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service0006 [1650657601.113237][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113280][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113302][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113337][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113358][3870:3873] CHIP:DL: Char1 /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1/service001f [1650657601.113399][3870:3873] CHIP:DL: New BLE connection 0xffff9c06b170, device DC:A6:32:8D:2B:A1, path /org/bluez/hci0/dev_DC_A6_32_8D_2B_A1 [1650657601.113586][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1650657601.113625][3870:3875] CHIP:IN: BleConnectionComplete: endPoint 0xaaaacc968b38 [1650657601.291146][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657601.389159][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1650657601.389252][3870:3875] CHIP:BLE: subscribe complete, ep = 0xaaaacc968b38 [1650657601.389395][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.389656][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.389725][3870:3875] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1650657601.389782][3870:3875] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1650657601.389833][3870:3875] CHIP:BLE: local and remote recv window size = 6 [1650657601.390033][3870:3875] CHIP:IN: BLE EndPoint 0xaaaacc968b38 Connection Complete [1650657601.535215][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657601.537978][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.538349][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.538566][3870:3875] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:1850391410 on exchange 10902i [1650657601.538642][3870:3875] CHIP:EM: Found matching exchange: 10902i, Delegate: 0xffff900017b8 [1650657601.538729][3870:3875] CHIP:SC: Received PBKDF param response [1650657601.538821][3870:3875] CHIP:SC: Peer assigned session ID 6029 [1650657601.538894][3870:3875] CHIP:SC: Found MRP parameters in the message [1650657601.549764][3870:3875] CHIP:IN: Prepared unauthenticated message 0xffffa48eb868 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 10902i with MessageCounter:3540746947. [1650657601.549825][3870:3875] CHIP:IN: Sending unauthenticated msg 0xffffa48eb868 with MessageCounter:3540746947 to 0x0000000000000000 at monotonic time: 0000000000C1F63C msec [1650657601.549943][3870:3875] CHIP:SC: Sent spake2p msg1 [1650657601.632564][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657601.635329][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.635692][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.635910][3870:3875] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:1850391411 on exchange 10902i [1650657601.635982][3870:3875] CHIP:EM: Found matching exchange: 10902i, Delegate: 0xffff900017b8 [1650657601.636067][3870:3875] CHIP:SC: Received spake2p msg2 [1650657601.639158][3870:3875] CHIP:IN: Prepared unauthenticated message 0xffffa48eb9a8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 10902i with MessageCounter:3540746948. [1650657601.639262][3870:3875] CHIP:IN: Sending unauthenticated msg 0xffffa48eb9a8 with MessageCounter:3540746948 to 0x0000000000000000 at monotonic time: 0000000000C1F696 msec [1650657601.639452][3870:3875] CHIP:SC: Sent spake2p msg3 [1650657601.730250][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657601.731552][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.732003][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.732216][3870:3875] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1850391412 on exchange 10902i [1650657601.732290][3870:3875] CHIP:EM: Found matching exchange: 10902i, Delegate: 0xffff900017b8 [1650657601.732393][3870:3875] CHIP:IN: New secure session created for device 0x00000000000004D2, LSID:60057 PSID:6029! [1650657601.732535][3870:3875] CHIP:CTL: Remote device completed SPAKE2+ handshake [1650657601.732596][3870:3875] CHIP:TOO: Pairing Success [1650657601.732703][3870:3875] CHIP:CTL: Going from commissioning step 'SecurePairing' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:265: Success' --> 'ReadCommissioningInfo' [1650657601.732770][3870:3875] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CommissioningDelegate.h:73: Success' [1650657601.732826][3870:3875] CHIP:CTL: Sending request for commissioning information [1650657601.732901][3870:3875] CHIP:DMG: SendReadRequest ReadClient[0xffff9000f9e0]: Sending Read Request [1650657601.733173][3870:3875] CHIP:IN: Prepared secure message 0xffffa48eb2e8 to 0x00000000000004D2 (1) of type 0x2 and protocolId (0, 1) on exchange 10903i with MessageCounter:13101021. [1650657601.733268][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48eb2e8 with MessageCounter:13101021 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1F6F4 msec [1650657601.733466][3870:3875] CHIP:DMG: MoveToState ReadClient[0xffff9000f9e0]: Moving to [AwaitingIn] [1650657601.827633][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657601.875504][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.875843][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.973973][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657601.974379][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657601.974618][3870:3875] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:16515797 on exchange 10903i [1650657601.974697][3870:3875] CHIP:EM: Found matching exchange: 10903i, Delegate: 0xffff9000f9e0 [1650657601.974911][3870:3875] CHIP:DMG: ReportDataMessage = [1650657601.974976][3870:3875] CHIP:DMG: { [1650657601.975030][3870:3875] CHIP:DMG: AttributeReportIBs = [1650657601.975107][3870:3875] CHIP:DMG: [ [1650657601.975169][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.975256][3870:3875] CHIP:DMG: { [1650657601.975328][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.975414][3870:3875] CHIP:DMG: { [1650657601.975504][3870:3875] CHIP:DMG: DataVersion = 0x6c95969d, [1650657601.975584][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.975675][3870:3875] CHIP:DMG: { [1650657601.975767][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.975858][3870:3875] CHIP:DMG: Cluster = 0x31, [1650657601.975947][3870:3875] CHIP:DMG: Attribute = 0x0000_0003, [1650657601.976031][3870:3875] CHIP:DMG: } [1650657601.976111][3870:3875] CHIP:DMG: [1650657601.976205][3870:3875] CHIP:DMG: Data = 0, [1650657601.976287][3870:3875] CHIP:DMG: }, [1650657601.976374][3870:3875] CHIP:DMG: [1650657601.976444][3870:3875] CHIP:DMG: }, [1650657601.976540][3870:3875] CHIP:DMG: [1650657601.976602][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.976685][3870:3875] CHIP:DMG: { [1650657601.976755][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.976839][3870:3875] CHIP:DMG: { [1650657601.976926][3870:3875] CHIP:DMG: DataVersion = 0xe85cf13c, [1650657601.977039][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.977130][3870:3875] CHIP:DMG: { [1650657601.977214][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.977305][3870:3875] CHIP:DMG: Cluster = 0x28, [1650657601.977385][3870:3875] CHIP:DMG: Attribute = 0x0000_0004, [1650657601.977475][3870:3875] CHIP:DMG: } [1650657601.977568][3870:3875] CHIP:DMG: [1650657601.977653][3870:3875] CHIP:DMG: Data = 32769, [1650657601.977741][3870:3875] CHIP:DMG: }, [1650657601.977827][3870:3875] CHIP:DMG: [1650657601.977896][3870:3875] CHIP:DMG: }, [1650657601.977992][3870:3875] CHIP:DMG: [1650657601.978055][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.978137][3870:3875] CHIP:DMG: { [1650657601.978207][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.978282][3870:3875] CHIP:DMG: { [1650657601.978363][3870:3875] CHIP:DMG: DataVersion = 0xe85cf13c, [1650657601.978440][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.978528][3870:3875] CHIP:DMG: { [1650657601.978611][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.978699][3870:3875] CHIP:DMG: Cluster = 0x28, [1650657601.978779][3870:3875] CHIP:DMG: Attribute = 0x0000_0002, [1650657601.978869][3870:3875] CHIP:DMG: } [1650657601.978955][3870:3875] CHIP:DMG: [1650657601.979042][3870:3875] CHIP:DMG: Data = 65521, [1650657601.979132][3870:3875] CHIP:DMG: }, [1650657601.979223][3870:3875] CHIP:DMG: [1650657601.979293][3870:3875] CHIP:DMG: }, [1650657601.979385][3870:3875] CHIP:DMG: [1650657601.979447][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.979530][3870:3875] CHIP:DMG: { [1650657601.979601][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.979676][3870:3875] CHIP:DMG: { [1650657601.979757][3870:3875] CHIP:DMG: DataVersion = 0x54675d6b, [1650657601.979836][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.979917][3870:3875] CHIP:DMG: { [1650657601.980001][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.980086][3870:3875] CHIP:DMG: Cluster = 0x30, [1650657601.980174][3870:3875] CHIP:DMG: Attribute = 0x0000_0003, [1650657601.980248][3870:3875] CHIP:DMG: } [1650657601.980334][3870:3875] CHIP:DMG: [1650657601.980427][3870:3875] CHIP:DMG: Data = 0, [1650657601.980508][3870:3875] CHIP:DMG: }, [1650657601.980600][3870:3875] CHIP:DMG: [1650657601.980669][3870:3875] CHIP:DMG: }, [1650657601.980763][3870:3875] CHIP:DMG: [1650657601.980825][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.980907][3870:3875] CHIP:DMG: { [1650657601.981019][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.981108][3870:3875] CHIP:DMG: { [1650657601.981196][3870:3875] CHIP:DMG: DataVersion = 0x54675d6b, [1650657601.981277][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.981366][3870:3875] CHIP:DMG: { [1650657601.981451][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.981531][3870:3875] CHIP:DMG: Cluster = 0x30, [1650657601.981783][3870:3875] CHIP:DMG: Attribute = 0x0000_0002, [1650657601.981869][3870:3875] CHIP:DMG: } [1650657601.981964][3870:3875] CHIP:DMG: [1650657601.982050][3870:3875] CHIP:DMG: Data = 0, [1650657601.982133][3870:3875] CHIP:DMG: }, [1650657601.982213][3870:3875] CHIP:DMG: [1650657601.982282][3870:3875] CHIP:DMG: }, [1650657601.982377][3870:3875] CHIP:DMG: [1650657601.982440][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.982521][3870:3875] CHIP:DMG: { [1650657601.982590][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.982674][3870:3875] CHIP:DMG: { [1650657601.982756][3870:3875] CHIP:DMG: DataVersion = 0x54675d6b, [1650657601.982828][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.982917][3870:3875] CHIP:DMG: { [1650657601.983007][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.983093][3870:3875] CHIP:DMG: Cluster = 0x30, [1650657601.983153][3870:3875] CHIP:DMG: Attribute = 0x0000_0001, [1650657601.983191][3870:3875] CHIP:DMG: } [1650657601.983233][3870:3875] CHIP:DMG: [1650657601.983332][3870:3875] CHIP:DMG: Data = [1650657601.983377][3870:3875] CHIP:DMG: { [1650657601.983415][3870:3875] CHIP:DMG: 0x0 = 60, [1650657601.983458][3870:3875] CHIP:DMG: }, [1650657601.983496][3870:3875] CHIP:DMG: }, [1650657601.983535][3870:3875] CHIP:DMG: [1650657601.983567][3870:3875] CHIP:DMG: }, [1650657601.983611][3870:3875] CHIP:DMG: [1650657601.983640][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.983678][3870:3875] CHIP:DMG: { [1650657601.983710][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.983745][3870:3875] CHIP:DMG: { [1650657601.983782][3870:3875] CHIP:DMG: DataVersion = 0x54675d6b, [1650657601.983818][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.983856][3870:3875] CHIP:DMG: { [1650657601.983897][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.983938][3870:3875] CHIP:DMG: Cluster = 0x30, [1650657601.983977][3870:3875] CHIP:DMG: Attribute = 0x0000_0000, [1650657601.984014][3870:3875] CHIP:DMG: } [1650657601.984052][3870:3875] CHIP:DMG: [1650657601.984095][3870:3875] CHIP:DMG: Data = 0, [1650657601.984132][3870:3875] CHIP:DMG: }, [1650657601.984171][3870:3875] CHIP:DMG: [1650657601.984202][3870:3875] CHIP:DMG: }, [1650657601.984246][3870:3875] CHIP:DMG: [1650657601.984274][3870:3875] CHIP:DMG: AttributeReportIB = [1650657601.984312][3870:3875] CHIP:DMG: { [1650657601.984344][3870:3875] CHIP:DMG: AttributeDataIB = [1650657601.984380][3870:3875] CHIP:DMG: { [1650657601.984417][3870:3875] CHIP:DMG: DataVersion = 0x6c95969d, [1650657601.984454][3870:3875] CHIP:DMG: AttributePathIB = [1650657601.984488][3870:3875] CHIP:DMG: { [1650657601.984529][3870:3875] CHIP:DMG: Endpoint = 0x0, [1650657601.984572][3870:3875] CHIP:DMG: Cluster = 0x31, [1650657601.984615][3870:3875] CHIP:DMG: Attribute = 0x0000_FFFC, [1650657601.984653][3870:3875] CHIP:DMG: } [1650657601.984696][3870:3875] CHIP:DMG: [1650657601.984735][3870:3875] CHIP:DMG: Data = 2, [1650657601.984776][3870:3875] CHIP:DMG: }, [1650657601.984814][3870:3875] CHIP:DMG: [1650657601.984846][3870:3875] CHIP:DMG: }, [1650657601.984882][3870:3875] CHIP:DMG: [1650657601.984910][3870:3875] CHIP:DMG: ], [1650657601.984989][3870:3875] CHIP:DMG: [1650657601.985021][3870:3875] CHIP:DMG: SuppressResponse = true, [1650657601.985051][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657601.985078][3870:3875] CHIP:DMG: } [1650657601.985974][3870:3875] CHIP:CTL: Finished commissioning step 'ReadCommissioningInfo' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' [1650657601.986023][3870:3875] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' --> 'ArmFailSafe' [1650657601.986056][3870:3875] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' [1650657601.986082][3870:3875] CHIP:CTL: Arming failsafe (60 seconds) [1650657601.986156][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657601.986191][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657601.986299][3870:3875] CHIP:IN: Prepared secure message 0xffffa48eafe8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10904i with MessageCounter:13101022. [1650657601.986346][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48eafe8 with MessageCounter:13101022 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1F7F1 msec [1650657601.986468][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657602.071340][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657602.073443][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.073820][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.074085][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515798 on exchange 10904i [1650657602.074161][3870:3875] CHIP:EM: Found matching exchange: 10904i, Delegate: 0xffff90004600 [1650657602.074245][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657602.074345][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657602.074408][3870:3875] CHIP:DMG: { [1650657602.074468][3870:3875] CHIP:DMG: suppressResponse = false, [1650657602.074529][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657602.074608][3870:3875] CHIP:DMG: [ [1650657602.074670][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657602.074755][3870:3875] CHIP:DMG: { [1650657602.074825][3870:3875] CHIP:DMG: CommandDataIB = [1650657602.074904][3870:3875] CHIP:DMG: { [1650657602.074987][3870:3875] CHIP:DMG: CommandPathIB = [1650657602.075070][3870:3875] CHIP:DMG: { [1650657602.075155][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657602.075250][3870:3875] CHIP:DMG: ClusterId = 0x30, [1650657602.075341][3870:3875] CHIP:DMG: CommandId = 0x1, [1650657602.075426][3870:3875] CHIP:DMG: }, [1650657602.075507][3870:3875] CHIP:DMG: [1650657602.075583][3870:3875] CHIP:DMG: CommandData = [1650657602.075657][3870:3875] CHIP:DMG: { [1650657602.075743][3870:3875] CHIP:DMG: 0x0 = 0, [1650657602.075828][3870:3875] CHIP:DMG: 0x1 = "", [1650657602.075914][3870:3875] CHIP:DMG: }, [1650657602.075999][3870:3875] CHIP:DMG: }, [1650657602.076092][3870:3875] CHIP:DMG: [1650657602.076161][3870:3875] CHIP:DMG: }, [1650657602.076242][3870:3875] CHIP:DMG: [1650657602.076302][3870:3875] CHIP:DMG: ], [1650657602.076379][3870:3875] CHIP:DMG: [1650657602.076440][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657602.076499][3870:3875] CHIP:DMG: }, [1650657602.076645][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1650657602.076792][3870:3875] CHIP:CTL: Received ArmFailSafe response [1650657602.076862][3870:3875] CHIP:CTL: Finished commissioning step 'ArmFailSafe' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' [1650657602.076924][3870:3875] CHIP:CTL: Going from commissioning step 'ArmFailSafe' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' --> 'ConfigRegulatory' [1650657602.077026][3870:3875] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' [1650657602.077083][3870:3875] CHIP:CTL: Setting Regulatory Config [1650657602.077135][3870:3875] CHIP:CTL: Device does not support configurable regulatory location [1650657602.077233][3870:3875] CHIP:CTL: Unable to find country code, defaulting to XX [1650657602.077352][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657602.077426][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657602.077585][3870:3875] CHIP:IN: Prepared secure message 0xffffa48eaaf8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10905i with MessageCounter:13101023. [1650657602.077721][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48eaaf8 with MessageCounter:13101023 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1F84C msec [1650657602.077921][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657602.078045][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657602.169077][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657602.170837][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.171207][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.171472][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515799 on exchange 10905i [1650657602.171549][3870:3875] CHIP:EM: Found matching exchange: 10905i, Delegate: 0xffff9000fae0 [1650657602.171636][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657602.171739][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657602.171802][3870:3875] CHIP:DMG: { [1650657602.171862][3870:3875] CHIP:DMG: suppressResponse = false, [1650657602.171924][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657602.172088][3870:3875] CHIP:DMG: [ [1650657602.172152][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657602.172246][3870:3875] CHIP:DMG: { [1650657602.172318][3870:3875] CHIP:DMG: CommandDataIB = [1650657602.172397][3870:3875] CHIP:DMG: { [1650657602.172480][3870:3875] CHIP:DMG: CommandPathIB = [1650657602.172570][3870:3875] CHIP:DMG: { [1650657602.172661][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657602.172754][3870:3875] CHIP:DMG: ClusterId = 0x30, [1650657602.172847][3870:3875] CHIP:DMG: CommandId = 0x3, [1650657602.172935][3870:3875] CHIP:DMG: }, [1650657602.173099][3870:3875] CHIP:DMG: [1650657602.173181][3870:3875] CHIP:DMG: CommandData = [1650657602.173263][3870:3875] CHIP:DMG: { [1650657602.173349][3870:3875] CHIP:DMG: 0x0 = 0, [1650657602.173446][3870:3875] CHIP:DMG: 0x1 = "", [1650657602.173538][3870:3875] CHIP:DMG: }, [1650657602.173621][3870:3875] CHIP:DMG: }, [1650657602.173784][3870:3875] CHIP:DMG: [1650657602.173907][3870:3875] CHIP:DMG: }, [1650657602.173992][3870:3875] CHIP:DMG: [1650657602.174052][3870:3875] CHIP:DMG: ], [1650657602.174129][3870:3875] CHIP:DMG: [1650657602.174190][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657602.174249][3870:3875] CHIP:DMG: }, [1650657602.174398][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1650657602.174537][3870:3875] CHIP:CTL: Received SetRegulatoryConfig response [1650657602.174608][3870:3875] CHIP:CTL: Finished commissioning step 'ConfigRegulatory' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' [1650657602.174670][3870:3875] CHIP:CTL: Going from commissioning step 'ConfigRegulatory' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' --> 'SendPAICertificateRequest' [1650657602.174734][3870:3875] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' [1650657602.174790][3870:3875] CHIP:CTL: Sending request for PAI certificate [1650657602.174838][3870:3875] CHIP:CTL: Sending Certificate Chain request to 0xffff90001760 device [1650657602.174948][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657602.175043][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657602.175290][3870:3875] CHIP:IN: Prepared secure message 0xffffa48eaa48 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10906i with MessageCounter:13101024. [1650657602.175385][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48eaa48 with MessageCounter:13101024 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1F8AE msec [1650657602.175586][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657602.175704][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657602.266445][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657602.314345][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.314681][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.415372][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.415749][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.608279][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.608683][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.609003][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515800 on exchange 10906i [1650657602.609079][3870:3875] CHIP:EM: Found matching exchange: 10906i, Delegate: 0xffff90004600 [1650657602.609175][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657602.609276][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657602.609337][3870:3875] CHIP:DMG: { [1650657602.609396][3870:3875] CHIP:DMG: suppressResponse = false, [1650657602.609457][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657602.609534][3870:3875] CHIP:DMG: [ [1650657602.609595][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657602.609685][3870:3875] CHIP:DMG: { [1650657602.609751][3870:3875] CHIP:DMG: CommandDataIB = [1650657602.609837][3870:3875] CHIP:DMG: { [1650657602.609918][3870:3875] CHIP:DMG: CommandPathIB = [1650657602.610000][3870:3875] CHIP:DMG: { [1650657602.610085][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657602.610179][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657602.610265][3870:3875] CHIP:DMG: CommandId = 0x3, [1650657602.610352][3870:3875] CHIP:DMG: }, [1650657602.610444][3870:3875] CHIP:DMG: [1650657602.610520][3870:3875] CHIP:DMG: CommandData = [1650657602.610608][3870:3875] CHIP:DMG: { [1650657602.610696][3870:3875] CHIP:DMG: 0x0 = [ [1650657602.610787][3870:3875] CHIP:DMG: ... (byte string too long) ... [1650657602.610886][3870:3875] CHIP:DMG: ] [1650657602.610968][3870:3875] CHIP:DMG: }, [1650657602.611044][3870:3875] CHIP:DMG: }, [1650657602.611130][3870:3875] CHIP:DMG: [1650657602.611198][3870:3875] CHIP:DMG: }, [1650657602.611279][3870:3875] CHIP:DMG: [1650657602.611338][3870:3875] CHIP:DMG: ], [1650657602.611413][3870:3875] CHIP:DMG: [1650657602.611474][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657602.611532][3870:3875] CHIP:DMG: }, [1650657602.611675][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1650657602.611758][3870:3875] CHIP:CTL: Received certificate chain from the device [1650657602.611830][3870:3875] CHIP:CTL: Finished commissioning step 'SendPAICertificateRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650657602.611898][3870:3875] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' --> 'SendDACCertificateRequest' [1650657602.611963][3870:3875] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650657602.612017][3870:3875] CHIP:CTL: Sending request for DAC certificate [1650657602.612065][3870:3875] CHIP:CTL: Sending Certificate Chain request to 0xffff90001760 device [1650657602.612177][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657602.612246][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657602.612407][3870:3875] CHIP:IN: Prepared secure message 0xffffa48ea9f8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10907i with MessageCounter:13101025. [1650657602.612497][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48ea9f8 with MessageCounter:13101025 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1FA63 msec [1650657602.612692][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657602.612808][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657602.705141][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657602.752373][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.752575][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.854156][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.854540][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.949624][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657602.949994][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657602.950263][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515801 on exchange 10907i [1650657602.950340][3870:3875] CHIP:EM: Found matching exchange: 10907i, Delegate: 0xffff9000fae0 [1650657602.950434][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657602.950538][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657602.950602][3870:3875] CHIP:DMG: { [1650657602.950661][3870:3875] CHIP:DMG: suppressResponse = false, [1650657602.950723][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657602.950801][3870:3875] CHIP:DMG: [ [1650657602.950862][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657602.950947][3870:3875] CHIP:DMG: { [1650657602.951016][3870:3875] CHIP:DMG: CommandDataIB = [1650657602.951101][3870:3875] CHIP:DMG: { [1650657602.951182][3870:3875] CHIP:DMG: CommandPathIB = [1650657602.951265][3870:3875] CHIP:DMG: { [1650657602.951351][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657602.951445][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657602.951531][3870:3875] CHIP:DMG: CommandId = 0x3, [1650657602.951620][3870:3875] CHIP:DMG: }, [1650657602.951706][3870:3875] CHIP:DMG: [1650657602.951783][3870:3875] CHIP:DMG: CommandData = [1650657602.951865][3870:3875] CHIP:DMG: { [1650657602.951953][3870:3875] CHIP:DMG: 0x0 = [ [1650657602.952035][3870:3875] CHIP:DMG: ... (byte string too long) ... [1650657602.952130][3870:3875] CHIP:DMG: ] [1650657602.952218][3870:3875] CHIP:DMG: }, [1650657602.952294][3870:3875] CHIP:DMG: }, [1650657602.952379][3870:3875] CHIP:DMG: [1650657602.952447][3870:3875] CHIP:DMG: }, [1650657602.952528][3870:3875] CHIP:DMG: [1650657602.952587][3870:3875] CHIP:DMG: ], [1650657602.952662][3870:3875] CHIP:DMG: [1650657602.952724][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657602.952783][3870:3875] CHIP:DMG: }, [1650657602.952926][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1650657602.953061][3870:3875] CHIP:CTL: Received certificate chain from the device [1650657602.953133][3870:3875] CHIP:CTL: Finished commissioning step 'SendDACCertificateRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650657602.953204][3870:3875] CHIP:CTL: Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' --> 'SendAttestationRequest' [1650657602.953270][3870:3875] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650657602.953325][3870:3875] CHIP:CTL: Sending Attestation Request to the device. [1650657602.953375][3870:3875] CHIP:CTL: Sending Attestation request to 0xffff90001760 device [1650657602.953485][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657602.953559][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657602.953724][3870:3875] CHIP:IN: Prepared secure message 0xffffa48ea9b8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10908i with MessageCounter:13101026. [1650657602.953816][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48ea9b8 with MessageCounter:13101026 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1FBB8 msec [1650657602.954010][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657602.954081][3870:3875] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1650657602.954182][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657603.046543][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657603.094221][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.094515][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.195295][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.195659][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.292238][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.292533][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.292745][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515802 on exchange 10908i [1650657603.292797][3870:3875] CHIP:EM: Found matching exchange: 10908i, Delegate: 0xffff90004600 [1650657603.292864][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657603.292939][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657603.293077][3870:3875] CHIP:DMG: { [1650657603.293118][3870:3875] CHIP:DMG: suppressResponse = false, [1650657603.293159][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657603.293213][3870:3875] CHIP:DMG: [ [1650657603.293254][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657603.293316][3870:3875] CHIP:DMG: { [1650657603.293364][3870:3875] CHIP:DMG: CommandDataIB = [1650657603.293417][3870:3875] CHIP:DMG: { [1650657603.293471][3870:3875] CHIP:DMG: CommandPathIB = [1650657603.293527][3870:3875] CHIP:DMG: { [1650657603.293583][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657603.293645][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657603.293706][3870:3875] CHIP:DMG: CommandId = 0x1, [1650657603.293765][3870:3875] CHIP:DMG: }, [1650657603.293827][3870:3875] CHIP:DMG: [1650657603.293878][3870:3875] CHIP:DMG: CommandData = [1650657603.293937][3870:3875] CHIP:DMG: { [1650657603.293996][3870:3875] CHIP:DMG: 0x0 = [ [1650657603.294054][3870:3875] CHIP:DMG: ... (byte string too long) ... [1650657603.294120][3870:3875] CHIP:DMG: ] [1650657603.294178][3870:3875] CHIP:DMG: 0x1 = [ [1650657603.294262][3870:3875] CHIP:DMG: 0x43, 0x61, 0xe7, 0x7c, 0x38, 0x18, 0x83, 0x61, 0xfb, 0x34, 0xb8, 0x3c, 0x44, 0xec, 0x7b, 0xe0, 0x1f, 0xb8, 0xf2, 0xd9, 0x95, 0x6b, 0xee, 0x6, 0x85, 0x21, 0x1, 0x2d, 0xa2, 0x8e, 0x37, 0x8d, 0xda, 0xb3, 0xd2, 0x49, 0xed, 0x7f, 0x86, 0x49, 0xe, 0x78, [1650657603.294325][3870:3875] CHIP:DMG: ] [1650657603.294379][3870:3875] CHIP:DMG: }, [1650657603.294435][3870:3875] CHIP:DMG: }, [1650657603.294494][3870:3875] CHIP:DMG: [1650657603.294539][3870:3875] CHIP:DMG: }, [1650657603.294594][3870:3875] CHIP:DMG: [1650657603.294635][3870:3875] CHIP:DMG: ], [1650657603.294687][3870:3875] CHIP:DMG: [1650657603.294728][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657603.294766][3870:3875] CHIP:DMG: }, [1650657603.294869][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1650657603.294926][3870:3875] CHIP:CTL: Received Attestation Information from the device [1650657603.294973][3870:3875] CHIP:CTL: Finished commissioning step 'SendAttestationRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' [1650657603.295076][3870:3875] CHIP:CTL: Going from commissioning step 'SendAttestationRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' --> 'AttestationVerification' [1650657603.295123][3870:3875] CHIP:CTL: Performing next commissioning step 'AttestationVerification' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' [1650657603.295160][3870:3875] CHIP:CTL: Verifying attestation [1650657603.303301][3870:3875] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1650657603.303371][3870:3875] CHIP:CTL: Finished commissioning step 'AttestationVerification' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' [1650657603.303405][3870:3875] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' --> 'SendOpCertSigningRequest' [1650657603.303438][3870:3875] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' [1650657603.303468][3870:3875] CHIP:CTL: Sending CSR request to 0xffff90001760 device [1650657603.303546][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657603.303586][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657603.303705][3870:3875] CHIP:IN: Prepared secure message 0xffffa48ea0a8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10909i with MessageCounter:13101027. [1650657603.303758][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48ea0a8 with MessageCounter:13101027 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1FD16 msec [1650657603.303888][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657603.303926][3870:3875] CHIP:CTL: Sent CSR request, waiting for the CSR [1650657603.303989][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657603.387550][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657603.435766][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.436123][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.681188][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.681587][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.681831][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515803 on exchange 10909i [1650657603.681908][3870:3875] CHIP:EM: Found matching exchange: 10909i, Delegate: 0xffff9c06c820 [1650657603.682035][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657603.682143][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657603.682214][3870:3875] CHIP:DMG: { [1650657603.682280][3870:3875] CHIP:DMG: suppressResponse = false, [1650657603.682342][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657603.682425][3870:3875] CHIP:DMG: [ [1650657603.682487][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657603.682578][3870:3875] CHIP:DMG: { [1650657603.682644][3870:3875] CHIP:DMG: CommandDataIB = [1650657603.682728][3870:3875] CHIP:DMG: { [1650657603.682810][3870:3875] CHIP:DMG: CommandPathIB = [1650657603.682892][3870:3875] CHIP:DMG: { [1650657603.682978][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657603.683071][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657603.683161][3870:3875] CHIP:DMG: CommandId = 0x5, [1650657603.683244][3870:3875] CHIP:DMG: }, [1650657603.683337][3870:3875] CHIP:DMG: [1650657603.683418][3870:3875] CHIP:DMG: CommandData = [1650657603.683500][3870:3875] CHIP:DMG: { [1650657603.683583][3870:3875] CHIP:DMG: 0x0 = [ [1650657603.683724][3870:3875] 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 [1650657603.683827][3870:3875] CHIP:DMG: ] [1650657603.683908][3870:3875] CHIP:DMG: 0x1 = [ [1650657603.684025][3870:3875] CHIP:DMG: 0x93, 0x7e, 0xf8, 0xa9, 0x57, 0xe5, 0x81, 0xa0, 0x97, 0x84, 0xca, 0x11, 0x4b, 0xb6, 0xe0, 0x61, 0xe9, 0x9e, 0xe1, 0x72, 0x9c, 0xe, 0x27, 0x16, 0x40, 0x9c, 0x8e, 0xe9, 0x41, 0x11, 0xc7, 0xf, 0x82, 0xea, 0xb0, 0x3c, 0x19, 0xc7, 0x8c, 0xdd, 0xd2, 0x35, [1650657603.684120][3870:3875] CHIP:DMG: ] [1650657603.684202][3870:3875] CHIP:DMG: }, [1650657603.684279][3870:3875] CHIP:DMG: }, [1650657603.684366][3870:3875] CHIP:DMG: [1650657603.684435][3870:3875] CHIP:DMG: }, [1650657603.684519][3870:3875] CHIP:DMG: [1650657603.684579][3870:3875] CHIP:DMG: ], [1650657603.684657][3870:3875] CHIP:DMG: [1650657603.684718][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657603.684776][3870:3875] CHIP:DMG: }, [1650657603.684925][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1650657603.685038][3870:3875] CHIP:CTL: Received certificate signing request from the device [1650657603.685110][3870:3875] CHIP:CTL: Finished commissioning step 'SendOpCertSigningRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' [1650657603.685173][3870:3875] CHIP:CTL: Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' --> 'ValidateCSR' [1650657603.685237][3870:3875] CHIP:CTL: Performing next commissioning step 'ValidateCSR' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' [1650657603.687698][3870:3875] CHIP:CTL: Finished commissioning step 'ValidateCSR' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650657603.687786][3870:3875] CHIP:CTL: Going from commissioning step 'ValidateCSR' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' --> 'GenerateNOCChain' [1650657603.687853][3870:3875] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650657603.687913][3870:3875] CHIP:CTL: Getting certificate chain for the device from the issuer [1650657603.688394][3870:3875] CHIP:CTL: Verifying Certificate Signing Request [1650657603.690286][3870:3875] CHIP:CTL: Generating NOC [1650657603.690817][3870:3875] CHIP:CTL: Providing certificate chain to the commissioner [1650657603.690866][3870:3875] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success [1650657603.690902][3870:3875] CHIP:CTL: Finished commissioning step 'GenerateNOCChain' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success' [1650657603.691087][3870:3875] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650657603.691121][3870:3875] CHIP:CTL: Sending root certificate to the device [1650657603.691198][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657603.691263][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657603.691387][3870:3875] CHIP:IN: Prepared secure message 0xffffa48e9958 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10910i with MessageCounter:13101028. [1650657603.691461][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48e9958 with MessageCounter:13101028 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1FE9A msec [1650657603.691587][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657603.691619][3870:3875] CHIP:CTL: Sent root certificate to the device [1650657603.691943][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657603.777260][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657603.874714][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657603.876843][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657603.877276][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657603.877540][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515804 on exchange 10910i [1650657603.877618][3870:3875] CHIP:EM: Found matching exchange: 10910i, Delegate: 0xffff90004600 [1650657603.877705][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657603.877805][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657603.877866][3870:3875] CHIP:DMG: { [1650657603.877925][3870:3875] CHIP:DMG: suppressResponse = false, [1650657603.877986][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657603.878064][3870:3875] CHIP:DMG: [ [1650657603.878124][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657603.878218][3870:3875] CHIP:DMG: { [1650657603.878283][3870:3875] CHIP:DMG: CommandStatusIB = [1650657603.878369][3870:3875] CHIP:DMG: { [1650657603.878444][3870:3875] CHIP:DMG: CommandPathIB = [1650657603.878527][3870:3875] CHIP:DMG: { [1650657603.878619][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657603.878709][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657603.878796][3870:3875] CHIP:DMG: CommandId = 0xb, [1650657603.878874][3870:3875] CHIP:DMG: }, [1650657603.878970][3870:3875] CHIP:DMG: [1650657603.879041][3870:3875] CHIP:DMG: StatusIB = [1650657603.879128][3870:3875] CHIP:DMG: { [1650657603.879211][3870:3875] CHIP:DMG: status = 0x00 (SUCCESS), [1650657603.879294][3870:3875] CHIP:DMG: }, [1650657603.879373][3870:3875] CHIP:DMG: [1650657603.879446][3870:3875] CHIP:DMG: }, [1650657603.879532][3870:3875] CHIP:DMG: [1650657603.879601][3870:3875] CHIP:DMG: }, [1650657603.879681][3870:3875] CHIP:DMG: [1650657603.879740][3870:3875] CHIP:DMG: ], [1650657603.879815][3870:3875] CHIP:DMG: [1650657603.879876][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657603.879933][3870:3875] CHIP:DMG: }, [1650657603.880072][3870:3875] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1650657603.880142][3870:3875] CHIP:CTL: Device confirmed that it has received the root certificate [1650657603.880207][3870:3875] CHIP:CTL: Finished commissioning step 'SendTrustedRootCert' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' [1650657603.880269][3870:3875] CHIP:CTL: Going from commissioning step 'SendTrustedRootCert' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' --> 'SendNOC' [1650657603.880332][3870:3875] CHIP:CTL: Performing next commissioning step 'SendNOC' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' [1650657603.880455][3870:3875] CHIP:DMG: ICR moving to [AddingComm] [1650657603.880537][3870:3875] CHIP:DMG: ICR moving to [AddedComma] [1650657603.880752][3870:3875] CHIP:IN: Prepared secure message 0xffffa48ea9e8 to 0x00000000000004D2 (1) of type 0x8 and protocolId (0, 1) on exchange 10911i with MessageCounter:13101029. [1650657603.880844][3870:3875] CHIP:IN: Sending encrypted msg 0xffffa48ea9e8 with MessageCounter:13101029 to 0x00000000000004D2 (1) at monotonic time: 0000000000C1FF57 msec [1650657603.881088][3870:3875] CHIP:DMG: ICR moving to [CommandSen] [1650657603.881156][3870:3875] CHIP:CTL: Sent operational certificate to the device [1650657603.881265][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657604.021072][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657604.167050][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657604.264797][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1650657604.411647][3870:3873] CHIP:DL: Indication received, conn = 0xffff9c06b170 [1650657604.412048][3870:3875] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1650657604.412306][3870:3875] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:16515805 on exchange 10911i [1650657604.412384][3870:3875] CHIP:EM: Found matching exchange: 10911i, Delegate: 0xffff9c06c820 [1650657604.412470][3870:3875] CHIP:DMG: ICR moving to [ResponseRe] [1650657604.412571][3870:3875] CHIP:DMG: InvokeResponseMessage = [1650657604.412633][3870:3875] CHIP:DMG: { [1650657604.412694][3870:3875] CHIP:DMG: suppressResponse = false, [1650657604.412751][3870:3875] CHIP:DMG: InvokeResponseIBs = [1650657604.412831][3870:3875] CHIP:DMG: [ [1650657604.412893][3870:3875] CHIP:DMG: InvokeResponseIB = [1650657604.413026][3870:3875] CHIP:DMG: { [1650657604.413097][3870:3875] CHIP:DMG: CommandDataIB = [1650657604.413185][3870:3875] CHIP:DMG: { [1650657604.413260][3870:3875] CHIP:DMG: CommandPathIB = [1650657604.413345][3870:3875] CHIP:DMG: { [1650657604.413436][3870:3875] CHIP:DMG: EndpointId = 0x0, [1650657604.413528][3870:3875] CHIP:DMG: ClusterId = 0x3e, [1650657604.413617][3870:3875] CHIP:DMG: CommandId = 0x8, [1650657604.413703][3870:3875] CHIP:DMG: }, [1650657604.413789][3870:3875] CHIP:DMG: [1650657604.413864][3870:3875] CHIP:DMG: CommandData = [1650657604.413945][3870:3875] CHIP:DMG: { [1650657604.414030][3870:3875] CHIP:DMG: 0x0 = 0, [1650657604.414120][3870:3875] CHIP:DMG: 0x1 = 1, [1650657604.414205][3870:3875] CHIP:DMG: }, [1650657604.414282][3870:3875] CHIP:DMG: }, [1650657604.414365][3870:3875] CHIP:DMG: [1650657604.414433][3870:3875] CHIP:DMG: }, [1650657604.414514][3870:3875] CHIP:DMG: [1650657604.414573][3870:3875] CHIP:DMG: ], [1650657604.414649][3870:3875] CHIP:DMG: [1650657604.414709][3870:3875] CHIP:DMG: InteractionModelRevision = 1 [1650657604.414767][3870:3875] CHIP:DMG: }, [1650657604.414913][3870:3875] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1650657604.415062][3870:3875] CHIP:CTL: Device returned status 0 on receiving the NOC [1650657604.415122][3870:3875] CHIP:CTL: Operational credentials provisioned on device 0xffff90001760 [1650657604.415205][3870:3875] CHIP:TOO: Secure Pairing Success [1650657604.415267][3870:3875] CHIP:CTL: Finished commissioning step 'SendNOC' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1390: Success' [1650657604.415327][3870:3875] CHIP:CTL: Required network information not provided in commissioning parameters [1650657604.415378][3870:3875] CHIP:CTL: Parameters supplied: wifi (yes) thread (no) [1650657604.415428][3870:3875] CHIP:CTL: Device supports: wifi (no) thread(yes) [1650657604.415492][3870:3875] CHIP:CTL: Going from commissioning step 'SendNOC' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:180: CHIP Error 0x0000002F: Invalid argument' --> 'Cleanup' [1650657604.415556][3870:3875] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1390: Success' [1650657604.415617][3870:3875] CHIP:CTL: Finished commissioning step 'Cleanup' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1497: Success' [1650657604.415678][3870:3875] CHIP:TOO: Device commissioning completed with success [1650657604.415813][3870:3875] CHIP:DMG: ICR moving to [AwaitingDe] [1650657604.416239][3870:3870] CHIP:CTL: Shutting down the commissioner [1650657604.416491][3870:3870] CHIP:CTL: Shutting down the controller [1650657604.416596][3870:3870] CHIP:CTL: Shutting down the commissioner [1650657604.416858][3870:3870] CHIP:CTL: Shutting down the controller [1650657604.416945][3870:3870] CHIP:IN: Expiring all connections for fabric 1!! [1650657604.417105][3870:3870] CHIP:CTL: Shutting down the commissioner [1650657604.417303][3870:3870] CHIP:CTL: Shutting down the controller [1650657604.417386][3870:3870] CHIP:IN: Expiring all connections for fabric 2!! [1650657604.417487][3870:3870] CHIP:CTL: Shutting down the commissioner [1650657604.417682][3870:3870] CHIP:CTL: Shutting down the controller [1650657604.417763][3870:3870] CHIP:IN: Expiring all connections for fabric 3!! [1650657604.417854][3870:3870] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650657604.420714][3870:3870] CHIP:DMG: IM WH moving to [Uninitialized] [1650657604.420942][3870:3870] CHIP:DMG: IM WH moving to [Uninitialized] [1650657604.421021][3870:3870] CHIP:DMG: IM WH moving to [Uninitialized] [1650657604.421073][3870:3870] CHIP:DMG: IM WH moving to [Uninitialized] [1650657604.421152][3870:3870] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650657604.421375][3870:3870] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650657604.421458][3870:3870] CHIP:IN: Clearing BLE pending packets. [1650657604.422030][3870:3870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-gqtol9) [1650657604.423070][3870:3870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657604.423159][3870:3870] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650657604.423234][3870:3870] CHIP:DL: Inet Layer shutdown [1650657604.423264][3870:3870] CHIP:DL: BLE shutdown [1650657604.423290][3870:3870] CHIP:BLE: Auto-closing end point's BLE connection. [1650657604.423315][3870:3870] CHIP:DL: Closing BLE GATT connection (con 0xffff9c06b170) [1650657604.424437][3870:3873] CHIP:DL: BluezDisconnect peer=DC:A6:32:8D:2B:A1 [1650657604.426333][3870:3870] CHIP:DL: System Layer shutdown ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 1234 1 [1650657649.746560][3880:3880] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650657649.746788][3880:3880] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650657649.747178][3880:3880] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650657649.747332][3880:3880] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650657649.747443][3880:3880] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650657649.747781][3880:3880] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-x65KCz) [1650657649.748394][3880:3880] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657649.748446][3880:3880] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1650657649.749384][3880:3880] CHIP:DL: Got Ethernet interface: eth0 [1650657649.750124][3880:3880] CHIP:DL: Found the primary Ethernet interface:eth0 [1650657649.750822][3880:3880] CHIP:DL: Got WiFi interface: wlan0 [1650657649.750899][3880:3880] CHIP:DL: Failed to reset WiFi statistic counts [1650657649.750996][3880:3880] CHIP:IN: UDP::Init bind&listen port=0 [1650657649.751132][3880:3880] CHIP:IN: UDP::Init bound to port=60728 [1650657649.751200][3880:3880] CHIP:IN: UDP::Init bind&listen port=0 [1650657649.751303][3880:3880] CHIP:IN: UDP::Init bound to port=46927 [1650657649.751328][3880:3880] CHIP:IN: BLEBase::Init - setting/overriding transport [1650657649.751350][3880:3880] CHIP:IN: TransportMgr initialized [1650657649.751398][3880:3880] CHIP:DIS: Init fabric pairing table with server storage [1650657649.751569][3880:3880] CHIP:IN: Loading from storage for fabric index 1 [1650657649.754105][3880:3880] CHIP:IN: Loading from storage for fabric index 2 [1650657649.754691][3880:3880] CHIP:IN: Loading from storage for fabric index 3 [1650657649.755305][3880:3880] CHIP:DIS: Add fabric pairing table delegate [1650657649.755567][3880:3880] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-a1ygq2) [1650657649.756208][3880:3880] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657649.756263][3880:3880] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 3000 (0xBB8) [1650657649.759117][3880:3880] CHIP:ZCL: Using ZAP configuration... [1650657649.762408][3880:3880] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.769677][3880:3880] CHIP:DL: MDNS failed to join multicast group on vethf98e81b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.771424][3880:3880] CHIP:DL: MDNS failed to join multicast group on veth49716b3 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.773402][3880:3880] CHIP:DL: MDNS failed to join multicast group on veth817a68d for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.775190][3880:3880] CHIP:DL: MDNS failed to join multicast group on veth4ef2089 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.776933][3880:3880] CHIP:DL: MDNS failed to join multicast group on vethb5a3c32 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657649.777302][3880:3880] CHIP:CTL: System State Initialized... [1650657649.777391][3880:3880] CHIP:CTL: Setting attestation nonce to random value [1650657649.777471][3880:3880] CHIP:CTL: Setting CSR nonce to random value [1650657649.777548][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.777641][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.777666][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.777755][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.777779][3880:3880] CHIP:IN: TransportMgr initialized [1650657649.777832][3880:3880] CHIP:CTL: Setting attestation nonce to random value [1650657649.777882][3880:3880] CHIP:CTL: Setting CSR nonce to random value [1650657649.778764][3880:3880] CHIP:CTL: Generating NOC [1650657649.779749][3880:3880] CHIP:DIS: Verifying the received credentials [1650657649.781570][3880:3880] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650657649.781606][3880:3880] CHIP:DIS: Assigned compressed fabric ID: 0x0BA7B4D5E28EA581, node ID: 0x000000000001B669 [1650657649.781661][3880:3880] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0BA7B4D5E28EA581 [1650657649.781703][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.781836][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.781863][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.781957][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.781980][3880:3880] CHIP:IN: TransportMgr initialized [1650657649.782078][3880:3880] CHIP:CTL: Setting attestation nonce to random value [1650657649.782137][3880:3880] CHIP:CTL: Setting CSR nonce to random value [1650657649.782922][3880:3880] CHIP:CTL: Generating NOC [1650657649.783774][3880:3880] CHIP:DIS: Verifying the received credentials [1650657649.785565][3880:3880] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650657649.785604][3880:3880] CHIP:DIS: Assigned compressed fabric ID: 0xC1CCD686519F7E0B, node ID: 0x000000000001B669 [1650657649.785629][3880:3880] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xC1CCD686519F7E0B [1650657649.785668][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.785835][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.785863][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.785953][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.785977][3880:3880] CHIP:IN: TransportMgr initialized [1650657649.786071][3880:3880] CHIP:CTL: Setting attestation nonce to random value [1650657649.786130][3880:3880] CHIP:CTL: Setting CSR nonce to random value [1650657649.786909][3880:3880] CHIP:CTL: Generating NOC [1650657649.787776][3880:3880] CHIP:DIS: Verifying the received credentials [1650657649.789896][3880:3880] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650657649.789938][3880:3880] CHIP:DIS: Assigned compressed fabric ID: 0xBA470D9A0C420C73, node ID: 0x000000000001B669 [1650657649.789962][3880:3880] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xBA470D9A0C420C73 [1650657649.790002][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.790129][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.790180][3880:3880] CHIP:IN: UDP::Init bind&listen port=5550 [1650657649.790274][3880:3880] CHIP:IN: UDP::Init bound to port=5550 [1650657649.790298][3880:3880] CHIP:IN: TransportMgr initialized [1650657649.828547][3880:3885] CHIP:DL: CHIP task running [1650657649.828728][3880:3885] CHIP:TOO: Sending command to node 0x4d2 [1650657649.828771][3880:3885] CHIP:CSM: FindOrEstablishSession: PeerId = 0BA7B4D5E28EA581:00000000000004D2 [1650657649.828805][3880:3885] CHIP:CSM: FindOrEstablishSession: No existing session found [1650657649.829549][3880:3885] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657649.829829][3880:3885] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657649.830081][3880:3885] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657649.830307][3880:3885] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657649.833940][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.834001][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.834033][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.834063][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.835030][3880:3885] CHIP:DIS: Lookup clearing interface for non LL address [1650657649.835072][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: new best score: 6 [1650657649.835172][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.835265][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.835300][3880:3885] CHIP:DIS: Checking node lookup status after 7 ms [1650657649.835329][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.836426][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.836467][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.836504][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.836593][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.836624][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.837550][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.837662][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.837754][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.837790][3880:3885] CHIP:DIS: Checking node lookup status after 9 ms [1650657649.837826][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.838998][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.839037][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.839072][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.839104][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.839134][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.839948][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.840052][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.840145][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.840179][3880:3885] CHIP:DIS: Checking node lookup status after 12 ms [1650657649.840207][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.842155][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.842231][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.842268][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.842300][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.842330][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.843140][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.843246][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.843335][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.843369][3880:3885] CHIP:DIS: Checking node lookup status after 15 ms [1650657649.843397][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.844780][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.844819][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.844856][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.844888][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.844917][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.845641][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.845762][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.845833][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.845858][3880:3885] CHIP:DIS: Checking node lookup status after 17 ms [1650657649.845880][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.847379][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.847408][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.847436][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.847460][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.847482][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.848082][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.848159][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.848230][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.848254][3880:3885] CHIP:DIS: Checking node lookup status after 20 ms [1650657649.848275][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.850198][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.850229][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.850256][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.850279][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.850301][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.850957][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.851037][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.851108][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.851133][3880:3885] CHIP:DIS: Checking node lookup status after 23 ms [1650657649.851155][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.853730][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.853888][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.853918][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.853942][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.853963][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.854586][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.854668][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.854741][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.854766][3880:3885] CHIP:DIS: Checking node lookup status after 26 ms [1650657649.854788][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.856633][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.856672][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.856709][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.856741][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.856771][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.857803][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.857918][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.858013][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.858048][3880:3885] CHIP:DIS: Checking node lookup status after 30 ms [1650657649.858076][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.860028][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.860068][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.860103][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.860135][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.860165][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.860991][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.861100][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.861194][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.861228][3880:3885] CHIP:DIS: Checking node lookup status after 33 ms [1650657649.861257][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.862852][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.862890][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.862926][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.862957][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.862987][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.863775][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.863920][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.864015][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.864103][3880:3885] CHIP:DIS: Checking node lookup status after 36 ms [1650657649.864131][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.865667][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.865706][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.865742][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.865774][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.865804][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.866605][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.866714][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.866810][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.866845][3880:3885] CHIP:DIS: Checking node lookup status after 38 ms [1650657649.866873][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.868496][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.868534][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.868571][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.868603][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.868633][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.869577][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.869684][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.869779][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.869813][3880:3885] CHIP:DIS: Checking node lookup status after 41 ms [1650657649.869842][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.871325][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.871363][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.871399][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.871431][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.871460][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.872254][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.872354][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.872447][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.872481][3880:3885] CHIP:DIS: Checking node lookup status after 44 ms [1650657649.872510][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.874148][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.874187][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.874223][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.874256][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.874285][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.875082][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.875184][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.875321][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.875356][3880:3885] CHIP:DIS: Checking node lookup status after 47 ms [1650657649.875385][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.877272][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.877311][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.877348][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.877380][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.877409][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.878201][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.878307][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.878401][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.878434][3880:3885] CHIP:DIS: Checking node lookup status after 50 ms [1650657649.878463][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.880062][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.880100][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.880135][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.880166][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.880196][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.881076][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.881184][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.881273][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.881307][3880:3885] CHIP:DIS: Checking node lookup status after 53 ms [1650657649.881335][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657649.882909][3880:3885] CHIP:DIS: Discovered node without a pending query [1650657649.882946][3880:3885] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657649.882981][3880:3885] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657649.883013][3880:3885] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657649.883042][3880:3885] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657649.883883][3880:3885] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657649.883991][3880:3885] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657649.884127][3880:3885] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657649.884163][3880:3885] CHIP:DIS: Checking node lookup status after 56 ms [1650657649.884191][3880:3885] CHIP:DIS: Keeping DNSSD lookup active [1650657650.028651][3880:3885] CHIP:DIS: Checking node lookup status after 200 ms [1650657650.028769][3880:3885] CHIP:CTL: Updating device address to UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 while in state 1 [1650657650.028828][3880:3885] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 1 --> 2 [1650657650.029193][3880:3885] CHIP:SC: Establishing CASE session to UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657650.030422][3880:3885] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaaac5281830, Got IPK for FabricIndex 1 [1650657650.030511][3880:3885] CHIP:SC: 0x46, 0xb2, 0x36, 0x65, 0xd0, 0x37, 0x07, 0x3a, [1650657650.030572][3880:3885] CHIP:SC: 0xee, 0xf0, 0x09, 0xd2, 0xac, 0x39, 0xe7, 0x2c, [1650657650.030809][3880:3885] CHIP:SC: Including MRP parameters [1650657650.030947][3880:3885] CHIP:IN: Prepared unauthenticated message 0xaaaac57bbd38 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 21029i with MessageCounter:591831641. [1650657650.031042][3880:3885] CHIP:IN: Sending unauthenticated msg 0xaaaac57bbd38 with MessageCounter:591831641 to 0x0000000000000000 at monotonic time: 0000000000C2B39E msec [1650657650.031450][3880:3885] CHIP:SC: Sent Sigma1 msg [1650657650.031685][3880:3885] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 2 --> 3 [1650657650.031973][3880:3885] CHIP:DIS: Discovery does not require any more timeouts [1650657650.034663][3880:3885] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1850391413 on exchange 21029i [1650657650.034720][3880:3885] CHIP:EM: Found matching exchange: 21029i, Delegate: 0xffff880015e0 [1650657650.034779][3880:3885] CHIP:EM: Rxd Ack; Removing MessageCounter:591831641 from Retrans Table on exchange 21029i [1650657650.034821][3880:3885] CHIP:EM: Removed CHIP MessageCounter:591831641 from RetransTable on exchange 21029i [1650657650.034875][3880:3885] CHIP:SC: Received Sigma2 msg [1650657650.034928][3880:3885] CHIP:SC: Peer assigned session session ID 6030 [1650657650.035845][3880:3885] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1650657650.040137][3880:3885] CHIP:SC: Found MRP parameters in the message [1650657650.040204][3880:3885] CHIP:SC: Sending Sigma3 [1650657650.040654][3880:3885] CHIP:EM: Piggybacking Ack for MessageCounter:1850391413 on exchange: 21029i [1650657650.040727][3880:3885] CHIP:IN: Prepared unauthenticated message 0xaaaac57bbd38 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 21029i with MessageCounter:591831642. [1650657650.040788][3880:3885] CHIP:IN: Sending unauthenticated msg 0xaaaac57bbd38 with MessageCounter:591831642 to 0x0000000000000000 at monotonic time: 0000000000C2B3A7 msec [1650657650.041055][3880:3885] CHIP:SC: Sent Sigma3 msg [1650657650.045077][3880:3885] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1850391414 on exchange 21029i [1650657650.045135][3880:3885] CHIP:EM: Found matching exchange: 21029i, Delegate: 0xffff880015e0 [1650657650.045192][3880:3885] CHIP:EM: Rxd Ack; Removing MessageCounter:591831642 from Retrans Table on exchange 21029i [1650657650.045233][3880:3885] CHIP:EM: Removed CHIP MessageCounter:591831642 from RetransTable on exchange 21029i [1650657650.045287][3880:3885] CHIP:SC: Success status report received. Session was established [1650657650.045333][3880:3885] CHIP:IN: New secure session created for device 0x00000000000004D2, LSID:58916 PSID:6030! [1650657650.045422][3880:3885] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 3 --> 4 [1650657650.045502][3880:3885] CHIP:TOO: Sending ReadAttribute to: [1650657650.045546][3880:3885] CHIP:TOO: cluster 0x0000_0101, attribute: 0x0000_FFFD, endpoint 1 [1650657650.045596][3880:3885] CHIP:DMG: SendReadRequest ReadClient[0xffff880014a0]: Sending Read Request [1650657650.045726][3880:3885] CHIP:IN: Prepared secure message 0xaaaac57bbd38 to 0x00000000000004D2 (1) of type 0x2 and protocolId (0, 1) on exchange 21030i with MessageCounter:9875532. [1650657650.045785][3880:3885] CHIP:IN: Sending encrypted msg 0xaaaac57bbd38 with MessageCounter:9875532 to 0x00000000000004D2 (1) at monotonic time: 0000000000C2B3AC msec [1650657650.045979][3880:3885] CHIP:DMG: MoveToState ReadClient[0xffff880014a0]: Moving to [AwaitingIn] [1650657650.046037][3880:3885] CHIP:EM: Sending Standalone Ack for MessageCounter:1850391414 on exchange 21029i [1650657650.046089][3880:3885] CHIP:IN: Prepared unauthenticated message 0xffff927cd9a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 21029i with MessageCounter:591831643. [1650657650.046142][3880:3885] CHIP:IN: Sending unauthenticated msg 0xffff927cd9a8 with MessageCounter:591831643 to 0x0000000000000000 at monotonic time: 0000000000C2B3AD msec [1650657650.046256][3880:3885] CHIP:EM: Flushed pending ack for MessageCounter:1850391414 on exchange 21029i [1650657650.047766][3880:3885] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:3192549 on exchange 21030i [1650657650.047809][3880:3885] CHIP:EM: Found matching exchange: 21030i, Delegate: 0xffff880014a0 [1650657650.047853][3880:3885] CHIP:EM: Rxd Ack; Removing MessageCounter:9875532 from Retrans Table on exchange 21030i [1650657650.047886][3880:3885] CHIP:EM: Removed CHIP MessageCounter:9875532 from RetransTable on exchange 21030i [1650657650.047955][3880:3885] CHIP:DMG: ReportDataMessage = [1650657650.047993][3880:3885] CHIP:DMG: { [1650657650.048023][3880:3885] CHIP:DMG: AttributeReportIBs = [1650657650.048066][3880:3885] CHIP:DMG: [ [1650657650.048100][3880:3885] CHIP:DMG: AttributeReportIB = [1650657650.048150][3880:3885] CHIP:DMG: { [1650657650.048189][3880:3885] CHIP:DMG: AttributeDataIB = [1650657650.048235][3880:3885] CHIP:DMG: { [1650657650.048280][3880:3885] CHIP:DMG: DataVersion = 0x37f812ed, [1650657650.048326][3880:3885] CHIP:DMG: AttributePathIB = [1650657650.048372][3880:3885] CHIP:DMG: { [1650657650.048424][3880:3885] CHIP:DMG: Endpoint = 0x1, [1650657650.048474][3880:3885] CHIP:DMG: Cluster = 0x101, [1650657650.048521][3880:3885] CHIP:DMG: Attribute = 0x0000_FFFD, [1650657650.048570][3880:3885] CHIP:DMG: } [1650657650.048622][3880:3885] CHIP:DMG: [1650657650.048673][3880:3885] CHIP:DMG: Data = 3, [1650657650.048723][3880:3885] CHIP:DMG: }, [1650657650.048771][3880:3885] CHIP:DMG: [1650657650.048809][3880:3885] CHIP:DMG: }, [1650657650.048854][3880:3885] CHIP:DMG: [1650657650.048888][3880:3885] CHIP:DMG: ], [1650657650.048930][3880:3885] CHIP:DMG: [1650657650.049003][3880:3885] CHIP:DMG: SuppressResponse = true, [1650657650.049040][3880:3885] CHIP:DMG: InteractionModelRevision = 1 [1650657650.049073][3880:3885] CHIP:DMG: } [1650657650.053206][3880:3885] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Attribute 0x0000_FFFD DataVersion: 939004653 [1650657650.054116][3880:3885] CHIP:TOO: ClusterRevision: 3 [1650657650.056344][3880:3885] CHIP:EM: Sending Standalone Ack for MessageCounter:3192549 on exchange 21030i [1650657650.056452][3880:3885] CHIP:IN: Prepared secure message 0xffff927cd9b8 to 0x00000000000004D2 (1) of type 0x10 and protocolId (0, 0) on exchange 21030i with MessageCounter:9875533. [1650657650.056507][3880:3885] CHIP:IN: Sending encrypted msg 0xffff927cd9b8 with MessageCounter:9875533 to 0x00000000000004D2 (1) at monotonic time: 0000000000C2B3B7 msec [1650657650.056658][3880:3885] CHIP:EM: Flushed pending ack for MessageCounter:3192549 on exchange 21030i [1650657650.056891][3880:3880] CHIP:CTL: Shutting down the commissioner [1650657650.057076][3880:3880] CHIP:CTL: Shutting down the controller [1650657650.057134][3880:3880] CHIP:CTL: Shutting down the commissioner [1650657650.057240][3880:3880] CHIP:CTL: Shutting down the controller [1650657650.057294][3880:3880] CHIP:IN: Expiring all connections for fabric 1!! [1650657650.057355][3880:3880] CHIP:CTL: Shutting down the commissioner [1650657650.057474][3880:3880] CHIP:CTL: Shutting down the controller [1650657650.057507][3880:3880] CHIP:IN: Expiring all connections for fabric 2!! [1650657650.057568][3880:3880] CHIP:CTL: Shutting down the commissioner [1650657650.057685][3880:3880] CHIP:CTL: Shutting down the controller [1650657650.057719][3880:3880] CHIP:IN: Expiring all connections for fabric 3!! [1650657650.057776][3880:3880] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650657650.059562][3880:3880] CHIP:DMG: IM WH moving to [Uninitialized] [1650657650.059607][3880:3880] CHIP:DMG: IM WH moving to [Uninitialized] [1650657650.059638][3880:3880] CHIP:DMG: IM WH moving to [Uninitialized] [1650657650.059669][3880:3880] CHIP:DMG: IM WH moving to [Uninitialized] [1650657650.059702][3880:3880] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650657650.059833][3880:3880] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650657650.060166][3880:3880] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-0nhLSC) [1650657650.060985][3880:3880] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657650.061061][3880:3880] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650657650.061100][3880:3880] CHIP:DL: Inet Layer shutdown [1650657650.061133][3880:3880] CHIP:DL: BLE shutdown [1650657650.061167][3880:3880] CHIP:DL: System Layer shutdown ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 1234 1 [1650657980.627187][3898:3898] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650657980.627414][3898:3898] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650657980.627848][3898:3898] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650657980.628020][3898:3898] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650657980.628132][3898:3898] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650657980.628484][3898:3898] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-KbIkcb) [1650657980.629145][3898:3898] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657980.629201][3898:3898] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4) [1650657980.630169][3898:3898] CHIP:DL: Got Ethernet interface: eth0 [1650657980.630875][3898:3898] CHIP:DL: Found the primary Ethernet interface:eth0 [1650657980.631584][3898:3898] CHIP:DL: Got WiFi interface: wlan0 [1650657980.631666][3898:3898] CHIP:DL: Failed to reset WiFi statistic counts [1650657980.631775][3898:3898] CHIP:IN: UDP::Init bind&listen port=0 [1650657980.631941][3898:3898] CHIP:IN: UDP::Init bound to port=54670 [1650657980.631970][3898:3898] CHIP:IN: UDP::Init bind&listen port=0 [1650657980.632086][3898:3898] CHIP:IN: UDP::Init bound to port=42564 [1650657980.632113][3898:3898] CHIP:IN: BLEBase::Init - setting/overriding transport [1650657980.632135][3898:3898] CHIP:IN: TransportMgr initialized [1650657980.632185][3898:3898] CHIP:DIS: Init fabric pairing table with server storage [1650657980.632338][3898:3898] CHIP:IN: Loading from storage for fabric index 1 [1650657980.634973][3898:3898] CHIP:IN: Loading from storage for fabric index 2 [1650657980.635596][3898:3898] CHIP:IN: Loading from storage for fabric index 3 [1650657980.636181][3898:3898] CHIP:DIS: Add fabric pairing table delegate [1650657980.636462][3898:3898] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-XZkfIU) [1650657980.637127][3898:3898] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657980.637195][3898:3898] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 4000 (0xFA0) [1650657980.640078][3898:3898] CHIP:ZCL: Using ZAP configuration... [1650657980.643355][3898:3898] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.650606][3898:3898] CHIP:DL: MDNS failed to join multicast group on vethf98e81b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.652393][3898:3898] CHIP:DL: MDNS failed to join multicast group on veth49716b3 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.654222][3898:3898] CHIP:DL: MDNS failed to join multicast group on veth817a68d for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.655939][3898:3898] CHIP:DL: MDNS failed to join multicast group on veth4ef2089 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.657725][3898:3898] CHIP:DL: MDNS failed to join multicast group on vethb5a3c32 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650657980.658112][3898:3898] CHIP:CTL: System State Initialized... [1650657980.658202][3898:3898] CHIP:CTL: Setting attestation nonce to random value [1650657980.658291][3898:3898] CHIP:CTL: Setting CSR nonce to random value [1650657980.658370][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.658484][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.658511][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.658618][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.658642][3898:3898] CHIP:IN: TransportMgr initialized [1650657980.658696][3898:3898] CHIP:CTL: Setting attestation nonce to random value [1650657980.658757][3898:3898] CHIP:CTL: Setting CSR nonce to random value [1650657980.659660][3898:3898] CHIP:CTL: Generating NOC [1650657980.660580][3898:3898] CHIP:DIS: Verifying the received credentials [1650657980.662403][3898:3898] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650657980.662440][3898:3898] CHIP:DIS: Assigned compressed fabric ID: 0x0BA7B4D5E28EA581, node ID: 0x000000000001B669 [1650657980.662464][3898:3898] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0BA7B4D5E28EA581 [1650657980.662505][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.662656][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.662683][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.662780][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.662804][3898:3898] CHIP:IN: TransportMgr initialized [1650657980.662913][3898:3898] CHIP:CTL: Setting attestation nonce to random value [1650657980.662971][3898:3898] CHIP:CTL: Setting CSR nonce to random value [1650657980.663783][3898:3898] CHIP:CTL: Generating NOC [1650657980.664642][3898:3898] CHIP:DIS: Verifying the received credentials [1650657980.666370][3898:3898] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650657980.666404][3898:3898] CHIP:DIS: Assigned compressed fabric ID: 0xC1CCD686519F7E0B, node ID: 0x000000000001B669 [1650657980.666428][3898:3898] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xC1CCD686519F7E0B [1650657980.666467][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.666610][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.666638][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.666751][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.666776][3898:3898] CHIP:IN: TransportMgr initialized [1650657980.666880][3898:3898] CHIP:CTL: Setting attestation nonce to random value [1650657980.666939][3898:3898] CHIP:CTL: Setting CSR nonce to random value [1650657980.667741][3898:3898] CHIP:CTL: Generating NOC [1650657980.668668][3898:3898] CHIP:DIS: Verifying the received credentials [1650657980.670749][3898:3898] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650657980.670790][3898:3898] CHIP:DIS: Assigned compressed fabric ID: 0xBA470D9A0C420C73, node ID: 0x000000000001B669 [1650657980.670813][3898:3898] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xBA470D9A0C420C73 [1650657980.670852][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.671001][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.671028][3898:3898] CHIP:IN: UDP::Init bind&listen port=5550 [1650657980.671133][3898:3898] CHIP:IN: UDP::Init bound to port=5550 [1650657980.671157][3898:3898] CHIP:IN: TransportMgr initialized [1650657980.710186][3898:3903] CHIP:DL: CHIP task running [1650657980.710359][3898:3903] CHIP:TOO: Sending command to node 0x4d2 [1650657980.710402][3898:3903] CHIP:CSM: FindOrEstablishSession: PeerId = 0BA7B4D5E28EA581:00000000000004D2 [1650657980.710431][3898:3903] CHIP:CSM: FindOrEstablishSession: No existing session found [1650657980.711136][3898:3903] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657980.711394][3898:3903] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657980.711621][3898:3903] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657980.711829][3898:3903] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650657980.715028][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.715090][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.715118][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.715145][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.716049][3898:3903] CHIP:DIS: Lookup clearing interface for non LL address [1650657980.716087][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: new best score: 6 [1650657980.716180][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.716261][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.716291][3898:3903] CHIP:DIS: Checking node lookup status after 6 ms [1650657980.716315][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.718061][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.718097][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.718128][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.718156][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.718181][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.718906][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.719021][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.719150][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.719180][3898:3903] CHIP:DIS: Checking node lookup status after 9 ms [1650657980.719205][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.720915][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.720975][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.721004][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.721026][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.721184][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.721936][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.722030][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.722110][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.722140][3898:3903] CHIP:DIS: Checking node lookup status after 12 ms [1650657980.722164][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.723318][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.723348][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.723374][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.723397][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.723419][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.724029][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.724111][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.724177][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.724202][3898:3903] CHIP:DIS: Checking node lookup status after 14 ms [1650657980.724224][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.726136][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.726166][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.726192][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.726216][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.726238][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.726903][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.726990][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.727058][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.727084][3898:3903] CHIP:DIS: Checking node lookup status after 17 ms [1650657980.727105][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.729131][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.729160][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.729215][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.729242][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.729264][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.729874][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.729955][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.730021][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.730047][3898:3903] CHIP:DIS: Checking node lookup status after 20 ms [1650657980.730068][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.732059][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.732087][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.732113][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.732136][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.732158][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.732817][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.732898][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.732992][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.733018][3898:3903] CHIP:DIS: Checking node lookup status after 23 ms [1650657980.733040][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.734843][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.734882][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.734917][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.734948][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.734977][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.735828][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.735936][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.736028][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.736062][3898:3903] CHIP:DIS: Checking node lookup status after 26 ms [1650657980.736091][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.737662][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.737698][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.737733][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.737765][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.737794][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.738585][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.738686][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.738780][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.738813][3898:3903] CHIP:DIS: Checking node lookup status after 28 ms [1650657980.738842][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.742108][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.742147][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.742181][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.742212][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.742242][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.743054][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.743162][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.743256][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.743290][3898:3903] CHIP:DIS: Checking node lookup status after 33 ms [1650657980.743319][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.744921][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.745095][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.745138][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.745175][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.745207][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.746090][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.746203][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.746305][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.746342][3898:3903] CHIP:DIS: Checking node lookup status after 36 ms [1650657980.746373][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.747766][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.747807][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.747844][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.747879][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.747911][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.748774][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.748936][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.749076][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.749114][3898:3903] CHIP:DIS: Checking node lookup status after 39 ms [1650657980.749146][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.750594][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.750634][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.750672][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.750708][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.750740][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.751660][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.751776][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.751882][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.751919][3898:3903] CHIP:DIS: Checking node lookup status after 41 ms [1650657980.751951][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.753501][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.753542][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.753580][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.753615][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.753648][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.754490][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.754596][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.754685][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.754717][3898:3903] CHIP:DIS: Checking node lookup status after 44 ms [1650657980.754743][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.756327][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.756362][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.756393][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.756422][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.756449][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.757196][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.757299][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.757386][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.757418][3898:3903] CHIP:DIS: Checking node lookup status after 47 ms [1650657980.757444][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.759824][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.759857][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.759889][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.759918][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.759946][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.760666][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.760767][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.760851][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.760882][3898:3903] CHIP:DIS: Checking node lookup status after 50 ms [1650657980.760908][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.762829][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.762863][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.762896][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.762926][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.762953][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.763691][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.763792][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.763877][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.763909][3898:3903] CHIP:DIS: Checking node lookup status after 53 ms [1650657980.763935][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.765539][3898:3903] CHIP:DIS: Discovered node without a pending query [1650657980.765581][3898:3903] CHIP:DIS: Node ID resolved for 0BA7B4D5E28EA581:00000000000004D2 [1650657980.765619][3898:3903] CHIP:DIS: Addr 0: [fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.765654][3898:3903] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:2b9f]:5540 [1650657980.765686][3898:3903] CHIP:DIS: Addr 2: [192.168.1.2]:5540 [1650657980.766545][3898:3903] CHIP:DIS: UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 6 [1650657980.766662][3898:3903] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:2b9f%eth0]:5540: score has not improved: 3 [1650657980.766764][3898:3903] CHIP:DIS: UDP:192.168.1.2%eth0:5540: score has not improved: 2 [1650657980.766801][3898:3903] CHIP:DIS: Checking node lookup status after 56 ms [1650657980.766833][3898:3903] CHIP:DIS: Keeping DNSSD lookup active [1650657980.910421][3898:3903] CHIP:DIS: Checking node lookup status after 200 ms [1650657980.910520][3898:3903] CHIP:CTL: Updating device address to UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 while in state 1 [1650657980.910569][3898:3903] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 1 --> 2 [1650657980.910848][3898:3903] CHIP:SC: Establishing CASE session to UDP:[fd54:23a1:c6de:4637:dea6:32ff:fe8d:2b9f]:5540 [1650657980.911906][3898:3903] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaaae82d8830, Got IPK for FabricIndex 1 [1650657980.911982][3898:3903] CHIP:SC: 0x46, 0xb2, 0x36, 0x65, 0xd0, 0x37, 0x07, 0x3a, [1650657980.912034][3898:3903] CHIP:SC: 0xee, 0xf0, 0x09, 0xd2, 0xac, 0x39, 0xe7, 0x2c, [1650657980.912245][3898:3903] CHIP:SC: Including MRP parameters [1650657980.912364][3898:3903] CHIP:IN: Prepared unauthenticated message 0xaaaae8812d38 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 24667i with MessageCounter:1192944059. [1650657980.912445][3898:3903] CHIP:IN: Sending unauthenticated msg 0xaaaae8812d38 with MessageCounter:1192944059 to 0x0000000000000000 at monotonic time: 0000000000C7C01F msec [1650657980.912727][3898:3903] CHIP:SC: Sent Sigma1 msg [1650657980.912785][3898:3903] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 2 --> 3 [1650657980.912843][3898:3903] CHIP:DIS: Discovery does not require any more timeouts [1650657980.914129][3898:3903] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1850391415 on exchange 24667i [1650657980.914198][3898:3903] CHIP:EM: Found matching exchange: 24667i, Delegate: 0xffff880015e0 [1650657980.914269][3898:3903] CHIP:EM: Rxd Ack; Removing MessageCounter:1192944059 from Retrans Table on exchange 24667i [1650657980.914321][3898:3903] CHIP:EM: Removed CHIP MessageCounter:1192944059 from RetransTable on exchange 24667i [1650657980.914404][3898:3903] CHIP:SC: Received error (protocol code 2) during pairing process. ../../../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/CASESession.cpp:1479: CHIP Error 0x00000054: Invalid CASE parameter [1650657980.914551][3898:3903] CHIP:CTL: OperationalDeviceProxy[0BA7B4D5E28EA581:00000000000004D2]: State change 3 --> 2 [1650657980.914640][3898:3903] CHIP:-: ../../../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/CASESession.cpp:1479: CHIP Error 0x00000054: Invalid CASE parameter at ../../../examples/chip-tool/commands/clusters/ModelCommand.cpp:53 [1650657980.914732][3898:3903] CHIP:EM: Sending Standalone Ack for MessageCounter:1850391415 on exchange 24667i [1650657980.914810][3898:3903] CHIP:IN: Prepared unauthenticated message 0xffff8fffd9a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 24667i with MessageCounter:1192944060. [1650657980.914882][3898:3903] CHIP:IN: Sending unauthenticated msg 0xffff8fffd9a8 with MessageCounter:1192944060 to 0x0000000000000000 at monotonic time: 0000000000C7C021 msec [1650657980.915052][3898:3903] CHIP:EM: Flushed pending ack for MessageCounter:1850391415 on exchange 24667i [1650657980.915391][3898:3898] CHIP:CTL: Shutting down the commissioner [1650657980.915609][3898:3898] CHIP:CTL: Shutting down the controller [1650657980.915701][3898:3898] CHIP:CTL: Shutting down the commissioner [1650657980.915887][3898:3898] CHIP:CTL: Shutting down the controller [1650657980.915948][3898:3898] CHIP:IN: Expiring all connections for fabric 1!! [1650657980.916044][3898:3898] CHIP:CTL: Shutting down the commissioner [1650657980.916224][3898:3898] CHIP:CTL: Shutting down the controller [1650657980.916273][3898:3898] CHIP:IN: Expiring all connections for fabric 2!! [1650657980.916361][3898:3898] CHIP:CTL: Shutting down the commissioner [1650657980.916546][3898:3898] CHIP:CTL: Shutting down the controller [1650657980.916597][3898:3898] CHIP:IN: Expiring all connections for fabric 3!! [1650657980.916678][3898:3898] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650657980.919223][3898:3898] CHIP:DMG: IM WH moving to [Uninitialized] [1650657980.919441][3898:3898] CHIP:DMG: IM WH moving to [Uninitialized] [1650657980.919492][3898:3898] CHIP:DMG: IM WH moving to [Uninitialized] [1650657980.919536][3898:3898] CHIP:DMG: IM WH moving to [Uninitialized] [1650657980.919582][3898:3898] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650657980.919803][3898:3898] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650657980.920220][3898:3898] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YlpAsT) [1650657980.921259][3898:3898] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650657980.921368][3898:3898] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650657980.921406][3898:3898] CHIP:DL: Inet Layer shutdown [1650657980.921439][3898:3898] CHIP:DL: BLE shutdown [1650657980.921471][3898:3898] CHIP:DL: System Layer shutdown [1650657980.921764][3898:3898] CHIP:TOO: Run command failure: ../../../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/CASESession.cpp:1479: CHIP Error 0x00000054: Invalid CASE parameter ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 1234 1 [1650658780.595136][3936:3936] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650658780.595390][3936:3936] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650658780.595832][3936:3936] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650658780.595996][3936:3936] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650658780.596125][3936:3936] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650658780.596484][3936:3936] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-oRli7g) [1650658780.597218][3936:3936] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650658780.597275][3936:3936] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5) [1650658780.598198][3936:3936] CHIP:DL: Got Ethernet interface: eth0 [1650658780.599017][3936:3936] CHIP:DL: Found the primary Ethernet interface:eth0 [1650658780.599845][3936:3936] CHIP:DL: Got WiFi interface: wlan0 [1650658780.599936][3936:3936] CHIP:DL: Failed to reset WiFi statistic counts [1650658780.600060][3936:3936] CHIP:IN: UDP::Init bind&listen port=0 [1650658780.600246][3936:3936] CHIP:IN: UDP::Init bound to port=48886 [1650658780.600280][3936:3936] CHIP:IN: UDP::Init bind&listen port=0 [1650658780.600413][3936:3936] CHIP:IN: UDP::Init bound to port=40538 [1650658780.600444][3936:3936] CHIP:IN: BLEBase::Init - setting/overriding transport [1650658780.600472][3936:3936] CHIP:IN: TransportMgr initialized [1650658780.600529][3936:3936] CHIP:DIS: Init fabric pairing table with server storage [1650658780.600707][3936:3936] CHIP:IN: Loading from storage for fabric index 1 [1650658780.603679][3936:3936] CHIP:IN: Loading from storage for fabric index 2 [1650658780.604396][3936:3936] CHIP:IN: Loading from storage for fabric index 3 [1650658780.605108][3936:3936] CHIP:DIS: Add fabric pairing table delegate [1650658780.605426][3936:3936] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-9zZtMA) [1650658780.606120][3936:3936] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650658780.606185][3936:3936] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 5000 (0x1388) [1650658780.609414][3936:3936] CHIP:ZCL: Using ZAP configuration... [1650658780.612601][3936:3936] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.619837][3936:3936] CHIP:DL: MDNS failed to join multicast group on vethf98e81b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.621687][3936:3936] CHIP:DL: MDNS failed to join multicast group on veth49716b3 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.623428][3936:3936] CHIP:DL: MDNS failed to join multicast group on veth817a68d for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.625236][3936:3936] CHIP:DL: MDNS failed to join multicast group on veth4ef2089 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.626974][3936:3936] CHIP:DL: MDNS failed to join multicast group on vethb5a3c32 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650658780.627353][3936:3936] CHIP:CTL: System State Initialized... [1650658780.627443][3936:3936] CHIP:CTL: Setting attestation nonce to random value [1650658780.627534][3936:3936] CHIP:CTL: Setting CSR nonce to random value [1650658780.627615][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.627736][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.627771][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.627868][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.627893][3936:3936] CHIP:IN: TransportMgr initialized [1650658780.627948][3936:3936] CHIP:CTL: Setting attestation nonce to random value [1650658780.628009][3936:3936] CHIP:CTL: Setting CSR nonce to random value [1650658780.628921][3936:3936] CHIP:CTL: Generating NOC [1650658780.629886][3936:3936] CHIP:DIS: Verifying the received credentials [1650658780.631625][3936:3936] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650658780.631658][3936:3936] CHIP:DIS: Assigned compressed fabric ID: 0x0BA7B4D5E28EA581, node ID: 0x000000000001B669 [1650658780.631682][3936:3936] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0BA7B4D5E28EA581 [1650658780.631723][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.631872][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.631908][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.632013][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.632037][3936:3936] CHIP:IN: TransportMgr initialized [1650658780.632142][3936:3936] CHIP:CTL: Setting attestation nonce to random value [1650658780.632200][3936:3936] CHIP:CTL: Setting CSR nonce to random value [1650658780.633037][3936:3936] CHIP:CTL: Generating NOC [1650658780.633911][3936:3936] CHIP:DIS: Verifying the received credentials [1650658780.635611][3936:3936] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650658780.635644][3936:3936] CHIP:DIS: Assigned compressed fabric ID: 0xC1CCD686519F7E0B, node ID: 0x000000000001B669 [1650658780.635668][3936:3936] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xC1CCD686519F7E0B [1650658780.635707][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.635852][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.635887][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.635985][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.636009][3936:3936] CHIP:IN: TransportMgr initialized [1650658780.636120][3936:3936] CHIP:CTL: Setting attestation nonce to random value [1650658780.636177][3936:3936] CHIP:CTL: Setting CSR nonce to random value [1650658780.637570][3936:3936] CHIP:CTL: Generating NOC [1650658780.638511][3936:3936] CHIP:DIS: Verifying the received credentials [1650658780.640248][3936:3936] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650658780.640282][3936:3936] CHIP:DIS: Assigned compressed fabric ID: 0xBA470D9A0C420C73, node ID: 0x000000000001B669 [1650658780.640307][3936:3936] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xBA470D9A0C420C73 [1650658780.640349][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.640499][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.640537][3936:3936] CHIP:IN: UDP::Init bind&listen port=5550 [1650658780.640639][3936:3936] CHIP:IN: UDP::Init bound to port=5550 [1650658780.640663][3936:3936] CHIP:IN: TransportMgr initialized [1650658780.680522][3936:3941] CHIP:DL: CHIP task running [1650658780.680708][3936:3941] CHIP:TOO: Sending command to node 0x4d2 [1650658780.680755][3936:3941] CHIP:CSM: FindOrEstablishSession: PeerId = 0BA7B4D5E28EA581:00000000000004D2 [1650658780.680789][3936:3941] CHIP:CSM: FindOrEstablishSession: No existing session found [1650658780.681575][3936:3941] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650658780.681849][3936:3941] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650658780.682101][3936:3941] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650658780.682342][3936:3941] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650658780.881396][3936:3941] CHIP:DIS: Checking node lookup status after 201 ms [1650658795.681138][3936:3941] CHIP:DIS: Checking node lookup status after 15001 ms [1650658795.681262][3936:3941] CHIP:DIS: Operational discovery failed for 0x00000000000004D2: ../../../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout [1650658795.681339][3936:3941] CHIP:-: ../../../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout at ../../../examples/chip-tool/commands/clusters/ModelCommand.cpp:53 [1650658795.681441][3936:3941] CHIP:DIS: Discovery does not require any more timeouts [1650658795.681749][3936:3936] CHIP:CTL: Shutting down the commissioner [1650658795.682027][3936:3936] CHIP:CTL: Shutting down the controller [1650658795.682124][3936:3936] CHIP:CTL: Shutting down the commissioner [1650658795.682313][3936:3936] CHIP:CTL: Shutting down the controller [1650658795.682405][3936:3936] CHIP:IN: Expiring all connections for fabric 1!! [1650658795.682504][3936:3936] CHIP:CTL: Shutting down the commissioner [1650658795.682719][3936:3936] CHIP:CTL: Shutting down the controller [1650658795.682781][3936:3936] CHIP:IN: Expiring all connections for fabric 2!! [1650658795.682861][3936:3936] CHIP:CTL: Shutting down the commissioner [1650658795.683078][3936:3936] CHIP:CTL: Shutting down the controller [1650658795.683157][3936:3936] CHIP:IN: Expiring all connections for fabric 3!! [1650658795.683229][3936:3936] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650658795.686101][3936:3936] CHIP:DMG: IM WH moving to [Uninitialized] [1650658795.686168][3936:3936] CHIP:DMG: IM WH moving to [Uninitialized] [1650658795.686221][3936:3936] CHIP:DMG: IM WH moving to [Uninitialized] [1650658795.686273][3936:3936] CHIP:DMG: IM WH moving to [Uninitialized] [1650658795.686325][3936:3936] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650658795.686512][3936:3936] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650658795.686942][3936:3936] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2movvO) [1650658795.688130][3936:3936] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650658795.688275][3936:3936] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650658795.688351][3936:3936] CHIP:DL: Inet Layer shutdown [1650658795.688407][3936:3936] CHIP:DL: BLE shutdown [1650658795.688464][3936:3936] CHIP:DL: System Layer shutdown [1650658795.688720][3936:3936] CHIP:TOO: Run command failure: ../../../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout