From f11e886dc73bb52ad2b4f9c8225c322cfa383de5 Mon Sep 17 00:00:00 2001 From: Piyush Mehrotra Date: Thu, 28 Mar 2024 12:04:24 +0000 Subject: Increase BMM logging coverage for restore at install flow This change adds BMM logging in restore at install flow right from the point when PackageManager triggers restore. The change also adds more detailed logging in Full Restore flow, around various failure points. This'll help with quantify different failures that happen in Full Restore flow, some of which are masked by the complexity in Framework code. Bug: 331749778 Test: Ensure that the change builds (m -j frameworks/base) Ensure CTS and GTS B&R tests pass Change-Id: Ieff6df433398ffff71c7eeda73174f9f1d509b58 --- services/backup/flags.aconfig | 8 +++ .../server/backup/UserBackupManagerService.java | 50 ++++++++++++++++++- .../server/backup/restore/FullRestoreEngine.java | 31 ++++++++++++ .../backup/restore/PerformUnifiedRestoreTask.java | 57 ++++++++++++++-------- .../utils/BackupManagerMonitorDumpsysUtils.java | 18 +++++++ 5 files changed, 142 insertions(+), 22 deletions(-) (limited to 'services') diff --git a/services/backup/flags.aconfig b/services/backup/flags.aconfig index e9f959f4b9eb..74adfe08dba7 100644 --- a/services/backup/flags.aconfig +++ b/services/backup/flags.aconfig @@ -50,4 +50,12 @@ flag { "logger." bug: "296844513" is_fixed_read_only: true +} + +flag { + name: "enable_increased_bmm_logging_for_restore_at_install" + namespace: "onboarding" + description: "Increase BMM logging coverage in restore at install flow." + bug: "331749778" + is_fixed_read_only: true } \ No newline at end of file diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java index 976504a8d880..dc1cfb92c3b8 100644 --- a/services/backup/java/com/android/server/backup/UserBackupManagerService.java +++ b/services/backup/java/com/android/server/backup/UserBackupManagerService.java @@ -3903,11 +3903,33 @@ public class UserBackupManagerService { skip = true; } + BackupManagerMonitorEventSender mBMMEventSender = + getBMMEventSender(/*monitor=*/ null); + PackageInfo packageInfo = getPackageInfoForBMMLogging(packageName); TransportConnection transportConnection = mTransportManager.getCurrentTransportClient("BMS.restoreAtInstall()"); if (transportConnection == null) { if (DEBUG) Slog.w(TAG, addUserIdToLogMessage(mUserId, "No transport client")); skip = true; + } else if (Flags.enableIncreasedBmmLoggingForRestoreAtInstall()) { + try { + BackupTransportClient transportClient = transportConnection.connectOrThrow( + "BMS.restoreAtInstall"); + mBMMEventSender.setMonitor(transportClient.getBackupManagerMonitor()); + } catch (TransportNotAvailableException | RemoteException e) { + mBMMEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_TRANSPORT_IS_NULL, packageInfo, + BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, null); + } + } + + if (Flags.enableIncreasedBmmLoggingForRestoreAtInstall()) { + mBMMEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_RESTORE_AT_INSTALL_INVOKED, packageInfo, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + mBMMEventSender.putMonitoringExtra(/*extras=*/null, + BackupManagerMonitor.EXTRA_LOG_OPERATION_TYPE, + BackupAnnotations.OperationType.RESTORE)); } if (!mAutoRestore) { @@ -3943,7 +3965,7 @@ public class UserBackupManagerService { RestoreParams.createForRestoreAtInstall( transportConnection, /* observer */ null, - /* monitor */ null, + mBMMEventSender.getMonitor(), restoreSet, packageName, token, @@ -3963,6 +3985,15 @@ public class UserBackupManagerService { if (skip) { // Auto-restore disabled or no way to attempt a restore + if (Flags.enableIncreasedBmmLoggingForRestoreAtInstall()) { + mBMMEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_SKIP_RESTORE_AT_INSTALL, packageInfo, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + mBMMEventSender.putMonitoringExtra(/*extras=*/null, + BackupManagerMonitor.EXTRA_LOG_OPERATION_TYPE, + BackupAnnotations.OperationType.RESTORE)); + } + if (transportConnection != null) { mTransportManager.disposeOfTransportClient( transportConnection, "BMS.restoreAtInstall()"); @@ -3976,6 +4007,23 @@ public class UserBackupManagerService { } } + private PackageInfo getPackageInfoForBMMLogging(String packageName) { + try { + return mPackageManager.getPackageInfoAsUser(packageName, 0, mUserId); + } catch (NameNotFoundException e) { + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Asked to get PackageInfo for BMM logging of nonexistent pkg " + + packageName)); + + PackageInfo packageInfo = new PackageInfo(); + packageInfo.packageName = packageName; + + return packageInfo; + } + } + /** Hand off a restore session. */ public IRestoreSession beginRestoreSession(String packageName, String transport) { if (DEBUG) { diff --git a/services/backup/java/com/android/server/backup/restore/FullRestoreEngine.java b/services/backup/java/com/android/server/backup/restore/FullRestoreEngine.java index 2c9eb51972af..b414b252cc37 100644 --- a/services/backup/java/com/android/server/backup/restore/FullRestoreEngine.java +++ b/services/backup/java/com/android/server/backup/restore/FullRestoreEngine.java @@ -29,6 +29,7 @@ import android.app.ApplicationThreadConstants; import android.app.IBackupAgent; import android.app.backup.BackupAgent; import android.app.backup.BackupAnnotations; +import android.app.backup.BackupManagerMonitor; import android.app.backup.FullBackup; import android.app.backup.IBackupManagerMonitor; import android.app.backup.IFullBackupRestoreObserver; @@ -57,6 +58,7 @@ import com.android.server.backup.OperationStorage.OpType; import com.android.server.backup.UserBackupManagerService; import com.android.server.backup.fullbackup.FullBackupObbConnection; import com.android.server.backup.utils.BackupEligibilityRules; +import com.android.server.backup.utils.BackupManagerMonitorEventSender; import com.android.server.backup.utils.BytesReadListener; import com.android.server.backup.utils.FullBackupRestoreObserverUtils; import com.android.server.backup.utils.RestoreUtils; @@ -143,6 +145,8 @@ public class FullRestoreEngine extends RestoreEngine { private FileMetadata mReadOnlyParent = null; + private BackupManagerMonitorEventSender mBackupManagerMonitorEventSender; + public FullRestoreEngine( UserBackupManagerService backupManagerService, OperationStorage operationStorage, BackupRestoreTask monitorTask, IFullBackupRestoreObserver observer, @@ -155,6 +159,7 @@ public class FullRestoreEngine extends RestoreEngine { mMonitorTask = monitorTask; mObserver = observer; mMonitor = monitor; + mBackupManagerMonitorEventSender = new BackupManagerMonitorEventSender(monitor); mOnlyPackage = onlyPackage; mAllowApks = allowApks; mAgentTimeoutParameters = Objects.requireNonNull( @@ -225,6 +230,9 @@ public class FullRestoreEngine extends RestoreEngine { // one app's data but see a different app's on the wire if (onlyPackage != null) { if (!pkg.equals(onlyPackage.packageName)) { + logBMMEvent( + BackupManagerMonitor.LOG_EVENT_ID_RESTORE_DATA_DOES_NOT_BELONG_TO_PACKAGE, + onlyPackage); Slog.w(TAG, "Expected data for " + onlyPackage + " but saw " + pkg); setResult(RestoreEngine.TRANSPORT_FAILURE); setRunning(false); @@ -412,6 +420,9 @@ public class FullRestoreEngine extends RestoreEngine { } if (mAgent == null) { + logBMMEvent( + BackupManagerMonitor.LOG_EVENT_ID_UNABLE_TO_CREATE_AGENT_FOR_RESTORE, + onlyPackage); Slog.e(TAG, "Unable to create agent for " + pkg); okay = false; tearDownPipes(); @@ -501,6 +512,9 @@ public class FullRestoreEngine extends RestoreEngine { } catch (RemoteException e) { // whoops, remote entity went away. We'll eat the content // ourselves, then, and not copy it over. + logBMMEvent( + BackupManagerMonitor.LOG_EVENT_ID_AGENT_CRASHED_BEFORE_RESTORE_DATA_IS_SENT, + onlyPackage); Slog.e(TAG, "Agent crashed during full restore"); agentSuccess = false; okay = false; @@ -531,6 +545,9 @@ public class FullRestoreEngine extends RestoreEngine { } catch (IOException e) { Slog.e(TAG, "Failed to write to restore pipe: " + e.getMessage()); + logBMMEvent( + BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_SEND_DATA_TO_AGENT_DURING_RESTORE, + onlyPackage); pipeOkay = false; } } @@ -548,6 +565,8 @@ public class FullRestoreEngine extends RestoreEngine { // okay, if the remote end failed at any point, deal with // it by ignoring the rest of the restore on it if (!agentSuccess) { + logBMMEvent(BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE_DURING_RESTORE, + onlyPackage); Slog.w(TAG, "Agent failure restoring " + pkg + "; ending restore"); mBackupManagerService.getBackupHandler().removeMessages( MSG_RESTORE_OPERATION_TIMEOUT); @@ -590,6 +609,8 @@ public class FullRestoreEngine extends RestoreEngine { if (DEBUG) { Slog.w(TAG, "io exception on restore socket read: " + e.getMessage()); } + logBMMEvent(BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_READ_DATA_FROM_TRANSPORT, + onlyPackage); setResult(RestoreEngine.TRANSPORT_FAILURE); info = null; } @@ -631,6 +652,16 @@ public class FullRestoreEngine extends RestoreEngine { return false; } + private void logBMMEvent(int eventId, PackageInfo pkgInfo) { + if (Flags.enableIncreasedBmmLoggingForRestoreAtInstall()) { + mBackupManagerMonitorEventSender.monitorEvent(eventId, pkgInfo, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + mBackupManagerMonitorEventSender.putMonitoringExtra(/*extras=*/ + null, BackupManagerMonitor.EXTRA_LOG_OPERATION_TYPE, + BackupAnnotations.OperationType.RESTORE)); + } + } + private static boolean isValidParent(FileMetadata parentDir, @NonNull FileMetadata childDir) { return parentDir != null && childDir.packageName.equals(parentDir.packageName) 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 8fece8257b89..e536876f6cc3 100644 --- a/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java +++ b/services/backup/java/com/android/server/backup/restore/PerformUnifiedRestoreTask.java @@ -418,25 +418,6 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { private void startRestore() { sendStartRestore(mAcceptSet.size()); - // 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 { String transportDirName = mTransportManager.getTransportDirName( @@ -459,6 +440,34 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { mBackupManagerMonitorEventSender.setMonitor(transport.getBackupManagerMonitor()); } + if (Flags.enableIncreasedBmmLoggingForRestoreAtInstall()) { + for (PackageInfo info : mAcceptSet) { + mBackupManagerMonitorEventSender.monitorEvent( + BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_ACCEPTED_FOR_RESTORE, info, + BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, + addRestoreOperationTypeToEvent(/* extras= */ null)); + } + } + + // 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); + } + mStatus = transport.startRestore(mToken, packages); if (mStatus != BackupTransport.TRANSPORT_OK) { Slog.e(TAG, "Transport error " + mStatus + "; no restore possible"); @@ -638,7 +647,7 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { Bundle monitoringExtras = addRestoreOperationTypeToEvent(/* extras= */ null); mBackupManagerMonitorEventSender.monitorEvent( BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_NOT_PRESENT, - mCurrentPackage, + createPackageInfoForBMMLogging(pkgName), BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, monitoringExtras); EventLog.writeEvent( @@ -739,7 +748,7 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { Bundle monitoringExtras = addRestoreOperationTypeToEvent(/* extras= */ null); mBackupManagerMonitorEventSender.monitorEvent( BackupManagerMonitor.LOG_EVENT_ID_NO_NEXT_RESTORE_TARGET, - mCurrentPackage, + null, BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, monitoringExtras); EventLog.writeEvent(EventLogTags.RESTORE_TRANSPORT_FAILURE); @@ -1804,4 +1813,10 @@ public class PerformUnifiedRestoreTask implements BackupRestoreTask { monitoringExtrasDenylist); } + private PackageInfo createPackageInfoForBMMLogging(String packageName) { + PackageInfo packageInfo = new PackageInfo(); + packageInfo.packageName = packageName; + + return packageInfo; + } } 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 6d315ba38b31..fad59d23a6dc 100644 --- a/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java +++ b/services/backup/java/com/android/server/backup/utils/BackupManagerMonitorDumpsysUtils.java @@ -371,6 +371,24 @@ public class BackupManagerMonitorDumpsysUtils { "V to U restore pkg not eligible"; case BackupManagerMonitor.LOG_EVENT_ID_V_TO_U_RESTORE_SET_LIST -> "V to U restore lists"; + case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_AT_INSTALL_INVOKED -> + "Invoked restore at install"; + case BackupManagerMonitor.LOG_EVENT_ID_SKIP_RESTORE_AT_INSTALL -> + "Skip restore at install"; + case BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_ACCEPTED_FOR_RESTORE -> + "Pkg accepted for restore"; + case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_DATA_DOES_NOT_BELONG_TO_PACKAGE -> + "Restore data does not belong to package"; + case BackupManagerMonitor.LOG_EVENT_ID_UNABLE_TO_CREATE_AGENT_FOR_RESTORE -> + "Unable to create Agent"; + case BackupManagerMonitor.LOG_EVENT_ID_AGENT_CRASHED_BEFORE_RESTORE_DATA_IS_SENT -> + "Agent crashed before restore data is streamed"; + case BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_SEND_DATA_TO_AGENT_DURING_RESTORE -> + "Failed to send data to agent"; + case BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE_DURING_RESTORE -> + "Agent failure during restore"; + case BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_READ_DATA_FROM_TRANSPORT -> + "Failed to read data from Transport"; default -> "Unknown log event ID: " + code; }; return id; -- cgit v1.2.3-59-g8ed1b