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

[AHaug]

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

[Dan]

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.

[AHaug]

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