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/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;