From 5b163cfcee971458dd4dadd8d03ed7489e2780db Mon Sep 17 00:00:00 2001
From: JW Wang <wangchun@google.com>
Date: Mon, 30 Mar 2020 15:53:39 +0800
Subject: [PATCH] Add logs for debugging

See b/151890602#comment4.

If the assumption is true, we will see logs that the rollback for
testappA is exipred happens slightly after the call to #getAvailableRollbacks.

Also move assertions below so the test runs to the end and we have a
better picture for what happened during the test.

(Cherry-picked from eab998a9afb052b5e022d0db9ab889e141213c42)

Bug: 151890602
Test: m
Merged-In: I85adb8c3c5598ef4ce11550b51f22d1ce3c282a6
Change-Id: I85adb8c3c5598ef4ce11550b51f22d1ce3c282a6
---
 .../rollback/RollbackManagerServiceImpl.java  |  9 +++------
 .../android/tests/rollback/RollbackTest.java  | 19 ++++++++++---------
 2 files changed, 13 insertions(+), 15 deletions(-)

diff --git a/services/core/java/com/android/server/rollback/RollbackManagerServiceImpl.java b/services/core/java/com/android/server/rollback/RollbackManagerServiceImpl.java
index b50c22ea09e31..e56bda2946f47 100644
--- a/services/core/java/com/android/server/rollback/RollbackManagerServiceImpl.java
+++ b/services/core/java/com/android/server/rollback/RollbackManagerServiceImpl.java
@@ -515,6 +515,7 @@ class RollbackManagerServiceImpl extends IRollbackManager.Stub {
         if (mRollbackLifetimeDurationInMillis < 0) {
             mRollbackLifetimeDurationInMillis = DEFAULT_ROLLBACK_LIFETIME_DURATION_MILLIS;
         }
+        Slog.d(TAG, "mRollbackLifetimeDurationInMillis=" + mRollbackLifetimeDurationInMillis);
     }
 
     @AnyThread
@@ -656,9 +657,7 @@ class RollbackManagerServiceImpl extends IRollbackManager.Stub {
                 if (!now.isBefore(
                         rollbackTimestamp
                                 .plusMillis(mRollbackLifetimeDurationInMillis))) {
-                    if (LOCAL_LOGV) {
-                        Slog.v(TAG, "runExpiration id=" + rollback.info.getRollbackId());
-                    }
+                    Slog.i(TAG, "runExpiration id=" + rollback.info.getRollbackId());
                     iter.remove();
                     rollback.delete(mAppDataRollbackHelper);
                 } else if (oldest == null || oldest.isAfter(rollbackTimestamp)) {
@@ -1170,9 +1169,7 @@ class RollbackManagerServiceImpl extends IRollbackManager.Stub {
     @WorkerThread
     @GuardedBy("rollback.getLock")
     private void makeRollbackAvailable(Rollback rollback) {
-        if (LOCAL_LOGV) {
-            Slog.v(TAG, "makeRollbackAvailable id=" + rollback.info.getRollbackId());
-        }
+        Slog.i(TAG, "makeRollbackAvailable id=" + rollback.info.getRollbackId());
         rollback.makeAvailable();
 
         // TODO(zezeozue): Provide API to explicitly start observing instead
diff --git a/tests/RollbackTest/RollbackTest/src/com/android/tests/rollback/RollbackTest.java b/tests/RollbackTest/RollbackTest/src/com/android/tests/rollback/RollbackTest.java
index cab8b4258bc85..042ddd6c78824 100644
--- a/tests/RollbackTest/RollbackTest/src/com/android/tests/rollback/RollbackTest.java
+++ b/tests/RollbackTest/RollbackTest/src/com/android/tests/rollback/RollbackTest.java
@@ -487,23 +487,24 @@ public class RollbackTest {
                 // Wait until rollback for app A has expired
                 // This will trigger an expiration run that should expire app A but not B
                 Thread.sleep(expirationTime / 2);
-                RollbackInfo rollback =
+                RollbackInfo rollbackA =
                         getUniqueRollbackInfoForPackage(rm.getAvailableRollbacks(), TestApp.A);
-                assertThat(rollback).isNull();
+                Log.i(TAG, "Checking if the rollback for TestApp.A is null");
 
                 // Rollback for app B should not be expired
-                rollback = getUniqueRollbackInfoForPackage(
+                RollbackInfo rollbackB1 = getUniqueRollbackInfoForPackage(
                         rm.getAvailableRollbacks(), TestApp.B);
-                assertThat(rollback).isNotNull();
-                assertThat(rollback).packagesContainsExactly(
-                        Rollback.from(TestApp.B2).to(TestApp.B1));
 
                 // Wait until rollback for app B has expired
                 Thread.sleep(expirationTime / 2);
-                rollback = getUniqueRollbackInfoForPackage(
+                RollbackInfo rollbackB2 = getUniqueRollbackInfoForPackage(
                         rm.getAvailableRollbacks(), TestApp.B);
-                // Rollback should be expired by now
-                assertThat(rollback).isNull();
+
+                assertThat(rollbackA).isNull();
+                assertThat(rollbackB1).isNotNull();
+                assertThat(rollbackB1).packagesContainsExactly(
+                        Rollback.from(TestApp.B2).to(TestApp.B1));
+                assertThat(rollbackB2).isNull();
             } finally {
                 RollbackUtils.forwardTimeBy(-expirationTime);
             }