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

7 files changed, 187 insertions, 22 deletions

diff --git a/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java b/cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java
index 0d3dc4901d8d..6310d32515c5 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 @@ public class Bmgr {
                 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 c66478f6cf84..e741bc2bf608 100644
--- a/core/java/android/app/backup/BackupManagerMonitor.java
+++ b/core/java/android/app/backup/BackupManagerMonitor.java
@@ -269,6 +269,33 @@ public class BackupManagerMonitor {
   /** 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 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;