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
diff --git a/services/core/java/com/android/server/job/JobSchedulerService.java b/services/core/java/com/android/server/job/JobSchedulerService.java
index b0d76e8..b8fe884 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 @@
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 @@
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 @@
@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 @@
@Override public void onUidIdle(int uid, boolean disabled) throws RemoteException {
if (disabled) {
- cancelJobsForUid(uid);
+ cancelJobsForUid(uid, "app uid idle");
}
}
};
@@ -689,7 +689,7 @@
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 @@
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 @@
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 @@
* @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 @@
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 @@
mJobPackageTracker.noteNonpending(cancelled);
}
// Cancel if running.
- stopJobOnServiceContextLocked(cancelled, JobParameters.REASON_CANCELED);
+ stopJobOnServiceContextLocked(cancelled, JobParameters.REASON_CANCELED, reason);
reportActiveLocked();
}
@@ -844,7 +844,8 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 ff39baf..637db11 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.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 @@
/** 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 @@
}
mJobPackageTracker.noteActive(job);
mAvailable = false;
+ mStoppedReason = null;
+ mStoppedTime = 0;
return true;
}
}
@@ -216,12 +225,12 @@
}
/** 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 @@
&& (!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 @@
@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 @@
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 @@
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 @@
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 @@
@Override
public void onServiceDisconnected(ComponentName name) {
synchronized (mLock) {
- closeAndCleanupJobLocked(true /* needsReschedule */);
+ closeAndCleanupJobLocked(true /* needsReschedule */, "unexpectedly disconnected");
}
}
@@ -374,6 +379,21 @@
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 @@
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 @@
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 @@
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 @@
}
}
- void doCancelLocked(int arg1) {
+ void doCancelLocked(int arg1, String debugReason) {
if (mVerb == VERB_FINISHED) {
if (DEBUG) {
Slog.d(TAG,
@@ -448,7 +468,7 @@
mPreferredUid = mRunningJob != null ? mRunningJob.getUid() :
NO_PREFERRED_UID;
}
- handleCancelLocked();
+ handleCancelLocked(debugReason);
}
/** Start the job on the service. */
@@ -459,7 +479,7 @@
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 @@
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 @@
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 @@
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 @@
* _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 @@
* 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 @@
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 @@
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 @@
// 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 @@
* 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 @@
} 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 @@
* 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 @@
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