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

Which device is issue being reported on? Can you get any logs from the device for us after you turn on verbose logging ?

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

A few things in addition to the questions in #2:

1. Can you verify that this problem still occurs in beta03? This is available now.
2. Can you check your merged manifest has a network permission (ACCESS_NETWORK_STATE)? It should get merged in automatically.

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

#3: have now tried beta03 and it's the same behaviour... periodic work schedule breaks down when network constraint is applied (after a period of time with no network). And yes, ACCESS_NETWORK_STATE is in the merged manifest... it's actually in the main manifest anyway.

#2: I'll try...

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

Re #2 getting logs... I have tried previously to get logs from the user, and on each occasion the logs started *after* the point of interest, as if the logs had been cleared just before (e.g. just after a problem), so they've not been of any use.

The way I'm getting logs is via a button in the widget configuration activity which runs the following:

Runtime.getRuntime().exec("logcat -f " + logFile + " *:V");

Is there a better way of getting logs from a user (where the user is not an advanced user and can only just about handle pressing a button and sending a text file)?

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

Looks like this issue isn't specific to Unique**Periodic**Work ... with a network constraint applied to UniqueWork, if it is scheduled for a time when there is no network, it doesn't go off, even when network is restored. Again, on this user's Android 4.3 device... on the devices I've tested, it works fine.

Do I need to do anything special to make this work on Android 4.3?

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

And periodic work is running just fine on the problem device without the network constraint applied... runs like clockwork.

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

Can you send us a sample app?

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

Does your app have verbose logging turned on for WorkManager. You will need to initialize WorkManager with a custom configuration for that.

* Remove the default WorkManager initializer using:

<provider
android:name="androidx.work.impl.WorkManagerInitializer"
android:authorities="${applicationId}.workmanager-init"
tools:node="remove"/>

* Initialize WorkManager in your own content provider or Application#onCreate() with a custom configuration

WorkManager.initialize(
applicationContext,
new Configuration.Builder().setMinimumLoggingLevel(Log.VERBOSE).build());

You will see a lot more WorkManager logs now.

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

Typically when there are changes in constraints on API <=22 and you are using the AlarmManager implementation you should see logs with a log tag "WM-ConstraintsCmdHandler".

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

Do you have any comment or suggestion regarding mine at #5? Is that an OK way to get logs from a user, particularly one that has a non-rooted device and where I don't particularly want to ask them to go to the trouble of install logcat apps etc... just a simple button in the app which will dump logs would be ideal.

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

We don't really have any good advice for you there; it touches on potentially sensitive data so getting data directly from the user is between what you and the user deem acceptable.

What is the user's 4.3 device name/model?

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

When I use:

WorkManager.initialize(
applicationContext,
new Configuration.Builder().setMinimumLoggingLevel(Log.VERBOSE).build());

The 'Builder' is highlighted in red with Cannot resolve symbol 'Builder'

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

Sorry, hard to tell without a sample app. It sounds like you may have a missing import or something, but I can't diagnose that.

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

OK I used androidx.work.Configuration.Builder() instead

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

User's device is a Samsung Galaxy S3

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

Where can I send a logcat from the user? There isn't anything of any sensitive nature so far as I can tell, but best not to post it here.

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

You can send the logs here; I just mean I can't advise you about collection.

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

I'm attaching some logs which may be of interest. It includes the extra WorkManager logging you describe above, plus some random bits of logging from my own code (though I've removed quite a bit to avoid overkill here). I've added some annotations to note where the user did various actions (I'm guessing a little but fairly sure) to add some context.

The interest bit starts from "01-29 20:51:44.715"

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

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

I looked at the logs, and there are a lot of Worker cancellations happening. Are you explicitly cancelling work or using Existing{Periodic}WorkPolicy.REPLACE ?
Can you send us a trimmed down sample of how Workers are being enqueued for your app ?