Crash with WorkManager [109894190]

WAI

Bug

Status Update

No update yet.

Description

pj...@lyft.com

created issue #1

Jun 8, 2018 02:00PM

Component used: WorkManager
Version used: android.arch.work:work-runtime:1.0.0-alpha02
Devices/Android versions reproduced on:8.0.0 and 8.1.0
Description:
We are using WorkManager to schedule some background jobs. We've released to a small number of users, and are seeing a crash with a few users.

Total affected right now:
- 4 events
- 3 users

Here is the full stack trace:
java.lang.RuntimeException: Unable to create service androidx.work.impl.background.systemjob.SystemJobService: java.lang.NullPointerException: Attempt to invoke virtual method 'androidx.work.impl.Processor androidx.work.impl.WorkManagerImpl.f()' on a null object reference
at android.app.ActivityThread.handleCreateService(ActivityThread.java:3552)
at android.app.ActivityThread.-wrap4(Unknown)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1786)
at android.os.Handler.dispatchMessage(Handler.java:105)
at android.os.Looper.loop(Looper.java:164)
at android.app.ActivityThread.main(ActivityThread.java:6938)
at java.lang.reflect.Method.invoke(Method.java:-2)
at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)
Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'androidx.work.impl.Processor androidx.work.impl.WorkManagerImpl.f()' on a null object reference
at androidx.work.impl.background.systemjob.SystemJobService.onCreate(SourceFile:52)
at android.app.ActivityThread.handleCreateService(ActivityThread.java:3542)
at android.app.ActivityThread.-wrap4(Unknown)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1786)
at android.os.Handler.dispatchMessage(Handler.java:105)
at android.os.Looper.loop(Looper.java:164)
at android.app.ActivityThread.main(ActivityThread.java:6938)
at java.lang.reflect.Method.invoke(Method.java:-2)
at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

I have not been able to reproduce the issue on my own 8.0 or 8.1 device. Please let me know if there is anything more you need from me.

Comments

su...@google.com <su...@google.com> #2Jun 8, 2018 04:52PM

Please upload a sample project that recreates this issue.

pj...@lyft.com <pj...@lyft.com> #3Jun 8, 2018 04:55PM

Here is the sample project: https://github.com/willflier/exception-report

su...@google.com <su...@google.com> #4Jun 8, 2018 05:04PM

Upload it for direct download

pj...@lyft.com <pj...@lyft.com> #5Jun 8, 2018 05:49PM

Project: platform/frameworks/support
Branch: androidx-main

commit 2e36de7a65cbbf0ff7d81d82842b0e4836629819
Author: Jeremy Woods <jbwoods@google.com>
Date: Wed Aug 18 14:34:35 2021

Fix indexOutOfBounds error for setGraph

For for loop in setGraph is currently attempting to access the array out
of bounds. It only fails when using 13 or 29 destinations in the graph.

RelNote: "There will no longer be an `ArrayIndexOutOfBoundsException`
when calling `setGraph` with a graph with 13 or 29 destinations."
Test: add navControllerRouteTest
Bug: 195171984

Change-Id: I1a9f17c4616bc38dd3dd89cb1da29814c3dfd512

M navigation/navigation-runtime/src/androidTest/java/androidx/navigation/NavControllerRouteTest.kt
M navigation/navigation-runtime/src/main/java/androidx/navigation/NavController.kt

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

su...@google.com <su...@google.com> #6Jun 8, 2018 06:33PM

This has been fixed internally and will be available in the Navigation 2.4.0-alpha08 release.

pj...@lyft.com <pj...@lyft.com> #7Jun 11, 2018 04:20PM

So we just started to get similar problems in our production build that has a single process running, and we don't enqueue any jobs at all. We only use the initialize call in onCreate and don't enqueue anything. Here is the stack trace:

java.lang.RuntimeException: Unable to create service androidx.work.impl.background.systemalarm.SystemAlarmService: java.lang.NullPointerException: Attempt to invoke virtual method 'androidx.work.impl.Processor androidx.work.impl.WorkManagerImpl.f()' on a null object reference
at android.app.ActivityThread.handleCreateService(ActivityThread.java:2771)
at android.app.ActivityThread.access$1800(ActivityThread.java:151)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1386)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:158)
at android.app.ActivityThread.main(ActivityThread.java:5255)
at java.lang.reflect.Method.invoke(Method.java:-2)
at java.lang.reflect.Method.invoke(Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:902)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)

We will now likely need to put out a fix. Is it safe to release a fix remove the initialize call in onCreate or is it going to persist some sort of state and would only make it worse?

su...@google.com <su...@google.com> #8Jun 11, 2018 04:49PM

Just so I'm clear: there are no enqueued WorkManager jobs and this code is being invoked? Were there *ever* any enqueued jobs on this device? This code should not run if no actual work is being executed.

su...@google.com <su...@google.com> #9Jun 11, 2018 05:40PM

Do you mind giving us a bugreport? Everything we're seeing is indicating that your WorkManager.initialize() call is not happening. If it's actually in the Application.onCreate, it should execute before the Service is created as per Android contracts.

Can you give us more info on these particular devices and the versions of Android they are using? Maybe it's a non-standard version of Android that we haven't seen before and is modifying some behavioral contract.

pj...@lyft.com <pj...@lyft.com> #10Jun 11, 2018 06:19PM

Hey guys thanks for prompt responses. I’m working to verify that our experimentation setup didn’t somehow trigger the enqueue events in prod. Will get back to you as soon as I have an answer for you. Thanks!

pj...@lyft.com <pj...@lyft.com> #11Jun 11, 2018 07:52PM

To follow up on some of the issues, is there any reason why we would see the bug originating in SystemAlarmService in prod vs SystemJobService in beta? My guess is that the WorkManager is selecting the service to use based on OS version of the device as mentioned in the docs for WorkManager. However, I do find it a bit odd that we wouldn't see SystemJobService bug in production too if that were the case.

Prod issues with SystemAlarmService affect versions: 5.0, 5.0.2, 5.1, and 5.1.1.
Beta issues with SystemJobService affect versions: 8.0.0, 8.1.1

su...@google.com <su...@google.com> #12Jun 11, 2018 07:59PM

SystemJobService is using JobScheduler on API 23 and higher. SystemAlarmService is for API 22 and lower. That's what you're seeing in the breakdown in the last 2 lines of update #11 to this bug.

I'm not sure why you're seeing this one in prod and one in beta, sorry. As I said, I'd need more info and bugreports and I'd like to see your setup. We haven't been able to see this issue internally and no one else is reporting it.

pj...@lyft.com <pj...@lyft.com> #13Jun 12, 2018 04:32PM

I think our experimentation setup created the issues in production as well, so that is confirmed and is no longer an issue. So back to the original issue, I think I've identified why it's possible that the initialize can come after the service wakes up the old job.

I didn't realize it before but while we are calling initialize in onCreate of our application, we are dispatching it to another thread similar to this:
Executors.newSingleThreadExecutor().execute(() -> {
androidx.work.WorkManager.initialize(context, new Configuration.Builder().build());
});

I think we need to just remove the executor service and call directly on the main thread. I apologize for not submitting a bugreport but I haven't been able to reproduce in our app yet. What do you guys think of moving it to the main thread though? You think this could be the root cause? Will this have much of an impact for our cold start time?

su...@google.com <su...@google.com> #14Jun 12, 2018 04:57PM

Status: Won't Fix (Intended Behavior)

You don't need to initialize WorkManager on a different thread. You're creating a race-condition - the JobService expects that WorkManager is initialized, but you're doing it asynchronously, so it hasn't finished in some cases.

Also: you are initializing WorkManager with the default Configuration, so you don't actually need to be manually initializing it at all.

pj...@lyft.com <pj...@lyft.com> #15Jun 12, 2018 04:59PM

We don't even need to call initialize if we use the default configuration?

su...@google.com <su...@google.com> #16Jun 12, 2018 05:27PM

You must have explicitly disabled the WorkManagerInitializer content provider in your manifest - undo that change as well.

pj...@lyft.com <pj...@lyft.com> #17Jun 12, 2018 10:36PM

If we wanted to manually call the initialize method in our app's onCreate with some custom build configuration, do you know how that might affect our launch time? Any metrics on that at all?

su...@google.com <su...@google.com> #18Jun 13, 2018 01:02PM

We don't have these numbers; they would vary a lot based on the rest of your setup and the device you are using. I would suggest you benchmark this yourself.