Chip tool debugging device error

[DoubleAmaing]

Hi，

I have a problem, please help me, I can't see where is the problem 。

refer to

Working with the CHIP Tool — Matter documentation (nRF Connect SDK) (nordicsemi.com)

Environment:

Raspberry Pie (Border Router)

router

PC (Win10) - VirtualBox (Ubuntu 22.04)

Board (Light_Blub)

Chih TooL: 

Using pre compiled, version 2.4.1

Releases · nrfconnect/sdk-connectedhomeip (github.com)

The error is as follows:

yd@yd-VirtualBox:~/chip-tool-linux_x64$ ./chip-tool-debug pairing ble-thread 1 hex:0e08000000000001000035060004001fffe00708fd5ea4308ad9f2d40c0402a0f7f8051000112233445566778899aabbccddeeff03104f70656e5468726561644d61747465720410b02285723920d515813e00fa447e4ec7000300000f0208111111112222222201021234 20202021 3840
[1693281548.188769][5543:5543] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1693281548.194245][5543:5543] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1693281548.194434][5543:5543] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1693281548.194632][5543:5543] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1693281548.195042][5543:5543] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rNwByq)
[1693281548.196393][5543:5543] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693281548.196433][5543:5543] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1693281548.196860][5543:5543] CHIP:DL: Got Ethernet interface: enp0s3
[1693281548.197063][5543:5543] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1693281548.197721][5543:5543] CHIP:DL: Failed to get WiFi interface
[1693281548.197791][5543:5543] CHIP:DL: Failed to reset WiFi statistic counts
[1693281548.198828][5543:5543] CHIP:IN: UDP::Init bind&listen port=0
[1693281548.198960][5543:5543] CHIP:IN: UDP::Init bound to port=34870
[1693281548.198969][5543:5543] CHIP:IN: UDP::Init bind&listen port=0
[1693281548.199010][5543:5543] CHIP:IN: UDP::Init bound to port=47444
[1693281548.199017][5543:5543] CHIP:IN: BLEBase::Init - setting/overriding transport
[1693281548.199020][5543:5543] CHIP:IN: TransportMgr initialized
[1693281548.199040][5543:5543] CHIP:FP: Initializing FabricTable from persistent storage
[1693281548.206252][5543:5543] CHIP:TS: Last Known Good Time: 2023-07-11T07:57:00
[1693281548.212065][5543:5543] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC3F8DB39D71B1829, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1693281548.216526][5543:5543] CHIP:ZCL: Using ZAP configuration...
[1693281548.220250][5543:5543] CHIP:DL: Avahi client registered
[1693281548.221826][5543:5543] CHIP:CTL: System State Initialized...
[1693281548.223314][5543:5543] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693281548.223357][5543:5543] CHIP:CTL: Setting attestation nonce to random value
[1693281548.223375][5543:5543] CHIP:CTL: Setting CSR nonce to random value
[1693281548.223642][5543:5545] CHIP:DL: CHIP task running
[1693281548.223761][5543:5545] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1693281548.223893][5543:5545] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693281548.224037][5543:5545] CHIP:CTL: Setting attestation nonce to random value
[1693281548.224061][5543:5545] CHIP:CTL: Setting CSR nonce to random value
[1693281548.229926][5543:5545] CHIP:CTL: Generating NOC
[1693281548.236726][5543:5545] CHIP:FP: Validating NOC chain
[1693281548.276048][5543:5545] CHIP:FP: NOC chain validation successful
[1693281548.276157][5543:5545] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1693281548.276350][5543:5545] CHIP:TS: Last Known Good Time: 2023-07-11T07:57:00
[1693281548.276435][5543:5545] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1693281548.276440][5543:5545] CHIP:TS: Retaining current Last Known Good Time
[1693281548.279811][5543:5545] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1693281548.283222][5543:5545] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-11T07:57:00
[1693281548.285262][5543:5545] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C3F8DB39D71B1829)
[1693281548.297085][5543:5545] CHIP:CTL: Setting thread operational dataset from parameters
[1693281548.297371][5543:5545] CHIP:CTL: Setting attestation nonce to random value
[1693281548.297960][5543:5545] CHIP:CTL: Setting CSR nonce to random value
[1693281548.297977][5543:5545] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1693281548.310807][5543:5544] CHIP:DL: TRACE: Bus acquired for name C-15a7
[1693281573.317555][5543:5544] CHIP:DL: FAIL: Error getting object manager client: Error calling StartServiceByName for org.bluez: Timeout was reached
[1693281573.318147][5543:5545] CHIP:DL: PlatformBlueZInit init success
[1693281573.318165][5543:5545] CHIP:DIS: Closing all BLE connections
[1693281573.318194][5543:5545] CHIP:BLE: No adapter available for new connection establishment
[1693281573.318201][5543:5545] CHIP:DL: Long dispatch time: 25021 ms, for event type 2
[1693281668.226041][5543:5543] CHIP:CTL: Shutting down the commissioner
[1693281668.226358][5543:5543] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693281668.226458][5543:5543] CHIP:CTL: Shutting down the controller
[1693281668.226471][5543:5543] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1693281668.226476][5543:5543] CHIP:FP: Forgetting fabric 0x1
[1693281668.226488][5543:5543] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:57:00
[1693281668.226557][5543:5543] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:57:00
[1693281668.226561][5543:5543] CHIP:TS: Reverted Last Known Good Time to previous value
[1693281668.226573][5543:5543] CHIP:CTL: Shutting down the commissioner
[1693281668.226576][5543:5543] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693281668.226579][5543:5543] CHIP:CTL: Shutting down the controller
[1693281668.226582][5543:5543] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1693281668.227063][5543:5543] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1693281668.227191][5543:5543] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1693281668.227207][5543:5543] CHIP:FP: Shutting down FabricTable
[1693281668.227214][5543:5543] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:57:00
[1693281668.227252][5543:5543] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:57:00
[1693281668.227257][5543:5543] CHIP:TS: Reverted Last Known Good Time to previous value
[1693281668.227409][5543:5543] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ed2AOW)
[1693281668.228819][5543:5543] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693281668.228932][5543:5543] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1693281668.228943][5543:5543] CHIP:DL: Inet Layer shutdown
[1693281668.228947][5543:5543] CHIP:DL: BLE shutdown

(process:5543): GLib-GObject-CRITICAL **: 12:01:08.228: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
[1693281668.229205][5543:5543] CHIP:DL: System Layer shutdown
[1693281668.229612][5543:5543] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:537: CHIP Error 0x00000032: Timeout

[AHaug]

Hi,

[1693281573.317555][5543:5544] CHIP:DL: FAIL: Error getting object manager client: Error calling StartServiceByName for org.bluez: Timeout was reached
[1693281573.318147][5543:5545] CHIP:DL: PlatformBlueZInit init success
[1693281573.318165][5543:5545] CHIP:DIS: Closing all BLE connections
[1693281573.318194][5543:5545] CHIP:BLE: No adapter available for new connection establishment

It looks like your VM does not have Bluetooth, which is why you can't find any available connection to establish. Are you able to verify if this is the case?

In general, I would recommend you to use a proper supported Linux distribution for Chip Tool as it is a bit tricky to get CHIP-tool to work on virtual machine. You will have to sort the bridging of Bluetooth and Wi-Fi, since the VM has a ethernet connection via the host by default and it does not have Bluetooth by default

Kind regards,
Andreas

[DoubleAmaing]

Hi, thank you.

I cannot solve the Bluetooth issue with VM.

So I used a Linux host (Ubuntu 22.04)

Execute commands： ./ Chip-tool-debug

I can see that the Cluster appears correctly.

However, when I ran the distribution network command, it encountered an error. Could you please help me take a look? Thank you。

yida@yida-ThinkPad-E470:~$ ./chip-tool-debug pairing ble-thread 1 hex:0e080000000000010000000300000d35060004001fffe00208ee7e4a2d48cdfd7e0708fd131483b543b1000510253bf95c157a90fe0984c54686572c74030f4f70656e5468726561642d643666370102d6f70410e2b8eaa64e39fc95ac12cc7b8757bd410c0402a0f7f8 20202021 3840
[1693455991.857097][4839:4839] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1693455991.857259][4839:4839] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1693455991.857292][4839:4839] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1693455991.857312][4839:4839] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1693455991.857419][4839:4839] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GRdMES)
[1693455991.857580][4839:4839] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693455991.857592][4839:4839] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1693455991.857767][4839:4839] CHIP:DL: Got Ethernet interface: enp4s0
[1693455991.857872][4839:4839] CHIP:DL: Found the primary Ethernet interface:enp4s0
[1693455991.857981][4839:4839] CHIP:DL: Got WiFi interface: wlp5s0
[1693455991.858096][4839:4839] CHIP:DL: Found the primary WiFi interface:wlp5s0
[1693455991.858111][4839:4839] CHIP:IN: UDP::Init bind&listen port=0
[1693455991.858167][4839:4839] CHIP:IN: UDP::Init bound to port=35531
[1693455991.858173][4839:4839] CHIP:IN: UDP::Init bind&listen port=0
[1693455991.858190][4839:4839] CHIP:IN: UDP::Init bound to port=60013
[1693455991.858194][4839:4839] CHIP:IN: BLEBase::Init - setting/overriding transport
[1693455991.858198][4839:4839] CHIP:IN: TransportMgr initialized
[1693455991.858210][4839:4839] CHIP:FP: Initializing FabricTable from persistent storage
[1693455991.858251][4839:4839] CHIP:TS: Last Known Good Time: 2023-07-11T07:53:58
[1693455991.858390][4839:4839] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x9E45793F71B1363E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1693455991.858814][4839:4839] CHIP:ZCL: Using ZAP configuration...
[1693455991.860751][4839:4839] CHIP:DL: Avahi client registered
[1693455991.861340][4839:4839] CHIP:CTL: System State Initialized...
[1693455991.861376][4839:4839] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693455991.861388][4839:4839] CHIP:CTL: Setting attestation nonce to random value
[1693455991.861395][4839:4839] CHIP:CTL: Setting CSR nonce to random value
[1693455991.861515][4839:4841] CHIP:DL: CHIP task running
[1693455991.861566][4839:4841] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1693455991.861642][4839:4841] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693455991.861651][4839:4841] CHIP:CTL: Setting attestation nonce to random value
[1693455991.861656][4839:4841] CHIP:CTL: Setting CSR nonce to random value
[1693455991.865085][4839:4841] CHIP:CTL: Generating NOC
[1693455991.868697][4839:4841] CHIP:FP: Validating NOC chain
[1693455991.884270][4839:4841] CHIP:FP: NOC chain validation successful
[1693455991.884290][4839:4841] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1693455991.884297][4839:4841] CHIP:TS: Last Known Good Time: 2023-07-11T07:53:58
[1693455991.884301][4839:4841] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1693455991.884305][4839:4841] CHIP:TS: Retaining current Last Known Good Time
[1693455991.884814][4839:4841] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1693455991.885274][4839:4841] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-11T07:53:58
[1693455991.885681][4839:4841] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 9E45793F71B1363E)
[1693455991.889681][4839:4841] CHIP:CTL: Setting thread operational dataset from parameters
[1693455991.889689][4839:4841] CHIP:CTL: Setting attestation nonce to random value
[1693455991.889695][4839:4841] CHIP:CTL: Setting CSR nonce to random value
[1693455991.889701][4839:4841] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1693455991.891513][4839:4840] CHIP:DL: TRACE: Bus acquired for name C-12e7
[1693455991.895595][4839:4841] CHIP:DL: PlatformBlueZInit init success
[1693455991.897811][4839:4840] CHIP:BLE: BLE removing known devices.
[1693455991.898425][4839:4840] CHIP:BLE: BLE initiating scan.
[1693455992.016874][4839:4841] CHIP:DL: Long dispatch time: 127 ms, for event type 2
[1693455992.136968][4839:4840] CHIP:BLE: Device 43:64:47:98:B2:6A does not look like a CHIP device.
[1693455992.139170][4839:4840] CHIP:BLE: Device 55:10:7D:B1:6C:94 does not look like a CHIP device.
[1693455992.144187][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455992.190893][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455992.192647][4839:4840] CHIP:BLE: Device 7B:3E:E8:FB:B9:E5 does not look like a CHIP device.
[1693455992.198519][4839:4840] CHIP:BLE: Device 4F:42:CC:FF:9D:AD does not look like a CHIP device.
[1693455992.237858][4839:4840] CHIP:BLE: Device 4A:97:7C:F4:F4:F1 does not look like a CHIP device.
[1693455992.244527][4839:4840] CHIP:BLE: Device D5:5B:3D:14:B3:8F does not look like a CHIP device.
[1693455992.302090][4839:4840] CHIP:BLE: Device 5E:1F:73:F2:C2:3F does not look like a CHIP device.
[1693455992.315487][4839:4840] CHIP:BLE: Device 35:29:5E:75:6B:ED does not look like a CHIP device.
[1693455992.385728][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455992.447875][4839:4840] CHIP:BLE: Device 55:10:7D:B1:6C:94 does not look like a CHIP device.
[1693455992.461133][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455992.476969][4839:4840] CHIP:BLE: Device 5F:03:20:5A:24:C4 does not look like a CHIP device.
[1693455992.535754][4839:4840] CHIP:BLE: Device 55:10:7D:B1:6C:94 does not look like a CHIP device.
[1693455992.562439][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455992.657832][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455992.675837][4839:4840] CHIP:BLE: Device C3:45:FB:8C:1A:33 does not look like a CHIP device.
[1693455992.739873][4839:4840] CHIP:BLE: Device 7B:3E:E8:FB:B9:E5 does not look like a CHIP device.
[1693455992.774767][4839:4840] CHIP:BLE: Device 4A:97:7C:F4:F4:F1 does not look like a CHIP device.
[1693455992.834091][4839:4840] CHIP:BLE: Device D5:F2:EA:48:13:47 does not look like a CHIP device.
[1693455992.886850][4839:4840] CHIP:BLE: Device 43:64:47:98:B2:6A does not look like a CHIP device.
[1693455992.930633][4839:4840] CHIP:BLE: Device 35:29:5E:75:6B:ED does not look like a CHIP device.
[1693455992.949098][4839:4840] CHIP:BLE: Device DB:9C:17:45:91:C0 does not look like a CHIP device.
[1693455992.983643][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455993.034911][4839:4840] CHIP:BLE: Device 35:29:5E:75:6B:ED does not look like a CHIP device.
[1693455993.223787][4839:4840] CHIP:BLE: Device 47:D0:1D:75:59:8C does not look like a CHIP device.
[1693455993.233188][4839:4840] CHIP:BLE: Device E9:D8:C3:FF:DB:BE does not look like a CHIP device.
[1693455993.260438][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455993.295423][4839:4840] CHIP:BLE: Device 7B:3E:E8:FB:B9:E5 does not look like a CHIP device.
[1693455993.305372][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455993.321427][4839:4840] CHIP:BLE: Device 4A:97:7C:F4:F4:F1 does not look like a CHIP device.
[1693455993.428689][4839:4840] CHIP:BLE: Device 43:64:47:98:B2:6A does not look like a CHIP device.
[1693455993.483470][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455993.560753][4839:4840] CHIP:BLE: Device 35:29:5E:75:6B:ED does not look like a CHIP device.
[1693455993.567996][4839:4840] CHIP:BLE: Device 4F:42:CC:FF:9D:AD does not look like a CHIP device.
[1693455993.749640][4839:4840] CHIP:BLE: Device D9:B1:89:CD:26:BC does not look like a CHIP device.
[1693455993.948121][4839:4840] CHIP:BLE: Device D2:D6:AF:FC:48:F7 does not look like a CHIP device.
[1693455993.948480][4839:4840] CHIP:BLE: Device F3:3D:4D:DB:DC:EE does not look like a CHIP device.
[1693455993.995691][4839:4840] CHIP:BLE: Device 35:29:5E:75:6B:ED does not look like a CHIP device.
[1693455994.125540][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455994.193786][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455994.308404][4839:4840] CHIP:BLE: Device 4F:42:CC:FF:9D:AD does not look like a CHIP device.
[1693455994.309306][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455994.398003][4839:4840] CHIP:BLE: Device 4F:42:CC:FF:9D:AD does not look like a CHIP device.
[1693455994.677452][4839:4840] CHIP:BLE: Device C3:45:FB:8C:1A:33 does not look like a CHIP device.
[1693455994.837861][4839:4840] CHIP:BLE: Device D5:F2:EA:48:13:47 does not look like a CHIP device.
[1693455995.176084][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455995.187870][4839:4840] CHIP:BLE: Device 02:67:D8:9B:04:BD does not look like a CHIP device.
[1693455995.227377][4839:4840] CHIP:BLE: Device 7B:3E:E8:FB:B9:E5 does not look like a CHIP device.
[1693455995.754318][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455995.755287][4839:4840] CHIP:BLE: Device D9:B1:89:CD:26:BC does not look like a CHIP device.
[1693455995.761597][4839:4840] CHIP:BLE: Device CF:AD:81:30:E7:BB does not look like a CHIP device.
[1693455995.770820][4839:4840] CHIP:BLE: Device 4F:42:CC:FF:9D:AD does not look like a CHIP device.
[1693455995.802829][4839:4840] CHIP:BLE: Device 7B:3E:E8:FB:B9:E5 does not look like a CHIP device.
[1693455995.803547][4839:4840] CHIP:BLE: Device 77:F8:C2:66:E0:EE does not look like a CHIP device.
[1693455995.810845][4839:4840] CHIP:BLE: Device 02:67:D8:9B:04:BD does not look like a CHIP device.
[1693455996.677254][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455996.678400][4839:4840] CHIP:BLE: Device C3:45:FB:8C:1A:33 does not look like a CHIP device.
[1693455997.478034][4839:4840] CHIP:BLE: Device E2:13:C2:7B:C0:70 does not look like a CHIP device.
[1693455998.197236][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455998.446706][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455998.625719][4839:4840] CHIP:BLE: Device 48:5F:74:67:2F:30 does not look like a CHIP device.
[1693455998.680855][4839:4840] CHIP:BLE: Device C3:45:FB:8C:1A:33 does not look like a CHIP device.
[1693455998.723092][4839:4840] CHIP:BLE: Device 5A:92:DF:03:CE:2E does not look like a CHIP device.
[1693455998.782864][4839:4840] CHIP:BLE: Device 52:B6:FE:0D:52:8E does not look like a CHIP device.
[1693455998.844840][4839:4840] CHIP:BLE: Device 4A:97:7C:F4:F4:F1 does not look like a CHIP device.
[1693455998.845869][4839:4840] CHIP:BLE: Device D5:F2:EA:48:13:47 does not look like a CHIP device.
[1693455999.001215][4839:4840] CHIP:BLE: New device scanned: CC:5E:B5:42:C3:48
[1693455999.001263][4839:4840] CHIP:BLE: Device discriminator match. Attempting to connect.
[1693456002.027697][4839:4841] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1693456009.009391][4839:4841] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1693456009.009445][4839:4841] CHIP:DIS: Closing all BLE connections
[1693456009.009636][4839:4840] CHIP:DL: FAIL: ConnectDevice : Operation was cancelled (19)
[1693456009.009853][4839:4841] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1693456111.861977][4839:4839] CHIP:CTL: Shutting down the commissioner
[1693456111.862036][4839:4839] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693456111.862062][4839:4839] CHIP:CTL: Shutting down the controller
[1693456111.862097][4839:4839] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1693456111.862125][4839:4839] CHIP:FP: Forgetting fabric 0x1
[1693456111.862163][4839:4839] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:53:58
[1693456111.862398][4839:4839] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:53:58
[1693456111.862427][4839:4839] CHIP:TS: Reverted Last Known Good Time to previous value
[1693456111.862470][4839:4839] CHIP:CTL: Shutting down the commissioner
[1693456111.862498][4839:4839] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693456111.862522][4839:4839] CHIP:CTL: Shutting down the controller
[1693456111.862541][4839:4839] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1693456111.863739][4839:4839] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1693456111.863833][4839:4839] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1693456111.863882][4839:4839] CHIP:FP: Shutting down FabricTable
[1693456111.863918][4839:4839] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:53:58
[1693456111.864103][4839:4839] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:53:58
[1693456111.864126][4839:4839] CHIP:TS: Reverted Last Known Good Time to previous value
[1693456111.864355][4839:4839] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-v57lyA)
[1693456111.865010][4839:4839] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693456111.865071][4839:4839] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1693456111.865095][4839:4839] CHIP:DL: Inet Layer shutdown
[1693456111.865114][4839:4839] CHIP:DL: BLE shutdown
[1693456111.865685][4839:4839] CHIP:DL: System Layer shutdown
[1693456111.866303][4839:4839] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:537: CHIP Error 0x00000032: Timeout

[DoubleAmaing]

Please help me take a look, thank you

[AHaug]

Hi,

A reply may some time take longer than a day. Please be patient.

Could you provide a device log as well?

From the output you've provided you can see that there is a scan error, even though your scanner finds a device at the end. When you find the device, this should stop the timer, but from the log it looks like the timer does not stop, which causes the timeout error you see and the cancellation of a BLE connection.

I don't know the reason for this, but the device log may provide some more hints.

Kind regards,
Andreas

[DoubleAmaing]

HI，

I still haven't solved the problem.

This is my own hardware, and I haven't brought out the UART port.

I can see the device 'MatterLight' on my computer;

Is there any other version available for me to ask questions about?

Can this be a problem with the border router?

[AHaug]

Hi Ethan,

If it is custom hardware there could be a multitude of reasons causing this issue and I am unable to make a qualified guess on what could be wrong with any precision. Device logs is unfortunately a must. Do you see the same behavior on a nRF52840DK or nRF5340DK? If you have one available, I suggest you start getting your setup working with one of these DKs before moving on to custom hardware to ensure that your setup is working properly and you don't have to debug both your hardware, firmware and the Matter network setup simultanously

DoubleAmaing said:

Can this be a problem with the border router?

There might be an issue with the OTBR. I recommend you to follow the steps in this documentation to see if you've set it up correctly https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/protocols/matter/getting_started/testing/index.html. For instance the first subpage where you have the controller and boarder router on separate devices: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/protocols/matter/getting_started/testing/thread_separate_otbr_linux_macos.html

Kind regards,
Andreas

[DoubleAmaing]

HI,

I bought J-Link and monitored communication through RTT. Below: Please help me take a look again, thank you.

nRF Terminal:

SEGGER J-Link V7.88j - Real time terminal output
SEGGER J-Link V10.1, SN=600105955
Process: JLinkExe
*** Booting Zephyr OS build v3.3.99-ncs1-1 ***
I: Init CHIP stack
I: 98 [DL]BLE address: FB:5A:2B:96:CD:50
I: 99 [DL]OpenThread started: OK
I: 99 [DL]Setting OpenThread device type to ROUTER
I: 99 [SVR]Subscription persistence not supported
I: 99 [SVR]Server initializing...
I: 99 [TS]Last Known Good Time: 2023-09-06T13:59:53
I: 100 [DMG]AccessControl: initializing
I: 100 [DMG]Examples::AccessControlDelegate::Init
I: 100 [DMG]AccessControl: setting
I: 100 [DMG]DefaultAclStorage: initializing
I: 100 [DMG]DefaultAclStorage: 0 entries loaded
D: 100 [IN]UDP::Init bind&listen port=5540
E: 100 [IN]SO_REUSEPORT failed: 109
D: 100 [IN]UDP::Init bound to port=5540
D: 100 [IN]BLEBase::Init - setting/overriding transport
D: 100 [IN]TransportMgr initialized
D: 102 [DL]Using Thread extended MAC for hostname.
I: 102 [ZCL]Using ZAP configuration...
I: 103 [DMG]AccessControlCluster: initializing
D: 103 [DL]Boot reason: 1
I: 103 [ZCL]Initiating Admin Commissioning cluster.
I: 103 [ZCL]Endpoint 1 On/off already set to new value
I: 103 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 103 [IN]SecureSession[0x20003320]: Allocated Type:1 LSID:33938
D: 103 [DL]CHIPoBLE advertising set to on
I: 103 [DIS]Updating services using commissioning mode 1
E: 104 [DIS]Failed to remove advertised services: 3
D: 104 [DL]Using Thread extended MAC for hostname.
I: 104 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 104 [DIS]Failed to advertise commissionable node: 3
E: 104 [DIS]Failed to finalize service update: 3
I: 104 [DIS]Updating services using commissioning mode 1
E: 104 [DIS]Failed to remove advertised services: 3
D: 104 [DL]Using Thread extended MAC for hostname.
I: 104 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 104 [DIS]Failed to advertise commissionable node: 3
E: 104 [DIS]Failed to finalize service update: 3
I: 104 [DIS]Delaying proxy of operational discovery: missing delegate
I: 104 [IN]CASE Server enabling CASE session setups
D: 104 [IN]SecureSession[0x200033d8]: Allocated Type:2 LSID:33939
I: 105 [SVR]Joining Multicast groups
I: 105 [SVR]Server Listening...
I: 105 [DL]Device Configuration:
I: 105 [DL]  Serial Number: 11223344556677889900
I: 105 [DL]  Vendor Id: 65521 (0xFFF1)
I: 105 [DL]  Product Id: 32773 (0x8005)
I: 105 [DL]  Product Name: not-specified
I: 105 [DL]  Hardware Version: 0
I: 105 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 105 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 105 [DL]  Manufacturing Date: (not set)
I: 105 [DL]  Device Type: 65535 (0xFFFF)
I: 105 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 105 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 108 [SVR]project-chip.github.io/.../qrcode.html
I: 108 [SVR]Manual pairing code: [34970112332]
I: 108 [DL]CHIP task running
I: 108 [DL]CHIPoBLE advertising started
I: 108 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 109 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 109 [DL]NFC Tag emulation started
E: SoftDevice Controller ASSERT: 48, 1319
E: ***** HARD FAULT *****
E:   Fault escalation (see below)
E: ARCH_EXCEPT with reason 3

E: r0/a1:  0x00000003  r1/a2:  0x2000faf8  r2/a3:  0x2000faf8
E: r3/a4:  0x20019114 r12/ip:  0x00000000 r14/lr:  0x0003b09f
E:  xpsr:  0x61000011
E: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
E: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
E: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
E: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
E: fpscr:  0x00000025
E: Faulting instruction address (r15/pc): 0x0003b0aa
E: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
E: Fault during interrupt handling

E: Current thread: 0x2000faf8 (idle)
E: Halting system

Chip-Tool-debug:

yida@yida-ThinkPad-E470:~/chip-tool/chip-tool-linux_x64$ ./chip-tool-debug pairing ble-thread 3 hex:0e08000000000001000035060004001fffe00708fd8cbda7fa852afe0c0402a0f7f8051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f0410445f2b5ca6f2a93a55ce570a70efeecb000300000f0208111111112222222201021234 20202021 3840
[1693981724.016457][61557:61557] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1693981724.016602][61557:61557] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1693981724.016636][61557:61557] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1693981724.016657][61557:61557] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1693981724.016732][61557:61557] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rI4tvR)
[1693981724.016856][61557:61557] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693981724.016868][61557:61557] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1693981724.017069][61557:61557] CHIP:DL: Got Ethernet interface: enp4s0
[1693981724.017213][61557:61557] CHIP:DL: Found the primary Ethernet interface:enp4s0
[1693981724.017358][61557:61557] CHIP:DL: Got WiFi interface: wlp5s0
[1693981724.017508][61557:61557] CHIP:DL: Found the primary WiFi interface:wlp5s0
[1693981724.017523][61557:61557] CHIP:IN: UDP::Init bind&listen port=0
[1693981724.017546][61557:61557] CHIP:IN: UDP::Init bound to port=59729
[1693981724.017552][61557:61557] CHIP:IN: UDP::Init bind&listen port=0
[1693981724.017572][61557:61557] CHIP:IN: UDP::Init bound to port=59118
[1693981724.017578][61557:61557] CHIP:IN: BLEBase::Init - setting/overriding transport
[1693981724.017584][61557:61557] CHIP:IN: TransportMgr initialized
[1693981724.017598][61557:61557] CHIP:FP: Initializing FabricTable from persistent storage
[1693981724.017656][61557:61557] CHIP:TS: Last Known Good Time: 2023-07-11T07:53:58
[1693981724.017875][61557:61557] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xA8C2A9631605E62C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1693981724.018368][61557:61557] CHIP:ZCL: Using ZAP configuration...
[1693981724.020315][61557:61557] CHIP:DL: Avahi client registered
[1693981724.020741][61557:61557] CHIP:CTL: System State Initialized...
[1693981724.020777][61557:61557] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693981724.020789][61557:61557] CHIP:CTL: Setting attestation nonce to random value
[1693981724.020795][61557:61557] CHIP:CTL: Setting CSR nonce to random value
[1693981724.020859][61557:61559] CHIP:DL: CHIP task running
[1693981724.020909][61557:61559] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1693981724.020983][61557:61559] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693981724.020992][61557:61559] CHIP:CTL: Setting attestation nonce to random value
[1693981724.020997][61557:61559] CHIP:CTL: Setting CSR nonce to random value
[1693981724.024491][61557:61559] CHIP:CTL: Generating NOC
[1693981724.028381][61557:61559] CHIP:FP: Validating NOC chain
[1693981724.043580][61557:61559] CHIP:FP: NOC chain validation successful
[1693981724.043607][61557:61559] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1693981724.043616][61557:61559] CHIP:TS: Last Known Good Time: 2023-07-11T07:53:58
[1693981724.043624][61557:61559] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1693981724.043631][61557:61559] CHIP:TS: Retaining current Last Known Good Time
[1693981724.044181][61557:61559] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1693981724.044628][61557:61559] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-11T07:53:58
[1693981724.045062][61557:61559] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: A8C2A9631605E62C)
[1693981724.050139][61557:61559] CHIP:CTL: Setting thread operational dataset from parameters
[1693981724.050166][61557:61559] CHIP:CTL: Setting attestation nonce to random value
[1693981724.050176][61557:61559] CHIP:CTL: Setting CSR nonce to random value
[1693981724.050183][61557:61559] CHIP:CTL: Commission called for node ID 0x0000000000000003
[1693981724.052312][61557:61558] CHIP:DL: TRACE: Bus acquired for name C-f075
[1693981724.055406][61557:61559] CHIP:DL: PlatformBlueZInit init success
[1693981724.057710][61557:61558] CHIP:BLE: BLE removing known devices.
[1693981724.097199][61557:61558] CHIP:BLE: BLE initiating scan.
[1693981724.247352][61557:61559] CHIP:DL: Long dispatch time: 197 ms, for event type 2
[1693981724.285629][61557:61558] CHIP:BLE: New device scanned: FB:5A:2B:96:CD:50
[1693981724.285675][61557:61558] CHIP:BLE: Device discriminator match. Attempting to connect.
[1693981725.365190][61557:61558] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1693981734.254322][61557:61559] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1693981734.285528][61557:61559] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1693981734.285574][61557:61559] CHIP:DIS: Closing all BLE connections
[1693981734.285675][61557:61558] CHIP:DL: FAIL: ConnectDevice : Operation was cancelled (19)
[1693981734.285757][61557:61559] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1693981844.021339][61557:61557] CHIP:CTL: Shutting down the commissioner
[1693981844.021375][61557:61557] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693981844.021384][61557:61557] CHIP:CTL: Shutting down the controller
[1693981844.021396][61557:61557] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1693981844.021404][61557:61557] CHIP:FP: Forgetting fabric 0x1
[1693981844.021415][61557:61557] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:53:58
[1693981844.021485][61557:61557] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:53:58
[1693981844.021492][61557:61557] CHIP:TS: Reverted Last Known Good Time to previous value
[1693981844.021506][61557:61557] CHIP:CTL: Shutting down the commissioner
[1693981844.021513][61557:61557] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1693981844.021520][61557:61557] CHIP:CTL: Shutting down the controller
[1693981844.021527][61557:61557] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1693981844.021917][61557:61557] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1693981844.021946][61557:61557] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1693981844.021959][61557:61557] CHIP:FP: Shutting down FabricTable
[1693981844.021967][61557:61557] CHIP:TS: Pending Last Known Good Time: 2023-07-11T07:53:58
[1693981844.022015][61557:61557] CHIP:TS: Previous Last Known Good Time: 2023-07-11T07:53:58
[1693981844.022020][61557:61557] CHIP:TS: Reverted Last Known Good Time to previous value
[1693981844.022107][61557:61557] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-FsYMTP)
[1693981844.022283][61557:61557] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1693981844.022301][61557:61557] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1693981844.022307][61557:61557] CHIP:DL: Inet Layer shutdown
[1693981844.022314][61557:61557] CHIP:DL: BLE shutdown
[1693981844.022524][61557:61557] CHIP:DL: System Layer shutdown
[1693981844.022638][61557:61557] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:537: CHIP Error 0x00000032: Timeout

[AHaug]

Hi,

Thanks for the logs, I will have a look at them. Just a quick tip for future log-pasting: You can use the insert code function to add logs so the ticket becomes easier to read

1. Are you debugging the application while you were fetching the logs? The debug session does most likely cause timing issues which the Soft Device does not handle very well, which is probably why you see the softdevice assert as well as the advertising issues. Do you see the same fault when you're not debugging?
2. Could you verify if you are able to reproduce this on a 52840DK, 5340DK or 7002DK?

Kind regards,
Andreas

[DoubleAmaing]

Hi，

Thank you for your guidance.

1. I don't have a Debug, my process is:

Download the program and connect to RTT;

2. Sorry, our company has not received any DK.

We have made a small system ourselves, using "E73-2G4M08S1C" and powered by 3.3V；

I use light_ Blub,  prj.conf

[DoubleAmaing]

Hi

E73-2G4M08S1C"included 52840,and

XT1=32MHZ

[AHaug]

Are you able to run basic Bluetooth samples on the module?

Kind regards,
Andreas