Unable to establish ble connection between devices #6347

nageshshamnur · 2021-04-28T14:12:02Z

Problem

expected behavior: Connect command in ChipDeviceController running on laptop should be able to connect to Lighting App running on RPi4B
actual behavior: Connect command in ChipDeviceController is timeout and unable to connect to Lighting App running on RPi4B.
system configuration:
Topology: Intel Corei7 laptop running Ubuntu 20.04.2 LTS <-------------------> RPi4B running Ubuntu 20.04.2 LTS
Branch: Test_event_2.2
Note: Both laptop and RPi using the default bluetooth radio (without any dongles). hciconfig on both devices is having hci0.

Laptop BD Address: 6C:6A:77:48:40:08
RPi4B BD Address: B8:27:EB:91:23:92

steps to reproduce:
RPi4B running Lighting App as suggested in the page https://github.com/project-chip/connectedhomeip/tree/master/examples/lighting-app/linux Logs as below:

$out/debug/chip-lighting-app --ble-device 0 
SetupPINCode: [20202021]
SetupQRCode:  [CH:H34DV+700 V5C.71]
CHIP:ZCL: Using ZAP configuration...
CHIP:ZCL: deactivate report event
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:ZCL: Unknown cluster ID: 40
CHIP:IN: TransportMgr initialized
CHIP:IN: local node id is 0x0000000000bc5c01
CHIP:DL: wpa_supplicant: _IsWiFiStationProvisioned: interface not connected
CHIP:BLE: Assigned local session key ID 0
CHIP:BLE: Waiting for PBKDF param request
CHIP:DIS: Start dns-sd server
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:DIS: Replying to DNS-SD service listing request
CHIP:DIS: Replying to DNS-SD service listing request
CHIP:DIS: Replying to DNS-SD service listing request
CHIP:SVR: Server Listening...
CHIP:DL: TRACE: Bluez mainloop starting Thread
CHIP:DL: TRACE: Bus acquired for name CHIP-3840
CHIP:DL: CREATE service object at /chipoble/0e8a/service
CHIP:DL: Create characteristic object at /chipoble/0e8a/service/c1
CHIP:DL: Create characteristic object at /chipoble/0e8a/service/c2
CHIP:DL: CHIP BTP C1 /chipoble/0e8a/service
CHIP:DL: CHIP BTP C2 /chipoble/0e8a/service
CHIP:DL: CHIP_ENABLE_ADDITIONAL_DATA_ADVERTISING is TRUE
CHIP:DL: Create characteristic object at /chipoble/0e8a/service/c3
CHIP:DL: rotatingDeviceId: 00007C5F6E176CD40F68685D100A1CF8A98B
CHIP:DL: CHIP BTP C3 /chipoble/0e8a/service
CHIP:DL: PlatformBlueZInit init success
CHIP:DL: BluezPeripheralRegisterAppDone done
CHIP:DL: HandlePlatformSpecificBLEEvent 16392
CHIP:DL: Create adv object at /chipoble/0e8a/advertising
CHIP:DL: SET service data to {'0xFFF6': <[byte 0x00, 0x00, 0x0f, 0x5a, 0x23, 0xff, 0xfe]>}
CHIP:DL: HandlePlatformSpecificBLEEvent 16393
CHIP:DL: CHIPoBLE advertising config complete
CHIP:DL: RegisterAdvertisement complete
CHIP:DL: HandlePlatformSpecificBLEEvent 16394

Running ChipDeviceController on Laptop but ble connection is not established due to Timeout. Logs as bdlow:

root1@root1-Nitro-AN515-55:~/Nagesh/CHIP/test_event_2.2/connectedhomeip/src/controller/python$ ./chip-device-ctrl.py 
CHIP:IN: TransportMgr initialized
CHIP:IN: local node id is 0x000000000001b669
CHIP:ZCL: Using ZAP configuration...
CHIP:ZCL: deactivate report event
CHIP:DL: CHIP task running
CHIP:DL: Platform main loop started.
Chip Device Controller Shell

chip-device-ctrl > ble-scan
2021-04-28 19:10:50,408 ChipBLEMgr   INFO     scanning started
2021-04-28 19:10:52,146 ChipBLEMgr   INFO     Name            = CHIP-3840
2021-04-28 19:10:52,146 ChipBLEMgr   INFO     ID              = 2193682d-4caf-3a4a-9713-03a1a3329db8
2021-04-28 19:10:52,147 ChipBLEMgr   INFO     RSSI            = -65
2021-04-28 19:10:52,147 ChipBLEMgr   INFO     Address         = B8:27:EB:91:23:92
2021-04-28 19:10:52,148 ChipBLEMgr   INFO     Pairing State   = 0
2021-04-28 19:10:52,148 ChipBLEMgr   INFO     Discriminator   = 3840
2021-04-28 19:10:52,148 ChipBLEMgr   INFO     Vendor Id       = 9050
2021-04-28 19:10:52,148 ChipBLEMgr   INFO     Product Id      = 65279
2021-04-28 19:10:52,148 ChipBLEMgr   INFO     Adv UUID        = 0000fff6-0000-1000-8000-00805f9b34fb
2021-04-28 19:10:52,149 ChipBLEMgr   INFO     Adv Data        = 00000f5a23fffe
2021-04-28 19:10:52,149 ChipBLEMgr   INFO     

2021-04-28 19:11:00,718 ChipBLEMgr   INFO     scanning stopped
chip-device-ctrl > 
chip-device-ctrl > connect -ble 3840 20202021
Device is assigned with nodeid = 587015
CHIP:BLE: Assigned local session key ID 1
CHIP:EM: SessionEstablishmentExchangeDispatch::SendMessageImpl  mTransportMgr 0x22044f0
CHIP:IN: Message appended to BLE send queue
CHIP:BLE: Sent PBKDF param request
CHIP:BLE: BLE removing known devices.
CHIP:BLE: BLE initiating scan.
CHIP:BLE: Device 94:53:30:33:D8:8A does not look like a CHIP device.
CHIP:BLE: Device 79:87:B2:61:37:AF does not look like a CHIP device.
CHIP:BLE: Device CC:0B:2A:79:92:CE does not look like a CHIP device.
CHIP:BLE: Device 6C:E8:C6:F2:87:33 does not look like a CHIP device.
CHIP:BLE: Device 70:59:8E:47:B5:A4 does not look like a CHIP device.
CHIP:BLE: New device scanned: B8:27:EB:91:23:92
CHIP:BLE: Device discriminator match. Attempting to connect.
CHIP:BLE: Scan complete notification without an active scan.
CHIP:DL: HandlePlatformSpecificBLEEvent 16386
CHIP:IN: Clearing BLE pending packets.
CHIP:IN: BleConnection Error: CHIP Error 4050 (0x00000FD2): Timeout
CHIP:DL: FAIL: ConnectDevice : Operation was cancelled
CHIP:DL: HandlePlatformSpecificBLEEvent 16386
Failed to establish secure session to device: 4050
CHIP Error 4050 (0x00000FD2): Timeout

Proposed Solution

NA

The text was updated successfully, but these errors were encountered:

sstruchtrup · 2021-04-29T11:41:46Z

I am seeing the same behavior. RPi4B with the provided TE2 image , DUT is a RPi3B with Ubuntu 20.04 (branch test_event_2.2).

Application being tested is the provided lighting example app.

nageshshamnur · 2021-04-29T12:37:21Z

I am facing same problem with with master branch

RPi4B running "chip-all-clusters-app" under the folder out/debug/standalone as well.
Laptop running ChipDeviceCtrl

Damian-Nordic · 2021-04-29T14:01:01Z

Are you able to connect the BLE device using bluetoothctl?

Run bluetoothctl
Run scan on
Once BLE address of the desired device appears, run connect <ble-address>
If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

nageshshamnur · 2021-04-29T14:27:50Z

After scanning through the code I found the error happening when invoke the function bluez_device1_call_connect( ) :

static gboolean ConnectDeviceImpl(ConnectParams * apParams)
{
    BluezDevice1 * device    = apParams->mDevice;
    BluezEndpoint * endpoint = apParams->mEndpoint;

    assert(device != nullptr);
    assert(endpoint != nullptr);

    g_cancellable_reset(endpoint->mpConnectCancellable);
    bluez_device1_call_connect(device, endpoint->mpConnectCancellable, ConnectDeviceDone, nullptr);
    g_object_unref(device);
    chip::Platform::Delete(apParams);

    return G_SOURCE_REMOVE;
}

call to bluez_device1_call_connect( ) translates to g_dbus_proxy_call( ) with the method-name "connect"
in the file out/debug/linux_x64_gcc_mbedtls/gen/include/platform/Linux/dbus/bluez/DbusBluez.c

nageshshamnur · 2021-04-29T15:01:57Z

Are you able to connect the BLE device using bluetoothctl?

Run bluetoothctl

Run scan on

Once BLE address of the desired device appears, run connect <ble-address>
If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

I had faced this issue with bluetoothctl in the past also. connect is not smooth. Connect happens after mulitple retries but happens for sure. It usually takes less than < 10sec as per my observation.

nageshshamnur · 2021-04-29T15:03:44Z

Is there any smooth way to address this connect issue. Many fellow members are also facing similar kind of issues.

Damian-Nordic · 2021-04-29T15:11:09Z

If you face the same issues with bluetoothctl then it doesn't seem to be related with the CHIP implementation. I encounter no issues on my laptop and the connection is established in a second, so it's difficult for me to reproduce the problem. Can you experiment with kConnectTimeoutMs constant from src/platform/Linux/BLEManagerImpl.cpp to see which timeout value is sufficient for your case?

nageshshamnur · 2021-04-29T15:23:29Z

If you face the same issues with bluetoothctl then it doesn't seem to be related with the CHIP implementation. I encounter no issues on my laptop and the connection is established in a second, so it's difficult for me to reproduce the problem. Can you experiment with kConnectTimeoutMs constant from src/platform/Linux/BLEManagerImpl.cpp to see which timeout value is sufficient for your case?

Let me buy and test with additional USB dongle (nRF 52840)

sstruchtrup · 2021-04-29T16:22:26Z

Are you able to connect the BLE device using bluetoothctl?

1. Run `bluetoothctl`

2. Run `scan on`

3. Once BLE address of the desired device appears, run `connect <ble-address>`
   If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

I can confirm that this fails for me. RPi4B to RPI3B.

Damian-Nordic · 2021-04-30T07:05:01Z

Two things which you can also try are:

restarting Bluez daemon by running systemctl restart bluetooth.
reloading Bluetooth drivers. Something like sudo rmmod btusb + sudo modprobe btusb should do it.

tima-q · 2021-05-03T19:16:36Z

Another thing to try is disabling the WiFi of the RPi4
sudo rfkill block wifi
There are reports of WiFi+BLE on RPi4 conflicting in some firmware versions of the Cypress module there.
RPi-Distro/firmware-nonfree#8

nageshshamnur · 2021-05-13T14:38:20Z

Are you able to connect the BLE device using bluetoothctl?

1. Run `bluetoothctl`

2. Run `scan on`

3. Once BLE address of the desired device appears, run `connect <ble-address>`
   If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

I have verified by registering profile @ Raspbeerypi and connecting from Laptop and consistently i have observed that it takes less than 10 seconds to establish the ble connection everytime.

nageshshamnur · 2021-05-13T14:49:41Z

If you face the same issues with bluetoothctl then it doesn't seem to be related with the CHIP implementation. I encounter no issues on my laptop and the connection is established in a second, so it's difficult for me to reproduce the problem. Can you experiment with kConnectTimeoutMs constant from src/platform/Linux/BLEManagerImpl.cpp to see which timeout value is sufficient for your case?

yes, i have increased kConnectTimeoutMs upto 20 seconds @ both laptop and RPi. But the connection still didn't go through. I find that this parameter has no bearing with the issue which I am currently facing.
Although the logs@controller now seems to indicate that it is unable to establish secure connection:

 CHIP:BLE: Device 94:53:30:33:D8:8A does not look like a CHIP device.
CHIP:BLE: Device 76:5D:01:CD:C8:E0 does not look like a CHIP device.
CHIP:BLE: Device 6D:4E:FB:B8:D7:73 does not look like a CHIP device.
CHIP:BLE: Device 5C:5F:67:DB:87:87 does not look like a CHIP device.
CHIP:BLE: Device CC:0B:2A:79:92:CE does not look like a CHIP device.
CHIP:BLE: Device 94:53:30:33:D8:8A does not look like a CHIP device.
CHIP:BLE: New device scanned: DC:A6:32:F2:CB:46
CHIP:BLE: Device discriminator match. Attempting to connect.
CHIP:BLE: Scan complete notification without an active scan.
CHIP:DL: ConnectDevice complete
CHIP:DL: HandlePlatformSpecificBLEEvent 16386
CHIP:IN: Clearing BLE pending packets.
CHIP:IN: BleConnection Error: CHIP Error 4050 (0x00000FD2): Timeout
CHIP:CTL: SyncSetKeyValue on StartKeyID
Failed to establish secure session to device: 4050
CHIP:BLE: PASESession timed out while waiting for a response from the peer. Expected message type was 33
CHIP:CTL: SyncSetKeyValue on StartKeyID
Failed to establish secure session to device: 4050
CHIP Error 4050 (0x00000FD2): Timeout

and logs @ RPi running lighting-app is as below:

CHIP:DL: SET service data to {'0xFFF6': <[byte 0x00, 0x00, 0x0f, 0x5a, 0x23, 0xff, 0xfe]>}
CHIP:DL: HandlePlatformSpecificBLEEvent 16393
CHIP:DL: CHIPoBLE advertising config complete
CHIP:DL: RegisterAdvertisement complete
CHIP:DL: HandlePlatformSpecificBLEEvent 16394
CHIP:DL: New BLE connection xxxx device <BD_Address> path /org/bluez/hci0/dev_xxx_xxx_xxxx
CHIP:DL: Bluez Disconnected
CHIP:DL: Bluez notify CHIPoBluez connection disconnected.

Please note that in the above log, as soon as controller prints CHIP:DL: ConnectDevice complete @RPI it prints new connection log followed by disconnection log immediately.
I am suspecting it is something to do with the profile that is registered to lighting-app. This is as confirmed by Luiz Augusto von Dentz from bluez mailing list which is quoting as below:

https://github.com/project-chip/connectedhomeip/blob/478357157414fb8b6bae0c7b04ac3c5860d4197a/src/controller/python/chip/ChipBluezMgr.py#L69

Are you sure the connectedhomeip is actually running properly, or
perhaps it is connecting in the wrong bearer, which perhaps is because
you made the adapter discoverable instead of start advertising.

nageshshamnur · 2021-05-13T14:52:59Z

Are you able to connect the BLE device using bluetoothctl?

Run bluetoothctl

Run scan on

Once BLE address of the desired device appears, run connect <ble-address>
If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

I had faced this issue with bluetoothctl in the past also. connect is not smooth. Connect happens after mulitple retries but happens for sure. It usually takes less than < 10sec as per my observation.

i stand corrected about this statement, it was happening so to me earlier because of profile registration. With proper profile registration, i am not facing this issue and everytime connect happens instantly within a second or two.

nageshshamnur · 2021-05-13T14:56:54Z

@Damian-Nordic

nageshshamnur · 2021-05-13T14:57:34Z

Another thing to try is disabling the WiFi of the RPi4
sudo rfkill block wifi
There are reports of WiFi+BLE on RPi4 conflicting in some firmware versions of the Cypress module there.
RPi-Distro/firmware-nonfree#8

I have tried this option as well, but made no difference to the issue.

nageshshamnur · 2021-05-13T14:59:00Z

Are you able to connect the BLE device using bluetoothctl?

1. Run `bluetoothctl`

2. Run `scan on`

3. Once BLE address of the desired device appears, run `connect <ble-address>`
   If so, how much time does it take to establish the connection? AFAIK we've set the connect timeout to 10s which works for most people, but maybe in some cases it's not enough.

I can confirm that this fails for me. RPi4B to RPI3B.

are you registering the profile properly in one of the device before initiating connect from the other device ?

nageshshamnur · 2021-05-21T07:10:29Z

original issue is no more happening after upgrading the ubuntu version and hence closing this issue.

fuxiaoming-lumi · 2021-11-01T14:46:51Z

@nageshshamnur Which ubuntu version have you updated ？I found similar problems.

fuxiaoming-lumi · 2021-11-02T10:47:31Z

After verification, we need to upgrade to version 21.04 Ubuntu. Otherwise, the BlueZ version is too low. I think we need to update the doc.

jamesluo11 · 2022-01-07T02:06:08Z

proper
I also encounter this issue, can you specify what's the correct profile registration

nageshshamnur closed this as completed Apr 29, 2021

nageshshamnur reopened this Apr 29, 2021

nageshshamnur closed this as completed May 21, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unable to establish ble connection between devices #6347

Unable to establish ble connection between devices #6347

nageshshamnur commented Apr 28, 2021 •

edited

Loading

sstruchtrup commented Apr 29, 2021 •

edited

Loading

nageshshamnur commented Apr 29, 2021

Damian-Nordic commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021 •

edited

Loading

nageshshamnur commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021

Damian-Nordic commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021

sstruchtrup commented Apr 29, 2021

Damian-Nordic commented Apr 30, 2021

tima-q commented May 3, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021 •

edited

Loading

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 21, 2021

fuxiaoming-lumi commented Nov 1, 2021

fuxiaoming-lumi commented Nov 2, 2021

jamesluo11 commented Jan 7, 2022

Unable to establish ble connection between devices #6347

Unable to establish ble connection between devices #6347

Comments

nageshshamnur commented Apr 28, 2021 • edited Loading

Problem

Proposed Solution

sstruchtrup commented Apr 29, 2021 • edited Loading

nageshshamnur commented Apr 29, 2021

Damian-Nordic commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021 • edited Loading

nageshshamnur commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021

Damian-Nordic commented Apr 29, 2021

nageshshamnur commented Apr 29, 2021

sstruchtrup commented Apr 29, 2021

Damian-Nordic commented Apr 30, 2021

tima-q commented May 3, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021 • edited Loading

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 13, 2021

nageshshamnur commented May 21, 2021

fuxiaoming-lumi commented Nov 1, 2021

fuxiaoming-lumi commented Nov 2, 2021

jamesluo11 commented Jan 7, 2022

nageshshamnur commented Apr 28, 2021 •

edited

Loading

sstruchtrup commented Apr 29, 2021 •

edited

Loading

nageshshamnur commented Apr 29, 2021 •

edited

Loading

nageshshamnur commented May 13, 2021 •

edited

Loading