From 05d5d5c2bc520ff20b6a22bf2e8dbfb9451ffad6 Mon Sep 17 00:00:00 2001 From: beatricemarch Date: Wed, 23 Aug 2023 15:29:10 +0000 Subject: Overload putMonitoringExtra so that it can take an int as a parameter. This will allow to correcly store EXTRA_LOG_OPERATION_TYPE Test: atest BackupManagerMonitorEventSender, atest CtsBackupHostTestCases, GtsBackupHostTestCases manual testing (restore to a phone and check that the backup dumpsys contain non-agent events) Bug: 297163190 Change-Id: I6bea76f31dba66c3ad958212d77be7e00902bb2b --- .../backup/utils/BackupManagerMonitorEventSender.java | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) (limited to 'services/backup/java') diff --git a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorEventSender.java b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorEventSender.java index 92e3107b6977..549d08c03933 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorEventSender.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorEventSender.java @@ -222,4 +222,21 @@ public class BackupManagerMonitorEventSender { extras.putBoolean(key, value); return extras; } + + /** + * Adds given key-value pair in the bundle and returns the bundle. If bundle was null it will + * be created. + * + * @param extras - bundle where to add key-value to, if null a new bundle will be created. + * @param key - key. + * @param value - value. + * @return extras if it was not null and new bundle otherwise. + */ + public static Bundle putMonitoringExtra(Bundle extras, String key, int value) { + if (extras == null) { + extras = new Bundle(); + } + extras.putInt(key, value); + return extras; + } } -- cgit v1.2.3-59-g8ed1b From e8d8bf4d73d5f75858e93bdb4373217a7c00b9ed Mon Sep 17 00:00:00 2001 From: beatricemarch Date: Thu, 31 Aug 2023 12:53:16 +0000 Subject: Add a 60 days retention period to BMM Events Test: manual testing(set a 5 minutes retention period, factory reset the test device, go trough SUW, confirm that the logs show in backup dumpsys, confirm that logs are deleted after 5 minutes) atest CtsBackupHostTestCases, GtsBackupHostTestCases atest BackupManagerMonitorDumpsysUtilsTest, BackupManagerMonitorEventSenderTest, UserBackupManagerServiceTest Bug: 297159898 Change-Id: If8ce57c68cf9ffaa5472e5e14aee72c6bf2e5153 --- .../server/backup/UserBackupManagerService.java | 16 ++ .../utils/BackupManagerMonitorDumpsysUtils.java | 166 ++++++++++++++++- .../BackupManagerMonitorDumpsysUtilsTest.java | 201 ++++++++++++++++++++- 3 files changed, 364 insertions(+), 19 deletions(-) (limited to 'services/backup/java') diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java index 4c137bce4f7b..2d80af92eea5 100644 --- a/services/backup/java/com/android/server/backup/UserBackupManagerService.java +++ b/services/backup/java/com/android/server/backup/UserBackupManagerService.java @@ -654,6 +654,13 @@ public class UserBackupManagerService { // the pending backup set mBackupHandler.postDelayed(this::parseLeftoverJournals, INITIALIZATION_DELAY_MILLIS); + // check if we are past the retention period for BMM Events, + // if so delete expired events and do not print them to dumpsys + BackupManagerMonitorDumpsysUtils backupManagerMonitorDumpsysUtils = + new BackupManagerMonitorDumpsysUtils(); + mBackupHandler.postDelayed(backupManagerMonitorDumpsysUtils::deleteExpiredBMMEvents, + INITIALIZATION_DELAY_MILLIS); + mBackupPreferences = new UserBackupPreferences(mContext, mBaseStateDir); // Power management @@ -4181,7 +4188,16 @@ public class UserBackupManagerService { private void dumpBMMEvents(PrintWriter pw) { BackupManagerMonitorDumpsysUtils bm = new BackupManagerMonitorDumpsysUtils(); + if (bm.deleteExpiredBMMEvents()) { + pw.println("BACKUP MANAGER MONITOR EVENTS HAVE EXPIRED"); + return; + } File events = bm.getBMMEventsFile(); + if (events.length() == 0){ + // We have not recorded BMMEvents yet. + pw.println("NO BACKUP MANAGER MONITOR EVENTS"); + return; + } pw.println("START OF BACKUP MANAGER MONITOR EVENTS"); try (BufferedReader reader = new BufferedReader(new FileReader(events))) { String line; diff --git a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java index 0b55ca21371b..bc2326d8241d 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java @@ -23,15 +23,22 @@ import android.os.Bundle; import android.os.Environment; import android.util.Slog; +import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.FastPrintWriter; +import java.io.BufferedReader; import java.io.File; +import java.io.FileInputStream; import java.io.FileOutputStream; +import java.io.FileWriter; +import java.io.IOException; +import java.io.InputStreamReader; import java.io.PrintWriter; import java.text.SimpleDateFormat; import java.util.ArrayList; import java.util.Date; import java.util.Map; +import java.util.concurrent.TimeUnit; /* @@ -46,12 +53,21 @@ public class BackupManagerMonitorDumpsysUtils { // Name of the subdirectory where the text file containing the BMM events will be stored. // Same as {@link UserBackupManagerFiles} private static final String BACKUP_PERSISTENT_DIR = "backup"; + private static final String INITIAL_SETUP_TIMESTAMP_KEY = "initialSetupTimestamp"; + // Retention period of 60 days (in millisec) for the BMM Events. + // After tha time has passed the text file containing the BMM events will be emptied + private static final long LOGS_RETENTION_PERIOD_MILLISEC = 60 * TimeUnit.DAYS.toMillis(1); + // We cache the value of IsAfterRetentionPeriod() to avoid unnecessary disk I/O + // mIsAfterRetentionPeriodCached tracks if we have cached the value of IsAfterRetentionPeriod() + private boolean mIsAfterRetentionPeriodCached = false; + // The cahched value of IsAfterRetentionPeriod() + private boolean mIsAfterRetentionPeriod; /** * Parses the BackupManagerMonitor bundle for a RESTORE event in a series of strings that * will be persisted in a text file and printed in the dumpsys. * - * If the evenntBundle passed is not a RESTORE event, return early + * If the eventBundle passed is not a RESTORE event, return early * * Key information related to the event: * - Timestamp (HAS TO ALWAYS BE THE FIRST LINE OF EACH EVENT) @@ -63,16 +79,21 @@ public class BackupManagerMonitorDumpsysUtils { * * Example of formatting: * RESTORE Event: [2023-08-18 17:16:00.735] Agent - Agent logging results - * Package name: com.android.wallpaperbackup - * Agent Logs: - * Data Type: wlp_img_system - * Item restored: 0/1 - * Agent Error - Category: no_wallpaper, Count: 1 - * Data Type: wlp_img_lock - * Item restored: 0/1 - * Agent Error - Category: no_wallpaper, Count: 1 + * Package name: com.android.wallpaperbackup + * Agent Logs: + * Data Type: wlp_img_system + * Item restored: 0/1 + * Agent Error - Category: no_wallpaper, Count: 1 + * Data Type: wlp_img_lock + * Item restored: 0/1 + * Agent Error - Category: no_wallpaper, Count: 1 */ public void parseBackupManagerMonitorRestoreEventForDumpsys(Bundle eventBundle) { + if (isAfterRetentionPeriod()) { + // We only log data for the first 60 days since setup + return; + } + if (eventBundle == null) { return; } @@ -89,8 +110,14 @@ public class BackupManagerMonitorDumpsysUtils { } File bmmEvents = getBMMEventsFile(); + if (bmmEvents.length() == 0) { + // We are parsing the first restore event. + // Time to also record the setup timestamp of the device + recordSetUpTimestamp(); + } + try (FileOutputStream out = new FileOutputStream(bmmEvents, /*append*/ true); - PrintWriter pw = new FastPrintWriter(out);) { + PrintWriter pw = new FastPrintWriter(out);) { int eventCategory = eventBundle.getInt(BackupManagerMonitor.EXTRA_LOG_EVENT_CATEGORY); int eventId = eventBundle.getInt(BackupManagerMonitor.EXTRA_LOG_EVENT_ID); @@ -257,4 +284,123 @@ public class BackupManagerMonitorDumpsysUtils { default -> false; }; } + + /** + * Store the timestamp when the device was set up (date when the first BMM event is parsed) + * in a text file. + */ + @VisibleForTesting + void recordSetUpTimestamp() { + File setupDateFile = getSetUpDateFile(); + // record setup timestamp only once + if (setupDateFile.length() == 0) { + try (FileOutputStream out = new FileOutputStream(setupDateFile, /*append*/ true); + PrintWriter pw = new FastPrintWriter(out);) { + long currentDate = System.currentTimeMillis(); + pw.println(currentDate); + } catch (IOException e) { + Slog.w(TAG, "An error occurred while recording the setup date: " + + e.getMessage()); + } + } + + } + + @VisibleForTesting + String getSetUpDate() { + File fname = getSetUpDateFile(); + try (FileInputStream inputStream = new FileInputStream(fname); + InputStreamReader reader = new InputStreamReader(inputStream); + BufferedReader bufferedReader = new BufferedReader(reader);) { + return bufferedReader.readLine(); + } catch (Exception e) { + Slog.w(TAG, "An error occurred while reading the date: " + e.getMessage()); + return "Could not retrieve setup date"; + } + } + + @VisibleForTesting + static boolean isDateAfterNMillisec(long startTimeStamp, long endTimeStamp, long millisec) { + if (startTimeStamp > endTimeStamp) { + // Something has gone wrong, timeStamp1 should always precede timeStamp2. + // Out of caution return true: we would delete the logs rather than + // risking them being kept for longer than the retention period + return true; + } + long timeDifferenceMillis = endTimeStamp - startTimeStamp; + return (timeDifferenceMillis >= millisec); + } + + /** + * Check if current date is after retention period + */ + @VisibleForTesting + boolean isAfterRetentionPeriod() { + if (mIsAfterRetentionPeriodCached) { + return mIsAfterRetentionPeriod; + } else { + File setUpDateFile = getSetUpDateFile(); + if (setUpDateFile.length() == 0) { + // We are yet to record a setup date. This means we haven't parsed the first event. + mIsAfterRetentionPeriod = false; + mIsAfterRetentionPeriodCached = true; + return false; + } + try { + long setupTimestamp = Long.parseLong(getSetUpDate()); + long currentTimestamp = System.currentTimeMillis(); + mIsAfterRetentionPeriod = isDateAfterNMillisec(setupTimestamp, currentTimestamp, + getRetentionPeriodInMillisec()); + mIsAfterRetentionPeriodCached = true; + return mIsAfterRetentionPeriod; + } catch (NumberFormatException e) { + // An error occurred when parsing the setup timestamp. + // Out of caution return true: we would delete the logs rather than + // risking them being kept for longer than the retention period + mIsAfterRetentionPeriod = true; + mIsAfterRetentionPeriodCached = true; + return true; + } + } + } + + @VisibleForTesting + File getSetUpDateFile() { + File dataDir = new File(Environment.getDataDirectory(), BACKUP_PERSISTENT_DIR); + File setupDateFile = new File(dataDir, INITIAL_SETUP_TIMESTAMP_KEY + ".txt"); + return setupDateFile; + } + + @VisibleForTesting + long getRetentionPeriodInMillisec() { + return LOGS_RETENTION_PERIOD_MILLISEC; + } + + /** + * Delete the BMM Events file after the retention period has passed. + * + * @return true if the retention period has passed false otherwise. + * we want to return true even if we were unable to delete the file, as this will prevent + * expired BMM events from being printed to the dumpsys + */ + public boolean deleteExpiredBMMEvents() { + try { + if (isAfterRetentionPeriod()) { + File bmmEvents = getBMMEventsFile(); + if (bmmEvents.exists()) { + if (bmmEvents.delete()) { + Slog.i(TAG, "Deleted expired BMM Events"); + } else { + Slog.e(TAG, "Unable to delete expired BMM Events"); + } + } + return true; + } + return false; + } catch (Exception e) { + // Handle any unexpected exceptions + // To be safe we return true as we want to avoid exposing expired BMMEvents + return true; + } + } } diff --git a/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java b/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java index 8e17b3a58769..a45b17e2e3c5 100644 --- a/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java @@ -17,26 +17,29 @@ package com.android.server.backup.utils; import static org.junit.Assert.assertTrue; - +import static org.testng.AssertJUnit.assertFalse; +import android.app.backup.BackupAnnotations; import android.app.backup.BackupManagerMonitor; import android.os.Bundle; - import org.junit.Before; import org.junit.Rule; import org.junit.Test; import org.junit.rules.TemporaryFolder; - import java.io.File; public class BackupManagerMonitorDumpsysUtilsTest { - private File mTempFile; + private long mRetentionPeriod; + private File mTempBMMEventsFile; + private File mTempSetUpDateFile; private TestBackupManagerMonitorDumpsysUtils mBackupManagerMonitorDumpsysUtils; @Rule public TemporaryFolder tmp = new TemporaryFolder(); @Before public void setUp() throws Exception { - mTempFile = tmp.newFile("testbmmevents.txt"); + mRetentionPeriod = 30 * 60 * 1000; + mTempBMMEventsFile = tmp.newFile("testbmmevents.txt"); + mTempSetUpDateFile = tmp.newFile("testSetUpDate.txt"); mBackupManagerMonitorDumpsysUtils = new TestBackupManagerMonitorDumpsysUtils(); } @@ -46,7 +49,7 @@ public class BackupManagerMonitorDumpsysUtilsTest { throws Exception { mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(null); - assertTrue(mTempFile.length() == 0); + assertTrue(mTempBMMEventsFile.length() == 0); } @@ -57,7 +60,7 @@ public class BackupManagerMonitorDumpsysUtilsTest { event.putInt(BackupManagerMonitor.EXTRA_LOG_EVENT_CATEGORY, 1); mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); - assertTrue(mTempFile.length() == 0); + assertTrue(mTempBMMEventsFile.length() == 0); } @Test @@ -67,18 +70,198 @@ public class BackupManagerMonitorDumpsysUtilsTest { event.putInt(BackupManagerMonitor.EXTRA_LOG_EVENT_ID, 1); mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); - assertTrue(mTempFile.length() == 0); + assertTrue(mTempBMMEventsFile.length() == 0); + } + + @Test + public void parseBackupManagerMonitorEventForDumpsys_eventWithCategoryAndId_eventIsWrittenToFile() + throws Exception { + Bundle event = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + + assertTrue(mTempBMMEventsFile.length() != 0); + } + + @Test + public void parseBackupManagerMonitorEventForDumpsys_firstEvent_recordSetUpTimestamp() + throws Exception { + assertTrue(mTempBMMEventsFile.length()==0); + assertTrue(mTempSetUpDateFile.length()==0); + + Bundle event = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + + assertTrue(mTempBMMEventsFile.length() != 0); + assertTrue(mTempSetUpDateFile.length()!=0); + } + + @Test + public void parseBackupManagerMonitorEventForDumpsys_notFirstEvent_doNotChangeSetUpTimestamp() + throws Exception { + Bundle event1 = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event1); + String setUpTimestampBefore = mBackupManagerMonitorDumpsysUtils.getSetUpDate(); + + Bundle event2 = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event2); + String setUpTimestampAfter = mBackupManagerMonitorDumpsysUtils.getSetUpDate(); + + assertTrue(setUpTimestampBefore.equals(setUpTimestampAfter)); + } + + + @Test + public void deleteExpiredBackupManagerMonitorEvent_eventsAreExpired_deleteEventsAndReturnTrue() + throws Exception { + Bundle event = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + assertTrue(mTempBMMEventsFile.length() != 0); + // Re-initialise the test BackupManagerMonitorDumpsysUtils to + // clear the cached value of isAfterRetentionPeriod + mBackupManagerMonitorDumpsysUtils = new TestBackupManagerMonitorDumpsysUtils(); + + // set a retention period of 0 second + mBackupManagerMonitorDumpsysUtils.setTestRetentionPeriod(0); + + assertTrue(mBackupManagerMonitorDumpsysUtils.deleteExpiredBMMEvents()); + assertFalse(mTempBMMEventsFile.exists()); + } + + @Test + public void deleteExpiredBackupManagerMonitorEvent_eventsAreNotExpired_returnFalse() throws + Exception { + Bundle event = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + assertTrue(mTempBMMEventsFile.length() != 0); + + // set a retention period of 30 minutes + mBackupManagerMonitorDumpsysUtils.setTestRetentionPeriod(30 * 60 * 1000); + + assertFalse(mBackupManagerMonitorDumpsysUtils.deleteExpiredBMMEvents()); + assertTrue(mTempBMMEventsFile.length() != 0); + } + + @Test + public void isAfterRetentionPeriod_afterRetentionPeriod_returnTrue() throws + Exception { + mBackupManagerMonitorDumpsysUtils.recordSetUpTimestamp(); + + // set a retention period of 0 second + mBackupManagerMonitorDumpsysUtils.setTestRetentionPeriod(0); + + assertTrue(mBackupManagerMonitorDumpsysUtils.isAfterRetentionPeriod()); + } + + @Test + public void isAfterRetentionPeriod_beforeRetentionPeriod_returnFalse() throws + Exception { + mBackupManagerMonitorDumpsysUtils.recordSetUpTimestamp(); + + // set a retention period of 30 minutes + mBackupManagerMonitorDumpsysUtils.setTestRetentionPeriod(30 * 60 * 1000); + + assertFalse(mBackupManagerMonitorDumpsysUtils.isAfterRetentionPeriod()); + } + + @Test + public void isAfterRetentionPeriod_noSetupDate_returnFalse() throws + Exception { + assertTrue(mTempSetUpDateFile.length() == 0); + + assertFalse(mBackupManagerMonitorDumpsysUtils.isAfterRetentionPeriod()); + } + + @Test + public void isDateAfterNMillisec_date1IsAfterThanDate2_returnTrue() throws + Exception { + long timestamp1 = System.currentTimeMillis(); + long timestamp2 = timestamp1 - 1; + + assertTrue(mBackupManagerMonitorDumpsysUtils.isDateAfterNMillisec(timestamp1, timestamp2, + 0)); + } + + @Test + public void isDateAfterNMillisec_date1IsAfterNMillisecFromDate2_returnTrue() throws + Exception { + long timestamp1 = System.currentTimeMillis(); + long timestamp2 = timestamp1 + 10; + + assertTrue(mBackupManagerMonitorDumpsysUtils.isDateAfterNMillisec(timestamp1, timestamp2, + 10)); + } + + @Test + public void isDateAfterNMillisec_date1IsLessThanNMillisecFromDate2_returnFalse() throws + Exception { + long timestamp1 = System.currentTimeMillis(); + long timestamp2 = timestamp1 + 10; + + assertFalse(mBackupManagerMonitorDumpsysUtils.isDateAfterNMillisec(timestamp1, timestamp2, + 11)); + } + + @Test + public void recordSetUpTimestamp_timestampNotSetBefore_setTimestamp() throws + Exception { + assertTrue(mTempSetUpDateFile.length() == 0); + + mBackupManagerMonitorDumpsysUtils.recordSetUpTimestamp(); + + assertTrue(mTempSetUpDateFile.length() != 0); + } + + @Test + public void recordSetUpTimestamp_timestampSetBefore_doNothing() throws + Exception { + mBackupManagerMonitorDumpsysUtils.recordSetUpTimestamp(); + assertTrue(mTempSetUpDateFile.length() != 0); + String timestampBefore = mBackupManagerMonitorDumpsysUtils.getSetUpDate(); + + mBackupManagerMonitorDumpsysUtils.recordSetUpTimestamp(); + + assertTrue(mTempSetUpDateFile.length() != 0); + String timestampAfter = mBackupManagerMonitorDumpsysUtils.getSetUpDate(); + assertTrue(timestampAfter.equals(timestampBefore)); + } + + private Bundle createRestoreBMMEvent() { + Bundle event = new Bundle(); + event.putInt(BackupManagerMonitor.EXTRA_LOG_EVENT_ID, 1); + event.putInt(BackupManagerMonitor.EXTRA_LOG_EVENT_CATEGORY, 1); + event.putInt(BackupManagerMonitor.EXTRA_LOG_OPERATION_TYPE, + BackupAnnotations.OperationType.RESTORE); + return event; } private class TestBackupManagerMonitorDumpsysUtils extends BackupManagerMonitorDumpsysUtils { + + private long testRetentionPeriod; + TestBackupManagerMonitorDumpsysUtils() { super(); + this.testRetentionPeriod = mRetentionPeriod; + } + + public void setTestRetentionPeriod(long testRetentionPeriod) { + this.testRetentionPeriod = testRetentionPeriod; } @Override public File getBMMEventsFile() { - return mTempFile; + return mTempBMMEventsFile; } + + @Override + File getSetUpDateFile() { + return mTempSetUpDateFile; + } + + @Override + long getRetentionPeriodInMillisec() { + return testRetentionPeriod; + } + } } -- cgit v1.2.3-59-g8ed1b From 501eeee21a5fb200b88b42eb8ed53be67bd16e56 Mon Sep 17 00:00:00 2001 From: beatricemarch Date: Thu, 31 Aug 2023 12:53:16 +0000 Subject: Add more BackupManagerMonitor events to PerformUnifiedRestoreTask. In particular add events to cover -If this is KV or Full restore -For each package, when the restore started and when it ended -When a restore operation starts, if it is system restore or restore at install -Any errors Test: manual testing. Run `adb shell bmgr restore 1` and verify that the new restore events are added to the dumpsys atest CtsBackupHostTestCases, GtsBackupHostTestCases atest BackupManagerMonitorDumpsysUtilsTest, BackupManagerMonitorEventSenderTest, UserBackupManagerServiceTest, PerformUnifiedRestoreTaskTest, BmgrTest Bug: 290747920 Change-Id: I0d221f10932fea3e8fb90a1827c7f1b5bf21d25d --- cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java | 34 ++++++ .../android/app/backup/BackupManagerMonitor.java | 51 +++++++++ .../backup/restore/PerformUnifiedRestoreTask.java | 117 +++++++++++++++++++++ .../utils/BackupManagerMonitorDumpsysUtils.java | 26 +++++ 4 files changed, 228 insertions(+) (limited to 'services/backup/java') diff --git a/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java b/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java index b6dc32a29f04..088372702ebc 100644 --- a/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java +++ b/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java @@ -1246,6 +1246,40 @@ public class Bmgr { return "TRANSPORT_IS_NULL"; case BackupManagerMonitor.LOG_EVENT_ID_AGENT_LOGGING_RESULTS: return "AGENT_LOGGING_RESULTS"; + case BackupManagerMonitor.LOG_EVENT_ID_START_SYSTEM_RESTORE: + return "START_SYSTEM_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_START_RESTORE_AT_INSTALL: + return "START_RESTORE_AT_INSTALL"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_DURING_START_RESTORE: + return "TRANSPORT_ERROR_DURING_START_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_CANNOT_GET_NEXT_PKG_NAME: + return "CANNOT_GET_NEXT_PKG_NAME"; + case BackupManagerMonitor.LOG_EVENT_ID_UNKNOWN_RESTORE_TYPE: + return "UNKNOWN_RESTORE_TYPE"; + case BackupManagerMonitor.LOG_EVENT_ID_KV_RESTORE: + return "KV_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_FULL_RESTORE: + return "FULL_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_NO_NEXT_RESTORE_TARGET: + return "NO_NEXT_RESTORE_TARGET"; + case BackupManagerMonitor.LOG_EVENT_ID_KV_AGENT_ERROR: + return "KV_AGENT_ERROR"; + case BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_RESTORE_FINISHED: + return "PACKAGE_RESTORE_FINISHED"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_KV_RESTORE: + return "TRANSPORT_ERROR_KV_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_NO_FEEDER_THREAD: + return "NO_FEEDER_THREAD"; + case BackupManagerMonitor.LOG_EVENT_ID_FULL_AGENT_ERROR: + return "FULL_AGENT_ERROR"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_FULL_RESTORE: + return "TRANSPORT_ERROR_FULL_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_COMPLETE: + return "RESTORE_COMPLETE"; + case BackupManagerMonitor.LOG_EVENT_ID_START_PACKAGE_RESTORE: + return "START_PACKAGE_RESTORE"; + case BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE: + return "AGENT_FAILURE"; default: return "UNKNOWN_ID"; } diff --git a/core/java/android/app/backup/BackupManagerMonitor.java b/core/java/android/app/backup/BackupManagerMonitor.java index f73366b6af0c..812bf8e6be6a 100644 --- a/core/java/android/app/backup/BackupManagerMonitor.java +++ b/core/java/android/app/backup/BackupManagerMonitor.java @@ -18,6 +18,7 @@ package android.app.backup; import android.annotation.SystemApi; import android.app.backup.BackupAnnotations.OperationType; +import android.content.pm.PackageInfo; import android.os.Bundle; /** @@ -190,6 +191,56 @@ public class BackupManagerMonitor { public static final int LOG_EVENT_ID_TRANSPORT_NON_INCREMENTAL_BACKUP_REQUIRED = 51; public static final int LOG_EVENT_ID_AGENT_LOGGING_RESULTS = 52; + /** @hide */ + public static final int LOG_EVENT_ID_START_SYSTEM_RESTORE = 53; + /** @hide */ + public static final int LOG_EVENT_ID_START_RESTORE_AT_INSTALL = 54; + /** A transport error happened during {@link PerformUnifiedRestoreTask#startRestore()} + @hide */ + public static final int LOG_EVENT_ID_TRANSPORT_ERROR_DURING_START_RESTORE = 55; + /** Unable to get the name of the next package in the queue during a restore operation + @hide */ + public static final int LOG_EVENT_ID_CANNOT_GET_NEXT_PKG_NAME = 56; + /** Attempting a restore operation that is neither KV nor full + @hide */ + public static final int LOG_EVENT_ID_UNKNOWN_RESTORE_TYPE = 57; + /** The package is part of KeyValue restore + @hide */ + public static final int LOG_EVENT_ID_KV_RESTORE = 58; + /** The package is part of Full restore + @hide */ + public static final int LOG_EVENT_ID_FULL_RESTORE = 59; + /** Unable to fetch the nest restore target in the queue + @hide */ + public static final int LOG_EVENT_ID_NO_NEXT_RESTORE_TARGET = 60; + /** An error occurred while attempting KeyValueRestore + @hide */ + public static final int LOG_EVENT_ID_KV_AGENT_ERROR = 61; + /** Restore operation finished for the given package + @hide */ + public static final int LOG_EVENT_ID_PACKAGE_RESTORE_FINISHED= 62; + /** A transport error happened during + * {@link PerformUnifiedRestoreTask#initiateOneRestore(PackageInfo, long)} + @hide */ + public static final int LOG_EVENT_ID_TRANSPORT_ERROR_KV_RESTORE = 63; + /** Unable to instantiate the feeder thread in full restore + @hide */ + public static final int LOG_EVENT_ID_NO_FEEDER_THREAD = 64; + /** An error occurred while attempting Full restore + @hide */ + public static final int LOG_EVENT_ID_FULL_AGENT_ERROR = 65; + /** A transport error happened during a full restore + @hide */ + public static final int LOG_EVENT_ID_TRANSPORT_ERROR_FULL_RESTORE = 66; + /** Start restore operation for a given package + @hide */ + public static final int LOG_EVENT_ID_START_PACKAGE_RESTORE = 67; + /** Whole restore operation is complete + @hide */ + public static final int LOG_EVENT_ID_RESTORE_COMPLETE = 68; + /** Agent error during {@link PerformUnifiedRestoreTask#restoreFinished()} + @hide */ + public static final int LOG_EVENT_ID_AGENT_FAILURE = 69; /** * This method will be called each time something important happens on BackupManager. diff --git a/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java b/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java index e04bf11dad9f..bbec79d6cd47 100644 --- a/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java +++ b/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java @@ -394,6 +394,20 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // If we're starting a full-system restore, set up to begin widget ID remapping if (mIsSystemRestore) { AppWidgetBackupBridge.systemRestoreStarting(mUserId); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_START_SYSTEM_RESTORE, + null, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); + } else { + //We are either performing RestoreAtInstall or Bmgr. + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_START_RESTORE_AT_INSTALL, + null, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); } try { @@ -421,6 +435,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { mStatus = transport.startRestore(mToken, packages); if (mStatus != BackupTransport.TRANSPORT_OK) { Slog.e(TAG, "Transport error " + mStatus + "; no restore possible"); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_DURING_START_RESTORE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, + monitoringExtras); mStatus = BackupTransport.TRANSPORT_ERROR; executeNextState(UnifiedRestoreState.FINAL); return; @@ -528,6 +548,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { final String pkgName = (mRestoreDescription != null) ? mRestoreDescription.getPackageName() : null; if (pkgName == null) { + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_CANNOT_GET_NEXT_PKG_NAME, + null, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, + monitoringExtras); Slog.e(TAG, "Failure getting next package name"); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); nextState = UnifiedRestoreState.FINAL; @@ -550,6 +576,14 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { Metadata metaInfo = mPmAgent.getRestoredMetadata(pkgName); if (metaInfo == null) { + PackageInfo pkgInfo = new PackageInfo(); + pkgInfo.packageName = pkgName; + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_PM_AGENT_HAS_NO_METADATA, + pkgInfo, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); Slog.e(TAG, "No metadata for " + pkgName); EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, pkgName, "Package metadata missing"); @@ -560,6 +594,13 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { try { mCurrentPackage = backupManagerService.getPackageManager().getPackageInfoAsUser( pkgName, PackageManager.GET_SIGNING_CERTIFICATES, mUserId); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_START_PACKAGE_RESTORE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); + } catch (NameNotFoundException e) { // Whoops, we thought we could restore this package but it // turns out not to be present. Skip it. @@ -641,12 +682,24 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { } else { // Unknown restore type; ignore this package and move on Slog.e(TAG, "Unrecognized restore type " + type); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null);; + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_UNKNOWN_RESTORE_TYPE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); nextState = UnifiedRestoreState.RUNNING_QUEUE; return; } } catch (Exception e) { Slog.e(TAG, "Can't get next restore target from transport; halting: " + e.getMessage()); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null);; + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_NO_NEXT_RESTORE_TARGET, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); nextState = UnifiedRestoreState.FINAL; return; @@ -663,6 +716,10 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { final String packageName = mCurrentPackage.packageName; // Validate some semantic requirements that apply in this way // only to the key/value restore API flow + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_KV_RESTORE, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + /*monitoringExtras*/ addRestoreOperationTypeToEvent(/*extras*/null)); if (mCurrentPackage.applicationInfo.backupAgentName == null || "".equals(mCurrentPackage.applicationInfo.backupAgentName)) { if (MORE_DEBUG) { @@ -721,6 +778,11 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { ++mCount; } catch (Exception e) { Slog.e(TAG, "Error when attempting restore: " + e.toString()); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_KV_AGENT_ERROR, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, + monitoringExtras); keyValueAgentErrorCleanup(false); executeNextState(UnifiedRestoreState.RUNNING_QUEUE); } @@ -759,6 +821,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // Transport-level failure. This failure could be specific to package currently in // restore. Slog.e(TAG, "Error getting restore data for " + packageName); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_KV_RESTORE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); stage.close(); downloadFile.delete(); @@ -815,6 +883,11 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { new ArrayList<>(getExcludedKeysForPackage(packageName))); } catch (Exception e) { Slog.e(TAG, "Unable to call app for restore: " + packageName, e); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_KV_AGENT_ERROR, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, packageName, e.toString()); // Clears any pending timeout messages as well. @@ -888,6 +961,10 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // // When finished, StreamFeederThread executes next state as appropriate on the // backup looper, and the overall unified restore task resumes + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_FULL_RESTORE, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + /*monitoringExtras*/ addRestoreOperationTypeToEvent(/*extras*/null)); try { StreamFeederThread feeder = new StreamFeederThread(); if (MORE_DEBUG) { @@ -903,6 +980,11 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // current target. We haven't asked the transport for data yet, though, // so we can do that simply by going back to running the restore queue. Slog.e(TAG, "Unable to construct pipes for stream restore!"); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_NO_FEEDER_THREAD, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); executeNextState(UnifiedRestoreState.RUNNING_QUEUE); } } @@ -927,6 +1009,10 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { } catch (Exception e) { final String packageName = mCurrentPackage.packageName; Slog.e(TAG, "Unable to finalize restore of " + packageName); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, packageName, e.toString()); keyValueAgentErrorCleanup(true); @@ -1020,6 +1106,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // handling will deal properly with that. Slog.e(TAG, "Error " + result + " streaming restore for " + mCurrentPackage.packageName); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_FULL_RESTORE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); status = result; } @@ -1032,6 +1124,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // but potentially recoverable; abandon this package's restore but // carry on with the next restore target. Slog.e(TAG, "Unable to route data for restore"); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_FULL_AGENT_ERROR, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, mCurrentPackage.packageName, "I/O error on pipes"); status = BackupTransport.AGENT_ERROR; @@ -1040,6 +1138,12 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // the sockets will wake up the engine and it will then tidy up the // remote end. Slog.e(TAG, "Transport failed during restore: " + e.getMessage()); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_FULL_RESTORE, + mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); status = BackupTransport.TRANSPORT_ERROR; } finally { @@ -1213,6 +1317,13 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { } Slog.i(TAG, "Restore complete."); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_RESTORE_COMPLETE, + null, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); + mListener.onFinished(callerLogString); } @@ -1313,6 +1424,7 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { @Override public void operationComplete(long unusedResult) { mOperationStorage.removeOperation(mEphemeralOpToken); + if (MORE_DEBUG) { Slog.i(TAG, "operationComplete() during restore: target=" + mCurrentPackage.packageName @@ -1341,6 +1453,11 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { // Okay, we're done with this package. Tidy up and go on to the next // app in the queue. int size = (int) mBackupDataName.length(); + Bundle monitoringExtras = addRestoreOperationTypeToEvent(/*extras*/null); + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_RESTORE_FINISHED, mCurrentPackage, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_PACKAGE, mCurrentPackage.packageName, size); diff --git a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java index bc2326d8241d..16da846a093a 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java @@ -272,6 +272,32 @@ public class BackupManagerMonitorDumpsysUtils { case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_NON_INCREMENTAL_BACKUP_REQUIRED -> "Transport non-incremental backup required"; case BackupManagerMonitor.LOG_EVENT_ID_AGENT_LOGGING_RESULTS -> "Agent logging results"; + case BackupManagerMonitor.LOG_EVENT_ID_START_SYSTEM_RESTORE -> "Start system restore"; + case BackupManagerMonitor.LOG_EVENT_ID_START_RESTORE_AT_INSTALL -> + "Start restore at install"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_DURING_START_RESTORE -> + "Transport error during start restore"; + case BackupManagerMonitor.LOG_EVENT_ID_CANNOT_GET_NEXT_PKG_NAME -> + "Cannot get next package name"; + case BackupManagerMonitor.LOG_EVENT_ID_UNKNOWN_RESTORE_TYPE -> "Unknown restore type"; + case BackupManagerMonitor.LOG_EVENT_ID_KV_RESTORE -> "KV restore"; + case BackupManagerMonitor.LOG_EVENT_ID_FULL_RESTORE -> "Full restore"; + case BackupManagerMonitor.LOG_EVENT_ID_NO_NEXT_RESTORE_TARGET -> + "No next restore target"; + case BackupManagerMonitor.LOG_EVENT_ID_KV_AGENT_ERROR -> "KV agent error"; + case BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_RESTORE_FINISHED -> + "Package restore finished"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_KV_RESTORE -> + "Transport error KV restore"; + case BackupManagerMonitor.LOG_EVENT_ID_NO_FEEDER_THREAD -> "No feeder thread"; + case BackupManagerMonitor.LOG_EVENT_ID_FULL_AGENT_ERROR -> "Full agent error"; + case BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_ERROR_FULL_RESTORE -> + "Transport error full restore"; + case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_COMPLETE -> "Restore complete"; + case BackupManagerMonitor.LOG_EVENT_ID_START_PACKAGE_RESTORE -> + "Start package restore"; + case BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE -> + "Agent failure"; default -> "Unknown log event ID: " + code; }; return id; -- cgit v1.2.3-59-g8ed1b From 3f8ff83497f421bef686a71b65c4afcf28ee9695 Mon Sep 17 00:00:00 2001 From: beatricemarch Date: Thu, 31 Aug 2023 12:53:16 +0000 Subject: Add a 2.5 MB size limit to the text file storing BMM Events. Test: atest CtsBackupHostTestCases, GtsBackupHostTestCases atest BackupManagerMonitorDumpsysUtilsTest, UserBackupManagerServiceTest Bug: 297163567 Change-Id: Ia1fdc0b465b960337f5e5c626460e305d96f4eb2 --- .../server/backup/UserBackupManagerService.java | 10 ++++++ .../utils/BackupManagerMonitorDumpsysUtils.java | 25 ++++++++++++- .../BackupManagerMonitorDumpsysUtilsTest.java | 42 ++++++++++++++++++++++ 3 files changed, 76 insertions(+), 1 deletion(-) (limited to 'services/backup/java') diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java index 2d80af92eea5..38af61b16ef3 100644 --- a/services/backup/java/com/android/server/backup/UserBackupManagerService.java +++ b/services/backup/java/com/android/server/backup/UserBackupManagerService.java @@ -486,6 +486,13 @@ public class UserBackupManagerService { File baseStateDir, File dataDir, TransportManager transportManager) { + // check if we are past the retention period for BMM Events, + // if so delete expired events and do not print them to dumpsys + BackupManagerMonitorDumpsysUtils backupManagerMonitorDumpsysUtils = + new BackupManagerMonitorDumpsysUtils(); + if (backupManagerMonitorDumpsysUtils.deleteExpiredBMMEvents() && DEBUG){ + Slog.d(TAG, "BMM Events recorded for dumpsys have expired"); + } return new UserBackupManagerService( userId, context, @@ -4197,6 +4204,9 @@ public class UserBackupManagerService { // We have not recorded BMMEvents yet. pw.println("NO BACKUP MANAGER MONITOR EVENTS"); return; + } else if (bm.isFileLargerThanSizeLimit(events)){ + pw.println("BACKUP MANAGER MONITOR EVENTS FILE OVER SIZE LIMIT - " + + "future events will not be recorded"); } pw.println("START OF BACKUP MANAGER MONITOR EVENTS"); try (BufferedReader reader = new BufferedReader(new FileReader(events))) { diff --git a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java index 16da846a093a..4b0d5a4928b6 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java @@ -57,11 +57,17 @@ public class BackupManagerMonitorDumpsysUtils { // Retention period of 60 days (in millisec) for the BMM Events. // After tha time has passed the text file containing the BMM events will be emptied private static final long LOGS_RETENTION_PERIOD_MILLISEC = 60 * TimeUnit.DAYS.toMillis(1); + // Size limit for the text file containing the BMM events + private static final long BMM_FILE_SIZE_LIMIT_BYTES = 25 * 1024 * 1000; // 2.5 MB + // We cache the value of IsAfterRetentionPeriod() to avoid unnecessary disk I/O // mIsAfterRetentionPeriodCached tracks if we have cached the value of IsAfterRetentionPeriod() private boolean mIsAfterRetentionPeriodCached = false; - // The cahched value of IsAfterRetentionPeriod() + // The cached value of IsAfterRetentionPeriod() private boolean mIsAfterRetentionPeriod; + // If isFileLargerThanSizeLimit(bmmEvents) returns true we cache the value to avoid + // unnecessary disk I/O + private boolean mIsFileLargerThanSizeLimit = false; /** * Parses the BackupManagerMonitor bundle for a RESTORE event in a series of strings that @@ -116,6 +122,11 @@ public class BackupManagerMonitorDumpsysUtils { recordSetUpTimestamp(); } + if(isFileLargerThanSizeLimit(bmmEvents)){ + // Do not write more events if the file is over size limit + return; + } + try (FileOutputStream out = new FileOutputStream(bmmEvents, /*append*/ true); PrintWriter pw = new FastPrintWriter(out);) { @@ -192,6 +203,13 @@ public class BackupManagerMonitorDumpsysUtils { return fname; } + public boolean isFileLargerThanSizeLimit(File events){ + if (!mIsFileLargerThanSizeLimit) { + mIsFileLargerThanSizeLimit = events.length() > getBMMEventsFileSizeLimit(); + } + return mIsFileLargerThanSizeLimit; + } + private String timestamp() { long currentTime = System.currentTimeMillis(); Date date = new Date(currentTime); @@ -402,6 +420,11 @@ public class BackupManagerMonitorDumpsysUtils { return LOGS_RETENTION_PERIOD_MILLISEC; } + @VisibleForTesting + long getBMMEventsFileSizeLimit(){ + return BMM_FILE_SIZE_LIMIT_BYTES; + } + /** * Delete the BMM Events file after the retention period has passed. * diff --git a/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java b/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java index a45b17e2e3c5..dcd531751cd7 100644 --- a/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtilsTest.java @@ -26,11 +26,14 @@ import org.junit.Rule; import org.junit.Test; import org.junit.rules.TemporaryFolder; import java.io.File; +import java.io.FileWriter; public class BackupManagerMonitorDumpsysUtilsTest { private long mRetentionPeriod; private File mTempBMMEventsFile; private File mTempSetUpDateFile; + + private long mSizeLimit; private TestBackupManagerMonitorDumpsysUtils mBackupManagerMonitorDumpsysUtils; @Rule public TemporaryFolder tmp = new TemporaryFolder(); @@ -38,6 +41,7 @@ public class BackupManagerMonitorDumpsysUtilsTest { @Before public void setUp() throws Exception { mRetentionPeriod = 30 * 60 * 1000; + mSizeLimit = 25 * 1024 * 1000; mTempBMMEventsFile = tmp.newFile("testbmmevents.txt"); mTempSetUpDateFile = tmp.newFile("testSetUpDate.txt"); mBackupManagerMonitorDumpsysUtils = new TestBackupManagerMonitorDumpsysUtils(); @@ -110,6 +114,33 @@ public class BackupManagerMonitorDumpsysUtilsTest { } + @Test + public void parseBackupManagerMonitorEventForDumpsys_fileOverSizeLimit_doNotRecordEvents() + throws Exception { + assertTrue(mTempBMMEventsFile.length() == 0); + Bundle event = createRestoreBMMEvent(); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + long fileSizeBefore = mTempBMMEventsFile.length(); + + mBackupManagerMonitorDumpsysUtils.setTestSizeLimit(0); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + long fileSizeAfter = mTempBMMEventsFile.length(); + assertTrue(mBackupManagerMonitorDumpsysUtils.isFileLargerThanSizeLimit(mTempBMMEventsFile)); + assertTrue(fileSizeBefore == fileSizeAfter); + } + + @Test + public void parseBackupManagerMonitorEventForDumpsys_fileUnderSizeLimit_recordEvents() + throws Exception { + assertTrue(mTempBMMEventsFile.length() == 0); + Bundle event = createRestoreBMMEvent(); + + mBackupManagerMonitorDumpsysUtils.setTestSizeLimit(25 * 1024 * 1000); + mBackupManagerMonitorDumpsysUtils.parseBackupManagerMonitorRestoreEventForDumpsys(event); + assertFalse(mBackupManagerMonitorDumpsysUtils.isFileLargerThanSizeLimit(mTempBMMEventsFile)); + assertTrue(mTempBMMEventsFile.length() != 0); + } + @Test public void deleteExpiredBackupManagerMonitorEvent_eventsAreExpired_deleteEventsAndReturnTrue() throws Exception { @@ -238,15 +269,20 @@ public class BackupManagerMonitorDumpsysUtilsTest { extends BackupManagerMonitorDumpsysUtils { private long testRetentionPeriod; + private long testSizeLimit; TestBackupManagerMonitorDumpsysUtils() { super(); this.testRetentionPeriod = mRetentionPeriod; + this.testSizeLimit = mSizeLimit; } public void setTestRetentionPeriod(long testRetentionPeriod) { this.testRetentionPeriod = testRetentionPeriod; } + public void setTestSizeLimit(long testSizeLimit) { + this.testSizeLimit = testSizeLimit; + } @Override public File getBMMEventsFile() { @@ -263,5 +299,11 @@ public class BackupManagerMonitorDumpsysUtilsTest { return testRetentionPeriod; } + @Override + long getBMMEventsFileSizeLimit(){ + return testSizeLimit; + } + + } } -- cgit v1.2.3-59-g8ed1b From 0c5993fa0e39e4959a18994663923bbb2ddc44e1 Mon Sep 17 00:00:00 2001 From: beatricemarch Date: Thu, 31 Aug 2023 12:53:16 +0000 Subject: Implement the ability to log extras relating to version mismatches between packages on the source and target. Imporve readability of events in dumpsys. Test: manual, do restore on test device, verify that the correct events are printed in the dumpsys atest CtsBackupHostTestCases, GtsBackupHostTestCases atest BackupManagerMonitorDumpsysUtilsTest Bug: 296818666 Change-Id: Ifd2d68861fcd33637c49f0e7802c456e43ffd9a2 --- .../utils/BackupManagerMonitorDumpsysUtils.java | 56 +++++++++++++++++----- 1 file changed, 43 insertions(+), 13 deletions(-) (limited to 'services/backup/java') diff --git a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java index 4b0d5a4928b6..797aed9297a3 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java @@ -84,15 +84,15 @@ public class BackupManagerMonitorDumpsysUtils { * - Agent logs (if available) * * Example of formatting: - * RESTORE Event: [2023-08-18 17:16:00.735] Agent - Agent logging results - * Package name: com.android.wallpaperbackup - * Agent Logs: - * Data Type: wlp_img_system - * Item restored: 0/1 - * Agent Error - Category: no_wallpaper, Count: 1 - * Data Type: wlp_img_lock - * Item restored: 0/1 - * Agent Error - Category: no_wallpaper, Count: 1 + * [2023-09-21 14:43:33.824] - Agent logging results + * Package: com.android.wallpaperbackup + * Agent Logs: + * Data Type: wlp_img_system + * Item restored: 0/1 + * Agent Error - Category: no_wallpaper, Count: 1 + * Data Type: wlp_img_lock + * Item restored: 0/1 + * Agent Error - Category: no_wallpaper, Count: 1 */ public void parseBackupManagerMonitorRestoreEventForDumpsys(Bundle eventBundle) { if (isAfterRetentionPeriod()) { @@ -139,17 +139,16 @@ public class BackupManagerMonitorDumpsysUtils { return; } - pw.println("RESTORE Event: [" + timestamp() + "] " + - getCategory(eventCategory) + " - " + - getId(eventId)); + pw.println("[" + timestamp() + "] - " + getId(eventId)); if (eventBundle.containsKey(BackupManagerMonitor.EXTRA_LOG_EVENT_PACKAGE_NAME)) { - pw.println("\tPackage name: " + pw.println("\tPackage: " + eventBundle.getString(BackupManagerMonitor.EXTRA_LOG_EVENT_PACKAGE_NAME)); } // TODO(b/296818666): add extras to the events addAgentLogsIfAvailable(eventBundle, pw); + addExtrasIfAvailable(eventBundle, pw); } catch (java.io.IOException e) { Slog.e(TAG, "IO Exception when writing BMM events to file: " + e); } @@ -194,6 +193,37 @@ public class BackupManagerMonitorDumpsysUtils { } } + /** + * Extracts some extras (defined in BackupManagerMonitor as EXTRA_LOG_) + * from the BackupManagerMonitor event. Not all extras have the same importance. For now only + * focus on extras relating to version mismatches between packages on the source and target. + * + * When an event with ID LOG_EVENT_ID_RESTORE_VERSION_HIGHER (trying to restore from higher to + * lower version of a package) parse: + * EXTRA_LOG_RESTORE_VERSION [int]: the version of the package on the source + * EXTRA_LOG_RESTORE_ANYWAY [bool]: if the package allows restore any version + * EXTRA_LOG_RESTORE_VERSION_TARGET [int]: an extra to record the package version on the target + */ + private void addExtrasIfAvailable(Bundle eventBundle, PrintWriter pw) { + if (eventBundle.getInt(BackupManagerMonitor.EXTRA_LOG_EVENT_ID) == + BackupManagerMonitor.LOG_EVENT_ID_RESTORE_VERSION_HIGHER) { + if (eventBundle.containsKey(BackupManagerMonitor.EXTRA_LOG_RESTORE_ANYWAY)) { + pw.println("\t\tPackage supports RestoreAnyVersion: " + + eventBundle.getBoolean(BackupManagerMonitor.EXTRA_LOG_RESTORE_ANYWAY)); + } + if (eventBundle.containsKey(BackupManagerMonitor.EXTRA_LOG_RESTORE_VERSION)) { + pw.println("\t\tPackage version on source: " + + eventBundle.getLong(BackupManagerMonitor.EXTRA_LOG_RESTORE_VERSION)); + } + if (eventBundle.containsKey( + BackupManagerMonitor.EXTRA_LOG_EVENT_PACKAGE_LONG_VERSION)) { + pw.println("\t\tPackage version on target: " + + eventBundle.getLong( + BackupManagerMonitor.EXTRA_LOG_EVENT_PACKAGE_LONG_VERSION)); + } + } + } + /* * Get the path of the text files which stores the BMM events */ -- cgit v1.2.3-59-g8ed1b