ubuntu@matter-7:~/jan31_cntrl/connectedhomeip/examples/chip-tool/out$ ./chip-tool pairing ble-wifi 1 zigbeehome matter123 20202021 3840 [1643607810.556101][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-krzeyI) [1643607810.556331][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1643607810.556541][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_config.ini-kS8Jfh) [1643607810.556661][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1643607810.556829][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ehBQRD) [1643607810.556944][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1643607810.557133][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Mt7D48) [1643607810.557625][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1643607810.557674][8535:8535] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1643607810.557804][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ty8ihh) [1643607810.559395][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1643607810.559462][8535:8535] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1643607810.559659][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-zTYUUv) [1643607810.560197][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1643607810.560247][8535:8535] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1643607810.560380][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_config.ini-85981A) [1643607810.560715][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1643607810.560757][8535:8535] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1643607810.560960][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_config.ini-SCI4fO) [1643607810.561829][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1643607810.561881][8535:8535] CHIP:DL: NVS set: chip-config/location-capability = 0 (0x0) [1643607810.562867][8535:8535] CHIP:DL: Got Ethernet interface: eth0 [1643607810.563451][8535:8535] CHIP:DL: Found the primary Ethernet interface:eth0 [1643607810.564038][8535:8535] CHIP:DL: Got WiFi interface: wlan0 [1643607810.564113][8535:8535] CHIP:DL: Failed to reset WiFi statistic counts [1643607810.564186][8535:8535] CHIP:IN: UDP::Init bind&listen port=5542 [1643607810.564300][8535:8535] CHIP:IN: UDP::Init bound to port=5542 [1643607810.564327][8535:8535] CHIP:IN: UDP::Init bind&listen port=5542 [1643607810.564415][8535:8535] CHIP:IN: UDP::Init bound to port=5542 [1643607810.564440][8535:8535] CHIP:IN: TransportMgr initialized [1643607810.564479][8535:8535] CHIP:DIS: Init fabric pairing table with server storage [1643607810.564759][8535:8535] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-9Wh0FF) [1643607810.565401][8535:8535] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1643607810.565461][8535:8535] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) [1643607810.565615][8535:8535] CHIP:ZCL: Using ZAP configuration... [1643607810.571892][8535:8535] CHIP:DL: MDNS failed to join multicast group on vethb317d35 for address type IPv4: ../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1643607810.573633][8535:8535] CHIP:DL: MDNS failed to join multicast group on vetheb1d234 for address type IPv4: ../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1643607810.575437][8535:8535] CHIP:DL: MDNS failed to join multicast group on veth6e368fe for address type IPv4: ../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1643607810.576918][8535:8535] CHIP:DL: MDNS failed to join multicast group on veth0660e58 for address type IPv4: ../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1643607810.578339][8535:8535] CHIP:DL: MDNS failed to join multicast group on veth1a92335 for address type IPv4: ../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1643607810.578626][8535:8535] CHIP:CTL: System State Initialized... [1643607810.578983][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.579087][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.579114][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.579211][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.579235][8535:8535] CHIP:IN: TransportMgr initialized [1643607810.583815][8535:8535] CHIP:CTL: Generating NOC [1643607810.584189][8535:8535] CHIP:CTL: Generating ICAC [1643607810.585197][8535:8535] CHIP:CTL: Generating RCAC [1643607810.587206][8535:8535] CHIP:DIS: Verifying the received credentials [1643607810.589048][8535:8535] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000001 and root pubkey [1643607810.589092][8535:8535] CHIP:IN: 0x04, 0x3f, 0x61, 0x13, 0x24, 0xb7, 0xab, 0xa8, [1643607810.589116][8535:8535] CHIP:IN: 0xcd, 0xd2, 0x6e, 0xae, 0xe1, 0x87, 0x66, 0xe7, [1643607810.589140][8535:8535] CHIP:IN: 0xcb, 0xbd, 0x07, 0x26, 0x54, 0x27, 0x8e, 0xe3, [1643607810.589163][8535:8535] CHIP:IN: 0x63, 0xc0, 0x47, 0x16, 0x23, 0xaf, 0xb2, 0x9e, [1643607810.589186][8535:8535] CHIP:IN: 0xbb, 0x0f, 0x8f, 0xff, 0x91, 0xa1, 0xf8, 0xb2, [1643607810.589209][8535:8535] CHIP:IN: 0xab, 0xa4, 0x12, 0xdc, 0xe7, 0xba, 0x14, 0x83, [1643607810.589231][8535:8535] CHIP:IN: 0x89, 0x83, 0xf6, 0x5f, 0x52, 0x67, 0x34, 0x43, [1643607810.589254][8535:8535] CHIP:IN: 0xcb, 0x6a, 0xf9, 0x1c, 0x7a, 0xa1, 0x32, 0x85, [1643607810.589274][8535:8535] CHIP:IN: 0x43, [1643607810.589332][8535:8535] CHIP:IN: Generated compressed fabric ID [1643607810.589359][8535:8535] CHIP:IN: 0x73, 0x3b, 0x2a, 0x7b, 0x83, 0x67, 0xd8, 0x83, [1643607810.589386][8535:8535] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1643607810.589408][8535:8535] CHIP:DIS: Assigned compressed fabric ID: 0x733B2A7B8367D883, node ID: 0x000000000001B669 [1643607810.590167][8535:8535] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x733B2A7B8367D883 [1643607810.590244][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.590374][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.590401][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.590491][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.590514][8535:8535] CHIP:IN: TransportMgr initialized [1643607810.591846][8535:8535] CHIP:CTL: Generating NOC [1643607810.592948][8535:8535] CHIP:DIS: Verifying the received credentials [1643607810.594622][8535:8535] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000002 and root pubkey [1643607810.594711][8535:8535] CHIP:IN: 0x04, 0x3f, 0x61, 0x13, 0x24, 0xb7, 0xab, 0xa8, [1643607810.594737][8535:8535] CHIP:IN: 0xcd, 0xd2, 0x6e, 0xae, 0xe1, 0x87, 0x66, 0xe7, [1643607810.594760][8535:8535] CHIP:IN: 0xcb, 0xbd, 0x07, 0x26, 0x54, 0x27, 0x8e, 0xe3, [1643607810.594784][8535:8535] CHIP:IN: 0x63, 0xc0, 0x47, 0x16, 0x23, 0xaf, 0xb2, 0x9e, [1643607810.594806][8535:8535] CHIP:IN: 0xbb, 0x0f, 0x8f, 0xff, 0x91, 0xa1, 0xf8, 0xb2, [1643607810.594829][8535:8535] CHIP:IN: 0xab, 0xa4, 0x12, 0xdc, 0xe7, 0xba, 0x14, 0x83, [1643607810.594851][8535:8535] CHIP:IN: 0x89, 0x83, 0xf6, 0x5f, 0x52, 0x67, 0x34, 0x43, [1643607810.594874][8535:8535] CHIP:IN: 0xcb, 0x6a, 0xf9, 0x1c, 0x7a, 0xa1, 0x32, 0x85, [1643607810.594894][8535:8535] CHIP:IN: 0x43, [1643607810.594949][8535:8535] CHIP:IN: Generated compressed fabric ID [1643607810.594975][8535:8535] CHIP:IN: 0xde, 0xdb, 0x1f, 0x3f, 0x5b, 0x3f, 0xdd, 0xc8, [1643607810.595003][8535:8535] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1643607810.595026][8535:8535] CHIP:DIS: Assigned compressed fabric ID: 0xDEDB1F3F5B3FDDC8, node ID: 0x000000000001B669 [1643607810.595894][8535:8535] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xDEDB1F3F5B3FDDC8 [1643607810.595972][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.596098][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.596124][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.596215][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.596238][8535:8535] CHIP:IN: TransportMgr initialized [1643607810.597503][8535:8535] CHIP:CTL: Generating NOC [1643607810.598614][8535:8535] CHIP:DIS: Verifying the received credentials [1643607810.600321][8535:8535] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000003 and root pubkey [1643607810.600362][8535:8535] CHIP:IN: 0x04, 0x3f, 0x61, 0x13, 0x24, 0xb7, 0xab, 0xa8, [1643607810.600386][8535:8535] CHIP:IN: 0xcd, 0xd2, 0x6e, 0xae, 0xe1, 0x87, 0x66, 0xe7, [1643607810.600410][8535:8535] CHIP:IN: 0xcb, 0xbd, 0x07, 0x26, 0x54, 0x27, 0x8e, 0xe3, [1643607810.600434][8535:8535] CHIP:IN: 0x63, 0xc0, 0x47, 0x16, 0x23, 0xaf, 0xb2, 0x9e, [1643607810.600457][8535:8535] CHIP:IN: 0xbb, 0x0f, 0x8f, 0xff, 0x91, 0xa1, 0xf8, 0xb2, [1643607810.600480][8535:8535] CHIP:IN: 0xab, 0xa4, 0x12, 0xdc, 0xe7, 0xba, 0x14, 0x83, [1643607810.600502][8535:8535] CHIP:IN: 0x89, 0x83, 0xf6, 0x5f, 0x52, 0x67, 0x34, 0x43, [1643607810.600524][8535:8535] CHIP:IN: 0xcb, 0x6a, 0xf9, 0x1c, 0x7a, 0xa1, 0x32, 0x85, [1643607810.600545][8535:8535] CHIP:IN: 0x43, [1643607810.600599][8535:8535] CHIP:IN: Generated compressed fabric ID [1643607810.600625][8535:8535] CHIP:IN: 0x85, 0x04, 0x8e, 0x25, 0x07, 0x74, 0x00, 0x0b, [1643607810.600654][8535:8535] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1643607810.600676][8535:8535] CHIP:DIS: Assigned compressed fabric ID: 0x85048E250774000B, node ID: 0x000000000001B669 [1643607810.601576][8535:8535] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x85048E250774000B [1643607810.601652][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.601785][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.601811][8535:8535] CHIP:IN: UDP::Init bind&listen port=5550 [1643607810.601905][8535:8535] CHIP:IN: UDP::Init bound to port=5550 [1643607810.601928][8535:8535] CHIP:IN: TransportMgr initialized [1643607810.602231][8535:8540] CHIP:DL: CHIP task running [1643607810.602552][8535:8540] CHIP:SC: Assigned local session key ID 1 [1643607810.602722][8535:8540] CHIP:SC: Including MRP parameters in PBKDF param request [1643607810.602849][8535:8540] CHIP:IN: Prepared unauthenticated message 0xffff81d33d58 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 3081i with MessageCounter:4138488198. [1643607810.602905][8535:8540] CHIP:IN: Sending unauthenticated msg 0xffff81d33d58 with MessageCounter:4138488198 to 0x0000000000000000 at monotonic time: 9822524 msec [1643607810.602945][8535:8540] CHIP:IN: Message appended to BLE send queue [1643607810.602970][8535:8540] CHIP:SC: Sent PBKDF param request [1643607810.602994][8535:8540] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1643607810.603032][8535:8540] CHIP:CTL: Setting wifi credentials from parameters [1643607810.603054][8535:8540] CHIP:CTL: Setting attestation nonce to random value [1643607810.603111][8535:8540] CHIP:CTL: Setting CSR nonce to random value [1643607810.603420][8535:8541] CHIP:DL: TRACE: Bluez mainloop starting Thread [1643607810.603592][8535:8538] CHIP:DL: TRACE: Bus acquired for name C-2157 [1643607810.610799][8535:8540] CHIP:DL: PlatformBlueZInit init success [1643607810.616000][8535:8538] CHIP:BLE: BLE removing known devices. [1643607810.617672][8535:8538] CHIP:BLE: BLE initiating scan. [1643607810.655285][8535:8538] CHIP:BLE: Device 68:72:C3:7F:53:63 does not look like a CHIP device. [1643607810.657353][8535:8538] CHIP:BLE: Device 0C:29:17:C9:69:94 does not look like a CHIP device. [1643607810.666840][8535:8538] CHIP:BLE: Device 38:68:A4:97:EB:AC does not look like a CHIP device. [1643607810.674800][8535:8538] CHIP:BLE: Device 05:50:9B:41:C5:89 does not look like a CHIP device. [1643607811.346205][8535:8538] CHIP:BLE: New device scanned: E4:5F:01:0F:27:56 [1643607811.346303][8535:8538] CHIP:BLE: Device discriminator match. Attempting to connect. [1643607811.350867][8535:8538] CHIP:BLE: Scan complete notification without an active scan. [1643607815.373620][8535:8538] CHIP:DL: ConnectDevice complete [1643607816.928385][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928444][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928472][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928496][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928522][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928545][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928575][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928598][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928624][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928647][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928672][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928695][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928728][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928751][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928781][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928804][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928830][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928853][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928878][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service0006 [1643607816.928901][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928929][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928952][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.928979][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.929001][8535:8538] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_0F_27_56/service001f [1643607816.929030][8535:8538] CHIP:DL: New BLE connection 0xffff7803ea30, device E4:5F:01:0F:27:56, path /org/bluez/hci0/dev_E4_5F_01_0F_27_56 [1643607816.929229][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1643607816.929267][8535:8540] CHIP:IN: BleConnectionComplete: endPoint 0xaaaade074058 [1643607817.224993][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607817.323422][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1643607817.323513][8535:8540] CHIP:BLE: subscribe complete, ep = 0xaaaade074058 [1643607817.323832][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607817.324165][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607817.324236][8535:8540] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1643607817.324293][8535:8540] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1643607817.324344][8535:8540] CHIP:BLE: local and remote recv window size = 6 [1643607817.324542][8535:8540] CHIP:IN: BLE EndPoint 0xaaaade074058 Connection Complete [1643607817.567056][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607817.569649][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607817.569965][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607817.570257][8535:8540] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:3178351438 on exchange 3081i [1643607817.570337][8535:8540] CHIP:EM: Found matching exchange: 3081i, Delegate: 0xffff81d9b868 [1643607817.570427][8535:8540] CHIP:SC: Received PBKDF param response [1643607817.570521][8535:8540] CHIP:SC: Peer assigned session ID 1 [1643607817.570598][8535:8540] CHIP:SC: Found MRP parameters in the message [1643607817.573817][8535:8540] CHIP:IN: Prepared unauthenticated message 0xffff81d338d8 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 3081i with MessageCounter:4138488199. [1643607817.574052][8535:8540] CHIP:IN: Sending unauthenticated msg 0xffff81d338d8 with MessageCounter:4138488199 to 0x0000000000000000 at monotonic time: 9829495 msec [1643607817.574253][8535:8540] CHIP:SC: Sent spake2p msg1 [1643607817.713259][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607817.715922][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607817.716262][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607817.716552][8535:8540] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:3178351439 on exchange 3081i [1643607817.716630][8535:8540] CHIP:EM: Found matching exchange: 3081i, Delegate: 0xffff81d9b868 [1643607817.716719][8535:8540] CHIP:SC: Received spake2p msg2 [1643607817.719802][8535:8540] CHIP:IN: Prepared unauthenticated message 0xffff81d339c8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 3081i with MessageCounter:4138488200. [1643607817.719886][8535:8540] CHIP:IN: Sending unauthenticated msg 0xffff81d339c8 with MessageCounter:4138488200 to 0x0000000000000000 at monotonic time: 9829641 msec [1643607817.720035][8535:8540] CHIP:SC: Sent spake2p msg3 [1643607817.810717][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607817.811848][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607817.812206][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607817.812498][8535:8540] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3178351440 on exchange 3081i [1643607817.812577][8535:8540] CHIP:EM: Found matching exchange: 3081i, Delegate: 0xffff81d9b868 [1643607817.812684][8535:8540] CHIP:IN: New secure session created for device 0x0000000000000001, LSID:1 PSID:1! [1643607817.812919][8535:8540] CHIP:CTL: Remote device completed SPAKE2+ handshake [1643607817.812988][8535:8540] CHIP:CTL: Arming failsafe [1643607817.813235][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607817.813404][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607817.813627][8535:8540] CHIP:IN: Prepared secure message 0xffff81d33288 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3082i with MessageCounter:5750926. [1643607817.813719][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d33288 with MessageCounter:5750926 to 0x0000000000000001 (1) at monotonic time: 9829735 msec [1643607817.813906][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607818.005942][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607818.007632][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.007996][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.008341][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197165 on exchange 3082i [1643607818.008424][8535:8540] CHIP:EM: Found matching exchange: 3082i, Delegate: 0xffff6c002190 [1643607818.008514][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607818.008618][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607818.008680][8535:8540] CHIP:DMG: { [1643607818.008738][8535:8540] CHIP:DMG: suppressResponse = false, [1643607818.008802][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607818.008880][8535:8540] CHIP:DMG: [ [1643607818.008941][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607818.009031][8535:8540] CHIP:DMG: { [1643607818.009100][8535:8540] CHIP:DMG: CommandDataIB = [1643607818.009185][8535:8540] CHIP:DMG: { [1643607818.009257][8535:8540] CHIP:DMG: CommandPathIB = [1643607818.009340][8535:8540] CHIP:DMG: { [1643607818.009422][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607818.009508][8535:8540] CHIP:DMG: ClusterId = 0x30, [1643607818.009595][8535:8540] CHIP:DMG: CommandId = 0x1, [1643607818.009675][8535:8540] CHIP:DMG: }, [1643607818.009762][8535:8540] CHIP:DMG: [1643607818.009835][8535:8540] CHIP:DMG: CommandData = [1643607818.009916][8535:8540] CHIP:DMG: { [1643607818.010000][8535:8540] CHIP:DMG: 0x0 = 0, [1643607818.010099][8535:8540] CHIP:DMG: 0x1 = "", [1643607818.010185][8535:8540] CHIP:DMG: }, [1643607818.010254][8535:8540] CHIP:DMG: }, [1643607818.010339][8535:8540] CHIP:DMG: [1643607818.010408][8535:8540] CHIP:DMG: }, [1643607818.010490][8535:8540] CHIP:DMG: [1643607818.010549][8535:8540] CHIP:DMG: ], [1643607818.010626][8535:8540] CHIP:DMG: [1643607818.010732][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607818.010792][8535:8540] CHIP:DMG: }, [1643607818.010940][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1643607818.011210][8535:8540] CHIP:CTL: Received ArmFailSafe response [1643607818.011279][8535:8540] CHIP:CTL: Sending request for network cluster feature map [1643607818.011667][8535:8540] CHIP:DMG: SendReadRequest ReadClient[0xffff78032000]: Sending Read Request [1643607818.011922][8535:8540] CHIP:IN: Prepared secure message 0xffff81d327f8 to 0x0000000000000001 (1) of type 0x2 and protocolId (0, 1) on exchange 3083i with MessageCounter:5750927. [1643607818.012016][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d327f8 with MessageCounter:5750927 to 0x0000000000000001 (1) at monotonic time: 9829933 msec [1643607818.012217][8535:8540] CHIP:DMG: MoveToState ReadClient[0xffff78032000]: Moving to [AwaitingIn] [1643607818.012331][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607818.103311][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607818.105266][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.105609][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.105931][8535:8540] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:5197166 on exchange 3083i [1643607818.106010][8535:8540] CHIP:EM: Found matching exchange: 3083i, Delegate: 0xffff78032000 [1643607818.106139][8535:8540] CHIP:DMG: ReportDataMessage = [1643607818.106204][8535:8540] CHIP:DMG: { [1643607818.106258][8535:8540] CHIP:DMG: AttributeReportIBs = [1643607818.106334][8535:8540] CHIP:DMG: [ [1643607818.106395][8535:8540] CHIP:DMG: AttributeReportIB = [1643607818.106481][8535:8540] CHIP:DMG: { [1643607818.106545][8535:8540] CHIP:DMG: AttributeDataIB = [1643607818.106631][8535:8540] CHIP:DMG: { [1643607818.106765][8535:8540] CHIP:DMG: DataVersion = 0x0, [1643607818.106843][8535:8540] CHIP:DMG: AttributePathIB = [1643607818.106924][8535:8540] CHIP:DMG: { [1643607818.107016][8535:8540] CHIP:DMG: Endpoint = 0x0, [1643607818.107104][8535:8540] CHIP:DMG: Cluster = 0x31, [1643607818.107200][8535:8540] CHIP:DMG: Attribute = 0x0000_FFFC, [1643607818.107284][8535:8540] CHIP:DMG: } [1643607818.107378][8535:8540] CHIP:DMG: [1643607818.107456][8535:8540] CHIP:DMG: Data = 2, [1643607818.107545][8535:8540] CHIP:DMG: }, [1643607818.107630][8535:8540] CHIP:DMG: [1643607818.107697][8535:8540] CHIP:DMG: }, [1643607818.107772][8535:8540] CHIP:DMG: [1643607818.107830][8535:8540] CHIP:DMG: ], [1643607818.107905][8535:8540] CHIP:DMG: [1643607818.107965][8535:8540] CHIP:DMG: SuppressResponse = true, [1643607818.108028][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607818.108085][8535:8540] CHIP:DMG: } [1643607818.108339][8535:8540] CHIP:CTL: Setting Regulatory Config [1643607818.108509][8535:8540] CHIP:CTL: Unable to find country code, defaulting to WW [1643607818.108637][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607818.108715][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607818.108931][8535:8540] CHIP:IN: Prepared secure message 0xffff81d328c8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3084i with MessageCounter:5750928. [1643607818.109021][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d328c8 with MessageCounter:5750928 to 0x0000000000000001 (1) at monotonic time: 9830030 msec [1643607818.109214][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607818.249612][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607818.251357][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.251722][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.252053][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197167 on exchange 3084i [1643607818.252134][8535:8540] CHIP:EM: Found matching exchange: 3084i, Delegate: 0xffff6c002190 [1643607818.252224][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607818.252325][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607818.252387][8535:8540] CHIP:DMG: { [1643607818.252446][8535:8540] CHIP:DMG: suppressResponse = false, [1643607818.252511][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607818.252590][8535:8540] CHIP:DMG: [ [1643607818.252650][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607818.252735][8535:8540] CHIP:DMG: { [1643607818.252806][8535:8540] CHIP:DMG: CommandDataIB = [1643607818.252885][8535:8540] CHIP:DMG: { [1643607818.252966][8535:8540] CHIP:DMG: CommandPathIB = [1643607818.253048][8535:8540] CHIP:DMG: { [1643607818.253131][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607818.253225][8535:8540] CHIP:DMG: ClusterId = 0x30, [1643607818.253315][8535:8540] CHIP:DMG: CommandId = 0x3, [1643607818.253397][8535:8540] CHIP:DMG: }, [1643607818.253475][8535:8540] CHIP:DMG: [1643607818.253547][8535:8540] CHIP:DMG: CommandData = [1643607818.253628][8535:8540] CHIP:DMG: { [1643607818.253713][8535:8540] CHIP:DMG: 0x0 = 0, [1643607818.253811][8535:8540] CHIP:DMG: 0x1 = "", [1643607818.253896][8535:8540] CHIP:DMG: }, [1643607818.253973][8535:8540] CHIP:DMG: }, [1643607818.254057][8535:8540] CHIP:DMG: [1643607818.254124][8535:8540] CHIP:DMG: }, [1643607818.254207][8535:8540] CHIP:DMG: [1643607818.254265][8535:8540] CHIP:DMG: ], [1643607818.254341][8535:8540] CHIP:DMG: [1643607818.254400][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607818.254459][8535:8540] CHIP:DMG: }, [1643607818.254603][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1643607818.254749][8535:8540] CHIP:CTL: Received SetRegulatoryConfig response [1643607818.254818][8535:8540] CHIP:CTL: Sending request for PAI certificate [1643607818.254870][8535:8540] CHIP:CTL: Sending Certificate Chain request to 0xffff81d9b808 device [1643607818.254991][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607818.255169][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607818.255394][8535:8540] CHIP:IN: Prepared secure message 0xffff81d32948 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3085i with MessageCounter:5750929. [1643607818.255485][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d32948 with MessageCounter:5750929 to 0x0000000000000001 (1) at monotonic time: 9830176 msec [1643607818.255683][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607818.255793][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607818.346982][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607818.394922][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.395284][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.495901][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.496284][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.591463][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.591840][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.592292][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197168 on exchange 3085i [1643607818.592370][8535:8540] CHIP:EM: Found matching exchange: 3085i, Delegate: 0xffff6c00dd90 [1643607818.592464][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607818.592565][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607818.592626][8535:8540] CHIP:DMG: { [1643607818.592685][8535:8540] CHIP:DMG: suppressResponse = false, [1643607818.592752][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607818.592831][8535:8540] CHIP:DMG: [ [1643607818.592891][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607818.592976][8535:8540] CHIP:DMG: { [1643607818.593045][8535:8540] CHIP:DMG: CommandDataIB = [1643607818.593124][8535:8540] CHIP:DMG: { [1643607818.593203][8535:8540] CHIP:DMG: CommandPathIB = [1643607818.593273][8535:8540] CHIP:DMG: { [1643607818.593352][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607818.593431][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607818.593504][8535:8540] CHIP:DMG: CommandId = 0x3, [1643607818.593571][8535:8540] CHIP:DMG: }, [1643607818.593652][8535:8540] CHIP:DMG: [1643607818.593722][8535:8540] CHIP:DMG: CommandData = [1643607818.593792][8535:8540] CHIP:DMG: { [1643607818.593862][8535:8540] CHIP:DMG: 0x0 = [ [1643607818.593932][8535:8540] CHIP:DMG: ... (byte string too long) ... [1643607818.594011][8535:8540] CHIP:DMG: ] [1643607818.594085][8535:8540] CHIP:DMG: }, [1643607818.594157][8535:8540] CHIP:DMG: }, [1643607818.594231][8535:8540] CHIP:DMG: [1643607818.594289][8535:8540] CHIP:DMG: }, [1643607818.594358][8535:8540] CHIP:DMG: [1643607818.594409][8535:8540] CHIP:DMG: ], [1643607818.594473][8535:8540] CHIP:DMG: [1643607818.594524][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607818.594573][8535:8540] CHIP:DMG: }, [1643607818.594736][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1643607818.594809][8535:8540] CHIP:CTL: Received certificate chain from the device [1643607818.594873][8535:8540] CHIP:CTL: Sending request for DAC certificate [1643607818.594918][8535:8540] CHIP:CTL: Sending Certificate Chain request to 0xffff81d9b808 device [1643607818.595021][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607818.595081][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607818.595270][8535:8540] CHIP:IN: Prepared secure message 0xffff81d328f8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3086i with MessageCounter:5750930. [1643607818.595347][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d328f8 with MessageCounter:5750930 to 0x0000000000000001 (1) at monotonic time: 9830516 msec [1643607818.595515][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607818.595601][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607818.688327][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607818.735663][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.735888][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.837062][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.837425][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.932618][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607818.932976][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607818.933427][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197169 on exchange 3086i [1643607818.933507][8535:8540] CHIP:EM: Found matching exchange: 3086i, Delegate: 0xffff6c002190 [1643607818.933604][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607818.933707][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607818.933768][8535:8540] CHIP:DMG: { [1643607818.933848][8535:8540] CHIP:DMG: suppressResponse = false, [1643607818.933911][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607818.934012][8535:8540] CHIP:DMG: [ [1643607818.934073][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607818.934179][8535:8540] CHIP:DMG: { [1643607818.934244][8535:8540] CHIP:DMG: CommandDataIB = [1643607818.934349][8535:8540] CHIP:DMG: { [1643607818.934424][8535:8540] CHIP:DMG: CommandPathIB = [1643607818.934528][8535:8540] CHIP:DMG: { [1643607818.934636][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607818.934770][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607818.934877][8535:8540] CHIP:DMG: CommandId = 0x3, [1643607818.934965][8535:8540] CHIP:DMG: }, [1643607818.935078][8535:8540] CHIP:DMG: [1643607818.935176][8535:8540] CHIP:DMG: CommandData = [1643607818.935266][8535:8540] CHIP:DMG: { [1643607818.935365][8535:8540] CHIP:DMG: 0x0 = [ [1643607818.935466][8535:8540] CHIP:DMG: ... (byte string too long) ... [1643607818.935563][8535:8540] CHIP:DMG: ] [1643607818.935664][8535:8540] CHIP:DMG: }, [1643607818.935764][8535:8540] CHIP:DMG: }, [1643607818.935860][8535:8540] CHIP:DMG: [1643607818.935947][8535:8540] CHIP:DMG: }, [1643607818.936018][8535:8540] CHIP:DMG: [1643607818.936096][8535:8540] CHIP:DMG: ], [1643607818.936173][8535:8540] CHIP:DMG: [1643607818.936256][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607818.936313][8535:8540] CHIP:DMG: }, [1643607818.936476][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1643607818.936578][8535:8540] CHIP:CTL: Received certificate chain from the device [1643607818.936653][8535:8540] CHIP:CTL: Sending Attestation Request to the device. [1643607818.936707][8535:8540] CHIP:CTL: Sending Attestation request to 0xffff81d9b808 device [1643607818.936842][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607818.936917][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607818.937192][8535:8540] CHIP:IN: Prepared secure message 0xffff81d328b8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3087i with MessageCounter:5750931. [1643607818.937308][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d328b8 with MessageCounter:5750931 to 0x0000000000000001 (1) at monotonic time: 9830858 msec [1643607818.937506][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607818.937601][8535:8540] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1643607818.937687][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607819.029579][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607819.077288][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607819.077590][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607819.177481][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607819.177837][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607819.178266][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197170 on exchange 3087i [1643607819.178342][8535:8540] CHIP:EM: Found matching exchange: 3087i, Delegate: 0xffff6c00dd90 [1643607819.178438][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607819.178541][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607819.178603][8535:8540] CHIP:DMG: { [1643607819.178744][8535:8540] CHIP:DMG: suppressResponse = false, [1643607819.178810][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607819.178891][8535:8540] CHIP:DMG: [ [1643607819.178974][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607819.179065][8535:8540] CHIP:DMG: { [1643607819.179149][8535:8540] CHIP:DMG: CommandDataIB = [1643607819.179225][8535:8540] CHIP:DMG: { [1643607819.179326][8535:8540] CHIP:DMG: CommandPathIB = [1643607819.179431][8535:8540] CHIP:DMG: { [1643607819.179523][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607819.179629][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607819.179735][8535:8540] CHIP:DMG: CommandId = 0x1, [1643607819.179815][8535:8540] CHIP:DMG: }, [1643607819.179930][8535:8540] CHIP:DMG: [1643607819.180022][8535:8540] CHIP:DMG: CommandData = [1643607819.180104][8535:8540] CHIP:DMG: { [1643607819.180210][8535:8540] CHIP:DMG: 0x0 = [ [1643607819.180322][8535:8540] CHIP:DMG: ... (byte string too long) ... [1643607819.180442][8535:8540] CHIP:DMG: ] [1643607819.180517][8535:8540] CHIP:DMG: 0x1 = [ [1643607819.180655][8535:8540] CHIP:DMG: 0xbe, 0xb6, 0x46, 0xf5, 0x86, 0xc0, 0xa9, 0xa5, 0x9b, 0xa7, 0xbd, 0x29, 0x11, 0xd0, 0x7e, 0x98, 0xcc, 0x8a, 0x40, 0x88, 0x79, 0xb1, 0x15, 0xe2, 0xb3, 0x52, 0xe1, 0x89, 0xd, 0xde, 0xdd, 0xfa, 0xde, 0xc7, 0xf4, 0x26, 0xdd, 0x1c, 0x65, 0xe8, 0xbc, 0x96 [1643607819.180774][8535:8540] CHIP:DMG: ] [1643607819.180857][8535:8540] CHIP:DMG: }, [1643607819.180966][8535:8540] CHIP:DMG: }, [1643607819.181063][8535:8540] CHIP:DMG: [1643607819.181153][8535:8540] CHIP:DMG: }, [1643607819.181257][8535:8540] CHIP:DMG: [1643607819.181317][8535:8540] CHIP:DMG: ], [1643607819.181414][8535:8540] CHIP:DMG: [1643607819.181476][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607819.181555][8535:8540] CHIP:DMG: }, [1643607819.181727][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1643607819.181831][8535:8540] CHIP:CTL: Received Attestation Information from the device [1643607819.181983][8535:8540] CHIP:CTL: Verifying attestation [1643607819.190821][8535:8540] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1643607819.190896][8535:8540] CHIP:CTL: Sending OpCSR request to 0xffff81d9b808 device [1643607819.190990][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607819.191033][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607819.191226][8535:8540] CHIP:IN: Prepared secure message 0xffff81d31eb8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3088i with MessageCounter:5750932. [1643607819.191293][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d31eb8 with MessageCounter:5750932 to 0x0000000000000001 (1) at monotonic time: 9831112 msec [1643607819.191446][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607819.191488][8535:8540] CHIP:CTL: Sent OpCSR request, waiting for the CSR [1643607819.191545][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607819.273237][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607819.370059][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607819.370412][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607819.517980][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607819.518238][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607819.518533][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197171 on exchange 3088i [1643607819.518582][8535:8540] CHIP:EM: Found matching exchange: 3088i, Delegate: 0xffff6c002190 [1643607819.518684][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607819.518759][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607819.518797][8535:8540] CHIP:DMG: { [1643607819.518851][8535:8540] CHIP:DMG: suppressResponse = false, [1643607819.518888][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607819.518949][8535:8540] CHIP:DMG: [ [1643607819.518986][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607819.519049][8535:8540] CHIP:DMG: { [1643607819.519095][8535:8540] CHIP:DMG: CommandDataIB = [1643607819.519155][8535:8540] CHIP:DMG: { [1643607819.519199][8535:8540] CHIP:DMG: CommandPathIB = [1643607819.519265][8535:8540] CHIP:DMG: { [1643607819.519329][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607819.519381][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607819.519446][8535:8540] CHIP:DMG: CommandId = 0x5, [1643607819.519507][8535:8540] CHIP:DMG: }, [1643607819.519560][8535:8540] CHIP:DMG: [1643607819.519617][8535:8540] CHIP:DMG: CommandData = [1643607819.519679][8535:8540] CHIP:DMG: { [1643607819.519729][8535:8540] CHIP:DMG: 0x0 = [ [1643607819.519819][8535:8540] CHIP:DMG: 0x15, 0x30, 0x1, 0xcc, 0x30, 0x81, 0xc9, 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 [1643607819.519881][8535:8540] CHIP:DMG: ] [1643607819.519934][8535:8540] CHIP:DMG: 0x1 = [ [1643607819.520005][8535:8540] CHIP:DMG: 0x1a, 0x88, 0x3, 0xa8, 0x3a, 0x11, 0x26, 0xbf, 0x1f, 0x5f, 0x2, 0x8c, 0x7f, 0x4b, 0xca, 0xb, 0x40, 0xb4, 0x74, 0x91, 0xdc, 0x2f, 0x85, 0x39, 0xf7, 0xd6, 0x9d, 0x2a, 0xf4, 0x2a, 0xa6, 0x3e, 0xe2, 0x7c, 0xbe, 0x3f, 0x6d, 0xfa, 0x3c, 0xb7, 0xfc, 0x43, [1643607819.520067][8535:8540] CHIP:DMG: ] [1643607819.520119][8535:8540] CHIP:DMG: }, [1643607819.520169][8535:8540] CHIP:DMG: }, [1643607819.520226][8535:8540] CHIP:DMG: [1643607819.520266][8535:8540] CHIP:DMG: }, [1643607819.520316][8535:8540] CHIP:DMG: [1643607819.520351][8535:8540] CHIP:DMG: ], [1643607819.520397][8535:8540] CHIP:DMG: [1643607819.520432][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607819.520466][8535:8540] CHIP:DMG: }, [1643607819.520561][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1643607819.520613][8535:8540] CHIP:CTL: Received certificate signing request from the device [1643607819.520661][8535:8540] CHIP:CTL: Getting certificate chain for the device from the issuer [1643607819.522214][8535:8540] CHIP:CTL: Verifying Certificate Signing Request [1643607819.523192][8535:8540] CHIP:CTL: Generating NOC [1643607819.523745][8535:8540] CHIP:CTL: Providing certificate chain to the commissioner [1643607819.523793][8535:8540] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:220: Success [1643607819.524035][8535:8540] CHIP:CTL: Sending root certificate to the device [1643607819.524130][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607819.524177][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607819.524438][8535:8540] CHIP:IN: Prepared secure message 0xffff81d31cb8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3089i with MessageCounter:5750933. [1643607819.524497][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d31cb8 with MessageCounter:5750933 to 0x0000000000000001 (1) at monotonic time: 9831445 msec [1643607819.524665][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607819.524713][8535:8540] CHIP:CTL: Sent root certificate to the device [1643607819.525135][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607819.614699][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607819.711378][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607819.713305][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607819.713631][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607819.714003][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197172 on exchange 3089i [1643607819.714082][8535:8540] CHIP:EM: Found matching exchange: 3089i, Delegate: 0xffff6c00dd90 [1643607819.714170][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607819.714267][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607819.714327][8535:8540] CHIP:DMG: { [1643607819.714406][8535:8540] CHIP:DMG: suppressResponse = false, [1643607819.714467][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607819.714567][8535:8540] CHIP:DMG: [ [1643607819.714627][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607819.714787][8535:8540] CHIP:DMG: { [1643607819.714852][8535:8540] CHIP:DMG: CommandStatusIB = [1643607819.714953][8535:8540] CHIP:DMG: { [1643607819.715025][8535:8540] CHIP:DMG: CommandPathIB = [1643607819.715134][8535:8540] CHIP:DMG: { [1643607819.715229][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607819.715362][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607819.715477][8535:8540] CHIP:DMG: CommandId = 0xb, [1643607819.715567][8535:8540] CHIP:DMG: }, [1643607819.715689][8535:8540] CHIP:DMG: [1643607819.715785][8535:8540] CHIP:DMG: StatusIB = [1643607819.715860][8535:8540] CHIP:DMG: { [1643607819.715966][8535:8540] CHIP:DMG: status = 0x0, [1643607819.716073][8535:8540] CHIP:DMG: }, [1643607819.716166][8535:8540] CHIP:DMG: [1643607819.716260][8535:8540] CHIP:DMG: }, [1643607819.716378][8535:8540] CHIP:DMG: [1643607819.716443][8535:8540] CHIP:DMG: }, [1643607819.716533][8535:8540] CHIP:DMG: [1643607819.716593][8535:8540] CHIP:DMG: ], [1643607819.716685][8535:8540] CHIP:DMG: [1643607819.716747][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607819.716829][8535:8540] CHIP:DMG: }, [1643607819.716990][8535:8540] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1643607819.717059][8535:8540] CHIP:CTL: Device confirmed that it has received the root certificate [1643607819.717146][8535:8540] CHIP:CTL: Sending operational certificate chain to the device [1643607819.717275][8535:8540] CHIP:DMG: ICR moving to [AddingComm] [1643607819.717377][8535:8540] CHIP:DMG: ICR moving to [AddedComma] [1643607819.717756][8535:8540] CHIP:IN: Prepared secure message 0xffff81d328e8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 3090i with MessageCounter:5750934. [1643607819.717849][8535:8540] CHIP:IN: Sending encrypted msg 0xffff81d328e8 with MessageCounter:5750934 to 0x0000000000000001 (1) at monotonic time: 9831639 msec [1643607819.718041][8535:8540] CHIP:DMG: ICR moving to [CommandSen] [1643607819.718113][8535:8540] CHIP:CTL: Sent operational certificate to the device [1643607819.718198][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607819.857893][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607819.955383][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607820.052475][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1643607820.199521][8535:8538] CHIP:DL: Indication received, conn = 0xffff7803ea30 [1643607820.199856][8535:8540] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1643607820.200207][8535:8540] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5197173 on exchange 3090i [1643607820.200275][8535:8540] CHIP:EM: Found matching exchange: 3090i, Delegate: 0xffff6c002190 [1643607820.200353][8535:8540] CHIP:DMG: ICR moving to [ResponseRe] [1643607820.200442][8535:8540] CHIP:DMG: InvokeResponseMessage = [1643607820.200514][8535:8540] CHIP:DMG: { [1643607820.200566][8535:8540] CHIP:DMG: suppressResponse = false, [1643607820.200619][8535:8540] CHIP:DMG: InvokeResponseIBs = [1643607820.200708][8535:8540] CHIP:DMG: [ [1643607820.200760][8535:8540] CHIP:DMG: InvokeResponseIB = [1643607820.200860][8535:8540] CHIP:DMG: { [1643607820.200934][8535:8540] CHIP:DMG: CommandDataIB = [1643607820.201002][8535:8540] CHIP:DMG: { [1643607820.201088][8535:8540] CHIP:DMG: CommandPathIB = [1643607820.201178][8535:8540] CHIP:DMG: { [1643607820.201256][8535:8540] CHIP:DMG: EndpointId = 0x0, [1643607820.201349][8535:8540] CHIP:DMG: ClusterId = 0x3e, [1643607820.201439][8535:8540] CHIP:DMG: CommandId = 0x8, [1643607820.201506][8535:8540] CHIP:DMG: }, [1643607820.201594][8535:8540] CHIP:DMG: [1643607820.201665][8535:8540] CHIP:DMG: CommandData = [1643607820.201760][8535:8540] CHIP:DMG: { [1643607820.201851][8535:8540] CHIP:DMG: 0x0 = 0, [1643607820.201946][8535:8540] CHIP:DMG: 0x1 = 1, [1643607820.202026][8535:8540] CHIP:DMG: 0x2 = "", [1643607820.202110][8535:8540] CHIP:DMG: }, [1643607820.202177][8535:8540] CHIP:DMG: }, [1643607820.202274][8535:8540] CHIP:DMG: [1643607820.202352][8535:8540] CHIP:DMG: }, [1643607820.202424][8535:8540] CHIP:DMG: [1643607820.202492][8535:8540] CHIP:DMG: ], [1643607820.202559][8535:8540] CHIP:DMG: [1643607820.202629][8535:8540] CHIP:DMG: InteractionModelRevision = 1 [1643607820.202714][8535:8540] CHIP:DMG: }, [1643607820.202886][8535:8540] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1643607820.203068][8535:8540] CHIP:CTL: Device returned status 0 on receiving the NOC [1643607820.203120][8535:8540] CHIP:CTL: Operational credentials provisioned on device 0xffff81d9b808 [1643607820.203192][8535:8540] CHIP:TOO: Secure Pairing Success [1643607820.203261][8535:8540] CHIP:CTL: Required network information not provided in commissioning parameters [1643607820.203312][8535:8540] CHIP:CTL: Rendezvous cleanup [1643607820.203386][8535:8540] CHIP:TOO: Device commissioning Failure: ../third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:157: CHIP Error 0x0000002F: Invalid argument [1643607820.203529][8535:8540] CHIP:DMG: ICR moving to [AwaitingDe] [1643607820.204005][8535:8535] CHIP:-: ../third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:157: CHIP Error 0x0000002F: Invalid argument at ../commands/common/CHIPCommand.cpp:61 [1643607820.204079][8535:8535] CHIP:TOO: Run command failure: ../third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:157: CHIP Error 0x0000002F: Invalid argument [1643607820.207800][8535:8535] CHIP:SPT: VerifyOrDie failure at ../third_party/connectedhomeip/src/lib/support/Pool.h:217: Allocated() == 0 Aborted (core dumped)