IssueTracker

Can you please send us a test app which can reproduce this ?

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

commit 5975b62cd1f3f170bb82e9761efca40e5e5bfb16
Author: Rahul Ravikumar <rahulrav@google.com>
Date:   Wed Jul 24 12:24:17 2019

    TaskExecutor's background executor is now SerialExecutor.
   
    * This gives us visibility into the number of pending tasks which will
      be important in the next CL.
   
      There is a race condition between the SerialExecutor draining its queue
      of pending tasks and SystemAlarmDispatcher's onAllCommandsCompleted() callback.
      This is because SystemAlarmDispatcher thinks there are no more things to be
      done even though there are pending runnables in the SerialExecutor.
      This CL makes this information available. In the next CL, CommandHandler
      will check for pending runnables in the SerialExecutor queue.
      (b/138238197)
   
    * Fixed TestWorkManagerImpl to use Configuration#getTaskExecutor().
    * Updated unit tests.
   
    Test: Updated unit tests.
    Change-Id: I5f32f1e1ef2563d4598934aed3b61d62a6d6167c

M       work/workmanager-gcm/src/androidTest/java/androidx/work/impl/background/gcm/WorkManagerGcmDispatcherTest.kt
M       work/workmanager-ktx/src/androidTest/java/androidx/work/CoroutineWorkerTest.kt
M       work/workmanager-rxjava2/src/test/java/androidx/work/RxWorkerTest.kt
M       work/workmanager-testing/src/androidTest/java/androidx/work/testing/WorkManagerInitHelperTest.java
M       work/workmanager-testing/src/main/java/androidx/work/testing/InstantWorkTaskExecutor.java
M       work/workmanager-testing/src/main/java/androidx/work/testing/TestWorkManagerImpl.java
M       work/workmanager-testing/src/main/java/androidx/work/testing/WorkManagerTestInitHelper.java
M       work/workmanager/src/androidTest/java/androidx/work/impl/utils/taskexecutor/InstantWorkTaskExecutor.java
M       work/workmanager/src/main/java/androidx/work/impl/utils/SerialExecutor.java
M       work/workmanager/src/main/java/androidx/work/impl/utils/taskexecutor/TaskExecutor.java
M       work/workmanager/src/main/java/androidx/work/impl/utils/taskexecutor/WorkManagerTaskExecutor.java

https://android-review.googlesource.com/1090749
https://goto.google.com/android-sha1/5975b62cd1f3f170bb82e9761efca40e5e5bfb16

There is a 2nd change that fixes the problem.

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

commit 7db27318ea09ae3857a7baebe8dd4e6fa9d16fdc
Author: Rahul Ravikumar <rahulrav@google.com>
Date:   Wed Jul 24 12:50:34 2019

    Ensure SerialExecutor has no more pending tasks.
   
    * We need to ensure this is the case because we might shutdown
      SystemAlarmService without actually completing all the tasks.
   
    Test: Existing unit tests pass. Ran integration tests.
    Fixes: b/138238197
    Change-Id: I72fe2ddb1607995721eae320ce41accad93fee8f

M       work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/SystemAlarmDispatcher.java
M       work/workmanager/src/main/java/androidx/work/impl/utils/SerialExecutor.java

https://android-review.googlesource.com/1090758
https://goto.google.com/android-sha1/7db27318ea09ae3857a7baebe8dd4e6fa9d16fdc

Awesomme! Thanks for the fix

  The following changes were cherrypicked through Coastguard (https://android-build.googleplex.com/coastguard/)
  Release Track: (https://android-build.googleplex.com/coastguard/dashboard/6206758647365632/#/cherrypickHistory/all)
  Created: 2019-07-26 23:31:17.300138+00:00
  Changes: aosp/1092373, aosp/1092374
 

Hi,

I used 2.2.0-RC1 and the issue still persists but not as frequent as before.

08-14 11:38:59.141 975-987/ A/PowerManager: WakeLock finalized while still held: WorkManager: bd0a17b6-e87a-4c44-bb7f-6ae195975b36 (2)
08-14 11:39:02.588 975-1102/com.yantranet.signware.agent.staging E/WM-SystemAlarmDispatche: Unexpected error in onHandleIntent
    java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@3b835a4f rejected from java.util.concurrent.ScheduledThreadPoolExecutor@48bb5dc[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:135)
        at androidx.work.impl.background.systemalarm.DelayMetCommandHandler.handleProcessWork(DelayMetCommandHandler.java:211)
        at androidx.work.impl.background.systemalarm.CommandHandler.handleDelayMet(CommandHandler.java:272)
        at androidx.work.impl.background.systemalarm.CommandHandler.onHandleIntent(CommandHandler.java:171)
        at androidx.work.impl.background.systemalarm.SystemAlarmDispatcher$1.run(SystemAlarmDispatcher.java:276)
        at androidx.work.impl.utils.SerialExecutor$Task.run(SerialExecutor.java:91)
        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:818)
08-14 11:39:44.850 975-987/ A/PowerManager: WakeLock finalized while still held: WorkManager: 348bf17e-7aa4-48df-b88e-a2e7e3b5483d (2)

Can you please give us a sample app that reproduces this problem?

Also, are you sure the app in question was using the recent version of WM ?

Questions and Answers:

#3 * Can you reproduce this issue at all on your end ?
We can not. We have done tests with several devices that we have here and it does not happen.

#3 * Can you send us a breakdown of devices and total # of users affected ?

Here you can see the devices and the total number of errors in the last 7 days for each one.

Moto C Plus (panell_s)  6,624   33.9%
Moto C (namath) 4,909   25.1%
Moto C Plus (panell_dl) 1,227   6.3%
Aquaris A4.5 (Aquaris_A45_sprout)       1,197   6.1%
Moto C Plus (panell_dt) 1,030   5.3%
LAIQ_Monaco     838     4.3%
Moto C Plus (panell_d)  686     3.5%
Alcatel 1C (U5A_PLUS_3G)        332     1.7%
4047G (U5_3G)   257     1.3%
BLADE A612 (P635F50)    236     1.2%
Xperia XA (F3111)       230     1.2%
HUAWEI Y5 2018 (HWDRA-MG)       201     1.0%
Aquaris M5 (Aquaris_M5) 179     0.9%
S550 (S550)     153     0.8%
Nokia 2 (E1M)   144     0.7%
F23 (HS6737MT)  134     0.7%
LG K20 Plus (lv517)     120     0.6%
iris80 (iris80) 96      0.5%
KIICAA MIX (KIICAA_MIX) 92      0.5%
Wooze L (Wooze_L)       78      0.4%
Others  788     4.0%

96% of these devices use Android 7.0
The total number of users affected by this error is 325 currently, which is a very very small percentage of active users with the latest update.


#4 * Also from the first screenshot, it looks like you are also seeing IllegalStateException's in SystemJobService#onCreate().
* The only reason that happens is if WorkManager is not been initialized for your process. Do you have multiple processes at all ?

We call "WorkManager.getInstance()...." whenever it is used, and no special initialization is made. It is called in 3 different places:

a) By using Broadcast,
Specifically when restarting the phone with: "android.intent.action.BOOT_COMPLETED"
and on the other hand when making an update with: "android.intent.action.MY_PACKAGE_REPLACED" or "android.intent.action.PACKAGE_REPLACED"

b) When starting the app (main thread).

c) Within a "Worker",
Some workers can start others.


#5 * Are you initializing WorkManager on a background thread or inside a coroutine ?

The first time it is called it could be inside a "BroadcastReceiver" if the user has just updated or restarted the phone. In any other case, it is called when you start the app.


#6 * ...The best hypothesis I could come up is that the OS Scheduler is keeping this bad job running even after the update.

We think that is what is currently happening.
In this update several "works" have been migrated to workmanager, which still continued using other old systems, specifically AlarmManager and FirebaseJobDispatcher in the previous version.

It seems that the errors are stabilizing, they are even receding. I will keep you informed, especially in future updates, when there is no change of works between versions.

I attached a crash report for this issue. Notice that even though we removed WorkManager from our build, this is one of the threads trace:

--------- thread trace ------------
Thread : 9955/WorkManager-WorkManagerTaskExecutor-thread-1
        isAlive : true
        isInterrupted : false
        isDaemon : false
                at android.database.CursorWindow.nativeDispose(Native Method)
                at android.database.CursorWindow.dispose(CursorWindow.java:175)
                at android.database.CursorWindow.onAllReferencesReleased(CursorWindow.java:730)
                at android.database.sqlite.SQLiteClosable.releaseReference(SQLiteClosable.java:74)
                at android.database.sqlite.SQLiteClosable.close(SQLiteClosable.java:106)
                at android.database.AbstractWindowedCursor.closeWindow(AbstractWindowedCursor.java:184)
                at android.database.AbstractWindowedCursor.onDeactivateOrClose(AbstractWindowedCursor.java:208)
                at android.database.AbstractCursor.close(AbstractCursor.java:170)
                at android.database.sqlite.SQLiteCursor.close(SQLiteCursor.java:214)
                at androidx.work.impl.b.j.a(WorkSpecDao_Impl.java:1211)
                at androidx.work.impl.i.b(WorkerWrapper.java:427)
                at androidx.work.impl.i.e(WorkerWrapper.java:393)
                at androidx.work.impl.i.d(WorkerWrapper.java:150)
                at androidx.work.impl.i.run(WorkerWrapper.java:128)
                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
                at java.lang.Thread.run(Thread.java:764)
-----------------------------------

This thread is the only thread on our report that is using workmanager somehow.


- # of users we rolled out the build with workmanager 1.0.1: 347
- # of users affected by this crash: 157
- Android versions affected by this crash: 7.0, 8.0 and 9.0

- # of users we rolled out the patch where we removed workmanager: 92
- # of users still seeing this crash: 47
- Android versions still affected by this crash: 7.0, 8.0 and 9.0

Another piece of information, these numbers are gather from Crashlitics (Fabric), and we notice a discrepancy between Crashlitics numbers and our internal tools.

Hi, this thread shouldn't exist if WorkManager isn't in your app.  So I'm not sure what's happening here, but you're still pulling in WorkManager somehow.  You should check your dependencies.

The dependency is still there so we could call `cancelAll` from the library. But none of our code is using any workmanager code. The next patch we have is to change that to a JobScheduler directly.

That won't work at all.

WorkManager does a lot of things including:
* Check for force-stops of your app and reschedule things automatically - without you having to do nothing.
* Handle existing onStartJob requests for persisted jobs in JobScheduler.

Hi Adrian, in #11 you mentioned:

#4 * Also from the first screenshot, it looks like you are also seeing IllegalStateException's in SystemJobService#onCreate().
* The only reason that happens is if WorkManager is not been initialized for your process. Do you have multiple processes at all ?

We call "WorkManager.getInstance()...." whenever it is used, and no special initialization is made. It is called in 3 different places:

This will not work. Because WorkManager is used in many places without you explicitly doing anything.
You should always ensure WorkManager is initialized in Application#onCreate() unless you happen to using on-demand initialization which is something we introduced in 2.1.0-alpha01.

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

commit d025815ea5cc023c0d33b810f99f5afb7cc40b85
Author: Sumir Kataria <sumir@google.com>
Date:   Fri May 31 14:15:54 2019

    Cancel invalid jobs attributed to WorkManager.
   
    Sometimes, there are invalid jobs returned in getAllPendingJobs() with no
    extras attributed to WorkManager.  These should be cleaned up proactively
    on startup.
   
    Fixes: 134058261
    Test: Added new test
    Change-Id: I9bdf821c589bc4ba99542307ea76ca4c0cb9ac2e

M       work/workmanager/src/androidTest/java/androidx/work/impl/background/systemjob/SystemJobSchedulerTest.java
M       work/workmanager/src/main/java/androidx/work/impl/WorkManagerImpl.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemjob/SystemJobScheduler.java
M       work/workmanager/src/main/java/androidx/work/impl/utils/ForceStopRunnable.java

https://android-review.googlesource.com/974683
https://goto.google.com/android-sha1/d025815ea5cc023c0d33b810f99f5afb7cc40b85

HI. Just wanted to add to this. We are also seeing this same thing with v 2.0.1. This is the first version we have used in production, so I cannot say if it occurred with previous versions. We had 4 unique, periodic jobs running in production, and had to do a hotfix removing all of them, the problem has subsided as we cancelled all of the pending jobs.

The reason I think it is the same bug is that we have a very similar breakdown of affected devices

100% people on Android 7
83% people on Motorola phones

Trace:

Fatal Exception: java.lang.IllegalStateException: JobScheduler 100 job limit exceeded.  We count 101 WorkManager jobs in JobScheduler; we have 4 tracked jobs in our DB; our Configuration limit is 20.
       at androidx.work.impl.background.systemjob.SystemJobScheduler.scheduleInternal(SystemJobScheduler.java:189)
       at androidx.work.impl.background.systemjob.SystemJobScheduler.schedule(SystemJobScheduler.java:129)
       at androidx.work.impl.Schedulers.schedule(Schedulers.java:93)
       at androidx.work.impl.utils.ForceStopRunnable.run(ForceStopRunnable.java:100)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
       at java.lang.Thread.run(Thread.java:761)

We have a very similar situation in our end, but we were using v1.0.1 with a crash rate of 40% across all devices and Android versions from API 21 and up.

In our case we rolled out an emergency fix to remove WorkManager entirely from our project, including the dependency on it, and the problem was not seen again. We didn't cancel the remaining jobs, but they're gone.

Hi, crash reports and device models are very useful.  There are some upcoming fixes in 2.1.0 that will address this; please make sure you try them out.

Re: #19, this crash should only occur on API 23 and up, so I'm not sure if there's something else going on there for you.  Unfortunately, we are chasing down some device differences that don't conform to what stock Android seems to do, and without more data.  Without identifying the models, it's hard to see test these.

Motorola devices in particular seem to exhibit this class of problems much more.

#19, also in general crash rate as a metric is not a useful one here. We know once these devices get into this state, its hard to recover.
Can you take a look at your crashes to see the total number of users affected ? It will be useful to know what devices they are on as well.

Sorry for spam this issue, but ther eis just 6 starred people, so I think it's ok.

Could you please look at: https://issuetracker.google.com/issues/63622293 (200 starred people, for a 2 years).
And some next info in https://issuetracker.google.com/issues/115560697 60 starred people for a year).

We use now 2.1.0-alpha03 and this crash (100 jobs) looks fixed for us. But https://issuetracker.google.com/issues/63622293 still happen on almost all platforms and it's not possible to workaround it, intead of this one which was possible workaround by cancelling all jobs after start app.

Thanks a lot

You posted screenshots of your build.gradle file and it's using WorkManager 2.1.0-alpha03. (https://issuetracker.google.com/issues//63622293)

I am not sure i understand why you are conflating WorkManager and JobIntentService here.

The crash in JobIntentService and your usage of 2.1.0-alpha03 are not related at all.

I'm sorry, I and some next pelople think, that JobIntentService is related to Workmanager, because before WorkManager we used JobScheduler and JobIntentService... etc, still have mess around jobs and notifications and background services...

We believe we're seeing 1M crashes a day from this problem. Would be great to get this fixed quickly.

#26: It would be great to get some more details as we believe the problem has been addressed (this bug is marked as fixed).  What version of WorkManager are you using?  Can you give more details?

Hi aarmstro@

Which version of WorkManager are you using. This bug has been marked fixed for around ~3 weeks. Are you using the new beta ?

I believe we are not yet using the beta (since we generally try to run only stable libraries for our production app). We'll investigate the fix there though. Do you feel confident that the beta is stable enough for large apps to use?

Google apps usually take drops from HEAD all the time. So I would say yes.

 If you are uncomfortable then you can always try using it in a beta
rollout of the app.

On Thu, Jun 20, 2019 at 5:45 PM <buganizer-system@google.com> wrote: