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.57k stars 2.05k forks source link

GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36) #26118

Open sprabhaa opened 1 year ago

sprabhaa commented 1 year ago

Reproduction steps

step 1: Flashed all-cluster-app in esp32-c3. step2 : When it is in Advertise mode , we start wifi commissioning using " ./chip-tool pairing ble-wifi 0x7283 wifi-SSID wifi-password 20202021 3840 "

And getting Getting "GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)" error.

Attached complete log. connected_home_ip_logs.txt

Query: Sometimes when we do blue tooth daemon stop and start this error is not seen, but it does not resolve the issue 100%. Kindly let us know what could be the root cause for this issue.

Bug prevalence

4 out of 5 trials.

GitHub hash of the SDK that was being used

20de6120cb807f7986bb4c39981e2de4625cf289

commit 20de6120cb807f7986bb4c39981e2de4625cf289 (HEAD -> master, origin/master, origin/HEAD) Author: manjunath-grl 102359958+manjunath-grl@users.noreply.github.com Date: Fri Feb 24 11:03:10 2023 +0530

Modified test Feb 23 (#25288)

* Modified automated/semiautomated/manual test
TC_ACL_2_2
TC_BRBINFO_2_1
TC_BRBINFO_2_2
TC_BRBINFO_2_3
TC_BR_2

Platform

raspi

Platform Version(s)

No response

Anything else?

No response

topraveenpaul commented 1 year ago

@sprabhaa @bzbarsky-apple Any updates on this error yet? I face the same issue. Any potential solutions?

Kaikas commented 12 months ago

Any way to fix this? I have the same issue.

TH Fall2023 Sha: 3f84bff5

ssh ubuntu@raspi_ip
cd app
./chip-tool pairing ble-wifi 1 wifi pass passcode discriminator --paa-trust-store-path /var/paa-root-certs/
[1702562551.702577][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1702562551.703473][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1702562551.703515][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1702562551.708831][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1702562551.709079][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1702562551.709190][2223:2223] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1702562551.709507][2223:2223] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-sot8Wy)
[1702562551.710074][2223:2223] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1702562551.710124][2223:2223] CHIP:DL: NVS set: chip-counters/reboot-count = 15 (0xF)
[1702562551.710923][2223:2223] CHIP:DL: Got Ethernet interface: eth0
[1702562551.711452][2223:2223] CHIP:DL: Found the primary Ethernet interface:eth0
[1702562551.712026][2223:2223] CHIP:DL: Got WiFi interface: wlan0
[1702562551.713985][2223:2223] CHIP:DL: Found the primary WiFi interface:wlan0
[1702562551.714047][2223:2223] CHIP:IN: UDP::Init bind&listen port=0
[1702562551.714149][2223:2223] CHIP:IN: UDP::Init bound to port=58954
[1702562551.714168][2223:2223] CHIP:IN: BLEBase::Init - setting/overriding transport
[1702562551.714185][2223:2223] CHIP:IN: TransportMgr initialized
[1702562551.714215][2223:2223] CHIP:FP: Initializing FabricTable from persistent storage
[1702562551.714365][2223:2223] CHIP:TS: Last Known Good Time: 2023-10-03T16:51:18
[1702562551.715787][2223:2223] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x932CAC57FD5FA014, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1702562551.717660][2223:2223] CHIP:ZCL: Using ZAP configuration...
[1702562551.721387][2223:2223] CHIP:DL: Avahi re-register required
[1702562551.721513][2223:2223] CHIP:CTL: System State Initialized...
[1702562552.283687][2223:2223] CHIP:CTL: Setting attestation nonce to random value
[1702562552.283772][2223:2223] CHIP:CTL: Setting CSR nonce to random value
[1702562552.283833][2223:2223] CHIP:IN: UDP::Init bind&listen port=5550
[1702562552.283956][2223:2223] CHIP:IN: UDP::Init bound to port=5550
[1702562552.283977][2223:2223] CHIP:IN: TransportMgr initialized
[1702562552.284238][2223:2225] CHIP:DL: CHIP task running
[1702562552.284429][2223:2225] CHIP:DL: HandlePlatformSpecificBLEEvent 32787
[1702562552.284713][2223:2225] CHIP:CTL: Setting attestation nonce to random value
[1702562552.284873][2223:2225] CHIP:CTL: Setting CSR nonce to random value
[1702562552.285638][2223:2225] CHIP:CTL: Generating NOC
[1702562552.286441][2223:2225] CHIP:FP: Validating NOC chain
[1702562552.288041][2223:2225] CHIP:FP: NOC chain validation successful
[1702562552.288185][2223:2225] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1702562552.288216][2223:2225] CHIP:TS: Last Known Good Time: 2023-10-03T16:51:18
[1702562552.288234][2223:2225] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1702562552.288251][2223:2225] CHIP:TS: Retaining current Last Known Good Time
[1702562552.290139][2223:2225] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1702562552.291687][2223:2225] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-03T16:51:18
[1702562552.293569][2223:2225] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 932CAC57FD5FA014)
[1702562552.293628][2223:2225] CHIP:IN: UDP::Init bind&listen port=5550
[1702562552.293766][2223:2225] CHIP:IN: UDP::Init bound to port=5550
[1702562552.293793][2223:2225] CHIP:IN: TransportMgr initialized
[1702562552.308108][2223:2225] CHIP:CTL: Setting wifi credentials from parameters
[1702562552.308149][2223:2225] CHIP:CTL: Setting attestation nonce to random value
[1702562552.308199][2223:2225] CHIP:CTL: Setting CSR nonce to random value
[1702562552.308232][2223:2225] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1702562552.312639][2223:2224] CHIP:DL: TRACE: Bus acquired for name C-08af
[1702562552.320043][2223:2225] CHIP:DL: PlatformBlueZInit init success
[1702562552.326327][2223:2224] CHIP:BLE: BLE removing known devices.
[1702562552.330060][2223:2224] CHIP:BLE: BLE initiating scan.
[1702562552.376369][2223:2224] CHIP:BLE: Device 58:93:D8:8A:69:BA does not look like a CHIP device.
[1702562552.378839][2223:2224] CHIP:BLE: Device 3B:BC:0E:1E:AF:20 does not look like a CHIP device.
[1702562558.027944][2223:2224] CHIP:BLE: New device scanned: F0:B4:C6:C9:88:70
[1702562558.028037][2223:2224] CHIP:BLE: Device discriminator match. Attempting to connect.
[1702562558.375456][2223:2224] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
[1702562558.807738][2223:2224] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
[1702562559.261481][2223:2224] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
[1702562559.793473][2223:2224] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
[1702562560.286459][2223:2224] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
[1702562560.286740][2223:2225] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1702562560.286809][2223:2225] CHIP:DIS: Closing all BLE connections
[1702562560.286952][2223:2225] CHIP:TOO: Pairing Failure: src/platform/Linux/bluez/Helper.cpp:1738: CHIP Error 0x000000AC: Internal error
[1702562560.287622][2223:2223] CHIP:CTL: Shutting down the commissioner
[1702562560.287824][2223:2223] CHIP:CTL: Shutting down the controller
[1702562560.287921][2223:2223] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1702562560.287975][2223:2223] CHIP:FP: Forgetting fabric 0x1
[1702562560.288042][2223:2223] CHIP:TS: Pending Last Known Good Time: 2023-10-03T16:51:18
[1702562560.288410][2223:2223] CHIP:TS: Previous Last Known Good Time: 2023-10-03T16:51:18
[1702562560.288494][2223:2223] CHIP:TS: Reverted Last Known Good Time to previous value
[1702562560.288610][2223:2223] CHIP:CTL: Shutting down the commissioner
[1702562560.288764][2223:2223] CHIP:CTL: Shutting down the controller
[1702562560.288859][2223:2223] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1702562560.289258][2223:2223] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1702562560.289454][2223:2223] CHIP:FP: Shutting down FabricTable
[1702562560.289586][2223:2223] CHIP:TS: Pending Last Known Good Time: 2023-10-03T16:51:18
[1702562560.289826][2223:2223] CHIP:TS: Previous Last Known Good Time: 2023-10-03T16:51:18
[1702562560.289892][2223:2223] CHIP:TS: Reverted Last Known Good Time to previous value
[1702562560.290364][2223:2223] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-FQ6SFU)
[1702562560.291502][2223:2223] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1702562560.291618][2223:2223] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1702562560.291656][2223:2223] CHIP:DL: Inet Layer shutdown
[1702562560.291685][2223:2223] CHIP:DL: BLE shutdown
[1702562560.292568][2223:2223] CHIP:DL: System Layer shutdown
[1702562560.293043][2223:2223] CHIP:TOO: Run command failure: src/platform/Linux/bluez/Helper.cpp:1738: CHIP Error 0x000000AC: Internal error
willyan2002 commented 5 months ago

The Raspberry Pi running the chip tool must have WiFi turned off, otherwise it will cause serious interference to the BLE. You can discover the matter device, but cannot successfully establish the BLE connection. The error log is as you can see.

If your Raspberry Pi‘s Wi-Fi is indeed on, please use nmcli or rfkill to turn it off, and then try to commission some matter device , you may see the success rate is almost 100%.

Raspberry Pi Wi-Fi on

  1. `[1718863192.902905][56656:56657] CHIP:BLE: Device 35:B0:FD:18:C2:C8 does not look like a CHIP device.
  2. [1718863192.916208][56656:56657] CHIP:BLE: New device scanned: C5:33:98:4C:92:A7
  3. [1718863192.916288][56656:56657] CHIP:BLE: Device discriminator match. Attempting to connect.
  4. [1718863192.920537][56656:56657] CHIP:BLE: ChipDeviceScanner has stopped scanning!
  5. [1718863196.772053][56656:56657] CHIP:DL: FAIL: ConnectDevice: GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
  6. [1718863196.772156][56656:56657] CHIP:DL: ConnectDevice retry: 1 out of 4
  7. [1718863197.784491][56656:56657] CHIP:DL: FAIL: ConnectDevice: GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
  8. [1718863197.784578][56656:56657] CHIP:DL: ConnectDevice retry: 2 out of 4
  9. [1718863201.824495][56656:56657] CHIP:DL: FAIL: ConnectDevice: GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
  10. [1718863201.824585][56656:56657] CHIP:DL: ConnectDevice retry: 3 out of 4
  11. [1718863204.335772][56656:56657] CHIP:DL: FAIL: ConnectDevice: GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
  12. [1718863204.335865][56656:56657] CHIP:DL: ConnectDevice retry: 4 out of 4
  13. [1718863204.348656][56656:56657] CHIP:BLE: Device connection failed: src/platform/Linux/bluez/BluezEndpoint.cpp:657: CHIP Error 0x000000AC: Internal error`

Wi-Fi off

ubuntu@ubuntu:~$ sudo nmcli radio wifi off ubuntu@ubuntu:~$

  1. `1718863407.072943][57126:57127] CHIP:BLE: Device B0:CE:18:DE:3E:7D does not look like a CHIP device.
  2. [1718863407.093220][57126:57127] CHIP:BLE: Device 51:44:C6:3C:5F:8D does not look like a CHIP device.
  3. [1718863407.106942][57126:57127] CHIP:BLE: Device 62:86:FD:E0:79:93 does not look like a CHIP device.
  4. [1718863407.108374][57126:57127] CHIP:BLE: New device scanned: E3:FC:A3:A8:7A:28
  5. [1718863407.108440][57126:57127] CHIP:BLE: Device discriminator match. Attempting to connect.
  6. [1718863407.113574][57126:57127] CHIP:BLE: ChipDeviceScanner has stopped scanning!
  7. **[1718863407.370060][57126:57127] CHIP:DL: ConnectDevice complete
  8. [1718863407.370156][57126:57127] CHIP:BLE: New device connected: E3:FC:A3:A8:7A:28**
  9. [1718863408.769827][57126:57127] CHIP:DL: Char /org/bluez/hci0/dev_E3_FC_A3_A8_7A_28/service000a on service /org/bluez/hci0/dev_E3_FC_A3_A8_7A_28/service000a`
andy31415 commented 1 month ago

@sprabhaa does wifi on/off make a difference in your test?

JTR-Wang commented 1 month ago

I face the same issue using same command, and I use the cypress wifi/bt module + rcp.

Here is my test: