IssueTracker

Project: platform/frameworks/support
Branch: androidx-master-dev

commit b90079595f33f58fece04026a97faa0d243acdb1
Author: Yuichi Araki <yaraki@google.com>
Date:   Wed Sep 18 16:55:49 2019

    Change the way to detect mismatch between POJO and query
   
    This fixes cursor mismatch warnings with expandProjection.
   
    Bug: 140759491
    Test: QueryMethodProcessorTest
    Change-Id: I7659002e5e0d1ef60fc1af2a625c0c36da0664d8

M       room/compiler/src/main/kotlin/androidx/room/processor/QueryMethodProcessor.kt
M       room/compiler/src/main/kotlin/androidx/room/solver/TypeAdapterStore.kt
M       room/compiler/src/main/kotlin/androidx/room/solver/query/result/PojoRowAdapter.kt
M       room/compiler/src/test/kotlin/androidx/room/processor/QueryMethodProcessorTest.kt
M       room/compiler/src/test/kotlin/androidx/room/testing/TestProcessor.kt

https://android-review.googlesource.com/1123258
https://goto.google.com/android-sha1/b90079595f33f58fece04026a97faa0d243acdb1

  The following changes were cherrypicked through Coastguard (https://android-build.googleplex.com/coastguard/)
  Release Track: (https://android-build.googleplex.com/coastguard/dashboard/6093116828680192/#/cherrypickHistory/all)
  Created: 2019-10-14 17:23:42.610596+00:00
  Changes: aosp/1123258
 

Project: platform/frameworks/support
Branch: androidx-master-dev

commit bdde5a1a970ddc9007b28de4aa29d60ffa588f08
Author: Yigit Boyar <yboyar@google.com>
Date:   Thu Apr 16 16:47:05 2020

    Re-factor how errors are dismissed when query is re-written
   
    This CL changes how we handle errors/warnings if query is
    re-written.
    There was a bug in expandProjection where we would report warnings
    for things that Room already fixes automatically (b/140759491).
    The solution to that problem (I7659002e5e0d1ef60fc1af2a625c0c36da0664d8)
    solved it by deferring validating of columns until after re-write
    decision is made. Unfortunately, this required changing PojoRowAdapter
    to have a dummy mapping until it is validating, make it hard to use
    as it does have a non-null mapping which is not useful.
   
    This CL partially reverts that change and instead rely on the log
    deferring logic we have in Context. This way, we don't need to break
    the stability of PojoRowAdapter while still having the ability to
    drop warnings that room fixes. This will also play nicer when we
    have different query re-writing options that can use more information
    about the query results.
   
    Bug: 153387066
    Bug: 140759491
    Test: existing tests pass
    Change-Id: I2ec967c763d33d7a3ff02c1a13c6953b460d1e5f

M       room/compiler/src/main/kotlin/androidx/room/log/RLog.kt
M       room/compiler/src/main/kotlin/androidx/room/processor/QueryMethodProcessor.kt
M       room/compiler/src/main/kotlin/androidx/room/solver/TypeAdapterStore.kt
M       room/compiler/src/main/kotlin/androidx/room/solver/query/result/PojoRowAdapter.kt

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

And shouldn't the behaviour be consistent across all Android versions?

We don't see any issues with KEEP.  If you have a way for us to reproduce any problems, please send us the appropriate instructions.

Ok, I found something odd. Seems like  setRequiredNetworkType(NetworkType.UNMETERED) causes this for some reason. I'm going to update the sample so you can review this again. Please, reopen this since it's not intended behavior.

This happens on a fresh install with KEEP instead of REPLACE if the constraints have setRequiredNetworkType(NetworkType.UNMETERED). I've updated the sample

"And shouldn't the behaviour be consistent across all Android versions?"
The behavior is actually consistent. Once your worker starts running, if we get a call to enqueueUniquePeriodicWork a new work request and with ExistingPeriodicWorkPolicy.REPLACE we will stop existing work.
If your Worker was not running, then there is nothing to cancel. This is just a matter of timing.

I'm not arguing against the expected behavior of ExistingPeriodicWorkPolicy.REPLACE, since that's working as intended. But this is happening only when setRequiredNetworkType(NetworkType.UNMETERED) is used while having ExistingPeriodicWorkPolicy.KEEP.

Can you send us an updated sample ?

Looks like you have updated the sample, let me take another look.

Yes, I've updated the sample on github. Thanks for taking another look.

I looked at your code. Looks like the constraints are being unmet after the work starts in some cases.
So essentially, your worker starts, and mid-way the constraints are unmet. At this point because your Worker may not recover gracefully, we cancel and reschedule work. This happens for all your workers actually (if you turn on verbose logging you can see that).
This too is expected.

We have exactly the same issue in a major app - so that even SDK versions < 23 make up a six figure number of installs. We use WorkManager to synchronize data from an api - this should only happen every couple of minutes and due to this issue, it leads to multiple api calls per seconds on those older Android versions, generating an "expensive" load on our cloud-based infrastructure.

Re: #13/14: We're looking at it some more.

#15: File a separate bug, with sample code or a sample app.  The issue is vague enough that there could be something completely different happening.

#14: Even with verbose logging selected, I only see TestWorkerA being cancelled. The other workers are still successful.

I can confirm the root cause is exactly the same here as in our app:

 java.util.concurrent.CancellationException: Task was cancelled.
        at androidx.work.impl.utils.futures.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1184)
        at androidx.work.impl.utils.futures.AbstractFuture.getDoneValue(AbstractFuture.java:514)
        at androidx.work.impl.utils.futures.AbstractFuture.get(AbstractFuture.java:475)
        at androidx.work.impl.WorkerWrapper$2.run(WorkerWrapper.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
        at java.lang.Thread.run(Thread.java:841)

In our case:

 fun scheduleHighlightsSync() {
        val request = PeriodicWorkRequest.Builder(SyncHighlightsWorker::class.java, 1, TimeUnit.HOURS)
                .setConstraints(Constraints.Builder()
                        .setRequiredNetworkType(NetworkType.CONNECTED)
                        .setRequiresBatteryNotLow(true)
                        .build())
                .build()
        WorkManager.getInstance().enqueueUniquePeriodicWork(SYNC_HIGHLIGHTS,
                ExistingPeriodicWorkPolicy.KEEP, request)
    }

according to the logs TimeUnit.HOURS is ignored and we get them several times per second on SDK < 23

01-09 18:36:22.440 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerA: I did some work
01-09 18:36:22.450 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerB: I did some work
01-09 18:36:22.740 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerC: I did some work
01-09 18:36:22.750 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerD: I did some work
01-09 18:36:23.050 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerE: I did some work
01-09 18:36:52.350 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerA: I did some work
01-09 18:36:52.360 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerB: I did some work
01-09 18:36:52.650 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerC: I did some work
01-09 18:36:52.650 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerD: I did some work
01-09 18:36:52.950 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerE: I did some work
01-09 18:37:22.350 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerA: I did some work
01-09 18:37:22.380 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerB: I did some work
01-09 18:37:22.660 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerC: I did some work
01-09 18:37:22.680 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerD: I did some work
01-09 18:37:22.960 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerE: I did some work
01-09 18:38:22.350 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerA: I did some work
01-09 18:38:22.390 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerB: I did some work
01-09 18:38:22.660 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerC: I did some work
01-09 18:38:22.690 12508-12528/com.github.rubensousa.workkitkatbug D/TestWorkerD: I did some work
01-09 18:38:22.950 12508-12529/com.github.rubensousa.workkitkatbug D/TestWorkerE: I did some work


Logs when all workers are affected. Even though Result.sucess() was returned, due to this issue, WorkManager keeps retrying them. You can see the exponential backoff starting at 30 sec and going to 1 min, 2 min, 4 min etc

Yes, definitely not 15 minutes as in your github example project.

I think if this issue can not be solved quickly, https://developer.android.com/topic/libraries/architecture/workmanager/ needs a big warning message for SDK < 23 - at least for periodic jobs

A fix should be available in the next beta.

Thanks!!! Is there a time estimate for the next beta ?

#23: Thank you so much for taking another look and solving the issue :)

#24: Most likely next week.