JobIntentService runs again after exiting Doze mode

Question

I'm running the following JobIntentService example from Google on Nexus 5X (Android 8.0)

public class SimpleJobIntentService extends JobIntentService {
   /**
    * Unique job ID for this service.
    */
   static final int JOB_ID = 1000;

  /**
   * Convenience method for enqueuing work in to this service.
   */
  static void enqueueWork(Context context, Intent work) {
    enqueueWork(context, SimpleJobIntentService.class, JOB_ID, work);
  }

  @Override
  protected void onHandleWork(Intent intent) {
    // We have received work to do.  The system or framework is already
    // holding a wake lock for us at this point, so we can just go.
    Log.i("SimpleJobIntentService", "Executing work: " + intent);
    String label = intent.getStringExtra("label");
    if (label == null) {
        label = intent.toString();
    }
    toast("Executing: " + label);
    for (int i = 0; i < 5; i++) {
        Log.i("SimpleJobIntentService", "Running service " + (i + 1)
                + "/5 @ " + SystemClock.elapsedRealtime());
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
        }
    }
    Log.i("SimpleJobIntentService", "Completed service @ " + SystemClock.elapsedRealtime());
 }

 @Override
 public void onDestroy() {
    super.onDestroy();
    Log.i(getClass().toString(), "JobIntentService destroyed");
 }
}

The service is added to AndroidManifest.xml as shown below.

<service android:name=".SimpleJobIntentService "
             android:exported="true"
             android:permission="android.permission.BIND_JOB_SERVICE"/>

Under normal condition, the service runs as expected, cycles through the loop before it exits.

Now I ran the following adb command to test Doze mode

adb shell dumpsys deviceidle force-idle

EDIT Here are the logs from when the service has started and then forced into Doze mode

12-14 12:11:18.587 24357-24396/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:11:18.588 24357-24396/<package-name> I/SimpleJobIntentService: Running service 2/5 @ 510158341
    12-14 12:11:18.588 24357-24396/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:11:19.629 24357-24396/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:11:19.629 24357-24396/<package-name> I/SimpleJobIntentService: Running service 3/5 @ 510159383
    12-14 12:11:19.629 24357-24396/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:11:20.593 24357-24357/<package-name> I/SimpleJobIntentService: JobIntentService destroyed
    12-14 12:11:20.670 24357-24396/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:11:20.670 24357-24396/<package-name> I/SimpleJobIntentService: Running service 4/5 @ 510160424
    12-14 12:11:20.670 24357-24396/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:11:21.708 24357-24396/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:11:21.709 24357-24396/<package-name> I/SimpleJobIntentService: Running service 5/5 @ 510161463
    12-14 12:11:21.709 24357-24396/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:11:22.750 24357-24396/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:11:22.750 24357-24396/<package-name> I/SimpleJobIntentService: Completed service @ 510162504

It clearly calls onDestroy(), but continues to cycle through the loop a bit later. I understand the system exits Doze mode periodically to let apps perform deferred activities. Once the service is finished under Doze mode, the following adb command is run to exit Doze mode

adb shell dumpsys deviceidle unforce

EDIT Here are the logs when the aforementioned adb command is executed

12-14 12:15:25.244 24357-24481/<package-name> I/class SimpleJobIntentService : work started
    12-14 12:15:25.244 24357-24481/<package-name> I/SimpleJobIntentService: Running service 1/5 @ 510404998
    12-14 12:15:25.244 24357-24481/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:15:26.285 24357-24481/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:15:26.285 24357-24481/<package-name> I/SimpleJobIntentService: Running service 2/5 @ 510406039
    12-14 12:15:26.285 24357-24481/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:15:27.326 24357-24481/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:15:27.327 24357-24481/<package-name> I/SimpleJobIntentService: Running service 3/5 @ 510407080
    12-14 12:15:27.327 24357-24481/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:15:28.367 24357-24481/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:15:28.368 24357-24481/<package-name> I/SimpleJobIntentService: Running service 4/5 @ 510408121
    12-14 12:15:28.368 24357-24481/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:15:29.408 24357-24481/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:15:29.409 24357-24481/<package-name> I/SimpleJobIntentService: Running service 5/5 @ 510409163
    12-14 12:15:29.409 24357-24481/<package-name> I/SimpleJobIntentService: before sleep
    12-14 12:15:30.446 24357-24481/<package-name> I/SimpleJobIntentService: after sleep
    12-14 12:15:30.446 24357-24481/<package-name> I/SimpleJobIntentService: Completed service @ 510410200
    12-14 12:15:30.457 24357-24357/<package-name> I/SimpleJobIntentService: JobIntentService destroyed

JobIntentService is executed again though it was finished earlier. Is this an acceptable behaviour? Or am I missing something? Help me understand the working of JobIntentService

Could you perhaps edit your question with a timeline of events? For example, perhaps you could show your LogCat output, with indicators of where in there you executed those two `adb shell` commands. I can think of a possible bug in `JobIntentService` here, based on how I am interpreting your symptoms, but I am concerned that perhaps I am mis-interpreting your sequence of events. — CommonsWare, Dec 14 '17 at 12:06
@CommonsWare Thanks for the prompt reply! Please find logcat outputs when both adb commands are executed. Please share your thoughts on what could go wrong. — Renjith, Dec 14 '17 at 12:20
My guess is that the act of Doze mode starting causes the underlying `JobService` to mark this job as having not been completed, even though the background thread on which `onHandleWork()` runs keeps going. That triggers the job to start again after Doze mode ends. — CommonsWare, Dec 14 '17 at 12:45
Could we use isStopped() method on JobIntentService to get away with this behaviour? — Renjith, Dec 14 '17 at 12:56
I'm a newbie to JobIntentService. On the javadocs, there is a method called isStopped() which returns true when JobScheduler has decided to stop this job. Could we use this method to stop running the service again? Correct me if I'm wrong. What do you think would be the best way to tackle this problem? — Renjith, Dec 14 '17 at 13:14
You could override `onStopCurrentWork()` or monitor `isStopped()` to control what you are doing in your background thread. The job will be restarted regardless, but you could avoid some of the duplicate work. — CommonsWare, Dec 14 '17 at 13:19
Looks like this is a bug on JobIntentService. Where should I raise it? — Renjith, Dec 14 '17 at 13:21
The issue tracker for public Google projects, including Android, is at: https://issuetracker.google.com/ — CommonsWare, Dec 14 '17 at 13:24

JobIntentService runs again after exiting Doze mode

0 Answers0