WorkManager incorrectly treats tasks as being cancelled [122578012]

Fixed

Bug

Status Update

No update yet.

Description

ru...@gmail.com

created issue #1

Jan 9, 2019 05:15PM

Component used: WorkManager
Version used: 1.0.0-beta1
Devices/Android versions reproduced on: API 19

This seems to be happening on API 19 only.

To reproduce, just add a Thread.sleep(1000) in any worker before returning Result.SUCCESS. Worker is stopped due to cancellation instead of being treated as being successful. This causes the worker to being retried.

In our case, the behavior is the same. We're using RxJava and blocking observable operators to perform network requests. This issue causes API 19 devices to keep running the same worker using the backoff strategy instead of marking it as success.

Sample project:

https://github.com/rubensousa/WorkManagerKitkatBug

Comments

ru...@gmail.com <ru...@gmail.com> #2Jan 9, 2019 05:39PM

Please include a sample project that reproduces your issue.

ra...@google.com <ra...@google.com> #3Jan 9, 2019 08:19PM

Status: Won't Fix (Intended Behavior)

Sample project attached. Just add to plain project this dependencies allow to reproduce.

def emoji2_version = "1.1.0-beta01"
implementation "androidx.emoji2:emoji2:$emoji2_version"

def lifecycle_version = "2.5.0-alpha01"
implementation "androidx.lifecycle:lifecycle-process:$lifecycle_version"

ru...@gmail.com <ru...@gmail.com> #4Jan 9, 2019 08:32PM

The reason may be related to this change, which check itself before it is initialized. Use 2.4.0 of lifecycle-process as workaround.

ru...@gmail.com <ru...@gmail.com> #5Jan 9, 2019 08:35PM

Yes, this is due to this change, as well as the fact that EmojiCompatInitializer has a ProcessLifecycleInitializer as a dependency and also re-calls it, but in manual mode.

su...@google.com <su...@google.com> #6Jan 9, 2019 08:40PM

ProcessLifecycleInitializer is expected to already be initialized (via the manifest provider for App Startup) by the time that code runs - App Startup shouldn't be calling create if that component has already been initialized, hence you shouldn't get any exception. We'll take a look on where things are breaking down though.

ru...@gmail.com <ru...@gmail.com> #7Jan 9, 2019 08:45PM

Thanks for the answer.

As I understand EmojiCompatInitializer has ProcessLifecycleInitializer as a dependency. That is mean, the ProcessLifecycleInitializer must be executed before the EmojiCompatInitializer, which in its create method calls the delayUntilFirstResume method, which in turn calls the ProcessLifecycleInitializer via appInitializer.initializeComponent(ProcessLifecycleInitializer.class)

Maybe it would be more correct to create a bug in emoji-2, but let it be here.

ru...@gmail.com <ru...@gmail.com> #8Jan 9, 2019 08:47PM

This issue isn't related to emoji2, it could be reproduced easily with the lifecycle-process (2.4.0 -> 2.5.0-alpha01) only.

ra...@google.com <ra...@google.com> #9Jan 9, 2019 08:54PM

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

commit 97993ad954cb98211ef52b6e26c7877dbdeeec1c
Author: Jeremy Woods <jbwoods@google.com>
Date: Tue Feb 01 17:06:11 2022

Bump lifecycle process start-up dependency to 1.1.1

Bumping the startup dependency to include aosp/1855769.

RelNote: "Updated `lifecycle-process` to depend on [Startup 1.1.1](/jetpack/androidx/releases/startup#1.1.1) to ensure that fixes that prevent `ProcessLifecycleInitializer` from throwing a `StartupException` are available by default."
Bug: 216490724
Test: tested in sample app

Change-Id: Ib01dfbba1d63aa03e43e09ee8886cc76e1050e1b

M lifecycle/lifecycle-process/build.gradle

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

ru...@gmail.com <ru...@gmail.com> #10Jan 9, 2019 08:59PM

This has been fixed internally and will be released in the Lifecycle 2.5.0-alpha02 release.

ra...@google.com <ra...@google.com> #11Jan 9, 2019 09:08PM

When will start-up 1.1.1 release?

ra...@google.com <ra...@google.com> #12Jan 9, 2019 09:09PM

It should be out before the end of the week.

ru...@gmail.com <ru...@gmail.com> #13Jan 9, 2019 09:13PM

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

ra...@google.com <ra...@google.com> #14Jan 9, 2019 09:32PM

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.

to...@gmail.com <to...@gmail.com> #15Jan 9, 2019 09:34PM

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.

su...@google.com <su...@google.com> #16Jan 9, 2019 09:38PM

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.

ru...@gmail.com <ru...@gmail.com> #17Jan 9, 2019 09:47PM

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

ra...@google.com <ra...@google.com> Jan 9, 2019 09:50PM

Assigned to ra...@google.com.

to...@gmail.com <to...@gmail.com> #18Jan 9, 2019 09:56PM

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

ru...@gmail.com <ru...@gmail.com> #19Jan 9, 2019 10:13PM

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

to...@gmail.com <to...@gmail.com> #20Jan 9, 2019 10:29PM

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

to...@gmail.com <to...@gmail.com> #21Jan 9, 2019 10:32PM

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

ra...@google.com <ra...@google.com> #22Jan 9, 2019 10:45PM

https://android-review.googlesource.com/c/platform/frameworks/support/+/867169

ra...@google.com <ra...@google.com> #23Jan 10, 2019 01:00AM

Marked as fixed.

A fix should be available in the next beta.

to...@gmail.com <to...@gmail.com> #24Jan 10, 2019 08:44AM

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

ru...@gmail.com <ru...@gmail.com> #25Jan 10, 2019 09:34AM

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

su...@google.com <su...@google.com> #26Jan 10, 2019 05:05PM

#24: Most likely next week.