Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 096d2829 authored by Brad Ebinger's avatar Brad Ebinger
Browse files

Add support for new SessionManager and EventManager tests

Test: Ran new unit tests
Bug: 26571395
Change-Id: I6d14d7c05b8fdc8dc1319a81f0e41f7bcd989b85
parent cbb03d1a
Loading
Loading
Loading
Loading
+13 −1
Original line number Diff line number Diff line
@@ -20,6 +20,7 @@ import android.annotation.NonNull;
import android.telecom.Log;
import android.text.TextUtils;

import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.util.IndentingPrintWriter;

import java.text.DateFormat;
@@ -46,6 +47,7 @@ import java.util.concurrent.LinkedBlockingQueue;
public class EventManager {

    public static final String TAG = "Logging.Events";
    @VisibleForTesting
    public static final int DEFAULT_EVENTS_TO_CACHE = 10;  // Arbitrarily chosen.

    public interface Loggable {
@@ -79,7 +81,7 @@ public class EventManager {
     * Maps from request events to a list of possible response events. Used to track
     * end-to-end timing for critical user-facing operations in Telecom.
     */
    public final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>();
    private final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>();

    private static final Object mSync = new Object();

@@ -340,6 +342,16 @@ public class EventManager {
        }
    }

    @VisibleForTesting
    public LinkedBlockingQueue<EventRecord> getEventRecords() {
        return mEventRecords;
    }

    @VisibleForTesting
    public Map<Loggable, EventRecord> getCallEventRecordMap() {
        return mCallEventRecordMap;
    }

    private void addEventRecord(EventRecord newRecord) {
        Loggable recordEntry = newRecord.getRecordEntry();

+48 −21
Original line number Diff line number Diff line
@@ -33,6 +33,10 @@ public class Session {
    public static final String END_SUBSESSION = "END_SUBSESSION";
    public static final String END_SESSION = "END_SESSION";

    /**
     * Initial value of mExecutionEndTimeMs and the final value of {@link #getLocalExecutionTime()}
     * if the Session is canceled.
     */
    public static final int UNDEFINED = -1;

    private String mSessionId;
@@ -140,27 +144,6 @@ public class Session {
        return String.valueOf(mChildCounter++);
    }

    @Override
    public boolean equals(Object obj) {
        if (!(obj instanceof Session)) {
            return false;
        }
        if (obj == this) {
            return true;
        }
        Session otherSession = (Session) obj;
        return (mSessionId.equals(otherSession.mSessionId)) &&
                (mShortMethodName.equals(otherSession.mShortMethodName)) &&
                mExecutionStartTimeMs == otherSession.mExecutionStartTimeMs &&
                mParentSession == otherSession.mParentSession &&
                mChildSessions.equals(otherSession.mChildSessions) &&
                mIsCompleted == otherSession.mIsCompleted &&
                mExecutionEndTimeMs == otherSession.mExecutionEndTimeMs &&
                mChildCounter == otherSession.mChildCounter &&
                mIsStartedFromActiveSession == otherSession.mIsStartedFromActiveSession &&
                mOwnerInfo == otherSession.mOwnerInfo;
    }

    // Builds full session id recursively
    private String getFullSessionId() {
        // Cache mParentSession locally to prevent a concurrency problem where
@@ -203,6 +186,50 @@ public class Session {
        }
    }

    @Override
    public int hashCode() {
        int result = mSessionId != null ? mSessionId.hashCode() : 0;
        result = 31 * result + (mShortMethodName != null ? mShortMethodName.hashCode() : 0);
        result = 31 * result + (int) (mExecutionStartTimeMs ^ (mExecutionStartTimeMs >>> 32));
        result = 31 * result + (int) (mExecutionEndTimeMs ^ (mExecutionEndTimeMs >>> 32));
        result = 31 * result + (mParentSession != null ? mParentSession.hashCode() : 0);
        result = 31 * result + (mChildSessions != null ? mChildSessions.hashCode() : 0);
        result = 31 * result + (mIsCompleted ? 1 : 0);
        result = 31 * result + mChildCounter;
        result = 31 * result + (mIsStartedFromActiveSession ? 1 : 0);
        result = 31 * result + (mOwnerInfo != null ? mOwnerInfo.hashCode() : 0);
        return result;
    }

    @Override
    public boolean equals(Object o) {
        if (this == o) return true;
        if (o == null || getClass() != o.getClass()) return false;

        Session session = (Session) o;

        if (mExecutionStartTimeMs != session.mExecutionStartTimeMs) return false;
        if (mExecutionEndTimeMs != session.mExecutionEndTimeMs) return false;
        if (mIsCompleted != session.mIsCompleted) return false;
        if (mChildCounter != session.mChildCounter) return false;
        if (mIsStartedFromActiveSession != session.mIsStartedFromActiveSession) return false;
        if (mSessionId != null ?
                !mSessionId.equals(session.mSessionId) : session.mSessionId != null)
            return false;
        if (mShortMethodName != null ? !mShortMethodName.equals(session.mShortMethodName)
                : session.mShortMethodName != null)
            return false;
        if (mParentSession != null ? !mParentSession.equals(session.mParentSession)
                : session.mParentSession != null)
            return false;
        if (mChildSessions != null ? !mChildSessions.equals(session.mChildSessions)
                : session.mChildSessions != null)
            return false;
        return mOwnerInfo != null ? mOwnerInfo.equals(session.mOwnerInfo)
                : session.mOwnerInfo == null;

    }

    @Override
    public String toString() {
        if (mParentSession != null && mIsStartedFromActiveSession) {
+43 −34
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ package android.telecom.Logging;
import android.content.Context;
import android.os.Handler;
import android.os.Looper;
import android.os.Process;
import android.provider.Settings;
import android.util.Base64;

@@ -53,11 +54,11 @@ public class SessionManager {
    private Context mContext;

    @VisibleForTesting
    public ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100);
    public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
    @VisibleForTesting
    public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper());
    public Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
    @VisibleForTesting
    public java.lang.Runnable sCleanStaleSessions = () ->
    public java.lang.Runnable mCleanStaleSessions = () ->
            cleanupStaleSessions(getSessionCleanupTimeoutMs());

    // Overridden in LogTest to skip query to ContentProvider
@@ -65,8 +66,16 @@ public class SessionManager {
        long get();
    }

    // Overridden in tests to provide test Thread IDs
    public interface ICurrentThreadId {
        int get();
    }

    @VisibleForTesting
    public ICurrentThreadId mCurrentThreadId = Process::myTid;

    @VisibleForTesting
    public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> {
    public ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
        // mContext may be null in some cases, such as testing. For these cases, use the
        // default value.
        if (mContext == null) {
@@ -99,14 +108,14 @@ public class SessionManager {
    }

    private long getSessionCleanupTimeoutMs() {
        return sSessionCleanupTimeoutMs.get();
        return mSessionCleanupTimeoutMs.get();
    }

    private synchronized void resetStaleSessionTimer() {
        sSessionCleanupHandler.removeCallbacksAndMessages(null);
        mSessionCleanupHandler.removeCallbacksAndMessages(null);
        // Will be null in Log Testing
        if (sCleanStaleSessions != null) {
            sSessionCleanupHandler.postDelayed(sCleanStaleSessions, getSessionCleanupTimeoutMs());
        if (mCleanStaleSessions != null) {
            mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs());
        }
    }

@@ -118,7 +127,7 @@ public class SessionManager {
            String callerIdentification) {
        resetStaleSessionTimer();
        int threadId = getCallingThreadId();
        Session activeSession = sSessionMapper.get(threadId);
        Session activeSession = mSessionMapper.get(threadId);
        // We have called startSession within an active session that has not ended... Register this
        // session as a subsession.
        if (activeSession != null) {
@@ -128,9 +137,9 @@ public class SessionManager {
        }
        Session newSession = new Session(getNextSessionID(), shortMethodName,
                System.currentTimeMillis(), threadId, false, callerIdentification);
        sSessionMapper.put(threadId, newSession);
        mSessionMapper.put(threadId, newSession);

        android.telecom.Log.v(LOGGING_TAG, Session.START_SESSION);
        android.util.Slog.v(LOGGING_TAG, Session.START_SESSION);
    }


@@ -145,9 +154,9 @@ public class SessionManager {

    private synchronized Session createSubsession(boolean isStartedFromActiveSession) {
        int threadId = getCallingThreadId();
        Session threadSession = sSessionMapper.get(threadId);
        Session threadSession = mSessionMapper.get(threadId);
        if (threadSession == null) {
            android.telecom.Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
            android.util.Slog.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
                    "active.");
            return null;
        }
@@ -159,10 +168,10 @@ public class SessionManager {
        newSubsession.setParentSession(threadSession);

        if (!isStartedFromActiveSession) {
            android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
            android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
                    newSubsession.toString());
        } else {
            android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
            android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
                    " (Invisible subsession)");
        }
        return newSubsession;
@@ -171,14 +180,14 @@ public class SessionManager {
    /**
     * Cancels a subsession that had Log.createSubsession() called on it, but will never have
     * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned
     * gracefully instead of being removed by the sSessionCleanupHandler forcefully later.
     * gracefully instead of being removed by the mSessionCleanupHandler forcefully later.
     */
    public synchronized void cancelSubsession(Session subsession) {
        if (subsession == null) {
            return;
        }

        subsession.markSessionCompleted(0);
        subsession.markSessionCompleted(Session.UNDEFINED);
        endParentSessions(subsession);
    }

@@ -197,16 +206,16 @@ public class SessionManager {
        subsession.setExecutionStartTimeMs(System.currentTimeMillis());
        Session parentSession = subsession.getParentSession();
        if (parentSession == null) {
            android.telecom.Log.d(LOGGING_TAG, "Log.continueSession was called with no session " +
                    "active for method %s.", shortMethodName);
            android.util.Slog.d(LOGGING_TAG, "Log.continueSession was called with no session " +
                    "active for method " + shortMethodName);
            return;
        }

        sSessionMapper.put(getCallingThreadId(), subsession);
        mSessionMapper.put(getCallingThreadId(), subsession);
        if (!subsession.isStartedFromActiveSession()) {
            android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
            android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
        } else {
            android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
            android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
                    " (Invisible Subsession) with Method " + shortMethodName);
        }
    }
@@ -217,30 +226,30 @@ public class SessionManager {
     */
    public synchronized void endSession() {
        int threadId = getCallingThreadId();
        Session completedSession = sSessionMapper.get(threadId);
        Session completedSession = mSessionMapper.get(threadId);
        if (completedSession == null) {
            android.telecom.Log.w(LOGGING_TAG, "Log.endSession was called with no session active.");
            android.util.Slog.w(LOGGING_TAG, "Log.endSession was called with no session active.");
            return;
        }

        completedSession.markSessionCompleted(System.currentTimeMillis());
        if (!completedSession.isStartedFromActiveSession()) {
            android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
            android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
                    completedSession.getLocalExecutionTime() + " mS)");
        } else {
            android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION +
            android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION +
                    " (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() +
                    " ms)");
        }
        // Remove after completed so that reference still exists for logging the end events
        Session parentSession = completedSession.getParentSession();
        sSessionMapper.remove(threadId);
        mSessionMapper.remove(threadId);
        endParentSessions(completedSession);
        // If this subsession was started from a parent session using Log.startSession, return the
        // ThreadID back to the parent after completion.
        if (parentSession != null && !parentSession.isSessionCompleted() &&
                completedSession.isStartedFromActiveSession()) {
            sSessionMapper.put(threadId, parentSession);
            mSessionMapper.put(threadId, parentSession);
        }
    }

@@ -262,7 +271,7 @@ public class SessionManager {
            // running time of the session.
            long fullSessionTimeMs =
                    System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
            android.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
            android.util.Slog.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
                    + " ms): " + subsession.toString());
            // TODO: Add analytics hook
            for (ISessionListener l : mSessionListeners) {
@@ -272,7 +281,7 @@ public class SessionManager {
    }

    public String getSessionId() {
        Session currentSession = sSessionMapper.get(getCallingThreadId());
        Session currentSession = mSessionMapper.get(getCallingThreadId());
        return currentSession != null ? currentSession.toString() : "";
    }

@@ -304,7 +313,7 @@ public class SessionManager {
    }

    public int getCallingThreadId() {
        return android.os.Process.myTid();
        return mCurrentThreadId.get();
    }

    @VisibleForTesting
@@ -317,7 +326,7 @@ public class SessionManager {
        // If this occurs, then there is most likely a Session active that never had
        // Log.endSession called on it.
        for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it =
             sSessionMapper.entrySet().iterator(); it.hasNext(); ) {
             mSessionMapper.entrySet().iterator(); it.hasNext(); ) {
            ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
            Session session = entry.getValue();
            if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
@@ -327,9 +336,9 @@ public class SessionManager {
            }
        }
        if (isSessionsStale) {
            android.telecom.Log.w(LOGGING_TAG, logMessage);
            android.util.Slog.w(LOGGING_TAG, logMessage);
        } else {
            android.telecom.Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
            android.util.Slog.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
        }
    }