Immediate long-running RxJava work makes the notification to be shown forever [150553362]

Duplicate

of 150553353

Bug

Status Update

No update yet.

Description

ar...@gmail.com

created issue #1

Mar 2, 2020 06:52AM

* Artifact: `androidx.work:work-rxjava2:2.3.2`
* 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. Run the application.

```kotlin
private fun scheduleForegroundWork() {
val workRequest = OneTimeWorkRequest.Builder(ForegroundWorker::class.java).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()
}
.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_upload)
.setContentText("Hello there from the foreground work")
.build()
}
```

* Actual behavior: the notification is shown but is never dismissed — not that the `Result` is provided immediately.
* Expected behavior: the notification is hidden.

The issue can be mitigated via adding a delay before producing a result:

```diff
}
+ .delay(1, TimeUnit.SECONDS)
.map { Result.success() }
```

I suspect that the foreground service is cancelled all the time when a result is provided, maybe there is a race somewhere.

Comments

ra...@google.com <ra...@google.com> #2Mar 2, 2020 09:35PM

Can you please turn on debug logging using https://developer.android.com/topic/libraries/architecture/workmanager/advanced/custom-configuration.

Set Log level to DEBUG. Send us the logs.

ar...@gmail.com <ar...@gmail.com> #3Mar 3, 2020 05:37AM

Sure thing!

Here we go:

D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
D/WM-ForceStopRunnable: Performing cleanup operations.
D/WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
D/WM-SystemJobScheduler: Scheduling work ID 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd Job ID 74
D/WM-GreedyScheduler: Starting work for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: Processor: processing 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-WorkerWrapper: Starting work for REDACTED.Application$ForegroundWorker
I/WM-Processor: Moving WorkSpec (2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd) to the foreground
D/WM-WorkerWrapper: REDACTED.Application$ForegroundWorker returned a Success {mOutputData=Data {}} result.
I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd, tags={ REDACTED.Application$ForegroundWorker } ]
D/WM-Processor: No more foreground work. SystemForegroundService is already stopped
D/WM-GreedyScheduler: Cancelling work ID 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: Processor stopping background work 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: WorkerWrapper could not be found for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-StopWorkRunnable: StopWorkRunnable for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd; Processor.stopWork = false
D/WM-SystemJobService: onStartJob for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: Processor: processing 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-WorkerWrapper: Status for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd is SUCCEEDED; not doing any work
D/WM-WorkerWrapper: REDACTED.Application$ForegroundWorker is not in ENQUEUED state. Nothing more to do.
I/WM-SystemFgDispatcher: Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=REDACTED/androidx.work.impl.foreground.SystemForegroundService (has extras) }
D/WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd, notificationType: 0)
D/WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd, notificationType: 0)
D/WM-Processor: Processor 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd executed; reschedule = false
D/WM-SystemJobService: 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd executed on JobScheduler
D/WM-SystemJobService: onStopJob for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: Processor 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd executed; reschedule = false
D/WM-SystemJobService: 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd executed on JobScheduler
D/WM-Processor: Processor stopping background work 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-Processor: WorkerWrapper could not be found for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd
D/WM-StopWorkRunnable: StopWorkRunnable for 2d2cab8b-beb4-45c4-8d04-9d85e5aa4ecd; Processor.stopWork = false

ra...@google.com <ra...@google.com> Mar 3, 2020 06:47AM

Status: Duplicate of

150553353

ar...@gmail.com <ar...@gmail.com> #4Mar 20, 2020 07:03AM

Just tried 2.3.4 which claims to resolve the issue 150553353 but the issue described here is not resolved (despite this one marked as a duplicate for some reason).

Logs:

D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
D/WM-ForceStopRunnable: Performing cleanup operations.
D/WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
D/WM-SystemJobScheduler: Scheduling work ID 2d44c9de-0e3c-4518-b960-c282ba924638 Job ID 299
D/WM-GreedyScheduler: Starting work for 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: Processor: processing 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-WorkerWrapper: Starting work for REDACTED.Application$ForegroundWorker
I/WM-Processor: Moving WorkSpec (2d44c9de-0e3c-4518-b960-c282ba924638) to the foreground
D/WM-WorkerWrapper: REDACTED.Application$ForegroundWorker returned a Success {mOutputData=Data {}} result.
I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=2d44c9de-0e3c-4518-b960-c282ba924638, tags={ REDACTED.Application$ForegroundWorker } ]
D/WM-Processor: No more foreground work. SystemForegroundService is already stopped
D/WM-GreedyScheduler: Cancelling work ID 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: Processor stopping background work 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: WorkerWrapper could not be found for 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-StopWorkRunnable: StopWorkRunnable for 2d44c9de-0e3c-4518-b960-c282ba924638; Processor.stopWork = false
D/WM-SystemJobService: onStartJob for 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: Processor: processing 2d44c9de-0e3c-4518-b960-c282ba924638
I/WM-SystemFgDispatcher: Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=REDACTED/androidx.work.impl.foreground.SystemForegroundService (has extras) }
D/WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 2d44c9de-0e3c-4518-b960-c282ba924638, notificationType: 0)
D/WM-SystemFgDispatcher: Notifying with (id: 42, workSpecId: 2d44c9de-0e3c-4518-b960-c282ba924638, notificationType: 0)
D/WM-WorkerWrapper: Status for 2d44c9de-0e3c-4518-b960-c282ba924638 is SUCCEEDED; not doing any work
D/WM-WorkerWrapper: REDACTED.Application$ForegroundWorker is not in ENQUEUED state. Nothing more to do.
D/WM-Processor: Processor 2d44c9de-0e3c-4518-b960-c282ba924638 executed; reschedule = false
D/WM-SystemJobService: 2d44c9de-0e3c-4518-b960-c282ba924638 executed on JobScheduler
D/WM-SystemJobService: onStopJob for 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: Processor stopping background work 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-Processor: WorkerWrapper could not be found for 2d44c9de-0e3c-4518-b960-c282ba924638
D/WM-StopWorkRunnable: StopWorkRunnable for 2d44c9de-0e3c-4518-b960-c282ba924638; Processor.stopWork = false
D/WM-Processor: Processor 2d44c9de-0e3c-4518-b960-c282ba924638 executed; reschedule = false
D/WM-SystemJobService: 2d44c9de-0e3c-4518-b960-c282ba924638 executed on JobScheduler

ra...@google.com <ra...@google.com> #5Mar 20, 2020 07:02PM

We marked it duplicate because if your Worker ran long enough, it would trigger the other bug which had a similar sticky Notification. However, you have a combination of problems one of which we fixed in 2.3.4.

Your RxWorker implementation has a bug. You are calling setForegroundAsync(...), but you are not waiting for completion. setForegroundAsync(...) returns a ListenableFuture that you should be waiting for.

What happens is that your Worker running on a dedicated Executor is racing against setForegroundAsync() and in some cases it ends up being called after your Worker returns a Result.success().

Message last modified on Mar 20, 2020 07:13PM

ar...@gmail.com <ar...@gmail.com> #6Mar 20, 2020 08:26PM

Yep, the call does return the Future but get is called on it. I was under an impression that it blocks the execution until the Future delivers a result. Isn’t that the case here?

ra...@google.com <ra...@google.com> #7Mar 20, 2020 08:46PM

Yes, that is how you should be blocking on the ListenableFuture. When I last looked at your code, you were not doing it correctly.

ar...@gmail.com <ar...@gmail.com> #8Mar 21, 2020 04:48PM

Sorry, I’m confused. The sample in the opening comment has this:

Single
    .fromCallable {
        setForegroundAsync(ForegroundInfo(42, createNotification())).get().toOptional()
    }
    .map { Result.success() }

What it does (from my POV):

changes the worker to be foregrounded using setForegroundAsync;
blocks until the setForegroundAsync ListenableFuture provides it;
emits a successful worker result.

Is there a bug in this implementation? I’m confused because #5 states that there is a bug in the sample but #7 confirms that blocking via get() should work.

ra...@google.com <ra...@google.com> #9Mar 23, 2020 03:21PM

Are you calling setForegroundAsync() in your constructor ?

ar...@gmail.com <ar...@gmail.com> #10Mar 23, 2020 03:34PM

Nope, the sample above calls it in the createWork method.

The official sample does it in the doWork. https://developer.android.com/topic/libraries/architecture/workmanager/advanced/long-running

ra...@google.com <ra...@google.com> #11Mar 23, 2020 05:23PM

WorkManager has multiple schedulers (in-process, JobScheduler, the AlarmManager based scheduler etc.).

What's happening in your case, is that the in-process Scheduler is picking up the RxWorker implementation and your Worker completes successfully by returning an instance of Result.

However, around the same time JobScheduler also wants to execute the same WorkRequest. For us to be able to de-dupe the execution, we create an instance of the Worker and check to see if it needs to be scheduled. As your logs point out, we correctly identify that the Worker is done.

D/WM-WorkerWrapper: Status for 2d44c9de-0e3c-4518-b960-c282ba924638 is SUCCEEDED; not doing any work
D/WM-WorkerWrapper: REDACTED.Application$ForegroundWorker is not in ENQUEUED state. Nothing more to do.

However in your RxWorker implementation the side-effect of calling setForegroundAsync() in createWork() is that a call to notify() happens despite your Worker not having to run at all. The reason this happens is because there is no easy way for you to be able to tell that the Worker actually started running (because that happens only when an underlying subscription is created).

We made this a lot more ergonomic in 2.4.0-alpha02 (soon to be released). Attempts to notify are ignored when a Worker is done.

In your RxWorker for a workaround around the notifications, you could do something like:

Single
    .fromCallable {
        val workInfo = WorkManager.getInstance(context).getWorkInfoById(getId()).get()
        if (workInfo != null && !workInfo.getState().isFinished()) {
          setForegroundAsync(ForegroundInfo(42, createNotification())).get().toOptional()
        }
    }
    .map { Result.success() }

Going forward, we automatically handle this for you.

ar...@gmail.com <ar...@gmail.com> #12Mar 23, 2020 06:32PM

Awesome, thanks for the detailed explanation! I’ll look forward to the 2.4.0.

Sorry for bothering you with this. It was a bit weird to follow the documentation and still having an issue.

ra...@google.com <ra...@google.com> #13Mar 23, 2020 06:46PM

No problem. In 2.4.0-alpha02 you can just call setForegroundAsync() and not have to worry about calling get(). We do the rest :)