From a340bfd7a1e639bb50125a62cfb1a14e2565607e Mon Sep 17 00:00:00 2001 From: Svetoslav Ganov Date: Tue, 2 Aug 2016 18:24:49 -0700 Subject: [PATCH] Add historical logging to settings provider This change adds historical operations to the dump state of the settings provider. The historica operations are currently appended only on user-debug and eng builds. These change is needed to help diagnose the referred bug and improve the settings provider's maintenance. bug:30561721 Change-Id: I58a1ba0d598c4d28adcb5e654ebb78cf947e94db --- .../providers/settings/EventLogTags.logtags | 3 +- .../providers/settings/SettingsProvider.java | 16 ++- .../providers/settings/SettingsState.java | 113 ++++++++++++++++-- .../providers/settings/SettingsStateTest.java | 9 +- 4 files changed, 124 insertions(+), 17 deletions(-) diff --git a/packages/SettingsProvider/src/com/android/providers/settings/EventLogTags.logtags b/packages/SettingsProvider/src/com/android/providers/settings/EventLogTags.logtags index 298d7768d01ff..7eff16b0def4c 100644 --- a/packages/SettingsProvider/src/com/android/providers/settings/EventLogTags.logtags +++ b/packages/SettingsProvider/src/com/android/providers/settings/EventLogTags.logtags @@ -1,5 +1,6 @@ -# See system/core/logcat/e for a description of the format of this file. +# See system/core/logcat/event.logtags for a description of the format of this file. option java_package com.android.providers.settings; 52100 unsupported_settings_query (uri|3),(selection|3),(whereArgs|3) +52101 persist_setting_error (message|3) diff --git a/packages/SettingsProvider/src/com/android/providers/settings/SettingsProvider.java b/packages/SettingsProvider/src/com/android/providers/settings/SettingsProvider.java index d27f1f830c327..0f7fe6fc5124f 100644 --- a/packages/SettingsProvider/src/com/android/providers/settings/SettingsProvider.java +++ b/packages/SettingsProvider/src/com/android/providers/settings/SettingsProvider.java @@ -544,7 +544,7 @@ public class SettingsProvider extends ContentProvider { final int userCount = users.size(); for (int i = 0; i < userCount; i++) { UserInfo user = users.get(i); - dumpForUser(user.id, pw); + dumpForUserLocked(user.id, pw); } } finally { Binder.restoreCallingIdentity(identity); @@ -552,12 +552,16 @@ public class SettingsProvider extends ContentProvider { } } - private void dumpForUser(int userId, PrintWriter pw) { + private void dumpForUserLocked(int userId, PrintWriter pw) { if (userId == UserHandle.USER_SYSTEM) { pw.println("GLOBAL SETTINGS (user " + userId + ")"); Cursor globalCursor = getAllGlobalSettings(ALL_COLUMNS); dumpSettings(globalCursor, pw); pw.println(); + + SettingsState globalSettings = mSettingsRegistry.getSettingsLocked( + SETTINGS_TYPE_GLOBAL, UserHandle.USER_SYSTEM); + globalSettings.dumpHistoricalOperations(pw); } pw.println("SECURE SETTINGS (user " + userId + ")"); @@ -565,10 +569,18 @@ public class SettingsProvider extends ContentProvider { dumpSettings(secureCursor, pw); pw.println(); + SettingsState secureSettings = mSettingsRegistry.getSettingsLocked( + SETTINGS_TYPE_SECURE, userId); + secureSettings.dumpHistoricalOperations(pw); + pw.println("SYSTEM SETTINGS (user " + userId + ")"); Cursor systemCursor = getAllSystemSettings(userId, ALL_COLUMNS); dumpSettings(systemCursor, pw); pw.println(); + + SettingsState systemSettings = mSettingsRegistry.getSettingsLocked( + SETTINGS_TYPE_SYSTEM, userId); + systemSettings.dumpHistoricalOperations(pw); } private void dumpSettings(Cursor cursor, PrintWriter pw) { diff --git a/packages/SettingsProvider/src/com/android/providers/settings/SettingsState.java b/packages/SettingsProvider/src/com/android/providers/settings/SettingsState.java index 4710d5adf3acd..bc91545ef13f5 100644 --- a/packages/SettingsProvider/src/com/android/providers/settings/SettingsState.java +++ b/packages/SettingsProvider/src/com/android/providers/settings/SettingsState.java @@ -16,6 +16,7 @@ package com.android.providers.settings; +import android.os.Build; import android.os.Handler; import android.os.Looper; import android.os.Message; @@ -26,6 +27,7 @@ import android.util.ArrayMap; import android.util.AtomicFile; import android.util.Base64; import android.util.Slog; +import android.util.TimeUtils; import android.util.Xml; import com.android.internal.annotations.GuardedBy; import libcore.io.IoUtils; @@ -39,6 +41,7 @@ import java.io.FileInputStream; import java.io.FileNotFoundException; import java.io.FileOutputStream; import java.io.IOException; +import java.io.PrintWriter; import java.nio.charset.StandardCharsets; import java.util.ArrayList; import java.util.List; @@ -60,7 +63,7 @@ final class SettingsState { private static final String LOG_TAG = "SettingsState"; - static final int SETTINGS_VERSOIN_NEW_ENCODING = 121; + static final int SETTINGS_VERSION_NEW_ENCODING = 121; private static final long WRITE_SETTINGS_DELAY_MILLIS = 200; private static final long MAX_WRITE_SETTINGS_DELAY_MILLIS = 2000; @@ -93,6 +96,12 @@ final class SettingsState { // This was used in version 120 and before. private static final String NULL_VALUE_OLD_STYLE = "null"; + private static final int HISTORICAL_OPERATION_COUNT = 20; + private static final String HISTORICAL_OPERATION_UPDATE = "update"; + private static final String HISTORICAL_OPERATION_DELETE = "delete"; + private static final String HISTORICAL_OPERATION_PERSIST = "persist"; + private static final String HISTORICAL_OPERATION_INITIALIZE = "initialize"; + private final Object mLock; private final Handler mHandler; @@ -116,6 +125,9 @@ final class SettingsState { } }; + @GuardedBy("mLock") + private final List mHistoricalOperations; + @GuardedBy("mLock") public final int mKey; @@ -134,6 +146,9 @@ final class SettingsState { @GuardedBy("mLock") private long mNextId; + @GuardedBy("mLock") + private int mNextHistoricalOpIdx; + public SettingsState(Object lock, File file, int key, int maxBytesPerAppPackage, Looper looper) { // It is important that we use the same lock as the settings provider @@ -150,6 +165,10 @@ final class SettingsState { mMaxBytesPerAppPackage = maxBytesPerAppPackage; mPackageToMemoryUsage = null; } + + mHistoricalOperations = Build.IS_DEBUGGABLE + ? new ArrayList<>(HISTORICAL_OPERATION_COUNT) : null; + synchronized (mLock) { readStateSyncLocked(); } @@ -238,16 +257,20 @@ final class SettingsState { Setting oldState = mSettings.get(name); String oldValue = (oldState != null) ? oldState.value : null; + Setting newState; if (oldState != null) { if (!oldState.update(value, packageName)) { return false; } + newState = oldState; } else { - Setting state = new Setting(name, value, packageName); - mSettings.put(name, state); + newState = new Setting(name, value, packageName); + mSettings.put(name, newState); } + addHistoricalOperationLocked(HISTORICAL_OPERATION_UPDATE, newState); + updateMemoryUsagePerPackageLocked(packageName, oldValue, value); scheduleWriteIfNeededLocked(); @@ -271,6 +294,8 @@ final class SettingsState { updateMemoryUsagePerPackageLocked(oldState.packageName, oldState.value, null); + addHistoricalOperationLocked(HISTORICAL_OPERATION_DELETE, oldState); + scheduleWriteIfNeededLocked(); return true; @@ -290,6 +315,51 @@ final class SettingsState { } } + private void addHistoricalOperationLocked(String type, Setting setting) { + if (mHistoricalOperations == null) { + return; + } + HistoricalOperation operation = new HistoricalOperation( + SystemClock.elapsedRealtime(), type, + setting != null ? new Setting(setting) : null); + if (mNextHistoricalOpIdx >= mHistoricalOperations.size()) { + mHistoricalOperations.add(operation); + } else { + mHistoricalOperations.set(mNextHistoricalOpIdx, operation); + } + mNextHistoricalOpIdx++; + if (mNextHistoricalOpIdx >= HISTORICAL_OPERATION_COUNT) { + mNextHistoricalOpIdx = 0; + } + } + + public void dumpHistoricalOperations(PrintWriter pw) { + synchronized (mLock) { + if (mHistoricalOperations == null) { + return; + } + pw.println("Historical operations"); + final int operationCount = mHistoricalOperations.size(); + for (int i = 0; i < operationCount; i++) { + int index = mNextHistoricalOpIdx - 1 - i; + if (index < 0) { + index = operationCount + index; + } + HistoricalOperation operation = mHistoricalOperations.get(index); + pw.print(TimeUtils.formatForLogging(operation.mTimestamp)); + pw.print(" "); + pw.print(operation.mOperation); + if (operation.mSetting != null) { + pw.print(" "); + pw.print(operation.mSetting); + } + pw.println(); + } + pw.println(); + pw.println(); + } + } + private void updateMemoryUsagePerPackageLocked(String packageName, String oldValue, String newValue) { if (mMaxBytesPerAppPackage == MAX_BYTES_PER_APP_PACKAGE_UNLIMITED) { @@ -407,6 +477,10 @@ final class SettingsState { serializer.endDocument(); destination.finishWrite(out); + synchronized (mLock) { + addHistoricalOperationLocked(HISTORICAL_OPERATION_PERSIST, null); + } + if (DEBUG_PERSISTENCE) { Slog.i(LOG_TAG, "[PERSIST END]"); } @@ -435,7 +509,7 @@ final class SettingsState { static void setValueAttribute(int version, XmlSerializer serializer, String value) throws IOException { - if (version >= SETTINGS_VERSOIN_NEW_ENCODING) { + if (version >= SETTINGS_VERSION_NEW_ENCODING) { if (value == null) { // Null value -> No ATTR_VALUE nor ATTR_VALUE_BASE64. } else if (isBinary(value)) { @@ -454,7 +528,7 @@ final class SettingsState { } private String getValueAttribute(XmlPullParser parser) { - if (mVersion >= SETTINGS_VERSOIN_NEW_ENCODING) { + if (mVersion >= SETTINGS_VERSION_NEW_ENCODING) { final String value = parser.getAttributeValue(null, ATTR_VALUE); if (value != null) { return value; @@ -479,22 +553,26 @@ final class SettingsState { private void readStateSyncLocked() { FileInputStream in; if (!mStatePersistFile.exists()) { + Slog.i(LOG_TAG, "No settings state " + mStatePersistFile); + addHistoricalOperationLocked(HISTORICAL_OPERATION_INITIALIZE, null); return; } try { in = new AtomicFile(mStatePersistFile).openRead(); } catch (FileNotFoundException fnfe) { - Slog.i(LOG_TAG, "No settings state"); + String message = "No settings state " + mStatePersistFile; + Slog.wtf(LOG_TAG, message); + Slog.i(LOG_TAG, message); return; } try { XmlPullParser parser = Xml.newPullParser(); parser.setInput(in, StandardCharsets.UTF_8.name()); parseStateLocked(parser); - } catch (XmlPullParserException | IOException e) { - throw new IllegalStateException("Failed parsing settings file: " - + mStatePersistFile , e); + String message = "Failed parsing settings file: " + mStatePersistFile; + Slog.wtf(LOG_TAG, message); + throw new IllegalStateException(message , e); } finally { IoUtils.closeQuietly(in); } @@ -567,6 +645,19 @@ final class SettingsState { } } + private class HistoricalOperation { + final long mTimestamp; + final String mOperation; + final Setting mSetting; + + public HistoricalOperation(long timestamp, + String operation, Setting setting) { + mTimestamp = timestamp; + mOperation = operation; + mSetting = setting; + } + } + class Setting { private String name; private String value; @@ -629,6 +720,10 @@ final class SettingsState { this.id = String.valueOf(mNextId++); return true; } + + public String toString() { + return "Setting{name=" + value + " from " + packageName + "}"; + } } /** diff --git a/packages/SettingsProvider/test/src/com/android/providers/settings/SettingsStateTest.java b/packages/SettingsProvider/test/src/com/android/providers/settings/SettingsStateTest.java index b5bd8ad3073d9..9964467fb5eca 100644 --- a/packages/SettingsProvider/test/src/com/android/providers/settings/SettingsStateTest.java +++ b/packages/SettingsProvider/test/src/com/android/providers/settings/SettingsStateTest.java @@ -15,7 +15,6 @@ */ package com.android.providers.settings; -import android.os.Handler; import android.os.Looper; import android.test.AndroidTestCase; import android.util.Xml; @@ -99,10 +98,10 @@ public class SettingsStateTest extends AndroidTestCase { checkWriteSingleSetting(serializer, null, null); checkWriteSingleSetting(serializer, CRAZY_STRING, null); SettingsState.writeSingleSetting( - SettingsState.SETTINGS_VERSOIN_NEW_ENCODING, + SettingsState.SETTINGS_VERSION_NEW_ENCODING, serializer, null, "k", "v", "package"); SettingsState.writeSingleSetting( - SettingsState.SETTINGS_VERSOIN_NEW_ENCODING, + SettingsState.SETTINGS_VERSION_NEW_ENCODING, serializer, "1", "k", "v", null); } @@ -115,7 +114,7 @@ public class SettingsStateTest extends AndroidTestCase { String key, String value) throws Exception { // Make sure the XML serializer won't crash. SettingsState.writeSingleSetting( - SettingsState.SETTINGS_VERSOIN_NEW_ENCODING, + SettingsState.SETTINGS_VERSION_NEW_ENCODING, serializer, "1", key, value, "package"); } @@ -129,7 +128,7 @@ public class SettingsStateTest extends AndroidTestCase { final SettingsState ssWriter = new SettingsState(lock, file, 1, SettingsState.MAX_BYTES_PER_APP_PACKAGE_UNLIMITED, Looper.getMainLooper()); - ssWriter.setVersionLocked(SettingsState.SETTINGS_VERSOIN_NEW_ENCODING); + ssWriter.setVersionLocked(SettingsState.SETTINGS_VERSION_NEW_ENCODING); ssWriter.insertSettingLocked("k1", "\u0000", "package"); ssWriter.insertSettingLocked("k2", "abc", "p2");