Work on issue #62390590: SecurityException in JobIntentService$...

...JobServiceEngineImpl$WrapperWorkItem.complete

Add more useful information in the security exception message that
is shown -- the reason the last job that was running on the context
was stopped.  This should tell you why when you are calling at that
point your job is no longer running.

Test: bit CtsJobSchedulerTestCases:*

Change-Id: Ia7155248b4b4f032cbf8e8754c5437f658ed192c

2 files changed, 98 insertions, 59 deletions

diff --git a/services/core/java/com/android/server/job/JobSchedulerService.java b/services/core/java/com/android/server/job/JobSchedulerService.java
index b0d76e854af2..b8fe88439c2d 100644
--- a/services/core/java/com/android/server/job/JobSchedulerService.java
+++ b/services/core/java/com/android/server/job/JobSchedulerService.java
@@ -524,7 +524,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
                                             Slog.d(TAG, "Removing jobs for package " + pkgName
                                                     + " in user " + userId);
                                         }
-                                        cancelJobsForUid(pkgUid);
+                                        cancelJobsForUid(pkgUid, "app package state changed");
                                     }
                                 } catch (RemoteException|IllegalArgumentException e) {
                                     /*
@@ -553,7 +553,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
                     if (DEBUG) {
                         Slog.d(TAG, "Removing jobs for uid: " + uidRemoved);
                     }
-                    cancelJobsForUid(uidRemoved);
+                    cancelJobsForUid(uidRemoved, "app uninstalled");
                 }
             } else if (Intent.ACTION_USER_REMOVED.equals(action)) {
                 final int userId = intent.getIntExtra(Intent.EXTRA_USER_HANDLE, 0);
@@ -611,7 +611,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
         @Override public void onUidGone(int uid, boolean disabled) throws RemoteException {
             updateUidState(uid, ActivityManager.PROCESS_STATE_CACHED_EMPTY);
             if (disabled) {
-                cancelJobsForUid(uid);
+                cancelJobsForUid(uid, "uid gone");
             }
         }
 
@@ -620,7 +620,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
 
         @Override public void onUidIdle(int uid, boolean disabled) throws RemoteException {
             if (disabled) {
-                cancelJobsForUid(uid);
+                cancelJobsForUid(uid, "app uid idle");
             }
         }
     };
@@ -689,7 +689,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             jobStatus.prepareLocked(ActivityManager.getService());
 
             if (toCancel != null) {
-                cancelJobImplLocked(toCancel, jobStatus);
+                cancelJobImplLocked(toCancel, jobStatus, "job rescheduled by app");
             }
             if (work != null) {
                 // If work has been supplied, enqueue it into the new job.
@@ -747,7 +747,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             final List<JobStatus> jobsForUser = mJobs.getJobsByUser(userHandle);
             for (int i=0; i<jobsForUser.size(); i++) {
                 JobStatus toRemove = jobsForUser.get(i);
-                cancelJobImplLocked(toRemove, null);
+                cancelJobImplLocked(toRemove, null, "user removed");
             }
         }
     }
@@ -765,7 +765,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             for (int i = jobsForUid.size() - 1; i >= 0; i--) {
                 final JobStatus job = jobsForUid.get(i);
                 if (job.getSourcePackageName().equals(pkgName)) {
-                    cancelJobImplLocked(job, null);
+                    cancelJobImplLocked(job, null, "app force stopped");
                 }
             }
         }
@@ -778,12 +778,12 @@ public final class JobSchedulerService extends com.android.server.SystemService
      * @param uid Uid to check against for removal of a job.
      *
      */
-    public void cancelJobsForUid(int uid) {
+    public void cancelJobsForUid(int uid, String reason) {
         synchronized (mLock) {
             final List<JobStatus> jobsForUid = mJobs.getJobsByUid(uid);
             for (int i=0; i<jobsForUid.size(); i++) {
                 JobStatus toRemove = jobsForUid.get(i);
-                cancelJobImplLocked(toRemove, null);
+                cancelJobImplLocked(toRemove, null, reason);
             }
         }
     }
@@ -800,12 +800,12 @@ public final class JobSchedulerService extends com.android.server.SystemService
         synchronized (mLock) {
             toCancel = mJobs.getJobByUidAndJobId(uid, jobId);
             if (toCancel != null) {
-                cancelJobImplLocked(toCancel, null);
+                cancelJobImplLocked(toCancel, null, "cancel() called by app");
             }
         }
     }
 
-    private void cancelJobImplLocked(JobStatus cancelled, JobStatus incomingJob) {
+    private void cancelJobImplLocked(JobStatus cancelled, JobStatus incomingJob, String reason) {
         if (DEBUG) Slog.d(TAG, "CANCEL: " + cancelled.toShortString());
         cancelled.unprepareLocked(ActivityManager.getService());
         stopTrackingJobLocked(cancelled, incomingJob, true /* writeBack */);
@@ -814,7 +814,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             mJobPackageTracker.noteNonpending(cancelled);
         }
         // Cancel if running.
-        stopJobOnServiceContextLocked(cancelled, JobParameters.REASON_CANCELED);
+        stopJobOnServiceContextLocked(cancelled, JobParameters.REASON_CANCELED, reason);
         reportActiveLocked();
     }
 
@@ -844,7 +844,8 @@ public final class JobSchedulerService extends com.android.server.SystemService
                     final JobStatus executing = jsc.getRunningJobLocked();
                     if (executing != null
                             && (executing.getFlags() & JobInfo.FLAG_WILL_BE_FOREGROUND) == 0) {
-                        jsc.cancelExecutingJobLocked(JobParameters.REASON_DEVICE_IDLE);
+                        jsc.cancelExecutingJobLocked(JobParameters.REASON_DEVICE_IDLE,
+                                "cancelled due to doze");
                     }
                 }
             } else {
@@ -1023,12 +1024,12 @@ public final class JobSchedulerService extends com.android.server.SystemService
         return removed;
     }
 
-    private boolean stopJobOnServiceContextLocked(JobStatus job, int reason) {
+    private boolean stopJobOnServiceContextLocked(JobStatus job, int reason, String debugReason) {
         for (int i=0; i<mActiveServices.size(); i++) {
             JobServiceContext jsc = mActiveServices.get(i);
             final JobStatus executing = jsc.getRunningJobLocked();
             if (executing != null && executing.matches(job.getUid(), job.getJobId())) {
-                jsc.cancelExecutingJobLocked(reason);
+                jsc.cancelExecutingJobLocked(reason, debugReason);
                 return true;
             }
         }
@@ -1270,7 +1271,8 @@ public final class JobSchedulerService extends com.android.server.SystemService
                         queueReadyJobsForExecutionLocked();
                         break;
                     case MSG_STOP_JOB:
-                        cancelJobImplLocked((JobStatus) message.obj, null);
+                        cancelJobImplLocked((JobStatus) message.obj, null,
+                                "app no longer allowed to run");
                         break;
                 }
                 maybeRunPendingJobsLocked();
@@ -1286,7 +1288,8 @@ public final class JobSchedulerService extends com.android.server.SystemService
             final JobStatus running = serviceContext.getRunningJobLocked();
             if (running != null && !running.isReady()) {
                 serviceContext.cancelExecutingJobLocked(
-                        JobParameters.REASON_CONSTRAINTS_NOT_SATISFIED);
+                        JobParameters.REASON_CONSTRAINTS_NOT_SATISFIED,
+                        "cancelled due to unsatisfied constraints");
             }
         }
     }
@@ -1960,7 +1963,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
 
             long ident = Binder.clearCallingIdentity();
             try {
-                JobSchedulerService.this.cancelJobsForUid(uid);
+                JobSchedulerService.this.cancelJobsForUid(uid, "cancelAll() called by app");
             } finally {
                 Binder.restoreCallingIdentity(ident);
             }
@@ -2357,7 +2360,14 @@ public final class JobSchedulerService extends com.android.server.SystemService
                 pw.print("  Slot #"); pw.print(i); pw.print(": ");
                 final JobStatus job = jsc.getRunningJobLocked();
                 if (job == null) {
-                    pw.println("inactive");
+                    if (jsc.mStoppedReason != null) {
+                        pw.print("inactive since ");
+                        TimeUtils.formatDuration(jsc.mStoppedTime, nowElapsed, pw);
+                        pw.print(", stopped because: ");
+                        pw.println(jsc.mStoppedReason);
+                    } else {
+                        pw.println("inactive");
+                    }
                     continue;
                 } else {
                     pw.println(job.toShortString());
diff --git a/services/core/java/com/android/server/job/JobServiceContext.java b/services/core/java/com/android/server/job/JobServiceContext.java
index ff39baf36c2e..637db11af6d8 100644
--- a/services/core/java/com/android/server/job/JobServiceContext.java
+++ b/services/core/java/com/android/server/job/JobServiceContext.java
@@ -38,6 +38,7 @@ import android.os.SystemClock;
 import android.os.UserHandle;
 import android.os.WorkSource;
 import android.util.Slog;
+import android.util.TimeUtils;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.annotations.VisibleForTesting;
@@ -126,6 +127,12 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
     /** Track when job will timeout. */
     private long mTimeoutElapsed;
 
+    // Debugging: reason this job was last stopped.
+    public String mStoppedReason;
+
+    // Debugging: time this job was last stopped.
+    public long mStoppedTime;
+
     JobServiceContext(JobSchedulerService service, IBatteryStats batteryStats,
             JobPackageTracker tracker, Looper looper) {
         this(service.getContext(), service.getLock(), batteryStats, tracker, service, looper);
@@ -204,6 +211,8 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             }
             mJobPackageTracker.noteActive(job);
             mAvailable = false;
+            mStoppedReason = null;
+            mStoppedTime = 0;
             return true;
         }
     }
@@ -216,12 +225,12 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
     }
 
     /** Called externally when a job that was scheduled for execution should be cancelled. */
-    void cancelExecutingJobLocked(int reason) {
-        doCancelLocked(reason);
+    void cancelExecutingJobLocked(int reason, String debugReason) {
+        doCancelLocked(reason, debugReason);
     }
 
     void preemptExecutingJobLocked() {
-        doCancelLocked(JobParameters.REASON_PREEMPT);
+        doCancelLocked(JobParameters.REASON_PREEMPT, "cancelled due to preemption");
     }
 
     int getPreferredUid() {
@@ -247,7 +256,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 && (!matchJobId || jobId == executing.getJobId())) {
             if (mVerb == VERB_EXECUTING) {
                 mParams.setStopReason(JobParameters.REASON_TIMEOUT);
-                sendStopMessageLocked();
+                sendStopMessageLocked("force timeout from shell");
                 return true;
             }
         }
@@ -256,17 +265,17 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
 
     @Override
     public void jobFinished(int jobId, boolean reschedule) {
-        doCallback(reschedule);
+        doCallback(reschedule, "app called jobFinished");
     }
 
     @Override
     public void acknowledgeStopMessage(int jobId, boolean reschedule) {
-        doCallback(reschedule);
+        doCallback(reschedule, null);
     }
 
     @Override
     public void acknowledgeStartMessage(int jobId, boolean ongoing) {
-        doCallback(ongoing);
+        doCallback(ongoing, "finished start");
     }
 
     @Override
@@ -275,14 +284,11 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         final long ident = Binder.clearCallingIdentity();
         try {
             synchronized (mLock) {
-                if (!verifyCallingUidLocked(callingUid)) {
-                    throw new SecurityException("Bad calling uid: " + callingUid);
-                }
-
+                assertCallingUidLocked(callingUid);
                 final JobWorkItem work = mRunningJob.dequeueWorkLocked();
                 if (work == null && !mRunningJob.hasExecutingWorkLocked()) {
                     // This will finish the job.
-                    doCallbackLocked(false);
+                    doCallbackLocked(false, "last work dequeued");
                 }
                 return work;
             }
@@ -297,9 +303,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         final long ident = Binder.clearCallingIdentity();
         try {
             synchronized (mLock) {
-                if (!verifyCallingUidLocked(callingUid)) {
-                    throw new SecurityException("Bad calling uid: " + callingUid);
-                }
+                assertCallingUidLocked(callingUid);
                 return mRunningJob.completeWorkLocked(ActivityManager.getService(), workId);
             }
         } finally {
@@ -324,7 +328,8 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             runningJob = mRunningJob;
 
             if (runningJob == null || !name.equals(runningJob.getServiceComponent())) {
-                closeAndCleanupJobLocked(true /* needsReschedule */);
+                closeAndCleanupJobLocked(true /* needsReschedule */,
+                        "connected for different component");
                 return;
             }
             this.service = IJobService.Stub.asInterface(service);
@@ -355,7 +360,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
     @Override
     public void onServiceDisconnected(ComponentName name) {
         synchronized (mLock) {
-            closeAndCleanupJobLocked(true /* needsReschedule */);
+            closeAndCleanupJobLocked(true /* needsReschedule */, "unexpectedly disconnected");
         }
     }
 
@@ -374,6 +379,21 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         return true;
     }
 
+    private void assertCallingUidLocked(final int callingUid) {
+        if (!verifyCallingUidLocked(callingUid)) {
+            StringBuilder sb = new StringBuilder(128);
+            sb.append("Bad calling uid ");
+            sb.append(callingUid);
+            if (mStoppedReason != null) {
+                sb.append(", last stopped ");
+                TimeUtils.formatDuration(SystemClock.elapsedRealtime() - mStoppedTime, sb);
+                sb.append(" because: ");
+                sb.append(mStoppedReason);
+            }
+            throw new SecurityException(sb.toString());
+        }
+    }
+
     /**
      * Scheduling of async messages (basically timeouts at this point).
      */
@@ -401,7 +421,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         handleServiceBoundLocked();
     }
 
-    void doCallback(boolean reschedule) {
+    void doCallback(boolean reschedule, String reason) {
         final int callingUid = Binder.getCallingUid();
         final long ident = Binder.clearCallingIdentity();
         try {
@@ -409,14 +429,14 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 if (!verifyCallingUidLocked(callingUid)) {
                     return;
                 }
-                doCallbackLocked(reschedule);
+                doCallbackLocked(reschedule, reason);
             }
         } finally {
             Binder.restoreCallingIdentity(ident);
         }
     }
 
-    void doCallbackLocked(boolean reschedule) {
+    void doCallbackLocked(boolean reschedule, String reason) {
         if (DEBUG) {
             Slog.d(TAG, "doCallback of : " + mRunningJob
                     + " v:" + VERB_STRINGS[mVerb]);
@@ -427,7 +447,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             handleStartedLocked(reschedule);
         } else if (mVerb == VERB_EXECUTING ||
                 mVerb == VERB_STOPPING) {
-            handleFinishedLocked(reschedule);
+            handleFinishedLocked(reschedule, reason);
         } else {
             if (DEBUG) {
                 Slog.d(TAG, "Unrecognised callback: " + mRunningJob);
@@ -435,7 +455,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         }
     }
 
-    void doCancelLocked(int arg1) {
+    void doCancelLocked(int arg1, String debugReason) {
         if (mVerb == VERB_FINISHED) {
             if (DEBUG) {
                 Slog.d(TAG,
@@ -448,7 +468,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             mPreferredUid = mRunningJob != null ? mRunningJob.getUid() :
                     NO_PREFERRED_UID;
         }
-        handleCancelLocked();
+        handleCancelLocked(debugReason);
     }
 
     /** Start the job on the service. */
@@ -459,7 +479,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         if (mVerb != VERB_BINDING) {
             Slog.e(TAG, "Sending onStartJob for a job that isn't pending. "
                     + VERB_STRINGS[mVerb]);
-            closeAndCleanupJobLocked(false /* reschedule */);
+            closeAndCleanupJobLocked(false /* reschedule */, "started job not pending");
             return;
         }
         if (mCancelled) {
@@ -467,7 +487,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 Slog.d(TAG, "Job cancelled while waiting for bind to complete. "
                         + mRunningJob);
             }
-            closeAndCleanupJobLocked(true /* reschedule */);
+            closeAndCleanupJobLocked(true /* reschedule */, "cancelled while waiting for bind");
             return;
         }
         try {
@@ -496,7 +516,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 mVerb = VERB_EXECUTING;
                 if (!workOngoing) {
                     // Job is finished already so fast-forward to handleFinished.
-                    handleFinishedLocked(false);
+                    handleFinishedLocked(false, "onStartJob returned false");
                     return;
                 }
                 if (mCancelled) {
@@ -504,7 +524,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                         Slog.d(TAG, "Job cancelled while waiting for onStartJob to complete.");
                     }
                     // Cancelled *while* waiting for acknowledgeStartMessage from client.
-                    handleCancelLocked();
+                    handleCancelLocked(null);
                     return;
                 }
                 scheduleOpTimeOutLocked();
@@ -522,11 +542,11 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
      *     _STARTING   -> Error
      *     _PENDING    -> Error
      */
-    private void handleFinishedLocked(boolean reschedule) {
+    private void handleFinishedLocked(boolean reschedule, String reason) {
         switch (mVerb) {
             case VERB_EXECUTING:
             case VERB_STOPPING:
-                closeAndCleanupJobLocked(reschedule);
+                closeAndCleanupJobLocked(reschedule, reason);
                 break;
             default:
                 Slog.e(TAG, "Got an execution complete message for a job that wasn't being" +
@@ -544,7 +564,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
      *                      in the message queue.
      *     _ENDING     -> No point in doing anything here, so we ignore.
      */
-    private void handleCancelLocked() {
+    private void handleCancelLocked(String reason) {
         if (JobSchedulerService.DEBUG) {
             Slog.d(TAG, "Handling cancel for: " + mRunningJob.getJobId() + " "
                     + VERB_STRINGS[mVerb]);
@@ -553,9 +573,10 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             case VERB_BINDING:
             case VERB_STARTING:
                 mCancelled = true;
+                applyStoppedReasonLocked(reason);
                 break;
             case VERB_EXECUTING:
-                sendStopMessageLocked();
+                sendStopMessageLocked(reason);
                 break;
             case VERB_STOPPING:
                 // Nada.
@@ -572,7 +593,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
             case VERB_BINDING:
                 Slog.e(TAG, "Time-out while trying to bind " + mRunningJob.toShortString() +
                         ", dropping.");
-                closeAndCleanupJobLocked(false /* needsReschedule */);
+                closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while binding");
                 break;
             case VERB_STARTING:
                 // Client unresponsive - wedged or failed to respond in time. We don't really
@@ -580,25 +601,25 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
                 // FINISHED/NO-RETRY.
                 Slog.e(TAG, "No response from client for onStartJob '" +
                         mRunningJob.toShortString());
-                closeAndCleanupJobLocked(false /* needsReschedule */);
+                closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while starting");
                 break;
             case VERB_STOPPING:
                 // At least we got somewhere, so fail but ask the JobScheduler to reschedule.
                 Slog.e(TAG, "No response from client for onStopJob, '" +
                         mRunningJob.toShortString());
-                closeAndCleanupJobLocked(true /* needsReschedule */);
+                closeAndCleanupJobLocked(true /* needsReschedule */, "timed out while stopping");
                 break;
             case VERB_EXECUTING:
                 // Not an error - client ran out of time.
                 Slog.i(TAG, "Client timed out while executing (no jobFinished received)." +
                         " sending onStop. "  + mRunningJob.toShortString());
                 mParams.setStopReason(JobParameters.REASON_TIMEOUT);
-                sendStopMessageLocked();
+                sendStopMessageLocked("timeout while executing");
                 break;
             default:
                 Slog.e(TAG, "Handling timeout for an invalid job state: " +
                         mRunningJob.toShortString() + ", dropping.");
-                closeAndCleanupJobLocked(false /* needsReschedule */);
+                closeAndCleanupJobLocked(false /* needsReschedule */, "invalid timeout");
         }
     }
 
@@ -606,11 +627,11 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
      * Already running, need to stop. Will switch {@link #mVerb} from VERB_EXECUTING ->
      * VERB_STOPPING.
      */
-    private void sendStopMessageLocked() {
+    private void sendStopMessageLocked(String reason) {
         removeOpTimeOutLocked();
         if (mVerb != VERB_EXECUTING) {
             Slog.e(TAG, "Sending onStopJob for a job that isn't started. " + mRunningJob);
-            closeAndCleanupJobLocked(false /* reschedule */);
+            closeAndCleanupJobLocked(false /* reschedule */, reason);
             return;
         }
         try {
@@ -620,7 +641,7 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         } catch (RemoteException e) {
             Slog.e(TAG, "Error sending onStopJob to client.", e);
             // The job's host app apparently crashed during the job, so we should reschedule.
-            closeAndCleanupJobLocked(true /* reschedule */);
+            closeAndCleanupJobLocked(true /* reschedule */, "host crashed when trying to stop");
         }
     }
 
@@ -630,11 +651,12 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
      * or from acknowledging the stop message we sent. Either way, we're done tracking it and
      * we want to clean up internally.
      */
-    private void closeAndCleanupJobLocked(boolean reschedule) {
+    private void closeAndCleanupJobLocked(boolean reschedule, String reason) {
         final JobStatus completedJob;
         if (mVerb == VERB_FINISHED) {
             return;
         }
+        applyStoppedReasonLocked(reason);
         completedJob = mRunningJob;
         mJobPackageTracker.noteInactive(completedJob);
         try {
@@ -658,6 +680,13 @@ public class JobServiceContext extends IJobCallback.Stub implements ServiceConne
         mCompletedListener.onJobCompletedLocked(completedJob, reschedule);
     }
 
+    private void applyStoppedReasonLocked(String reason) {
+        if (reason != null && mStoppedReason == null) {
+            mStoppedReason = reason;
+            mStoppedTime = SystemClock.elapsedRealtime();
+        }
+    }
+
     /**
      * 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