From 7e7cf134f0456d9578fe2faec26a084c8a62d759 Mon Sep 17 00:00:00 2001 From: Oli Lan Date: Mon, 7 Mar 2022 17:06:56 +0000 Subject: [PATCH] Add logging of user stop and user removal events. This adds logging for user stop and remove, similar to other user lifecycle events that are already logged, such as create and switch. Bug: 218688672 Test: make statsd_testdrive; statsd_testdrive Test: atest UserControllerTest Change-Id: I3e16370fe0f9a2d5bddb0cfcb71a1478c8ceaaec --- .../com/android/server/am/UserController.java | 35 +++++++++--- .../android/server/pm/UserManagerService.java | 57 ++++++++++++++++--- .../android/server/am/UserControllerTest.java | 2 + 3 files changed, 78 insertions(+), 16 deletions(-) diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java index b886196755ea0..c04377389e8ee 100644 --- a/services/core/java/com/android/server/am/UserController.java +++ b/services/core/java/com/android/server/am/UserController.java @@ -173,7 +173,7 @@ class UserController implements Handler.Callback { // Message constant to clear {@link UserJourneySession} from {@link mUserIdToUserJourneyMap} if // the user journey, defined in the UserLifecycleJourneyReported atom for statsd, is not // complete within {@link USER_JOURNEY_TIMEOUT}. - private static final int CLEAR_USER_JOURNEY_SESSION_MSG = 200; + static final int CLEAR_USER_JOURNEY_SESSION_MSG = 200; // Wait time for completing the user journey. If a user journey is not complete within this // time, the remaining lifecycle events for the journey would not be logged in statsd. // Timeout set for 90 seconds. @@ -209,12 +209,15 @@ class UserController implements Handler.Callback { FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_START; private static final int USER_JOURNEY_USER_CREATE = FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_CREATE; + private static final int USER_JOURNEY_USER_STOP = + FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_STOP; @IntDef(prefix = { "USER_JOURNEY" }, value = { USER_JOURNEY_UNKNOWN, USER_JOURNEY_USER_SWITCH_FG, USER_JOURNEY_USER_SWITCH_UI, USER_JOURNEY_USER_START, USER_JOURNEY_USER_CREATE, + USER_JOURNEY_USER_STOP }) @interface UserJourney {} @@ -233,6 +236,8 @@ class UserController implements Handler.Callback { FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__UNLOCKING_USER; private static final int USER_LIFECYCLE_EVENT_UNLOCKED_USER = FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__UNLOCKED_USER; + private static final int USER_LIFECYCLE_EVENT_STOP_USER = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__STOP_USER; @IntDef(prefix = { "USER_LIFECYCLE_EVENT" }, value = { USER_LIFECYCLE_EVENT_UNKNOWN, USER_LIFECYCLE_EVENT_SWITCH_USER, @@ -241,6 +246,7 @@ class UserController implements Handler.Callback { USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED, USER_LIFECYCLE_EVENT_UNLOCKING_USER, USER_LIFECYCLE_EVENT_UNLOCKED_USER, + USER_LIFECYCLE_EVENT_STOP_USER }) @interface UserLifecycleEvent {} @@ -1008,6 +1014,10 @@ class UserController implements Handler.Callback { return; } + logUserJourneyInfo(null, getUserInfo(userId), USER_JOURNEY_USER_STOP); + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_STOP_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); + if (stopUserCallback != null) { uss.mStopCallbacks.add(stopUserCallback); } @@ -1066,6 +1076,9 @@ class UserController implements Handler.Callback { synchronized (mLock) { if (uss.state != UserState.STATE_STOPPING) { // Whoops, we are being started back up. Abort, abort! + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_STOP_USER, + USER_LIFECYCLE_EVENT_STATE_NONE); + clearSessionId(userId); return; } uss.setState(UserState.STATE_SHUTDOWN); @@ -1165,10 +1178,18 @@ class UserController implements Handler.Callback { mInjector.getUserManager().removeUserEvenWhenDisallowed(userId); } + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_STOP_USER, + USER_LIFECYCLE_EVENT_STATE_FINISH); + clearSessionId(userId); + if (!lockUser) { return; } dispatchUserLocking(userIdToLock, keyEvictedCallbacks); + } else { + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_STOP_USER, + USER_LIFECYCLE_EVENT_STATE_NONE); + clearSessionId(userId); } } @@ -2962,13 +2983,13 @@ class UserController implements Handler.Callback { if (userJourneySession != null) { // TODO(b/157007231): Move this logic to a separate class/file. if ((userJourneySession.mJourney == USER_JOURNEY_USER_SWITCH_UI - && journey == USER_JOURNEY_USER_START) - || (userJourneySession.mJourney == USER_JOURNEY_USER_SWITCH_FG - && journey == USER_JOURNEY_USER_START)) { + || userJourneySession.mJourney == USER_JOURNEY_USER_SWITCH_FG) + && (journey == USER_JOURNEY_USER_START + || journey == USER_JOURNEY_USER_STOP)) { /* - * There is already a user switch journey, and a user start journey for the same - * target user received. User start journey is most likely a part of user switch - * journey so no need to create a new journey for user start. + * There is already a user switch journey, and a user start or stop journey for + * the same target user received. New journey is most likely a part of user + * switch journey so no need to create a new journey. */ if (DEBUG_MU) { Slogf.d(TAG, journey + " not logged as it is expected to be part of " diff --git a/services/core/java/com/android/server/pm/UserManagerService.java b/services/core/java/com/android/server/pm/UserManagerService.java index d340561c28628..98ed25b33e905 100644 --- a/services/core/java/com/android/server/pm/UserManagerService.java +++ b/services/core/java/com/android/server/pm/UserManagerService.java @@ -4317,16 +4317,9 @@ public class UserManagerService extends IUserManager.Stub { private long logUserCreateJourneyBegin(@UserIdInt int userId, String userType, @UserInfoFlag int flags) { - final long sessionId = ThreadLocalRandom.current().nextLong(1, Long.MAX_VALUE); - // log the journey atom with the user metadata - FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED, sessionId, + return logUserJourneyBegin( FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_CREATE, - /* origin_user= */ -1, userId, UserManager.getUserTypeForStatsd(userType), flags); - // log the event atom to indicate the event start - FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, sessionId, userId, - FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__CREATE_USER, - FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN); - return sessionId; + userId, userType, flags); } private void logUserCreateJourneyFinish(long sessionId, @UserIdInt int userId, boolean finish) { @@ -4336,6 +4329,46 @@ public class UserManagerService extends IUserManager.Stub { : FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE); } + private long logUserRemoveJourneyBegin(@UserIdInt int userId, String userType, + @UserInfoFlag int flags) { + return logUserJourneyBegin( + FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_REMOVE, + userId, userType, flags); + } + + private void logUserRemoveJourneyFinish(long sessionId, @UserIdInt int userId, boolean finish) { + FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, sessionId, userId, + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__REMOVE_USER, + finish ? FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__FINISH + : FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE); + } + + private long logUserJourneyBegin(int journey, @UserIdInt int userId, String userType, + @UserInfoFlag int flags) { + final long sessionId = ThreadLocalRandom.current().nextLong(1, Long.MAX_VALUE); + // log the journey atom with the user metadata + FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED, sessionId, + journey, /* origin_user= */ -1, userId, + UserManager.getUserTypeForStatsd(userType), flags); + + // log the event atom to indicate the event start + int event; + switch (journey) { + case FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_CREATE: + event = FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__CREATE_USER; + break; + case FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__JOURNEY__USER_REMOVE: + event = FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__REMOVE_USER; + break; + default: + throw new IllegalArgumentException("Journey " + journey + " not expected."); + } + + FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, sessionId, userId, + event, FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN); + return sessionId; + } + /** Register callbacks for statsd pulled atoms. */ private void registerStatsCallbacks() { final StatsManager statsManager = mContext.getSystemService(StatsManager.class); @@ -4578,6 +4611,10 @@ public class UserManagerService extends IUserManager.Stub { userData.info.flags |= UserInfo.FLAG_DISABLED; writeUserLP(userData); } + + final long sessionId = logUserRemoveJourneyBegin( + userId, userData.info.userType, userData.info.flags); + try { mAppOpsService.removeUser(userId); } catch (RemoteException e) { @@ -4600,9 +4637,11 @@ public class UserManagerService extends IUserManager.Stub { @Override public void userStopped(int userIdParam) { finishRemoveUser(userIdParam); + logUserRemoveJourneyFinish(sessionId, userIdParam, true); } @Override public void userStopAborted(int userIdParam) { + logUserRemoveJourneyFinish(sessionId, userIdParam, false); } }); } catch (RemoteException e) { diff --git a/services/tests/servicestests/src/com/android/server/am/UserControllerTest.java b/services/tests/servicestests/src/com/android/server/am/UserControllerTest.java index e4f1a9645e5c6..db1209224bd5f 100644 --- a/services/tests/servicestests/src/com/android/server/am/UserControllerTest.java +++ b/services/tests/servicestests/src/com/android/server/am/UserControllerTest.java @@ -28,6 +28,7 @@ import static android.testing.DexmakerShareClassLoaderRule.runWithDexmakerShareC import static androidx.test.platform.app.InstrumentationRegistry.getInstrumentation; +import static com.android.server.am.UserController.CLEAR_USER_JOURNEY_SESSION_MSG; import static com.android.server.am.UserController.COMPLETE_USER_SWITCH_MSG; import static com.android.server.am.UserController.CONTINUE_USER_SWITCH_MSG; import static com.android.server.am.UserController.REPORT_LOCKED_BOOT_COMPLETE_MSG; @@ -410,6 +411,7 @@ public class UserControllerTest { expectedCodes.add(COMPLETE_USER_SWITCH_MSG); expectedCodes.add(REPORT_USER_SWITCH_COMPLETE_MSG); if (backgroundUserStopping) { + expectedCodes.add(CLEAR_USER_JOURNEY_SESSION_MSG); expectedCodes.add(0); // this is for directly posting in stopping. } Set actualCodes = mInjector.mHandler.getMessageCodes();