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

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

Fix a scheduling issue

Metrics suggest that there are some cases when the
NetworkTimeUpdateService POLL intent can fire much more often than
expected. There is no hard evidence yet for what is actually happening;
this commit contains a fix for one possible answer: the sharing of the
NtpTrustedTime singleton can lead to successful refreshes producing new
cached time results that aren't being handled properly. Recent changes
made the current scheduling logic more susceptable to problems here.

This commit makes changes intended to ensure that a callback cannot be
scheduled in the past. It also explicitly resets the mTryAgainCounter to
zero if there is a recent-enough successful time refresh to avoid using
the "short" polling interval incorrectly when the latest refresh was
successful.

A test has been added that fails with old logic and passes with new
logic.

Bug: 269425914
Test: Local manual testing
Test: atest services/tests/servicestests/src/com/android/server/timedetector/NetworkTimeUpdateServiceTest.java
Change-Id: I0ae4cd94badaf25a7b951d33fc6414ea3332863e
parent 4ada8aaf
Loading
Loading
Loading
Loading
+130 −59
Original line number Diff line number Diff line
@@ -65,7 +65,7 @@ import java.util.function.Supplier;
 * If a request fails, it retries a number of times with a "short" interval and then resets to the
 * normal interval. The process then repeats.
 *
 * <p>When a valid network time is available, the time is always suggested to the {@link
 * <p>When a valid network time is available, the network time is always suggested to the {@link
 * com.android.server.timedetector.TimeDetectorService} where it may be used to set the device
 * system clock, depending on user settings and what other signals are available.
 */
@@ -286,7 +286,7 @@ public class NetworkTimeUpdateService extends Binder {
        }

        /**
         * Checks if the user prefers to automatically set the time.
         * Checks if the user prefers to automatically set the device's system clock time.
         */
        private boolean isAutomaticTimeEnabled() {
            ContentResolver resolver = mContext.getContentResolver();
@@ -313,7 +313,7 @@ public class NetworkTimeUpdateService extends Binder {
    }

    /**
     * The interface the service uses to interact with the time refresh logic.
     * The interface the service uses to interact with the network time refresh logic.
     * Extracted for testing.
     */
    @VisibleForTesting
@@ -387,10 +387,10 @@ public class NetworkTimeUpdateService extends Binder {
        private final NtpTrustedTime mNtpTrustedTime;

        /**
         * Records the time of the last refresh attempt (successful or otherwise) by this service.
         * This is used when scheduling the next refresh attempt. In cases where {@link
         * #refreshAndRescheduleIfRequired} is called too frequently, this will prevent each call
         * resulting in a network request. See also {@link #mShortPollingIntervalMillis}.
         * Records the elapsed realtime of the last refresh attempt (successful or otherwise) by
         * this service. This is used when scheduling the next refresh attempt. In cases where
         * {@link #refreshAndRescheduleIfRequired} is called too frequently, this will prevent each
         * call resulting in a network request. See also {@link #mShortPollingIntervalMillis}.
         *
         * <p>Time servers are a shared resource and so Android should avoid loading them.
         * Generally, a refresh attempt will succeed and the service won't need to make further
@@ -454,8 +454,11 @@ public class NetworkTimeUpdateService extends Binder {
                return;
            }

            // Attempt to refresh the network time if there is no latest time result, or if the
            // latest time result is considered too old.
            // Step 1: Work out if the latest time result, if any, needs to be refreshed and handle
            // the refresh.

            // A refresh should be attempted if there is no latest time result, or if the latest
            // time result is considered too old.
            NtpTrustedTime.TimeResult initialTimeResult = mNtpTrustedTime.getCachedTimeResult();
            boolean shouldAttemptRefresh;
            synchronized (this) {
@@ -472,22 +475,42 @@ public class NetworkTimeUpdateService extends Binder {
            boolean refreshSuccessful = false;
            if (shouldAttemptRefresh) {
                // This is a blocking call. Deliberately invoked without holding the "this" monitor
                // to avoid blocking logic that wants to use the "this" monitor.
                // to avoid blocking other logic that wants to use the "this" monitor, e.g. dump().
                refreshSuccessful = tryRefresh(network);
            }

            synchronized (this) {
                // Manage mTryAgainCounter.
                // This section of code deliberately doesn't assume it is the only component using
                // the NtpTrustedTime singleton to obtain NTP times: another component in the same
                // process could be gathering NTP signals (which then won't have been suggested to
                // the time detector).
                // TODO(b/222295093): Make this class the sole user of the NtpTrustedTime singleton
                //  and simplify / reduce duplicate suggestions and other logic.
                NtpTrustedTime.TimeResult latestTimeResult = mNtpTrustedTime.getCachedTimeResult();

                // currentElapsedRealtimeMillis is used to evaluate ages and refresh scheduling
                // below. Capturing this after obtaining the cached time result ensures that latest
                // time result ages will be >= 0.
                long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();

                long latestTimeResultAgeMillis = calculateTimeResultAgeMillis(
                        latestTimeResult, currentElapsedRealtimeMillis);

                // Step 2: Set mTryAgainCounter.
                //   + == 0: The last attempt was successful OR the latest time result is acceptable
                //           OR the mTryAgainCounter exceeded mTryAgainTimesMax and has been reset
                //           to 0. In all these cases the normal refresh interval should be used.
                //   + > 0: The last refresh attempt was unsuccessful. Some number of retries are
                //          allowed using the short interval depending on mTryAgainTimesMax.
                if (shouldAttemptRefresh) {
                    if (refreshSuccessful) {
                        // Reset failure tracking.
                        mTryAgainCounter = 0;
                    } else {
                        if (mTryAgainTimesMax < 0) {
                            // When mTryAgainTimesMax is negative there's no enforced maximum and
                            // short intervals should be used until a successful refresh. Setting
                            // mTryAgainCounter to 1 is sufficient for the interval calculations
                            // below. There's no need to increment.
                            // below, i.e. there's no need to increment.
                            mTryAgainCounter = 1;
                        } else {
                            mTryAgainCounter++;
@@ -497,58 +520,97 @@ public class NetworkTimeUpdateService extends Binder {
                        }
                    }
                }
                if (latestTimeResultAgeMillis < mNormalPollingIntervalMillis) {
                    // The latest time result may indicate a successful refresh has been achieved by
                    // another user of the NtpTrustedTime singleton. This could be an "else if", but
                    // this is deliberately done defensively in all cases to maintain the invariant
                    // that mTryAgainCounter will be 0 if the latest time result is currently ok.
                    mTryAgainCounter = 0;
                }

                // currentElapsedRealtimeMillis is used to evaluate ages and refresh scheduling
                // below. Capturing this after a possible successful refresh ensures that latest
                // time result ages will be >= 0.
                long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();

                // This section of code deliberately doesn't assume it is the only component using
                // mNtpTrustedTime to obtain NTP times: another component in the same process could
                // be gathering NTP signals (which then won't have been suggested to the time
                // detector).
                // TODO(b/222295093): Make this class the sole owner of mNtpTrustedTime and
                //  simplify / reduce duplicate suggestions.
                NtpTrustedTime.TimeResult latestTimeResult = mNtpTrustedTime.getCachedTimeResult();
                long latestTimeResultAgeMillis = calculateTimeResultAgeMillis(
                        latestTimeResult, currentElapsedRealtimeMillis);

                // Suggest the latest time result to the time detector if it is fresh regardless of
                // whether refresh happened above.
                // Step 3: Suggest the latest time result to the time detector if it is fresh
                // regardless of whether a refresh happened / succeeded above. The time detector
                // service can detect duplicate suggestions and not do more work than it has to, so
                // there is no need to avoid making duplicate suggestions.
                if (latestTimeResultAgeMillis < mNormalPollingIntervalMillis) {
                    // We assume the time detector service will detect duplicate suggestions and not
                    // do more work than it has to, so no need to avoid making duplicate
                    // suggestions.
                    makeNetworkTimeSuggestion(latestTimeResult, reason, refreshCallbacks);
                }

                // (Re)schedule the next refresh based on the latest state.
                // Determine which refresh delay to use by using the current value of
                // mTryAgainCounter. The refresh delay is applied to a different point in time
                // depending on whether the latest available time result (if any) is still
                // considered fresh to ensure the delay acts correctly.
                long refreshDelayMillis = mTryAgainCounter > 0
                // Step 4: (Re)schedule the next refresh attempt based on the latest state.

                // Determine which refresh attempt delay to use by using the current value of
                // mTryAgainCounter.
                long refreshAttemptDelayMillis = mTryAgainCounter > 0
                        ? mShortPollingIntervalMillis : mNormalPollingIntervalMillis;

                // The refresh attempt delay is applied to a different point in time depending on
                // whether a refresh attempt is overdue to ensure the refresh attempt scheduling
                // acts correctly / safely, i.e. won't schedule actions for immediate execution or
                // in the past.
                long nextRefreshElapsedRealtimeMillis;
                if (latestTimeResultAgeMillis < mNormalPollingIntervalMillis) {
                    // The latest time result is fresh, use it to determine when next to refresh.
                if (latestTimeResultAgeMillis < refreshAttemptDelayMillis) {
                    // The latestTimeResultAgeMillis and refreshAttemptDelayMillis indicate a
                    // refresh attempt is not yet due.  This branch uses the elapsed realtime of the
                    // latest time result to calculate when the latest time result will become too
                    // old and the next refresh attempt will be due.
                    //
                    // Possibilities:
                    //   + A refresh was attempted and successful, mTryAgainCounter will be set
                    //     to 0, refreshAttemptDelayMillis == mNormalPollingIntervalMillis, and this
                    //     branch will execute.
                    //   + No refresh was attempted, but something else refreshed the latest time
                    //     result held by the NtpTrustedTime.
                    //
                    // If a refresh was attempted but was unsuccessful, latestTimeResultAgeMillis >=
                    // mNormalPollingIntervalMillis (because otherwise it wouldn't be attempted),
                    // this branch won't be executed, and the one below will be instead.
                    nextRefreshElapsedRealtimeMillis =
                            latestTimeResult.getElapsedRealtimeMillis() + refreshDelayMillis;
                            latestTimeResult.getElapsedRealtimeMillis() + refreshAttemptDelayMillis;
                } else if (mLastRefreshAttemptElapsedRealtimeMillis != null) {
                    // The latest time result is missing or old and still needs to be refreshed.
                    // mLastRefreshAttemptElapsedRealtimeMillis, which should always be set by this
                    // point because there's no fresh time result, should be very close to
                    // currentElapsedRealtimeMillis unless the refresh was not allowed.
                    // This branch is executed when the latest time result is missing, or it's older
                    // than refreshAttemptDelayMillis. There may already have been attempts to
                    // refresh the network time that have failed, so the important point for this
                    // branch is not how old the latest time result is, but when the last refresh
                    // attempt took place:
                    //   + If a refresh was just attempted (and failed), then
                    //     mLastRefreshAttemptElapsedRealtimeMillis will be close to
                    //     currentElapsedRealtimeMillis.
                    //   + If a refresh was not just attempted, for a refresh not to have been
                    //     attempted EITHER:
                    //     + The latest time result must be < mNormalPollingIntervalMillis ago
                    //       (would be handled by the branch above)
                    //     + A refresh wasn't allowed because {time since last refresh attempt}
                    //       < mShortPollingIntervalMillis, so
                    //       (mLastRefreshAttemptElapsedRealtimeMillis + refreshAttemptDelayMillis)
                    //       would have to be in the future regardless of the
                    //       refreshAttemptDelayMillis value. This ignores the execution time
                    //       between the "current time" used to work out whether a refresh needed to
                    //       happen, and "current time" used to compute the last time result age,
                    //       but a single short interval shouldn't matter.
                    nextRefreshElapsedRealtimeMillis =
                            mLastRefreshAttemptElapsedRealtimeMillis + refreshDelayMillis;
                            mLastRefreshAttemptElapsedRealtimeMillis + refreshAttemptDelayMillis;
                } else {
                    // This should not happen: mLastRefreshAttemptElapsedRealtimeMillis should
                    // always be non-null by this point.
                    logToDebugAndDumpsys(
                            "mLastRefreshAttemptElapsedRealtimeMillis unexpectedly missing."
                                    + " Scheduling using currentElapsedRealtimeMillis");
                    // This branch should never execute: mLastRefreshAttemptElapsedRealtimeMillis
                    // should always be non-null because a refresh should always be attempted at
                    // least once above. Regardelss, the calculation below should result in safe
                    // scheduling behavior.
                    String logMsg = "mLastRefreshAttemptElapsedRealtimeMillis unexpectedly missing."
                            + " Scheduling using currentElapsedRealtimeMillis";
                    Log.w(TAG, logMsg);
                    logToDebugAndDumpsys(logMsg);
                    nextRefreshElapsedRealtimeMillis =
                            currentElapsedRealtimeMillis + refreshAttemptDelayMillis;
                }

                // Defensive coding to guard against bad scheduling / logic errors above: Try to
                // ensure that alarms aren't scheduled in the past.
                if (nextRefreshElapsedRealtimeMillis <= currentElapsedRealtimeMillis) {
                    String logMsg = "nextRefreshElapsedRealtimeMillis is a time in the past."
                            + " Scheduling using currentElapsedRealtimeMillis instead";
                    Log.w(TAG, logMsg);
                    logToDebugAndDumpsys(logMsg);
                    nextRefreshElapsedRealtimeMillis =
                            currentElapsedRealtimeMillis + refreshDelayMillis;
                            currentElapsedRealtimeMillis + refreshAttemptDelayMillis;
                }
                refreshCallbacks.scheduleNextRefresh(nextRefreshElapsedRealtimeMillis);

@@ -562,7 +624,7 @@ public class NetworkTimeUpdateService extends Binder {
                        + formatElapsedRealtimeMillis(currentElapsedRealtimeMillis)
                        + ", latestTimeResult=" + latestTimeResult
                        + ", mTryAgainCounter=" + mTryAgainCounter
                        + ", refreshDelayMillis=" + refreshDelayMillis
                        + ", refreshAttemptDelayMillis=" + refreshAttemptDelayMillis
                        + ", nextRefreshElapsedRealtimeMillis="
                        + formatElapsedRealtimeMillis(nextRefreshElapsedRealtimeMillis));
            }
@@ -592,6 +654,12 @@ public class NetworkTimeUpdateService extends Binder {
            return currentElapsedRealtimeMillis >= nextRefreshAllowedElapsedRealtimeMillis;
        }

        /**
         * Attempts a network time refresh. Updates {@link
         * #mLastRefreshAttemptElapsedRealtimeMillis} regardless of the outcome and returns whether
         * the attempt was successful. The latest successful refresh result can be found in {@link
         * NtpTrustedTime#getCachedTimeResult()}.
         */
        private boolean tryRefresh(@NonNull Network network) {
            long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();
            synchronized (this) {
@@ -600,15 +668,18 @@ public class NetworkTimeUpdateService extends Binder {
            return mNtpTrustedTime.forceRefresh(network);
        }

        /** Suggests the time to the time detector. It may choose use it to set the system clock. */
        private void makeNetworkTimeSuggestion(@NonNull TimeResult ntpResult,
        /**
         * Suggests the network time to the time detector. It may choose use it to set the system
         * clock.
         */
        private void makeNetworkTimeSuggestion(@NonNull TimeResult timeResult,
                @NonNull String debugInfo, @NonNull RefreshCallbacks refreshCallbacks) {
            UnixEpochTime timeSignal = new UnixEpochTime(
                    ntpResult.getElapsedRealtimeMillis(), ntpResult.getTimeMillis());
                    timeResult.getElapsedRealtimeMillis(), timeResult.getTimeMillis());
            NetworkTimeSuggestion timeSuggestion =
                    new NetworkTimeSuggestion(timeSignal, ntpResult.getUncertaintyMillis());
                    new NetworkTimeSuggestion(timeSignal, timeResult.getUncertaintyMillis());
            timeSuggestion.addDebugInfo(debugInfo);
            timeSuggestion.addDebugInfo(ntpResult.toString());
            timeSuggestion.addDebugInfo(timeResult.toString());
            refreshCallbacks.submitSuggestion(timeSuggestion);
        }

+135 −34

File changed.

Preview size limit exceeded, changes collapsed.