WorkManager Periodic work stops after a period [111469837]

Fixed

Bug

Status Update

No update yet.

Description

da...@gmail.com

created issue #1

Jul 15, 2018 06:15PM

I'm using WorkManager alpha-4 and have converted my app's sync jobs to workers. If the device remains plugged in, the periodic jobs run as expected (approx once an hour as scheduled). However, when taking the device off power, allowing it to go to sleep, after a period of time the workers no longer excecute.

My log contains the following statements at the time when the jobs (there are 4) were supposed to execute:

2018-07-15 13:52:15.456 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id 5caee77a-e9c5-4a99-bc7b-651ad21eb94b. Retry requested
2018-07-15 13:52:15.460 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id e3641a8b-1df8-49b9-8c90-1c893c3afc0f. Retry requested
2018-07-15 13:52:15.464 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id db7c03a2-0fe6-42c4-baf8-0ef6e8220e9b. Retry requested
2018-07-15 13:52:15.465 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id d3efce3a-6aa7-4e10-84af-759f1124ccf5. Retry requested

As you can see from the log entries below, things were running just fine up to that point:

2018-07-15 11:30:02.168 12947-12947/com.dvtonder.chronus D/SystemJobService: 5caee77a-e9c5-4a99-bc7b-651ad21eb94b executed on JobScheduler
2018-07-15 11:30:02.396 12947-12947/com.dvtonder.chronus D/SystemJobService: d3efce3a-6aa7-4e10-84af-759f1124ccf5 executed on JobScheduler
2018-07-15 11:30:03.291 12947-12947/com.dvtonder.chronus D/SystemJobService: e3641a8b-1df8-49b9-8c90-1c893c3afc0f executed on JobScheduler
2018-07-15 11:30:03.292 12947-12947/com.dvtonder.chronus D/SystemJobService: db7c03a2-0fe6-42c4-baf8-0ef6e8220e9b executed on JobScheduler
2018-07-15 11:54:09.377 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for b4303ff7-dd6c-4288-8be2-e859c56cddc5
2018-07-15 11:54:09.383 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for 27c2a27b-4da0-4512-ac60-924fb134addd
2018-07-15 11:54:09.478 12947-12947/com.dvtonder.chronus D/SystemJobService: 27c2a27b-4da0-4512-ac60-924fb134addd executed on JobScheduler
2018-07-15 11:54:10.026 12947-12947/com.dvtonder.chronus D/SystemJobService: b4303ff7-dd6c-4288-8be2-e859c56cddc5 executed on JobScheduler
2018-07-15 12:49:00.838 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for e3641a8b-1df8-49b9-8c90-1c893c3afc0f
2018-07-15 12:49:00.865 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for 5caee77a-e9c5-4a99-bc7b-651ad21eb94b
2018-07-15 12:49:01.136 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for db7c03a2-0fe6-42c4-baf8-0ef6e8220e9b
2018-07-15 12:49:01.548 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for d3efce3a-6aa7-4e10-84af-759f1124ccf5
2018-07-15 12:49:09.589 12947-12947/com.dvtonder.chronus D/SystemJobService: db7c03a2-0fe6-42c4-baf8-0ef6e8220e9b executed on JobScheduler
2018-07-15 12:49:17.334 12947-12947/com.dvtonder.chronus D/SystemJobService: d3efce3a-6aa7-4e10-84af-759f1124ccf5 executed on JobScheduler
2018-07-15 12:49:25.292 12947-12947/com.dvtonder.chronus D/SystemJobService: e3641a8b-1df8-49b9-8c90-1c893c3afc0f executed on JobScheduler
2018-07-15 12:49:42.364 12947-12947/com.dvtonder.chronus D/SystemJobService: 5caee77a-e9c5-4a99-bc7b-651ad21eb94b executed on JobScheduler
2018-07-15 12:50:03.938 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for 7fa7b9d0-4e00-466f-a29d-fcc89d4c5b5d
2018-07-15 12:50:04.015 12947-12947/com.dvtonder.chronus D/SystemJobService: 7fa7b9d0-4e00-466f-a29d-fcc89d4c5b5d executed on JobScheduler
2018-07-15 12:50:32.909 12947-12947/com.dvtonder.chronus D/SystemJobService: onStartJob for 204b2e5e-5e24-466e-bdd7-814ef9a4582b
2018-07-15 12:50:33.329 12947-12947/com.dvtonder.chronus D/SystemJobService: 204b2e5e-5e24-466e-bdd7-814ef9a4582b executed on JobScheduler
2018-07-15 13:52:15.456 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id 5caee77a-e9c5-4a99-bc7b-651ad21eb94b. Retry requested
2018-07-15 13:52:15.460 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id e3641a8b-1df8-49b9-8c90-1c893c3afc0f. Retry requested
2018-07-15 13:52:15.464 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id db7c03a2-0fe6-42c4-baf8-0ef6e8220e9b. Retry requested
2018-07-15 13:52:15.465 12947-12947/com.dvtonder.chronus D/SystemJobService: Override deadline expired for id d3efce3a-6aa7-4e10-84af-759f1124ccf5. Retry requested

Comments

ra...@google.com <ra...@google.com> #2Jul 16, 2018 04:50PM

Status: Won't Fix (Intended Behavior)

Yigit, do you have time to fix it?

reemission of the same liveData is racy

da...@gmail.com <da...@gmail.com> #3Jul 16, 2018 06:03PM

yea i'll take it.

da...@gmail.com <da...@gmail.com> #4Jul 16, 2018 09:15PM

Thanks for the detailed analysis. This may not be an issue anymore since we've started using Main.immediate there but I' not sure; I'll try to create a test case.

ra...@google.com <ra...@google.com> #5Jul 16, 2018 09:25PM

just emitting same live data reproduces the issue.

@Test
fun raceTest() {
val subLiveData = MutableLiveData(1)
val subject = liveData(testScope.coroutineContext) {
emitSource(subLiveData)
emitSource(subLiveData) //crashes
}
subject.addObserver().apply {
testScope.advanceUntilIdle()
}
}

da...@gmail.com <da...@gmail.com> #6Jul 16, 2018 09:42PM

With 2.2.0-alpha04 (that use Main.immediate), the issue seems to be still there (I tested it by calling emitSource() twice, like your test case)

da...@gmail.com <da...@gmail.com> #7Jul 16, 2018 11:03PM

yea sorry immediate does not fix it.
I actually have a WIP fix for it:

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

if your case is the one i found (emitting same LiveData multiple times, as shown in #5) you can work around it by adding a dummy transformation.

val subLiveData = MutableLiveData(1)
val subject = liveData(testScope.coroutineContext) {
emitSource(subLiveData.map {it })
emitSource(subLiveData.map {it} )
}

ra...@google.com <ra...@google.com> #8Jul 18, 2018 06:27PM

Assigned to ra...@google.com.

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

commit af12e75e6b4110f48e44ca121466943909de8f06
Author: Yigit Boyar <yboyar@google.com>
Date: Tue Sep 03 12:58:11 2019

Fix coroutine livedata race condition

This CL fixes a bug in liveData builder where emitting same
LiveData source twice would make it crash because the second
emission registry could possibly happen before first one is
removed as source.

We fix it by using a suspending dispose function. It does feel
a bit hacky but we cannot make DisposableHandle.dispose async
and we do not want to block there. This does not mean that there
is a problem if developer disposes it manually since our emit
functions take care of making sure it disposes (and there is
no other way to add source to the underlying MediatorLiveData)

Bug: 140249349
Test: BuildLiveDataTest#raceTest_*

Change-Id: I0b464c242a583da4669af195cf2504e2adc4de40

M lifecycle/lifecycle-livedata-ktx/api/2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/current.txt
M lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_current.txt
M lifecycle/lifecycle-livedata-ktx/api/restricted_2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/restricted_current.txt
M lifecycle/lifecycle-livedata-ktx/src/main/java/androidx/lifecycle/CoroutineLiveData.kt
M lifecycle/lifecycle-livedata-ktx/src/test/java/androidx/lifecycle/BuildLiveDataTest.kt

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

https://goto.google.com/android-sha1/af12e75e6b4110f48e44ca121466943909de8f06

su...@google.com <su...@google.com> Jul 23, 2018 09:53PM

Marked as fixed.

da...@gmail.com <da...@gmail.com> #9Aug 26, 2018 04:28PM

This seems to have been broken with the alpha07 release.

su...@google.com <su...@google.com> #10Aug 27, 2018 07:36PM

Yes, the fix will be out with alpha08 later today.

sa...@gmail.com <sa...@gmail.com> #11Jun 27, 2019 08:20AM

Hi,

Work manager triggering when it started. But in Background (after killing or in doze mode) it is not triggered in 2.0.1 version. Tested mobile Vivo v11 pro, android version 9.

-------Worker class-------

class LocationTracker(private val mContext: Context, workerParams: WorkerParameters) : Worker(mContext, workerParams) {

private val TAG = "LocationTracker"

override fun doWork(): Result {
Log.d(TAG, "doWork: Done")
// var locationRequestListener: LocationRequestListener
Log.d(TAG, "onStartJob: STARTING JOB..")

try {

GPSLocation(applicationContext)

} catch (ignored: ParseException) {
ignored.printStackTrace()
}

return Result.success()
}
}

------ Work manager --------
private fun startLocationTrackingService() {
val constraints = Constraints.Builder()
.setRequiredNetworkType(NetworkType.CONNECTED)
.build()
val periodicWork = PeriodicWorkRequest.Builder(LocationTracker::class.java, 15, TimeUnit.MINUTES)
.addTag(LOCATION_TAG)
.setConstraints(constraints)
.build()
WorkManager.getInstance().enqueueUniquePeriodicWork(LOCATION_TAG, ExistingPeriodicWorkPolicy.KEEP, periodicWork)

}

ra...@google.com <ra...@google.com> #12Jun 27, 2019 02:21PM

Could you please open a new bug ?

Also could you please enable WorkManager logging as it will give us more insight into what is going on. For more information please look at

https://developer.android.com/topic/libraries/architecture/workmanager/advanced/custom-configuration and make sure you use Log.DEBUG

Also check to see if your device has settings for non-standard battery optimizations. Some OEMs force-stop your app when its in the background which means that all your jobs are gone. An easy way to tell whether this is the case to to try and reproduce this problem on an emulator.