commit faedb36fb794e3230a421c3bb286e954dd935284
author Kanyinsola <kanyinsola@google.com> Wed Feb 23 17:04:30 2022 +0000
committer Kanyinsola <kanyinsola@google.com> Fri Feb 25 13:47:20 2022 +0000
tree d277beeaef129d11e5dffdeae90d445d0c5ae6f7
parent 94dd832f60abce760d81e046fa22795687a849bd

Add local logs to NetworkTimeUpdateService

Bug: b/217357882
Test: Changes adds local logs. Existing unit tests still pass.
Change-Id: I2876a479c5219b6e4af6dfe25ba0942d82115ca5

core/java/android/util/NtpTrustedTime.java

diff --git a/core/java/android/util/NtpTrustedTime.java b/core/java/android/util/NtpTrustedTime.java
index 4ac3178..8604078 100644
--- a/core/java/android/util/NtpTrustedTime.java
+++ b/core/java/android/util/NtpTrustedTime.java
@@ -81,7 +81,16 @@
 
         /** Calculates and returns the age of this result. */
         public long getAgeMillis() {
-            return SystemClock.elapsedRealtime() - mElapsedRealtimeMillis;
+            return getAgeMillis(SystemClock.elapsedRealtime());
+        }
+
+        /**
+         * Calculates and returns the age of this result relative to currentElapsedRealtimeMillis.
+         *
+         * @param currentElapsedRealtimeMillis - reference elapsed real time
+         */
+        public long getAgeMillis(long currentElapsedRealtimeMillis) {
+            return currentElapsedRealtimeMillis - mElapsedRealtimeMillis;
         }
 
         @Override

services/core/java/com/android/server/NetworkTimeUpdateService.java

diff --git a/services/core/java/com/android/server/NetworkTimeUpdateService.java b/services/core/java/com/android/server/NetworkTimeUpdateService.java
index ff2308c..a0f239d 100644
--- a/services/core/java/com/android/server/NetworkTimeUpdateService.java
+++ b/services/core/java/com/android/server/NetworkTimeUpdateService.java
@@ -16,6 +16,7 @@
 
 package com.android.server;
 
+import android.annotation.NonNull;
 import android.app.AlarmManager;
 import android.app.PendingIntent;
 import android.app.timedetector.NetworkTimeSuggestion;
@@ -38,6 +39,7 @@
 import android.os.SystemClock;
 import android.os.TimestampedValue;
 import android.provider.Settings;
+import android.util.LocalLog;
 import android.util.Log;
 import android.util.NtpTrustedTime;
 import android.util.TimeUtils;
@@ -95,6 +97,13 @@
     // connection to happen.
     private int mTryAgainCounter;
 
+    /**
+     * A log that records the decisions to fetch a network time update.
+     * This is logged in bug reports to assist with debugging issues with network time suggestions.
+     */
+    @NonNull
+    private final LocalLog mLocalLog = new LocalLog(30, false /* useLocalTimestamps */);
+
     public NetworkTimeUpdateService(Context context) {
         mContext = context;
         mTime = NtpTrustedTime.getInstance(context);
@@ -155,15 +164,29 @@
     }
 
     private void onPollNetworkTimeUnderWakeLock(int event) {
+        long currentElapsedRealtimeMillis = SystemClock.elapsedRealtime();
         // Force an NTP fix when outdated
         NtpTrustedTime.TimeResult cachedNtpResult = mTime.getCachedTimeResult();
-        if (cachedNtpResult == null || cachedNtpResult.getAgeMillis() >= mPollingIntervalMs) {
+        if (cachedNtpResult == null || cachedNtpResult.getAgeMillis(currentElapsedRealtimeMillis)
+                >= mPollingIntervalMs) {
             if (DBG) Log.d(TAG, "Stale NTP fix; forcing refresh");
-            mTime.forceRefresh();
+            boolean isSuccessful = mTime.forceRefresh();
+            if (!isSuccessful) {
+                String logMsg = "forceRefresh() returned false: cachedNtpResult=" + cachedNtpResult
+                        + ", currentElapsedRealtimeMillis=" + currentElapsedRealtimeMillis;
+
+                if (DBG) {
+                    Log.d(TAG, logMsg);
+                }
+                mLocalLog.log(logMsg);
+            }
+
             cachedNtpResult = mTime.getCachedTimeResult();
         }
 
-        if (cachedNtpResult != null && cachedNtpResult.getAgeMillis() < mPollingIntervalMs) {
+        if (cachedNtpResult != null
+                && cachedNtpResult.getAgeMillis(currentElapsedRealtimeMillis)
+                < mPollingIntervalMs) {
             // Obtained fresh fix; schedule next normal update
             resetAlarm(mPollingIntervalMs);
 
@@ -180,6 +203,11 @@
                 resetAlarm(mPollingIntervalShorterMs);
             } else {
                 // Try much later
+                String logMsg = "mTryAgainTimesMax exceeded, cachedNtpResult=" + cachedNtpResult;
+                if (DBG) {
+                    Log.d(TAG, logMsg);
+                }
+                mLocalLog.log(logMsg);
                 mTryAgainCounter = 0;
                 resetAlarm(mPollingIntervalMs);
             }
@@ -285,6 +313,8 @@
         if (ntpResult != null) {
             pw.println("NTP result age: " + ntpResult.getAgeMillis());
         }
+        pw.println("Local logs:");
+        mLocalLog.dump(fd, pw, args);
         pw.println();
     }
 }