android - 为什么 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

我做错了什么？

因为我的工作人员正在报告结果 SUCCESS 并且成功的定义如下:-

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.

这显然是 worker 代码中的一个缺陷，因为上面的日志显示我的 worker 已成功完成然后被停止，如果它已经成功完成，还有什么可以“停止”？

我不明白为什么我的 worker 会调用 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 中存在的 worker 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 问题需要很长时间才能出现.

例如如果我设置一个“循环”，每次上一个工作人员完成 OK 时我都会启动一个新工作人员，我总是会看到这个问题，其中后续工作人员实例将同时完成 SUCCESS 和 onStopped() 被调用。

更新二

这是一个代码 fragment ，展示了我如何启动 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使用重现问题的小项目

Answer 1

我创建了一个简单的示例:它只是在单击按钮时启动为您提供的 SyncWorker。没有启动连续的worker，只有一个worker，我什至简化了worker的创建:

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

WorkManager
    .getInstance(application)
    .enqueue(refreshDatabaseWork)

当我按下按钮时，有时会调用 onStopped()，有时不会。它很少被调用，大约每 20 次点击一次。这种不一致的行为看起来确实像一个错误。 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 bool 标志，这在我们的例子中是 false，但该标志从未被该方法使用，它看起来也很奇怪。

我也试过androidx.work:work-runtime:2.2.0，现在可以用了，但是结果是一样的。我认为最好创建一个谷歌问题来从库开发人员那里得到答案。这种行为看起来很奇怪，但我只能猜测它的 Intent 。