Foreground RxJava work is never cancelled [156310133]

Fixed

Bug

Status Update

No update yet.

Description

ar...@gmail.com

created issue #1

May 12, 2020 06:55AM

WorkManager versions: 2.3.4, 2.4.0-alpha03
Android version: 10
Device: emulator API level 29, x86

Put the following code in the Application subclass and call the scheduleForegroundWork method in the onCreate one.

Disable Wi-Fi.
Run the application.
Enable Wi-Fi.
Wait 5 seconds or so.
Disable Wi-Fi.
Results:
- Actual: work is not cancelled, the Single keeps working, the notification remains in place.
- Expected: work is cancelled, the Single is disposed, the notification is hidden.

private fun scheduleForegroundWork() {
    val workConstraints = Constraints.Builder()
        .setRequiredNetworkType(NetworkType.UNMETERED)
        .build()

    val workRequest = OneTimeWorkRequest.Builder(ForegroundWorker::class.java)
        .setConstraints(workConstraints)
        .build()

    WorkManager
        .getInstance(this)
        .enqueueUniqueWork("foreground-work", ExistingWorkPolicy.REPLACE, workRequest)
}

class ForegroundWorker(private val context: Context, parameters: WorkerParameters) : RxWorker(context, parameters) {

    companion object {
        private const val NOTIFICATION_CHANNEL_ID = "foreground-work"
    }

    override fun createWork() = Single
        .fromCallable {
            createNotificationChannel()

            setForegroundAsync(ForegroundInfo(42, createNotification())).get().toOptional()
        }
        .flatMapObservable {
            Observable
                .interval(0, 1, TimeUnit.SECONDS)
                .switchMap {
                    println("Worker interval $it")
         
                    if (it > 60) {
                        Observable.just(Unit)
                    } else {
                        Observable.never()
                    }
                }
        }
        .firstOrError()
        .map { Result.success() }

    private fun createNotificationChannel() {
        val channel = NotificationChannel(
            NOTIFICATION_CHANNEL_ID,
            "Foreground work",
            NotificationManager.IMPORTANCE_LOW
        )

        context.getSystemService<NotificationManager>()?.createNotificationChannel(channel)
    }

    private fun createNotification() = Notification.Builder(context, NOTIFICATION_CHANNEL_ID)
        .setSmallIcon(R.drawable.ic_notification)
        .setContentText("Hello there from the foreground work")
        .build()
}

Debug logs (2.4.0-alpha03):

// Open the application

WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
WM-ForceStopRunnable: Performing cleanup operations.
WM-ForceStopRunnable: Application was force-stopped, rescheduling.
WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
WM-SystemJobScheduler: Scheduling work ID 8f1237eb-ea6c-415c-a512-c431c6ee985c Job ID 0
WM-GreedyScheduler: Starting tracking for [8f1237eb-ea6c-415c-a512-c431c6ee985c]
WM-ConstraintTracker: NetworkStateTracker: initial state = [ Connected=false Validated=false Metered=true NotRoaming=false ]
WM-NetworkStateTracker: Registering network callback
WM-GreedyScheduler: Constraints not met: Cancelling work ID 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: Processor stopping background work 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: WorkerWrapper could not be found for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-StopWorkRunnable: StopWorkRunnable for 8f1237eb-ea6c-415c-a512-c431c6ee985c; Processor.stopWork = false

// Enable Wi-Fi

WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -30]
WM-WorkConstraintsTrack: Constraints met for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-GreedyScheduler: Constraints met: Scheduling work ID 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: Processor: processing 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-WorkerWrapper: Starting work for PACKAGE.Application$ForegroundWorker
WM-Processor: Moving WorkSpec (8f1237eb-ea6c-415c-a512-c431c6ee985c) to the foreground
WM-SystemFgDispatcher: Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=PACKAGE/androidx.work.impl.foreground.SystemForegroundService (has extras) }
WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 8f1237eb-ea6c-415c-a512-c431c6ee985c, notificationType: 0)
WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 8f1237eb-ea6c-415c-a512-c431c6ee985c, notificationType: 0)
WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -30]
WM-WorkConstraintsTrack: Constraints met for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-SystemJobService: onStartJob for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: Processor: processing 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-WorkConstraintsTrack: Constraints met for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-GreedyScheduler: Constraints met: Scheduling work ID 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-WorkConstraintsTrack: Constraints met for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-WorkerWrapper: Status for 8f1237eb-ea6c-415c-a512-c431c6ee985c is RUNNING;not doing any work and rescheduling for later execution
WM-WorkerWrapper: PACKAGE.Application$ForegroundWorker is not in ENQUEUED state. Nothing more to do.
WM-Processor: Processor 8f1237eb-ea6c-415c-a512-c431c6ee985c executed; reschedule = true
WM-GreedyScheduler: Stopping tracking for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-NetworkStateTracker: Unregistering network callback
WM-SystemJobService: 8f1237eb-ea6c-415c-a512-c431c6ee985c executed on JobScheduler
WM-Processor: Processor: processing 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-WorkerWrapper: Status for 8f1237eb-ea6c-415c-a512-c431c6ee985c is RUNNING;not doing any work and rescheduling for later execution
WM-Processor: Processor 8f1237eb-ea6c-415c-a512-c431c6ee985c executed; reschedule = true
WM-WorkerWrapper: PACKAGE.Application$ForegroundWorker is not in ENQUEUED state. Nothing more to do.

// Disable Wi-Fi (nothing is printed)

// Pass 60 seconds for Single to complete

WM-WorkerWrapper: PACKAGE.Application$ForegroundWorker returned a Success {mOutputData=Data {}} result.
WM-WorkerWrapper: Worker result SUCCESS for Work [ id=8f1237eb-ea6c-415c-a512-c431c6ee985c, tags={ PACKAGE.Application$ForegroundWorker } ]
WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver disabled
WM-Processor: No more foreground work. Stopping SystemForegroundService
WM-SystemFgDispatcher: Stopping foreground service
WM-SystemFgService: All commands completed.
WM-Processor: Processor 8f1237eb-ea6c-415c-a512-c431c6ee985c executed; reschedule = false
WM-GreedyScheduler: Cancelling work ID 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: Processor stopping background work 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-Processor: WorkerWrapper could not be found for 8f1237eb-ea6c-415c-a512-c431c6ee985c
WM-StopWorkRunnable: StopWorkRunnable for 8f1237eb-ea6c-415c-a512-c431c6ee985c; Processor.stopWork = false

Comments

ra...@google.com <ra...@google.com> #2May 12, 2020 04:34PM

Yigit, do you have time to fix it?

reemission of the same liveData is racy

ar...@gmail.com <ar...@gmail.com> #3May 12, 2020 05:08PM

yea i'll take it.

work-manager-observable.zip

251 KB

Download

ra...@google.com <ra...@google.com> #4May 12, 2020 05:55PM

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.

ra...@google.com <ra...@google.com> #5May 12, 2020 05:57PM

Status: Won't Fix (Not Reproducible)

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()
}
}

ra...@google.com <ra...@google.com> #6May 12, 2020 05:57PM

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)

ar...@gmail.com <ar...@gmail.com> #7May 12, 2020 06:12PM

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} )
}

worker.txt

15 KB

View

Download

ra...@google.com <ra...@google.com> #8May 12, 2020 06:29PM

Assigned to ra...@google.com.

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

ap...@google.com <ap...@google.com> #9May 12, 2020 08:04PM

Marked as fixed.

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

commit 889cad12d1cadf8ee1ec3e031b204cb94e498233
Author: Rahul Ravikumar <rahulrav@google.com>
Date: Tue May 12 11:35:53 2020

Processor needs to check for both foreground and background work.

* Processor needs to check for enqueued foreground and background work,
so there is only ever 1 `WorkerWrapper` per work request.

Fixes:

b/156310133

Test: Existing unit tests pass.
Change-Id: Ib4223565beeb983001bc51d8d45ee417ebf53d62

M work/workmanager/src/main/java/androidx/work/impl/Processor.java

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

ar...@gmail.com <ar...@gmail.com> #10May 13, 2020 05:40AM

Thanks for the quick fix! Is it possible to check a snapshot of some sort with the included change?

ra...@google.com <ra...@google.com> #11May 13, 2020 02:55PM

Yeah we publish our snapshots via https://androidx.dev now. You can try using this:

Add this snippet to your build.gradle file.

allprojects {
    repositories {
        google()
        jcenter()
        maven { url 'https://androidx.dev/snapshots/builds/6490637/artifacts/repository' }
    }
}

Add this to your dependencies block:

dependencies {
    def work_version = '2.4.0-SNAPSHOT'
    implementation "androidx.work:work-runtime:$work_version"
}

ar...@gmail.com <ar...@gmail.com> #12May 13, 2020 03:16PM

Just checked the snapshot — works as expected. Thanks again!

ra...@google.com <ra...@google.com> #13May 13, 2020 03:43PM

Thanks for confirming !