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
diff --git a/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java b/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java
index 0d3dc49..6310d32 100644
--- a/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java
+++ b/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java
@@ -1280,6 +1280,24 @@
return "START_PACKAGE_RESTORE";
case BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE:
return "AGENT_FAILURE";
+ case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_AT_INSTALL_INVOKED:
+ return "RESTORE_AT_INSTALL_INVOKED";
+ case BackupManagerMonitor.LOG_EVENT_ID_SKIP_RESTORE_AT_INSTALL:
+ return "SKIP_RESTORE_AT_INSTALL";
+ case BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_ACCEPTED_FOR_RESTORE:
+ return "PACKAGE_ACCEPTED_FOR_RESTORE";
+ case BackupManagerMonitor.LOG_EVENT_ID_RESTORE_DATA_DOES_NOT_BELONG_TO_PACKAGE:
+ return "RESTORE_DATA_DOES_NOT_BELONG_TO_PACKAGE";
+ case BackupManagerMonitor.LOG_EVENT_ID_UNABLE_TO_CREATE_AGENT_FOR_RESTORE:
+ return "UNABLE_TO_CREATE_AGENT_FOR_RESTORE";
+ case BackupManagerMonitor.LOG_EVENT_ID_AGENT_CRASHED_BEFORE_RESTORE_DATA_IS_SENT:
+ return "AGENT_CRASHED_BEFORE_RESTORE_DATA_IS_SEN";
+ case BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_SEND_DATA_TO_AGENT_DURING_RESTORE:
+ return "FAILED_TO_SEND_DATA_TO_AGENT_DURING_RESTORE";
+ case BackupManagerMonitor.LOG_EVENT_ID_AGENT_FAILURE_DURING_RESTORE:
+ return "AGENT_FAILURE_DURING_RESTORE";
+ case BackupManagerMonitor.LOG_EVENT_ID_FAILED_TO_READ_DATA_FROM_TRANSPORT:
+ return "FAILED_TO_READ_DATA_FROM_TRANSPORT";
default:
return "UNKNOWN_ID";
}
diff --git a/core/java/android/app/backup/BackupManagerMonitor.java b/core/java/android/app/backup/BackupManagerMonitor.java
index c66478f..e741bc2 100644
--- a/core/java/android/app/backup/BackupManagerMonitor.java
+++ b/core/java/android/app/backup/BackupManagerMonitor.java
@@ -269,6 +269,33 @@
/** V to U restore attempt, allowlist and denlist are set
@hide */
public static final int LOG_EVENT_ID_V_TO_U_RESTORE_SET_LIST = 72;
+ /** As part of package install, {@link PackageManager} invoked restore.
+ @hide */
+ public static final int LOG_EVENT_ID_RESTORE_AT_INSTALL_INVOKED = 73;
+ /** Skipping restore at package install
+ @hide */
+ public static final int LOG_EVENT_ID_SKIP_RESTORE_AT_INSTALL = 74;
+ /** Package is eligible and is accepted for restore
+ @hide */
+ public static final int LOG_EVENT_ID_PACKAGE_ACCEPTED_FOR_RESTORE = 75;
+ /** Restore data doesn't belong to the package for which restore is started
+ @hide */
+ public static final int LOG_EVENT_ID_RESTORE_DATA_DOES_NOT_BELONG_TO_PACKAGE = 76;
+ /** Unable to create BackupAgent for package for restore
+ @hide */
+ public static final int LOG_EVENT_ID_UNABLE_TO_CREATE_AGENT_FOR_RESTORE = 77;
+ /** BackupAgent crashed after creation but before accepting any data
+ @hide */
+ public static final int LOG_EVENT_ID_AGENT_CRASHED_BEFORE_RESTORE_DATA_IS_SENT = 78;
+ /** Failure in streaming restore data to BackupAgent
+ @hide */
+ public static final int LOG_EVENT_ID_FAILED_TO_SEND_DATA_TO_AGENT_DURING_RESTORE = 79;
+ /** BackupAgent related failure during restore
+ @hide */
+ public static final int LOG_EVENT_ID_AGENT_FAILURE_DURING_RESTORE = 80;
+ /** Failure in reading data from TransportPackage during restore
+ @hide */
+ public static final int LOG_EVENT_ID_FAILED_TO_READ_DATA_FROM_TRANSPORT = 81;
/**
* This method will be called each time something important happens on BackupManager.
diff --git a/services/backup/flags.aconfig b/services/backup/flags.aconfig
index e9f959f..74adfe0 100644
--- a/services/backup/flags.aconfig
+++ b/services/backup/flags.aconfig
@@ -50,4 +50,12 @@
"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 976504a..dc1cfb9 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 @@
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 @@
RestoreParams.createForRestoreAtInstall(
transportConnection,
/* observer */ null,
- /* monitor */ null,
+ mBMMEventSender.getMonitor(),
restoreSet,
packageName,
token,
@@ -3963,6 +3985,15 @@
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 @@
}
}
+ 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 2c9eb51..b414b25 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.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.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 @@
private FileMetadata mReadOnlyParent = null;
+ private BackupManagerMonitorEventSender mBackupManagerMonitorEventSender;
+
public FullRestoreEngine(
UserBackupManagerService backupManagerService, OperationStorage operationStorage,
BackupRestoreTask monitorTask, IFullBackupRestoreObserver observer,
@@ -155,6 +159,7 @@
mMonitorTask = monitorTask;
mObserver = observer;
mMonitor = monitor;
+ mBackupManagerMonitorEventSender = new BackupManagerMonitorEventSender(monitor);
mOnlyPackage = onlyPackage;
mAllowApks = allowApks;
mAgentTimeoutParameters = Objects.requireNonNull(
@@ -225,6 +230,9 @@
// 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 @@
}
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 @@
} 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 @@
} 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 @@
// 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 @@
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 @@
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 8fece82..e536876 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 @@
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 @@
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 @@
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 @@
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 @@
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 6d315ba..fad59d2 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 @@
"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;