BLE scan with PendingIntent after connection was closed [142404995]

Infeasible

Bug

[AOSP] assigned

Status Update

No update yet.

Description

ma...@gmail.com

created issue #1

Oct 10, 2019 11:31AM

Hi there,

I'm developing a BLE application which searches for a device, then connects to it, does some communication and finally closes the connection. Afterwards, I start scanning again. In order to be able to do that in the background, I use the startScan call with a PendingIntent as parameter.

What I expect is that the scanning starts immediately after the connection was closed. But instead, I instantly get some scan results (I assume that they're old because the RSSI value is not appropriate). Then it takes around 9 seconds until I get another result. During this, I see something like the following lines (interval matches the advertising rate of my peripheral) all times:

10-10 13:12:00.816 6016 6096 D ScanRecord: Not a Multi Manu data
10-10 13:12:00.816 6016 6096 D ScanRecord: Not a Multi Manu data
10-10 13:12:00.816 6016 6096 D BtGatt.GattService: onScanResult to scannerId: 7- eventType=0x1b, addressType=1, address=FD:D, primaryPhy=1, secondaryPhy=0, advertisingSid=0xff, txPower=127, rssi=-70, periodicAdvInt=0x0

After these 9 seconds, I always see the following messages:

10-10 13:23:05.187 7915 21193 W NamedFutures: Timeout future task has been cancelled: 9000 milliseconds
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: Task 174 failed or timed out. Client 34812108658243306 disconnecting from SearchService!
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: java.util.concurrent.CancellationException: Task was cancelled.
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.common.s.a.d.c(SourceFile:114)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.common.s.a.d.get(SourceFile:74)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.common.s.a.dk.a(SourceFile:1)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.common.s.a.bv.a(SourceFile:6)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.common.s.a.br.run(SourceFile:4)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.google.android.apps.gsa.shared.util.c.a.bb.run(SourceFile:2)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at android.os.Handler.handleCallback(Handler.java:873)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at android.os.Handler.dispatchMessage(Handler.java:99)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at android.os.Looper.loop(Looper.java:214)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at android.app.ActivityThread.main(ActivityThread.java:7037)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at java.lang.reflect.Method.invoke(Native Method)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:494)
10-10 13:23:05.189 7915 7915 E SearchServiceStarter: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:965)

After this, I receive an intent for ACL_DISCONNECTED and then my expected scan results.

What makes me wonder is the correlation between the 9 seconds from starting to scan until getting the scan results and the 9 seconds mentioned in the NamedFutures message.

I tried my code on a Samsung S10 (Android 9) and a Google Pixel 3a (Android 10). Attached you can find a sample project to try it out.

This strange behavior does not exist if I don't connect to a device but simply stop and restart the scan.

deleted

Restricted

0 B

Comments

ma...@gmail.com <ma...@gmail.com> #2Oct 10, 2019 03:58PM

Project: platform/frameworks/support
Branch: androidx-main

commit e1b42da3ee5bcb06756d8cb8377abf6116086e11
Author: Sanura N'Jaka <sanura@google.com>
Date: Tue Sep 07 20:23:52 2021

Make nullable NavDeepLink arguments not required

Removing the inclusion of nullable NavDeepLink
arguments from the "required" argument checking.

RelNote: "Nullable `NavDeepLink` arguments no longer
require a default value."
Test: deepLinkNullableArgumentNotRequired test
Bug: 198689811

Change-Id: Ia14ef04bfe5b25942163688f40adacc30fa7e044

M navigation/navigation-common/src/androidTest/java/androidx/navigation/AddInDefaultArgsTest.kt
M navigation/navigation-common/src/androidTest/java/androidx/navigation/NavDeepLinkTest.kt
M navigation/navigation-common/src/androidTest/java/androidx/navigation/test/NavArgument.kt
M navigation/navigation-common/src/main/java/androidx/navigation/NavDeepLink.kt

https://android-review.googlesource.com/1817360

am...@google.com <am...@google.com> #3Oct 15, 2019 08:09AM

Assigned to am...@google.com.

There's two issues here:

android:defaultValue="@null" is actually treated as the defaultValue attribute not existing at all at runtime (we do still use it for Safe Args)
We enforced every argument without a default value to be present in the URI/route, even if it was nullable.

While we can't fix the first one, we have made the change in Navigation 2.4.0-alpha09 to only check for default values for non-nullable parameters. This should mean that

Using android:defaultValue="@null" won't be a problem
Constructing a type in the Kotlin DSL via navArgument("argument_name") and making it nullable = true without a default value won't be a problem.

ma...@gmail.com <ma...@gmail.com> #4Oct 17, 2019 08:54AM

Unfortunately I still experience this bug with 2.4.0-alpha09 :(

java.lang.IllegalArgumentException: Deep link penny://app/offers can't be used to open destination Destination(de.penny.app.debug:id/offerListFragment) label=OfferListFragment class=de.penny.feature.offer.view.OfferListFragment.
    Following required arguments are missing: [sectionIndexOrName, raffleId]

This is the excerpt from my navigation graph XML:

<argument
    android:name="sectionIndexOrName"
    android:defaultValue="@null"
    app:argType="string"
    app:nullable="true" />

<argument
    android:name="raffleId"
    android:defaultValue="@null"
    app:argType="string"
    app:nullable="true" />

<deepLink
    android:id="@+id/offersDeeplink"
    app:uri="penny://app/offers" />

As you can see both parameters are nullable and have a default value of null.

ma...@gmail.com <ma...@gmail.com> #5Oct 21, 2019 08:30AM

Re comment#4 - please file a new bug with a sample project that reproduces your issue.

ma...@gmail.com <ma...@gmail.com> #6Oct 21, 2019 10:18AM

I'm sorry, I forgot to upgrade the Safe Args Gradle plugin as well. However when upgrading the plugin I now get another error.

ma...@gmail.com <ma...@gmail.com> #7Oct 29, 2019 09:46AM

Are there any updates to this issue? Can you at least confirm or falsify the observed behavior?

ma...@gmail.com <ma...@gmail.com> #8Nov 26, 2019 07:56AM

Any updates yet? Just asking ...

ma...@gmail.com <ma...@gmail.com> #9Jan 13, 2020 03:43PM

I did more testing on a Google Pixel 2: This (IMHO) misbehavior leads to the system iterating over outdated scan results for several minutes. Eventually, it is never able to keep up with sending incoming scan results (only very few BLE devices in the environment but they're advertising at a high rate) to the application immediately.

Currently, I cannot reproduce it anymore, but I was able that the operating system gathered more and more heap and the GC was not able to free it which resulted in a reboot.

When I had a look at Android Studio's profiler, the app memory did not increase that much (around 5MB), at the time of the reboot the app used ~50MB.

Needless to say, but an app must not be able to crash the whole system! So please take it seriously and investigate in this issue.

am...@google.com <am...@google.com> #10Jan 20, 2020 07:17AM

Thank you for reporting this issue. We’ve shared this with our product and engineering teams and will continue to provide updates as more information becomes available.

ma...@gmail.com <ma...@gmail.com> #11Jan 23, 2020 09:02AM

Thank you very much for the feedback!

IMHO the BLE stack on Android needs a complete overhaul so that the OS takes more control over it. Currently, it's too easy to write a program to kill the BLE stack so it's unusable until Bluetooth was turned off and on again.

am...@google.com <am...@google.com> #12May 29, 2020 11:53AM

Status: Won't Fix (Infeasible)

Thanks for taking the time to report! We took a look during our triage, and unfortunately, realistically with other fires and problems we’re dealing with we won’t be able to give your bug the attention we really want to. So regrettably, we’re closing it.