• State Verified Answer
  • Locked Locked
  • Replies 5 replies
  • Subscribers 75 subscribers
  • Views 2754 views
  • Users 0 members are here
Attachments (0)
Nordic Case Info
  • Case ID: 290099
Options
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

Dan

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

  • 0

    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

  • 0 in reply to Dan

    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

  • 0

    Hi Dan,

    I have asked the Matter team for more input on your issue, and while waiting for a response from them I found this similar ticket (albeit with NCS 1.9.99) which might be of help. Some of the error CHIP codes you have in your log are also showing up here. 

    Let me know if the ticket mentioned points you in a direction that solves your issue while we wait for a response from the Matter team. I'll let you about their input as soon as I get a response from them (hopefully within 1-2 working days).

    Kind regards,
    Andreas

  • 0 in reply to AHaug

    Hi Andreas - thanks for the link to that ticket - I actually looked at it and the issue there (IGMP snooping disabled) is not one I have.

    I have some good news though.... I just updated the NRF SDK to 2.0 and rebuilt the Matter light bulb sample and it works great! I am able now to commission using the Android Chiptool app and also toggle the light on/off. So excited to proceed with my project.

    One thing of interest/note in case it affects future readers of this thread. I did notice that in the NRF Terminal log, towards the end of the commissioning process, the nordic device complained about:

    E: 328772 [SC]PASESession timed out while waiting for a response from the peer. Expected message type was 34

    Meanwhile the Android Chiptool was complaining about:

    E/SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33

    I wonder if this was due to some versioning issue, and changes in message types between the chiptool libraries that each was using.

  • 0 in reply to Dan

    Hi Dan,

    I am glad to hear you found the issue! Good luck with the development, and please feel free to open new tickets if new issues occurs while developing with our SDK and products!

    Kind regards,
    Andreas

Related
Terms of service