search

NordicSemiconductor / Android-BLE-Library

A library that makes working with Bluetooth LE on Android a pleasure. Seriously.
BSD 3-Clause "New" or "Revised" License
2.04k stars 419 forks source link

setPreferredPhy in initialize() fails on Android 13 #414

Closed bobatsar closed 2 years ago

bobatsar commented 2 years ago

Setting a preferred PHY in the initialize() method, fails on Android 13 (on a Pixel 4a) but works on older Android versions.

onDeviceReady() is never called on Android 13.

Setting the preferredPHY in the connect request doesn't seem to work at all, even on older devices.

 clientManager.connect(device)
    .useAutoConnect(false)
    .usePreferredPhy(PhyRequest.PHY_LE_2M_MASK)
    .enqueue()

On older devices, I read the PHY in onDeviceReady() and it displays 2M only when setting it in initialize() not via the connectrequest.

I adapted the GattService.kt example to work with my BLE device (uses Nordic UART service). The Android 13 version receives the notifications but onDeviceReady() is not called.

I am testing with 2.5.1 on the latest commit 52d60a4de110b73faef05938ea31a699a9a38163


override fun onDeviceReady() {
    Log.i(TAG, "--------------------------------------")
    Log.i(TAG, "device is ready")
    Log.i(TAG, "--------------------------------------")
    readPhy().enqueue()
    super.onDeviceReady()
}

override fun initialize() {

    setNotificationCallback(mTXCharacteristic)
        .with { _, data ->
            if (data.value != null) {
                val value = String(data.value!!, Charsets.UTF_8)
                defaultScope.launch {
                    myCharacteristicChangedChannel?.send(value)
                }
            }
        }

    enableNotifications(mTXCharacteristic).enqueue()

    if (true && Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
        val bluetoothManager =
            context.getSystemService(Context.BLUETOOTH_SERVICE) as BluetoothManager
        if (bluetoothManager.adapter?.isLe2MPhySupported == true) {
            setPreferredPhy(
                PhyRequest.PHY_LE_2M_MASK,
                PhyRequest.PHY_LE_2M_MASK,
                PhyRequest.PHY_OPTION_NO_PREFERRED
            ).enqueue()
        } else {
            Log.w(TAG, "PHY LE 2M not supported. Run with default 1M")
        }
    }
}
philips77 commented 2 years ago

Thank you for creating the issue. We will investigate it, hopefully next week.

philips77 commented 2 years ago

Setting the preferredPHY in the connect request doesn't seem to work at all, even on older devices.

Yes.. I know, this is kind of a dead API. Android just prefers PHY 2LE if the other side supports it and that's all.

philips77 commented 2 years ago

Similarly, scanning with LE_CODED only doesn't work and always returns both 1M and Coded (if the phone can scan coded at all).

philips77 commented 2 years ago

Also, here:

        val bluetoothManager =
            context.getSystemService(Context.BLUETOOTH_SERVICE) as BluetoothManager
        if (bluetoothManager.adapter?.isLe2MPhySupported == true) {
            setPreferredPhy(
                PhyRequest.PHY_LE_2M_MASK,
                PhyRequest.PHY_LE_2M_MASK,
                PhyRequest.PHY_OPTION_NO_PREFERRED
            ).enqueue()
        } else {
            Log.w(TAG, "PHY LE 2M not supported. Run with default 1M")
        }

you don't have to check it, as the library does it for you, and may report fail if not supported.

bobatsar commented 2 years ago

I just checked with the nrf connect app and there also setting the preferred phy doesn't work on the Pixel 4a. There is just a spinning wheel. On another phone with Android 11 nothing happens but I don't know how I can see the currently used PHY in the nrf connect app. There is the option to read it but I can't find a way to display it.

philips77 commented 2 years ago

It is printed in the log on INFO level. Swipe the services pane to the right to see the log, or select menu->Show log.

bobatsar commented 2 years ago

FYI: it seems the new Gabeldorsche bluetooth stack in Android 13 created multiple issues. https://issuetracker.google.com/issues?q=android%2013%20bluetooth

Could be that this issue is also due to the new stack.

bobatsar commented 2 years ago

FYI: I just did the Android 13 september update and the issue still persists on the Pixel 4A

weliem commented 2 years ago

Looks like an Android 13 bug. I did some isolated tests without using this library and onPhyUpdate is simply never called.

...using a Pixel 5

philips77 commented 2 years ago

Here's the sniffer trace from a test: image

Phone used: Pixel 5, Android 13 (September 5, 2022 security update).

~The phone initiated disconnection upon successful PHY update. For no good reason.~ There was no onPhyUpdate(...) callback invocation, just a disconnection.

Edit: actually, the disconnection was cause by user action. The only issue is lack of onPhyUpdate callback, which hangs the library.

philips77 commented 2 years ago

For comparison, here's Huawei Mate 20 Pro (Android 9) with the same test: image

Logs:

15:15:19.038 BlinkyManagerImpl        V  Requesting preferred PHYs...
15:15:19.040 BlinkyManagerImpl        D  gatt.setPreferredPhy(LE 2M, LE 2M, coding option = No preferred)
15:15:19.528 BluetoothGatt            D  onPhyUpdate() - status=0 address=CB:39:11:19:BA:BD txPhy=2 rxPhy=2
15:15:19.529 BlinkyManagerImpl        I  PHY updated (TX: LE 2M, RX: LE 2M)
15:15:19.540 BlinkyManager            D  Preferred PHY set

Everything seems OK.

weliem commented 2 years ago

The issue is that the call actually succeeds, but the callback is never called....

philips77 commented 2 years ago

And here's Pixel 6 with Android 13, August 5th (not September) security update:

image

Failing just like Pixel 5.

philips77 commented 2 years ago

Tests on Pixel 6 with:

connect(device)
   .usePreferredPhy(PhyRequest.PHY_LE_2M_MASK)
   .enqueue()

The preferred PHY was completely ignored: image despite the device reporting support for it in feature exchange: image

philips77 commented 2 years ago

The same when using Pixel 5: image

  1. The preferred PHY is ignored during connection, all packets are sent with PHY 1M
  2. Calling setPreferredPhy causes disconnection

Fun fact: switching to PHY 2M actually works. The LLCP Length Request packet selected above is sent using PHY 2M: image

philips77 commented 2 years ago

Ok, so what can be done now:

  1. We leave it as is, blaming Android, perhaps filing a bug report. This has some changes to be fixed in Android 14, I believe. Perhaps with a security update?
  2. We may test other (non-Pixel) phones with Android 13, checking if it's on Android side, or Google part.
  3. In BLE library I can add "unless Android 13" check in setPreferredPhy to not call it at all. After all, it's "preferred", and "no change" is better than a disconnection.
bobatsar commented 2 years ago

Thanks for the tests. It seems the Android Bluetooth team was currently working on a fix for the disconnect issue with bonded devices (see https://issuetracker.google.com/issues/242755161) and they said they will ship a fix in an upcoming security update. Perhaps this is also the reason for the disconnect issues on your side.

In my tests (we don't bond the device) I don't have disconnects but as @weliem wrote, the callback is not called so the Android-BLE-Library never completes the connect completely.

So filing a bug report would at least make sure they know of the issue. If you could do that, that would be great.

Currently there aren't much Android 13 phones available but that should change soon.

Checking for Android 13 is what I am doing now. This would at least make sure the connection can be handled but of course this should be removed if this bug is fixed on the android side.

philips77 commented 2 years ago

I edited https://github.com/NordicSemiconductor/Android-BLE-Library/issues/414#issuecomment-1262259744

It was the app triggering disconnection. The only issue is lack of onPhyUpdate(..) callback.

weliem commented 2 years ago

Indeed just the lack of the callback. To make matters worse, I found out that the callback IS called when a Phy request is not supported! Then I get an error....

philips77 commented 2 years ago

I just merged a PR with a workaround. I'll release a new version, could you give it a spin?

philips77 commented 2 years ago

Version 2.6.0-alpha01 should be public in couple of minutes.

bobatsar commented 2 years ago

It seems to work on my Pixel 4a. Thanks for the fix @philips77

When will be an official release?

philips77 commented 2 years ago

My idea was to let people test the new features for couple of days and wait for a feedback. I think there are also 2 other issues I'd like to look into before releasing 2.6.0, but I don't expect any breaking API changes now.

philips77 commented 2 years ago

Btw, in the PR you may see, that there's a 1 second delay, which I give to the native API to call the proper callback. I tried making to 400ms, but that was too short in my case. However, this depends on the connection interval, as setting PHY requires 3 packets. It may not be enough for all cases. Perhaps would be a good idea to base it on the connection parameters callback.

philips77 commented 2 years ago

Sorry, there was an issue in GitHub Actions workflow and the release failed. I'm releasing 2.6.0-alpha01 on Maven Central now.

bobatsar commented 2 years ago

I tested now the 2.6.0-alpha01 with my app and have one more issue. I connect to two devices and the first setPhy on the first device always failes (no error, but the PHY is not updated to 2M. When I retry with setPhy, it is correctly set to 2M.

I can handle this in my code but perhaps this is a general issue. Besides that, it is working.

philips77 commented 2 years ago

Could you share some logs? Also, the current version is 2.6.0-alpha03, but there were no changes to PHY in later releases.

bobatsar commented 2 years ago

Here are some logs, tested with latest October security update on Pixel 4a with 2.6.0-alpha03.

You can see, that the first onPhyRead() returns 1M. When calling setPreferredPhy() again, it is working to set 2M. There is even an error message in the log:

packages/modules/Bluetooth/system/gd/hci/hci_layer.cc:156 on_command_status: Received UNEXPECTED command status:CONTROLLER_BUSY opcode:0x2032 (LE_SET_PHY)

It seems the bluetooth stack also reports the missing callback for onPhyUpdate

2022-10-06 18:23:08.673  bluetooth               W  packages/modules/Bluetooth/system/main/shim/acl.cc:758 OnPhyUpdate: Dropping ACL event with no callback
2022-10-06 18:23:06.481  bt_btif_gattc           I  packages/modules/Bluetooth/system/btif/src/btif_gatt_client.cc:365 btif_gattc_open_impl: Transport=2, device type=2, address type =1, phy=1
2022-10-06 18:23:06.487  bt_btif_gattc           I  packages/modules/Bluetooth/system/btif/src/btif_gatt_client.cc:365 btif_gattc_open_impl: Transport=2, device type=2, address type =1, phy=1
2022-10-06 18:23:06.547  bluetooth               I  packages/modules/Bluetooth/system/stack/gap/gap_ble.cc:303 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:7c:03 callback:Connected
2022-10-06 18:23:06.548  BluetoothRemoteDevices  E  aclStateChangeCallback: device is NULL, address=F7:59:0A:2E:7C:03, newState=0
2022-10-06 18:23:06.549                          D  [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2022-10-06 18:23:06.600  bluetooth               I  packages/modules/Bluetooth/system/stack/gap/gap_ble.cc:303 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:c3:a2 callback:Connected
2022-10-06 18:23:06.608                          D  [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2022-10-06 18:23:07.430                          V  Requesting preferred PHYs...
2022-10-06 18:23:07.430                          D  gatt.setPreferredPhy(LE 2M, LE 2M, coding option = No preferred)
2022-10-06 18:23:07.771                          V  Requesting preferred PHYs...
2022-10-06 18:23:07.771                          D  gatt.setPreferredPhy(LE 2M, LE 2M, coding option = No preferred)
2022-10-06 18:23:08.434                          W  Callback not received in 1000 ms
2022-10-06 18:23:08.434                          V  Reading PHY...
2022-10-06 18:23:08.435                          D  gatt.readPhy()
2022-10-06 18:23:08.440  BluetoothGatt           D  onPhyRead() - status=0 address=F7:59:0A:2E:7C:03 txPhy=1 rxPhy=1
2022-10-06 18:23:08.440                          I  PHY read (TX: LE 1M, RX: LE 1M)
2022-10-06 18:23:08.446                          I  F7:59:0A:2E:7C:03 PHY Updated: (TX: LE 1M, RX: LE 1M)
2022-10-06 18:23:08.446                          W  F7:59:0A:2E:7C:03 PHY not updated -> retrying 1/5
2022-10-06 18:23:08.533                          V  Requesting preferred PHYs...
2022-10-06 18:23:08.533                          D  gatt.setPreferredPhy(LE 2M, LE 2M, coding option = No preferred)
2022-10-06 18:23:08.537  bluetooth               E  packages/modules/Bluetooth/system/gd/hci/hci_layer.cc:156 on_command_status: Received UNEXPECTED command status:CONTROLLER_BUSY opcode:0x2032 (LE_SET_PHY)
2022-10-06 18:23:08.665  bluetooth               W  packages/modules/Bluetooth/system/main/shim/acl.cc:758 OnPhyUpdate: Dropping ACL event with no callback
2022-10-06 18:23:08.673  bluetooth               W  packages/modules/Bluetooth/system/main/shim/acl.cc:758 OnPhyUpdate: Dropping ACL event with no callback
2022-10-06 18:23:08.774                          W  Callback not received in 1000 ms
2022-10-06 18:23:08.774                          V  Reading PHY...
2022-10-06 18:23:08.774                          D  gatt.readPhy()
2022-10-06 18:23:08.778  BluetoothGatt           D  onPhyRead() - status=0 address=DE:31:9A:5F:C3:A2 txPhy=2 rxPhy=2
2022-10-06 18:23:08.778                          I  PHY read (TX: LE 2M, RX: LE 2M)
2022-10-06 18:23:08.784                          I  DE:31:9A:5F:C3:A2 PHY Updated: (TX: LE 2M, RX: LE 2M)
2022-10-06 18:23:09.537                          W  Callback not received in 1000 ms
2022-10-06 18:23:09.537                          V  Reading PHY...
2022-10-06 18:23:09.537                          D  gatt.readPhy()
2022-10-06 18:23:09.542  BluetoothGatt           D  onPhyRead() - status=0 address=F7:59:0A:2E:7C:03 txPhy=2 rxPhy=2
2022-10-06 18:23:09.542                          I  PHY read (TX: LE 2M, RX: LE 2M)
2022-10-06 18:23:09.547                          I  F7:59:0A:2E:7C:03 PHY Updated: (TX: LE 2M, RX: LE 2M)
2022-10-06 18:23:25.873                          D  [Callback] Connection state changed with status: 0 and new state: 0 (DISCONNECTED)
2022-10-06 18:23:25.880                          D  [Callback] Connection state changed with status: 0 and new state: 0 (DISCONNECTED)
2022-10-06 18:23:26.867  l2c_link                W  packages/modules/Bluetooth/system/stack/l2cap/l2c_link.cc:500 l2c_link_timeout: TODO: Remove this callback into bcm_sec_disconnect
2022-10-06 18:23:26.869  l2c_link                W  packages/modules/Bluetooth/system/stack/l2cap/l2c_link.cc:500 l2c_link_timeout: TODO: Remove this callback into bcm_sec_disconnect
2022-10-06 18:23:26.894  bluetooth               I  packages/modules/Bluetooth/system/stack/gap/gap_ble.cc:303 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:7c:03 callback:Disconnected
2022-10-06 18:23:26.895  BluetoothRemoteDevices  E  aclStateChangeCallback: device is NULL, address=F7:59:0A:2E:7C:03, newState=1
2022-10-06 18:23:26.900  bluetooth               I  packages/modules/Bluetooth/system/stack/gap/gap_ble.cc:303 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:c3:a2 callback:Disconnected
philips77 commented 2 years ago

Looks like in your case this 1 second is not enough to complete the PHY request, like I described here: https://github.com/NordicSemiconductor/Android-BLE-Library/issues/414#issuecomment-1262763453

What are the connection parameters used for the connection, do you know?

philips77 commented 2 years ago

If you have the BLE lib included as source, could you try increasing the delay from 1 sec to 2+ seconds, for testing purposes?

https://github.com/NordicSemiconductor/Android-BLE-Library/blob/537b649c3e7eb14a77f539cbd62cd35fc65bcd25/ble/src/main/java/no/nordicsemi/android/ble/BleManagerHandler.java#L3622

jose7165 commented 1 year ago

I edited #414 (comment)

It was the app triggering disconnection. The only issue is lack of onPhyUpdate(..) callback.

Hi! I am just wondering if there was ever an Android issue created to capture this issue at Android 13?

bobatsar commented 1 year ago

@jose7165 I don't think there was an Android Issue created yet.