From 7273aad8132d388d25a8461408f3e27825ce80f4 Mon Sep 17 00:00:00 2001
From: Makoto Onuki <omakoto@google.com>
Date: Thu, 11 Jan 2018 15:51:23 -0800
Subject: [PATCH] Skip "sync didn't run" WTF when job is stopped too soon

Job scheduler may call onStopJob() right after onStartJob() when a
constraint is no longer satisfied. In that case this WTF shouldn't fire.

Bug: 71866667
Test: manual test (trigger some syncs)
Change-Id: I2ba3b076b60692b02019f3e74b384aea63e27bb4
---
 .../com/android/server/content/SyncJobService.java | 32 ++++++++++++++++++----
 1 file changed, 27 insertions(+), 5 deletions(-)

diff --git a/services/core/java/com/android/server/content/SyncJobService.java b/services/core/java/com/android/server/content/SyncJobService.java
index d957ca054819..40a93c1c2808 100644
--- a/services/core/java/com/android/server/content/SyncJobService.java
+++ b/services/core/java/com/android/server/content/SyncJobService.java
@@ -22,10 +22,12 @@ import android.content.Intent;
 import android.os.Message;
 import android.os.Messenger;
 import android.os.RemoteException;
+import android.os.SystemClock;
 import android.util.Log;
 import android.util.Slog;
 import android.util.SparseArray;
 import android.util.SparseBooleanArray;
+import android.util.SparseLongArray;
 
 import com.android.internal.annotations.GuardedBy;
 
@@ -44,6 +46,9 @@ public class SyncJobService extends JobService {
     @GuardedBy("mLock")
     private final SparseBooleanArray mStartedSyncs = new SparseBooleanArray();
 
+    @GuardedBy("mLock")
+    private final SparseLongArray mJobStartUptimes = new SparseLongArray();
+
     private final SyncLogger mLogger = SyncLogger.getInstance();
 
     /**
@@ -82,7 +87,9 @@ public class SyncJobService extends JobService {
         synchronized (mLock) {
             final int jobId = params.getJobId();
             mJobParamsMap.put(jobId, params);
+
             mStartedSyncs.delete(jobId);
+            mJobStartUptimes.put(jobId, SystemClock.uptimeMillis());
         }
         Message m = Message.obtain();
         m.what = SyncManager.SyncHandler.MESSAGE_START_SYNC;
@@ -113,14 +120,24 @@ public class SyncJobService extends JobService {
             final int jobId = params.getJobId();
             mJobParamsMap.remove(jobId);
 
-            if (!mStartedSyncs.get(jobId)) {
-                final String message = "Job " + jobId + " didn't start: params=" +
-                        jobParametersToString(params);
-                mLogger.log(message);
-                Slog.wtf(TAG, message);
+            final long startUptime = mJobStartUptimes.get(jobId);
+            final long nowUptime = SystemClock.uptimeMillis();
+            if (startUptime == 0) {
+                wtf("Job " + jobId + " start uptime not found: "
+                        + " params=" + jobParametersToString(params));
+            } else if ((nowUptime - startUptime) > 60 * 1000) {
+                // WTF if startSyncH() hasn't happened, *unless* onStopJob() was called too soon.
+                // (1 minute threshold.)
+                if (!mStartedSyncs.get(jobId)) {
+                    wtf("Job " + jobId + " didn't start: "
+                            + " startUptime=" + startUptime
+                            + " nowUptime=" + nowUptime
+                            + " params=" + jobParametersToString(params));
+                }
             }
 
             mStartedSyncs.delete(jobId);
+            mJobStartUptimes.delete(jobId);
         }
         Message m = Message.obtain();
         m.what = SyncManager.SyncHandler.MESSAGE_STOP_SYNC;
@@ -169,4 +186,9 @@ public class SyncJobService extends JobService {
                     + SyncOperation.maybeCreateFromJobExtras(params.getExtras());
         }
     }
+
+    private void wtf(String message) {
+        mLogger.log(message);
+        Slog.wtf(TAG, message);
+    }
 }
-- 
2.11.0