Matter over Thread Commissioning failed

[sbah]

Hi,

I want to test Matter over Thread, with the Light Bulb example from nRF Connect. The Border Router and controller are on the same device RPi4.

The border router is working properly and I was able to ping the border router from the light bulb and vis versa over Thread. However, after building successfully the CHIP, the Bluetooth connection is failing while doing the commissioning or pairing. Can you help please?   

 

Environment:

- Raspberry Pi4 with Ubuntu 22.04 as Chip-Tool (controller)

- Same RPi as Threat Border Router coupled with nRF52840 as radio co-processor

FROM THE CHIP CONTROLLER

FROM THE LIGHT BULB TERMINAL

There is a gap of 7s where a request from the controller was not fulfilled and the pairing ended on a timeout.

Can you help? 

[Amanda Hsieh]

Hi, 

You said that you are able to ping the border router from the light bulb and vice versa over Thread, but then you wrote that aren't able to commission the device to Thread. So, as I understood properly, you connect to the Thread network manually using ot commands (OpenThread CLI commands), right? And what does it mean that the client built CHIP? Is it Chip-Tool, or the light bulb example itself? Regarding the logs attached, it seems that the controller closed the BLE connection for some reason. In this case, I would suggest ensuring that you have the proper version of ChipTool which is appropriate to the version used in the nRF Connect example.

Regards,
Amanda H.

[sbah]

Hi,

• I used the ot commands to connect the light bulb to the border router. 
• By CHIP I meant the chip-tool on the RPi with Ubuntu 20.04 installed. 

How to check the compatibility of the Chip-Tool and the version of nRF connect? Which version ChipTool is compatible with which version of nRF connect example?

I also tried different approaches to commission: Over IP, with code payload or manual pairing code but all lamentably failed to commission the device.

[Amanda Hsieh]

Hi, 

You should use the corresponding version of sdk-connectedhomeip as the NCS version. 

If you still have the issue, please try NCS v2.4.0 and sdk-connectedhomeip v2.4.0. 

Regards,
Amanda H.

[sbah]

Hi Amanda,

I followed your recommendations and installed NCS v2.4.0 and sdk-connectedhomeip v2.4.0. After re-flashing the light bulb with the new firmware, I was able to do the commissioning. I was even able to add a new device (the light switch application) to the network. To make sure we were good, we have decided to reboot the RPi and retry the process again.

After, restarting the RPi, we were not able to do the pairing no more. However, the switch was still able to control the light bulb at a Thread connectivity level but we were not able to use the Chip-Tool controller on the RPi for any action. Can you look at the logs please?

/// Chip-Toll Terminal

router@poe:~/Downloads$ ./chip-tool-debug pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001ff
fe00208d212cd589cd14fa90708fd6822c97f6416d9051086c32410820706b7f5f8d09f86e67620030f4f70656e5468726561642d38656
26501028ebe04103dcb3c26d22d6465c38df0fdcd97013d0c0402a0f7f8 20202021 3840
[1686068195.100076][7127:7127] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1686068195.107827][7127:7127] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1686068195.108093][7127:7127] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1686068195.108215][7127:7127] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1686068195.108604][7127:7127] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-cYcHXj)
[1686068195.109334][7127:7127] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1686068195.109412][7127:7127] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6)
[1686068195.110103][7127:7127] CHIP:DL: Got Ethernet interface: eth0
[1686068195.110970][7127:7127] CHIP:DL: Found the primary Ethernet interface:eth0
[1686068195.111838][7127:7127] CHIP:DL: Got WiFi interface: wlan0
[1686068195.114356][7127:7127] CHIP:DL: Found the primary WiFi interface:wlan0
[1686068195.114454][7127:7127] CHIP:IN: UDP::Init bind&listen port=0
[1686068195.114702][7127:7127] CHIP:IN: UDP::Init bound to port=38872
[1686068195.114744][7127:7127] CHIP:IN: UDP::Init bind&listen port=0
[1686068195.114882][7127:7127] CHIP:IN: UDP::Init bound to port=45803
[1686068195.114913][7127:7127] CHIP:IN: BLEBase::Init - setting/overriding transport
[1686068195.114939][7127:7127] CHIP:IN: TransportMgr initialized
[1686068195.115020][7127:7127] CHIP:FP: Initializing FabricTable from persistent storage
[1686068195.119203][7127:7127] CHIP:TS: Last Known Good Time: 2023-06-06T11:59:48
[1686068195.120137][7127:7127] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x5B76ECB8E382716D, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1686068195.123820][7127:7127] CHIP:ZCL: Using ZAP configuration...
[1686068195.129706][7127:7127] CHIP:DL: Avahi re-register required
[1686068195.131470][7127:7127] CHIP:DIS: Delaying proxy of operational discovery: missing delegate
[1686068195.132596][7127:7127] CHIP:CTL: System State Initialized...
[1686068195.134322][7127:7127] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1686068195.134432][7127:7127] CHIP:CTL: Setting attestation nonce to random value
[1686068195.134477][7127:7127] CHIP:CTL: Setting CSR nonce to random value
[1686068195.134891][7127:7129] CHIP:DL: CHIP task running
[1686068195.135134][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 32785
[1686068195.135499][7127:7129] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1686068195.135565][7127:7129] CHIP:CTL: Setting attestation nonce to random value
[1686068195.135610][7127:7129] CHIP:CTL: Setting CSR nonce to random value
[1686068195.151842][7127:7129] CHIP:CTL: Generating NOC
[1686068195.167561][7127:7129] CHIP:FP: Validating NOC chain
[1686068195.213742][7127:7129] CHIP:FP: NOC chain validation successful
[1686068195.213798][7127:7129] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1686068195.213824][7127:7129] CHIP:TS: Last Known Good Time: 2023-06-06T11:59:48
[1686068195.213842][7127:7129] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1686068195.213859][7127:7129] CHIP:TS: Retaining current Last Known Good Time
[1686068195.217179][7127:7129] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1686068195.220288][7127:7129] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-06T11:59:48
[1686068195.223472][7127:7129] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 5B76ECB8E382716D)
[1686068195.247243][7127:7129] CHIP:CTL: Setting thread operational dataset from parameters
[1686068195.247288][7127:7129] CHIP:CTL: Setting attestation nonce to random value
[1686068195.247323][7127:7129] CHIP:CTL: Setting CSR nonce to random value
[1686068195.247349][7127:7129] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1686068195.247373][7127:7129] CHIP:DL: Long dispatch time: 112 ms, for event type 2
[1686068195.252124][7127:7128] CHIP:DL: TRACE: Bus acquired for name C-1bd7
[1686068195.263941][7127:7129] CHIP:DL: PlatformBlueZInit init success
[1686068195.270425][7127:7128] CHIP:BLE: BLE removing known devices.
[1686068195.272584][7127:7128] CHIP:BLE: BLE initiating scan.
[1686068195.286518][7127:7128] CHIP:BLE: Device 4E:02:37:33:B9:D2 does not look like a CHIP device.
[1686068195.310846][7127:7128] CHIP:BLE: Device 08:13:59:97:4C:D8 does not look like a CHIP device.
[1686068195.320992][7127:7128] CHIP:BLE: Device E2:04:42:00:11:23 does not look like a CHIP device.
[1686068195.345877][7127:7128] CHIP:BLE: Device 59:77:17:AA:0B:CA does not look like a CHIP device.
[1686068195.349683][7127:7128] CHIP:BLE: Device 0E:10:ED:68:E0:76 does not look like a CHIP device.
[1686068195.371781][7127:7128] CHIP:BLE: Device 02:45:7D:1E:7E:99 does not look like a CHIP device.
[1686068195.443099][7127:7128] CHIP:BLE: Device 68:34:B8:10:EF:62 does not look like a CHIP device.
[1686068195.447233][7127:7128] CHIP:BLE: New device scanned: D9:0B:A2:F3:3E:C0
[1686068195.447332][7127:7128] CHIP:BLE: Device discriminator match. Attempting to connect.
[1686068195.831658][7127:7128] CHIP:DL: ConnectDevice complete
[1686068197.408470][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408520][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408550][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408570][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408595][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408615][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408646][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408666][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408690][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408709][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408739][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408758][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408780][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408799][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408822][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408842][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408869][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408888][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408910][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408928][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408950][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0001
[1686068197.408969][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.408997][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.409017][7127:7128] CHIP:DL: Char1 /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0/service0010
[1686068197.409044][7127:7128] CHIP:DL: New BLE connection 0xffff9c04d190, device D9:0B:A2:F3:3E:C0, path /org/bluez/hci0/dev_D9_0B_A2_F3_3E_C0
[1686068197.409162][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1686068197.409198][7127:7129] CHIP:DIS: Closing all BLE connections
[1686068197.409280][7127:7129] CHIP:IN: BleConnectionComplete: endPoint 0xaaaabd510aa0
[1686068197.409659][7127:7129] CHIP:IN: SecureSession[0xffff940095a0]: Allocated Type:1 LSID:15869
[1686068197.409697][7127:7129] CHIP:SC: Assigned local session key ID 15869
[1686068197.409887][7127:7129] CHIP:EM: <<< [E:63865i S:0 M:49376378] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1686068197.409959][7127:7129] CHIP:IN: (U) Sending msg 49376378 to IP address 'BLE'
[1686068197.409990][7127:7129] CHIP:IN: Message appended to BLE send queue
[1686068197.410013][7127:7129] CHIP:SC: Sent PBKDF param request
[1686068197.730382][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686068197.823623][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1686068197.823751][7127:7129] CHIP:BLE: subscribe complete, ep = 0xaaaabd510aa0
[1686068197.823681][7127:7128] CHIP:DL: Indication received, conn = 0xffff9c04d190
[1686068197.824520][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686068197.824567][7127:7129] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1686068197.824603][7127:7129] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1686068197.824635][7127:7129] CHIP:BLE: local and remote recv window size = 5
[1686068197.825357][7127:7129] CHIP:IN: BLE EndPoint 0xaaaabd510aa0 Connection Complete
[1686068197.909831][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686068200.431839][7127:7128] CHIP:DL: Indication received, conn = 0xffff9c04d190
[1686068200.432156][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686068202.995274][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686068205.278857][7127:7129] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1686068205.471698][7127:7128] CHIP:DL: Indication received, conn = 0xffff9c04d190
[1686068205.472133][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686068206.661433][7127:7128] CHIP:DL: Got IP address on interface: wlan0 IP: 192.168.9.187
[1686068206.661807][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 32770
[1686068208.035673][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686068209.269745][7127:7129] CHIP:DL: Avahi re-register required
[1686068209.280894][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 32785
[1686068209.280992][7127:7129] CHIP:DL: Avahi re-register required
[1686068209.283103][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 32785
[1686068210.511976][7127:7128] CHIP:DL: Indication received, conn = 0xffff9c04d190
[1686068210.512359][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686068213.075498][7127:7129] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686068214.412122][7127:7129] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1686068214.412235][7127:7129] CHIP:IN: SecureSession[0xffff940095a0]: Released - Type:1 LSID:15869
[1686068214.412301][7127:7129] CHIP:TOO: Secure Pairing Failed
[1686068214.412398][7127:7129] CHIP:DIS: Closing all BLE connections
[1686068214.412456][7127:7129] CHIP:IN: Clearing BLE pending packets.
[1686068214.413300][7127:7129] CHIP:BLE: Auto-closing end point's BLE connection.
[1686068214.413368][7127:7129] CHIP:DL: Closing BLE GATT connection (con 0xffff9c04d190)
[1686068214.413544][7127:7128] CHIP:DL: BluezDisconnect peer=D9:0B:A2:F3:3E:C0
[1686068214.744092][7127:7129] CHIP:TOO: Pairing Failure: src/protocols/secure_channel/PASESession.cpp:255: CHIP Error 0x00000032: Timeout
[1686068214.745745][7127:7127] CHIP:CTL: Shutting down the commissioner
[1686068214.745845][7127:7127] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1686068214.745878][7127:7128] CHIP:DL: Bluez disconnected
[1686068214.745905][7127:7127] CHIP:CTL: Shutting down the controller
[1686068214.746082][7127:7127] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1686068214.746203][7127:7127] CHIP:FP: Forgetting fabric 0x1
[1686068214.746279][7127:7127] CHIP:TS: Pending Last Known Good Time: 2023-06-06T11:59:48
[1686068214.746763][7127:7127] CHIP:TS: Previous Last Known Good Time: 2023-06-06T11:59:48
[1686068214.746919][7127:7127] CHIP:TS: Reverted Last Known Good Time to previous value
[1686068214.747078][7127:7127] CHIP:CTL: Shutting down the commissioner
[1686068214.747231][7127:7127] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1686068214.747106][7127:7128] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1686068214.747307][7127:7127] CHIP:CTL: Shutting down the controller
[1686068214.747475][7127:7127] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1686068214.750088][7127:7127] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1686068214.750394][7127:7127] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1686068214.750615][7127:7127] CHIP:FP: Shutting down FabricTable
[1686068214.750858][7127:7127] CHIP:TS: Pending Last Known Good Time: 2023-06-06T11:59:48
[1686068214.751210][7127:7127] CHIP:TS: Previous Last Known Good Time: 2023-06-06T11:59:48
[1686068214.751362][7127:7127] CHIP:TS: Reverted Last Known Good Time to previous value
[1686068214.752377][7127:7127] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-4o7MmR)
[1686068214.754195][7127:7127] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1686068214.754298][7127:7127] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1686068214.754325][7127:7127] CHIP:DL: Inet Layer shutdown
[1686068214.754343][7127:7127] CHIP:DL: BLE shutdown
[1686068214.755618][7127:7127] CHIP:DL: System Layer shutdown
[1686068214.756032][7127:7127] CHIP:TOO: Run command failure: src/protocols/secure_channel/PASESession.cpp:255: CHIP Error 0x00000032: Timeout
router@poe:~/Downloads$

//// Light bulb log

uart:~$ I: 2971321 [DL]BLE connection established (ConnId: 0x00)
I: 2971326 [DL]Current number of connections: 1/1
I: 2971331 [DL]CHIPoBLE advertising stopped
I: 2971334 [DL]NFC Tag emulation stopped
D: 2973057 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 2973065 [BLE]local and remote recv window sizes = 5
I: 2973069 [BLE]selected BTP version 4
I: 2973073 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 2973147 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 2973152 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 2973159 [IN]BLE EndPoint 0x2000a728 Connection Complete
I: 2973165 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 2973237 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 2973245 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 2973253 [EM]>>> [E:43941r S:0 M:162900743] (U) Msg RX from 0:F6B9AFCE0CFC788C [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 2975754 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 2975847 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 2978322 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 2980830 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 2980842 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 2980847 [IN]Clearing BLE pending packets.
I: 2980851 [BLE]Releasing end point's BLE connection back to application.
I: 2980857 [DL]Closing BLE GATT connection (ConnId 00)
D: 2980887 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 2980895 [BLE]no endpoint for BLE sent data ack
I: 2980977 [DL]BLE GAP connection terminated (reason 0x16)
I: 2980982 [DL]Current number of connections: 0/1
I: 2980989 [DL]CHIPoBLE advertising started
I: 2980995 [DL]NFC Tag emulation started

[Amanda Hsieh]

Hi, 

After adding the Light Bulb and Light Switch to the Matter network,  you cannot commission the devices again without performing the factory reset on them. If there is a connection between light-switch and light-bulb after RPi reboots it means that Thread Border Router works correctly and both devices are still in Matter(Thread) network. You can try to make a new CASE session with Light-Switch or Light-Bulb using chip-tool (for example chiptool_ncs onoff toggle {light_bulb_node_id} 1) instead of trying commission devices again, but it can be also impossible because chip tool saves the Matter fabric's data in the temp directory, which can be deleted during RPi restart and all information about the previous connection can be lost. To test whether everything works you should perform the factory reset on both devices, then restart RPi and try to commission both one more time.

-Amanda H.

[sbah]

Hi,

I have done the factory reset on both the border router and the light bulb before saving these logs you have right now. It is still not working. 

[Amanda Hsieh]

Hi, 

Do you use your own factory data, or have modified some of the original configs? It looks like the secure BLE session hasn't been established, and it is strange that it worked after the first flash. There might be also a problem with the Raspberry PI Bluetooth configuration. Could you please perform the same test on the desktop PC? How did you perform the factory reset of your device? Did you keep pressing a button for 10 seconds?

-Amanda H.