This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Matter Commissioning with Android ChipTool - Fails

Hi - I am unable to commission my NRF-5340-DK as a Matter device using the Android Chiptool app.

I am using the matter sample Light Bulb with v.1.9 of the NRF SDK. The sample loads and works on the board and I can turn on/off the LED-2 by pushing Button-2.

I can successfully scan the QR code, and the Android Chiptool app does connect to the device and start the commissioning process (LED-1 goes from 10% duty cycle to 50% duty cycle as expected, and toast messages appear on the Chiptool app, and I see in NRF Terminal that the handshake is happening). Below is a log of the NRF Terminal. After it fails the first time, I try a second time, and then finally I just toggle the on board buttons.

Any thoughts or suggestions on what can be going wrong?

I am using an EERO 6 which has an OTBR which I can access.

Thanks! Dan.

I: Factory Reset triggered
I: 13478777 [DL]Performing factory reset
I: 13478783 [DL]Erasing Thread persistent info...
*** Booting Zephyr OS build v2.7.99-ncs1-1 ***
I: Starting bootloader
I: Swap type: none
I: Swap type: none
I: Bootloader chainload address offset: 0x10000
I: Jumping to the first image slot

uart:~$ I: nRF5 802154 radio initialized
I: 8 Sectors of 4096 bytes
I: alloc wra: 0, df8
I: data wra: 0, 2dc
*** Booting Zephyr OS build v2.7.99-ncs1-1 ***
I: Init CHIP stack
I: 165 [DL]BLE address: EB:9E:04:4E:B6:3D
I: Starting CHIP task
I: Init Thread stack
I: 193 [DL]OpenThread started: OK
I: 196 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 203 [ZCL]Using ZAP configuration...
I: 207 [ZCL]Initiating Admin Commissioning cluster.
I: 211 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 219 [DIS]Set the fabric pairing table delegate
I: 224 [ZCL]0xae790ep 0 clus 0x0000_0028 attr 0x0000_000F not supported
E: 231 [ZCL]Error setting Serial Number String: 0x86
I: 235 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 240 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 246 [DIS]Init fabric pairing table with server storage
D: 252 [IN]UDP::Init bind&listen port=5540
D: 256 [IN]UDP::Init bound to port=5540
D: 260 [IN]TransportMgr initialized
D: 267 [SC]Assigned local session key ID 1
D: 271 [SC]Waiting for PBKDF param request
D: 275 [DL]CHIPoBLE advertising set to on
D: 278 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
D: 283 [DL]Using Thread extended MAC for hostname.
I: 288 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 294 [DIS]Start dns-sd server - no current nodeId
D: 299 [DL]Using Thread extended MAC for hostname.
I: 303 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
E: 312 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 320 [DIS]Scheduling Discovery timeout in secs=900
E: 324 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 330 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
D: 335 [DL]Using Thread extended MAC for hostname.
I: 340 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 346 [DIS]Start dns-sd server - no current nodeId
D: 351 [DL]Using Thread extended MAC for hostname.
I: 355 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
E: 364 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 372 [DIS]Scheduling Discovery timeout in secs=900
E: 376 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 382 [IN]CASE Server enabling CASE session setups
D: 387 [DL]Using Thread extended MAC for hostname.
I: 392 [SVR]Server Listening...
I: 395 [DL]Device Configuration:
I: 398 [DL] Serial Number: TEST_SN
I: 401 [DL] Vendor Id: 9050 (0x235A)
I: 404 [DL] Product Id: 20044 (0x4E4C)
I: 408 [DL] Hardware Version: 0
I: 411 [DL] Setup Pin Code: 20202021
I: 414 [DL] Setup Discriminator: 3840 (0xF00)
I: 418 [DL] Manufacturing Date: (not set)
I: 422 [DL] Device Type: 65535 (0xFFFF)
I: 426 [SVR]SetupQRCode: [MT:Y3.13OTB00KA0648G00]
I: 430 [SVR]Copy/paste the below URL in a browser to see the QR Code:
dhrishi.github.io/.../qrcode.html
I: 444 [SVR]Manual pairing code: [34970112332]
I: 449 [SVR]Long manual pairing code: [749701123309050200447]
D: 454 [IN]UDP::Init bind&listen port=12345
D: 458 [IN]UDP::Init bound to port=12345
D: 462 [DL]CHIP task running
I: 469 [DL]CHIPoBLE advertising started
I: 472 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
I: 480 [DL]NFC Tag emulation started
I: 30473 [DL]CHIPoBLE advertising mode changed to slow
I: 74969 [DL]BLE connection established (ConnId: 0x00)
I: 74974 [DL]Current number of connections: 1/1
I: 74978 [DL]CHIPoBLE advertising stopped
I: 74982 [DL]NFC Tag emulation stopped
D: 75827 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 75833 [BLE]local and remote recv window sizes = 5
I: 75838 [BLE]selected BTP version 4
I: 75841 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 75908 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 75913 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 75919 [IN]BLE EndPoint 0x20008970 Connection Complete
I: 75924 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 76005 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 76153 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 76158 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:254857308 on exchange 7644r
D: 76168 [EM]Handling via exchange: 7644r, Delegate: 0x20005d98
D: 76174 [SC]Received PBKDF param request
D: 76178 [SC]Peer assigned session ID 21818
D: 76182 [SC]Found MRP parameters in the message
D: 76186 [SC]Including MRP parameters in PBKDF param response
I: 76369 [IN]Prepared unauthenticated message 0x20029c10 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 7644r with MessageCounter:2021497765.
I: 76384 [IN]Sending unauthenticated msg 0x20029c10 with MessageCounter:2021497765 to 0x0000000000000000 at monotonic time: 76384 msec
D: 76396 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130)
D: 76402 [SC]Sent PBKDF param response
E: 76406 [DL]Long dispatch time: 254 ms, for event type 16388
D: 76590 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 79077 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 81582 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 81616 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 84122 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 86628 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 86657 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 89162 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 91669 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 91697 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 94217 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 96724 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 96752 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 99272 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 101778 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 101807 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 104328 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 105843 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 105847 [IN]Clearing BLE pending packets.
I: 105851 [BLE]Releasing end point's BLE connection back to application.
I: 105857 [DL]Closing BLE GATT connection (ConnId 00)
I: 105887 [DL]BLE GAP connection terminated (reason 0x16)
I: 105892 [DL]Current number of connections: 0/1
I: 105900 [DL]CHIPoBLE advertising started
I: 105904 [DL]NFC Tag emulation started
E: 106369 [SC]PASESession timed out while waiting for a response from the peer. Expected message type was 34
E: 106378 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032
D: 106385 [SC]Assigned local session key ID 2
D: 106389 [SC]Waiting for PBKDF param request
D: 106393 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
D: 106398 [DL]Using Thread extended MAC for hostname.
I: 106403 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 106409 [DIS]Start dns-sd server - no current nodeId
D: 106414 [DL]Using Thread extended MAC for hostname.
I: 106419 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
E: 106428 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 106436 [DIS]Scheduling Discovery timeout in secs=900
E: 106441 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 135904 [DL]CHIPoBLE advertising mode changed to slow
I: 166047 [DL]BLE connection established (ConnId: 0x00)
I: 166052 [DL]Current number of connections: 1/1
I: 166056 [DL]CHIPoBLE advertising stopped
I: 166060 [DL]NFC Tag emulation stopped
I: 253391 [DL]BLE GAP connection terminated (reason 0x13)
I: 253396 [DL]Current number of connections: 0/1
I: 253404 [DL]CHIPoBLE advertising started
I: 253408 [DL]NFC Tag emulation started
I: 283408 [DL]CHIPoBLE advertising mode changed to slow
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 679410 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: 679414 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 679964 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 679968 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254

Parents
  • In case it is helpful, I include here the debug trace from Android Studio when running the Android Chiptool and trying to "Provision Chip Device with Thread"

    I/chip.BluetoothManager: Bluetooth Device Scanned Addr: F8:CF:BD:C7:5B:1B, Name MatterLight
    D/BluetoothAdapter: isLeEnabled(): ON
    I/DeviceProvisioningFragment: showMessage:Connecting to MatterLight
    I/chip.BluetoothManager: Connecting
    D/BluetoothGatt: connect() - device: F8:CF:BD:C7:5B:1B, auto: false
    D/BluetoothGatt: registerApp()
    D/BluetoothGatt: registerApp() - UUID=1078a6ba-b9c8-4621-af24-80b95ed214b0
    D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
    D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=F8:CF:BD:C7:5B:1B
    I/chip.BluetoothManager: MatterLight.onConnectionStateChange status = 0, newState=2
    I/chip.BluetoothManager|onConnectionStateChange: Discovering Services...
    D/BluetoothGatt: discoverServices() - device: F8:CF:BD:C7:5B:1B
    D/BluetoothGatt: onConnectionUpdated() - Device=F8:CF:BD:C7:5B:1B interval=6 latency=0 timeout=500 status=0
    D/BluetoothGatt: onPhyUpdate() - status=0 address=F8:CF:BD:C7:5B:1B txPhy=2 rxPhy=2
    D/BluetoothGatt: onSearchComplete() = Device=F8:CF:BD:C7:5B:1B Status=0
    D/chip.BluetoothManager: MatterLight.onServicesDiscovered status = 0
    I/chip.BluetoothManager|onServicesDiscovered: Services Discovered
    D/BluetoothGatt: configureMTU() - device: F8:CF:BD:C7:5B:1B mtu: 247
    D/BluetoothGatt: onConfigureMTU() - Device=F8:CF:BD:C7:5B:1B mtu=247 status=0
    D/chip.BluetoothManager: MatterLight.onMtuChanged: connecting to CHIP device
    I/DeviceProvisioningFragment: showMessage:Pairing
    D/BluetoothGatt: onConnectionUpdated() - Device=F8:CF:BD:C7:5B:1B interval=39 latency=0 timeout=500 status=0
    D/ChipDeviceController: Bluetooth connection added with ID: 1
    D/ChipDeviceController: Pairing device with ID: 46
    D/CTL: pairDevice() called with device ID, connection object, and pincode
    D/IN: BleConnectionComplete: endPoint 0x7002e810
    D/DL: Received GetMTU
    D/AndroidBleManager: Android Manufacturer: (motorola)
    D/AndroidBleManager: Android Model: (moto g pure)
    D/DL: Received SendWriteRequest
    D/IN: SecureSession Allocated 0x872f23f0 Type:1 LSID:58380
    D/SC: Assigned local session key ID 58380
    D/SC: Including MRP parameters in PBKDF param request
    D/IN: Prepared unauthenticated message 0xbe882ec0 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 42904i with MessageCounter:222902487.
    D/IN: Sending unauthenticated msg 0xbe882ec0 with MessageCounter:222902487 to 0x0000000000000000 at monotonic time: 000000000DF74DDA msec
    D/IN: Message appended to BLE send queue
    D/SC: Sent PBKDF param request
    D/CTL: Setting thread operational dataset from parameters
    D/CTL: Setting attestation nonce to random value
    D/CTL: Setting CSR nonce to random value
    D/CTL: Commission called for node ID 0x000000000000002E
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/DL: Received SubscribeCharacteristic
    D/BluetoothGatt: setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: true
    D/chip.BluetoothManager: MatterLight.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 0
    D/BLE: subscribe complete, ep = 0x7002e810
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/BLE: peripheral chose BTP version 4; central expected between 4 and 4
    D/BLE: using BTP fragment sizes rx 244 / tx 244.
    D/BLE: local and remote recv window size = 5
    D/DL: Received SendWriteRequest
    D/IN: BLE EndPoint 0x7002e810 Connection Complete
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/IN: Received malformed unsecure packet with source 0x0000000000000000 destination 0x0000000000000000
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/BluetoothGatt: onConnectionUpdated() - Device=F8:CF:BD:C7:5B:1B interval=12 latency=0 timeout=42 status=0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    D/chip.BluetoothManager: MatterLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
    D/DL: Received SendWriteRequest
    D/chip.BluetoothManager: MatterLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
    E/SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
    D/IN: SecureSession Released 0x872f23f0 Type:1 LSID:58380
    D/DeviceProvisioningFragment: Pairing status update: 1
    D/DIS: Closing all BLE connections
    D/IN: Clearing BLE pending packets.
    D/DL: Received UnsubscribeCharacteristic
    D/BluetoothGatt: setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: false
    D/BLE: Auto-closing end point's BLE connection.
    D/DL: Received CloseConnection
    D/BluetoothGatt: close()
    D/BluetoothGatt: unregisterApp() - mClientIf=8
    D/chip.BluetoothManager: onCloseBleComplete
    D/DeviceProvisioningFragment: onPairingComplete: 50
    I/DeviceProvisioningFragment: showMessage:Pairing failed
    
    
    

    and the corresponding trace from the NRF Terminal connected to the NRF5340-DK

    *** Booting Zephyr OS build v2.7.99-ncs1-1  ***
    I: Starting bootloader
    I: Swap type: none
    I: Swap type: none
    I: Bootloader chainload address offset: 0x10000
    I: Jumping to the first image slot
    
    uart:~$ I: nRF5 802154 radio initialized
    I: 8 Sectors of 4096 bytes
    I: alloc wra: 0, dc8
    I: data wra: 0, 304
    *** Booting Zephyr OS build v2.7.99-ncs1-1  ***
    I: Init CHIP stack
    I: 164 [DL]BLE address: F8:CF:BD:C7:5B:1B
    I: Starting CHIP task
    I: Init Thread stack
    I: 192 [DL]OpenThread started: OK
    I: 195 [DL]Setting OpenThread device type to MINIMAL END DEVICE
    I: 202 [ZCL]Using ZAP configuration...
    I: 206 [ZCL]Initiating Admin Commissioning cluster.
    I: 210 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
    D: 218 [DIS]Set the fabric pairing table delegate
    I: 224 [ZCL]0xae790ep 0 clus 0x0000_0028 attr 0x0000_000F not supported
    E: 230 [ZCL]Error setting Serial Number String: 0x86
    I: 235 [ZCL]Cluster OnOff: attribute OnOff set to 0
    I: 239 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
    D: 245 [DIS]Init fabric pairing table with server storage
    D: 252 [IN]UDP::Init bind&listen port=5540
    D: 256 [IN]UDP::Init bound to port=5540
    D: 259 [IN]TransportMgr initialized
    D: 266 [SC]Assigned local session key ID 1
    D: 270 [SC]Waiting for PBKDF param request
    D: 274 [DL]CHIPoBLE advertising set to on
    D: 278 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
    D: 283 [DL]Using Thread extended MAC for hostname.
    I: 288 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 293 [DIS]Start dns-sd server - no current nodeId
    D: 298 [DL]Using Thread extended MAC for hostname.
    I: 303 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    E: 311 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
    D: 319 [DIS]Scheduling Discovery timeout in secs=900
    E: 324 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
    D: 330 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
    D: 335 [DL]Using Thread extended MAC for hostname.
    I: 340 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 345 [DIS]Start dns-sd server - no current nodeId
    D: 350 [DL]Using Thread extended MAC for hostname.
    I: 355 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    E: 363 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
    D: 371 [DIS]Scheduling Discovery timeout in secs=900
    E: 376 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
    I: 382 [IN]CASE Server enabling CASE session setups
    D: 386 [DL]Using Thread extended MAC for hostname.
    I: 391 [SVR]Server Listening...
    I: 394 [DL]Device Configuration:
    I: 397 [DL]  Serial Number: TEST_SN
    I: 400 [DL]  Vendor Id: 9050 (0x235A)
    I: 404 [DL]  Product Id: 20044 (0x4E4C)
    I: 407 [DL]  Hardware Version: 0
    I: 410 [DL]  Setup Pin Code: 20202021
    I: 414 [DL]  Setup Discriminator: 3840 (0xF00)
    I: 418 [DL]  Manufacturing Date: (not set)
    I: 422 [DL]  Device Type: 65535 (0xFFFF)
    I: 426 [SVR]SetupQRCode: [MT:Y3.13OTB00KA0648G00]
    I: 430 [SVR]Copy/paste the below URL in a browser to see the QR Code:
        https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AY3.13OTB00KA0648G00
    I: 444 [SVR]Manual pairing code: [34970112332]
    I: 449 [SVR]Long manual pairing code: [749701123309050200447]
    D: 454 [IN]UDP::Init bind&listen port=12345
    D: 458 [IN]UDP::Init bound to port=12345
    D: 462 [DL]CHIP task running
    I: 469 [DL]CHIPoBLE advertising started
    I: 472 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
    I: 479 [DL]NFC Tag emulation started
    I: 30472 [DL]CHIPoBLE advertising mode changed to slow
    I: 66847 [DL]BLE connection established (ConnId: 0x00)
    I: 66852 [DL]Current number of connections: 1/1
    I: 66856 [DL]CHIPoBLE advertising stopped
    I: 66860 [DL]NFC Tag emulation stopped
    D: 67756 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    I: 67762 [BLE]local and remote recv window sizes = 5
    I: 67767 [BLE]selected BTP version 4
    I: 67770 [BLE]using BTP fragment sizes rx 244 / tx 244.
    D: 67854 [DL]ConnId: 0x00, New CCCD value: 0x0001
    D: 67858 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
    D: 67864 [IN]BLE EndPoint 0x20008970 Connection Complete
    I: 67869 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
    D: 67953 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 67958 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    I: 67964 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:2334347064 on exchange 33712r
    D: 67975 [EM]Handling via exchange: 33712r, Delegate: 0x20005d98
    D: 67980 [SC]Received PBKDF param request
    D: 67984 [SC]Peer assigned session ID 5851
    D: 67988 [SC]Found MRP parameters in the message
    D: 67993 [SC]Including MRP parameters in PBKDF param response
    I: 68176 [IN]Prepared unauthenticated message 0x20029c10 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 33712r with MessageCounter:1623085649.
    I: 68191 [IN]Sending unauthenticated msg 0x20029c10 with MessageCounter:1623085649 to 0x0000000000000000 at monotonic time: 68191 msec
    D: 68203 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130)
    D: 68209 [SC]Sent PBKDF param response
    E: 68213 [DL]Long dispatch time: 255 ms, for event type 16388
    D: 68389 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 70876 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 73382 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 73407 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 75942 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 78449 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 78477 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 80998 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 83504 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 83532 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 86053 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 88558 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 88587 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 91123 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 93629 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 93658 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 96178 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 97768 [DL]ConnId: 0x00, New CCCD value: 0x0000
    D: 97773 [IN]Clearing BLE pending packets.
    I: 97776 [BLE]Releasing end point's BLE connection back to application.
    I: 97783 [DL]Closing BLE GATT connection (ConnId 00)
    I: 97813 [DL]BLE GAP connection terminated (reason 0x16)
    I: 97818 [DL]Current number of connections: 0/1
    I: 97825 [DL]CHIPoBLE advertising started
    I: 97829 [DL]NFC Tag emulation started
    E: 98176 [SC]PASESession timed out while waiting for a response from the peer. Expected message type was 34
    E: 98186 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032
    D: 98192 [SC]Assigned local session key ID 2
    D: 98196 [SC]Waiting for PBKDF param request
    D: 98200 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
    D: 98205 [DL]Using Thread extended MAC for hostname.
    I: 98210 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 98216 [DIS]Start dns-sd server - no current nodeId
    D: 98221 [DL]Using Thread extended MAC for hostname.
    I: 98226 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    E: 98234 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
    D: 98242 [DIS]Scheduling Discovery timeout in secs=900
    E: 98247 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
    I: 127829 [DL]CHIPoBLE advertising mode changed to slow
    I: 297410 [DL]BLE connection established (ConnId: 0x00)
    I: 297415 [DL]Current number of connections: 1/1
    I: 297419 [DL]CHIPoBLE advertising stopped
    I: 297423 [DL]NFC Tag emulation stopped
    D: 298352 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    I: 298358 [BLE]local and remote recv window sizes = 5
    I: 298362 [BLE]selected BTP version 4
    I: 298366 [BLE]using BTP fragment sizes rx 244 / tx 244.
    D: 298449 [DL]ConnId: 0x00, New CCCD value: 0x0001
    D: 298454 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
    D: 298460 [IN]BLE EndPoint 0x20008970 Connection Complete
    I: 298465 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
    D: 298549 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 298554 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    I: 298560 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:222902487 on exchange 42904r
    D: 298570 [EM]Handling via exchange: 42904r, Delegate: 0x20005d98
    D: 298576 [SC]Received PBKDF param request
    D: 298580 [SC]Peer assigned session ID 58380
    D: 298584 [SC]Found MRP parameters in the message
    D: 298589 [SC]Including MRP parameters in PBKDF param response
    I: 298773 [IN]Prepared unauthenticated message 0x20029c10 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 42904r with MessageCounter:1623085650.
    I: 298788 [IN]Sending unauthenticated msg 0x20029c10 with MessageCounter:1623085650 to 0x0000000000000000 at monotonic time: 298787 msec
    D: 298799 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130)
    D: 298806 [SC]Sent PBKDF param response
    E: 298810 [DL]Long dispatch time: 256 ms, for event type 16388
    D: 299034 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 301520 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 304026 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 304051 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 306587 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 309093 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 309122 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 311657 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 314163 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 314207 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 316742 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 319249 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 319277 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 321797 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 324304 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
    D: 324332 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
    D: 326868 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
    D: 328383 [DL]ConnId: 0x00, New CCCD value: 0x0000
    D: 328387 [IN]Clearing BLE pending packets.
    I: 328391 [BLE]Releasing end point's BLE connection back to application.
    I: 328397 [DL]Closing BLE GATT connection (ConnId 00)
    I: 328427 [DL]BLE GAP connection terminated (reason 0x16)
    I: 328432 [DL]Current number of connections: 0/1
    I: 328440 [DL]CHIPoBLE advertising started
    I: 328444 [DL]NFC Tag emulation started
    E: 328772 [SC]PASESession timed out while waiting for a response from the peer. Expected message type was 34
    E: 328781 [SVR]Commissioning failed (attempt 2): Error CHIP:0x00000032
    D: 328788 [SC]Assigned local session key ID 3
    D: 328792 [SC]Waiting for PBKDF param request
    D: 328796 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
    D: 328801 [DL]Using Thread extended MAC for hostname.
    I: 328806 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 328812 [DIS]Start dns-sd server - no current nodeId
    D: 328817 [DL]Using Thread extended MAC for hostname.
    I: 328822 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    E: 328831 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
    D: 328839 [DIS]Scheduling Discovery timeout in secs=900
    E: 328844 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
    I: 358444 [DL]CHIPoBLE advertising mode changed to slow

  • Also - if I issue 'ot' commands directly in NRF Terminal, I can commission the NRF device to my eero thread network simply by passing the networkkey. The LED-1 turns solid and stays solid. However, I am still unable to control the board from the Android Chiptool app using the "Light ON/OFF & Level Cluster" fragment/page.

    ot dataset
    ot dataset
    Done
    ot dataset networkkey adf72e6c715385ac312e2d7d3582abaf
    ot dataset networkkey adf72e6c715385ac312e2d7d3582abaf
    Done
    ot dataset commit active
    ot dataset commit active
    Done
    D: 995661 [DL]OpenThread State Changed (Flags: 0x10040100)
    D: 995666 [DL]   Network Name: OpenThread
    D: 995670 [DL]   PAN Id: 0xFFFF
    D: 995673 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 995677 [DL]   Channel: 11
    D: 995680 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    ot dataset active
    ot dataset active
    Network Key: adf72e6c715385ac312e2d7d3582abaf
    Done
    ot ifconfig up
    ot ifconfig up
    Done
    D: 1021177 [DL]OpenThread State Changed (Flags: 0x01001009)
    D: 1021183 [DL]   Thread Unicast Addresses:
    D: 1021187 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    ot thread start
    ot thread start
    Done
    D: 1033572 [DL]OpenThread State Changed (Flags: 0x10009015)
    D: 1033577 [DL]   Device Role: DETACHED
    D: 1033581 [DL]   Network Name: OpenThread
    D: 1033585 [DL]   PAN Id: 0xD99A
    D: 1033588 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 1033593 [DL]   Channel: 11
    D: 1033595 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    D: 1033600 [DL]   Thread Unicast Addresses:
    D: 1033604 [DL]        fdde:ad00:beef:0:3b8a:8b90:90ff:754a/64 valid
    D: 1033610 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    uart:~$ D: 1039564 [DL]OpenThread State Changed (Flags: 0x00000100)
    D: 1039815 [DL]OpenThread State Changed (Flags: 0x0000f017)
    D: 1039820 [DL]   Device Role: DETACHED
    D: 1039824 [DL]   Network Name: OpenThread
    D: 1039827 [DL]   PAN Id: 0x78E0
    D: 1039830 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 1039835 [DL]   Channel: 25
    D: 1039838 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    D: 1039842 [DL]   Thread Unicast Addresses:
    D: 1039846 [DL]        fdde:ad00:beef:0:3b8a:8b90:90ff:754a/64 valid
    D: 1039852 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    I: 1043524 [DL]SRP Client was started, detected server: fd63:4474:e016:0000:1070:a3f1:7eef:eadb
    D: 1043534 [DL]OpenThread State Changed (Flags: 0x301332b7)
    D: 1043539 [DL]   Device Role: CHILD
    D: 1043542 [DL]   Network Name: eero-thread
    D: 1043546 [DL]   PAN Id: 0x78E0
    D: 1043549 [DL]   Extended PAN Id: 0xCD133347665770FE
    D: 1043554 [DL]   Channel: 25
    D: 1043557 [DL]   Mesh Prefix: fd63:4474:e016::/64
    D: 1043561 [DL]   Partition Id: 0x4D1BFB9B
    D: 1043565 [DL]   Thread Unicast Addresses:
    D: 1043569 [DL]        fd62:1d09:d2a:1:cbae:b853:59ba:db6d/64 valid preferred
    D: 1043576 [DL]        fd63:4474:e016::ff:fe00:2408/64 valid rloc
    D: 1043582 [DL]        fd63:4474:e016:0:3b8a:8b90:90ff:754a/64 valid
    D: 1043588 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    E: 1043751 [DL]Long dispatch time: 217 ms, for event type 32780
    D: 1043758 [DL]OpenThread State Changed (Flags: 0x00000001)
    D: 1043763 [DL]   Thread Unicast Addresses:
    D: 1043767 [DL]        fd62:1d09:d2a:1:cbae:b853:59ba:db6d/64 valid preferred
    D: 1043774 [DL]        fd63:4474:e016::ff:fe00:2408/64 valid rloc
    D: 1043780 [DL]        fd63:4474:e016:0:3b8a:8b90:90ff:754a/64 valid
    D: 1043786 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    I: 1043880 [DL]OnSrpClientNotification: Last requested operation completed successfully
    D: 1043888 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
    I: 1043894 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 1043900 [DIS]Start dns-sd server - no current nodeId
    D: 1043905 [DL]Using Thread extended MAC for hostname.
    I: 1043910 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    I: 1043919 [DL]advertising srp service: 3C47635F276D78E1._matterc._udp
    D: 1043926 [DIS]Scheduling Discovery timeout in secs=900
    I: 1045075 [DL]OnSrpClientNotification: Last requested operation completed successfully
    
    ot state
    ot state
    child
    Done
    
    ot ipaddr
    ot ipaddr
    fd62:1d09:d2a:1:cbae:b853:59ba:db6d
    fd63:4474:e016:0:0:ff:fe00:2408
    fd63:4474:e016:0:3b8a:8b90:90ff:754a
    fe80:0:0:0:9430:fab4:7cf:c9ad
    Done
    ot networkname
    ot networkname
    eero-thread
    Done
    

Reply
  • Also - if I issue 'ot' commands directly in NRF Terminal, I can commission the NRF device to my eero thread network simply by passing the networkkey. The LED-1 turns solid and stays solid. However, I am still unable to control the board from the Android Chiptool app using the "Light ON/OFF & Level Cluster" fragment/page.

    ot dataset
    ot dataset
    Done
    ot dataset networkkey adf72e6c715385ac312e2d7d3582abaf
    ot dataset networkkey adf72e6c715385ac312e2d7d3582abaf
    Done
    ot dataset commit active
    ot dataset commit active
    Done
    D: 995661 [DL]OpenThread State Changed (Flags: 0x10040100)
    D: 995666 [DL]   Network Name: OpenThread
    D: 995670 [DL]   PAN Id: 0xFFFF
    D: 995673 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 995677 [DL]   Channel: 11
    D: 995680 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    ot dataset active
    ot dataset active
    Network Key: adf72e6c715385ac312e2d7d3582abaf
    Done
    ot ifconfig up
    ot ifconfig up
    Done
    D: 1021177 [DL]OpenThread State Changed (Flags: 0x01001009)
    D: 1021183 [DL]   Thread Unicast Addresses:
    D: 1021187 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    ot thread start
    ot thread start
    Done
    D: 1033572 [DL]OpenThread State Changed (Flags: 0x10009015)
    D: 1033577 [DL]   Device Role: DETACHED
    D: 1033581 [DL]   Network Name: OpenThread
    D: 1033585 [DL]   PAN Id: 0xD99A
    D: 1033588 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 1033593 [DL]   Channel: 11
    D: 1033595 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    D: 1033600 [DL]   Thread Unicast Addresses:
    D: 1033604 [DL]        fdde:ad00:beef:0:3b8a:8b90:90ff:754a/64 valid
    D: 1033610 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    uart:~$ D: 1039564 [DL]OpenThread State Changed (Flags: 0x00000100)
    D: 1039815 [DL]OpenThread State Changed (Flags: 0x0000f017)
    D: 1039820 [DL]   Device Role: DETACHED
    D: 1039824 [DL]   Network Name: OpenThread
    D: 1039827 [DL]   PAN Id: 0x78E0
    D: 1039830 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
    D: 1039835 [DL]   Channel: 25
    D: 1039838 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    D: 1039842 [DL]   Thread Unicast Addresses:
    D: 1039846 [DL]        fdde:ad00:beef:0:3b8a:8b90:90ff:754a/64 valid
    D: 1039852 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    I: 1043524 [DL]SRP Client was started, detected server: fd63:4474:e016:0000:1070:a3f1:7eef:eadb
    D: 1043534 [DL]OpenThread State Changed (Flags: 0x301332b7)
    D: 1043539 [DL]   Device Role: CHILD
    D: 1043542 [DL]   Network Name: eero-thread
    D: 1043546 [DL]   PAN Id: 0x78E0
    D: 1043549 [DL]   Extended PAN Id: 0xCD133347665770FE
    D: 1043554 [DL]   Channel: 25
    D: 1043557 [DL]   Mesh Prefix: fd63:4474:e016::/64
    D: 1043561 [DL]   Partition Id: 0x4D1BFB9B
    D: 1043565 [DL]   Thread Unicast Addresses:
    D: 1043569 [DL]        fd62:1d09:d2a:1:cbae:b853:59ba:db6d/64 valid preferred
    D: 1043576 [DL]        fd63:4474:e016::ff:fe00:2408/64 valid rloc
    D: 1043582 [DL]        fd63:4474:e016:0:3b8a:8b90:90ff:754a/64 valid
    D: 1043588 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    E: 1043751 [DL]Long dispatch time: 217 ms, for event type 32780
    D: 1043758 [DL]OpenThread State Changed (Flags: 0x00000001)
    D: 1043763 [DL]   Thread Unicast Addresses:
    D: 1043767 [DL]        fd62:1d09:d2a:1:cbae:b853:59ba:db6d/64 valid preferred
    D: 1043774 [DL]        fd63:4474:e016::ff:fe00:2408/64 valid rloc
    D: 1043780 [DL]        fd63:4474:e016:0:3b8a:8b90:90ff:754a/64 valid
    D: 1043786 [DL]        fe80::9430:fab4:7cf:c9ad/64 valid preferred
    I: 1043880 [DL]OnSrpClientNotification: Last requested operation completed successfully
    D: 1043888 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
    I: 1043894 [DIS]Failed to find a valid admin pairing. Node ID unknown
    I: 1043900 [DIS]Start dns-sd server - no current nodeId
    D: 1043905 [DL]Using Thread extended MAC for hostname.
    I: 1043910 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
    I: 1043919 [DL]advertising srp service: 3C47635F276D78E1._matterc._udp
    D: 1043926 [DIS]Scheduling Discovery timeout in secs=900
    I: 1045075 [DL]OnSrpClientNotification: Last requested operation completed successfully
    
    ot state
    ot state
    child
    Done
    
    ot ipaddr
    ot ipaddr
    fd62:1d09:d2a:1:cbae:b853:59ba:db6d
    fd63:4474:e016:0:0:ff:fe00:2408
    fd63:4474:e016:0:3b8a:8b90:90ff:754a
    fe80:0:0:0:9430:fab4:7cf:c9ad
    Done
    ot networkname
    ot networkname
    eero-thread
    Done
    

Children
No Data
Related