Workers executed when constraint is met crashing on Android 4.4-5.1 (WorkManager scheduling instead of JobService) [129226383]

Fixed

Bug

Status Update

No update yet.

Description

jo...@gmail.com

created issue #1

Mar 25, 2019 09:29AM

Component used: androidx.work:work-runtime
Version used: 2.0.0
Devices/Android versions reproduced on: reported on Android 5.0/5.1 (Play Console) / Android 4.4.2/4.4.4/5.0-5.1.1 (Firebase Crashlytics). Multiple devices from various manufacturers, including Samsung, Lenovo, LG, Motorola, HTC, Sony and Asus.

After updating our app from android.arch.work:work-runtime:1.0.0-rc02 to androidx.work:work-runtime:2.0.0, we're seeing crashes when WorkManager starts a job for a significant amount of our users, which doesn't make much sense because the code should be similar to the previous version but it is still a problem.
Unfortunately, we haven't been able to replicate the issue on our 4.4.2 test device. Because the issue is limited to Android versions where JobService isn't used (and the stack trace, see below), it seems like the issue is caused by WorkManager's scheduling and not the job itself.

The worker is set up by a periodic request:

Constraints workerConstraints = new Constraints.Builder().setRequiredNetworkType(NetworkType.CONNECTED).build();
PeriodicWorkRequest userUpdateWorker = new PeriodicWorkRequest.Builder(UserUpdateWorker.class, 8, TimeUnit.HOURS)
.addTag(UserUpdateWorker.class.getName())
.setConstraints(workerConstraints)
.build();
WorkManager.getInstance().enqueue(userUpdateWorker);

Stack trace from the Crashlytics/Play Console crash reports:

Fatal Exception: java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateBroadcastReceiver@42849958
at android.app.LoadedApk$ReceiverDispatcher$Args.run (LoadedApk.java:941)
at android.os.Handler.handleCallback (Handler.java:739)
at android.os.Handler.dispatchMessage (Handler.java:95)
at android.os.Looper.loop (Looper.java:145)
at android.app.ActivityThread.main (ActivityThread.java:6117)
at java.lang.reflect.Method.invoke (Method.java)
at java.lang.reflect.Method.invoke (Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:1399)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1194)
Caused by java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2ac263d0 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@320e0fc9[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution (ThreadPoolExecutor.java:2011)
at java.util.concurrent.ThreadPoolExecutor.reject (ThreadPoolExecutor.java:793)
at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute (ScheduledThreadPoolExecutor.java:298)
at java.util.concurrent.ScheduledThreadPoolExecutor.schedule (ScheduledThreadPoolExecutor.java:503)
at java.util.concurrent.Executors$DelegatedScheduledExecutorService.schedule (Executors.java:644)
at androidx.work.impl.background.systemalarm.WorkTimer.startTimer (WorkTimer.java:82)
at androidx.work.impl.background.systemalarm.DelayMetCommandHandler.onAllConstraintsMet (DelayMetCommandHandler.java:100)
at androidx.work.impl.constraints.WorkConstraintsTracker.onConstraintMet (WorkConstraintsTracker.java:150)
at androidx.work.impl.constraints.controllers.ConstraintController.updateCallback (ConstraintController.java:134)
at androidx.work.impl.constraints.controllers.ConstraintController.onConstraintChanged (ConstraintController.java:141)
at androidx.work.impl.constraints.trackers.ConstraintTracker.setState (ConstraintTracker.java:103)
at androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateBroadcastReceiver.onReceive (NetworkStateTracker.java:170)
at android.app.LoadedApk$ReceiverDispatcher$Args.run (LoadedApk.java:931)
at android.os.Handler.handleCallback (Handler.java:739)
at android.os.Handler.dispatchMessage (Handler.java:95)
at android.os.Looper.loop (Looper.java:145)
at android.app.ActivityThread.main (ActivityThread.java:6117)
at java.lang.reflect.Method.invoke (Method.java)
at java.lang.reflect.Method.invoke (Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:1399)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1194)

Comments

jo...@gmail.com <jo...@gmail.com> #2Mar 25, 2019 09:48AM

Yigit, do you have time to fix it?

reemission of the same liveData is racy

je...@gmail.com <je...@gmail.com> #3Mar 25, 2019 03:26PM

yea i'll take it.

ra...@google.com <ra...@google.com> Mar 25, 2019 09:05PM

Assigned to ra...@google.com.

ap...@google.com <ap...@google.com> #4Mar 26, 2019 12:05AM

Marked as fixed.

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.

jo...@gmail.com <jo...@gmail.com> #5Mar 26, 2019 05:53AM

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()
}
}

ra...@google.com <ra...@google.com> #6Mar 26, 2019 05:25PM

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)

di...@gmail.com <di...@gmail.com> #7Apr 1, 2019 07:20PM

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} )
}

[Deleted User] <[Deleted User]> #8Apr 1, 2019 07:32PM

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

dr...@gmail.com <dr...@gmail.com> #9Apr 6, 2019 09:13AM

Thanks for reporting this, OP, and thanks for the quick fix, Android team... my users were seeing this too...

li...@gmail.com <li...@gmail.com> #10May 17, 2019 02:14AM

We are using workmanager 2.1.0-alpha01 which include code change of

https://android-review.googlesource.com/933140, but a lot crashes caused by same problems still showing in firebase console.

Affected Android Version
62% Android 5
37% Android 4
1% Android 6

Fatal Exception: java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateBroadcastReceiver@42203f30
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:769)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5433)
at java.lang.reflect.Method.invokeNative(Method.java)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1268)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1084)
at dalvik.system.NativeStart.main(NativeStart.java)

Caused by java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@421dec00 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@4222d1a8[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2011)
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:793)
at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:298)
at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:503)
at java.util.concurrent.Executors$DelegatedScheduledExecutorService.schedule(Executors.java:644)
at androidx.work.impl.background.systemalarm.WorkTimer.startTimer(WorkTimer.java:82)
at androidx.work.impl.background.systemalarm.DelayMetCommandHandler.onAllConstraintsMet(DelayMetCommandHandler.java:100)
at androidx.work.impl.constraints.WorkConstraintsTracker.onConstraintMet(WorkConstraintsTracker.java:150)
at androidx.work.impl.constraints.controllers.ConstraintController.updateCallback(ConstraintController.java:134)
at androidx.work.impl.constraints.controllers.ConstraintController.onConstraintChanged(ConstraintController.java:141)
at androidx.work.impl.constraints.trackers.ConstraintTracker.setState(ConstraintTracker.java:103)
at androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateBroadcastReceiver.onReceive(NetworkStateTracker.java:170)
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:759)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5433)
at java.lang.reflect.Method.invokeNative(Method.java)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1268)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1084)
at dalvik.system.NativeStart.main(NativeStart.java)

ra...@google.com <ra...@google.com> #11May 17, 2019 06:03PM

Are you sure that these crash reports are coming from the latest version of your app which has the new version of WorkManager ?

ar...@gmail.com <ar...@gmail.com> #12Jun 10, 2019 01:18PM

According to release notes this crash have been fixed in 2.0.1, but we recently update work manager from 1.0.0 to 2.0.1 and now it is our top crash.

ra...@google.com <ra...@google.com> #13Jun 10, 2019 04:05PM

This would still happen in some rare conditions. So we have another fix for it in 2.1.0-alpha03.

[Deleted User] <[Deleted User]> #14Feb 25, 2020 12:36PM

I'm also getting same crash in Google Play console only for android-sdk 4.4 to 5.2
used work manager version = '2.3.0'
implementation "androidx.work:work-runtime:2.3.0"

This is Top most crash in my App Account.

Message last modified on Feb 25, 2020 12:39PM

mi...@charter.com <mi...@charter.com> #15Apr 1, 2020 11:28PM

We have noticed a huge surge in this issue after migrating to Android Studio 3.6 in our latest release (updated classpath in root build.gradle to "com.android.tools.build:gradle:3.6.x" -- we were previously on 3.4.2).

Doing so, forced our work manager to version up to 2.0.0, even though we are still declaring 1.x in our dependencies (Gradle automatically chooses the latest version to resolve dependency version conflicts).
This introduced the same crash and logs mentioned in earlier comments on this issue tracker ticket.

This crash bug was likely not fixed until 2.2.0-rc1:

https://developer.android.com/jetpack/androidx/releases/work#2.2.0-rc01

So our attempted solution was to adopt the latest stable version of work manager (2.3.4 according to the documentation). However, with this new gradle build tools version, the dependency appears to be locked to 2.0.0 no matter what we try. Using "strictly" or "force" as described in the gradle documentation seems to have to no effect. And using exclude does not make much sense.

https://docs.gradle.org/current/userguide/dependency_downgrade_and_exclude.html

When using Gradle's dependency insight, we can see that for some reason after the migration, the dependency now has a new selection reason.
"Selected by rule : ENABLE_JETIFIER is enabled".

So at this point, it seems our options appear to be:
- Waiting for fix from Google or Gradle,
- Disabling jetifier and refactoring everything in order to avoid using AndroidX components.
- Revert our migration to Android Studio 3.6
- Remove work manager dependency altogether for the OS versions / device models affected

Hopefully this information helps, and hopefully it gets resolved soon!

Message last modified on Apr 2, 2020 03:11PM

il...@google.com <il...@google.com> #16Apr 1, 2020 11:37PM

Re #15 - make sure you're using androidx.work and not the android.arch.work group ID in your dependency (using android.arch.work will cause the behavior you're seeing) as per the documentation.

mi...@charter.com <mi...@charter.com> #17Apr 2, 2020 03:18PM

My goodness, thank you so much for responding so quickly! I must have looked over those code snippets a dozen times and did not realize this change.
Yes, it works when migrating to the androidX group id. Perhaps the AndroidX migration guide needs to add this dependency as well:

https://developer.android.com/jetpack/androidx/migrate/artifact-mappings