Improved logging and assertions on UserLifecycleStressTest. (0a967bfa) · Commits · e / os / android_frameworks_base

services/tests/servicestests/src/com/android/server/pm/UserLifecycleStressTest.java

+86 −53

Original line number	Diff line number	Diff line
		@@ -17,11 +17,11 @@ package com.android.server.pm;

		import static android.os.UserHandle.USER_NULL;

		import static com.google.common.truth.Truth.assertThat;
		import static com.google.common.truth.Truth.assertWithMessage;

		import static org.junit.Assume.assumeFalse;

		import android.annotation.UserIdInt;
		import android.app.ActivityManager;
		import android.app.IStopUserCallback;
		import android.content.Context;
		@@ -42,12 +42,15 @@ import com.android.compatibility.common.util.BlockingBroadcastReceiver;
		import com.android.compatibility.common.util.ShellUtils;
		import com.android.internal.util.FunctionalUtils;

		import com.google.common.truth.StandardSubjectBuilder;
		import com.google.errorprone.annotations.FormatMethod;
		import com.google.errorprone.annotations.FormatString;

		import org.junit.After;
		import org.junit.Before;
		import org.junit.Test;
		import org.junit.runner.RunWith;

		import java.io.IOException;
		import java.util.List;
		import java.util.concurrent.CountDownLatch;
		import java.util.concurrent.TimeUnit;
		@@ -60,7 +63,7 @@ import java.util.concurrent.TimeoutException;
		@Postsubmit
		@RunWith(AndroidJUnit4.class)
		@LargeTest
		public class UserLifecycleStressTest {
		public final class UserLifecycleStressTest {
		private static final String TAG = "UserLifecycleStressTest";
		// TODO: Make this smaller once we have improved it.
		private static final int TIMEOUT_IN_SECOND = 40;
		@@ -80,7 +83,7 @@ public class UserLifecycleStressTest {
		private int mOriginalCurrentUserId;

		@Before
		public void setup() throws RemoteException {
		public void setup() throws Exception {
		mContext = InstrumentationRegistry.getInstrumentation().getContext();
		mUserManager = mContext.getSystemService(UserManager.class);
		mActivityManager = mContext.getSystemService(ActivityManager.class);
		@@ -92,8 +95,8 @@ public class UserLifecycleStressTest {
		}

		@After
		public void tearDown() throws IOException {
		switchUser(mOriginalCurrentUserId);
		public void tearDown() throws Exception {
		switchUser("on tearDown()", mOriginalCurrentUserId);
		mUserSwitchWaiter.close();
		Settings.Global.putString(mContext.getContentResolver(),
		Settings.Global.REMOVE_GUEST_ON_EXIT, mRemoveGuestOnExitOriginalValue);
		@@ -105,19 +108,24 @@ public class UserLifecycleStressTest {
		* in a reasonable amount of time.
		*/
		@Test
		public void stopManagedProfileStressTest() throws RemoteException, InterruptedException {
		public void stopManagedProfileStressTest() throws Exception {
		UserHandle mainUser = mUserManager.getMainUser();
		assumeFalse("There is no main user", mainUser == null);
		switchUser(mainUser.getIdentifier());
		switchUser("before iterations", mainUser.getIdentifier());

		for (int i = 0; i < NUM_ITERATIONS; i++) {
		logIteration(i, "stopManagedProfileStressTest");

		final UserInfo userInfo = mUserManager.createProfileForUser(TEST_USER_NAME,
		UserManager.USER_TYPE_PROFILE_MANAGED, 0, ActivityManager.getCurrentUser());
		assertThat(userInfo).isNotNull();
		int currentUserId = ActivityManager.getCurrentUser();
		int flags = 0;
		UserInfo userInfo = mUserManager.createProfileForUser(TEST_USER_NAME,
		UserManager.USER_TYPE_PROFILE_MANAGED, flags, currentUserId);
		assertWithMessageAtIteration(i, "result of createProfileForUser(%s, %s, %s, %s)",
		TEST_USER_NAME, UserManager.USER_TYPE_PROFILE_MANAGED, flags, currentUserId)
		.that(userInfo).isNotNull();
		Log.d(TAG, "Profile created: " + userInfo);
		try {
		assertWithMessage("Failed to start the profile")
		assertWithMessageAtIteration(i, "result of startUserInBackground(%s)", userInfo.id)
		.that(ActivityManager.getService().startUserInBackground(userInfo.id))
		.isTrue();
		// Seems the broadcast queue is getting more busy if we wait a few seconds before
		@@ -125,6 +133,7 @@ public class UserLifecycleStressTest {
		TimeUnit.SECONDS.sleep(WAIT_BEFORE_STOP_USER_IN_SECOND);
		stopUser(userInfo.id);
		} finally {
		Log.d(TAG, "Removing " + userInfo.id);
		mUserManager.removeUser(userInfo.id);
		}
		}
		@@ -137,22 +146,24 @@ public class UserLifecycleStressTest {
		* might still be trying to access those deleted files.
		*/
		@Test
		public void removeRecentlyStartedUserStressTest() throws RemoteException, InterruptedException {
		public void removeRecentlyStartedUserStressTest() throws Exception {
		for (int i = 0; i < NUM_ITERATIONS; i++) {
		logIteration(i, "removeRecentlyStartedUserStressTest");

		Log.d(TAG, "Creating a new user");
		final UserInfo userInfo = mUserManager.createUser(TEST_USER_NAME,
		UserManager.USER_TYPE_FULL_SECONDARY, 0);
		assertWithMessage("Failed to create the user")
		int flags = 0;
		UserInfo userInfo = mUserManager.createUser(TEST_USER_NAME,
		UserManager.USER_TYPE_FULL_SECONDARY, flags);
		assertWithMessageAtIteration(i, "result of createUser(%s, %s, %s)",
		TEST_USER_NAME, UserManager.USER_TYPE_FULL_SECONDARY, flags)
		.that(userInfo)
		.isNotNull();
		try {
		Log.d(TAG, "Starting user " + userInfo.id);
		startUserInBackgroundAndWaitForUserStartedBroadcast(userInfo.id);
		startUserInBackgroundAndWaitForUserStartedBroadcast(i, userInfo.id);
		} finally {
		Log.d(TAG, "Removing user " + userInfo.id);
		assertWithMessage("Failed to remove the user " + userInfo.id)
		assertWithMessageAtIteration(i, "removeUser(%s)", userInfo.id)
		.that(removeUser(userInfo.id))
		.isTrue();
		}
		@@ -183,37 +194,36 @@ public class UserLifecycleStressTest {

		if (currentGuestId != USER_NULL) {
		Log.d(TAG, "Switching to the existing guest");
		switchUser(currentGuestId);
		switchUser(i, currentGuestId);

		Log.d(TAG, "Marking current guest for deletion");
		assertWithMessage("Couldn't mark guest for deletion")
		assertWithMessageAtIteration(i, "result of markGuestForDeletion(%s)",
		currentGuestId)
		.that(mUserManager.markGuestForDeletion(currentGuestId))
		.isTrue();
		}

		Log.d(TAG, "Creating a new guest");
		final UserInfo newGuest = mUserManager.createGuest(mContext);
		assertWithMessage("Couldn't create new guest")
		.that(newGuest)
		.isNotNull();
		assertWithMessageAtIteration(i, "result of createGuest()").that(newGuest).isNotNull();

		Log.d(TAG, "Switching to the new guest");
		switchUser(newGuest.id);
		switchUser(i, newGuest.id);

		if (currentGuestId != USER_NULL) {
		Log.d(TAG, "Removing the previous guest");
		assertWithMessage("Couldn't remove guest")
		assertWithMessageAtIteration(i, "result of removeGuest(%s)", currentGuestId)
		.that(mUserManager.removeUser(currentGuestId))
		.isTrue();
		}

		Log.d(TAG, "Switching back to the initial user");
		switchUser(mOriginalCurrentUserId);
		switchUser(i, mOriginalCurrentUserId);

		nextGuestId = newGuest.id;
		}
		if (nextGuestId != USER_NULL) {
		Log.d(TAG, "Removing the last created guest user");
		Log.d(TAG, "Removing the last created guest user (id=" + nextGuestId + ")");
		mUserManager.removeUser(nextGuestId);
		}
		Log.d(TAG, "testSwitchToExistingGuestAndStartOver - End");
		@@ -239,36 +249,51 @@ public class UserLifecycleStressTest {
		}

		/** Stops the given user and waits for the stop to finish. */
		private void stopUser(int userId) throws RemoteException, InterruptedException {
		private void stopUser(@UserIdInt int userId) throws RemoteException, InterruptedException {
		runWithLatch("stop user", countDownLatch -> {
		ActivityManager.getService()
		.stopUserWithCallback(userId, new IStopUserCallback.Stub() {
		@Override
		public void userStopped(int userId) {
		Log.d(TAG, "userStopped(" + userId + ")");
		countDownLatch.countDown();
		}

		@Override
		public void userStopAborted(int i) throws RemoteException {

		public void userStopAborted(int usserId) throws RemoteException {
		Log.d(TAG, "userStoppedAborted(" + userId + ")");
		}
		});
		});
		}

		/** Starts the given user in the foreground and waits for the switch to finish. */
		private void switchUser(int userId) {
		/**
		* Starts the given user in the foreground and waits for the switch to finish.
		*
		* @param when when this method was called (either a string describing it, or an int with
		* the 0-indexed iteration)
		*/
		private void switchUser(Object when, @UserIdInt int userId) {
		String on;
		if (when instanceof String) {
		on = " " + when;
		} else if (when instanceof Integer) {
		on = " on iteration #" + (((Integer) when) + 1);
		} else {
		throw new IllegalArgumentException("Invalid `where` class: " + when);
		}

		if (ActivityManager.getCurrentUser() == userId) {
		Log.d(TAG, "No need to switch, current user is already user " + userId);
		return;
		}
		Log.d(TAG, "Switching to user " + userId);
		Log.d(TAG, "Switching to user " + userId + on);

		mUserSwitchWaiter.runThenWaitUntilSwitchCompleted(userId, () -> {
		assertWithMessage("Could not start switching to user " + userId)
		assertWithMessage("result of switchUser(%s)%s", userId, on)
		.that(mActivityManager.switchUser(userId)).isTrue();
		}, /* onFail= */ () -> {
		throw new AssertionError("Could not complete switching to user " + userId);
		throw new AssertionError("Could not complete switching to user " + userId + on);
		});
		}

		@@ -277,8 +302,11 @@ public class UserLifecycleStressTest {
		* <p> To start in foreground instead, see {@link #switchUser(int)}.
		* <p> This should always be used for profiles since profiles cannot be started in foreground.
		*/
		private void startUserInBackgroundAndWaitForUserStartedBroadcast(int userId) {
		runWithBlockingBroadcastReceiver("start user and wait for ACTION_USER_STARTED broadcast",
		private void startUserInBackgroundAndWaitForUserStartedBroadcast(int iteration,
		@UserIdInt int userId) {
		runWithBlockingBroadcastReceiver(
		"start user and wait for ACTION_USER_STARTED broadcast on iteration #"
		+ (iteration + 1),
		userId, Intent.ACTION_USER_STARTED,
		() -> ActivityManager.getService().startUserInBackground(userId));
		}
		@@ -286,23 +314,23 @@ public class UserLifecycleStressTest {
		/**
		* Calls the given runnable and expects the given broadcast to be received before timeout,
		* or fails the test otherwise.
		* @param tag tag for logging
		* @param message message to shown in case of failure
		* @param userId id of the user to register the broadcast receiver with
		* see {@link Context#registerReceiverAsUser}
		* @param action action of the broadcast intent filter i.e. {@link Intent#ACTION_USER_STARTED}
		* @param runnable this will be called after registering the broadcast receiver
		*/
		private void runWithBlockingBroadcastReceiver(String tag, int userId, String action,
		FunctionalUtils.ThrowingRunnable runnable) {
		private void runWithBlockingBroadcastReceiver(String message, @UserIdInt int userId,
		String action, FunctionalUtils.ThrowingRunnable runnable) {
		try (BlockingBroadcastReceiver blockingBroadcastReceiver = new BlockingBroadcastReceiver(
		mContext, action,
		intent -> intent.getIntExtra(Intent.EXTRA_USER_HANDLE, USER_NULL) == userId)) {
		blockingBroadcastReceiver.setTimeout(TIMEOUT_IN_SECOND);
		blockingBroadcastReceiver.registerForAllUsers();
		runnable.run();
		assertWithMessage("Took more than " + TIMEOUT_IN_SECOND + "s to " + tag)
		.that(blockingBroadcastReceiver.awaitForBroadcast())
		.isNotNull();
		if (blockingBroadcastReceiver.awaitForBroadcast() == null) {
		assertWithMessage("Took more than %ss to %s", TIMEOUT_IN_SECOND, message).fail();
		}
		}
		}

		@@ -310,26 +338,31 @@ public class UserLifecycleStressTest {
		* Calls the given consumer with a CountDownLatch parameter, and expects it's countDown() method
		* to be called before timeout, or fails the test otherwise.
		*/
		private void runWithLatch(String tag,
		private void runWithLatch(String action,
		FunctionalUtils.RemoteExceptionIgnoringConsumer<CountDownLatch> consumer)
		throws RemoteException, InterruptedException {
		final CountDownLatch countDownLatch = new CountDownLatch(1);
		final long startTime = System.currentTimeMillis();

		consumer.acceptOrThrow(countDownLatch);
		final boolean doneBeforeTimeout = countDownLatch.await(TIMEOUT_IN_SECOND, TimeUnit.SECONDS);
		assertWithMessage("Took more than " + TIMEOUT_IN_SECOND + "s to " + tag)
		.that(doneBeforeTimeout)
		.isTrue();
		if (!countDownLatch.await(TIMEOUT_IN_SECOND, TimeUnit.SECONDS)) {
		assertWithMessage("Took more than %s to %s", TIMEOUT_IN_SECOND, action).fail();
		}

		final long elapsedTime = System.currentTimeMillis() - startTime;
		Log.d(TAG, tag + " takes " + elapsedTime + " ms");
		Log.d(TAG, action + " takes " + elapsedTime + " ms");
		}

		private void logIteration(int iteration, String testMethodName) {
		Log.d(TAG, testMethodName + " - Iteration " + (iteration + 1) + " / " + NUM_ITERATIONS);
		}

		@FormatMethod
		private static StandardSubjectBuilder assertWithMessageAtIteration(int iteration,
		@FormatString String msgFormat, Object... msgArgs) {
		return assertWithMessage(msgFormat + " (at iteration #" + (iteration + 1) + ")", msgArgs);
		}

		private static void waitForBroadcastBarrier() {
		try {
		Log.d(TAG, "Starting to waitForBroadcastBarrier");