Improve debug / bug report logging for time zones
Pushing the local debug logging responsibility down to SystemTimeZone.
Now that all time zone changes go through system time zone, it makes
sense that the logging is moved there. This means that changes for any
reason, now including initial device initialization, and API / shell
command calls can be logged, which previously wasn't the case.
Bug: 236612872
Test: build / boot / factory reset / manual inspection of dumpsys
Test: treehugger
Change-Id: I1e7cf86ae89a73c31e036f68f32f99fae4d6392a
diff --git a/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java b/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java
index 232d3c9..901796b 100644
--- a/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java
+++ b/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java
@@ -2153,7 +2153,7 @@
}
}
- void setTimeZoneImpl(String tzId, @TimeZoneConfidence int confidence) {
+ void setTimeZoneImpl(String tzId, @TimeZoneConfidence int confidence, String logInfo) {
if (TextUtils.isEmpty(tzId)) {
return;
}
@@ -2166,7 +2166,7 @@
// TimeZone.getTimeZone() can return a time zone with a different ID (e.g. it can return
// "GMT" if the ID is unrecognized). The parameter ID is used here rather than
// newZone.getId(). It will be rejected if it is invalid.
- timeZoneWasChanged = SystemTimeZone.setTimeZoneId(tzId, confidence);
+ timeZoneWasChanged = SystemTimeZone.setTimeZoneId(tzId, confidence, logInfo);
if (KERNEL_TIME_ZONE_SYNC_ENABLED) {
// Update the kernel timezone information
@@ -2706,8 +2706,9 @@
}
@Override
- public void setTimeZone(String tzId, @TimeZoneConfidence int confidence) {
- setTimeZoneImpl(tzId, confidence);
+ public void setTimeZone(String tzId, @TimeZoneConfidence int confidence,
+ String logInfo) {
+ setTimeZoneImpl(tzId, confidence, logInfo);
}
@Override
@@ -3010,7 +3011,7 @@
// of confidence, but since the time zone ID should come either from apps working on
// behalf of the user or a developer, confidence is assumed "high".
final int timeZoneConfidence = TIME_ZONE_CONFIDENCE_HIGH;
- setTimeZoneImpl(tz, timeZoneConfidence);
+ setTimeZoneImpl(tz, timeZoneConfidence, "AlarmManager.setTimeZone() called");
} finally {
Binder.restoreCallingIdentity(oldId);
}
diff --git a/services/core/java/com/android/server/AlarmManagerInternal.java b/services/core/java/com/android/server/AlarmManagerInternal.java
index 67aa2b9..b6a8227 100644
--- a/services/core/java/com/android/server/AlarmManagerInternal.java
+++ b/services/core/java/com/android/server/AlarmManagerInternal.java
@@ -59,8 +59,9 @@
* @param tzId the time zone ID
* @param confidence the confidence that {@code tzId} is correct, see {@link TimeZoneConfidence}
* for details
+ * @param logInfo the reason the time zone is being changed, for bug report logging
*/
- void setTimeZone(String tzId, @TimeZoneConfidence int confidence);
+ void setTimeZone(String tzId, @TimeZoneConfidence int confidence, String logInfo);
/**
* Sets the device's current time and time confidence.
diff --git a/services/core/java/com/android/server/SystemTimeZone.java b/services/core/java/com/android/server/SystemTimeZone.java
index 7ce0831..dd07081 100644
--- a/services/core/java/com/android/server/SystemTimeZone.java
+++ b/services/core/java/com/android/server/SystemTimeZone.java
@@ -19,12 +19,15 @@
import static java.lang.annotation.RetentionPolicy.SOURCE;
import android.annotation.IntDef;
+import android.annotation.NonNull;
import android.os.SystemProperties;
import android.text.TextUtils;
+import android.util.LocalLog;
import android.util.Slog;
import com.android.i18n.timezone.ZoneInfoDb;
+import java.io.PrintWriter;
import java.lang.annotation.Retention;
import java.lang.annotation.Target;
@@ -70,6 +73,14 @@
*/
public static final @TimeZoneConfidence int TIME_ZONE_CONFIDENCE_HIGH = 100;
+ /**
+ * An in-memory log that records the debug info related to the device's time zone setting.
+ * This is logged in bug reports to assist with debugging time zone detection issues.
+ */
+ @NonNull
+ private static final LocalLog sTimeZoneDebugLog =
+ new LocalLog(30, false /* useLocalTimestamps */);
+
private SystemTimeZone() {}
/**
@@ -78,27 +89,44 @@
public static void initializeTimeZoneSettingsIfRequired() {
String timezoneProperty = SystemProperties.get(TIME_ZONE_SYSTEM_PROPERTY);
if (!isValidTimeZoneId(timezoneProperty)) {
- Slog.w(TAG, TIME_ZONE_SYSTEM_PROPERTY + " is not valid (" + timezoneProperty
- + "); setting to " + DEFAULT_TIME_ZONE_ID);
- setTimeZoneId(DEFAULT_TIME_ZONE_ID, TIME_ZONE_CONFIDENCE_LOW);
+ String logInfo = "initializeTimeZoneSettingsIfRequired():" + TIME_ZONE_SYSTEM_PROPERTY
+ + " is not valid (" + timezoneProperty + "); setting to "
+ + DEFAULT_TIME_ZONE_ID;
+ Slog.w(TAG, logInfo);
+ setTimeZoneId(DEFAULT_TIME_ZONE_ID, TIME_ZONE_CONFIDENCE_LOW, logInfo);
}
}
/**
- * Updates the device's time zone system property and associated metadata. Returns {@code true}
- * if the device's time zone changed, {@code false} if the ID is invalid or the device is
- * already set to the supplied ID.
+ * Adds an entry to the system time zone debug log that is included in bug reports. This method
+ * is intended to be used to record event that may lead to a time zone change, e.g. config or
+ * mode changes.
+ */
+ public static void addDebugLogEntry(@NonNull String logMsg) {
+ sTimeZoneDebugLog.log(logMsg);
+ }
+
+ /**
+ * Updates the device's time zone system property, associated metadata and adds an entry to the
+ * debug log. Returns {@code true} if the device's time zone changed, {@code false} if the ID is
+ * invalid or the device is already set to the supplied ID.
*
* <p>This method ensures the confidence metadata is set to the supplied value if the supplied
* time zone ID is considered valid.
*
* <p>This method is intended only for use by the AlarmManager. When changing the device's time
* zone other system service components must use {@link
- * com.android.server.AlarmManagerInternal#setTimeZone(String, int)} to ensure that important
+ * AlarmManagerInternal#setTimeZone(String, int, String)} to ensure that important
* system-wide side effects occur.
*/
- public static boolean setTimeZoneId(String timeZoneId, @TimeZoneConfidence int confidence) {
+ public static boolean setTimeZoneId(
+ @NonNull String timeZoneId, @TimeZoneConfidence int confidence,
+ @NonNull String logInfo) {
if (TextUtils.isEmpty(timeZoneId) || !isValidTimeZoneId(timeZoneId)) {
+ addDebugLogEntry("setTimeZoneId: Invalid time zone ID."
+ + " timeZoneId=" + timeZoneId
+ + ", confidence=" + confidence
+ + ", logInfo=" + logInfo);
return false;
}
@@ -112,7 +140,14 @@
}
timeZoneChanged = true;
}
- setTimeZoneConfidence(confidence);
+ boolean timeZoneConfidenceChanged = setTimeZoneConfidence(confidence);
+ if (timeZoneChanged || timeZoneConfidenceChanged) {
+ String logMsg = "Time zone or confidence set: "
+ + " (new) timeZoneId=" + timeZoneId
+ + ", (new) confidence=" + confidence
+ + ", logInfo=" + logInfo;
+ addDebugLogEntry(logMsg);
+ }
}
return timeZoneChanged;
@@ -121,16 +156,18 @@
/**
* Sets the time zone confidence value if required. See {@link TimeZoneConfidence} for details.
*/
- private static void setTimeZoneConfidence(@TimeZoneConfidence int confidence) {
+ private static boolean setTimeZoneConfidence(@TimeZoneConfidence int newConfidence) {
int currentConfidence = getTimeZoneConfidence();
- if (currentConfidence != confidence) {
+ if (currentConfidence != newConfidence) {
SystemProperties.set(
- TIME_ZONE_CONFIDENCE_SYSTEM_PROPERTY, Integer.toString(confidence));
+ TIME_ZONE_CONFIDENCE_SYSTEM_PROPERTY, Integer.toString(newConfidence));
if (DEBUG) {
Slog.v(TAG, "Time zone confidence changed: old=" + currentConfidence
- + ", new=" + confidence);
+ + ", newConfidence=" + newConfidence);
}
+ return true;
}
+ return false;
}
/** Returns the time zone confidence value. See {@link TimeZoneConfidence} for details. */
@@ -148,6 +185,13 @@
return SystemProperties.get(TIME_ZONE_SYSTEM_PROPERTY);
}
+ /**
+ * Dumps information about recent time zone decisions / changes to the supplied writer.
+ */
+ public static void dump(PrintWriter writer) {
+ sTimeZoneDebugLog.dump(writer);
+ }
+
private static boolean isValidTimeZoneConfidence(@TimeZoneConfidence int confidence) {
return confidence >= TIME_ZONE_CONFIDENCE_LOW && confidence <= TIME_ZONE_CONFIDENCE_HIGH;
}
diff --git a/services/core/java/com/android/server/timezonedetector/EnvironmentImpl.java b/services/core/java/com/android/server/timezonedetector/EnvironmentImpl.java
index d973ca6..4749f73 100644
--- a/services/core/java/com/android/server/timezonedetector/EnvironmentImpl.java
+++ b/services/core/java/com/android/server/timezonedetector/EnvironmentImpl.java
@@ -28,6 +28,7 @@
import com.android.server.SystemTimeZone;
import com.android.server.SystemTimeZone.TimeZoneConfidence;
+import java.io.PrintWriter;
import java.util.Objects;
/**
@@ -57,6 +58,7 @@
}
@Override
+ @NonNull
public ConfigurationInternal getCurrentUserConfigurationInternal() {
return mServiceConfigAccessor.getCurrentUserConfigurationInternal();
}
@@ -74,14 +76,25 @@
@Override
public void setDeviceTimeZoneAndConfidence(
- @NonNull String zoneId, @TimeZoneConfidence int confidence) {
+ @NonNull String zoneId, @TimeZoneConfidence int confidence,
+ @NonNull String logInfo) {
AlarmManagerInternal alarmManagerInternal =
LocalServices.getService(AlarmManagerInternal.class);
- alarmManagerInternal.setTimeZone(zoneId, confidence);
+ alarmManagerInternal.setTimeZone(zoneId, confidence, logInfo);
}
@Override
public @ElapsedRealtimeLong long elapsedRealtimeMillis() {
return SystemClock.elapsedRealtime();
}
+
+ @Override
+ public void addDebugLogEntry(@NonNull String logMsg) {
+ SystemTimeZone.addDebugLogEntry(logMsg);
+ }
+
+ @Override
+ public void dumpDebugLog(@NonNull PrintWriter printWriter) {
+ SystemTimeZone.dump(printWriter);
+ }
}
diff --git a/services/core/java/com/android/server/timezonedetector/TimeZoneDetectorStrategyImpl.java b/services/core/java/com/android/server/timezonedetector/TimeZoneDetectorStrategyImpl.java
index 9b35779..6f227ee 100644
--- a/services/core/java/com/android/server/timezonedetector/TimeZoneDetectorStrategyImpl.java
+++ b/services/core/java/com/android/server/timezonedetector/TimeZoneDetectorStrategyImpl.java
@@ -36,13 +36,13 @@
import android.os.Handler;
import android.os.TimestampedValue;
import android.util.IndentingPrintWriter;
-import android.util.LocalLog;
import android.util.Slog;
import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;
import com.android.server.SystemTimeZone.TimeZoneConfidence;
+import java.io.PrintWriter;
import java.time.Duration;
import java.util.List;
import java.util.Objects;
@@ -86,10 +86,11 @@
@TimeZoneConfidence int getDeviceTimeZoneConfidence();
/**
- * Sets the device's time zone and associated confidence.
+ * Sets the device's time zone, associated confidence, and records a debug log entry.
*/
void setDeviceTimeZoneAndConfidence(
- @NonNull String zoneId, @TimeZoneConfidence int confidence);
+ @NonNull String zoneId, @TimeZoneConfidence int confidence,
+ @NonNull String logInfo);
/**
* Returns the time according to the elapsed realtime clock, the same as {@link
@@ -97,6 +98,16 @@
*/
@ElapsedRealtimeLong
long elapsedRealtimeMillis();
+
+ /**
+ * Adds a standalone entry to the time zone debug log.
+ */
+ void addDebugLogEntry(@NonNull String logMsg);
+
+ /**
+ * Dumps the time zone debug log to the supplied {@link PrintWriter}.
+ */
+ void dumpDebugLog(PrintWriter printWriter);
}
private static final String LOG_TAG = TimeZoneDetectorService.TAG;
@@ -169,13 +180,6 @@
private final Environment mEnvironment;
/**
- * A log that records the decisions / decision metadata that affected the device's time zone.
- * This is logged in bug reports to assist with debugging issues with detection.
- */
- @NonNull
- private final LocalLog mTimeZoneChangesLog = new LocalLog(30, false /* useLocalTimestamps */);
-
- /**
* A mapping from slotIndex to a telephony time zone suggestion. We typically expect one or two
* mappings: devices will have a small number of telephony devices and slotIndexes are assumed
* to be stable.
@@ -299,7 +303,7 @@
TimeZoneCapabilities capabilities = capabilitiesAndConfig.getCapabilities();
if (capabilities.getSuggestManualTimeZoneCapability() != CAPABILITY_POSSESSED) {
Slog.i(LOG_TAG, "User does not have the capability needed to set the time zone manually"
- + ", capabilities=" + capabilities
+ + ": capabilities=" + capabilities
+ ", timeZoneId=" + timeZoneId
+ ", cause=" + cause);
return false;
@@ -349,11 +353,11 @@
mTelephonyTimeZoneFallbackEnabled = new TimestampedValue<>(
mEnvironment.elapsedRealtimeMillis(), fallbackEnabled);
- String logMsg = "enableTelephonyTimeZoneFallbackMode"
- + ": currentUserConfig=" + currentUserConfig
+ String logMsg = "enableTelephonyTimeZoneFallbackMode: "
+ + " currentUserConfig=" + currentUserConfig
+ ", mTelephonyTimeZoneFallbackEnabled="
+ mTelephonyTimeZoneFallbackEnabled;
- logTimeZoneDetectorChange(logMsg);
+ logTimeZoneDebugInfo(logMsg);
// mTelephonyTimeZoneFallbackEnabled and mLatestGeoLocationSuggestion interact.
// If there is currently a certain geolocation suggestion, then the telephony fallback
@@ -558,19 +562,18 @@
mTelephonyTimeZoneFallbackEnabled = new TimestampedValue<>(
mEnvironment.elapsedRealtimeMillis(), fallbackEnabled);
- String logMsg = "disableTelephonyFallbackIfNeeded"
- + ": mTelephonyTimeZoneFallbackEnabled="
- + mTelephonyTimeZoneFallbackEnabled;
- logTimeZoneDetectorChange(logMsg);
+ String logMsg = "disableTelephonyFallbackIfNeeded:"
+ + " mTelephonyTimeZoneFallbackEnabled=" + mTelephonyTimeZoneFallbackEnabled;
+ logTimeZoneDebugInfo(logMsg);
}
}
}
- private void logTimeZoneDetectorChange(@NonNull String logMsg) {
+ private void logTimeZoneDebugInfo(@NonNull String logMsg) {
if (DBG) {
Slog.d(LOG_TAG, logMsg);
}
- mTimeZoneChangesLog.log(logMsg);
+ mEnvironment.addDebugLogEntry(logMsg);
}
/**
@@ -598,7 +601,7 @@
bestTelephonySuggestion.score >= TELEPHONY_SCORE_USAGE_THRESHOLD;
if (!suggestionGoodEnough) {
if (DBG) {
- Slog.d(LOG_TAG, "Best suggestion not good enough."
+ Slog.d(LOG_TAG, "Best suggestion not good enough:"
+ " bestTelephonySuggestion=" + bestTelephonySuggestion
+ ", detectionReason=" + detectionReason);
}
@@ -611,12 +614,12 @@
if (zoneId == null) {
Slog.w(LOG_TAG, "Empty zone suggestion scored higher than expected. This is an error:"
+ " bestTelephonySuggestion=" + bestTelephonySuggestion
- + " detectionReason=" + detectionReason);
+ + ", detectionReason=" + detectionReason);
return;
}
- String cause = "Found good suggestion."
- + ", bestTelephonySuggestion=" + bestTelephonySuggestion
+ String cause = "Found good suggestion:"
+ + " bestTelephonySuggestion=" + bestTelephonySuggestion
+ ", detectionReason=" + detectionReason;
setDeviceTimeZoneIfRequired(zoneId, cause);
}
@@ -634,9 +637,8 @@
if (newZoneId.equals(currentZoneId) && newConfidence <= currentConfidence) {
// No need to modify the device time zone settings.
if (DBG) {
- Slog.d(LOG_TAG, "No need to change the time zone;"
- + " device is already set to newZoneId."
- + ", newZoneId=" + newZoneId
+ Slog.d(LOG_TAG, "No need to change the time zone device is already set to newZoneId"
+ + ": newZoneId=" + newZoneId
+ ", cause=" + cause
+ ", currentScore=" + currentConfidence
+ ", newConfidence=" + newConfidence);
@@ -644,13 +646,14 @@
return;
}
- mEnvironment.setDeviceTimeZoneAndConfidence(newZoneId, newConfidence);
- String logMsg = "Set device time zone or higher confidence."
- + ", currentZoneId=" + currentZoneId
- + ", newZoneId=" + newZoneId
+ String logInfo = "Set device time zone or higher confidence:"
+ + " newZoneId=" + newZoneId
+ ", cause=" + cause
+ ", newConfidence=" + newConfidence;
- logTimeZoneDetectorChange(logMsg);
+ if (DBG) {
+ Slog.d(LOG_TAG, logInfo);
+ }
+ mEnvironment.setDeviceTimeZoneAndConfidence(newZoneId, newConfidence, logInfo);
}
@GuardedBy("this")
@@ -702,7 +705,7 @@
String logMsg = "handleConfigurationInternalChanged:"
+ " oldConfiguration=" + mCurrentConfigurationInternal
+ ", newConfiguration=" + currentUserConfig;
- logTimeZoneDetectorChange(logMsg);
+ logTimeZoneDebugInfo(logMsg);
mCurrentConfigurationInternal = currentUserConfig;
// The configuration change may have changed available suggestions or the way suggestions
@@ -731,9 +734,9 @@
+ formatDebugString(mTelephonyTimeZoneFallbackEnabled));
ipw.decreaseIndent(); // level 2
- ipw.println("Time zone change log:");
+ ipw.println("Time zone debug log:");
ipw.increaseIndent(); // level 2
- mTimeZoneChangesLog.dump(ipw);
+ mEnvironment.dumpDebugLog(ipw);
ipw.decreaseIndent(); // level 2
ipw.println("Manual suggestion history:");
diff --git a/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java b/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
index fbb853793..972d4e8 100644
--- a/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
+++ b/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
@@ -12551,9 +12551,10 @@
if (mInjector.settingsGlobalGetInt(Global.AUTO_TIME_ZONE, 0) == 1) {
return false;
}
+ String logInfo = "DevicePolicyManager.setTimeZone()";
mInjector.binderWithCleanCallingIdentity(() ->
mInjector.getAlarmManagerInternal()
- .setTimeZone(timeZone, TIME_ZONE_CONFIDENCE_HIGH));
+ .setTimeZone(timeZone, TIME_ZONE_CONFIDENCE_HIGH, logInfo));
DevicePolicyEventLogger
.createEvent(DevicePolicyEnums.SET_TIME_ZONE)
diff --git a/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java b/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java
index 830e2ac..e2b25ef 100644
--- a/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java
+++ b/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java
@@ -3438,7 +3438,7 @@
public void setTimeZoneImpl() {
final long durationMs = 20000L;
when(mActivityManagerInternal.getBootTimeTempAllowListDuration()).thenReturn(durationMs);
- mService.setTimeZoneImpl("UTC", TIME_ZONE_CONFIDENCE_HIGH);
+ mService.setTimeZoneImpl("UTC", TIME_ZONE_CONFIDENCE_HIGH, "AlarmManagerServiceTest");
final ArgumentCaptor<Intent> intentCaptor = ArgumentCaptor.forClass(Intent.class);
final ArgumentCaptor<Bundle> bundleCaptor = ArgumentCaptor.forClass(Bundle.class);
verify(mMockContext).sendBroadcastAsUser(intentCaptor.capture(), eq(UserHandle.ALL),
diff --git a/services/tests/servicestests/src/com/android/server/devicepolicy/DevicePolicyManagerTest.java b/services/tests/servicestests/src/com/android/server/devicepolicy/DevicePolicyManagerTest.java
index 0bdcac6..ddb3049 100644
--- a/services/tests/servicestests/src/com/android/server/devicepolicy/DevicePolicyManagerTest.java
+++ b/services/tests/servicestests/src/com/android/server/devicepolicy/DevicePolicyManagerTest.java
@@ -4503,7 +4503,7 @@
setupDeviceOwner();
dpm.setTimeZone(admin1, "Asia/Shanghai");
verify(getServices().alarmManagerInternal)
- .setTimeZone("Asia/Shanghai", TIME_ZONE_CONFIDENCE_HIGH);
+ .setTimeZone(eq("Asia/Shanghai"), eq(TIME_ZONE_CONFIDENCE_HIGH), anyString());
}
@Test
@@ -4519,7 +4519,7 @@
configureProfileOwnerOfOrgOwnedDevice(admin1, CALLER_USER_HANDLE);
dpm.setTimeZone(admin1, "Asia/Shanghai");
verify(getServices().alarmManagerInternal)
- .setTimeZone("Asia/Shanghai", TIME_ZONE_CONFIDENCE_HIGH);
+ .setTimeZone(eq("Asia/Shanghai"), eq(TIME_ZONE_CONFIDENCE_HIGH), anyString());
}
@Test
diff --git a/services/tests/servicestests/src/com/android/server/timezonedetector/TimeZoneDetectorStrategyImplTest.java b/services/tests/servicestests/src/com/android/server/timezonedetector/TimeZoneDetectorStrategyImplTest.java
index ff838fd..81d3f30 100644
--- a/services/tests/servicestests/src/com/android/server/timezonedetector/TimeZoneDetectorStrategyImplTest.java
+++ b/services/tests/servicestests/src/com/android/server/timezonedetector/TimeZoneDetectorStrategyImplTest.java
@@ -51,6 +51,7 @@
import org.junit.Before;
import org.junit.Test;
+import java.io.PrintWriter;
import java.util.Arrays;
import java.util.Collections;
import java.util.List;
@@ -1155,7 +1156,7 @@
@Override
public void setDeviceTimeZoneAndConfidence(
- String zoneId, @TimeZoneConfidence int confidence) {
+ String zoneId, @TimeZoneConfidence int confidence, String logInfo) {
mTimeZoneId.set(zoneId);
mTimeZoneConfidence = confidence;
}
@@ -1185,6 +1186,16 @@
public long elapsedRealtimeMillis() {
return mElapsedRealtimeMillis;
}
+
+ @Override
+ public void addDebugLogEntry(String logMsg) {
+ // No-op for tests
+ }
+
+ @Override
+ public void dumpDebugLog(PrintWriter printWriter) {
+ // No-op for tests
+ }
}
/**