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.

Thanks for reporting this. We will take a look at FBE and try to land a fix in a future release. In the meantime, as the exception notes, you will want to initialize WorkManager in Application.onCreate or via a ContentProvider to avoid the error.

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

Initialize WorkManager in Application.onCreate or via a ContentProvider may cause other error:
08-07 14:03:13.261 5869 5869 E AndroidRuntime: java.lang.RuntimeException: Unable to get provider androidx.work.impl.WorkManagerInitializer: java.lang.IllegalStateException: SharedPreferences in credential encrypted storage are not available until after user is unlocked
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.installProvider(ActivityThread.java:6366)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.installContentProviders(ActivityThread.java:5910)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:5818)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.-wrap1(Unknown Source:0)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1717)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:106)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.os.Looper.loop(Looper.java:164)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:6618)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:810)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: Caused by: java.lang.IllegalStateException: SharedPreferences in credential encrypted storage are not available until after user is unlocked
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ContextImpl.getSharedPreferences(ContextImpl.java:387)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ContextImpl.getSharedPreferences(ContextImpl.java:372)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.content.ContextWrapper.getSharedPreferences(ContextWrapper.java:167)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.utils.IdGenerator.<init>(IdGenerator.java:47)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.background.systemjob.SystemJobScheduler.<init>(SystemJobScheduler.java:69)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.background.systemjob.SystemJobScheduler.<init>(SystemJobScheduler.java:55)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.Schedulers.createBestAvailableBackgroundScheduler(Schedulers.java:114)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.WorkManagerImpl.getSchedulers(WorkManagerImpl.java:228)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.WorkManagerImpl.<init>(WorkManagerImpl.java:179)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.WorkManagerImpl.<init>(WorkManagerImpl.java:151)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.WorkManagerImpl.initialize(WorkManagerImpl.java:133)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.WorkManager.initialize(WorkManager.java:160)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at androidx.work.impl.WorkManagerInitializer.onCreate(WorkManagerInitializer.java:40)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.content.ContentProvider.attachInfo(ContentProvider.java:1928)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.content.ContentProvider.attachInfo(ContentProvider.java:1903)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: at android.app.ActivityThread.installProvider(ActivityThread.java:6363)
08-07 14:03:13.261 5869 5869 E AndroidRuntime: ... 10 more

I will try other ways.

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

This may actually be fixed in alpha07 (launching later today), but we will take a closer look and get back to you.

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

Are you enqueuing Work with WorkManager while in Direct Boot mode (i.e., before the device is unlocked)?

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

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

commit f3e63e3a3432b5fb941aec3d4a21e9a5ea42f1d1
Author: Sumir Kataria <sumir@google.com>
Date: Fri Aug 17 14:34:56 2018

Explicitly label WM components as direct boot unaware.

Because WM defaults to a database in encrypted storage, it
cannot run while in direct boot. By explicitly labelling the
components this way, they cannot inherit a directBootAware
flag from the merged <application> xml.

In the future, we will provide a version of WorkManager that
is direct-boot aware. See the tracking feature request at

https://issuetracker.google.com/112773820 This is something
that might land post-1.0.

Bug: 112665532
Test: Ran some integration tests in a test app.
Change-Id: Ide87b8e4c5dfefb88a54c3ce4c45262335f47e96

M work/workmanager/src/main/AndroidManifest.xml

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

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

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

Further work will be tracked on

https://issuetracker.google.com/112773820.

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

Marked as fixed.

1st exception:
java.lang.IllegalStateException: SharedPreferences in credential encrypted storage are not available until after user is unlocked
2nd exception:
java.lang.IllegalStateException: WorkManager needs to be initialized via a ContentProvider#onCreate() or an Application#onCreate().

I'm enqueuing Work with WorkManager on some specific activity or fragment. So I tried to call WorkManager.initialize() on my launch activity after the 1st exception is thrown. The 2nd exception happened only once after clicking on the launch icon.I am not sure how to reproduce the 2nd one.