Why is Android Worker finishing successfully and calling onStopped()

Question

My current Android app employs androidx.work:work-runtime:2.2.0-rc01

My Worker code resembles this:-

class SyncWorker(context: Context, workerParams: WorkerParameters) : Worker(context, workerParams) {

    private var syncWorkerResult: Result = Result.success()

    override fun doWork(): Result {

        return syncWorkerResult
    }

    override fun onStopped() {
        Log.i(TAG, "onStopped() $isStopped")

        super.onStopped()

    }
}

As far as I understand the docs for Worker I shouldnt be seeing the following logs:-

2019-08-21 14:25:55.183 22716-22750/com.my.app I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=70a5ff81-1b4b-4604-9d2e-a0b3d342a608, tags={ com.my.app.sync.SyncWorker, SYNC-IN-PROGRESS-TAG } ]
2019-08-21 14:25:55.202 22716-22768/com.my.app I/SyncWorker: onStopped() true

What am I doing wrong?

As my worker is reporting result SUCCESS and success is defined as follows:-

Returns an instance of ListenableWorker.Result that can be used to indicate that the work completed successfully. Any work that depends on this can be executed as long as all of its other dependencies and constraints are met.

This is obviously a defect in the worker code as the above logs shows my worker has completed successfully and then gets stopped, what is there to "STOP" if its already completed successfully?

I do not understand why androidx.work.impl.WorkerWrapper interrupt method is being called for my worker that has completed successfully

/**
 * @hide
 */
@RestrictTo(RestrictTo.Scope.LIBRARY_GROUP)
public void interrupt(boolean cancelled) {
    mInterrupted = true;
    // Resolve WorkerWrapper's future so we do the right thing and setup a reschedule
    // if necessary. mInterrupted is always true here, we don't really care about the return
    // value.
    tryCheckForInterruptionAndResolve();
    if (mInnerFuture != null) {
        // Propagate the cancellations to the inner future.
        mInnerFuture.cancel(true);
    }
    // Worker can be null if run() hasn't been called yet.
    if (mWorker != null) {
        mWorker.stop();
    }
}

Searching through the Android worker source code I have identified this method

/**
 * Stops a unit of work.
 *
 * @param id The work id to stop
 * @return {@code true} if the work was stopped successfully
 */
public boolean stopWork(String id) {
    synchronized (mLock) {
        Logger.get().debug(TAG, String.format("Processor stopping %s", id));
        WorkerWrapper wrapper = mEnqueuedWorkMap.remove(id);
        if (wrapper != null) {
            wrapper.interrupt(false);
            Logger.get().debug(TAG, String.format("WorkerWrapper stopped for %s", id));
            return true;
        }
        Logger.get().debug(TAG, String.format("WorkerWrapper could not be found for %s", id));
        return false;
    }
}

Which calls the wrapper.interrupt(false); method when it removes a worker ID present in the mEnqueuedWorkMap as shown by this debug variables image

Heres the WorkManager logs for when my Worker has its onStopped() method called

2019-08-23 13:02:32.754 21031-21031/com.my.app D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
2019-08-23 13:02:32.754 21031-21031/com.my.app D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
2019-08-23 13:02:32.763 21031-21085/com.my.app D/WM-ForceStopRunnable: Performing cleanup operations.
2019-08-23 13:02:32.884 21031-21085/com.my.app D/WM-ForceStopRunnable: Application was force-stopped, rescheduling.
2019-08-23 13:02:44.219 21031-21098/com.my.app D/WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
2019-08-23 13:02:44.237 21031-21098/com.my.app D/WM-SystemJobScheduler: Scheduling work ID e6a31ec8-a155-4d15-8cf7-af505c70e323 Job ID 0
2019-08-23 13:02:44.244 21031-21098/com.my.app D/WM-GreedyScheduler: Starting work for e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.268 21031-21085/com.my.app D/WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
2019-08-23 13:02:44.302 21031-21085/com.my.app D/WM-SystemJobScheduler: Scheduling work ID 075fb9b3-e19b-463b-89f1-9e737e476d5b Job ID 1
2019-08-23 13:02:44.331 21031-21101/com.my.app D/WM-Processor: Processor: processing e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.723 21031-21031/com.my.app D/WM-WorkerWrapper: Starting work for com.my.app.sync.SyncWorker
2019-08-23 13:02:44.730 21031-21031/com.my.app D/WM-SystemJobService: onStartJob for e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.731 21031-21101/com.my.app D/WM-Processor: Work e6a31ec8-a155-4d15-8cf7-af505c70e323 is already enqueued for processing
2019-08-23 13:02:44.795 21031-21098/com.my.app D/WM-WorkerWrapper: com.my.app.sync.SyncWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-08-23 13:02:44.797 21031-21098/com.my.app I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=e6a31ec8-a155-4d15-8cf7-af505c70e323, tags={ com.my.app.sync.SyncWorker, SYNC-IN-PROGRESS-TAG } ]
2019-08-23 13:02:44.808 21031-21031/com.my.app D/WM-Processor: Processor e6a31ec8-a155-4d15-8cf7-af505c70e323 executed; reschedule = false
2019-08-23 13:02:44.808 21031-21031/com.my.app D/WM-SystemJobService: e6a31ec8-a155-4d15-8cf7-af505c70e323 executed on JobScheduler
2019-08-23 13:02:44.814 21031-21098/com.my.app D/WM-GreedyScheduler: Cancelling work ID e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.828 21031-21085/com.my.app D/WM-Processor: Processor stopping e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.829 21031-21085/com.my.app D/WM-Processor: WorkerWrapper could not be found for e6a31ec8-a155-4d15-8cf7-af505c70e323
2019-08-23 13:02:44.829 21031-21085/com.my.app D/WM-StopWorkRunnable: StopWorkRunnable for e6a31ec8-a155-4d15-8cf7-af505c70e323; Processor.stopWork = false
2019-08-23 13:02:44.856 21031-21098/com.my.app D/WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
2019-08-23 13:02:44.874 21031-21098/com.my.app D/WM-SystemJobScheduler: Scheduling work ID ba72423c-5e4b-425c-aaab-a9a14efaf3f8 Job ID 2
2019-08-23 13:02:44.880 21031-21098/com.my.app D/WM-GreedyScheduler: Starting work for ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.882 21031-21101/com.my.app D/WM-Processor: Processor: processing ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.897 21031-21031/com.my.app D/WM-SystemJobService: onStartJob for ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.900 21031-21031/com.my.app D/WM-WorkerWrapper: Starting work for com.my.app.sync.SyncWorker
2019-08-23 13:02:44.908 21031-21101/com.my.app D/WM-Processor: Work ba72423c-5e4b-425c-aaab-a9a14efaf3f8 is already enqueued for processing
2019-08-23 13:02:44.973 21031-21101/com.my.app D/WM-WorkerWrapper: com.my.app.sync.SyncWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-08-23 13:02:44.975 21031-21101/com.my.app I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=ba72423c-5e4b-425c-aaab-a9a14efaf3f8, tags={ com.my.app.sync.SyncWorker, SYNC-IN-PROGRESS-TAG } ]
2019-08-23 13:02:44.989 21031-21101/com.my.app D/WM-GreedyScheduler: Cancelling work ID ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.996 21031-21085/com.my.app D/WM-Processor: Processor stopping ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.997 21031-21085/com.my.app D/WM-WorkerWrapper: Work interrupted for Work [ id=ba72423c-5e4b-425c-aaab-a9a14efaf3f8, tags={ com.my.app.sync.SyncWorker, SYNC-IN-PROGRESS-TAG } ]

2019-08-23 13:02:44.999 21031-21085/com.my.app I/SyncWorker: onStopped() ba72423c-5e4b-425c-aaab-a9a14efaf3f8 Success {mOutputData=androidx.work.Data@0}

2019-08-23 13:02:44.999 21031-21085/com.my.app D/WM-Processor: WorkerWrapper stopped for ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:44.999 21031-21085/com.my.app D/WM-StopWorkRunnable: StopWorkRunnable for ba72423c-5e4b-425c-aaab-a9a14efaf3f8; Processor.stopWork = true
2019-08-23 13:02:45.045 21031-21031/com.my.app D/WM-Processor: Processor ba72423c-5e4b-425c-aaab-a9a14efaf3f8 executed; reschedule = false
2019-08-23 13:02:45.046 21031-21031/com.my.app D/WM-SystemJobService: ba72423c-5e4b-425c-aaab-a9a14efaf3f8 executed on JobScheduler
2019-08-23 13:02:45.047 21031-21031/com.my.app D/WM-SystemJobService: onStopJob for ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:45.049 21031-21098/com.my.app D/WM-Processor: Processor stopping ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:45.049 21031-21098/com.my.app D/WM-Processor: WorkerWrapper could not be found for ba72423c-5e4b-425c-aaab-a9a14efaf3f8
2019-08-23 13:02:45.049 21031-21098/com.my.app D/WM-StopWorkRunnable: StopWorkRunnable for ba72423c-5e4b-425c-aaab-a9a14efaf3f8; Processor.stopWork = false

UPDATE

This issue occurs when I start a second instance of my the worker immediately after the first instance completes OK. The second instance consistently behaves as shown above. When I add a Thread.sleep(Xms) within the doWork() method I have "some" control over when it occurs as by increasing Xms the issue takes long to appear.

e.g. If I set up a "loop" where I start a new worker each time the pervious worker completes OK, I always see this issue where a subsequent worker instance will both complete SUCCESS and onStopped() is called.

UPDATE II

Heres a code snippet showing how I start the Worker

val refreshDatabaseWork: OneTimeWorkRequest = OneTimeWorkRequest.Builder(SyncWorker::class.java)
        .keepResultsForAtLeast(1L, TimeUnit.NANOSECONDS)
        .addTag(WORK_IN_PROGRESS_TAG).build()
WorkManager.getInstance(application).beginUniqueWork(UNIQUE_WORK_NAME, ExistingWorkPolicy.KEEP, refreshDatabaseWork).enqueue()

I've opened an Issue https://issuetracker.google.com/issues/140055777 with small project that reproduces the issue

Piling

I've created a simple example with the same work-runtime version, but the worker isn't cancelled after completion and onStop() isn't called. Could you add more details to the question, which Android version you tested on? Does the worker request have any constrains? Is the app in the background when the worker is run? How do you test the worker? I see in the log that the app had force-stopped just a few seconds before the worker has been executed. – Applecart

In your simple example try starting a subsequent worker each time the previous instance completes OK and I guarantee you will see my issue. – Piling

Do you mean a workManager.beginWith(firstWork).then(secondWork) sequence? I've tested it a lot and I indeed got onStop() called, but just few times, when I click the button that runs the work many times simultaneously. I've also tried to run just one work as well as to run the next work from doWork() callback, but the result is the same. – Applecart

@ValeriyKatkov I do not chain my work requests. I simply start unique work with KEEP and as soon as the first worker completes OK I immediately start a new Unique work. The second instance almost always finishes OK and has onStopped called, what is odd is that all subsequent Workers finish OK and onStopped() NEVER seems to get called – Piling

Could you attach the code, which creates and enqueues the workers? It would be easier to reproduce the problem. – Applecart

@ValeriyKatkov I have updated my question to include a code snippet of starting the Worker – Piling

Answer 1

I've created a simple example: it just starts the SyncWorker you are provided when a button is clicked. No sequential workers are started, just one worker, I even simplified the worker creation:

val refreshDatabaseWork: OneTimeWorkRequest = OneTimeWorkRequest.Builder(SyncWorker::class.java)
    .build()

WorkManager
    .getInstance(application)
    .enqueue(refreshDatabaseWork)

When I press the button, sometimes the onStopped() is called, sometimes isn't. It's called very rarely, about one time per 20 clicks. Such inconsistent behavior looks like a bug indeed. There is onExecuted() callback method in the Processor implementation that is called each time when the worker finishes:

@Override
public void onExecuted(
    @NonNull final String workSpecId,
    boolean needsReschedule
) {
    synchronized (mLock) {
        mEnqueuedWorkMap.remove(workSpecId);
        Logger.get().debug(TAG, String.format("%s %s executed; reschedule = %s",
                getClass().getSimpleName(), workSpecId, needsReschedule));

        for (ExecutionListener executionListener : mOuterListeners) {
            executionListener.onExecuted(workSpecId, needsReschedule);
        }
    }
}

This method removes the worker wrapper from mEnqueuedWorkMap, but sometimes stopWork() method gets the wrapper before it's removed, and as a result the worker is stopped and onStopped() callback is called.

Also I've noticed that wrapper.interrupt(false) call receives cancelled boolean flag which is false in our case, but the flag is never used by the method, it also looks strange.

I've also tried androidx.work:work-runtime:2.2.0, which is now available, but the result is the same. I think it's better to create a google issue to get an answer from the library developers. The behavior looks very strange, but I can only guess what it's intended to be.

Applecart

I have raised an issue with small project that ALWAYS reproduces the issue. Thanks for your efforts – Piling

Answer 2

The bug is already fixed in version 2.3.0-alpha02 and higher. So I changed my dependencies and I couldn't reproduce it anymore:

implementation "androidx.work:work-runtime:2.3.0-alpha03"

Unwept

Answer 3

Its working as expected as per the documentation which for "Worker" class says:

Once you return from this * method, the Worker is considered to have finished what its doing and will be destroyed. If * you need to do your work asynchronously on a thread of your own choice

And also for onStopped() method of ListenableWorker class.

 /**
     * This method is invoked when this Worker has been told to stop.  This could happen due
     * to an explicit cancellation signal by the user, or because the system has decided to preempt
     * the task.  In these cases, the results of the work will be ignored by WorkManager.  All
     * processing in this method should be lightweight - there are no contractual guarantees about
     * which thread will invoke this call, so this should not be a long-running or blocking
     * operation.
     */

Hathorn

This is not working as designed as from my understanding of the onStopped method the Worker Result will ALWAYS be CANCELLED when onStopped() has been called. In My case you can see the work has finished successfully then onStopped gets called. What is there to "STOP" if the worker has already completed Successfully? My worker is not performing any work, it just completes successfully. I believe this is a bug which occurs when the worker finishes "very/too quickly" – Piling

@Piling why should it be canceled, when you return Result.success()? just don't override fun onStopped and move on. – Topflight

@MartinZeitler It isn't cancelled as shown by the logs and the fact I get a result of SUCESS. I believe theres a bug in the worker code that allows some worker instances to both complete successfully and still have onStopped() called. I have to override onStopped() as when the worker is executing and the user logs out, I need to clear down my Apps database. – Piling