为什么Android Worker成功完成并调用onStopped()函数

Question

我的当前Android应用程序使用androidx.work:work-runtime:2.2.0-rc01

我的Worker代码类似于这样：

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

    }
}

据我理解，Worker 的文档中不应该出现以下日志：-

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

我应该做些什么才能正确操作？

当我的工作人员报告结果为“成功”，而且成功的定义如下：

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.

这显然是工作代码中的缺陷，因为上面的日志显示我的工作程序已经成功完成，然后被停止了。如果已经成功完成，还有什么可以“停止”的呢？

我不明白为什么会对已经成功完成的我的工作程序调用androidx.work.impl.WorkerWrapper的中断方法。

/**
 * @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();
    }
}

我搜索了Android worker源代码，找到了这个方法

/**
 * 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;
    }
}

当它从mEnqueuedWorkMap中移除一个存在的工作 ID 时，调用wrapper.interrupt(false);方法，如此调试变量图像所示。

以下是我的 Worker 调用 onStopped() 方法时的 WorkManager 日志

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

更新

当我在第一个实例完成后立即启动第二个实例时，就会出现此问题。第二个实例始终表现如上所示。当我在doWork()方法中添加Thread.sleep(Xms)时，我可以“有些”控制它何时出现，因为增加Xms会使问题需要更长时间才能出现。

例如，如果我设置一个“循环”，每次在前一个工作程序完成后启动一个新的工作程序，我总是看到这个问题，其中后续的工作程序实例将同时完成SUCCESS和调用onStopped()。

更新 II

以下是代码片段，显示了我如何启动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()

我已经提出了一个问题https://issuetracker.google.com/issues/140055777，并提供了一个能重现该问题的小项目。

- Hector

---

我已经创建了一个简单的示例，使用相同的work-runtime版本，但是工作程序在完成后没有被取消，并且onStop()也没有被调用。您能否在问题中添加更多细节，例如您测试的Android版本？工作程序请求是否有任何限制？当工作程序运行时，应用程序是否在后台运行？您如何测试工作程序？我在日志中看到应用程序在工作程序执行前仅停止了几秒钟。 - Valeriy Katkov

在你的简单示例中，尝试在前一个实例完成后每次启动一个后续工作程序，我保证你会看到我的问题。 - Hector

你是说一个 workManager.beginWith(firstWork).then(secondWork) 的顺序吗？我测试了很多次，确实会调用 onStop()，但仅在我同时点击运行工作的按钮几次时才会出现。我也尝试过只运行一个工作，或者从 doWork() 回调中运行下一个工作，但结果是一样的。 - Valeriy Katkov

@ValeriyKatkov 我不会链接我的工作请求。我只是使用KEEP开始独特的工作，一旦第一个工作者完成OK，我立即开始新的独特工作。第二个实例几乎总是完成OK并调用onStopped，但奇怪的是所有后续的工作者都完成OK，而onStopped()似乎从未被调用。 - Hector

你能附上创建和排队工作人员的代码吗？这样更容易复现问题。 - Valeriy Katkov

@ValeriyKatkov，我已更新我的问题，并包含了一个启动Worker的代码片段。 - Hector

Answer 1

我已经创建了一个简单的示例：当点击按钮时，它只会启动提供给您的SyncWorker。没有启动顺序工作程序，只有一个工作程序，我甚至简化了工作程序的创建方式：

我创建了一个简单的示例：当点击按钮时，它只会启动提供给您的SyncWorker。没有启动顺序工作程序，只有一个工作程序，我甚至简化了工作程序的创建方式：

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

WorkManager
    .getInstance(application)
    .enqueue(refreshDatabaseWork)

当我按下按钮时，有时会调用onStopped()方法，有时不会。它很少被调用，大约每20次点击才会调用一次。这种不一致的行为确实看起来像是一个bug。在Processor实现中有一个onExecuted()回调方法，每当worker完成时都会被调用。

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

该方法从`mEnqueuedWorkMap`中移除工作包装器，但有时候`stopWork()`方法会在它被移除之前获取该包装器，因此工作会停止并调用`onStopped()`回调。

此外，我注意到`wrapper.interrupt(false)`调用收到了一个布尔值标志`cancelled`，在我们的情况下为false，但是该标志从未被该方法使用，这看起来也很奇怪。

我还尝试了现在可用的`androidx.work:work-runtime:2.2.0`，但结果是相同的。我认为最好创建一个Google issue来从库开发人员那里得到答案。这种行为看起来非常奇怪，但我只能猜测它的预期目的是什么。

最初的回答：该方法删除工作包装器，但由于某些原因，有时`stopWork()`方法会在包装器被移除之前获得它，导致工作被停止并调用`onStopped()`回调。此外，`wrapper.interrupt（false）`调用收到了一个布尔标志`cancelled`，但是该标志从未被使用过，这似乎很奇怪。 尝试使用新版本的库没有解决问题，建议向Google提出问题以获得更多信息。

- Valeriy Katkov

---

我已经提出了一个小项目的问题，该问题始终会复现。感谢您的努力。 - Hector

Answer 2

错误已在版本2.3.0-alpha02及更高版本中修复。 因此，我更改了我的依赖项，无法再次重现该错误：

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

- Andrew

Answer 3

根据“Worker”类的文档，它按预期工作：

一旦从此方法返回，Worker被认为已完成其工作并将被销毁。如果您需要在自己选择的线程上异步执行工作

还有ListenableWorker类的onStopped()方法。

 /**
     * 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.
     */

- Manish Patiyal

---

根据我对onStopped方法的理解，当调用onStopped()时，Worker Result将始终为CANCELLED，因此这不是按设计工作的。在我的情况下，您可以看到工作已经成功完成，然后调用了onStopped。如果worker已经成功完成，那还有什么需要“STOP”呢？我的worker没有执行任何工作，它只是成功地完成了。我认为这是一个bug，当worker“非常/太快”完成时会发生。 - Hector

@Hector为什么要取消，当你返回Result.success()时？只需不覆盖fun onStopped并继续即可。 - Martin Zeitler

@MartinZeitler，根据日志和成功的结果，它并没有被取消。我相信工作代码中存在一个错误，允许某些工作实例成功完成并仍然调用onStopped()。当工作正在执行且用户注销时，我必须覆盖onStopped()，以清除我的应用程序数据库。 - Hector