Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit f11e886d authored by Piyush Mehrotra's avatar Piyush Mehrotra
Browse files

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
parent 6579627c

cmds/bmgr/src/com/android/commands/bmgr/Bmgr.java

+18 −0
Original line number Diff line number Diff line
@@ -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";

        }

core/java/android/app/backup/BackupManagerMonitor.java

+27 −0
Original line number Diff line number Diff line
@@ -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.

services/backup/flags.aconfig

+8 −0
Original line number Diff line number Diff line
@@ -51,3 +51,11 @@ flag { 
    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

services/backup/java/com/android/server/backup/UserBackupManagerService.java

+49 −1
Original line number Diff line number Diff line
@@ -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) {

services/backup/java/com/android/server/backup/restore/FullRestoreEngine.java

+31 −0
Original line number Diff line number Diff line
@@ -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)