UniquePeriodicWork stops working when network constraint is applied (and no network) [123379508]

Fixed

Bug

Status Update

No update yet.

Description

dr...@gmail.com

created issue #1

Jan 25, 2019 11:41AM

This is a follow-on from my comment here:

https://issuetracker.google.com/issues/121436946#comment6

I think my issue is unrelated, hence this new bug report.

I am applying a network constrain to my PeriodicWorkRequest:

// ...
constraintsBuilder.setRequiredNetworkType(NetworkType.CONNECTED);
// ...
Constraints constraints = constraintsBuilder.build();
// ...
periodicWorkRequestBuilder.setConstraints(constraints);
// ...
PeriodicWorkRequest = periodicWorkRequestBuilder.build();

The idea is of course that the periodic work will run only if there is network. If there isn't, it will wait until there is, and then perform the work, and the subsequent periodic work will be scheduled after that.

This all works very well based on my own tests. But I have *one* user of an older Android 4.3 device where things break down (there may be others... but only one is reporting it... certainly it is not widespread).

From what I can determine, with a network constraint applied to the periodic work as above, if the periodic work is scheduled to run at time when there is no network, it appears on this user device that it does not run, as expected (because if if did, a "retry" work request would be scheduled by my code, which it isn't).

But it also appears that it NEVER RUNS AGAIN. In other words, the periodic work seems to be enqueued still, but just never runs again. It's as if the restoration of network doesn't kick it into running, and so it never does, ever again.

When this user runs an alternative version of the app where the network constraint is NOT applied to the periodic work (instead applying Constraints.NONE), the periodic work appears to survive the network downtime, and carry on ticking. It does attempt to run without network, which I can tell because a onetime "retry" work is scheduled, which surfaces later.

I have tried to reproduce this on an Android 4.3 emulator to no avail... seems to work as expected. So, this may not be enough information to go on.

It's almost as if CONNECTIVITY_CHANGE is not being received (I assume that WorkManager uses this signal)... or not acted on.

We don't need to add any special permissions or anything to make CONNECTIVITY_CHANGE work on all devices?

Comments

ra...@google.com <ra...@google.com> #2Jan 25, 2019 06:26PM

A couple of questions:

1. Have you saw crash in real device or only in simulators?
2. Do you use dynamic feature for language ID?

su...@google.com <su...@google.com> #3Jan 25, 2019 07:04PM

Tested on Android 12 Emulator with custom executor, but cannot repro this issue.

dr...@gmail.com <dr...@gmail.com> #4Jan 26, 2019 04:18PM

Second crash in the description is from a real device. Experienced it myself on two different Xiaomi phones, plus lots of crashes from users in the Google Play console.
Dynamic features are not used in the application.

As a wild guess, I have downgraded build tools from 31.0.0 to 30.0.3, compileSdk from 31 to 30, and moved all work with Language ID to the service in a separate process (just to be sure that crash can kill secondary process instead of main). This combination is in beta for 2 days by now and I don't see any SIGSEGV crashes.

dr...@gmail.com <dr...@gmail.com> #5Jan 27, 2019 03:04PM

Hmm, I feel the crash might be something related to separate/secondary process.

I also changed compileSdk and targetSDK to 31 but still cannot repro this issue.

dr...@gmail.com <dr...@gmail.com> #6Jan 27, 2019 08:03PM

On the contrary, there was no separate process before, when crashes started.

In the new build (with the aforementioned changes) I can see SIGSEGV crash, but only one instead of dozens and it has a bit different backtrace:

signal 11 (SIGSEGV), code 1 (SEGV_MAPERR)
liblanguage_id_jni.so (offset 0x11e000)

backtrace:
  #00  pc 000000000003c7c0  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 000000000003b960  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 000000000003bb48  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 000000000003bafc  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 0000000000036c98  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 0000000000032714  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 0000000000031cac  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/split_config.arm64_v8a.apk!lib/arm64-v8a/liblanguage_id_jni.so (offset 0x11e000)
  #00  pc 0000000000057438  /data/app/azagroup.reedy-mF7zTu2bv_ELlbFArwNgqA==/oat/arm64/base.odex (offset 0x57000)

dr...@gmail.com <dr...@gmail.com> #7Jan 27, 2019 08:30PM

FYI, ML Kit launched a new language ID SDK in the latest release, which uses a new language ID model. https://developers.google.com/ml-kit/release-notes#august_11_2021

Could you try the new SDK version(17.0.0) to check if you can still repro this native crash? Thanks!

su...@google.com <su...@google.com> #8Jan 27, 2019 09:43PM

Thank you, I'll try it and check.

ra...@google.com <ra...@google.com> #9Jan 29, 2019 12:09AM

Hello. I have similar experience.

I'm using mlkit-language 16.1.1
I didnot meet this error until using AGP 4.2
I can get this error since using AGP 7.0
This error raised on Release build only(minimized by R8)
This error raised without obfuscation.

ra...@google.com <ra...@google.com> #10Jan 29, 2019 12:11AM

Also I found there is a post which presents same issue on stackoverflow.

https://stackoverflow.com/questions/68832304/mlkit-translate-sdk-crashes-in-release-build

dr...@gmail.com <dr...@gmail.com> #11Jan 29, 2019 10:06AM

I created reproducible project.

$ git clone https://github.com/ganadist/VersionCodeDemo -b mlkit_agp7 mlkit_agp7
$ cd mlkit_agp7
$ ./gradlew :app:pPRUA
$ adb install app/build/outputs/universal_apk/productionRelease/app-production-release-universal.apk
$ adb shell am start -n com.example.myapplication/.MainActivity

$ adb logcat -b crash -d
10-19 19:41:49.844 17810 17810 F libc    : Fatal signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x7acf9d733c in tid 17810 (e.myapplication), pid 17810 (e.myapplication)
10-19 19:41:50.473 17849 17849 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
10-19 19:41:50.473 17849 17849 F DEBUG   : Build fingerprint: 'google/crosshatch/crosshatch:12/SPB5.210812.002/7671067:user/release-keys'
10-19 19:41:50.473 17849 17849 F DEBUG   : Revision: 'MP1.0'
10-19 19:41:50.473 17849 17849 F DEBUG   : ABI: 'arm64'
10-19 19:41:50.473 17849 17849 F DEBUG   : Timestamp: 2021-10-19 19:41:49.903736988+0900
10-19 19:41:50.473 17849 17849 F DEBUG   : Process uptime: 0s
10-19 19:41:50.473 17849 17849 F DEBUG   : Cmdline: com.example.myapplication
10-19 19:41:50.474 17849 17849 F DEBUG   : pid: 17810, tid: 17810, name: e.myapplication  >>> com.example.myapplication <<<
10-19 19:41:50.474 17849 17849 F DEBUG   : uid: 10240
10-19 19:41:50.474 17849 17849 F DEBUG   : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x7acf9d733c
10-19 19:41:50.474 17849 17849 F DEBUG   :     x0  0000000000000000  x1  00000000000008fc  x2  0000007a76760c71  x3  0000000000000000
10-19 19:41:50.474 17849 17849 F DEBUG   :     x4  0000000000000010  x5  0000007ba4db49d0  x6  0000007b34dc3680  x7  3de38e3900000608
10-19 19:41:50.474 17849 17849 F DEBUG   :     x8  0000007bb4dbedf0  x9  0000007acf9db2aa  x10 0000000000000000  x11 0000007acf9d6640
10-19 19:41:50.474 17849 17849 F DEBUG   :     x12 0000000000000009  x13 0000000000000000  x14 0000000000000061  x15 00000000ebad6a89
10-19 19:41:50.474 17849 17849 F DEBUG   :     x16 0000007a767cfef8  x17 0000007d9a564b40  x18 0000007da3830000  x19 0000007feaf56a08
10-19 19:41:50.474 17849 17849 F DEBUG   :     x20 0000000000000000  x21 0000007ba4da50b0  x22 0000007bb4dbedf0  x23 0000007ba4da50b8
10-19 19:41:50.474 17849 17849 F DEBUG   :     x24 0000000000000009  x25 000000000000067e  x26 0000000000000012  x27 0000000000000008
10-19 19:41:50.474 17849 17849 F DEBUG   :     x28 0000007b64dc8440  x29 0000000000000000
10-19 19:41:50.474 17849 17849 F DEBUG   :     lr  0000007a7678a964  sp  0000007feaf56810  pc  0000007a7678b7c0  pst 0000000060000000
10-19 19:41:50.474 17849 17849 F DEBUG   : backtrace:
10-19 19:41:50.474 17849 17849 F DEBUG   :       #00 pc 000000000003c7c0  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #01 pc 000000000003b960  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #02 pc 000000000003bb48  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #03 pc 000000000003bafc  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #04 pc 0000000000036c98  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #05 pc 00000000000324a4  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)
10-19 19:41:50.474 17849 17849 F DEBUG   :       #06 pc 0000000000031b5c  /data/app/~~mHaMq-e9ocbm9UfYnkCGkQ==/com.example.myapplication-HgG9vkluwDDO1K78-Vzr0A==/lib/arm64/liblanguage_id_jni.so (Java_com_google_mlkit_nl_languageid_internal_LanguageIdentificationJni_nativeIdentifyLanguage+100) (BuildId: 859ec0ec2000a39e6ae8ed42e1704f46)

But after downgrade to AGP 4.2, crash is not reproducible.

$ git clone https://github.com/ganadist/VersionCodeDemo -b mlkit_agp42 mlkit_agp42
$ cd mlkit_agp42
$ ./gradlew :app:pPRUA
$ adb install app/build/outputs/universal_apk/productionRelease/app-production-release-universal.apk
$ adb shell am start -n com.example.myapplication/.MainActivity

Also, I tried to disable inline optimizers on R8 with AGP 7.0, and crash is not reproducible.

$ git clone https://github.com/ganadist/VersionCodeDemo -b mlkit_agp7_r8_disable_inline_optimizer  mlkit_agp7_r8
$ cd mlkit_agp7_r8
$ ./gradlew :app:pPRUA
$ adb install app/build/outputs/universal_apk/productionRelease/app-production-release-universal.apk
$ adb shell am start -n com.example.myapplication/.MainActivity

su...@google.com <su...@google.com> #12Jan 29, 2019 06:17PM

I tried the repro steps but got a NPE when I run ./gradlew :app:pPRUA

FAILURE: Build failed with an exception.

* What went wrong:
java.lang.NullPointerException
> java.lang.NullPointerException (no error message)

Could you also check if this is reproducible on 17.0.0 or 17.0.1? If yes, could you attach the full log that I can take a look? Thanks!

dr...@gmail.com <dr...@gmail.com> #13Jan 29, 2019 06:19PM

Here are gradle build scan logs for each branches.
All builds were clean build, and disabled build cache.

mlkit_agp7 : https://scans.gradle.com/s/qrymdqfzwokbq
mlkit_agp42 : https://scans.gradle.com/s/b6644hzfyfhaw
mlkit_agp7_r8_disable_inline_optimizer : https://scans.gradle.com/s/c6h5hy2nxod4u
- You can see R8 debug mode on build log : https://scans.gradle.com/s/c6h5hy2nxod4u/console-log#L95

Also, I pushed to update MLKit Language Id version 17.0.1 on mlkit17_agp7 branch And here is gradle build scan

https://scans.gradle.com/s/ytaa2kkbp5vc4
- Here is version of com.google.mlkit:language-id

And here is crash log after apply 17.0.1
You can see that BuildId of liblanguage_id_l2c_jni.so was changed from 859ec0ec2000a39e6ae8ed42e1704f46 to be6e59455cc10135330c93acdebfc121

10-20 03:07:24.522 24587 24628 F libc    : Fatal signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x7acf995426 in tid 24628 (pool-3-thread-3), pid 24587 (e.myapplication)
10-20 03:07:25.190 24710 24710 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
10-20 03:07:25.190 24710 24710 F DEBUG   : Build fingerprint: 'google/crosshatch/crosshatch:12/SPB5.210812.002/7671067:user/release-keys'
10-20 03:07:25.190 24710 24710 F DEBUG   : Revision: 'MP1.0'
10-20 03:07:25.190 24710 24710 F DEBUG   : ABI: 'arm64'
10-20 03:07:25.190 24710 24710 F DEBUG   : Timestamp: 2021-10-20 03:07:24.583346246+0900
10-20 03:07:25.190 24710 24710 F DEBUG   : Process uptime: 0s
10-20 03:07:25.190 24710 24710 F DEBUG   : Cmdline: com.example.myapplication
10-20 03:07:25.190 24710 24710 F DEBUG   : pid: 24587, tid: 24628, name: pool-3-thread-3  >>> com.example.myapplication <<<
10-20 03:07:25.190 24710 24710 F DEBUG   : uid: 10240
10-20 03:07:25.190 24710 24710 F DEBUG   : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x7acf995426
10-20 03:07:25.190 24710 24710 F DEBUG   :     x0  0000007b54da9d30  x1  0000007d9a5fe7cc  x2  0000000000000000  x3  0000000000000010
10-20 03:07:25.190 24710 24710 F DEBUG   :     x4  0000000000000000  x5  0000007c34dbc79c  x6  0000002f0000083b  x7  000003c300002dd5
10-20 03:07:25.190 24710 24710 F DEBUG   :     x8  0000000000000001  x9  0000000000000004  x10 0000000000000010  x11 0000000000000000
10-20 03:07:25.190 24710 24710 F DEBUG   :     x12 0000000000000000  x13 000000000000217e  x14 0000007acf9932a8  x15 000000000000217e
10-20 03:07:25.190 24710 24710 F DEBUG   :     x16 0000000000000000  x17 0000007d9a564c78  x18 0000007a6ef18000  x19 0000007c34dbc580
10-20 03:07:25.190 24710 24710 F DEBUG   :     x20 0000007ca4dc7170  x21 0000007ca4dc7800  x22 0000007ca4dc71e0  x23 0000000000000000
10-20 03:07:25.190 24710 24710 F DEBUG   :     x24 0000000000000018  x25 0000000000000007  x26 0000000000000006  x27 0000000000000004
10-20 03:07:25.190 24710 24710 F DEBUG   :     x28 0000007ca4dc7090  x29 0000007cb4da9940
10-20 03:07:25.190 24710 24710 F DEBUG   :     lr  0000007a770a9624  sp  0000007a6f7de9c0  pc  0000007a770a96a8  pst 0000000020000000
10-20 03:07:25.190 24710 24710 F DEBUG   : backtrace:
10-20 03:07:25.190 24710 24710 F DEBUG   :       #00 pc 00000000000386a8  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #01 pc 00000000000388a0  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #02 pc 00000000000844a0  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #03 pc 000000000008783c  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #04 pc 0000000000035fc4  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #05 pc 0000000000034954  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.190 24710 24710 F DEBUG   :       #06 pc 00000000000340e8  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/lib/arm64/liblanguage_id_l2c_jni.so (Java_com_google_mlkit_nl_languageid_internal_ThickLanguageIdentifier_nativeIdentifyPossibleLanguages+108) (BuildId: be6e59455cc10135330c93acdebfc121)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #07 pc 00000000002d9a44  /apex/com.android.art/lib64/libart.so (art_quick_generic_jni_trampoline+148) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #08 pc 000000000020a700  /apex/com.android.art/lib64/libart.so (nterp_helper+5648) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #09 pc 00000000000cd0dc  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #10 pc 000000000020a044  /apex/com.android.art/lib64/libart.so (nterp_helper+3924) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #11 pc 00000000000ccfa8  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #12 pc 0000000000557cb4  /system/framework/arm64/boot-framework.oat (android.os.Binder.transact+148) (BuildId: 43a571a0ad85d6451b47016336a541ecb0eb12bb)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #13 pc 000000000020b53c  /apex/com.android.art/lib64/libart.so (nterp_helper+9292) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #14 pc 00000000000b7aba  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #15 pc 000000000020a044  /apex/com.android.art/lib64/libart.so (nterp_helper+3924) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #16 pc 00000000000a7496  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #17 pc 000000000020a044  /apex/com.android.art/lib64/libart.so (nterp_helper+3924) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #18 pc 00000000000a7360  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #19 pc 000000000020ae64  /apex/com.android.art/lib64/libart.so (nterp_helper+7540) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #20 pc 000000000009e46c  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #21 pc 000000000020ae64  /apex/com.android.art/lib64/libart.so (nterp_helper+7540) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #22 pc 00000000000d33d6  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #23 pc 000000000020ae64  /apex/com.android.art/lib64/libart.so (nterp_helper+7540) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #24 pc 000000000009df0a  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #25 pc 0000000000209124  /apex/com.android.art/lib64/libart.so (nterp_helper+52) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #26 pc 000000000009e350  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #27 pc 000000000037b9ac  /apex/com.android.art/javalib/arm64/boot.oat (java.util.concurrent.ThreadPoolExecutor.runWorker+988) (BuildId: ab2bf4ec264efdb6c452a238be38fe624de826b8)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #28 pc 00000000003751d4  /apex/com.android.art/javalib/arm64/boot.oat (java.util.concurrent.ThreadPoolExecutor$Worker.run+68) (BuildId: ab2bf4ec264efdb6c452a238be38fe624de826b8)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #29 pc 000000000020aec4  /apex/com.android.art/lib64/libart.so (nterp_helper+7636) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #30 pc 000000000009e370  /data/app/~~KjjULZV48O7KSOgOP1wYNQ==/com.example.myapplication-vFUidUPTjaGg4oo3SRAYJw==/oat/arm64/base.vdex
10-20 03:07:25.191 24710 24710 F DEBUG   :       #31 pc 00000000001bf35c  /apex/com.android.art/javalib/arm64/boot.oat (java.lang.Thread.run+76) (BuildId: ab2bf4ec264efdb6c452a238be38fe624de826b8)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #32 pc 00000000002d0164  /apex/com.android.art/lib64/libart.so (art_quick_invoke_stub+548) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #33 pc 000000000031ccac  /apex/com.android.art/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+156) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #34 pc 00000000003cf8a0  /apex/com.android.art/lib64/libart.so (art::JValue art::InvokeVirtualOrInterfaceWithJValues<art::ArtMethod*>(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, art::ArtMethod*, jvalue const*)+380) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #35 pc 0000000000460894  /apex/com.android.art/lib64/libart.so (art::Thread::CreateCallback(void*)+992) (BuildId: cdecb8dde1264c9871695c29854aa3b1)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #36 pc 00000000000b1910  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+264) (BuildId: ba489d4985c0cf173209da67405662f9)
10-20 03:07:25.191 24710 24710 F DEBUG   :       #37 pc 00000000000513f0  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) (BuildId: ba489d4985c0cf173209da67405662f9)

su...@google.com <su...@google.com> #14Jan 29, 2019 06:24PM

Cross-posted on R8 issue tracker. https://issuetracker.google.com/issues/203573699

dr...@gmail.com <dr...@gmail.com> #15Jan 29, 2019 06:25PM

Hi,

Looks like we figured out the root cause in b/203573699

For temporary workarounds for the existing SDKs, you need to add this rule

-keep class com.google.mlkit.nl.languageid.internal.LanguageIdentificationJni { *; }

for language-id 16.1.1, and add this rule

-keep class com.google.mlkit.nl.languageid.internal.ThickLanguageIdentifier { *; }

for version language-id 17.0.0+ for the newer model.

We'll fix this issue in the upcoming release so that you'll not need these workarounds in the future release.

Thanks a lot for reporting this issue!

dr...@gmail.com <dr...@gmail.com> #16Jan 29, 2019 06:30PM

Added workarounds in Known issues section in public docs.

dr...@gmail.com <dr...@gmail.com> #17Jan 29, 2019 08:24PM

https://issuetracker.google.com/issues/250610583

https://issuetracker.google.com/issues/250609756

https://issuetracker.google.com/issues/250609759

https://issuetracker.google.com/issues/250610272

https://issuetracker.google.com/issues/250610273

https://issuetracker.google.com/issues/250610276

https://issuetracker.google.com/issues/250610278

https://issuetracker.google.com/issues/250610593

https://issuetracker.google.com/issues/250610280

https://issuetracker.google.com/issues/250610923

https://issuetracker.google.com/issues/250610282

https://issuetracker.google.com/issues/250611106

https://issuetracker.google.com/issues/250610598

https://issuetracker.google.com/issues/250611463

https://issuetracker.google.com/issues/250611111

https://issuetracker.google.com/issues/250610933

https://issuetracker.google.com/issues/250610935

https://issuetracker.google.com/issues/250611113

https://issuetracker.google.com/issues/250610937

https://issuetracker.google.com/issues/250611116

https://issuetracker.google.com/issues/250611466

https://issuetracker.google.com/issues/250612724

https://issuetracker.google.com/issues/250612604

https://issuetracker.google.com/issues/250612726

https://issuetracker.google.com/issues/250611471

https://issuetracker.google.com/issues/250177858

https://issuetracker.google.com/issues/250172577

https://www.endezo-it.com/2022/10/the-dark-event-of-indonesian-football.html

https://www.49erssports.com/2022/10/kanjuruhan-tragedy-arema-fc-management.html

https://one-piece-red-full-movie-english.webflow.io/

https://documenter.getpostman.com/view/21828632/2s83tJGAat

su...@google.com <su...@google.com> #18Jan 29, 2019 08:45PM

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

dr...@gmail.com <dr...@gmail.com> #19Jan 29, 2019 09:31PM

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"

logcat1548792694186.txt

708 KB

View

Download

ra...@google.com <ra...@google.com> #20Jan 30, 2019 12:35AM

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 ?

ra...@google.com <ra...@google.com> #21Jan 30, 2019 01:13AM

Assigned to ra...@google.com.

Sorry, I see that you are using unique work. Looking into this further.

dr...@gmail.com <dr...@gmail.com> #22Jan 30, 2019 08:28AM

I don't think I'm doing much out of the ordinary when scheduling the periodic work... basically as follows (leaving in the logging that corresponds to what you see in the logcat, and removing some of the value fetching logic, e.g. fetching values from SharedPrefs etc). Entry point is e.g. schedulePeriodicWork(1234, "some-trigger");

static void schedulePeriodicWork(int appWidgetId, String trigger) {
Log.d(TAG, "schedulePeriodicWork for " + appWidgetId);
String name = getPeriodicName(appWidgetId);
long interval = getInterval();
Constraints constraints = getConstraints("periodic");
Data inputData = getPeriodicInputData(appWidgetId, trigger);
PeriodicWorkRequest workRequest = getPeriodicWorkRequest(appWidgetId, interval, constraints, inputData);
WorkManager workManager = WorkManager.getInstance();
workManager.enqueueUniquePeriodicWork(name, ExistingPeriodicWorkPolicy.REPLACE, workRequest);
}

private static String getPeriodicName(int appWidgetId) {
return "periodic-" + appWidgetId;
}

private static long getInterval() {
return 15 * 60 * 1000;
}

private static Constraints getConstraints(String method) {
Log.d(TAG, "creating Constraints for " + method);
Constraints.Builder constraintsBuilder = new Constraints.Builder();
Log.d(TAG, "adding network constraint");
constraintsBuilder.setRequiredNetworkType(NetworkType.CONNECTED);
return constraintsBuilder.build();
}

private static PeriodicWorkRequest getPeriodicWorkRequest(int appWidgetId, long interval, Constraints constraints, Data inputData) {
String workTag = getWorkTag(appWidgetId);
Log.d(TAG, "creating PeriodicWorkRequest with tag " + workTag + " and with interval " + interval + " ms");
PeriodicWorkRequest.Builder workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS);
workRequestBuilder.setConstraints(constraints);
workRequestBuilder.setInputData(inputData);
workRequestBuilder.addTag(workTag);
workRequestBuilder.addTag(PERIODIC);
return workRequestBuilder.build();
}

private static Data getPeriodicInputData(int appWidgetId, String trigger) {
Log.d(TAG, "creating Data");
Data.Builder dataBuilder = new Data.Builder();
dataBuilder.putInt(AppWidgetManager.EXTRA_APPWIDGET_ID, appWidgetId);
dataBuilder.putString(trigger);
dataBuilder.putString("method", "periodic");
return dataBuilder.build();
}

private static String getWorkTag(int appWidgetId) {
return "widget-" + appWidgetId;
}

dr...@gmail.com <dr...@gmail.com> #23Jan 30, 2019 08:34AM

Presumably there is some significance in the log entries around the time that the 15 min periodic work is due to run -- if there had been network available -- i.e. around 21:07 ? i.e. the ones that refer to failed linking and resolving of work-related classes? Examples:

01-29 21:07:01.245 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/background/systemjob/SystemJobService; (90)
01-29 21:07:01.245 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/background/systemjob/SystemJobService;' failed
01-29 21:07:01.245 E/dalvikvm(29185): Could not find class 'androidx.work.impl.background.systemjob.SystemJobService', referenced from method androidx.work.impl.Schedulers.createBestAvailableBackgroundScheduler
01-29 21:07:01.245 W/dalvikvm(29185): VFY: unable to resolve const-class 2971 (Landroidx/work/impl/background/systemjob/SystemJobService;) in Landroidx/work/impl/Schedulers;
01-29 21:07:01.345 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.345 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.350 E/dalvikvm(29185): Could not find class 'androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateCallback', referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.<init>
01-29 21:07:01.350 W/dalvikvm(29185): VFY: unable to resolve new-instance 2994 (Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;) in Landroidx/work/impl/constraints/trackers/NetworkStateTracker;
01-29 21:07:01.355 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.getActiveNetwork, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.isActiveNetworkValidated
01-29 21:07:01.355 W/dalvikvm(29185): VFY: unable to resolve virtual method 1865: Landroid/net/ConnectivityManager;.getActiveNetwork ()Landroid/net/Network;
01-29 21:07:01.355 D/dalvikvm(29185): VFY: replacing opcode 0x6e at 0x000a
01-29 21:07:01.360 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.360 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.360 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.registerDefaultNetworkCallback, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.startTracking
01-29 21:07:01.360 W/dalvikvm(29185): VFY: unable to resolve virtual method 1871: Landroid/net/ConnectivityManager;.registerDefaultNetworkCallback (Landroid/net/ConnectivityManager$NetworkCallback;)V
01-29 21:07:01.365 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.365 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.365 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.unregisterNetworkCallback, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.stopTracking
01-29 21:07:01.365 W/dalvikvm(29185): VFY: unable to resolve virtual method 1872: Landroid/net/ConnectivityManager;.unregisterNetworkCallback (Landroid/net/ConnectivityManager$NetworkCallback;)V
01-29 21:07:01.365 D/dalvikvm(29185): VFY: replacing opcode 0x6e at 0x0018
01-29 21:07:01.370 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.370 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.370 D/dalvikvm(29185): DexOpt: unable to opt direct call 0x593e at 0x17 in Landroidx/work/impl/constraints/trackers/NetworkStateTracker;.<init>

dr...@gmail.com <dr...@gmail.com> #24Jan 30, 2019 08:39AM

And at the time the logs are taken by the user, the app dumps the current work queue, and sure enough there is a periodic work still enqueued (but this periodic work doesn't run when network has been restored and never seems to run again)... this is the log entry here:

01-29 21:11:33.875 D/Meteogram_ConfigActvty(29556): ********** LOG OF WORK QUEUE **********
01-29 21:11:34.175 D/Meteogram_Worker(29556): workInfo: WorkInfo{mId='8eaea234-7001-479e-ae88-2d628f57a62b', mState=ENQUEUED, mOutputData=androidx.work.Data@0, mTags=[widget-43443, com.cloud3squared.meteogram.MeteogramWorker, periodic]}
01-29 21:11:34.175 D/Meteogram_Worker(29556): workInfo: WorkInfo{mId='c43771c7-6b71-49fb-a2ee-c8486b37b798', mState=SUCCEEDED, mOutputData=androidx.work.Data@0, mTags=[widget-43443, com.cloud3squared.meteogram.MeteogramWorker, onetime]}
01-29 21:11:34.175 D/Meteogram_ConfigActvty(29556): ********** END OF WORK QUEUE **********

The above is logged by the following function, with the widget id passed in to get the tag (same method as in previous post), and filtering the work on this tag:

static void logWorkQueue(int appWidgetId) {
String tag = getWorkTag(appWidgetId);
WorkManager workManager = WorkManager.getInstance();
ListenableFuture<List<WorkInfo>> workInfos = workManager.getWorkInfosByTag(tag);
try {
List<WorkInfo> workInfoList = workInfos.get();
for (WorkInfo workInfo : workInfoList) {
Log.d(TAG, "workInfo: " + workInfo.toString());
}
} catch (ExecutionException e) {
e.printStackTrace();
} catch (InterruptedException e) {
e.printStackTrace();
}
}

dr...@gmail.com <dr...@gmail.com> #25Jan 30, 2019 01:57PM

Further update: it's just possible that this isn't specifically related to the network constraint. This user has now reported that a even a non-network-constrained periodic work seems to have stopped (as manifested by the associated widget no longer auto updating). I don't have logs for this, but maybe some of those log entries around 21:07 from the previous logcat might also be occurring even for periodic work that is not network constrained? Until now, the non-network-constrained periodic work does however seem to be more reliable... network constrained periodic work seems consistently to stop after a period without network.

ra...@google.com <ra...@google.com> #26Jan 30, 2019 06:11PM

Thanks for the details. I should have updated the thread yesterday. I think I know what might be going on.
I have a pending CL as well. It should be fixed in the next beta.

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

dr...@gmail.com <dr...@gmail.com> #27Jan 30, 2019 06:46PM

This is excellent news... thanks for checking it out so carefully, and fingers crossed... look forward to the next beta and will report back either way.

Any ETA on the next beta?

Keep up the good work on this really useful library!

ap...@google.com <ap...@google.com> #28Jan 30, 2019 07:06PM

Marked as fixed.

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

commit 177837514245d5bb24cc8e9bc27f20503e23e308
Author: Rahul Ravikumar <rahulrav@google.com>
Date: Tue Jan 29 17:50:14 2019

Fixes ConstraintsCommandHandler that correctly enables and disables proxies.

* ConstraintsCommandHandler was only looking at work that was eligible to be scheduled.
This is incorrect, as we may have Workers that are scheduled, but are pending execution due
to an unmet constraint. We need to look at all scheduled work which is unfinished.
* The only reason why this worked before with integration tests was due to one of 2 reasons:
* The process was in the foreground anyway, and there was an active WorkConstraintTracker.
* Enabling / disabling airplane mode (to test Network Constraints) would have caused a
TIME_SET broadcast in some cases where we reschedule everything (RescheduleReceiver).

Test: Updated SystemAlarmDispatcherTests & integration tests on API 22 with the Battery charging
Constraint that has no other side effects.

Change-Id: Ib973931b47be915dd8f533e1e651b6c1a29843f9
Fixes:

b/123379508

M work/workmanager/src/androidTest/java/androidx/work/impl/background/systemalarm/SystemAlarmDispatcherTest.java
M work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/ConstraintsCommandHandler.java
M work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/RescheduleReceiver.java
M work/workmanager/src/main/java/androidx/work/impl/model/WorkSpecDao.java

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

https://goto.google.com/android-sha1/177837514245d5bb24cc8e9bc27f20503e23e308

dr...@gmail.com <dr...@gmail.com> #29Feb 1, 2019 08:14AM

Any ETA for beta04? Am desperate to try it out..

ra...@google.com <ra...@google.com> #30Feb 1, 2019 05:34PM

Looking at early next week.

dr...@gmail.com <dr...@gmail.com> #31Feb 1, 2019 05:36PM

OK, thanks!

dr...@gmail.com <dr...@gmail.com> #32Feb 15, 2019 05:52PM

I'm still seeing this problem, or seeing it again. I'm monitoring (at a server) requests from the device of the same user (Android 4.3), and can see that a periodic work request seems to run OK for a time, but when the device is idle and without network, when the device is given network again, not only does the late work not run, but no work ever seems to run again. And a log output of all work does still show that a periodic work is enqueued, but it just never seems to run again.

Are the tests you ran when fixing this before still working? Or has something subsequently messed it up? Or maybe I'm seeing another issue altogether.

su...@google.com <su...@google.com> #33Feb 15, 2019 06:00PM

Please give us a sample project. I think that's the simplest way for us to take a look at exactly what's happening for you. Which device are you running this on?

dr...@gmail.com <dr...@gmail.com> #34Feb 15, 2019 06:02PM

Device is as per #16 -- Samsung Galaxy S3 running Android 4.3

su...@google.com <su...@google.com> #35Feb 15, 2019 06:08PM

Can you reproduce the same behavior using a stock Android device/emulator?

dr...@gmail.com <dr...@gmail.com> #36Feb 15, 2019 06:13PM

Not as yet; am trying now.

dr...@gmail.com <dr...@gmail.com> #37Feb 15, 2019 06:19PM

Is there any way of querying a bit more information about enqueued work requests? The most information I can get at the moment is something like:

02-15 17:37:31.535 D/My_Worker(11599): workInfo: WorkInfo{mId='00db2ea7-07d6-42a1-a506-a26ff8e3217d', mState=ENQUEUED, mOutputData=androidx.work.Data@0, mTags=[com.example.myapp.MyWorker, widget-43806, periodic]}
02-15 17:37:31.535 D/My_Worker(11599): workInfo: WorkInfo{mId='08bce448-5d4a-4a17-89d2-6fdce6ef1091', mState=SUCCEEDED, mOutputData=androidx.work.Data@0, mTags=[com.example.myapp.MyWorker, widget-43806, backstop]}

And the only reason I can even tell if the work item is periodic or not is because I tag it with 'periodic' if it is. Otherwise, all I get is a work ID and a state... would be really handy to know when it last ran, when it is due to run next, etc. Would be very useful not least for debugging purposes.

As suggested:

https://issuetracker.google.com/issues/123222823

ra...@google.com <ra...@google.com> #38Feb 15, 2019 06:20PM

You need to enable verbose logs. That will tell us a lot more.

ra...@google.com <ra...@google.com> #39Feb 15, 2019 06:22PM

Also, if you are going into a SUCCEEDED state, that mean your Worker is actually not periodic. PeriodicWork never goes into a terminal state unless it has been cancelled.
It always goes back to ENQUEUED for the next interval.

dr...@gmail.com <dr...@gmail.com> #40Feb 15, 2019 06:22PM

As per #9 above. Yes, the 4.3 user is currently running a test version with this verbose logging enabled to see if I can get something interesting from it.

ra...@google.com <ra...@google.com> #41Feb 15, 2019 06:24PM

For reference all WorkManager logs are prefixed with a "WM-".

dr...@gmail.com <dr...@gmail.com> #42Feb 15, 2019 06:24PM

#39: indeed, but the SUCCEEDED entry is a onetime worker... it is not tagged with 'periodic' but only 'backstop' (which is a onetime request).

dr...@gmail.com <dr...@gmail.com> #43Feb 15, 2019 11:22PM

I've seen this behaviour now on the 4.3 emulator. I started a periodic work request (for updating a widget) with network constraint and interval of one hour (flex of 30 mins). I put the emulator into airplane mode and came back some time later. On disabling airplane mode the widget did update immediately but the trigger was ON_ENABLED for the widget and not the late work request. Thereafter, I left the widget for an hour, and nothing happened... the periodic work that was meant to trigger an update hasn't happened. I meant to dump the alarm state with "adb shell dumpsys alarm" but unfortunately I reset the widget before doing so. Will next time. Sorry it's a bit nebulous thus far... I will try to bring more concrete information next time but there's definitely still something not right with network-constrained periodic work on Android 4.3.

su...@google.com <su...@google.com> #44Feb 15, 2019 11:42PM

Yes, please send us a sample project when you have it.

dr...@gmail.com <dr...@gmail.com> #45Feb 15, 2019 11:48PM

I'll try, but am short of time over next few days. Tempting just to set minsdk to 21 and be done with it!

dr...@gmail.com <dr...@gmail.com> #46Feb 16, 2019 12:06PM

I have some logs to post... would that be of assistance in lieu of a sample project for now?

ra...@google.com <ra...@google.com> #47Feb 16, 2019 04:19PM

Yes, please send them

dr...@gmail.com <dr...@gmail.com> #48Feb 17, 2019 04:34PM

Logs attached, from the user's Android 4.3 device. During the period in which the logs were generated, the periodic work concerned should have fired (to cause a widget to update) at least twice but failed to do so. The periodic work was on a 30 minute interval, with 15 minute flex interval. With network constraint. After enqueuing the periodic work, the device was without network for a time, then network was restored. But periodic work failed to trigger. I schedule the periodic work basically as described in #22 *except* that I now use a flex interval (to address a double running of work as per another issue).

There seems to be lots of "D/WM-" stuff in there that refers to constraints... hopefully something of interest.

logcat1550410984826.txt

215 KB

View

Download

dr...@gmail.com <dr...@gmail.com> #49Feb 17, 2019 07:53PM

Some further information which may be of interest...

To see if it made a difference, I went back to NOT using a flexInterval, i.e. using:

workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS);

INSTEAD of:

workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS, flexInterval, TimeUnit.MILLISECONDS);

And without using flexInterval, behaviour seems to be FAR more reliable so far. The periodic work (with network constraint) has so far survived some degree of testing (on the user device): letting the periodic work fire a few times, then turning off network for one or more scheduled firings, then network back on... and each time so far the "missed" work runs straight away.

It's far from an extensive test yet, but it seems like it can't be coincidence... the above change (to NOT use flexInterval) is all I've changed, and it is performing better so far.

After *this current* issue (i.e. #123379508) was marked fixed on 30 Jan, a change was made to WorkManager flexInterval behaviour on 13 Feb as per the following:

https://issuetracker.google.com/issues/124274584

Would it have anything to do with that? Between #123379508 being fixed (30 Jan) and #124274584 being fixed (13 Feb), I think that things were going well. It seemed to be after #124274584 was fixed that things went downhill again. Again, I can't be certain, but it's a lead anyway.

P.S. the only reason I started using flexInterval in the first place was to address the issue reported here:

https://issuetracker.google.com/issues/123804615#comment8

dr...@gmail.com <dr...@gmail.com> #50Feb 17, 2019 07:54PM

BTW the logs in #48 were BEFORE I made the change mentioned in #49, i.e. using flexInterval

ra...@google.com <ra...@google.com> #51Feb 18, 2019 07:57PM

I looked at the logs. It looks like the ConstraintTracker correctly tries to start the work, but the device subsequently reports that the constraints are unmet when trying to run the Worker.

02-17 14:02:25.255 D/WM-ConstraintTracker( 1608): NetworkStateTracker: initial state = [ Connected=false Validated=false Metered=false NotRoaming=false ]. This happens twice, like you described.

This is expected behavior. I think your disabling of flex has nothing to do with why the Worker was running when you had flex. I think the device does not have access to a reliable network as far as I can tell.

dr...@gmail.com <dr...@gmail.com> #52Feb 18, 2019 08:09PM

It's a WiFi network... not saying that is necessary "reliable" but it surely is unlikely to be consistently unreliable?

And how do you explain why NOT specifying a flexInterval results in completely reliable periodic behaviour? While specifying a flexInterval makes it fall apart?

I don't follow your comment about expected behaviour... in the period of the logs, the device had no WiFi for at least two expected periodic runs, but didn't run because there was no network. That's expected behaviour, yes. What is not expected is that even when network was restored, the work did not run, ever again. That is when specifying a flexInterval.

But when not specifying a flexInterval, it all works smoothly... that doesn't make sense does it?

Am getting reports in now from said user... it's running like clockwork with the version that doesn't specify flexInterval when setting up the periodic work request.

ra...@google.com <ra...@google.com> #53Feb 19, 2019 02:05AM

Specifying flex does nothing except delay the Worker in the AlarmManager implementation.
There is absolutely no difference in how constraints are handled.

Also, from the logs that you attached, it is clear that the device was not connected to a network. That's what I am basing this on. (NetworkStateTracker: initial state = [ Connected=false Validated=false Metered=false NotRoaming=false ]).

If you still think there might be something else going on, I think the best thing to do is to send us a sample app to reproduce this on our end.

dr...@gmail.com <dr...@gmail.com> #54Feb 19, 2019 11:45AM

There are two such logs entries (one of which you quote above) that say "Connected=false".

But there is a third one, later, that says "Connected=true":

02-17 14:40:50.345 D/WM-ConstraintTracker( 3798): NetworkStateTracker: initial state = [ Connected=true Validated=false Metered=false NotRoaming=true ]

And then immediately after:

02-17 14:40:50.345 D/WM-WorkConstraintsTrack( 3798): Constraints met for 635bfec6-81c9-499a-a9d2-5e273f07573c

So why did the work not run?

su...@google.com <su...@google.com> #55Feb 19, 2019 05:47PM

So I think we're going very very deep into a bug that we cannot reproduce. Please send us a sample project.

dr...@gmail.com <dr...@gmail.com> #56Feb 19, 2019 06:35PM

Trouble is, I think this may be quite specific to that device. I can't reproduce it on the emulator (what I thought I was seeing in #43 was actually something else). So all we have to go on is the logs from the user device. I thought the D/WM- log entries would help... clearly not. Is it not possible to determine from those why the work constraints were met at 02-17 14:40:50.345 and yet the work did not execute?

dr...@gmail.com <dr...@gmail.com> #57Feb 20, 2019 11:20AM

Here is another instance, today, where the network-constrained periodic work (widget update) failed to run on the user's Android 4.3 device after turning the WiFi back on first thing this morning... see attached logs, with relevant entries below:

02-20 10:28:12.735 D/WM-ConstraintProxy( 1227): onReceive : Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x8000010 cmp=com.cloud3squared.meteogram.devpro/androidx.work.impl.background.systemalarm.ConstraintProxy$NetworkStateProxy (has extras) }

02-20 10:28:14.770 D/WM-ConstraintTracker( 1227): NetworkStateTracker: initial state = [ Connected=true Validated=false Metered=false NotRoaming=true ]

02-20 10:28:14.815 D/WM-WorkConstraintsTrack( 1227): Constraints met for 5d210711-4c14-43cb-b6ea-2a6de910d76a

And yet, after this, the work doesn't run... there are no log entries from the startWork() function of the associated Worker.

logcat-1550655242829.txt

116 KB

View

Download

Issue 123379508

Description

Issue summary

Comments

ra...@google.com <ra...@google.com> #2Jan 25, 2019 06:26PM

su...@google.com <su...@google.com> #3Jan 25, 2019 07:04PM

dr...@gmail.com <dr...@gmail.com> #4Jan 26, 2019 04:18PM

dr...@gmail.com <dr...@gmail.com> #5Jan 27, 2019 03:04PM

dr...@gmail.com <dr...@gmail.com> #6Jan 27, 2019 08:03PM

dr...@gmail.com <dr...@gmail.com> #7Jan 27, 2019 08:30PM

su...@google.com <su...@google.com> #8Jan 27, 2019 09:43PM

ra...@google.com <ra...@google.com> #9Jan 29, 2019 12:09AM

ra...@google.com <ra...@google.com> #10Jan 29, 2019 12:11AM

dr...@gmail.com <dr...@gmail.com> #11Jan 29, 2019 10:06AM

su...@google.com <su...@google.com> #12Jan 29, 2019 06:17PM

dr...@gmail.com <dr...@gmail.com> #13Jan 29, 2019 06:19PM

su...@google.com <su...@google.com> #14Jan 29, 2019 06:24PM

dr...@gmail.com <dr...@gmail.com> #15Jan 29, 2019 06:25PM

dr...@gmail.com <dr...@gmail.com> #16Jan 29, 2019 06:30PM

dr...@gmail.com <dr...@gmail.com> #17Jan 29, 2019 08:24PM

su...@google.com <su...@google.com> #18Jan 29, 2019 08:45PM

dr...@gmail.com <dr...@gmail.com> #19Jan 29, 2019 09:31PM

ra...@google.com <ra...@google.com> #20Jan 30, 2019 12:35AM

ra...@google.com <ra...@google.com> #21Jan 30, 2019 01:13AM

dr...@gmail.com <dr...@gmail.com> #22Jan 30, 2019 08:28AM

dr...@gmail.com <dr...@gmail.com> #23Jan 30, 2019 08:34AM

dr...@gmail.com <dr...@gmail.com> #24Jan 30, 2019 08:39AM

dr...@gmail.com <dr...@gmail.com> #25Jan 30, 2019 01:57PM

ra...@google.com <ra...@google.com> #26Jan 30, 2019 06:11PM

dr...@gmail.com <dr...@gmail.com> #27Jan 30, 2019 06:46PM

ap...@google.com <ap...@google.com> #28Jan 30, 2019 07:06PM

dr...@gmail.com <dr...@gmail.com> #29Feb 1, 2019 08:14AM

ra...@google.com <ra...@google.com> #30Feb 1, 2019 05:34PM

dr...@gmail.com <dr...@gmail.com> #31Feb 1, 2019 05:36PM

dr...@gmail.com <dr...@gmail.com> #32Feb 15, 2019 05:52PM

su...@google.com <su...@google.com> #33Feb 15, 2019 06:00PM

dr...@gmail.com <dr...@gmail.com> #34Feb 15, 2019 06:02PM

su...@google.com <su...@google.com> #35Feb 15, 2019 06:08PM

dr...@gmail.com <dr...@gmail.com> #36Feb 15, 2019 06:13PM

dr...@gmail.com <dr...@gmail.com> #37Feb 15, 2019 06:19PM

ra...@google.com <ra...@google.com> #38Feb 15, 2019 06:20PM

ra...@google.com <ra...@google.com> #39Feb 15, 2019 06:22PM

dr...@gmail.com <dr...@gmail.com> #40Feb 15, 2019 06:22PM

ra...@google.com <ra...@google.com> #41Feb 15, 2019 06:24PM

dr...@gmail.com <dr...@gmail.com> #42Feb 15, 2019 06:24PM

dr...@gmail.com <dr...@gmail.com> #43Feb 15, 2019 11:22PM

su...@google.com <su...@google.com> #44Feb 15, 2019 11:42PM

dr...@gmail.com <dr...@gmail.com> #45Feb 15, 2019 11:48PM

dr...@gmail.com <dr...@gmail.com> #46Feb 16, 2019 12:06PM

ra...@google.com <ra...@google.com> #47Feb 16, 2019 04:19PM

dr...@gmail.com <dr...@gmail.com> #48Feb 17, 2019 04:34PM

dr...@gmail.com <dr...@gmail.com> #49Feb 17, 2019 07:53PM

dr...@gmail.com <dr...@gmail.com> #50Feb 17, 2019 07:54PM

ra...@google.com <ra...@google.com> #51Feb 18, 2019 07:57PM

dr...@gmail.com <dr...@gmail.com> #52Feb 18, 2019 08:09PM

ra...@google.com <ra...@google.com> #53Feb 19, 2019 02:05AM

dr...@gmail.com <dr...@gmail.com> #54Feb 19, 2019 11:45AM

su...@google.com <su...@google.com> #55Feb 19, 2019 05:47PM

dr...@gmail.com <dr...@gmail.com> #56Feb 19, 2019 06:35PM

dr...@gmail.com <dr...@gmail.com> #57Feb 20, 2019 11:20AM

Add comment

Issue metadata