Log sync stop (== onStopJob) reason in the sync log.

Bug: 71866667
Test: Manual test

Change-Id: I89e492362759fe6318102b61a28818b642f5bc2f

core/java/android/app/job/JobParameters.java

@@ -70,6 +70,7 @@ public class JobParameters implements Parcelable {
     private final Network network;
 
     private int stopReason; // Default value of stopReason is REASON_CANCELED
+    private String debugStopReason; // Human readable stop reason for debugging.
 
     /** @hide */
     public JobParameters(IBinder callback, int jobId, PersistableBundle extras,
@@ -103,6 +104,14 @@ public class JobParameters implements Parcelable {
         return stopReason;
     }
 
+    /**
+     * Reason onStopJob() was called on this job.
+     * @hide
+     */
+    public String getDebugStopReason() {
+        return debugStopReason;
+    }
+
     /**
      * @return The extras you passed in when constructing this job with
      * {@link android.app.job.JobInfo.Builder#setExtras(android.os.PersistableBundle)}. This will
@@ -288,11 +297,13 @@ public class JobParameters implements Parcelable {
             network = null;
         }
         stopReason = in.readInt();
+        debugStopReason = in.readString();
     }
 
     /** @hide */
-    public void setStopReason(int reason) {
+    public void setStopReason(int reason, String debugStopReason) {
         stopReason = reason;
+        this.debugStopReason = debugStopReason;
     }
 
     @Override
@@ -323,6 +334,7 @@ public class JobParameters implements Parcelable {
             dest.writeInt(0);
         }
         dest.writeInt(stopReason);
+        dest.writeString(debugStopReason);
     }
 
     public static final Creator<JobParameters> CREATOR = new Creator<JobParameters>() {

services/core/java/com/android/server/content/SyncJobService.java

@@ -122,10 +122,12 @@ public class SyncJobService extends JobService {
 
             final long startUptime = mJobStartUptimes.get(jobId);
             final long nowUptime = SystemClock.uptimeMillis();
+            final long runtime = nowUptime - startUptime;
+
             if (startUptime == 0) {
                 wtf("Job " + jobId + " start uptime not found: "
                         + " params=" + jobParametersToString(params));
-            } else if ((nowUptime - startUptime) > 60 * 1000) {
+            } else if (runtime > 60 * 1000) {
                 // WTF if startSyncH() hasn't happened, *unless* onStopJob() was called too soon.
                 // (1 minute threshold.)
                 if (!mStartedSyncs.get(jobId)) {
@@ -134,6 +136,12 @@ public class SyncJobService extends JobService {
                             + " nowUptime=" + nowUptime
                             + " params=" + jobParametersToString(params));
                 }
+            } else if (runtime < 10 * 1000) {
+                // Job stopped too soon. WTF.
+                wtf("Job " + jobId + " stopped in " + runtime + " ms: "
+                        + " startUptime=" + startUptime
+                        + " nowUptime=" + nowUptime
+                        + " params=" + jobParametersToString(params));
             }
 
             mStartedSyncs.delete(jobId);
@@ -183,6 +191,7 @@ public class SyncJobService extends JobService {
             return "job:null";
         } else {
             return "job:#" + params.getJobId() + ":"
+                    + "sr=[" + params.getStopReason() + "/" + params.getDebugStopReason() + "]:"
                     + SyncOperation.maybeCreateFromJobExtras(params.getExtras());
         }
     }

services/core/java/com/android/server/job/JobSchedulerService.java

@@ -934,12 +934,14 @@ public final class JobSchedulerService extends com.android.server.SystemService
      * @param uid Uid of the calling client.
      * @param jobId Id of the job, provided at schedule-time.
      */
-    public boolean cancelJob(int uid, int jobId) {
+    public boolean cancelJob(int uid, int jobId, int callingUid) {
         JobStatus toCancel;
         synchronized (mLock) {
             toCancel = mJobs.getJobByUidAndJobId(uid, jobId);
             if (toCancel != null) {
-                cancelJobImplLocked(toCancel, null, "cancel() called by app");
+                cancelJobImplLocked(toCancel, null,
+                        "cancel() called by app, callingUid=" + callingUid
+                        + " uid=" + uid + " jobId=" + jobId);
             }
             return (toCancel != null);
         }
@@ -2341,7 +2343,8 @@ public final class JobSchedulerService extends com.android.server.SystemService
             final int uid = Binder.getCallingUid();
             long ident = Binder.clearCallingIdentity();
             try {
-                JobSchedulerService.this.cancelJobsForUid(uid, "cancelAll() called by app");
+                JobSchedulerService.this.cancelJobsForUid(uid,
+                        "cancelAll() called by app, callingUid=" + uid);
             } finally {
                 Binder.restoreCallingIdentity(ident);
             }
@@ -2353,7 +2356,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
 
             long ident = Binder.clearCallingIdentity();
             try {
-                JobSchedulerService.this.cancelJob(uid, jobId);
+                JobSchedulerService.this.cancelJob(uid, jobId, uid);
             } finally {
                 Binder.restoreCallingIdentity(ident);
             }
@@ -2466,7 +2469,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             for (int i=0; i<mActiveServices.size(); i++) {
                 final JobServiceContext jc = mActiveServices.get(i);
                 final JobStatus js = jc.getRunningJobLocked();
-                if (jc.timeoutIfExecutingLocked(pkgName, userId, hasJobId, jobId)) {
+                if (jc.timeoutIfExecutingLocked(pkgName, userId, hasJobId, jobId, "shell")) {
                     foundSome = true;
                     pw.print("Timing out: ");
                     js.printUniqueId(pw);
@@ -2506,7 +2509,7 @@ public final class JobSchedulerService extends com.android.server.SystemService
             }
         } else {
             pw.println("Canceling job " + pkgName + "/#" + jobId + " in user " + userId);
-            if (!cancelJob(pkgUid, jobId)) {
+            if (!cancelJob(pkgUid, jobId, Process.SHELL_UID)) {
                 pw.println("No matching job found.");
             }
         }

services/core/java/com/android/server/job/JobServiceContext.java

@@ -312,13 +312,14 @@ public final class JobServiceContext implements ServiceConnection {
         return mTimeoutElapsed;
     }
 
-    boolean timeoutIfExecutingLocked(String pkgName, int userId, boolean matchJobId, int jobId) {
+    boolean timeoutIfExecutingLocked(String pkgName, int userId, boolean matchJobId, int jobId,
+            String reason) {
         final JobStatus executing = getRunningJobLocked();
         if (executing != null && (userId == UserHandle.USER_ALL || userId == executing.getUserId())
                 && (pkgName == null || pkgName.equals(executing.getSourcePackageName()))
                 && (!matchJobId || jobId == executing.getJobId())) {
             if (mVerb == VERB_EXECUTING) {
-                mParams.setStopReason(JobParameters.REASON_TIMEOUT);
+                mParams.setStopReason(JobParameters.REASON_TIMEOUT, reason);
                 sendStopMessageLocked("force timeout from shell");
                 return true;
             }
@@ -537,7 +538,7 @@ public final class JobServiceContext implements ServiceConnection {
             }
             return;
         }
-        mParams.setStopReason(arg1);
+        mParams.setStopReason(arg1, debugReason);
         if (arg1 == JobParameters.REASON_PREEMPT) {
             mPreferredUid = mRunningJob != null ? mRunningJob.getUid() :
                     NO_PREFERRED_UID;
@@ -687,7 +688,7 @@ public final class JobServiceContext implements ServiceConnection {
                 // Not an error - client ran out of time.
                 Slog.i(TAG, "Client timed out while executing (no jobFinished received), " +
                         "sending onStop: " + getRunningJobNameLocked());
-                mParams.setStopReason(JobParameters.REASON_TIMEOUT);
+                mParams.setStopReason(JobParameters.REASON_TIMEOUT, "client timed out");
                 sendStopMessageLocked("timeout while executing");
                 break;
             default: