IssueTracker

Yigit, do you have time to fix it?

reemission of the same liveData is racy

yea i'll take it.

Thanks for the detailed analysis. This may not be an issue anymore since we've started using Main.immediate there but I' not sure; I'll try to create a test case.

just emitting same live data reproduces the issue.

    @Test
    fun raceTest() {
        val subLiveData = MutableLiveData(1)
        val subject = liveData(testScope.coroutineContext) {
            emitSource(subLiveData)
            emitSource(subLiveData) //crashes
        }
        subject.addObserver().apply {
            testScope.advanceUntilIdle()
        }
    }

With 2.2.0-alpha04 (that use Main.immediate), the issue seems to be still there (I tested it by calling emitSource() twice, like your test case)

yea sorry immediate does not fix it.
I actually have a WIP fix for it:
https://android-review.googlesource.com/c/platform/frameworks/support/+/1112186

if your case is the one i found (emitting same LiveData multiple times, as shown in #5) you can work around it by adding a dummy transformation.


val subLiveData = MutableLiveData(1)
        val subject = liveData(testScope.coroutineContext) {
            emitSource(subLiveData.map {it })
            emitSource(subLiveData.map {it} )
        }

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

commit af12e75e6b4110f48e44ca121466943909de8f06
Author: Yigit Boyar <yboyar@google.com>
Date:   Tue Sep 03 12:58:11 2019

    Fix coroutine livedata race condition
   
    This CL fixes a bug in liveData builder where emitting same
    LiveData source twice would make it crash because the second
    emission registry could possibly happen before first one is
    removed as source.
   
    We fix it by using a suspending dispose function. It does feel
    a bit hacky but we cannot make DisposableHandle.dispose async
    and we do not want to block there. This does not mean that there
    is a problem if developer disposes it manually since our emit
    functions take care of making sure it disposes (and there is
    no other way to add source to the underlying MediatorLiveData)
   
    Bug: 140249349
    Test: BuildLiveDataTest#raceTest_*
   
    Change-Id: I0b464c242a583da4669af195cf2504e2adc4de40

M       lifecycle/lifecycle-livedata-ktx/api/2.2.0-alpha05.txt
M       lifecycle/lifecycle-livedata-ktx/api/current.txt
M       lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_2.2.0-alpha05.txt
M       lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_current.txt
M       lifecycle/lifecycle-livedata-ktx/api/restricted_2.2.0-alpha05.txt
M       lifecycle/lifecycle-livedata-ktx/api/restricted_current.txt
M       lifecycle/lifecycle-livedata-ktx/src/main/java/androidx/lifecycle/CoroutineLiveData.kt
M       lifecycle/lifecycle-livedata-ktx/src/test/java/androidx/lifecycle/BuildLiveDataTest.kt

https://android-review.googlesource.com/1112186
https://goto.google.com/android-sha1/af12e75e6b4110f48e44ca121466943909de8f06

Can you please turn on verbose logging and send us all the logs ? I am going to try and reproduce this on my end.

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.

I think I know what is going on. There are 2 competing schedulers that can pick up work. When the in-process scheduler picks up work and the process gets killed there is nothing else that can wake up to reschedule that Worker until the application is launched again.

Thanks for looking into this more.
I've attached the logs I captured when reproducing the problem as follows:

1. Create a brand new Nexus 7 (2012) API 22 emulator to make sure the system does not have any old state that affects behavior, and start it, and let it boot up and rest a bit. Double-check that in Settings -> Storage, it doesn't say "running out of storage". If it does say that, reboot the emulator. That should get rid of the message. If you try to install the app when the device is in its strange "running out of storage state", you will get "stale dex" errors when installing the app. I'm using the x86 emulator on a 2018 MacBook Pro.

2. Start log capturing with this command: adb -s emulator-5554 logcat -T 0 -v threadtime -s '*:V' | tee ~/log-workmanager-repro-verbose-3.txt

3. Start the app, and after ~10 seconds, close it (I've increased sleep to 20 s)

4. Wait for a long enough time to convince yourself of that the Worker will never be scheduled again (I waited for > 10 minutes)

5. Stop logging.

For your convenience, I have inlined the log filtered with: grep -e Repro -e WM- -e Killing.*workmanager ~/log-workmanager-repro-verbose-3.txt
at the end of the mail. For full logs, see attached file.

The last line with 'Killing' is from me swiping away the app in the App Switcher.

Note that the logs have this line:
WM-SystemAlarmService: All commands completed in dispatcher
So it looks like even though SystemAlarmService was used to dispatch the Worker, the bug happened. ("All commands completed in dispatcher" means SystemAlarmService is about to do Service.stopSelf() as you probably know.)

Let me know if I can help you in any other way.

BR Martin



01-30 09:42:31.954  3613  3613 D WM-Schedulers: Created SystemAlarmScheduler
01-30 09:42:31.960  3613  3613 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.SystemAlarmService enabled
01-30 09:42:31.970  3613  3632 D WM-ForceStopRunnable: Application was force-stopped, rescheduling.
01-30 09:42:31.993  3613  3613 E Repro   : Calling enqueueUniqueWork(1548837751988, ...)
01-30 09:42:32.040  3613  3632 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
01-30 09:42:32.043  3613  3632 D WM-SystemAlarmScheduler: Scheduling work with workSpecId 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.046  3613  3632 D WM-Processor: Processor: processing 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.054  3613  3613 D WM-SystemAlarmDispatche: Adding command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) } (1)
01-30 09:42:32.055  3613  3632 D WM-SystemAlarmDispatche: Processing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }, 1
01-30 09:42:32.055  3613  3632 D WM-SystemAlarmDispatche: Acquiring operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=false, refCount=0}
01-30 09:42:32.055  3613  3632 D WM-CommandHandler: Handling schedule work for 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.056  3613  3637 E Repro   : doWork() called. Now swipe away app in App Switcher. Tags: [com.github.enselic.workmanagerfailedscheduling.LogPrinter, 1548837751988]
01-30 09:42:32.056  3613  3632 W WM-CommandHandler: Skipping scheduling 576d2452-a559-4c85-b217-c954c6905d7e because it is no longer enqueued
01-30 09:42:32.056  3613  3632 D WM-SystemAlarmDispatche: Releasing operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=true, refCount=1}
01-30 09:42:32.096  3613  3613 D WM-SystemAlarmDispatche: Checking if commands are complete.
01-30 09:42:32.096  3613  3613 D WM-SystemAlarmDispatche: Removing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }
01-30 09:42:32.096  3613  3613 D WM-SystemAlarmDispatche: No more commands & intents.
01-30 09:42:32.096  3613  3613 D WM-SystemAlarmService: All commands completed in dispatcher
01-30 09:42:43.607  1647  2397 I ActivityManager: Killing 3613:com.github.enselic.workmanagerfailedscheduling/u0a58 (adj 9): remove task

Thanks for providing more information.. This is in line with a fix that I am working on. This should be fixed in the next beta.

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

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

commit ebb4f87d732f66d01d1a4cf362bb11a815e80b74
Author: Rahul Ravikumar <rahulrav@google.com>
Date:   Tue Jan 29 16:16:17 2019

    Correctly retry work on process death when using AlarmManager based implementation.
   
    * AlarmManager now schedules a Worker unless the WorkSpec#isFinished() is true.
    * When AlarmManager gets worken up by ActivityManager to resume processing, we
      correctly execute the Worker after a backoff period.
    * We now correctly handle rescheduling in DelayMetCommandHandler. Previously the
      only reason why this worked before was the call to Schedulers.schedule() in
      WorkerWrapper inside the onWorkFinished() method.
    * When delaying execution of Workers in WorkerWrapper we always reschedule givem
      SystemJobScheduler does not schedule jobs where JobScheduler is already aware
      of the jobId.
    * Added a lot more logging in GreedyScheduler, SystemJobScheduler and SystemAlarmScheduler
      to make debugging easier.
    * Ran a lot of integration tests on API 22, 23 (double scheduling) and 28.
      Look at https://paste.googleplex.com/5709211287683072?raw
      for more information. I also ran integration tests that cancel
      workers to sanity check.
   
    Fixes: b/123329850
    Test: Added additional test cases in SystemAlarmDispatcherTest.
   
    Change-Id: I1bcff1ebf5f60928a02e3e94e2e6ccaed0de47b1

M       work/integration-tests/testapp/src/main/java/androidx/work/integration/testapp/MainActivity.java
A       work/integration-tests/testapp/src/main/java/androidx/work/integration/testapp/RetryWorker.java
M       work/integration-tests/testapp/src/main/res/layout/activity_main.xml
M       work/integration-tests/testapp/src/main/res/values/strings.xml
M       work/workmanager/src/androidTest/java/androidx/work/impl/WorkerWrapperTest.java
M       work/workmanager/src/androidTest/java/androidx/work/impl/background/systemalarm/SystemAlarmDispatcherTest.java
M       work/workmanager/src/main/java/androidx/work/impl/WorkerWrapper.java
M       work/workmanager/src/main/java/androidx/work/impl/background/greedy/GreedyScheduler.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/CommandHandler.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/DelayMetCommandHandler.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemjob/SystemJobScheduler.java

https://android-review.googlesource.com/889837
https://goto.google.com/android-sha1/ebb4f87d732f66d01d1a4cf362bb11a815e80b74