remove possible JobScheduler race in cancel()

Client can jobFinished() before getting a cancel msg.
1) Do better clean up of JobServiceContext after client jobFinished()
to remove superfluous MSG_CANCELs
2) When processing MSG_CANCEL check whether the context is still active
3) Do JobServiceContext cleanup before calling back to JobSchedulerService
Client can get a cancel msg even after calling jobFinished() (opposite to above)
1) explicitly check whether there are any MSG_CALLBACKs in the queue before
processing a MSG_CANCEL. If there are we can throw away the cancel.

Bug: 16547638
Change-Id: I90644586c7895a9ce97de752a5d657faf7f74b78

4 files changed, 135 insertions, 44 deletions

diff --git a/core/java/android/app/job/JobInfo.java b/core/java/android/app/job/JobInfo.java
index 70f6966..936e205 100644
--- a/core/java/android/app/job/JobInfo.java
+++ b/core/java/android/app/job/JobInfo.java
@@ -266,6 +266,11 @@ public class JobInfo implements Parcelable {
         }
     };
 
+    @Override
+    public String toString() {
+        return "(job:" + jobId + "/" + service.flattenToShortString() + ")";
+    }
+
     /** Builder class for constructing {@link JobInfo} objects. */
     public static final class Builder {
         private int mJobId;
diff --git a/services/core/java/com/android/server/job/JobSchedulerService.java b/services/core/java/com/android/server/job/JobSchedulerService.java
index 587f596..9ac90dc 100644
--- a/services/core/java/com/android/server/job/JobSchedulerService.java
+++ b/services/core/java/com/android/server/job/JobSchedulerService.java
@@ -224,6 +224,9 @@ public class JobSchedulerService extends com.android.server.SystemService
     }
 
     private void cancelJobLocked(JobStatus cancelled) {
+        if (DEBUG) {
+            Slog.d(TAG, "Cancelling: " + cancelled);
+        }
         // Remove from store.
         stopTrackingJob(cancelled);
         // Remove from pending queue.
@@ -447,8 +450,7 @@ public class JobSchedulerService extends com.android.server.SystemService
         }
         if (!stopTrackingJob(jobStatus)) {
             if (DEBUG) {
-                Slog.e(TAG, "Error removing job: could not find job to remove. Was job " +
-                        "removed while executing?");
+                Slog.d(TAG, "Could not find job to remove. Was job removed while executing?");
             }
             return;
         }
@@ -611,7 +613,7 @@ public class JobSchedulerService extends com.android.server.SystemService
                         final JobStatus running = jsc.getRunningJob();
                         if (running != null && running.matches(nextPending.getUid(),
                                 nextPending.getJobId())) {
-                            // Already running this tId for this uId, skip.
+                            // Already running this job for this uId, skip.
                             availableContext = null;
                             break;
                         }
@@ -691,7 +693,7 @@ public class JobSchedulerService extends com.android.server.SystemService
         @Override
         public int schedule(JobInfo job) throws RemoteException {
             if (DEBUG) {
-                Slog.d(TAG, "Scheduling job: " + job);
+                Slog.d(TAG, "Scheduling job: " + job.toString());
             }
             final int pid = Binder.getCallingPid();
             final int uid = Binder.getCallingUid();
diff --git a/services/core/java/com/android/server/job/JobServiceContext.java b/services/core/java/com/android/server/job/JobServiceContext.java
index ee45833..5297911 100644
--- a/services/core/java/com/android/server/job/JobServiceContext.java
+++ b/services/core/java/com/android/server/job/JobServiceContext.java
@@ -34,7 +34,6 @@ import android.os.RemoteException;
 import android.os.SystemClock;
 import android.os.UserHandle;
 import android.os.WorkSource;
-import android.util.Log;
 import android.util.Slog;
 
 import com.android.internal.annotations.GuardedBy;
@@ -45,8 +44,22 @@ import com.android.server.job.controllers.JobStatus;
 import java.util.concurrent.atomic.AtomicBoolean;
 
 /**
- * Handles client binding and lifecycle of a job. A job will only execute one at a time on an
- * instance of this class.
+ * Handles client binding and lifecycle of a job. Jobs execute one at a time on an instance of this
+ * class.
+ *
+ * There are two important interactions into this class from the
+ * {@link com.android.server.job.JobSchedulerService}. To execute a job and to cancel a job.
+ * - Execution of a new job is handled by the {@link #mAvailable}. This bit is flipped once when a
+ * job lands, and again when it is complete.
+ * - Cancelling is trickier, because there are also interactions from the client. It's possible
+ * the {@link com.android.server.job.JobServiceContext.JobServiceHandler} tries to process a
+ * {@link #MSG_CANCEL} after the client has already finished. This is handled by having
+ * {@link com.android.server.job.JobServiceContext.JobServiceHandler#handleCancelH} check whether
+ * the context is still valid.
+ * To mitigate this, tearing down the context removes all messages from the handler, including any
+ * tardy {@link #MSG_CANCEL}s. Additionally, we avoid sending duplicate onStopJob()
+ * calls to the client after they've specified jobFinished().
+ *
  */
 public class JobServiceContext extends IJobCallback.Stub implements ServiceConnection {
     private static final boolean DEBUG = true;
@@ -60,7 +73,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
     private static final long OP_TIMEOUT_MILLIS = 8 * 1000;
 
     private static final String[] VERB_STRINGS = {
-            "VERB_STARTING", "VERB_EXECUTING", "VERB_STOPPING", "VERB_PENDING"
+            "VERB_BINDING", "VERB_STARTING", "VERB_EXECUTING", "VERB_STOPPING"
     };
 
     // States that a job occupies while interacting with the client.
@@ -101,7 +114,10 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
     IJobService service;
 
     private final Object mLock = new Object();
-    /** Whether this context is free. */
+    /**
+     * Whether this context is free. This is set to false at the start of execution, and reset to
+     * true when execution is complete.
+     */
     @GuardedBy("mLock")
     private boolean mAvailable;
     /** Track start time. */
@@ -164,9 +180,15 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         }
     }
 
-    /** Used externally to query the running job. Will return null if there is no job running. */
+    /**
+     * Used externally to query the running job. Will return null if there is no job running.
+     * Be careful when using this function, at any moment it's possible that the job returned may
+     * stop executing.
+     */
     JobStatus getRunningJob() {
-        return mRunningJob;
+        synchronized (mLock) {
+            return mRunningJob;
+        }
     }
 
     /** Called externally when a job that was scheduled for execution should be cancelled. */
@@ -242,10 +264,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         mCallbackHandler.obtainMessage(MSG_SERVICE_BOUND).sendToTarget();
     }
 
-    /**
-     * If the client service crashes we reschedule this job and clean up.
-     * @param name The concrete component name of the service whose
-     */
+    /** If the client service crashes we reschedule this job and clean up. */
     @Override
     public void onServiceDisconnected(ComponentName name) {
         mCallbackHandler.obtainMessage(MSG_SHUTDOWN_EXECUTION).sendToTarget();
@@ -312,7 +331,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                     closeAndCleanupJobH(true /* needsReschedule */);
                     break;
                 default:
-                    Log.e(TAG, "Unrecognised message: " + message);
+                    Slog.e(TAG, "Unrecognised message: " + message);
             }
         }
 
@@ -337,7 +356,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 scheduleOpTimeOut();
                 service.startJob(mParams);
             } catch (RemoteException e) {
-                Log.e(TAG, "Error sending onStart message to '" +
+                Slog.e(TAG, "Error sending onStart message to '" +
                         mRunningJob.getServiceComponent().getShortClassName() + "' ", e);
             }
         }
@@ -359,6 +378,9 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                         return;
                     }
                     if (mCancelled.get()) {
+                        if (DEBUG) {
+                            Slog.d(TAG, "Job cancelled while waiting for onStartJob to complete.");
+                        }
                         // Cancelled *while* waiting for acknowledgeStartMessage from client.
                         handleCancelH();
                         return;
@@ -366,7 +388,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                     scheduleOpTimeOut();
                     break;
                 default:
-                    Log.e(TAG, "Handling started job but job wasn't starting! Was "
+                    Slog.e(TAG, "Handling started job but job wasn't starting! Was "
                             + VERB_STRINGS[mVerb] + ".");
                     return;
             }
@@ -396,16 +418,31 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
          *                    {@link #onServiceConnected(android.content.ComponentName, android.os.IBinder)}
          *     _STARTING   -> Mark as cancelled and wait for
          *                    {@link JobServiceContext#acknowledgeStartMessage(int, boolean)}
-         *     _EXECUTING  -> call {@link #sendStopMessageH}}.
+         *     _EXECUTING  -> call {@link #sendStopMessageH}}, but only if there are no callbacks
+         *                      in the message queue.
          *     _ENDING     -> No point in doing anything here, so we ignore.
          */
         private void handleCancelH() {
+            if (mRunningJob == null) {
+                if (DEBUG) {
+                    Slog.d(TAG, "Trying to process cancel for torn-down context, ignoring.");
+                }
+                return;
+            }
+            if (JobSchedulerService.DEBUG) {
+                Slog.d(TAG, "Handling cancel for: " + mRunningJob.getJobId() + " "
+                        + VERB_STRINGS[mVerb]);
+            }
             switch (mVerb) {
                 case VERB_BINDING:
                 case VERB_STARTING:
                     mCancelled.set(true);
                     break;
                 case VERB_EXECUTING:
+                    if (hasMessages(MSG_CALLBACK)) {
+                        // If the client has called jobFinished, ignore this cancel.
+                        return;
+                    }
                     sendStopMessageH();
                     break;
                 case VERB_STOPPING:
@@ -419,8 +456,8 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
 
         /** Process MSG_TIMEOUT here. */
         private void handleOpTimeoutH() {
-            if (Log.isLoggable(JobSchedulerService.TAG, Log.DEBUG)) {
-                Log.d(TAG, "MSG_TIMEOUT of " +
+            if (JobSchedulerService.DEBUG) {
+                Slog.d(TAG, "MSG_TIMEOUT of " +
                         mRunningJob.getServiceComponent().getShortClassName() + " : "
                         + mParams.getJobId());
             }
@@ -431,28 +468,28 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                     // Client unresponsive - wedged or failed to respond in time. We don't really
                     // know what happened so let's log it and notify the JobScheduler
                     // FINISHED/NO-RETRY.
-                    Log.e(TAG, "No response from client for onStartJob '" +
-                            mRunningJob.getServiceComponent().getShortClassName() + "' tId: "
+                    Slog.e(TAG, "No response from client for onStartJob '" +
+                            mRunningJob.getServiceComponent().getShortClassName() + "' jId: "
                             + jobId);
                     closeAndCleanupJobH(false /* needsReschedule */);
                     break;
                 case VERB_STOPPING:
                     // At least we got somewhere, so fail but ask the JobScheduler to reschedule.
-                    Log.e(TAG, "No response from client for onStopJob, '" +
-                            mRunningJob.getServiceComponent().getShortClassName() + "' tId: "
+                    Slog.e(TAG, "No response from client for onStopJob, '" +
+                            mRunningJob.getServiceComponent().getShortClassName() + "' jId: "
                             + jobId);
                     closeAndCleanupJobH(true /* needsReschedule */);
                     break;
                 case VERB_EXECUTING:
                     // Not an error - client ran out of time.
-                    Log.i(TAG, "Client timed out while executing (no jobFinished received)." +
+                    Slog.i(TAG, "Client timed out while executing (no jobFinished received)." +
                             " sending onStop. "  +
-                            mRunningJob.getServiceComponent().getShortClassName() + "' tId: "
+                            mRunningJob.getServiceComponent().getShortClassName() + "' jId: "
                             + jobId);
                     sendStopMessageH();
                     break;
                 default:
-                    Log.e(TAG, "Handling timeout for an unknown active job state: "
+                    Slog.e(TAG, "Handling timeout for an unknown active job state: "
                             + mRunningJob);
                     return;
             }
@@ -465,7 +502,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         private void sendStopMessageH() {
             mCallbackHandler.removeMessages(MSG_TIMEOUT);
             if (mVerb != VERB_EXECUTING) {
-                Log.e(TAG, "Sending onStopJob for a job that isn't started. " + mRunningJob);
+                Slog.e(TAG, "Sending onStopJob for a job that isn't started. " + mRunningJob);
                 closeAndCleanupJobH(false /* reschedule */);
                 return;
             }
@@ -474,7 +511,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 scheduleOpTimeOut();
                 service.stopJob(mParams);
             } catch (RemoteException e) {
-                Log.e(TAG, "Error sending onStopJob to client.", e);
+                Slog.e(TAG, "Error sending onStopJob to client.", e);
                 closeAndCleanupJobH(false /* reschedule */);
             }
         }
@@ -486,8 +523,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
          * we want to clean up internally.
          */
         private void closeAndCleanupJobH(boolean reschedule) {
-            removeMessages(MSG_TIMEOUT);
-            mCompletedListener.onJobCompleted(mRunningJob, reschedule);
+            final JobStatus completedJob = mRunningJob;
             synchronized (mLock) {
                 try {
                     mBatteryStats.noteJobFinish(mRunningJob.getName(), mRunningJob.getUid());
@@ -504,12 +540,18 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 service = null;
                 mAvailable = true;
             }
+            removeMessages(MSG_TIMEOUT);
+            removeMessages(MSG_CALLBACK);
+            removeMessages(MSG_SERVICE_BOUND);
+            removeMessages(MSG_CANCEL);
+            removeMessages(MSG_SHUTDOWN_EXECUTION);
+            mCompletedListener.onJobCompleted(completedJob, reschedule);
         }
 
         /**
-         * Called when sending a message to the client, over whose execution we have no control. If we
-         * haven't received a response in a certain amount of time, we want to give up and carry on
-         * with life.
+         * Called when sending a message to the client, over whose execution we have no control. If
+         * we haven't received a response in a certain amount of time, we want to give up and carry
+         * on with life.
          */
         private void scheduleOpTimeOut() {
             mCallbackHandler.removeMessages(MSG_TIMEOUT);
diff --git a/tests/JobSchedulerTestApp/src/com/android/demo/jobSchedulerApp/service/TestJobService.java b/tests/JobSchedulerTestApp/src/com/android/demo/jobSchedulerApp/service/TestJobService.java
index bf8e887..e2c3be0 100644
--- a/tests/JobSchedulerTestApp/src/com/android/demo/jobSchedulerApp/service/TestJobService.java
+++ b/tests/JobSchedulerTestApp/src/com/android/demo/jobSchedulerApp/service/TestJobService.java
@@ -20,16 +20,21 @@ import android.app.job.JobInfo;
 import android.app.job.JobScheduler;
 import android.app.job.JobParameters;
 import android.app.job.JobService;
+import android.content.ComponentName;
 import android.content.Context;
 import android.content.Intent;
+import android.os.AsyncTask;
 import android.os.Message;
 import android.os.Messenger;
 import android.os.RemoteException;
 import android.util.Log;
+import android.util.SparseArray;
 
 import com.android.demo.jobSchedulerApp.MainActivity;
 
+import java.util.HashMap;
 import java.util.LinkedList;
+import java.util.Random;
 
 
 /**
@@ -75,39 +80,76 @@ public class TestJobService extends JobService {
 
     @Override
     public boolean onStartJob(JobParameters params) {
-        jobParamsMap.add(params);
+        Log.i(TAG, "on start job: " + params.getJobId());
+        currentId++;
+        jobParamsMap.put(currentId, params);
+        final int currId = this.currentId;
+        Log.d(TAG, "putting :" + currId + " for " + params.toString());
+        Log.d(TAG, " pulled: " + jobParamsMap.get(currId));
         if (mActivity != null) {
             mActivity.onReceivedStartJob(params);
         }
-        Log.i(TAG, "on start job: " + params.getJobId());
+
+        // Spin off a new task on a separate thread for a couple seconds.
+        new AsyncTask<Void, Void, Void>() {
+            @Override
+            protected Void doInBackground(Void... voids) {
+                try {
+                    Log.d(TAG, "Sleeping for 3 seconds.");
+                    Thread.sleep(3000L);
+                } catch (InterruptedException e) {}
+                final JobParameters params = jobParamsMap.get(currId);
+                Log.d(TAG, "Pulled :" + currId + " " + params);
+                jobFinished(params, false);
+
+                Log.d(TAG, "Rescheduling new job: " + params.getJobId());
+                scheduleJob(
+                        new JobInfo.Builder(params.getJobId(),
+                                new ComponentName(getBaseContext(), TestJobService.class))
+                                .setMinimumLatency(2000L)
+                                .setOverrideDeadline(3000L)
+                                .setRequiresCharging(true)
+                                .build()
+                );
+
+                return null;
+            }
+        }.execute();
         return true;
     }
 
+
     @Override
     public boolean onStopJob(JobParameters params) {
-        jobParamsMap.remove(params);
-        mActivity.onReceivedStopJob();
         Log.i(TAG, "on stop job: " + params.getJobId());
+        int ind = jobParamsMap.indexOfValue(params);
+        jobParamsMap.remove(ind);
+        mActivity.onReceivedStopJob();
         return true;
     }
 
+    static int currentId = 0;
     MainActivity mActivity;
-    private final LinkedList<JobParameters> jobParamsMap = new LinkedList<JobParameters>();
+    private final SparseArray<JobParameters> jobParamsMap = new SparseArray<JobParameters>();
+
 
     public void setUiCallback(MainActivity activity) {
         mActivity = activity;
     }
 
     /** Send job to the JobScheduler. */
-    public void scheduleJob(JobInfo t) {
-        Log.d(TAG, "Scheduling job");
+    public void scheduleJob(JobInfo job) {
+        Log.d(TAG, "Scheduling job " + job);
         JobScheduler tm =
                 (JobScheduler) getSystemService(Context.JOB_SCHEDULER_SERVICE);
-        tm.schedule(t);
+        tm.schedule(job);
     }
 
     public boolean callJobFinished() {
-        JobParameters params = jobParamsMap.poll();
+        if (jobParamsMap.size() == 0) {
+            return false;
+        }
+        JobParameters params = jobParamsMap.valueAt(0);
         if (params == null) {
             return false;
         } else {