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 <atom #>
Test: atest UserControllerTest
Change-Id: I3e16370fe0f9a2d5bddb0cfcb71a1478c8ceaaec
This commit is contained in:
Oli Lan
2022-03-07 17:06:56 +00:00
parent e1dbfe84d4
commit 7e7cf134f0
3 changed files with 78 additions and 16 deletions

View File

@@ -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 "

View File

@@ -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) {

View File

@@ -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<Integer> actualCodes = mInjector.mHandler.getMessageCodes();