Error on commissioning step:operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout

[maheswara]

I am trying to test template sample application with nRF52840DK and see that commissioning fails

My environment:

nRF connect sdk:   v2.3.0

nRF connect toolchain:   v2.3.0

chip-tool running on ubuntu

border router: Raspberry Pi with nRf52840 Dongle

I see that BLE connection is successful, but fails  with error -Failed to perform commissioning step 18

Please see the attached file for logs

Appreciate your quick help

Thanks,

Mahesh

Fullscreen nRF52840dk.log Download

: 92797EEA6C7282EA._matterc._udp
E: 89539 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 89543 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 89549 [IN]Expiring all sessions for fabric 0x1!!
E: 89554 [FP]Reverting pending fabric data for fabric 0x1
D: 89559 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015DD7
D: 89573 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89580 [FP]Warning: metadata not found during delete of fabric 0x1
I: 89651 [FP]Fabric (0x1) deleted.
I: 89655 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 89660 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e3
D: 89667 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e4
I: 89832 [TS]Pending Last Known Good Time: 2023-02-18T10:14:41
I: 89838 [TS]Previous Last Known Good Time: 2023-02-18T10:14:41
I: 89844 [TS]Reverted Last Known Good Time to previous value
D: 89850 [EVL]LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015EF9
D: 89864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89870 [FP]Warning: metadata not found during delete of fabric 0x1
E: 89879 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 89884 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b98af9cc
D: 89891 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
I: 89898 [NP]Reverting Thread operational dataset
E: 89911 [DL]Long dispatch time: 460 ms, for event type 32782
I: 89916 [FS]Fail-safe cleanly disarmed
I: 89922 [DL]CHIPoBLE advertising started
D: 89926 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 89931 [DL]   Device Role: DISABLED
D: 89934 [DL]   Thread Unicast Addresses:
D: 89938 [DL]        fd6a:8c75:12d3:1:2d9d:1522:2c95:e401/64 valid preferred
D: 89946 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 119926 [DL]CHIPoBLE advertising mode changed to slow
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 3, 940
I: data wra: 3, 84c


uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 221 [DL]BLE address: F7:C4:D2:DA:E3:6F
I: 232 [DL]OpenThread started: OK
I: 235 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 241 [SVR]Server initializing...
I: 244 [TS]Last Known Good Time: 2023-02-18T10:14:41
I: 249 [TS]Setting Last Known Good Time to firmware build time 2023-03-09T08:28:35
I: 259 [DMG]AccessControl: initializing
I: 262 [DMG]Examples::AccessControlDelegate::Init
I: 266 [DMG]AccessControl: setting
I: 270 [DMG]DefaultAclStorage: initializing
I: 273 [DMG]DefaultAclStorage: 0 entries loaded
D: 278 [IN]UDP::Init bind&listen port=5540
E: 281 [IN]SO_REUSEPORT failed: 109
D: 285 [IN]UDP::Init bound to port=5540
D: 288 [IN]BLEBase::Init - setting/overriding transport
D: 293 [IN]TransportMgr initialized
I: 303 [ZCL]Using ZAP configuration...
I: 308 [DMG]AccessControlCluster: initializing
I: 312 [ZCL]Initiating Admin Commissioning cluster.
D: 319 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25692
I: 325 [DIS]Updating services using commissioning mode 1
I: 331 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 340 [DIS]Failed to advertise commissionable node: 3
E: 345 [DIS]Failed to finalize service update: 1c
I: 349 [DIS]Updating services using commissioning mode 1
I: 355 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 364 [DIS]Failed to advertise commissionable node: 3
E: 369 [DIS]Failed to finalize service update: 1c
I: 373 [DIS]Delaying proxy of operational discovery: missing delegate
I: 379 [IN]CASE Server enabling CASE session setups
D: 384 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:25693
I: 390 [SVR]Joining Multicast groups
I: 393 [SVR]Server Listening...
I: 396 [DL]Device Configuration:
I: 399 [DL]  Serial Number: 11223344556677889900
I: 404 [DL]  Vendor Id: 65521 (0xFFF1)
I: 407 [DL]  Product Id: 32768 (0x8000)
I: 411 [DL]  Hardware Version: 0
I: 415 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 420 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 427 [DL]  Manufacturing Date: (not set)
I: 431 [DL]  Device Type: 65535 (0xFFFF)
I: 436 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 440 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 446 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 455 [SVR]Manual pairing code: [34970112332]
I: 460 [DL]CHIP task running
I: 465 [DL]CHIPoBLE advertising started
I: 20280 [DL]BLE connection established (ConnId: 0x00)
I: 20285 [DL]Current number of connections: 1/1
I: 20289 [DL]CHIPoBLE advertising stopped
I: 21882 [BLE]local and remote recv window sizes = 5
I: 21886 [BLE]selected BTP version 4
I: 21890 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 21972 [IN]BLE EndPoint 0x2000fd28 Connection Complete
I: 21977 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 22063 [EM]>>> [E:32398r M:133325430] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 22076 [EM]<<< [E:32398r M:103602529] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 22087 [IN](U) Sending msg 103602529 to IP address 'BLE'
I: 22198 [EM]>>> [E:32398r M:133325431] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 24073 [EM]<<< [E:32398r M:103602530] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 24084 [IN](U) Sending msg 103602530 to IP address 'BLE'
E: 24089 [DL]Long dispatch time: 1891 ms, for event type 16388
I: 24223 [EM]>>> [E:32398r M:133325432] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 24234 [EM]<<< [E:32398r M:103602531] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 24245 [IN](U) Sending msg 103602531 to IP address 'BLE'
I: 24252 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive'
D: 24259 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:25692
D: 24266 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:25692 PSID:56322!
I: 24275 [SVR]Commissioning completed session establishment step
I: 24281 [DIS]Updating services using commissioning mode 0
I: 24287 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
E: 24296 [DIS]Failed to advertise extended commissionable node: 3
D: 24302 [DIS]Scheduling extended discovery timeout in 900s
E: 24307 [DIS]Failed to finalize service update: 1c
I: 24312 [SVR]Device completed Rendezvous process
I: 24319 [EM]>>> [E:32399r M:259258149] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 24329 [IM]Received Read request
I: 24338 [EM]<<< [E:32399r M:182183003] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 24348 [IN](S) Sending msg 182183003 on secure session with LSID: 25692
I: 24494 [EM]>>> [E:32400r M:259258150] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24505 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 24512 [EM]<<< [E:32400r M:182183004] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24523 [IN](S) Sending msg 182183004 on secure session with LSID: 25692
I: 24584 [EM]>>> [E:32401r M:259258151] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24597 [EM]<<< [E:32401r M:182183005] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24608 [IN](S) Sending msg 182183005 on secure session with LSID: 25692
I: 24674 [EM]>>> [E:32402r M:259258152] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24685 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 24694 [EM]<<< [E:32402r M:182183006] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24705 [IN](S) Sending msg 182183006 on secure session with LSID: 25692
I: 24944 [EM]>>> [E:32403r M:259258153] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24955 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 24964 [EM]<<< [E:32403r M:182183007] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24975 [IN](S) Sending msg 182183007 on secure session with LSID: 25692
I: 25214 [EM]>>> [E:32404r M:259258154] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25226 [ZCL]OpCreds: Received an AttestationRequest command
I: 25262 [ZCL]OpCreds: AttestationRequest successful.
I: 25270 [EM]<<< [E:32404r M:182183008] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25281 [IN](S) Sending msg 182183008 on secure session with LSID: 25692
I: 25619 [EM]>>> [E:32405r M:259258155] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25630 [ZCL]OpCreds: Received a CSRRequest command
I: 25820 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 25856 [ZCL]OpCreds: CSRRequest successful.
I: 25862 [EM]<<< [E:32405r M:182183009] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25873 [IN](S) Sending msg 182183009 on secure session with LSID: 25692
E: 25880 [DL]Long dispatch time: 262 ms, for event type 16388
I: 26204 [EM]>>> [E:32406r M:259258156] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26216 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 26279 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 26285 [EM]<<< [E:32406r M:182183010] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 26296 [IN](S) Sending msg 182183010 on secure session with LSID: 25692
E: 26303 [DL]Long dispatch time: 101 ms, for event type 16388
I: 26656 [EM]>>> [E:32407r M:259258157] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26667 [ZCL]OpCreds: Received an AddNOC command
I: 26674 [FP]Validating NOC chain
I: 26792 [FP]NOC chain validation successful
I: 26796 [FP]Added new fabric at index: 0x1
I: 26800 [FP]Assigned compressed fabric ID: 0x78D8657DCCA52CBD, node ID: 0x0000000000000001
I: 26808 [TS]Last Known Good Time: 2023-03-09T08:28:35
I: 26813 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 26819 [TS]Retaining current Last Known Good Time
I: 27015 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 27024 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 27030 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 27038 [EM]<<< [E:32407r M:182183011] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27048 [IN](S) Sending msg 182183011 on secure session with LSID: 25692
E: 27055 [DL]Long dispatch time: 402 ms, for event type 16388
I: 27106 [EM]>>> [E:32408r M:259258158] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 27123 [EM]<<< [E:32408r M:182183012] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27134 [IN](S) Sending msg 182183012 on secure session with LSID: 25692
I: 27194 [EM]>>> [E:32409r M:259258159] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28666 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
I: 28679 [EM]<<< [E:32409r M:182183013] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28690 [IN](S) Sending msg 182183013 on secure session with LSID: 25692
I: 28697 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 28704 [SVR]Operational advertising enabled
I: 29450 [DIS]Setting operational delegate post init
I: 29458 [SWU]Stopping the watchdog timer
I: 29462 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 29468 [DIS]Updating services using commissioning mode 0
I: 29473 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 29480 [DL]advertising srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 29489 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 29499 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 73766 [IN]Clearing BLE pending packets.
I: 73770 [BLE]Releasing end point's BLE connection back to application.
I: 73776 [DL]Closing BLE GATT connection (ConnId 00)
I: 73901 [DL]BLE GAP connection terminated (reason 0x16)
I: 73906 [DL]Current number of connections: 0/1
I: 84511 [FS]Fail-safe timer expired
E: 84514 [SVR]Failsafe timer expired
D: 84518 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:25692
I: 84524 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction'
D: 84532 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25692
E: 84538 [SVR]Commissioning failed (attempt 1): 32
D: 84545 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25694
I: 84551 [DIS]Updating services using commissioning mode 1
I: 84556 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 84564 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84574 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
E: 84580 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 84584 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 84591 [IN]Expiring all sessions for fabric 0x1!!
E: 84595 [FP]Reverting pending fabric data for fabric 0x1
E: 84601 [FP]Warning: metadata not found during delete of fabric 0x1
I: 84612 [FP]Fabric (0x1) deleted.
I: 84615 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 84620 [DIS]Updating services using commissioning mode 1
I: 84626 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84635 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
I: 84642 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 84769 [TS]Pending Last Known Good Time: 2023-03-09T08:28:35
I: 84775 [TS]Previous Last Known Good Time: 2023-03-09T08:28:35
I: 84781 [TS]Reverted Last Known Good Time to previous value
E: 84787 [FP]Warning: metadata not found during delete of fabric 0x1
E: 84795 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 84801 [NP]Reverting Thread operational dataset
E: 84813 [DL]Long dispatch time: 299 ms, for event type 32782
I: 84818 [FS]Fail-safe cleanly disarmed
I: 84823 [DL]CHIPoBLE advertising started
I: 114827 [DL]CHIPoBLE advertising mode changed to slow
I: 114834 [DL]CHIPoBLE advertising started
I: 900318 [SVR]Closing pairing window
D: 900321 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25694
I: 900327 [DIS]Updating services using commissioning mode 0
I: 900333 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 900343 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 900349 [DIS]Scheduling extended discovery timeout in 900s
I: 900354 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 900362 [DL]CHIPoBLE advertising stopped

chip-tool.log

[Priyanka]

Hi Mahesh,

I have contacted internally regarding the issue and will get back to you as soon as I get a response.

Best Regards,

Priyanka

[maheswara]

Any update on this issue?

[maheswara]

Need help with this quickly

[Priyanka]

Hi,

I understand that it's an urgent issue and I have relayed it internally as well. Please do bear with us and will get back to you by next week.

-Priyanka

[Priyanka]

It looks like you have not set RIO on wifi interface in Ubuntu, which is required in order to get communication, according to the OpenThread Border Router documentation. Please try to follow the steps mentioned in the documentation exactly.

-Priyanka

[maheswara]

Thanks for the quick response.

$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra
1
$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra_rt_info_max_plen
64
$ifconfig wlx18a6f712c1ee
wlx18a6f712c1ee: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.100.170 netmask 255.255.255.0 broadcast 192.168.100.255
inet6 fe80::51bd:e05f:3127:2b5e prefixlen 64 scopeid 0x20<link>
inet6 fdde:ad00:beef:cafe:1aa6:f7ff:fe12:c1ee prefixlen 64 scopeid 0x0<global>
inet6 fdde:ad00:beef:cafe:ec12:ad5b:5aa7:41d prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:f903:9af6:420a:321 prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:1aa6:f7ff:fe12:c1ee prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:ab68:9cb6:c799:9f9f prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa::ad2 prefixlen 128 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:10b7:9573:6508:a924 prefixlen 64 scopeid 0x0<global>
ether 18:a6:f7:12:c1:ee txqueuelen 1000 (Ethernet)
RX packets 84961 bytes 67576011 (67.5 MB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 58154 bytes 11608576 (11.6 MB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

As suggested I have configured RA settings, Above is the dump from the ubuntu PC

[maheswara]

Any update on this. Appreciate quick help

[Priyanka]

Hi Mahesh,

I was on sick leave and will take a look into this today. I will get back to you tomorrow with a response. But were you able to reproduce the issues on the configured environment?

-Priyanka

[maheswara]

I already had the  RA setting on my ubuntu as below

$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra

1

$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra_rt_info_max_plen

64

[Priyanka]

Okay. I will just discuss with the internal team and get back to you.

-Priyanka

[Priyanka]

Hi Mahesh,

I have heard back from the team and they say that you have, under Raspberrypi hyperlink, set link to the setup border router for v2.0.1 not v2.3.0, if you made a mistake providing link.

However they went through whole setup of Border Router on RaspberryPi for NCS v2.3.0 version and these are their steps. They were able to successfully commission the template sample to the Matter:

PC - device with ubuntu to run chip-tool
RaspberryPi - Border Router

- Flash on sd card ubuntu 22.04.02LTS (64-BIT)
- Insert SD card to Raspberry Pi 4
- Connect raspberry to the network (e.g. WiFi)
- clone ot-br-posix: `git clone github.com/.../ot-br-posix.git`
- move to repo: `cd ot-br-posix`
- checkout to recommended ot-br-posix revision for NCS 2.3.0: `git checkout a892bf7`
- run bootstrap: `./script/bootstrap`
- run setup on connected interface: `INFRA_IF_NAME=wlan0 ./script/setup`
- build and flash RCP from NCS v2.3.0 based on below documentation:
developer.nordicsemi.com/.../tools.html
- insert flashed RCP to raspberry Pi
- to the `/etc/default/otbr-agent` specify baudrate by updating `spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=1000000`
- restart obtr-agent service `sudo service otbr-agent restart`
- form network: openthread.io/.../openthread-border-router
- build and flash Matter example from v2.3.0 version
- download chip-tool from: github.com/.../v2.3.0
- connect PC (on which chip-tool will be run) to the same network as Border Router
- on PC setup RA/RIO for me it is (wlo1 interface):
`sudo sysctl -w net.ipv6.conf.wlo1.accept_ra=1` # should be at least 1 if ip forwarding is not enabled, and 2 otherwise.
`sudo sysctl -w net.ipv6.conf.wlo1.accept_ra_rt_info_max_plen=64`
- get dataset from border router: `sudo ot-ctl dataset active -x`
- on the PC run commissioning procedure using chip-tool: `./chip-tool-debug pairing ble-thread 1 hex:<dataset from previous step> 20202021 3840`

The difference between border router setup for version 2.0.1 and 2.3.0 is only in revision of ot-br-posix revision:

v2.0.1 - 4b04548

v2.3.0 - a892bf7

[maheswara]

Thanks for the detailed steps, able to commission the device, 

I am using the light bulb sample and see the UNSUPPORTED_CLUSTER, But isn't this expected to work on light bulb sample because it has ON_OFF_CLUSTER

./chip-tool-debug onoff toggle 1 0
[1680624583.358078][11363:11363] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1680624583.358555][11363:11363] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1680624583.358700][11363:11363] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1680624583.358825][11363:11363] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1680624583.359182][11363:11363] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-KtEucA)
[1680624583.359686][11363:11363] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1680624583.359741][11363:11363] CHIP:DL: NVS set: chip-counters/reboot-count = 30 (0x1E)
[1680624583.360345][11363:11363] CHIP:DL: Got Ethernet interface: enp4s0
[1680624583.360662][11363:11363] CHIP:DL: Found the primary Ethernet interface:enp4s0
[1680624583.360981][11363:11363] CHIP:DL: Got WiFi interface: wlx18a6f712c1ee
[1680624583.361340][11363:11363] CHIP:DL: Found the primary WiFi interface:wlx18a6f712c1ee
[1680624583.361390][11363:11363] CHIP:IN: UDP::Init bind&listen port=0
[1680624583.361464][11363:11363] CHIP:IN: UDP::Init bound to port=36923
[1680624583.361483][11363:11363] CHIP:IN: UDP::Init bind&listen port=0
[1680624583.361546][11363:11363] CHIP:IN: UDP::Init bound to port=33931
[1680624583.361571][11363:11363] CHIP:IN: BLEBase::Init - setting/overriding transport
[1680624583.361595][11363:11363] CHIP:IN: TransportMgr initialized
[1680624583.361635][11363:11363] CHIP:FP: Initializing FabricTable from persistent storage
[1680624583.361790][11363:11363] CHIP:TS: Last Known Good Time: 2023-03-02T09:25:05
[1680624583.362254][11363:11363] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x086DE1578C0F3AC0, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1680624583.363904][11363:11363] CHIP:ZCL: Using ZAP configuration...
[1680624583.372593][11363:11363] CHIP:DL: Avahi client registered
[1680624583.375206][11363:11363] CHIP:CTL: System State Initialized...
[1680624583.375294][11363:11363] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1680624583.375338][11363:11363] CHIP:CTL: Setting attestation nonce to random value
[1680624583.375365][11363:11363] CHIP:CTL: Setting CSR nonce to random value
[1680624583.375613][11363:11365] CHIP:DL: CHIP task running
[1680624583.375747][11363:11365] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1680624583.376030][11363:11365] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1680624583.376078][11363:11365] CHIP:CTL: Setting attestation nonce to random value
[1680624583.376115][11363:11365] CHIP:CTL: Setting CSR nonce to random value
[1680624583.388524][11363:11365] CHIP:CTL: Generating NOC
[1680624583.402685][11363:11365] CHIP:FP: Validating NOC chain
[1680624583.452410][11363:11365] CHIP:FP: NOC chain validation successful
[1680624583.452468][11363:11365] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1680624583.452492][11363:11365] CHIP:TS: Last Known Good Time: 2023-03-02T09:25:05
[1680624583.452530][11363:11365] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1680624583.452545][11363:11365] CHIP:TS: Retaining current Last Known Good Time
[1680624583.456235][11363:11365] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1680624583.457799][11363:11365] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-02T09:25:05
[1680624583.459243][11363:11365] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 086DE1578C0F3AC0)
[1680624583.467393][11363:11365] CHIP:TOO: Sending command to node 0x1
[1680624583.467849][11363:11365] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1680624583.467908][11363:11365] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1680624583.468002][11363:11365] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1680624583.468056][11363:11365] CHIP:DIS: Resolving 086DE1578C0F3AC0:0000000000000001 ...
[1680624583.668251][11363:11365] CHIP:DIS: Checking node lookup status after 200 ms
[1680624584.570112][11363:11364] CHIP:DL: Got IP address on interface: wlx18a6f712c1ee IP: 192.168.100.170
[1680624584.570278][11363:11365] CHIP:DL: HandlePlatformSpecificBLEEvent 32770
[1680624585.825619][11363:11365] CHIP:DL: Avahi resolve found
[1680624585.825719][11363:11365] CHIP:DIS: Node ID resolved for 086DE1578C0F3AC0:0000000000000001
[1680624585.825749][11363:11365] CHIP:DIS: Hostname: FEB215FCE7C67565
[1680624585.825779][11363:11365] CHIP:DIS: IP Address #1: fda2:e8de:96ff:1:f037:6392:9fa0:b4d2
[1680624585.825803][11363:11365] CHIP:DIS: Port: 5540
[1680624585.825830][11363:11365] CHIP:DIS: Mrp Interval idle: 1000 ms
[1680624585.825856][11363:11365] CHIP:DIS: Mrp Interval active: 1000 ms
[1680624585.825877][11363:11365] CHIP:DIS: TCP Supported: 0
[1680624585.826289][11363:11365] CHIP:DIS: Lookup clearing interface for non LL address
[1680624585.826385][11363:11365] CHIP:DIS: UDP:[fda2:e8de:96ff:1:f037:6392:9fa0:b4d2%wlx18a6f712c1ee]:5540: new best score: 4
[1680624585.826413][11363:11365] CHIP:DIS: Checking node lookup status after 2359 ms
[1680624585.826449][11363:11365] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fda2:e8de:96ff:1:f037:6392:9fa0:b4d2]:5540 while in state 2
[1680624585.826480][11363:11365] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1680624585.826572][11363:11365] CHIP:IN: SecureSession[0x7fcb900098e0]: Allocated Type:2 LSID:27275
[1680624585.826615][11363:11365] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1680624585.846806][11363:11365] CHIP:EM: <<< [E:52976i M:73333447] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1680624585.846877][11363:11365] CHIP:IN: (U) Sending msg 73333447 to IP address 'UDP:[fda2:e8de:96ff:1:f037:6392:9fa0:b4d2]:5540'
[1680624585.847047][11363:11365] CHIP:SC: Sent Sigma1 msg
[1680624585.847075][11363:11365] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1680624585.929648][11363:11365] CHIP:EM: >>> [E:52976i M:158236512 (Ack:73333447)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1680624585.929691][11363:11365] CHIP:EM: Found matching exchange: 52976i, Delegate: 0x7fcb9000cf68
[1680624585.929725][11363:11365] CHIP:EM: Rxd Ack; Removing MessageCounter:73333447 from Retrans Table on exchange 52976i
[1680624586.284977][11363:11365] CHIP:EM: >>> [E:52976i M:158236513 (Ack:73333447)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1680624586.285019][11363:11365] CHIP:EM: Found matching exchange: 52976i, Delegate: 0x7fcb9000cf68
[1680624586.285040][11363:11365] CHIP:EM: CHIP MessageCounter:73333447 not in RetransTable on exchange 52976i
[1680624586.285080][11363:11365] CHIP:SC: Received Sigma2 msg
[1680624586.285109][11363:11365] CHIP:SC: Peer assigned session session ID 20958
[1680624586.378234][11363:11365] CHIP:SC: Found MRP parameters in the message
[1680624586.378285][11363:11365] CHIP:SC: Sending Sigma3
[1680624586.390879][11363:11365] CHIP:EM: <<< [E:52976i M:73333448 (Ack:158236513)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1680624586.390989][11363:11365] CHIP:IN: (U) Sending msg 73333448 to IP address 'UDP:[fda2:e8de:96ff:1:f037:6392:9fa0:b4d2%wlx18a6f712c1ee]:5540'
[1680624586.391155][11363:11365] CHIP:SC: Sent Sigma3 msg
[1680624586.497581][11363:11365] CHIP:EM: >>> [E:52976i M:158236514 (Ack:73333448)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1680624586.497650][11363:11365] CHIP:EM: Found matching exchange: 52976i, Delegate: 0x7fcb9000cf68
[1680624586.497739][11363:11365] CHIP:EM: Rxd Ack; Removing MessageCounter:73333448 from Retrans Table on exchange 52976i
[1680624586.807150][11363:11365] CHIP:EM: >>> [E:52976i M:158236515 (Ack:73333448)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1680624586.807194][11363:11365] CHIP:EM: Found matching exchange: 52976i, Delegate: 0x7fcb9000cf68
[1680624586.807222][11363:11365] CHIP:EM: CHIP MessageCounter:73333448 not in RetransTable on exchange 52976i
[1680624586.807270][11363:11365] CHIP:SC: Success status report received. Session was established
[1680624586.810497][11363:11365] CHIP:SC: SecureSession[0x7fcb900098e0]: Moving from state 'kEstablishing' --> 'kActive'
[1680624586.810543][11363:11365] CHIP:IN: SecureSession[0x7fcb900098e0]: Activated - Type:2 LSID:27275
[1680624586.810570][11363:11365] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:27275 PSID:20958!
[1680624586.810592][11363:11365] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1680624586.810637][11363:11365] CHIP:TOO: Sending cluster (0x00000006) command (0x00000002) on endpoint 0
[1680624586.810737][11363:11365] CHIP:DMG: ICR moving to [AddingComm]
[1680624586.810782][11363:11365] CHIP:DMG: ICR moving to [AddedComma]
[1680624586.810914][11363:11365] CHIP:EM: <<< [E:52977i M:217785115] (S) Msg TX to 1:0000000000000001 [3AC0] --- Type 0001:08 (IM:InvokeCommandRequest)
[1680624586.810948][11363:11365] CHIP:IN: (S) Sending msg 217785115 on secure session with LSID: 27275
[1680624586.811152][11363:11365] CHIP:DMG: ICR moving to [CommandSen]
[1680624586.811234][11363:11365] CHIP:EM: <<< [E:52976i M:73333449 (Ack:158236515)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1680624586.811371][11363:11365] CHIP:IN: (U) Sending msg 73333449 to IP address 'UDP:[fda2:e8de:96ff:1:f037:6392:9fa0:b4d2%wlx18a6f712c1ee]:5540'
[1680624586.811478][11363:11365] CHIP:EM: Flushed pending ack for MessageCounter:158236515 on exchange 52976i
[1680624586.887155][11363:11365] CHIP:EM: >>> [E:52977i M:31688150 (Ack:217785115)] (S) Msg RX from 1:0000000000000001 [3AC0] --- Type 0001:09 (IM:InvokeCommandResponse)
[1680624586.887217][11363:11365] CHIP:EM: Found matching exchange: 52977i, Delegate: 0x7fcb900090f8
[1680624586.887273][11363:11365] CHIP:EM: Rxd Ack; Removing MessageCounter:217785115 from Retrans Table on exchange 52977i
[1680624586.887311][11363:11365] CHIP:DMG: ICR moving to [ResponseRe]
[1680624586.887386][11363:11365] CHIP:DMG: InvokeResponseMessage =
[1680624586.887410][11363:11365] CHIP:DMG: {
[1680624586.887434][11363:11365] CHIP:DMG: suppressResponse = false,
[1680624586.887455][11363:11365] CHIP:DMG: InvokeResponseIBs =
[1680624586.887483][11363:11365] CHIP:DMG: [
[1680624586.887506][11363:11365] CHIP:DMG: InvokeResponseIB =
[1680624586.887532][11363:11365] CHIP:DMG: {
[1680624586.887555][11363:11365] CHIP:DMG: CommandStatusIB =
[1680624586.887577][11363:11365] CHIP:DMG: {
[1680624586.887604][11363:11365] CHIP:DMG: CommandPathIB =
[1680624586.887630][11363:11365] CHIP:DMG: {
[1680624586.887659][11363:11365] CHIP:DMG: EndpointId = 0x0,
[1680624586.887699][11363:11365] CHIP:DMG: ClusterId = 0x6,
[1680624586.887739][11363:11365] CHIP:DMG: CommandId = 0x2,
[1680624586.887765][11363:11365] CHIP:DMG: },
[1680624586.887794][11363:11365] CHIP:DMG:
[1680624586.887819][11363:11365] CHIP:DMG: StatusIB =
[1680624586.887843][11363:11365] CHIP:DMG: {
[1680624586.887869][11363:11365] CHIP:DMG: status = 0xc3 (UNSUPPORTED_CLUSTER),
[1680624586.887893][11363:11365] CHIP:DMG: },
[1680624586.887919][11363:11365] CHIP:DMG:
[1680624586.887943][11363:11365] CHIP:DMG: },
[1680624586.887968][11363:11365] CHIP:DMG:
[1680624586.887993][11363:11365] CHIP:DMG: },
[1680624586.888018][11363:11365] CHIP:DMG:
[1680624586.888041][11363:11365] CHIP:DMG: ],
[1680624586.888067][11363:11365] CHIP:DMG:
[1680624586.888091][11363:11365] CHIP:DMG: InteractionModelRevision = 1
[1680624586.888111][11363:11365] CHIP:DMG: },
[1680624586.888165][11363:11365] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0006 Command=0x0000_0002 Status=0xc3
[1680624586.888201][11363:11365] CHIP:TOO: Error: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER)
[1680624586.888238][11363:11365] CHIP:DMG: ICR moving to [AwaitingDe]
[1680624586.888352][11363:11365] CHIP:EM: <<< [E:52977i M:217785116 (Ack:31688150)] (S) Msg TX to 1:0000000000000001 [3AC0] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1680624586.888392][11363:11365] CHIP:IN: (S) Sending msg 217785116 on secure session with LSID: 27275
[1680624586.888614][11363:11365] CHIP:EM: Flushed pending ack for MessageCounter:31688150 on exchange 52977i
[1680624586.888897][11363:11363] CHIP:CTL: Shutting down the commissioner
[1680624586.888957][11363:11363] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1680624586.888976][11363:11363] CHIP:CTL: Shutting down the controller
[1680624586.888996][11363:11363] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1680624586.889012][11363:11363] CHIP:IN: SecureSession[0x7fcb900098e0]: MarkForEviction Type:2 LSID:27275
[1680624586.889028][11363:11363] CHIP:SC: SecureSession[0x7fcb900098e0]: Moving from state 'kActive' --> 'kPendingEviction'
[1680624586.889045][11363:11363] CHIP:IN: SecureSession[0x7fcb900098e0]: Released - Type:2 LSID:27275
[1680624586.889066][11363:11363] CHIP:FP: Forgetting fabric 0x1
[1680624586.889095][11363:11363] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1680624586.889244][11363:11363] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1680624586.889266][11363:11363] CHIP:TS: Reverted Last Known Good Time to previous value
[1680624586.889292][11363:11363] CHIP:CTL: Shutting down the commissioner
[1680624586.889308][11363:11363] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1680624586.889324][11363:11363] CHIP:CTL: Shutting down the controller
[1680624586.889337][11363:11363] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1680624586.890774][11363:11363] CHIP:DMG: IM WH moving to [Uninitialized]
[1680624586.890837][11363:11363] CHIP:DMG: IM WH moving to [Uninitialized]
[1680624586.890851][11363:11363] CHIP:DMG: IM WH moving to [Uninitialized]
[1680624586.890867][11363:11363] CHIP:DMG: IM WH moving to [Uninitialized]
[1680624586.890882][11363:11363] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1680624586.890959][11363:11363] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1680624586.891001][11363:11363] CHIP:FP: Shutting down FabricTable
[1680624586.891034][11363:11363] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1680624586.891162][11363:11363] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1680624586.891181][11363:11363] CHIP:TS: Reverted Last Known Good Time to previous value
[1680624586.891482][11363:11363] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-srjXDj)
[1680624586.892233][11363:11363] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1680624586.892404][11363:11363] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1680624586.892426][11363:11363] CHIP:DL: Inet Layer shutdown
[1680624586.892445][11363:11363] CHIP:DL: BLE shutdown
[1680624586.892463][11363:11363] CHIP:DL: System Layer shutdown
[1680624586.892835][11363:11363] CHIP:TOO: Run command failure: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER)