Compatibility of nRF Connect SDK version and Matter Chip Tool

[Oide Brett]

Hi,

I am using the latest version of nRF connect SDK v2.1.3 and the latest branch of matter project chip sdk v1.0.0.2 but I am getting a AttestationVerfication error when I try to pair using the chip tool.

sudo out/chip-tool pairing ble-thread 2 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd1836531296ab0b051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840

[1673198372.161569][106605:106607] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1673198372.161599][106605:106607] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1673198372.161620][106605:106607] CHIP:CTL: Verifying attestation
[1673198372.207501][106605:106607] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 601. Look at AttestationVerificationResult enum to understand the errors
[1673198372.207550][106605:106607] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'

Any ideas? I also tried nRF connect SDK v2.1.1 but I was getting the same attestation issue.

Many thanks

Oide

[Marte Myrvold]

Hi Oide,

Can you try downloading the CHIP Tool from the nRF Connect SDK downstream of the connectedhomeip repo, https://github.com/nrfconnect/sdk-connectedhomeip/releases? Make sure to download and use the same version as the SDK you are using.

Which example are you using, and have you made any changes to it?

Please upload the entire log from the CHIP Tool and the device.

Best regards,

Marte

[Oide Brett]

Thanks Marte, I did as you suggested and even went one step further and completely cloned and built the entire v2.1.3 sdk-connectedhomeip repo from scratch on my laptop. I built the chiptool and the nrfconnect matter light-switch-app sample in examples/light-switch-app/nrfconnect/

The pairing still fails. I have a raspberry pi running the otbr-posix with the nrf 52840 dongle as the RCP. The git checkout branch of otbr-posix that i am running is 0895ad5. I have successfully started the otbr-agent and otbr-web service and I formed a thread network (which I use in the chiptool pairing).

I have attached the chiptool log, the end of the logs from the nrf52840 running the matter light-switch sample app and the message logs from the otbr. It looks like the pairing is partially completing but there is some problems joining the end matter device to the thread network.

Any ideas on what I should investigate to fix this.

Many thanks for your help on this.

5428.chiptool.log?

Fullscreen light-switch nrf52840 screen.log Download

D: 525982 [DL]   Extended PAN Id: 0x1111111122222222
D: 525987 [DL]   Channel: 15
D: 525990 [DL]   Mesh Prefix: fd18:3653:1296:ab0b::/64
D: 525995 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 526001 [DL]   Device Role: DETACHED
D: 526004 [DL]   Thread Unicast Addresses:
D: 526008 [DL]        fd18:3653:1296:ab0b:be56:f073:3993:427d/64 valid
D: 526015 [DL]        fe80::84a6:efa0:90c3:2f14/64 valid preferred
D: 528419 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 528476 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 529336 [DL]SRP Client was started, detected server: fd09:a255:002b:f955:e1af:0360:d8b9:4a02
D: 529345 [DL]OpenThread State Changed (Flags: 0x200002a4)
D: 529514 [DL]   Device Role: CHILD
D: 529519 [DL]   Partition Id: 0x6DB10F51
E: 529562 [DL]Long dispatch time: 217 ms, for event type 32777
D: 529569 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 529575 [DL]   Thread Unicast Addresses:
D: 529579 [DL]        fd6c:e575:5e81:1:2190:1a2e:a672:a7da/64 valid preferred
D: 529587 [DL]        fd18:3653:1296:ab0b:0:ff:fe00:e001/64 valid rloc
D: 529593 [DL]        fd18:3653:1296:ab0b:be56:f073:3993:427d/64 valid
D: 529600 [DL]        fe80::84a6:efa0:90c3:2f14/64 valid preferred
I: 529612 [SWU]Stopping the watchdog timer
I: 529616 [SWU]Starting the periodic query timer, timeout: 86400 seconds
D: 529622 [DMG]Command handler moving to [ Preparing]
D: 529627 [DMG]Command handler moving to [AddingComm]
D: 529632 [DMG]Command handler moving to [AddedComma]
D: 529637 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6169b479
D: 529643 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 529651 [EM]<<< [E:19181r M:23606163] (S) Msg TX to 1:FFFFFFFB00000000 [03B3] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 529662 [IN](S) Sending msg 23606163 on secure session with LSID: 19869
D: 529668 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 69)
D: 529676 [DMG]Command handler moving to [CommandSen]
D: 529680 [DMG]Command handler moving to [AwaitingDe]
D: 529685 [DMG]Endpoint 0, Cluster 0x0000_002A update version to a2ee2622
D: 529692 [DMG]Endpoint 0, Cluster 0x0000_002A update version to a2ee2623
D: 529699 [DL]Using Thread extended MAC for hostname.
I: 529704 [DIS]Advertise operational node 055AD343E2FE03B3-0000000000000002
I: 529710 [SVR]Operational advertising enabled
D: 529736 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 530996 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
E: 531361 [DL]SRP update error: timed out waiting on server response
D: 533504 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 533696 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 534465 [DL]SRP update error: timed out waiting on server response
D: 536396 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 538903 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 539096 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 539712 [DL]SRP update error: timed out waiting on server response
D: 541796 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 544303 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 544495 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 544721 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 544725 [IN]Clearing BLE pending packets.
I: 544729 [BLE]Releasing end point's BLE connection back to application.
I: 544735 [DL]Closing BLE GATT connection (ConnId 00)
I: 544856 [DL]BLE GAP connection terminated (reason 0x16)
I: 544861 [DL]Current number of connections: 0/1
E: 548597 [DL]SRP update error: timed out waiting on server response
E: 563669 [DL]SRP update error: timed out waiting on server response
D: 576802 [DL]OpenThread State Changed (Flags: 0x00000200)
D: 578323 [DL]OpenThread State Changed (Flags: 0x00000200)
I: 580020 [FS]Fail-safe timer expired
E: 580023 [SVR]Failsafe timer expired
D: 580027 [IN]SecureSession[0x20003698]: MarkForEviction Type:1 LSID:19869
I: 580033 [SC]SecureSession[0x20003698]: Moving from state 'kActive' --> 'kPendingEviction'
D: 580041 [IN]SecureSession[0x20003698]: Released - Type:1 LSID:19869
E: 580047 [SVR]Commissioning failed (attempt 1): 32
D: 580054 [IN]SecureSession[0x20003698]: Allocated Type:1 LSID:19870
D: 580060 [SC]Assigned local session key ID 19870
D: 580065 [SC]Waiting for PBKDF param request
D: 580069 [DL]CHIPoBLE advertising set to on
I: 580073 [DIS]Updating services using commissioning mode 1
D: 580078 [DL]Using Thread extended MAC for hostname.
D: 580083 [DL]Using Thread extended MAC for hostname.
I: 580088 [DIS]Advertise operational node 055AD343E2FE03B3-0000000000000002
E: 580095 [DIS]Failed to advertise operational node: 3
D: 580100 [DL]Using Thread extended MAC for hostname.
I: 580105 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=1
E: 580114 [DIS]Failed to advertise commissionable node: 3
E: 580120 [DIS]Failed to finalize service update: 1c
E: 580124 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 580129 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 580135 [IN]Expiring all sessions for fabric 0x1!!
E: 580140 [FP]Reverting pending fabric data for fabric 0x1
D: 580145 [EVL]LogEvent event number: 0x0000000000010003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000008DA31
D: 580159 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 580166 [FP]Warning: metadata not found during delete of fabric 0x1
I: 580181 [FP]Fabric (0x1) deleted.
I: 580184 [ZCL]UserLabel: Last Fabric index 0x1 was removed
I: 580190 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 580195 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 1dd08d3b
D: 580202 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 1dd08d3c
I: 580226 [TS]Pending Last Known Good Time: 2023-01-09T18:49:07
I: 580232 [TS]Previous Last Known Good Time: 2023-01-09T18:49:07
I: 580238 [TS]Reverted Last Known Good Time to previous value
D: 580244 [EVL]LogEvent event number: 0x0000000000010004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000008DA93
D: 580258 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 580264 [FP]Warning: metadata not found during delete of fabric 0x1
E: 580272 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 580278 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6169b47a
D: 580285 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
I: 580292 [NP]Reverting Thread operational dataset
E: 580304 [DL]Long dispatch time: 281 ms, for event type 32782
I: 580310 [FS]Fail-safe cleanly disarmed
I: 580315 [DL]CHIPoBLE advertising started
D: 580319 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 580325 [DL]   Device Role: DISABLED
D: 580328 [DL]   Thread Unicast Addresses:
D: 580332 [DL]        fd6c:e575:5e81:1:2190:1a2e:a672:a7da/64 valid preferred
D: 580340 [DL]OpenThread State Changed (Flags: 0x10000000)
E: Commissioning with a Thread network has not been done. An error occurred...
I: 580354 [DL]NFC Tag emulation started
I: 610319 [DL]CHIPoBLE advertising mode changed to slow

otbr-messages.log

[Oide Brett]

Hi Marte,

I got it working now. I did a ot-ctl reset and then a ot-ctl factory reset on the Open Thread Border Router (otbr) and restarted the otbr-agent and otbr-web service until I could see no formed network when I did ot-ctl dataset active -x

i then formed a new network and ran ot-ctl dataset active -x again to confirm that the thread network was formed.

That seemed to work for me.

Many thanks for your help

[Marte Myrvold]

Hi Oide,

Good to hear that you managed to solve the issue, and thanks for sharing how you solved it

I will mark this ticket as solved.

Best regards,

Marte