search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.45k stars 1.99k forks source link

[BUILD-ISSUE] Unable to do commissioning on examples/lighting-app/esp32 #33894

Open Teodor12 opened 4 months ago

Teodor12 commented 4 months ago

Reproduction steps

After successfully erasing flash, and flashing the firmware I wanted to do the commissioning with the command: /chip-tool pairing ble-wifi 12344320 SSID PASSWORD 20202021 3840

I get the following output:

[1718274993.660990][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1718274993.661418][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1718274993.661424][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1718274993.662742][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1718274993.662769][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1718274993.662801][41630:41630] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1718274993.662883][41630:41630] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-VWM1lB)
[1718274993.663116][41630:41630] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1718274993.663144][41630:41630] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3)
[1718274993.663282][41630:41630] CHIP:DL: Failed to get Ethernet interface
[1718274993.663366][41630:41630] CHIP:DL: Failed to reset Ethernet statistic counts
[1718274993.663414][41630:41630] CHIP:DL: Got WiFi interface: wlp1s0
[1718274993.663469][41630:41630] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1718274993.663484][41630:41630] CHIP:IN: UDP::Init bind&listen port=0
[1718274993.663516][41630:41630] CHIP:IN: UDP::Init bound to port=52820
[1718274993.663518][41630:41630] CHIP:IN: UDP::Init bind&listen port=0
[1718274993.663527][41630:41630] CHIP:IN: UDP::Init bound to port=47287
[1718274993.663529][41630:41630] CHIP:IN: BLEBase::Init - setting/overriding transport
[1718274993.663557][41630:41630] CHIP:IN: TransportMgr initialized
[1718274993.663567][41630:41630] CHIP:FP: Initializing FabricTable from persistent storage
[1718274993.663609][41630:41630] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1718274993.663989][41630:41630] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xCD412C776F617E4E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1718274993.668088][41630:41630] CHIP:ZCL: Using ZAP configuration...
[1718274993.668389][41630:41630] CHIP:CTL: System State Initialized...
[1718274993.668467][41630:41630] CHIP:CTL: Setting attestation nonce to random value
[1718274993.668491][41630:41630] CHIP:CTL: Setting CSR nonce to random value
[1718274993.668506][41630:41630] CHIP:IN: UDP::Init bind&listen port=5550
[1718274993.668535][41630:41630] CHIP:IN: UDP::Init bound to port=5550
[1718274993.668552][41630:41630] CHIP:IN: UDP::Init bind&listen port=5550
[1718274993.668558][41630:41630] CHIP:IN: UDP::Init bound to port=5550
[1718274993.668560][41630:41630] CHIP:IN: TransportMgr initialized
[1718274993.668734][41630:41632] CHIP:DL: CHIP task running
[1718274993.668756][41630:41632] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1718274993.668853][41630:41632] CHIP:CTL: Setting attestation nonce to random value
[1718274993.668872][41630:41632] CHIP:CTL: Setting CSR nonce to random value
[1718274993.669084][41630:41632] CHIP:CTL: Generating NOC
[1718274993.669289][41630:41632] CHIP:FP: Validating NOC chain
[1718274993.669654][41630:41632] CHIP:FP: NOC chain validation successful
[1718274993.669702][41630:41632] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1718274993.669705][41630:41632] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1718274993.669708][41630:41632] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1718274993.669710][41630:41632] CHIP:TS: Retaining current Last Known Good Time
[1718274993.670095][41630:41632] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1718274993.670470][41630:41632] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1718274993.670802][41630:41632] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: CD412C776F617E4E)
[1718274993.670807][41630:41632] CHIP:IN: UDP::Init bind&listen port=5550
[1718274993.670856][41630:41632] CHIP:IN: UDP::Init bound to port=5550
[1718274993.670858][41630:41632] CHIP:IN: UDP::Init bind&listen port=5550
[1718274993.670864][41630:41632] CHIP:IN: UDP::Init bound to port=5550
[1718274993.670866][41630:41632] CHIP:IN: TransportMgr initialized
[1718274993.673204][41630:41632] CHIP:CTL: Setting wifi credentials from parameters
[1718274993.673212][41630:41632] CHIP:CTL: Setting attestation nonce to random value
[1718274993.673221][41630:41632] CHIP:CTL: Setting CSR nonce to random value
[1718274993.673226][41630:41632] CHIP:CTL: Commission called for node ID 0x0000000000001122
[1718274993.676326][41630:41631] CHIP:BLE: BLE removing known devices
[1718274993.676946][41630:41631] CHIP:BLE: BLE initiating scan
[1718274993.805167][41630:41631] CHIP:BLE: Failed to start discovery: GDBus.Error:org.bluez.Error.InProgress: Operation already in progress
[1718274993.805314][41630:41632] CHIP:BLE: Failed to initiate BLE scan start: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error
[1718274993.805335][41630:41632] CHIP:BLE: Scan complete. No matching device found.
[1718274993.805345][41630:41632] CHIP:BLE: Failed to start BLE scan: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error
[1718274993.805353][41630:41632] CHIP:DIS: Closing all BLE connections
[1718274993.805406][41630:41632] CHIP:TOO: Pairing Failure: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error
[1718274993.805430][41630:41632] CHIP:DL: Long dispatch time: 133 ms, for event type 3
[1718274993.805620][41630:41630] CHIP:CTL: Shutting down the commissioner
[1718274993.805674][41630:41630] CHIP:CTL: Shutting down the controller
[1718274993.805701][41630:41630] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1718274993.805708][41630:41630] CHIP:FP: Forgetting fabric 0x1
[1718274993.805722][41630:41630] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1718274993.805802][41630:41630] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1718274993.805809][41630:41630] CHIP:TS: Reverted Last Known Good Time to previous value
[1718274993.805830][41630:41630] CHIP:CTL: Shutting down the commissioner
[1718274993.805850][41630:41630] CHIP:CTL: Shutting down the controller
[1718274993.805855][41630:41630] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1718274993.805937][41630:41630] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1718274993.805983][41630:41630] CHIP:FP: Shutting down FabricTable
[1718274993.805991][41630:41630] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1718274993.806033][41630:41630] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1718274993.806038][41630:41630] CHIP:TS: Reverted Last Known Good Time to previous value
[1718274993.806150][41630:41630] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JzdNdW)
[1718274993.806417][41630:41630] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1718274993.806440][41630:41630] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1718274993.806449][41630:41630] CHIP:DL: Inet Layer shutdown
[1718274993.806455][41630:41630] CHIP:DL: BLE Layer shutdown
[1718274993.806807][41630:41630] CHIP:DL: System Layer shutdown
[1718274993.806930][41630:41630] CHIP:TOO: Run command failure: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error

Bug prevalence

Always

GitHub hash of the SDK that was being used

2d97cda23024e72f36216900ca667bf1a0d9499f

Platform

esp32

Platform Version(s)

v1.2.0.1

Anything else?

I followed the steps from this tutorial(s):

https://grandcentrix.net/en/blog/matter_03/

I'm using ESP-32 H2 board from Waveshare.

bzbarsky-apple commented 4 months ago 
[1718274993.805314][41630:41632] CHIP:BLE: Failed to initiate BLE scan start: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error

Sounds like something is broken with your bluez setup on the machine you are running chip-tool on, @Teodor12

Teodor12 commented 4 months ago 
[1718274993.805314][41630:41632] CHIP:BLE: Failed to initiate BLE scan start: src/platform/Linux/bluez/BluezObjectManager.cpp:312: CHIP Error 0x000000AC: Internal error

Sounds like something is broken with your bluez setup on the machine you are running chip-tool on, @Teodor12

Hello!

Thank you!

Do you have any suggestions to fix the mentioned package/setup?

bzbarsky-apple commented 4 months ago

@Teodor12 No idea, sorry... I have no experience with it.

andy31415 commented 3 days ago

@Teodor12 we will need reproduction steps to be able to debug as this seems to be environment specific based on logs.

26118 has suggestions about BLE interfering with WIFI and maybe turning off wifi getting ble to be successful. Overall does bluetooth work on your linux machine (can you have BT mice or headphones for example)? What is that machine? is it a generic linux or a RPi or something else?

Platform on the bug says esp32 however this seems to be specific to chip-tool running on linux.