java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in zl$a@5eda151 [133313734]

Fixed

Bug

Status Update

No update yet.

Description

ni...@gmail.com

created issue #1

May 23, 2019 07:24AM

WorkManager 2.1.0-alpha01
I know 2.1.0-alpha02 is out but I cannot test it as I CANNOT reproduce this issue on both alpha01 and 02.

Proguard mappings
------------------
androidx.work.impl.constraints.trackers.NetworkStateTracker -> zl
androidx.work.impl.constraints.trackers.ConstraintTracker -> yl
androidx.work.impl.constraints.controllers.ConstraintController -> pl
androidx.work.impl.constraints.WorkConstraintsTracker -> ml
androidx.work.impl.background.systemalarm.WorkTimer -> gl

Crash report from user
-----------------
APP_VERSION_NAME=228 armeabi-v7a
ANDROID_VERSION=5.0
BRAND=samsung
PHONE_MODEL=SM-N9005
PRODUCT=hltexx
USER_APP_START_DATE=2019-05-22T09:58:13.756+01:00
USER_CRASH_DATE=2019-05-22T19:21:59.888+01:00
STACK_TRACE=java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in zl$a@5eda151
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:933)
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:5938)
at java.lang.reflect.Method.invoke(Native Method)
at java.lang.reflect.Method.invoke(Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1400)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1195)
Caused by: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@220005dc rejected from java.util.concurrent.ScheduledThreadPoolExecutor@ffebca8[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 gl.a(SourceFile:7)
at dl.b(SourceFile:5)
at ml.a(SourceFile:21)
at pl.b(SourceFile:3)
at pl.a(SourceFile:18)
at yl.a(SourceFile:17)
at zl$a.onReceive(SourceFile:4)
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:923)
... 8 more

LOGCAT=--------- beginning of main
05-22 19:21:59.727 D/AndroidRuntime(11913): Shutting down VM
05-22 19:21:59.757 E/ACRA (11913): ACRA caught a RuntimeException for com.nll.asr
05-22 19:21:59.757 E/ACRA (11913): java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in zl$a@5eda151
05-22 19:21:59.757 E/ACRA (11913): at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:933)
05-22 19:21:59.757 E/ACRA (11913): at android.os.Handler.handleCallback(Handler.java:739)
05-22 19:21:59.757 E/ACRA (11913): at android.os.Handler.dispatchMessage(Handler.java:95)
05-22 19:21:59.757 E/ACRA (11913): at android.os.Looper.loop(Looper.java:145)
05-22 19:21:59.757 E/ACRA (11913): at android.app.ActivityThread.main(ActivityThread.java:5938)
05-22 19:21:59.757 E/ACRA (11913): at java.lang.reflect.Method.invoke(Native Method)
05-22 19:21:59.757 E/ACRA (11913): at java.lang.reflect.Method.invoke(Method.java:372)
05-22 19:21:59.757 E/ACRA (11913): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1400)
05-22 19:21:59.757 E/ACRA (11913): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1195)
05-22 19:21:59.757 E/ACRA (11913): Caused by: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@220005dc rejected from java.util.concurrent.ScheduledThreadPoolExecutor@ffebca8[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
05-22 19:21:59.757 E/ACRA (11913): at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2011)
05-22 19:21:59.757 E/ACRA (11913): at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:793)
05-22 19:21:59.757 E/ACRA (11913): at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:298)
05-22 19:21:59.757 E/ACRA (11913): at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:503)
05-22 19:21:59.757 E/ACRA (11913): at java.util.concurrent.Executors$DelegatedScheduledExecutorService.schedule(Executors.java:644)
05-22 19:21:59.757 E/ACRA (11913): at gl.a(SourceFile:7)
05-22 19:21:59.757 E/ACRA (11913): at dl.b(SourceFile:5)
05-22 19:21:59.757 E/ACRA (11913): at ml.a(SourceFile:21)
05-22 19:21:59.757 E/ACRA (11913): at pl.b(SourceFile:3)
05-22 19:21:59.757 E/ACRA (11913): at pl.a(SourceFile:18)
05-22 19:21:59.757 E/ACRA (11913): at yl.a(SourceFile:17)
05-22 19:21:59.757 E/ACRA (11913): at zl$a.onReceive(SourceFile:4)
05-22 19:21:59.757 E/ACRA (11913): at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:923)
05-22 19:21:59.757 E/ACRA (11913): ... 8 more

REPORT_ID=a476ba1d-9c82-4b7a-90cd-5d91e77df69d
IS_SILENT=false

Comments

li...@gmail.com <li...@gmail.com> #2May 23, 2019 10:50AM

We have same issue.

Version used: WorkManager 2.1.0-alpha01
Devices/Android versions reproduced on: mostly Android 5 & 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@c5142c8
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:876)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5254)
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:902)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)
Caused by java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@64a6d62 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@16d09ef3[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:866)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5254)
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:902)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)

ra...@google.com <ra...@google.com> #3May 23, 2019 05:06PM

liujian16@: Are you sure this is happening on Android 6? Because the stack trace points to DelayMetCommandHandler (which is something that the AlarmManager based implementation uses) which is only used on API <= 22.

nihansin@: Sorry its not clear what you meant by

"WorkManager 2.1.0-alpha01
I know 2.1.0-alpha02 is out but I cannot test it as I CANNOT reproduce this issue on both alpha01 and 02."

Did you mean that you cannot reproduce this on your own but you see this happen in production ?

My guess is something like this might be happening:

If you have a Worker in RUNNING state, and you have been asked to stop (either because constraints are no longer met / or if you called cancel()) your Worker still needs to cooperatively cancel.
If your Worker never stops running, then WorkTimer will try and shutdown your Worker again (in 10 minutes). This time that will fail, because the Executor has already been shutdown.
This typically stems from a bug in your code (because your Worker never stopped).

Can you please turn on WorkManager's logging so it will better help us diagnose the problem ?
For this you need to use custom initialization. Something like:

Configuration configuration = new Configuration.Builder()
.setMinimumLoggingLevel(Log.VERBOSE)
.build();

WorkManager.initialize(context, configuration);

Make sure you disable the default initializer.

ra...@google.com <ra...@google.com> #4May 23, 2019 05:17PM

I will investigate this further on my end as well.

ni...@gmail.com <ni...@gmail.com> #5May 23, 2019 05:17PM

Yes, I meant that I cannot reproduce it in my tests.

Here are some points.

- I skip the job if there is an already active job when doWork is called.

- I am never call cancell and I exit with success if job takes longer than
9 minutes. However, I do do batch processing and it may be that one of the
runs in the batch might have taken more than 10 minutes.

On Thu, 23 May 2019, 18:06 , <buganizer-system@google.com> wrote:

- Show quoted text -

ra...@google.com <ra...@google.com> #6May 23, 2019 05:20PM

"I skip the job if there is an already active job when doWork is called."

What do you mean by that ?
What kind of result are you returning ?

"I am never call cancell and I exit with success if job takes longer than
9 minutes. "

How are you accounting for time ? Are you regularly polling inside your Worker ?

ni...@gmail.com <ni...@gmail.com> #7May 23, 2019 05:31PM

I have a utility method to check the status of the jobs by tag

fun Worker.isRunning(tag: String): Boolean {
val instance = androidx.work.WorkManager.getInstance(applicationContext)
val statuses = instance.getWorkInfosByTag(tag)
try {
var running = false
val workInfoList = statuses.get()
for (workInfo in workInfoList) {
val state = workInfo.state
running = (state == WorkInfo.State.RUNNING)
}
return running
} catch (e: ExecutionException) {
e.printStackTrace()
return false
} catch (e: InterruptedException) {
e.printStackTrace()
return false
}
}

This is a periodic work. I always return Result.success() regardless what I
do when doWork run.

I assign current millis to a value in the beginning of doWork, call my
method that does what I want to do and check time on each loop.

My method is a simple for each loop that pulls a list from app dB and goes
through items.

On Thu, 23 May 2019, 18:20 , <buganizer-system@google.com> wrote:

- Show quoted text -

su...@google.com <su...@google.com> #8May 23, 2019 05:51PM

Can you please send us a sample app? Failing that, can you send us an unobfuscated stacktrace?

ni...@gmail.com <ni...@gmail.com> #9May 23, 2019 05:57PM

Was it addressed to me? Unfortunately I cannot reproduce it on my test
devices at all.

I use R8 now. I'll try deobfuscate with prouguard.

Here is my code that crash originates

class PeriodicUploadWorker(context: Context, workerParams:
WorkerParameters) : Worker(context, workerParams) {
private val workManagerTimeLimit = 570000L //WorkManager limits
execution time to 10 minutes! We stop at 9.5 minutes just in case
private val LOG_TAG = "PeriodicUploadWorker"
override fun doWork(): Result {
if (Cloud2Logger.INSTANCE.DEBUG) {
Cloud2Logger.INSTANCE.log(LOG_TAG, "PeriodicUploadWorker run @
${DateFormat.getDateTimeInstance(DateFormat.LONG,
DateFormat.LONG).format(System.currentTimeMillis())}")
}

val delayedOneTimeUploadJobWorkRunning =
isRunning(CloudQueue.delayedOneTimeUploadJobWorkTag)
val periodicDeleteJobRunning =
isRunning(CloudQueue.periodicDeleteJobWorkTag)
val manualOneTimeUploadJobRunning =
isRunning(CloudQueue.manualOneTimeUploadJobWorkTag)
val isAnyWorkerRunning = delayedOneTimeUploadJobWorkRunning ||
periodicDeleteJobRunning || manualOneTimeUploadJobRunning
if (!isAnyWorkerRunning) {

CloudManagerProvider.getInstance(applicationContext).upload(workManagerTimeLimit)

} else {
if (Cloud2Logger.INSTANCE.DEBUG) {
Cloud2Logger.INSTANCE.log(LOG_TAG, "Skipped job as a worker
is already running")
}
}
return Result.success()
}

On Thu, 23 May 2019, 18:51 , <buganizer-system@google.com> wrote:

- Show quoted text -

su...@google.com <su...@google.com> #10May 23, 2019 07:17PM

Thanks, we will wait for your unobfuscated stacktraces.

ni...@gmail.com <ni...@gmail.com> #11May 23, 2019 08:03PM

Here it is

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@c5142c8
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:876)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5254)
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:902)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)
Caused by java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@64a6d62 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@16d09ef3[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:866)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5254)
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:902)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)

ra...@google.com <ra...@google.com> #12May 23, 2019 08:21PM

Can you also turn on verbose logging in WorkManager while I am investigating this, so we can better understand what might be going on?

For that you need to custom initialize WorkManager.

Configuration configuration = new Configuration.Builder()
.setMinimumLoggingLevel(Log.DEBUG)
.build();

WorkManager.initialize(context, configuration);

Make sure you disable the default WorkManager initializer.

ni...@gmail.com <ni...@gmail.com> #13May 23, 2019 08:33PM

I can but it won't make any difference. Crash log submission is voluntary in my app. User has to tap the notification, select send, open their email client and send the attachment. Since I cannot reproduce it in my test devices, I would need to push an update to the app logging enabled and hope that it crashes on someone that willing to send crash logs.

ni...@gmail.com <ni...@gmail.com> #14May 23, 2019 08:33PM

Perhaps someone who are able to reproduce it can send them?

ra...@google.com <ra...@google.com> #15May 23, 2019 08:36PM

Yes, that's what I meant. If you push it out with logging enabled, you might see more information associated with the crash report.

ra...@google.com <ra...@google.com> #16May 23, 2019 10:40PM

One other question is: Are you absolutely sure that these crash reports are coming are actually coming from an app which was built with WorkManager 2.1.0-alpha0x ?

li...@gmail.com <li...@gmail.com> #17May 24, 2019 06:13AM

#3： My fault. The issue is happening on Android 5&4.

ra...@google.com <ra...@google.com> #18May 24, 2019 03:32PM

Can you also answer #16? My suspicion is those crashes could be coming from an older version of the app that does not have the bugfix.

li...@gmail.com <li...@gmail.com> #19May 25, 2019 12:20AM

#16: Yes, we are using WorkManager 2.1.0-alpha01

ra...@google.com <ra...@google.com> #20May 29, 2019 04:49AM

Marked as fixed, reassigned to ra...@google.com.

Fixed by

https://android-review.googlesource.com/c/platform/frameworks/support/+/971650

Issue 133313734

Description

Issue summary

Comments

li...@gmail.com <li...@gmail.com> #2May 23, 2019 10:50AM

ra...@google.com <ra...@google.com> #3May 23, 2019 05:06PM

ra...@google.com <ra...@google.com> #4May 23, 2019 05:17PM

ni...@gmail.com <ni...@gmail.com> #5May 23, 2019 05:17PM

ra...@google.com <ra...@google.com> #6May 23, 2019 05:20PM

ni...@gmail.com <ni...@gmail.com> #7May 23, 2019 05:31PM

su...@google.com <su...@google.com> #8May 23, 2019 05:51PM

ni...@gmail.com <ni...@gmail.com> #9May 23, 2019 05:57PM

su...@google.com <su...@google.com> #10May 23, 2019 07:17PM

ni...@gmail.com <ni...@gmail.com> #11May 23, 2019 08:03PM

ra...@google.com <ra...@google.com> #12May 23, 2019 08:21PM

ni...@gmail.com <ni...@gmail.com> #13May 23, 2019 08:33PM

ni...@gmail.com <ni...@gmail.com> #14May 23, 2019 08:33PM

ra...@google.com <ra...@google.com> #15May 23, 2019 08:36PM

ra...@google.com <ra...@google.com> #16May 23, 2019 10:40PM

li...@gmail.com <li...@gmail.com> #17May 24, 2019 06:13AM

ra...@google.com <ra...@google.com> #18May 24, 2019 03:32PM

li...@gmail.com <li...@gmail.com> #19May 25, 2019 12:20AM

ra...@google.com <ra...@google.com> #20May 29, 2019 04:49AM

Add comment

Issue metadata