ANR/Deadlock [134361006]

Fixed

Bug

Status Update

No update yet.

Description

d....@googlemail.com

created issue #1

Jun 3, 2019 10:37AM

Component used: WorkManager
Version used: 1.0.1
Devices/Android versions reproduced on: different Samsung Galaxy devices running Android 8 and 9

I have received deadlock reports like this:

"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x76790a58 self=0x7d81014c00
| sysTid=27874 nice=0 cgrp=default sched=0/0 handle=0x7e07c1a560
| state=S schedstat=( 1835900780 7285545518 5958 ) utm=82 stm=100 core=1 HZ=100
| stack=0x7febcdd000-0x7febcdf000 stackSize=8MB
| held mutexes=
at androidx.work.impl.constraints.trackers.ConstraintTracker.removeListener (ConstraintTracker.java:77)
- waiting to lock <0x08a4f10d> (a java.lang.Object) held by thread 13 // ConstraintTracker.mLock
at androidx.work.impl.constraints.controllers.ConstraintController.replace (ConstraintController.java:98)
at androidx.work.impl.constraints.WorkConstraintsTracker.replace (WorkConstraintsTracker.java:99)
- locked <0x0cbac8c2> (a java.lang.Object) // WorkConstrainsTracker.mLock
at androidx.work.impl.background.greedy.GreedyScheduler.removeConstraintTrackingFor (GreedyScheduler.java:153)
- locked <0x0cbec6d3> (a java.lang.Object) // GreedyScheduler.mLock
at androidx.work.impl.background.greedy.GreedyScheduler.onExecuted (GreedyScheduler.java:141)
at androidx.work.impl.Processor.onExecuted (Processor.java:230)
- locked <0x08012210> (a java.lang.Object)
at androidx.work.impl.Processor$FutureListener.run (Processor.java:263)
at android.os.Handler.handleCallback (Handler.java:873)
at android.os.Handler.dispatchMessage (Handler.java:99)
at android.os.Looper.loop (Looper.java:214)
at android.app.ActivityThread.main (ActivityThread.java:7032)
at java.lang.reflect.Method.invoke (Method.java)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:494)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:965)
"ConnectivityThread" tid=13 Blocked
"ConnectivityThread" prio=5 tid=13 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x12fc0770 self=0x7d7ab86800
| sysTid=27897 nice=0 cgrp=default sched=0/0 handle=0x7d684114f0
| state=S schedstat=( 247567475 11539483672 1368 ) utm=16 stm=7 core=2 HZ=100
| stack=0x7d6830e000-0x7d68310000 stackSize=1041KB
| held mutexes=
at androidx.work.impl.a.d.c (SourceFile:157) // synchronized (mLock)
- waiting to lock <0x0cbac8c2> (a java.lang.Object) held by thread 1 // trying to lock WorkConstraintsTracker.mLock
at androidx.work.impl.a.a.c.b (SourceFile:133) ConstraintController: mCallback.onConstraintNotMet(mMatchingWorkSpecIds);
at androidx.work.impl.a.a.c.a (SourceFile:142) ConstraintController: updateCallback();
at androidx.work.impl.a.b.d.a (SourceFile:103) listener.onConstraintChanged(mCurrentState);
- locked <0x08a4f10d> (a java.lang.Object) (ConstraintTracker.mLock)
at androidx.work.impl.a.b.e$b.onCapabilitiesChanged (SourceFile:149) (NetworkStateTracker)
at android.net.ConnectivityManager$CallbackHandler.handleMessage (ConnectivityManager.java:3331)
at android.os.Handler.dispatchMessage (Handler.java:106)
at android.os.Looper.loop (Looper.java:214)
at android.os.HandlerThread.run (HandlerThread.java:65)

I have written after the lines what is happening there.

The GreedyScheduler has finished executing and onExecuted is called. This tries to remove the workSpecId from the mConstrainedWorkSpecs list. After removing it it calls mWorkConstraintsTracker.replace to send the new list to the WorkContraintsTracker. This causes a lock of WorkConstraintsTracker.mLock and a call to ConstraintController.replace. This calls ConstraintController.removeListener which tries to lock ConstraintController.mLock but fails/deadlocks. So as you can see it has first locked WorkConstraintsTracker.mLock and then it tries to lock ConstraintController.mLock.

As you can see now the other thread does the opposite, which leads to the deadlock: The WorkManager receives a "onCapabilitiesChanges" message and locks ConstraintTracker.mLock. Then it tries to call onConstraintNotMet but it cannot lock WorkConstraintsTracker.mLock, because it is already locked by the upper thread.

So there is a deadlock because both functions are running at the same time and are locking the locks in opposite order. Can you please fix it? Or did I make a mistake somewhere?

(BTW I am only using WorkManager.getInstance, I am not calling "initialize").

Thank you very much!

Comments

ra...@google.com <ra...@google.com> #2Jun 3, 2019 04:57PM

Assigned to ra...@google.com.

Yigit, do you have time to fix it?

reemission of the same liveData is racy

ra...@google.com <ra...@google.com> #3Jun 3, 2019 05:11PM

yea i'll take it.

d....@googlemail.com <d....@googlemail.com> #4Jun 3, 2019 05:26PM

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> #5Jun 3, 2019 05:56PM

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

d....@googlemail.com <d....@googlemail.com> #6Jun 3, 2019 09:38PM

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)

ra...@google.com <ra...@google.com> #7Jun 5, 2019 05:31PM

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

ap...@google.com <ap...@google.com> #8Jun 5, 2019 06:15PM

Marked as fixed.

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