Log apexd reverts to StatsLog

When resuming sessions in StagingManager, check whether any
apex sessions have an associated crashing native process, which
indicates the session has been reverted by apexd. Keep track of
this failure reason (there will be only one), and the one or more
package names which have been reverted. Wait until the BOOT_COMPLETED
broadcast (which needs to occur to know that StatsLog is ready) before
logging through WatchdogRollbackLogger.

Only log once per logging parent package, in the case that multiple
packages with the same parent have been reverted.

Test: atest WatchdogRollbackLoggerTest
Test: atest ApexRollbackTests#testAutomaticBootLoopRecovery, check
      logcat to ensure revert is being correctly logged
Bug: 138782888

Change-Id: I57999260a826e476e0a75abe1304a83768b4c819

3 files changed, 172 insertions, 25 deletions

diff --git a/services/core/java/com/android/server/pm/StagingManager.java b/services/core/java/com/android/server/pm/StagingManager.java
index 89354537526c..614cc3fc2f3a 100644
--- a/services/core/java/com/android/server/pm/StagingManager.java
+++ b/services/core/java/com/android/server/pm/StagingManager.java
@@ -57,6 +57,7 @@ import android.os.UserHandle;
 import android.os.UserManagerInternal;
 import android.os.storage.IStorageManager;
 import android.os.storage.StorageManager;
+import android.text.TextUtils;
 import android.util.IntArray;
 import android.util.Slog;
 import android.util.SparseArray;
@@ -67,6 +68,7 @@ import com.android.internal.annotations.GuardedBy;
 import com.android.internal.content.PackageHelper;
 import com.android.internal.os.BackgroundThread;
 import com.android.server.LocalServices;
+import com.android.server.rollback.WatchdogRollbackLogger;
 
 import java.io.File;
 import java.io.IOException;
@@ -99,6 +101,10 @@ public class StagingManager {
     @GuardedBy("mStagedSessions")
     private final SparseIntArray mSessionRollbackIds = new SparseIntArray();
 
+    @GuardedBy("mFailedPackageNames")
+    private final List<String> mFailedPackageNames = new ArrayList<>();
+    private String mNativeFailureReason;
+
     StagingManager(PackageInstallerService pi, Context context) {
         mPi = pi;
         mContext = context;
@@ -441,6 +447,22 @@ public class StagingManager {
         }
     }
 
+    /**
+     *  Prepares for the logging of apexd reverts by storing the native failure reason if necessary,
+     *  and adding the package name of the session which apexd reverted to the list of reverted
+     *  session package names.
+     *  Logging needs to wait until the ACTION_BOOT_COMPLETED broadcast is sent.
+     */
+    private void prepareForLoggingApexdRevert(@NonNull PackageInstallerSession session,
+            @NonNull String nativeFailureReason) {
+        synchronized (mFailedPackageNames) {
+            mNativeFailureReason = nativeFailureReason;
+            if (session.getPackageName() != null) {
+                mFailedPackageNames.add(session.getPackageName());
+            }
+        }
+    }
+
     private void resumeSession(@NonNull PackageInstallerSession session) {
         Slog.d(TAG, "Resuming session " + session.sessionId);
 
@@ -450,6 +472,12 @@ public class StagingManager {
             // Check with apexservice whether the apex packages have been activated.
             apexSessionInfo = mApexManager.getStagedSessionInfo(session.sessionId);
 
+            // Prepare for logging a native crash during boot, if one occurred.
+            if (apexSessionInfo != null && !TextUtils.isEmpty(
+                    apexSessionInfo.crashingNativeProcess)) {
+                prepareForLoggingApexdRevert(session, apexSessionInfo.crashingNativeProcess);
+            }
+
             if (apexSessionInfo != null && apexSessionInfo.isVerified) {
                 // Session has been previously submitted to apexd, but didn't complete all the
                 // pre-reboot verification, perhaps because the device rebooted in the meantime.
@@ -955,12 +983,23 @@ public class StagingManager {
         }
     }
 
+    private void logFailedApexSessionsIfNecessary() {
+        synchronized (mFailedPackageNames) {
+            if (!mFailedPackageNames.isEmpty()) {
+                WatchdogRollbackLogger.logApexdRevert(mContext,
+                        mFailedPackageNames, mNativeFailureReason);
+            }
+        }
+    }
+
     void systemReady() {
         // Register the receiver of boot completed intent for staging manager.
         mContext.registerReceiver(new BroadcastReceiver() {
             @Override
             public void onReceive(Context ctx, Intent intent) {
                 mPreRebootVerificationHandler.readyToStart();
+                BackgroundThread.getExecutor().execute(
+                        () -> logFailedApexSessionsIfNecessary());
                 ctx.unregisterReceiver(this);
             }
         }, new IntentFilter(Intent.ACTION_BOOT_COMPLETED));
diff --git a/services/core/java/com/android/server/rollback/WatchdogRollbackLogger.java b/services/core/java/com/android/server/rollback/WatchdogRollbackLogger.java
index 46ec2f8258ca..f3f14a95eac6 100644
--- a/services/core/java/com/android/server/rollback/WatchdogRollbackLogger.java
+++ b/services/core/java/com/android/server/rollback/WatchdogRollbackLogger.java
@@ -20,7 +20,12 @@ import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCU
 import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_APP_NOT_RESPONDING;
 import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_EXPLICIT_HEALTH_CHECK;
 import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH;
+import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH_DURING_BOOT;
 import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_UNKNOWN;
+import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_BOOT_TRIGGERED;
+import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_FAILURE;
+import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_INITIATE;
+import static com.android.internal.util.FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS;
 
 import android.annotation.NonNull;
 import android.annotation.Nullable;
@@ -36,7 +41,6 @@ import android.util.Slog;
 import android.util.StatsLog;
 
 import com.android.internal.annotations.VisibleForTesting;
-import com.android.internal.util.FrameworkStatsLog;
 import com.android.server.PackageWatchdog;
 
 import java.util.ArrayList;
@@ -58,8 +62,8 @@ public final class WatchdogRollbackLogger {
     private static String getLoggingParentName(Context context, @NonNull String packageName) {
         PackageManager packageManager = context.getPackageManager();
         try {
-            ApplicationInfo ai = packageManager.getApplicationInfo(packageName,
-                    PackageManager.GET_META_DATA);
+            int flags = PackageManager.MATCH_APEX | PackageManager.GET_META_DATA;
+            ApplicationInfo ai = packageManager.getPackageInfo(packageName, flags).applicationInfo;
             if (ai.metaData == null) {
                 return null;
             }
@@ -95,6 +99,22 @@ public final class WatchdogRollbackLogger {
         return loggingParent;
     }
 
+
+    /**
+     * Gets the set of parent packages for a given set of failed package names. In the case that
+     * multiple sessions have failed, we want to log failure for each of the parent packages.
+     * Even if multiple failed packages have the same parent, we only log the parent package once.
+     */
+    private static Set<VersionedPackage> getLogPackages(Context context,
+            @NonNull List<String> failedPackageNames) {
+        Set<VersionedPackage> parentPackages = new ArraySet<>();
+        for (String failedPackageName: failedPackageNames) {
+            parentPackages.add(getLogPackage(context, new VersionedPackage(failedPackageName, 0)));
+        }
+        return parentPackages;
+    }
+
+
     static void logRollbackStatusOnBoot(Context context, int rollbackId,
             List<RollbackInfo> recentlyCommittedRollbacks) {
         PackageInstaller packageInstaller = context.getPackageManager().getPackageInstaller();
@@ -142,19 +162,36 @@ public final class WatchdogRollbackLogger {
         for (VersionedPackage oldLoggingPackage : oldLoggingPackages) {
             if (sessionInfo.isStagedSessionApplied()) {
                 logEvent(oldLoggingPackage,
-                        FrameworkStatsLog
-                                .WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS,
+                        WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS,
                         WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_UNKNOWN, "");
             } else if (sessionInfo.isStagedSessionFailed()) {
                 logEvent(oldLoggingPackage,
-                        FrameworkStatsLog
-                                .WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_FAILURE,
+                        WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_FAILURE,
                         WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_UNKNOWN, "");
             }
         }
     }
 
     /**
+     * Logs that one or more apexd reverts have occurred, along with the crashing native process
+     * that caused apexd to revert during boot.
+     *
+     * @param context the context to use when determining the log packages
+     * @param failedPackageNames a list of names of packages which were reverted
+     * @param failingNativeProcess the crashing native process which caused a revert
+     */
+    public static void logApexdRevert(Context context, @NonNull List<String> failedPackageNames,
+            @NonNull String failingNativeProcess) {
+        Set<VersionedPackage> logPackages = getLogPackages(context, failedPackageNames);
+        for (VersionedPackage logPackage: logPackages) {
+            logEvent(logPackage,
+                    WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS,
+                    WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH_DURING_BOOT,
+                    failingNativeProcess);
+        }
+    }
+
+    /**
      * Log a Watchdog rollback event to statsd.
      *
      * @param logPackage the package to associate the rollback with.
@@ -196,14 +233,13 @@ public final class WatchdogRollbackLogger {
 
     private static String rollbackTypeToString(int type) {
         switch (type) {
-            case FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_INITIATE:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_INITIATE:
                 return "ROLLBACK_INITIATE";
-            case FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS:
                 return "ROLLBACK_SUCCESS";
-            case FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_FAILURE:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_FAILURE:
                 return "ROLLBACK_FAILURE";
-            case FrameworkStatsLog
-                        .WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_BOOT_TRIGGERED:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_BOOT_TRIGGERED:
                 return "ROLLBACK_BOOT_TRIGGERED";
             default:
                 return "UNKNOWN";
@@ -212,16 +248,16 @@ public final class WatchdogRollbackLogger {
 
     private static String rollbackReasonToString(int reason) {
         switch (reason) {
-            case FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH:
                 return "REASON_NATIVE_CRASH";
-            case FrameworkStatsLog
-                    .WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_EXPLICIT_HEALTH_CHECK:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_EXPLICIT_HEALTH_CHECK:
                 return "REASON_EXPLICIT_HEALTH_CHECK";
-            case FrameworkStatsLog.WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_APP_CRASH:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_APP_CRASH:
                 return "REASON_APP_CRASH";
-            case FrameworkStatsLog
-                        .WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_APP_NOT_RESPONDING:
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_APP_NOT_RESPONDING:
                 return "REASON_APP_NOT_RESPONDING";
+            case WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_REASON__REASON_NATIVE_CRASH_DURING_BOOT:
+                return "REASON_NATIVE_CRASH_DURING_BOOT";
             default:
                 return "UNKNOWN";
         }
diff --git a/services/tests/servicestests/src/com/android/server/rollback/WatchdogRollbackLoggerTest.java b/services/tests/servicestests/src/com/android/server/rollback/WatchdogRollbackLoggerTest.java
index ba493d4f9646..d1c9643859e3 100644
--- a/services/tests/servicestests/src/com/android/server/rollback/WatchdogRollbackLoggerTest.java
+++ b/services/tests/servicestests/src/com/android/server/rollback/WatchdogRollbackLoggerTest.java
@@ -20,7 +20,11 @@ import static com.google.common.truth.Truth.assertThat;
 
 import static org.mockito.ArgumentMatchers.anyInt;
 import static org.mockito.ArgumentMatchers.anyString;
+import static org.mockito.ArgumentMatchers.eq;
+import static org.mockito.ArgumentMatchers.same;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 
 import android.content.Context;
@@ -36,6 +40,8 @@ import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.junit.runners.JUnit4;
 
+import java.util.List;
+
 @RunWith(JUnit4.class)
 public class WatchdogRollbackLoggerTest {
 
@@ -46,6 +52,11 @@ public class WatchdogRollbackLoggerTest {
     private PackageInfo mPackageInfo;
 
     private static final String LOGGING_PARENT_KEY = "android.content.pm.LOGGING_PARENT";
+    private static final String LOGGING_PARENT_VALUE = "logging.parent";
+    private static final int PACKAGE_INFO_FLAGS = PackageManager.MATCH_APEX
+            | PackageManager.GET_META_DATA;
+    private static final List<String> sFailingPackages =
+            List.of("package1", "package2", "package3");
 
     @Before
     public void setUp() {
@@ -64,10 +75,12 @@ public class WatchdogRollbackLoggerTest {
      */
     @Test
     public void testLogPackageHasNoMetadata() throws Exception {
-        when(mMockPm.getApplicationInfo(anyString(), anyInt())).thenReturn(mApplicationInfo);
+        when(mMockPm.getPackageInfo(anyString(), anyInt())).thenReturn(mPackageInfo);
         VersionedPackage logPackage = WatchdogRollbackLogger.getLogPackage(mMockContext,
                 sTestPackageV1);
         assertThat(logPackage).isNull();
+        verify(mMockPm, times(1)).getPackageInfo(
+                sTestPackageV1.getPackageName(), PACKAGE_INFO_FLAGS);
     }
 
     /**
@@ -76,12 +89,16 @@ public class WatchdogRollbackLoggerTest {
      */
     @Test
     public void testLogPackageParentKeyIsNull() throws Exception {
-        when(mMockPm.getApplicationInfo(anyString(), anyInt())).thenReturn(mApplicationInfo);
+        when(mMockPm.getPackageInfo(anyString(), anyInt())).thenReturn(mPackageInfo);
         Bundle bundle = new Bundle();
         bundle.putString(LOGGING_PARENT_KEY, null);
+        mApplicationInfo.metaData = bundle;
+        mPackageInfo.applicationInfo = mApplicationInfo;
         VersionedPackage logPackage = WatchdogRollbackLogger.getLogPackage(mMockContext,
                 sTestPackageV1);
         assertThat(logPackage).isNull();
+        verify(mMockPm, times(1)).getPackageInfo(
+                sTestPackageV1.getPackageName(), PACKAGE_INFO_FLAGS);
     }
 
     /**
@@ -90,15 +107,18 @@ public class WatchdogRollbackLoggerTest {
     @Test
     public void testLogPackageHasParentKey() throws Exception {
         Bundle bundle = new Bundle();
-        bundle.putString(LOGGING_PARENT_KEY, "logging.parent");
+        bundle.putString(LOGGING_PARENT_KEY, LOGGING_PARENT_VALUE);
         mApplicationInfo.metaData = bundle;
+        mPackageInfo.applicationInfo = mApplicationInfo;
         mPackageInfo.setLongVersionCode(12345L);
-        when(mMockPm.getApplicationInfo(anyString(), anyInt())).thenReturn(mApplicationInfo);
         when(mMockPm.getPackageInfo(anyString(), anyInt())).thenReturn(mPackageInfo);
         VersionedPackage logPackage = WatchdogRollbackLogger.getLogPackage(mMockContext,
                 sTestPackageV1);
-        VersionedPackage expectedLogPackage = new VersionedPackage("logging.parent", 12345);
+        VersionedPackage expectedLogPackage = new VersionedPackage(LOGGING_PARENT_VALUE, 12345);
         assertThat(logPackage).isEqualTo(expectedLogPackage);
+        verify(mMockPm, times(1)).getPackageInfo(
+                sTestPackageV1.getPackageName(), PACKAGE_INFO_FLAGS);
+
     }
 
     /**
@@ -107,12 +127,64 @@ public class WatchdogRollbackLoggerTest {
     @Test
     public void testLogPackageNameNotFound() throws Exception {
         Bundle bundle = new Bundle();
-        bundle.putString("android.content.pm.LOGGING_PARENT", "logging.parent");
+        bundle.putString(LOGGING_PARENT_KEY, LOGGING_PARENT_VALUE);
         mApplicationInfo.metaData = bundle;
-        when(mMockPm.getPackageInfo(anyString(), anyInt())).thenThrow(
+        mPackageInfo.applicationInfo = mApplicationInfo;
+        when(mMockPm.getPackageInfo(anyString(), anyInt())).thenReturn(mPackageInfo);
+        when(mMockPm.getPackageInfo(same(LOGGING_PARENT_VALUE), anyInt())).thenThrow(
                 new PackageManager.NameNotFoundException());
         VersionedPackage logPackage = WatchdogRollbackLogger.getLogPackage(mMockContext,
                 sTestPackageV1);
         assertThat(logPackage).isNull();
+        verify(mMockPm, times(1)).getPackageInfo(
+                sTestPackageV1.getPackageName(), PACKAGE_INFO_FLAGS);
+    }
+
+    /**
+     * Ensures that we make the correct Package Manager calls in the case that the failing packages
+     * are correctly configured with parent packages.
+     */
+    @Test
+    public void testApexdLoggingCallsWithParents() throws Exception {
+        for (String failingPackage: sFailingPackages) {
+            PackageInfo packageInfo = new PackageInfo();
+            ApplicationInfo applicationInfo = new ApplicationInfo();
+            Bundle bundle = new Bundle();
+            bundle.putString(LOGGING_PARENT_KEY, getParent(failingPackage));
+            applicationInfo.metaData = bundle;
+            packageInfo.applicationInfo = applicationInfo;
+            when(mMockPm.getPackageInfo(same(failingPackage), anyInt())).thenReturn(packageInfo);
+        }
+
+        when(mMockPm.getPackageInfo(anyString(), eq(0))).thenReturn(mPackageInfo);
+        WatchdogRollbackLogger.logApexdRevert(mMockContext, sFailingPackages, "test_process");
+        for (String failingPackage: sFailingPackages) {
+            verify(mMockPm, times(1)).getPackageInfo(failingPackage, PACKAGE_INFO_FLAGS);
+            verify(mMockPm, times(1)).getPackageInfo(getParent(failingPackage), 0);
+        }
+    }
+
+    /**
+     * Ensures that we don't make any calls to parent packages in the case that packages are not
+     * correctly configured with parent packages.
+     */
+    @Test
+    public void testApexdLoggingCallsWithNoParents() throws Exception {
+        for (String failingPackage: sFailingPackages) {
+            PackageInfo packageInfo = new PackageInfo();
+            packageInfo.applicationInfo = new ApplicationInfo();
+            when(mMockPm.getPackageInfo(same(failingPackage), anyInt())).thenReturn(packageInfo);
+        }
+        when(mMockPm.getPackageInfo(anyString(), eq(0))).thenReturn(mPackageInfo);
+
+        WatchdogRollbackLogger.logApexdRevert(mMockContext, sFailingPackages, "test_process");
+        verify(mMockPm, times(sFailingPackages.size())).getPackageInfo(anyString(), anyInt());
+        for (String failingPackage: sFailingPackages) {
+            verify(mMockPm, times(1)).getPackageInfo(failingPackage, PACKAGE_INFO_FLAGS);
+        }
+    }
+
+    private String getParent(String packageName) {
+        return packageName + "-parent";
     }
 }