Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit eea78707 authored by Neil Fuller's avatar Neil Fuller
Browse files

Improve debug logging for NetworkTimeHelper 

Adds dumpsys logging support to NetworkTimeHelper and
implement it for NtpNetworkTimeHelper.

This enables better tracking of whether it currently does what is
expected and help comparison with its proposed replacement.

Bug: 222295093
Test: treehugger / manual build / boot
Change-Id: Idb74ad2842dcc7f521800cdd4f026db1b47dbebc
parent 8ad07e27

services/core/java/com/android/server/location/gnss/ExponentialBackOff.java

+9 −0
Original line number Diff line number Diff line
@@ -44,5 +44,14 @@ class ExponentialBackOff { 
    void reset() {

        mCurrentIntervalMillis = mInitIntervalMillis / MULTIPLIER;

    }



    @Override

    public String toString() {

        return "ExponentialBackOff{"

                + "mInitIntervalMillis=" + mInitIntervalMillis

                + ", mMaxIntervalMillis=" + mMaxIntervalMillis

                + ", mCurrentIntervalMillis=" + mCurrentIntervalMillis

                + '}';

    }

}

services/core/java/com/android/server/location/gnss/GnssLocationProvider.java

+1 −0
Original line number Diff line number Diff line
@@ -1695,6 +1695,7 @@ public class GnssLocationProvider extends AbstractLocationProvider implements 
        pw.println("mFixInterval=" + mFixInterval);

        pw.print(mGnssMetrics.dumpGnssMetricsAsText());

        if (dumpAll) {

            mNetworkTimeHelper.dump(pw);

            pw.println("mSupportsPsds=" + mSupportsPsds);

            pw.println(

                    "PsdsServerConfigured=" + mGnssConfiguration.isLongTermPsdsServerConfigured());

services/core/java/com/android/server/location/gnss/NetworkTimeHelper.java

+13 −3
Original line number Diff line number Diff line
@@ -15,9 +15,14 @@ 
 */

package com.android.server.location.gnss;



import android.annotation.CurrentTimeMillisLong;

import android.annotation.ElapsedRealtimeLong;

import android.annotation.NonNull;

import android.content.Context;

import android.os.Looper;



import java.io.PrintWriter;



/**

 * An abstraction for use by {@link GnssLocationProvider}. This class allows switching between

 * implementations with a compile-time constant change, which is less risky than rolling back a
@@ -32,15 +37,16 @@ abstract class NetworkTimeHelper { 
     * the looper passed to {@link #create(Context, Looper, InjectTimeCallback)}.

     */

    interface InjectTimeCallback {

        void injectTime(long unixEpochTimeMillis, long elapsedRealtimeMillis,

                int uncertaintyMillis);

        void injectTime(@CurrentTimeMillisLong long unixEpochTimeMillis,

                @ElapsedRealtimeLong long elapsedRealtimeMillis, int uncertaintyMillis);

    }



    /**

     * Creates the {@link NetworkTimeHelper} instance for use by {@link GnssLocationProvider}.

     */

    static NetworkTimeHelper create(

            Context context, Looper looper, InjectTimeCallback injectTimeCallback) {

            @NonNull Context context, @NonNull Looper looper,

            @NonNull InjectTimeCallback injectTimeCallback) {

        return new NtpNetworkTimeHelper(context, looper, injectTimeCallback);

    }
@@ -72,4 +78,8 @@ abstract class NetworkTimeHelper { 
     */

    abstract void onNetworkAvailable();



    /**

     * Dumps internal state during bugreports useful for debugging.

     */

    abstract void dump(@NonNull PrintWriter pw);

}

services/core/java/com/android/server/location/gnss/NtpNetworkTimeHelper.java

+78 −25
Original line number Diff line number Diff line
@@ -23,12 +23,17 @@ import android.os.Handler; 
import android.os.Looper;

import android.os.PowerManager;

import android.os.PowerManager.WakeLock;

import android.os.SystemClock;

import android.util.IndentingPrintWriter;

import android.util.LocalLog;

import android.util.Log;

import android.util.NtpTrustedTime;



import com.android.internal.annotations.GuardedBy;

import com.android.internal.annotations.VisibleForTesting;



import java.io.PrintWriter;



/**

 * Handles injecting network time to GNSS by explicitly making NTP requests when needed.

 */
@@ -60,6 +65,9 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 
    private static final long WAKELOCK_TIMEOUT_MILLIS = 60 * 1000;

    private static final String WAKELOCK_KEY = "NtpTimeHelper";



    private final LocalLog mDumpLog = new LocalLog(10, /*useLocalTimestamps=*/false);



    @GuardedBy("this")

    private final ExponentialBackOff mNtpBackOff = new ExponentialBackOff(RETRY_INTERVAL,

            MAX_RETRY_INTERVAL);
@@ -103,14 +111,37 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 


    @Override

    void demandUtcTimeInjection() {

        retrieveAndInjectNtpTime();

        retrieveAndInjectNtpTime("demandUtcTimeInjection");

    }



    @Override

    synchronized void onNetworkAvailable() {

        if (mInjectNtpTimeState == STATE_PENDING_NETWORK) {

            retrieveAndInjectNtpTime();

            retrieveAndInjectNtpTime("onNetworkAvailable");

        }

    }



    @Override

    void dump(PrintWriter pw) {

        pw.println("NtpNetworkTimeHelper:");



        IndentingPrintWriter ipw = new IndentingPrintWriter(pw, "  ");

        ipw.increaseIndent();

        synchronized (this) {

            ipw.println("mInjectNtpTimeState=" + mInjectNtpTimeState);

            ipw.println("mPeriodicTimeInjection=" + mPeriodicTimeInjection);

            ipw.println("mNtpBackOff=" + mNtpBackOff);

        }



        ipw.println("Debug log:");

        ipw.increaseIndent();

        mDumpLog.dump(ipw);

        ipw.decreaseIndent();



        ipw.println("NtpTrustedTime:");

        ipw.increaseIndent();

        mNtpTime.dump(ipw);

        ipw.decreaseIndent();

    }



    /**
@@ -122,14 +153,14 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 
        return activeNetworkInfo != null && activeNetworkInfo.isConnected();

    }



    private synchronized void retrieveAndInjectNtpTime() {

    private synchronized void retrieveAndInjectNtpTime(String reason) {

        if (mInjectNtpTimeState == STATE_RETRIEVING_AND_INJECTING) {

            // already downloading data

            return;

        }

        if (!isNetworkConnected()) {

            // try to inject the cached NTP time

            injectCachedNtpTime();

            maybeInjectCachedNtpTime(reason + "[Network not connected]");

            // try again when network is up

            mInjectNtpTimeState = STATE_PENDING_NETWORK;

            return;
@@ -143,7 +174,8 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 


    /** {@link NtpTrustedTime#forceRefresh} is a blocking network operation. */

    private void blockingGetNtpTimeAndInject() {

        long delay;

        long debugId = SystemClock.elapsedRealtime();

        long delayMillis;



        // force refresh NTP cache when outdated

        boolean refreshSuccess = true;
@@ -158,26 +190,30 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 


            // only update when NTP time is fresh

            // If refreshSuccess is false, cacheAge does not drop down.

            if (injectCachedNtpTime()) {

                delay = NTP_INTERVAL;

            String injectReason = "blockingGetNtpTimeAndInject:"

                    + ", debugId=" + debugId

                    + ", refreshSuccess=" + refreshSuccess;

            if (maybeInjectCachedNtpTime(injectReason)) {

                delayMillis = NTP_INTERVAL;

                mNtpBackOff.reset();

            } else {

                Log.e(TAG, "requestTime failed");

                delay = mNtpBackOff.nextBackoffMillis();

                logWarn("maybeInjectCachedNtpTime() returned false");

                delayMillis = mNtpBackOff.nextBackoffMillis();

            }



            if (DEBUG) {

                Log.d(TAG, String.format(

                        "mPeriodicTimeInjection=%s, refreshSuccess=%s, delay=%s",

                        mPeriodicTimeInjection,

                        refreshSuccess,

                        delay));

            }

            if (mPeriodicTimeInjection || !refreshSuccess) {

                String debugMsg = "blockingGetNtpTimeAndInject: Scheduling later NTP retrieval"

                                + ", debugId=" + debugId

                                + ", mPeriodicTimeInjection=" + mPeriodicTimeInjection

                                + ", refreshSuccess=" + refreshSuccess

                                + ", delayMillis=" + delayMillis;

                logDebug(debugMsg);



                // Schedule next NTP injection.

                // Since this is delayed, the wake lock is released right away, and will be held

                // again when the delayed task runs.

                mHandler.postDelayed(this::retrieveAndInjectNtpTime, delay);

                String reason = "scheduled: debugId=" + debugId;

                mHandler.postDelayed(() -> retrieveAndInjectNtpTime(reason), delayMillis);

            }

        }

        // release wake lock held by task
@@ -185,24 +221,41 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { 
    }



    /** Returns true if successfully inject cached NTP time. */

    private synchronized boolean injectCachedNtpTime() {

    private synchronized boolean maybeInjectCachedNtpTime(String reason) {

        NtpTrustedTime.TimeResult ntpResult = mNtpTime.getCachedTimeResult();

        if (ntpResult == null || ntpResult.getAgeMillis() >= NTP_INTERVAL) {

            String debugMsg = "maybeInjectCachedNtpTime: Not injecting latest NTP time"

                    + ", reason=" + reason

                    + ", ntpResult=" + ntpResult;

            logDebug(debugMsg);



            return false;

        }



        long unixEpochTimeMillis = ntpResult.getTimeMillis();

        long timeReferenceMillis = ntpResult.getElapsedRealtimeMillis();

        int uncertaintyMillis = ntpResult.getUncertaintyMillis();

        if (DEBUG) {

        long currentTimeMillis = System.currentTimeMillis();

            Log.d(TAG, "NTP server returned: " + unixEpochTimeMillis

                    + " ntpResult: " + ntpResult

                    + " system time offset: " + (unixEpochTimeMillis - currentTimeMillis));

        }

        String debugMsg = "maybeInjectCachedNtpTime: Injecting latest NTP time"

                + ", reason=" + reason

                + ", ntpResult=" + ntpResult

                + ", System time offset millis=" + (unixEpochTimeMillis - currentTimeMillis);

        logDebug(debugMsg);



        long timeReferenceMillis = ntpResult.getElapsedRealtimeMillis();

        int uncertaintyMillis = ntpResult.getUncertaintyMillis();

        mHandler.post(() -> mCallback.injectTime(unixEpochTimeMillis, timeReferenceMillis,

                uncertaintyMillis));

        return true;

    }



    private void logWarn(String logMsg) {

        mDumpLog.log(logMsg);

        Log.e(TAG, logMsg);

    }



    private void logDebug(String debugMsg) {

        mDumpLog.log(debugMsg);

        if (DEBUG) {

            Log.d(TAG, debugMsg);

        }

    }

}