Merge "Added more events to user switch journey" into rvc-dev

2 files changed, 155 insertions, 52 deletions

diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto
index 573a84f2fe33..12158b318676 100644
--- a/cmds/statsd/src/atoms.proto
+++ b/cmds/statsd/src/atoms.proto
@@ -9673,6 +9673,9 @@ message UserLifecycleEventOccurred {
         SWITCH_USER = 1; // Indicates that this is a user switch event
         START_USER = 2; // Indicates that this is a user start event
         CREATE_USER = 3; // Indicates that this is a user create event
+        USER_RUNNING_LOCKED = 4; // Indicates that user is running in locked state
+        UNLOCKING_USER = 5; // Indicates that this is a user unlocking event
+        UNLOCKED_USER = 6; // Indicates that this is a user unlocked event
     }
     optional Event event = 3;
 
diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java
index fac4a1e95827..ea7059894f38 100644
--- a/services/core/java/com/android/server/am/UserController.java
+++ b/services/core/java/com/android/server/am/UserController.java
@@ -90,7 +90,6 @@ import android.util.Pair;
 import android.util.Slog;
 import android.util.SparseArray;
 import android.util.SparseIntArray;
-import android.util.SparseLongArray;
 import android.util.proto.ProtoOutputStream;
 
 import com.android.internal.R;
@@ -154,6 +153,15 @@ class UserController implements Handler.Callback {
     static final int REPORT_LOCKED_BOOT_COMPLETE_MSG = 110;
     static final int START_USER_SWITCH_FG_MSG = 120;
 
+    // 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;
+    // 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.
+    private static final int USER_JOURNEY_TIMEOUT_MS = 90_000;
+
     // UI thread message constants
     static final int START_USER_SWITCH_UI_MSG = 1000;
 
@@ -194,14 +202,37 @@ class UserController implements Handler.Callback {
             FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__START_USER;
     private static final int USER_LIFECYCLE_EVENT_CREATE_USER =
             FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__CREATE_USER;
+    private static final int USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED =
+            FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__USER_RUNNING_LOCKED;
+    private static final int USER_LIFECYCLE_EVENT_UNLOCKING_USER =
+            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;
     @IntDef(prefix = { "USER_LIFECYCLE_EVENT" }, value = {
             USER_LIFECYCLE_EVENT_UNKNOWN,
             USER_LIFECYCLE_EVENT_SWITCH_USER,
             USER_LIFECYCLE_EVENT_START_USER,
             USER_LIFECYCLE_EVENT_CREATE_USER,
+            USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED,
+            USER_LIFECYCLE_EVENT_UNLOCKING_USER,
+            USER_LIFECYCLE_EVENT_UNLOCKED_USER,
     })
     @interface UserLifecycleEvent {}
 
+    // User lifecyle event state, defined in the UserLifecycleEventOccurred atom for statsd
+    private static final int USER_LIFECYCLE_EVENT_STATE_BEGIN =
+            FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN;
+    private static final int USER_LIFECYCLE_EVENT_STATE_FINISH =
+            FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__FINISH;
+    private static final int USER_LIFECYCLE_EVENT_STATE_NONE =
+            FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE;
+    @IntDef(prefix = { "USER_LIFECYCLE_EVENT_STATE" }, value = {
+            USER_LIFECYCLE_EVENT_STATE_BEGIN,
+            USER_LIFECYCLE_EVENT_STATE_FINISH,
+            USER_LIFECYCLE_EVENT_STATE_NONE,
+    })
+    @interface UserLifecycleEventState {}
+
     /**
      * Maximum number of users we allow to be running at a time, including system user.
      *
@@ -311,11 +342,11 @@ class UserController implements Handler.Callback {
     private final ArrayList<Integer> mLastActiveUsers = new ArrayList<>();
 
     /**
-     * A per-user, journey to session id map, used for statsd logging for the
+     * {@link UserIdInt} to {@link UserJourneySession} mapping used for statsd logging for the
      * UserLifecycleJourneyReported and UserLifecycleEventOccurred atoms.
      */
-    @GuardedBy("mUserJourneyToSessionIdMap")
-    private final SparseArray<SparseLongArray> mUserJourneyToSessionIdMap = new SparseArray<>();
+    @GuardedBy("mUserIdToUserJourneyMap")
+    private final SparseArray<UserJourneySession> mUserIdToUserJourneyMap = new SparseArray<>();
 
     UserController(ActivityManagerService service) {
         this(new Injector(service));
@@ -447,6 +478,8 @@ class UserController implements Handler.Callback {
         // but we might immediately step into RUNNING below if the user
         // storage is already unlocked.
         if (uss.setState(STATE_BOOTING, STATE_RUNNING_LOCKED)) {
+            logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED,
+                    USER_LIFECYCLE_EVENT_STATE_NONE);
             mInjector.getUserManagerInternal().setUserState(userId, uss.state);
             // Do not report secondary users, runtime restarts or first boot/upgrade
             if (userId == UserHandle.USER_SYSTEM
@@ -503,6 +536,8 @@ class UserController implements Handler.Callback {
     private boolean finishUserUnlocking(final UserState uss) {
         final int userId = uss.mHandle.getIdentifier();
         EventLog.writeEvent(EventLogTags.UC_FINISH_USER_UNLOCKING, userId);
+        logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_UNLOCKING_USER,
+                USER_LIFECYCLE_EVENT_STATE_BEGIN);
         // Only keep marching forward if user is actually unlocked
         if (!StorageManager.isUserKeyUnlocked(userId)) return false;
         synchronized (mLock) {
@@ -2396,8 +2431,8 @@ class UserController implements Handler.Callback {
             case START_USER_SWITCH_FG_MSG:
                 logUserJourneyInfo(getUserInfo(getCurrentUserId()), getUserInfo(msg.arg1),
                         USER_JOURNEY_USER_SWITCH_FG);
-                logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_SWITCH_FG,
-                        USER_LIFECYCLE_EVENT_SWITCH_USER, true);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_SWITCH_USER,
+                        USER_LIFECYCLE_EVENT_STATE_BEGIN);
                 startUserInForeground(msg.arg1);
                 break;
             case REPORT_USER_SWITCH_MSG:
@@ -2420,14 +2455,14 @@ class UserController implements Handler.Callback {
                         BatteryStats.HistoryItem.EVENT_USER_RUNNING_START,
                         Integer.toString(msg.arg1), msg.arg1);
                 logUserJourneyInfo(null, getUserInfo(msg.arg1), USER_JOURNEY_USER_START);
-                logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_START,
-                        USER_LIFECYCLE_EVENT_START_USER, true);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_START_USER,
+                        USER_LIFECYCLE_EVENT_STATE_BEGIN);
 
                 mInjector.getSystemServiceManager().startUser(TimingsTraceAndSlog.newAsyncLog(),
                         msg.arg1);
 
-                logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_START,
-                        USER_LIFECYCLE_EVENT_START_USER, false);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_START_USER,
+                        USER_LIFECYCLE_EVENT_STATE_FINISH);
                 clearSessionId(msg.arg1, USER_JOURNEY_USER_START);
                 break;
             case USER_UNLOCK_MSG:
@@ -2437,10 +2472,17 @@ class UserController implements Handler.Callback {
                 FgThread.getHandler().post(() -> {
                     mInjector.loadUserRecents(userId);
                 });
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKING_USER,
+                        USER_LIFECYCLE_EVENT_STATE_FINISH);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKED_USER,
+                        USER_LIFECYCLE_EVENT_STATE_BEGIN);
                 finishUserUnlocked((UserState) msg.obj);
                 break;
             case USER_UNLOCKED_MSG:
                 mInjector.getSystemServiceManager().onUserUnlocked(msg.arg1);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKED_USER,
+                        USER_LIFECYCLE_EVENT_STATE_FINISH);
+                clearSessionId(msg.arg1);
                 break;
             case USER_CURRENT_MSG:
                 mInjector.batteryStatsServiceNoteEvent(
@@ -2458,11 +2500,8 @@ class UserController implements Handler.Callback {
             case REPORT_USER_SWITCH_COMPLETE_MSG:
                 dispatchUserSwitchComplete(msg.arg1);
 
-                final int currentJourney = mUserSwitchUiEnabled ? USER_JOURNEY_USER_SWITCH_UI
-                                                                : USER_JOURNEY_USER_SWITCH_FG;
-                logUserLifecycleEvent(msg.arg1, currentJourney,
-                        USER_LIFECYCLE_EVENT_SWITCH_USER, false);
-                clearSessionId(msg.arg1, currentJourney);
+                logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_SWITCH_USER,
+                        USER_LIFECYCLE_EVENT_STATE_FINISH);
                 break;
             case REPORT_LOCKED_BOOT_COMPLETE_MSG:
                 dispatchLockedBootComplete(msg.arg1);
@@ -2471,10 +2510,13 @@ class UserController implements Handler.Callback {
                 final Pair<UserInfo, UserInfo> fromToUserPair = (Pair<UserInfo, UserInfo>) msg.obj;
                 logUserJourneyInfo(fromToUserPair.first, fromToUserPair.second,
                         USER_JOURNEY_USER_SWITCH_UI);
-                logUserLifecycleEvent(fromToUserPair.second.id, USER_JOURNEY_USER_SWITCH_UI,
-                        USER_LIFECYCLE_EVENT_SWITCH_USER, true);
+                logUserLifecycleEvent(fromToUserPair.second.id, USER_LIFECYCLE_EVENT_SWITCH_USER,
+                        USER_LIFECYCLE_EVENT_STATE_BEGIN);
                 showUserSwitchDialog(fromToUserPair);
                 break;
+            case CLEAR_USER_JOURNEY_SESSION_MSG:
+                clearSessionId(msg.arg1);
+                break;
         }
         return false;
     }
@@ -2482,27 +2524,61 @@ class UserController implements Handler.Callback {
     /**
      * statsd helper method for logging the start of a user journey via a UserLifecycleEventOccurred
      * atom given the originating and targeting users for the journey.
-     *
-     * Note: these info atoms are currently logged more than once per journey since there is no
-     * state associated with the user's ongoing journey - this will be updated in a later CL.
      */
     private void logUserJourneyInfo(UserInfo origin, UserInfo target, @UserJourney int journey) {
         final long newSessionId = ThreadLocalRandom.current().nextLong(1, Long.MAX_VALUE);
-        synchronized (mUserJourneyToSessionIdMap) {
-            SparseLongArray userSessions = mUserJourneyToSessionIdMap.get(target.id);
-            if (userSessions == null) {
-                userSessions = new SparseLongArray();
-                mUserJourneyToSessionIdMap.put(target.id, userSessions);
-            }
-            final long oldSessionId = userSessions.get(journey);
-            if (oldSessionId != INVALID_SESSION_ID) {
-                // potentially an incomplete or timed-out session
+        synchronized (mUserIdToUserJourneyMap) {
+            UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(target.id);
+            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)) {
+                    /*
+                     * 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.
+                     */
+                    if (DEBUG_MU) {
+                        Slog.d(TAG, journey + " not logged as it is expected to be part of "
+                                + userJourneySession.mJourney);
+                    }
+                    return;
+                }
+                /*
+                 * Possible reasons for this condition to be true:
+                 * - A user switch journey is received while another user switch journey is in
+                 *   process for the same user.
+                 * - A user switch journey is received while user start journey is in process for
+                 *   the same user.
+                 * - A user start journey is received while another user start journey is in process
+                 *   for the same user.
+                 * In all cases potentially an incomplete, timed-out session or multiple
+                 * simultaneous requests. It is not possible to keep track of multiple sessions for
+                 * the same user, so previous session is abandoned.
+                 */
                 FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED,
-                        oldSessionId, target.id, USER_LIFECYCLE_EVENT_UNKNOWN,
-                        FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE);
+                        userJourneySession.mSessionId, target.id, USER_LIFECYCLE_EVENT_UNKNOWN,
+                        USER_LIFECYCLE_EVENT_STATE_NONE);
+            }
+
+            if (DEBUG_MU) {
+                Slog.d(TAG,
+                        "Starting a new journey: " + journey + " with session id: " + newSessionId);
             }
-            // update session id
-            userSessions.put(journey, newSessionId);
+
+            userJourneySession = new UserJourneySession(newSessionId, journey);
+            mUserIdToUserJourneyMap.put(target.id, userJourneySession);
+            /*
+             * User lifecyle journey would be complete when {@code #clearSessionId} is called after
+             * the last expected lifecycle event for the journey. It may be possible that the last
+             * event is not called, e.g., user not unlocked after user switching. In such cases user
+             * journey is cleared after {@link USER_JOURNEY_TIMEOUT}.
+             */
+            mHandler.removeMessages(CLEAR_USER_JOURNEY_SESSION_MSG);
+            mHandler.sendMessageDelayed(mHandler.obtainMessage(CLEAR_USER_JOURNEY_SESSION_MSG,
+                    target.id), USER_JOURNEY_TIMEOUT_MS);
         }
 
         FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED, newSessionId,
@@ -2511,41 +2587,65 @@ class UserController implements Handler.Callback {
     }
 
     /**
-     * statsd helper method for logging the begin or finish of the given event for the
-     * UserLifecycleEventOccurred statsd atom.
-     * Note: This does not clear the user's journey session id - if this event represents the end of
-     * a particular journey, call {@link #clearSessionId} to indicate that the session is over.
+     * statsd helper method for logging the given event for the UserLifecycleEventOccurred statsd
+     * atom.
      */
-    private void logUserLifecycleEvent(@UserIdInt int userId, @UserJourney int journey,
-            @UserLifecycleEvent int event, boolean begin) {
+    private void logUserLifecycleEvent(@UserIdInt int userId, @UserLifecycleEvent int event,
+            @UserLifecycleEventState int eventState) {
         final long sessionId;
-        synchronized (mUserJourneyToSessionIdMap) {
-            final SparseLongArray eventToSessionMap = mUserJourneyToSessionIdMap.get(userId);
-            if (eventToSessionMap == null || eventToSessionMap.size() == 0) {
-                return;
-            }
-            sessionId = eventToSessionMap.get(journey);
-            if (sessionId == INVALID_SESSION_ID) {
+        synchronized (mUserIdToUserJourneyMap) {
+            final UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(userId);
+            if (userJourneySession == null || userJourneySession.mSessionId == INVALID_SESSION_ID) {
+                Slog.w(TAG, "UserLifecycleEvent " + event
+                        + " received without an active userJourneySession.");
                 return;
             }
+            sessionId = userJourneySession.mSessionId;
         }
 
         FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, sessionId, userId,
-                event, begin ? FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN
-                             : FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__FINISH);
+                event, eventState);
     }
 
     /**
-     * Clears the user's session id associated with the given UserJourney (for statsd).
+     * Clears the {@link UserJourneySession} for a given {@link UserIdInt} and {@link UserJourney}.
      */
     private void clearSessionId(@UserIdInt int userId, @UserJourney int journey) {
-        synchronized (mUserJourneyToSessionIdMap) {
-            if (mUserJourneyToSessionIdMap.get(userId) != null) {
-                mUserJourneyToSessionIdMap.get(userId).delete(journey);
+        synchronized (mUserIdToUserJourneyMap) {
+            final UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(userId);
+            if (userJourneySession != null && userJourneySession.mJourney == journey) {
+                clearSessionId(userId);
             }
         }
     }
 
+    /**
+     * Clears the {@link UserJourneySession} for a given {@link UserIdInt}.
+     */
+    private void clearSessionId(@UserIdInt int userId) {
+        synchronized (mUserIdToUserJourneyMap) {
+            mHandler.removeMessages(CLEAR_USER_JOURNEY_SESSION_MSG);
+            mUserIdToUserJourneyMap.delete(userId);
+        }
+    }
+
+    /**
+     * Helper class to store user journey and session id.
+     *
+     * <p> User journey tracks a chain of user lifecycle events occurring during different user
+     * activities such as user start, user switch, and user creation.
+     */
+    // TODO(b/157007231): Move this class and user journey tracking logic to a separate file.
+    private static class UserJourneySession {
+        final long mSessionId;
+        @UserJourney final int mJourney;
+
+        UserJourneySession(long sessionId, @UserJourney int journey) {
+            mJourney = journey;
+            mSessionId = sessionId;
+        }
+    }
+
     private static class UserProgressListener extends IProgressListener.Stub {
         private volatile long mUnlockStarted;
         @Override