Android service discovery never completes

Question

Android service discovery never completes

tigohenryschultz opened this issue a year ago · 30 comments

tigohenryschultz commented a year ago

We are seeing a bug where the connect never triggers success or fail.

We are reverting back to 1.4.1 for now.

Not seeing any errors in the logs either, our app just gets stuck 'connecting'.

What is the timeout threshold?

Answer 1 · 2023-02-08T22:17:10.000Z

Interesting. Are you able to try a few of the releases between 1.4.1 and 1.6.1 to hopefully narrow down when the regression might have occurred?

I'm using 1.6.1 myself and haven't encountered any issue like this so far 🤔

Answer 2 · 2023-02-08T22:19:31.000Z

What is your android target and compile SDK versions? The biggest changes between those versions is related to Android 12 support.

Any details about the phone you are seeing this issue with? Is it a variety of phones/Android versions?

Answer 3 · 2023-02-08T22:22:50.000Z

@tigohenryschultz just to confirm... are you using the slim variant of the plugin that requires you to manually specify the necessary manifest permissions, or just the normal 1.6.1 plugin?

Answer 4 · 2023-02-08T23:44:04.000Z

I tried 1.4.1-slim but will try 1.6.1-slim now.

Both are Android 12(Sony / Galaxy 21)

ext {
versionCode = 47203
versionName = "4.7.2"
minSdkVersion = 22
compileSdkVersion = 31
targetSdkVersion = 31
androidxActivityVersion = '1.4.0'
androidxAppCompatVersion = '1.4.2'
androidxCoordinatorLayoutVersion = '1.2.0'
androidxCoreVersion = '1.8.0'
androidxFragmentVersion = '1.4.1'
coreSplashScreenVersion = '1.0.0-rc01'
androidxWebkitVersion = '1.4.0'
junitVersion = '4.13.2'
androidxJunitVersion = '1.1.3'
androidxMaterialVersion = '1.6.1'
androidxBrowserVersion = '1.4.0'
androidxLocalbroadcastmanagerVersion = '1.0.0'
androidxExifInterfaceVersion = '1.3.3'
firebaseMessagingVersion = '23.0.5'
playServicesLocationVersion = '20.0.0'
androidxEspressoCoreVersion = '3.4.0'
cordovaAndroidVersion = '10.1.1'
}

Answer 5 · 2023-02-08T23:46:59.000Z

Turning BLE off and on on the phone seems to make it work the first connect but the second is always problematic, investigating more.

Answer 6 · 2023-02-08T23:56:56.000Z

1.6.1-slim has the same issue on S21+ and Sony XQ-BC62. First time is successful, the second one the connect gets stuck. Both running Android 13 with new issues other than Android 12.

Answer 7 · 2023-02-08T23:59:38.000Z

Android 12 on a tablet works fine with 1.6.1

No problems. Seems like Android 13.

Answer 8 · 2023-02-09T02:17:37.000Z

Interesting. With 1.4.1, were you using v31 for the compile SDK, or were you targeting and earlier version?

I'll see if I can dig up access to an Android 13 phone and play 🙂

Answer 9 · 2023-02-09T02:22:37.000Z

Yeah we were using 31, Updated both to 33 to test and same issues.

Answer 10 · 2023-02-09T09:20:30.000Z

@tigohenryschultz so... I dug a Pixel 4a with Android 13, but haven't been able to reproduce the issue you are seeing here with a barebones cordova app.

I have seen that attempting to connect quickly after a disconnect often results in a Peripheral Disconnected error, but that doesn't sound relevant to what you're experiencing here.

Does the device require some kind of pairing or bonding per chance?

Are you able to capture the logcat output of a successful connection followed by a hung connection and put them here?

With regards your environment, are you using this with cordova or capacitor? Are there any other plugins that might possibly conflict with this plugin?

Answer 11 · 2023-02-09T09:23:34.000Z

The total changes between these versions can be found here: 1.4.1...1.6.1

There's nothing there in review that stands out to me obviously.

What's the exact plugin variant & version you're having the issue with? Is it the slim or normal variant? (I think you said slim already.. but just want to confirm).

If it's the slim variant, what Bluetooth-related permissions are you using in your AndroidManifest.xml?

Answer 12 · 2023-02-09T19:13:06.000Z

1.4.1 slim and 1.6.1 slim, both are having issues for Android 13

    <uses-permission android:name="android.permission.ACCESS_COARSE_LOCATION" />
    <uses-permission android:name="android.permission.ACCESS_FINE_LOCATION" />
    <uses-permission android:maxSdkVersion="30" android:name="android.permission.BLUETOOTH" />
    <uses-permission android:maxSdkVersion="30" android:name="android.permission.BLUETOOTH_ADMIN" />
    <uses-permission android:name="android.permission.BLUETOOTH_SCAN" android:usesPermissionFlags="neverForLocation" />
    <uses-permission android:name="android.permission.BLUETOOTH_CONNECT" />
    <uses-permission android:name="android.permission.INTERNET" />
    <uses-permission android:name="android.permission.READ_EXTERNAL_STORAGE" />
    <uses-permission android:name="android.permission.WRITE_EXTERNAL_STORAGE" />
    <uses-permission android:name="android.permission.ACCESS_NETWORK_STATE" />
    <uses-permission android:name="android.permission.CAMERA" />
    <uses-permission android:name="android.permission.RECORD_AUDIO" />
    <uses-permission android:name="android.permission.MODIFY_AUDIO_SETTINGS" />

Answer 13 · 2023-02-09T22:22:48.000Z

Any chance of getting an android logcat (adb logcat) log of the scenario?

Also, are you using cordova or capacitor? If capacitor, are you using the capacitor community wrapper?

Answer 14 · 2023-02-09T23:51:08.000Z

I am using capacitor but not sure if it is the community wrapper. I'll send the adb logcat tomorrow when I start work. I reverted our app back to: https://github.com/tigohenryschultz/cordova-plugin-ble-central

The 1.6.1-slim 1.4.1-slim had location permission issues and was not prompting for us properly. My fork/change does work for now but still have the connect stuck bug on Android 13.

Answer 15 · 2023-02-10T01:15:55.000Z

Right. I suspect the compile SDK detection code is not behaving properly with capacitor... will double-check and raise a bug if that's the case 🙂

Answer 16 · 2023-02-10T19:09:11.000Z

Here are the logs:

The first time we try it works:
Success.txt

The second time it fails:(gets stuck connecting forever)

error.txt

Answer 17 · 2023-02-13T01:29:43.000Z

The key difference is that service discovery does not seem to complete in the second case.

In the good case, the logs show this:

2023-02-10 11:06:34.666 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x0001, e_handle=0x0006
2023-02-10 11:06:34.666 15013-15041/? D/BtGatt.GattService: onClientConnUpdate() - connId=9, status=0
2023-02-10 11:06:34.666 27190-27274/? D/BluetoothGatt: onConnectionUpdated() - Device=04:C0:5B:80:BC:D1 interval=6 latency=0 timeout=500 status=0
2023-02-10 11:06:34.680 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.680 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x0001, e_handle=0x0006
2023-02-10 11:06:34.695 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 15
2023-02-10 11:06:34.710 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.710 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x0004, e_handle=0x0004
2023-02-10 11:06:34.725 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:06:34.725 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x0007, e_handle=0x000a
2023-02-10 11:06:34.741 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.741 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x0007, e_handle=0x000a
2023-02-10 11:06:34.755 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 8
2023-02-10 11:06:34.770 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.770 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000a, e_handle=0x000a
2023-02-10 11:06:34.785 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:06:34.786 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x000b, e_handle=0x0012
2023-02-10 11:06:34.800 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.800 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x000b, e_handle=0x0012
2023-02-10 11:06:34.815 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 22
2023-02-10 11:06:34.830 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:06:34.830 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000e, e_handle=0x000e
2023-02-10 11:06:34.846 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:06:34.861 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 15, msg_len = 4
2023-02-10 11:06:34.864 15013-15072/? I/bt_stack: [INFO:bta_gattc_cache.cc(230)] bta_gattc_explore_srvc_finished: service discovery finished

In the error case, this occurs instead:

2023-02-10 11:07:22.547 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x0001, e_handle=0x0006
2023-02-10 11:07:22.547 15013-15041/? D/BtGatt.GattService: onClientConnUpdate() - connId=9, status=0
2023-02-10 11:07:22.547 27190-27351/? D/BluetoothGatt: onConnectionUpdated() - Device=04:C0:5B:80:BC:D1 interval=6 latency=0 timeout=500 status=0
2023-02-10 11:07:22.561 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.561 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x0001, e_handle=0x0006
2023-02-10 11:07:22.576 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 15
2023-02-10 11:07:22.591 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.591 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x0004, e_handle=0x0004
2023-02-10 11:07:22.605 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:07:22.605 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x0007, e_handle=0x000a
2023-02-10 11:07:22.621 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.621 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x0007, e_handle=0x000a
2023-02-10 11:07:22.643 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 8
2023-02-10 11:07:22.658 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.658 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000a, e_handle=0x000a
2023-02-10 11:07:22.674 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:07:22.674 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=3, s_handle=0x000b, e_handle=0x0012
2023-02-10 11:07:22.689 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.689 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=4, s_handle=0x000b, e_handle=0x0012
2023-02-10 11:07:22.703 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 9, msg_len = 22
2023-02-10 11:07:22.718 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.718 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000e, e_handle=0x000e
2023-02-10 11:07:22.733 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:07:22.748 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
[ last line repeats forever ]

Is there any possibility of a firmware bug here?

Answer 18 · 2023-02-13T01:42:44.000Z

interestingly, the last GATTC_Discover message there is very different between the good & bad cases.

In the good case, this is:

2023-02-10 11:06:34.830 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000e, e_handle=0x000e
2023-02-10 11:06:34.846 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:06:34.861 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 15, msg_len = 4
2023-02-10 11:06:34.864 15013-15072/? I/bt_stack: [INFO:bta_gattc_cache.cc(230)] bta_gattc_explore_srvc_finished: service discovery finished

In the bad case, you instead get:

2023-02-10 11:07:22.718 15013-15072/? I/bt_stack: [INFO:gatt_api.cc(930)] GATTC_Discover conn_id=0x0009, disc_type=5, s_handle=0x000e, e_handle=0x000e
2023-02-10 11:07:22.733 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 5, msg_len = 5
2023-02-10 11:07:22.748 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
2023-02-10 11:07:22.763 15013-15072/? I/bt_stack: [INFO:gatt_main.cc(1716)] gatt_data_process op_code = 1, msg_len = 4
...

That op_code = 1, msg_len = 4 seems like the same data is being sent over and over again by the peripheral (or Android's BLE stack is getting caught in a loop).

Answer 19 · 2023-02-13T02:09:57.000Z

I reverted to 1.4.1 and onky the Sony phone has the issue still, Samsung and Google pixel all Android 13 are good

Answer 20 · 2023-02-13T03:01:12.000Z

Are you also changing the compileSdk or targetSdk versions when going back to 1.4.1?

Answer 21 · 2023-02-15T01:31:30.000Z

@czzplnm are you using refreshDeviceCache routinely in your code?

Answer 22 · 2023-02-15T07:26:11.000Z

I've published 1.6.2, which reverts some behaviour around refreshDeviceCache to 1.4.1 functionality. Are you able to give this a go and see if it helps?

Answer 23 · 2023-02-15T17:25:59.000Z

@czzplnm are you using refreshDeviceCache routinely in your code?

I don't use this at all, I will check 1.6.2 shortly. Thanks for checking out this issue!

Answer 24 · 2023-02-15T22:17:50.000Z

Still seeing the issue and verified 1.6.2 with our npx cap sync:

[capacitor] [info] Found 11 Cordova plugins for android:
[capacitor]        cordova-plugin-advanced-http@3.3.1
[capacitor]        cordova-plugin-android-permissions@1.1.5
[capacitor]        cordova-plugin-ble-central@1.6.2
[capacitor]        cordova-plugin-file@6.0.2
[capacitor]        cordova-plugin-globalization@1.11.0
[capacitor]        cordova-plugin-network-information@2.0.2
[capacitor]        cordova-plugin-screen-orientation@3.0.2
[capacitor]        cordova-plugin-wifiwizard2@3.1.1
[capacitor]        cordova.plugins.diagnostic@7.1.1
[capacitor]        es6-promise-plugin@4.2.2
[capacitor]        phonegap-plugin-barcodescanner@8.1.1-dev
[capacitor] √ update android in 283.14ms
[capacitor] [info] Sync finished in 0.884s

This particular Sony phone seems to have the issue most prevalent. We have pushed our app with the old Android 12 changes and have not heard from any users about this.

Answer 25 · 2023-02-15T23:33:02.000Z

Are you able to link me to the commit that you are using successfully? (i.e., what code is in the old Android 12 changes you've noted there)

From what I'm understanding, currently you are seeing:

1.4.1-slim = good
1.6.1-slim = bad
1.6.2-slim = bad

Is this accurate?

Answer 26 · 2023-02-15T23:35:47.000Z

The Sony phone has problems with all of them but my phone and the Google Pixel we used had less issues with this fork:

https://github.com/tigohenryschultz/cordova-plugin-ble-central

I did see the Connecting stuck on my Samsung S21+ but I don't see that on that fork. If you want me to test anything specific let me know.

Answer 27 · 2023-03-16T10:21:02.000Z

Quick thing that I noticed in passing... Are you using compileSdkVersion = 31 for all these tests? If so, how are you granting the necessary permissions for 1.4.1 with Android 12+, as compatibility in the plugin wasn't until 1.5.0 at the earliest...

Answer 28 · 2023-03-16T16:39:03.000Z

In some scenarios we use this plugin for invoking permissions:

cordova.plugins.diagnostic

Answer 29 · 2023-05-05T21:43:05.000Z

@tigohenryschultz just in case you still have a setup to reproduce this issue, I've pushed a test package with a hard-coded 1s delay befor6 performing service discovery after connecting.

You can install this via npm install cordova-plugin-ble-central@1.7.0-alpha.1

I'd be interested to know if this affects your connect reliability at all.

Answer 30 · 2023-11-11T00:36:51.000Z

Closing this out as no underlying cause has been found, and it lacks sufficient information to root-cause further.