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

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

commit b90079595f33f58fece04026a97faa0d243acdb1
Author: Yuichi Araki <yaraki@google.com>
Date: Wed Sep 18 16:55:49 2019

Change the way to detect mismatch between POJO and query

This fixes cursor mismatch warnings with expandProjection.

Bug: 140759491
Test: QueryMethodProcessorTest
Change-Id: I7659002e5e0d1ef60fc1af2a625c0c36da0664d8

M room/compiler/src/main/kotlin/androidx/room/processor/QueryMethodProcessor.kt
M room/compiler/src/main/kotlin/androidx/room/solver/TypeAdapterStore.kt
M room/compiler/src/main/kotlin/androidx/room/solver/query/result/PojoRowAdapter.kt
M room/compiler/src/test/kotlin/androidx/room/processor/QueryMethodProcessorTest.kt
M room/compiler/src/test/kotlin/androidx/room/testing/TestProcessor.kt

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

https://goto.google.com/android-sha1/b90079595f33f58fece04026a97faa0d243acdb1

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

The following changes were cherrypicked through Coastguard (

https://android-build.googleplex.com/coastguard/)
Release Track: (

https://android-build.googleplex.com/coastguard/dashboard/6093116828680192/#/cherrypickHistory/all)
Created: 2019-10-14 17:23:42.610596+00:00
Changes: aosp/1123258

work-manager-observable.zip

251 KB

Download

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

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

commit bdde5a1a970ddc9007b28de4aa29d60ffa588f08
Author: Yigit Boyar <yboyar@google.com>
Date: Thu Apr 16 16:47:05 2020

Re-factor how errors are dismissed when query is re-written

This CL changes how we handle errors/warnings if query is
re-written.
There was a bug in expandProjection where we would report warnings
for things that Room already fixes automatically (

b/140759491

).
The solution to that problem (I7659002e5e0d1ef60fc1af2a625c0c36da0664d8)
solved it by deferring validating of columns until after re-write
decision is made. Unfortunately, this required changing PojoRowAdapter
to have a dummy mapping until it is validating, make it hard to use
as it does have a non-null mapping which is not useful.

This CL partially reverts that change and instead rely on the log
deferring logic we have in Context. This way, we don't need to break
the stability of PojoRowAdapter while still having the ability to
drop warnings that room fixes. This will also play nicer when we
have different query re-writing options that can use more information
about the query results.

Bug: 153387066
Bug: 140759491
Test: existing tests pass
Change-Id: I2ec967c763d33d7a3ff02c1a13c6953b460d1e5f

M room/compiler/src/main/kotlin/androidx/room/log/RLog.kt
M room/compiler/src/main/kotlin/androidx/room/processor/QueryMethodProcessor.kt
M room/compiler/src/main/kotlin/androidx/room/solver/TypeAdapterStore.kt
M room/compiler/src/main/kotlin/androidx/room/solver/query/result/PojoRowAdapter.kt

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

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

Status: Won't Fix (Not Reproducible)

Also, to see the logs I am talking about, you might want to enable verbose logging. For more information look at https://developer.android.com/topic/libraries/architecture/workmanager/advanced/custom-configuration and use Log.DEBUG.

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

If you have more information, I can reopen the bug.

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

Yep, the verbose logging was enabled to produce logs in the initial comment.

Video with the reproducible scenario using the sample above.
Made new logs, attaching.

worker.txt

15 KB

View

Download

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

Assigned to ra...@google.com.

Okay, I think I know what might be going on. Thanks for the logs, that really helped.

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 !