Error when running the Python CHIP controller

[Carla31]

I'm actually trying to run the Python CHIP controller in my PC but I got some errors.

I've successfully set up the Open Thread Border Router in a Raspberry PI and I'm using the Light Bulb Matter example flashed in a nRF5340 DK which is my Matter accessory. 

I followed the tutorial https://developer.nordicsemi.com/nRF_Connect_SDK/doc/1.9.1/matter/python_chip_controller_building.html#using-python-chip-controller-for-matter-accessory-testing to create my Matter controller using the tool Python CHIP controller.

I used all the required commands here below for installation and building the Python CHIP controller.

Then I tried to run the tool as shown here below :

I successfully activated the Python virtual environment. Then I tried to run the Python CHIP controller using "sudo out/python_env/bin/chip-device-ctrl " but I got the following output :

:~/connectedhomeip$ sudo out/python_env/bin/chip-device-ctrl 
[1647525260.928139][48172:48172] CHIP:CTL: Setting attestation nonce to random value
[1647525260.928241][48172:48172] CHIP:CTL: Setting CSR nonce to random value
[1647525260.930233][48172:48172] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hoBbXJ)
[1647525260.930450][48172:48172] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1647525260.930478][48172:48172] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6)
[1647525260.930711][48172:48172] CHIP:DL: Got Ethernet interface: enp0s31f6
[1647525260.930868][48172:48172] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1647525260.931027][48172:48172] CHIP:DL: Got WiFi interface: wlp1s0
[1647525260.931673][48172:48172] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1647525260.931786][48172:48186] CHIP:DL: Platform main loop started.
2022-03-17 14:54:20 IMP-IT0087lx root[48172] CRITICAL Loading configuration from /tmp/chip-device-ctrl-storage.json...
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 1
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 2
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 3
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 4
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 5
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 6
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 7
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 8
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 9
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 10
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 11
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 12
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 13
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 14
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 15
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO Loading from storage for fabric index 16
2022-03-17 14:54:20 IMP-IT0087lx chip.DL[48172] INFO writing settings to file (/tmp/chip_counters.ini-23Pp4J)
2022-03-17 14:54:20 IMP-IT0087lx chip.DL[48172] ERROR renamed tmp file to file (/tmp/chip_counters.ini)
2022-03-17 14:54:20 IMP-IT0087lx chip.DL[48172] INFO NVS set: chip-counters/GlobalMCTR = 6000 (0x1770)
2022-03-17 14:54:20 IMP-IT0087lx root[48172] INFO SetSdkKey: gcc = b'\xd0\x07\x00\x00'
2022-03-17 14:54:20 IMP-IT0087lx root[48172] INFO SetSdkKey: gdc = b'\xd0\x07\x00\x00'
2022-03-17 14:54:20 IMP-IT0087lx chip.ZCL[48172] INFO Using ZAP configuration...
2022-03-17 14:54:20 IMP-IT0087lx chip.DL[48172] INFO Avahi connecting
2022-03-17 14:54:20 IMP-IT0087lx chip.IN[48172] INFO CASE Server enabling CASE session setups
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] ERROR Failed to initialize advertiser: ../../src/platform/Linux/DnssdImpl.cpp:333: CHIP Error 0x00000003: Incorrect state
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] INFO Failed to find a valid admin pairing. Node ID unknown
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] INFO Start dns-sd server - no current nodeId
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] ERROR Failed to advertise unprovisioned commissionable node: ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:473: CHIP Error 0x00000003: Incorrect state
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
2022-03-17 14:54:20 IMP-IT0087lx chip.DIS[48172] ERROR Failed to advertise commissioner: ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:473: CHIP Error 0x00000003: Incorrect state
2022-03-17 14:54:21 IMP-IT0087lx chip.DL[48172] ERROR Avahi client failure
2022-03-17 14:54:21 IMP-IT0087lx chip.DIS[48172] ERROR DNS-SD error: ../../src/platform/Linux/DnssdImpl.cpp:405: CHIP Error 0x000000AC: Internal error
New FabricAdmin: FabricId: 1(1)
2022-03-17 14:54:21 IMP-IT0087lx root[48172] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}}
Allocating new controller with FabricId: 1(1), NodeId: 1
2022-03-17 14:54:21 IMP-IT0087lx chip.CTL[48172] INFO Setting attestation nonce to random value
2022-03-17 14:54:21 IMP-IT0087lx chip.CTL[48172] INFO Setting CSR nonce to random value
2022-03-17 14:54:21 IMP-IT0087lx chip.CTL[48172] INFO Generating NOC
CHIP Error 0x00000003: Incorrect state
Failed to bringup CHIPDeviceController CLI
Exception ignored in: <function ChipDeviceController.__del__ at 0x7f75f07d4040>
Traceback (most recent call last):
  File "/home/czena/connectedhomeip/out/python_env/lib/python3.8/site-packages/chip/ChipDeviceCtrl.py", line 186, in __del__
    self.Shutdown()
  File "/home/czena/connectedhomeip/out/python_env/lib/python3.8/site-packages/chip/ChipDeviceCtrl.py", line 150, in Shutdown
    if (self.isActive):
AttributeError: 'ChipDeviceController' object has no attribute 'isActive'
Segmentation fault

I would like to know why I got a segmentation fault. Could you help me please ?

I'm using OS Ubuntu 20.04.4 LTS and nRF Connect SDK v1.9.1

[Karl Ylvisaker]

Hello again,

I hope you have had a great weekend!

Could you confirm that you have the Avahi-daemon up and running?
Could you also tell me what
 

systemctl status avahi-daemon

and 

ps aux | grep avahi-daemon

returns for you?

Best regards,
Karl

[Carla31]

Hello, I'm trying to connect my board nRF5340DK (with the Light Bulb Matter example) with my PC (Matter controller) over Bluetooth but the connection is not established. This is what I get :

chip-device-ctrl > connect -ble 3840 20202021
2022-04-28 10:44:31 IMP-IT0087lx root[695542] WARNING  /usr/local/bin/chip-device-ctrl:601: DeprecationWarning:This method is being deprecated. Please use the DeviceController.[ConnectBLE|CommissionIP] methods directly in the REPL
Device is assigned with nodeid = 308642
2022-04-28 10:44:31 IMP-IT0087lx chip.IN[695542] INFO Prepared unauthenticated message 0x7ff46affb8f0 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 62712i with MessageCounter:1124971237.
2022-04-28 10:44:31 IMP-IT0087lx chip.IN[695542] INFO Sending unauthenticated msg 0x7ff46affb8f0 with MessageCounter:1124971237 to 0x0000000000000000 at monotonic time: 000000000F76DDB3 msec
2022-04-28 10:44:31 IMP-IT0087lx chip.CTL[695542] INFO Setting attestation nonce to random value
2022-04-28 10:44:31 IMP-IT0087lx chip.CTL[695542] INFO Setting CSR nonce to random value
2022-04-28 10:44:31 IMP-IT0087lx chip.CTL[695542] INFO Commission called for node ID 0x000000000004B5A2
2022-04-28 10:44:31 IMP-IT0087lx chip.BLE[695542] INFO BLE removing known devices.
2022-04-28 10:44:31 IMP-IT0087lx chip.BLE[695542] INFO BLE initiating scan.
2022-04-28 10:44:32 IMP-IT0087lx chip.BLE[695542] INFO New device scanned: DD:30:06:22:DC:86
2022-04-28 10:44:32 IMP-IT0087lx chip.BLE[695542] INFO Device discriminator match. Attempting to connect.
2022-04-28 10:44:32 IMP-IT0087lx chip.BLE[695542] INFO Scan complete notification without an active scan.
2022-04-28 10:44:34 IMP-IT0087lx chip.BLE[695542] INFO subscribe complete, ep = 0x7ff47264cb80
2022-04-28 10:44:34 IMP-IT0087lx chip.BLE[695542] INFO peripheral chose BTP version 4; central expected between 4 and 4
2022-04-28 10:44:34 IMP-IT0087lx chip.BLE[695542] INFO using BTP fragment sizes rx 244 / tx 244.
2022-04-28 10:44:34 IMP-IT0087lx chip.BLE[695542] INFO local and remote recv window size = 5
2022-04-28 10:44:35 IMP-IT0087lx chip.IN[695542] INFO Received malformed unsecure packet with source 0x0000000000000000 destination 0x0000000000000000
2022-04-28 10:45:01 IMP-IT0087lx chip.SC[695542] ERROR PASESession timed out while waiting for a response from the peer. Expected message type was 33
Failed to establish secure session to device: 50
CHIP Error 0x00000032: Timeout

I would like to know why I can't establish the secure connection over Bluetooth LE.

When I use the command ble-scan, to scan all advertised Matter devices, I got the following output:

2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG destroy device
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO Name            = MatterLight
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO ID              = 766dcf2a-2adf-37fc-abbc-b104dd4e0ec4
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO RSSI            = -56
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO Address         = DD:30:06:22:DC:86
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO Adv UUID        = 0000fff6-0000-1000-8000-00805f9b34fb
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO Adv Data        = 00000f5a234c4e00
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] INFO 
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'Name'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'Name'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'Name'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'Name'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'Name'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'ServiceData'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'ServiceData'
2022-04-28 10:44:12 IMP-IT0087lx ChipBLEMgr[695542] DEBUG org.freedesktop.DBus.Error.InvalidArgs: No such property 'ServiceData'

Could you help me please ? 

[Karl Ylvisaker]

Hello again, Carla

Thank you for your patience with this.

Is this still an issue?
It seems to me that you are trying to access properties that are not found, and that the connection times out.
Please open a new ticket for this issue, since it diverges from the issue in the original post - this keeps the forum tidy and easy to navigate for other users.

Best regards,
Karl