DO NOT MERGE Sanity check loaded periodics and cap runtime.

BUG: 24900376
We've seen an issue where periodic run times can be massively
inflated after loading from disk.
As a safeguard, cap the period's loaded runtime to be [p, 2p]
from the time of loading.

Change-Id: Ie4464490c8d6702fee8efe9190c3da5dc5f013f6
(cherry picked from commit fa8e5084eed63ab8d92c71fcff656690a30293c3)

4 files changed, 78 insertions, 11 deletions

diff --git a/services/core/java/com/android/server/job/JobServiceContext.java b/services/core/java/com/android/server/job/JobServiceContext.java
index 43d5648..f4f8201 100644
--- a/services/core/java/com/android/server/job/JobServiceContext.java
+++ b/services/core/java/com/android/server/job/JobServiceContext.java
@@ -62,7 +62,7 @@ import java.util.concurrent.atomic.AtomicBoolean;
  *
  */
 public class JobServiceContext extends IJobCallback.Stub implements ServiceConnection {
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = JobSchedulerService.DEBUG;
     private static final String TAG = "JobServiceContext";
     /** Define the maximum # of jobs allowed to run on a service at once. */
     private static final int defaultMaxActiveJobsPerService =
diff --git a/services/core/java/com/android/server/job/JobStore.java b/services/core/java/com/android/server/job/JobStore.java
index 24d4f15..53125c0 100644
--- a/services/core/java/com/android/server/job/JobStore.java
+++ b/services/core/java/com/android/server/job/JobStore.java
@@ -24,6 +24,7 @@ import android.os.Handler;
 import android.os.PersistableBundle;
 import android.os.SystemClock;
 import android.os.UserHandle;
+import android.text.format.DateUtils;
 import android.util.AtomicFile;
 import android.util.ArraySet;
 import android.util.Pair;
@@ -552,9 +553,10 @@ public class JobStore {
                 return null;
             }
 
-            Pair<Long, Long> runtimes;
+            // Tuple of (earliest runtime, latest runtime) in elapsed realtime after disk load.
+            Pair<Long, Long> elapsedRuntimes;
             try {
-                runtimes = buildExecutionTimesFromXml(parser);
+                elapsedRuntimes = buildExecutionTimesFromXml(parser);
             } catch (NumberFormatException e) {
                 if (DEBUG) {
                     Slog.d(TAG, "Error parsing execution time parameters, skipping.");
@@ -562,22 +564,45 @@ public class JobStore {
                 return null;
             }
 
+            final long elapsedNow = SystemClock.elapsedRealtime();
             if (XML_TAG_PERIODIC.equals(parser.getName())) {
                 try {
                     String val = parser.getAttributeValue(null, "period");
-                    jobBuilder.setPeriodic(Long.valueOf(val));
+                    final long periodMillis = Long.valueOf(val);
+                    jobBuilder.setPeriodic(periodMillis);
+                    // As a sanity check, cap the recreated run time to be no later than 2 periods
+                    // from now. This is the latest the periodic could be pushed out. This could
+                    // happen if the periodic ran early (at the start of its period), and then the
+                    // device rebooted.
+                    if (elapsedRuntimes.second > elapsedNow + 2 * periodMillis) {
+                        final long clampedEarlyRuntimeElapsed = elapsedNow + periodMillis;
+                        final long clampedLateRuntimeElapsed = elapsedNow + 2 * periodMillis;
+                        Slog.w(TAG,
+                                String.format("Periodic job for uid='%d' persisted run-time is" +
+                                                " too big [%s, %s]. Clamping to [%s,%s]",
+                                        uid,
+                                        DateUtils.formatElapsedTime(elapsedRuntimes.first / 1000),
+                                        DateUtils.formatElapsedTime(elapsedRuntimes.second / 1000),
+                                        DateUtils.formatElapsedTime(
+                                                clampedEarlyRuntimeElapsed / 1000),
+                                        DateUtils.formatElapsedTime(
+                                                clampedLateRuntimeElapsed / 1000))
+                        );
+                        elapsedRuntimes =
+                                Pair.create(clampedEarlyRuntimeElapsed, clampedLateRuntimeElapsed);
+                    }
                 } catch (NumberFormatException e) {
                     Slog.d(TAG, "Error reading periodic execution criteria, skipping.");
                     return null;
                 }
             } else if (XML_TAG_ONEOFF.equals(parser.getName())) {
                 try {
-                    if (runtimes.first != JobStatus.NO_EARLIEST_RUNTIME) {
-                        jobBuilder.setMinimumLatency(runtimes.first - SystemClock.elapsedRealtime());
+                    if (elapsedRuntimes.first != JobStatus.NO_EARLIEST_RUNTIME) {
+                        jobBuilder.setMinimumLatency(elapsedRuntimes.first - elapsedNow);
                     }
-                    if (runtimes.second != JobStatus.NO_LATEST_RUNTIME) {
+                    if (elapsedRuntimes.second != JobStatus.NO_LATEST_RUNTIME) {
                         jobBuilder.setOverrideDeadline(
-                                runtimes.second - SystemClock.elapsedRealtime());
+                                elapsedRuntimes.second - elapsedNow);
                     }
                 } catch (NumberFormatException e) {
                     Slog.d(TAG, "Error reading job execution criteria, skipping.");
@@ -598,7 +623,8 @@ public class JobStore {
             do {
                 eventType = parser.next();
             } while (eventType == XmlPullParser.TEXT);
-            if (!(eventType == XmlPullParser.START_TAG && XML_TAG_EXTRAS.equals(parser.getName()))) {
+            if (!(eventType == XmlPullParser.START_TAG
+                    && XML_TAG_EXTRAS.equals(parser.getName()))) {
                 if (DEBUG) {
                     Slog.d(TAG, "Error reading extras, skipping.");
                 }
@@ -609,7 +635,8 @@ public class JobStore {
             jobBuilder.setExtras(extras);
             parser.nextTag(); // Consume </extras>
 
-            return new JobStatus(jobBuilder.build(), uid, runtimes.first, runtimes.second);
+            return new JobStatus(
+                    jobBuilder.build(), uid, elapsedRuntimes.first, elapsedRuntimes.second);
         }
 
         private JobInfo.Builder buildBuilderFromXml(XmlPullParser parser) throws NumberFormatException {
diff --git a/services/core/java/com/android/server/job/controllers/StateController.java b/services/core/java/com/android/server/job/controllers/StateController.java
index cda7c32..21c30c7 100644
--- a/services/core/java/com/android/server/job/controllers/StateController.java
+++ b/services/core/java/com/android/server/job/controllers/StateController.java
@@ -18,6 +18,7 @@ package com.android.server.job.controllers;
 
 import android.content.Context;
 
+import com.android.server.job.JobSchedulerService;
 import com.android.server.job.StateChangedListener;
 
 import java.io.PrintWriter;
@@ -28,7 +29,7 @@ import java.io.PrintWriter;
  * are ready to run, or whether they must be stopped.
  */
 public abstract class StateController {
-    protected static final boolean DEBUG = false;
+    protected static final boolean DEBUG = JobSchedulerService.DEBUG;
     protected Context mContext;
     protected StateChangedListener mStateChangedListener;
     protected boolean mDeviceIdleMode;
diff --git a/services/tests/servicestests/src/com/android/server/job/JobStoreTest.java b/services/tests/servicestests/src/com/android/server/job/JobStoreTest.java
index bd64392..0b73beb 100644
--- a/services/tests/servicestests/src/com/android/server/job/JobStoreTest.java
+++ b/services/tests/servicestests/src/com/android/server/job/JobStoreTest.java
@@ -6,6 +6,7 @@ import android.content.Context;
 import android.app.job.JobInfo;
 import android.app.job.JobInfo.Builder;
 import android.os.PersistableBundle;
+import android.os.SystemClock;
 import android.test.AndroidTestCase;
 import android.test.RenamingDelegatingContext;
 import android.util.Log;
@@ -102,6 +103,14 @@ public class JobStoreTest extends AndroidTestCase {
         Iterator<JobStatus> it = jobStatusSet.iterator();
         JobStatus loaded1 = it.next();
         JobStatus loaded2 = it.next();
+
+        // Reverse them so we know which comparison to make.
+        if (loaded1.getJobId() != 8) {
+            JobStatus tmp = loaded1;
+            loaded1 = loaded2;
+            loaded2 = tmp;
+        }
+
         assertTasksEqual(task1, loaded1.getJob());
         assertTasksEqual(task2, loaded2.getJob());
         assertTrue("JobStore#contains invalid.", mTaskStoreUnderTest.containsJob(taskStatus1));
@@ -143,6 +152,36 @@ public class JobStoreTest extends AndroidTestCase {
         assertTasksEqual(task, loaded.getJob());
     }
 
+    public void testMassivePeriodClampedOnRead() throws Exception {
+        final long TEN_SECONDS = 10000L;
+        JobInfo.Builder b = new Builder(8, mComponent)
+                .setPeriodic(TEN_SECONDS)
+                .setPersisted(true);
+        final long invalidLateRuntimeElapsedMillis =
+                SystemClock.elapsedRealtime() + (TEN_SECONDS * 2) + 5000;  // >2P from now.
+        final long invalidEarlyRuntimeElapsedMillis =
+                invalidLateRuntimeElapsedMillis - TEN_SECONDS;  // Early is (late - period).
+        final JobStatus js = new JobStatus(b.build(), SOME_UID,
+                invalidEarlyRuntimeElapsedMillis, invalidLateRuntimeElapsedMillis);
+
+        mTaskStoreUnderTest.add(js);
+        Thread.sleep(IO_WAIT);
+
+        final ArraySet<JobStatus> jobStatusSet = new ArraySet<JobStatus>();
+        mTaskStoreUnderTest.readJobMapFromDisk(jobStatusSet);
+        assertEquals("Incorrect # of persisted tasks.", 1, jobStatusSet.size());
+        JobStatus loaded = jobStatusSet.iterator().next();
+
+        // Assert early runtime was clamped to be under now + period. We can do <= here b/c we'll
+        // call SystemClock.elapsedRealtime after doing the disk i/o.
+        final long newNowElapsed = SystemClock.elapsedRealtime();
+        assertTrue("Early runtime wasn't correctly clamped.",
+                loaded.getEarliestRunTime() <= newNowElapsed + TEN_SECONDS);
+        // Assert late runtime was clamped to be now + period*2.
+        assertTrue("Early runtime wasn't correctly clamped.",
+                loaded.getEarliestRunTime() <= newNowElapsed + TEN_SECONDS*2);
+    }
+
     /**
      * Helper function to throw an error if the provided task and TaskStatus objects are not equal.
      */