Merge "Add support for starting external Sessions" am: 4ce60695f9 am: 9bec1a5095 (74cd51fe) · Commits · e / os / android_frameworks_base

telecomm/java/android/telecom/Log.java

+9 −0

Original line number	Diff line number	Diff line
		@@ -188,6 +188,15 @@ public class Log {
		getSessionManager().startSession(shortMethodName, callerIdentification);
		}

		public static void startSession(Session.Info info, String shortMethodName,
		String callerIdentification) {
		getSessionManager().startSession(info, shortMethodName, callerIdentification);
		}

		public static void startExternalSession(Session.Info sessionInfo, String shortMethodName) {
		getSessionManager().startExternalSession(sessionInfo, shortMethodName);
		}

		public static Session createSubsession() {
		return getSessionManager().createSubsession();
		}

telecomm/java/android/telecom/Logging/Session.java

+106 −2

Original line number	Diff line number	Diff line
		@@ -17,6 +17,11 @@
		package android.telecom.Logging;

		import android.annotation.NonNull;
		import android.os.Parcel;
		import android.os.Parcelable;
		import android.text.TextUtils;

		import com.android.internal.annotations.VisibleForTesting;

		import java.util.ArrayList;

		@@ -33,12 +38,58 @@ public class Session {
		public static final String END_SUBSESSION = "END_SUBSESSION";
		public static final String END_SESSION = "END_SESSION";

		public static final String SUBSESSION_SEPARATION_CHAR = "->";
		public static final String EXTERNAL_INDICATOR = "E-";

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

		public static class Info implements Parcelable {
		public final String sessionId;
		public final String shortMethodName;

		private Info(String id, String methodName) {
		sessionId = id;
		shortMethodName = methodName;
		}

		public static Info getInfo (Session s) {
		return new Info(s.getFullSessionId(), s.getShortMethodName());
		}

		/** Responsible for creating Info objects for deserialized Parcels. */
		public static final Parcelable.Creator<Info> CREATOR =
		new Parcelable.Creator<Info> () {
		@Override
		public Info createFromParcel(Parcel source) {
		String id = source.readString();
		String methodName = source.readString();
		return new Info(id, methodName);
		}

		@Override
		public Info[] newArray(int size) {
		return new Info[size];
		}
		};

		/** {@inheritDoc} */
		@Override
		public int describeContents() {
		return 0;
		}

		/** Writes Info object into a Parcel. */
		@Override
		public void writeToParcel(Parcel destination, int flags) {
		destination.writeString(sessionId);
		destination.writeString(shortMethodName);
		}
		}

		private String mSessionId;
		private String mShortMethodName;
		private long mExecutionStartTimeMs;
		@@ -46,6 +97,7 @@ public class Session {
		private Session mParentSession;
		private ArrayList<Session> mChildSessions;
		private boolean mIsCompleted = false;
		private boolean mIsExternal = false;
		private int mChildCounter = 0;
		// True if this is a subsession that has been started from the same thread as the parent
		// session. This can happen if Log.startSession(...) is called multiple times on the same
		@@ -56,8 +108,11 @@ public class Session {
		// Optionally provided info about the method/class/component that started the session in order
		// to make Logging easier. This info will be provided in parentheses along with the session.
		private String mOwnerInfo;
		// Cache Full Method path so that recursive population of the full method path only needs to
		// be calculated once.
		private String mFullMethodPathCache;

		public Session(String sessionId, String shortMethodName, long startTimeMs, long threadID,
		public Session(String sessionId, String shortMethodName, long startTimeMs,
		boolean isStartedFromActiveSession, String ownerInfo) {
		setSessionId(sessionId);
		setShortMethodName(shortMethodName);
		@@ -86,6 +141,14 @@ public class Session {
		mShortMethodName = shortMethodName;
		}

		public void setIsExternal(boolean isExternal) {
		mIsExternal = isExternal;
		}

		public boolean isExternal() {
		return mIsExternal;
		}

		public void setParentSession(Session parentSession) {
		mParentSession = parentSession;
		}
		@@ -126,6 +189,15 @@ public class Session {
		return mIsStartedFromActiveSession;
		}

		public Info getInfo() {
		return Info.getInfo(this);
		}

		@VisibleForTesting
		public String getSessionId() {
		return mSessionId;
		}

		// Mark this session complete. This will be deleted by Log when all subsessions are complete
		// as well.
		public void markSessionCompleted(long executionEndTimeMs) {
		@@ -186,6 +258,38 @@ public class Session {
		}
		}

		// Recursively concatenate mShortMethodName with the parent Sessions to create full method
		// path. Caches this string so that multiple calls for the path will be quick.
		public String getFullMethodPath() {
		StringBuilder sb = new StringBuilder();
		getFullMethodPath(sb);
		return sb.toString();
		}

		private synchronized void getFullMethodPath(StringBuilder sb) {
		// Don't calculate if we have already figured it out!
		if (!TextUtils.isEmpty(mFullMethodPathCache)) {
		sb.append(mFullMethodPathCache);
		return;
		}
		Session parentSession = getParentSession();
		boolean isSessionStarted = false;
		if (parentSession != null) {
		// Check to see if the session has been renamed yet. If it has not, then the session
		// has not been continued.
		isSessionStarted = !mShortMethodName.equals(parentSession.mShortMethodName);
		parentSession.getFullMethodPath(sb);
		sb.append(SUBSESSION_SEPARATION_CHAR);
		}
		sb.append(mShortMethodName);

		if(isSessionStarted) {
		// Cache this value so that we do not have to do this work next time!
		// We do not cache the value if the session being evaluated hasn't been continued yet.
		mFullMethodPathCache = sb.toString();
		}
		}

		@Override
		public int hashCode() {
		int result = mSessionId != null ? mSessionId.hashCode() : 0;
		@@ -238,7 +342,7 @@ public class Session {
		return mParentSession.toString();
		} else {
		StringBuilder methodName = new StringBuilder();
		methodName.append(mShortMethodName);
		methodName.append(getFullMethodPath());
		if (mOwnerInfo != null && !mOwnerInfo.isEmpty()) {
		methodName.append("(InCall package: ");
		methodName.append(mOwnerInfo);

telecomm/java/android/telecom/Logging/SessionManager.java

+96 −36

Original line number	Diff line number	Diff line
		@@ -21,6 +21,7 @@ import android.os.Handler;
		import android.os.Looper;
		import android.os.Process;
		import android.provider.Settings;
		import android.telecom.Log;
		import android.util.Base64;

		import com.android.internal.annotations.VisibleForTesting;
		@@ -41,12 +42,9 @@ public class SessionManager {

		// Currently using 3 letters, So don't exceed 64^3
		private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144;

		// This parameter can be overridden in Telecom's Timeouts class.
		public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds

		private static String LOGGING_TAG = "Logging";

		private static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds
		private static final String LOGGING_TAG = "Logging";
		private static final String TIMEOUTS_PREFIX = "telecom.";

		// Synchronized in all method calls
		@@ -56,10 +54,9 @@ public class SessionManager {
		@VisibleForTesting
		public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
		@VisibleForTesting
		public Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
		@VisibleForTesting
		public java.lang.Runnable mCleanStaleSessions = () ->
		cleanupStaleSessions(getSessionCleanupTimeoutMs());
		private Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());

		// Overridden in LogTest to skip query to ContentProvider
		private interface ISessionCleanupTimeoutMs {
		@@ -74,8 +71,7 @@ public class SessionManager {
		@VisibleForTesting
		public ICurrentThreadId mCurrentThreadId = Process::myTid;

		@VisibleForTesting
		public ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
		private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
		// mContext may be null in some cases, such as testing. For these cases, use the
		// default value.
		if (mContext == null) {
		@@ -119,6 +115,21 @@ public class SessionManager {
		}
		}

		/**
		* Determines whether or not to start a new session or continue an existing session based on
		* the {@link Session.Info} info passed into startSession. If info is null, a new Session is
		* created. This code must be accompanied by endSession() at the end of the Session.
		*/
		public synchronized void startSession(Session.Info info, String shortMethodName,
		String callerIdentification) {
		// Start a new session normally if the
		if(info == null) {
		startSession(shortMethodName, callerIdentification);
		} else {
		startExternalSession(info, shortMethodName);
		}
		}

		/**
		* Call at an entry point to the Telecom code to track the session. This code must be
		* accompanied by a Log.endSession().
		@@ -134,14 +145,54 @@ public class SessionManager {
		Session childSession = createSubsession(true);
		continueSession(childSession, shortMethodName);
		return;
		} else {
		// Only Log that we are starting the parent session.
		Log.d(LOGGING_TAG, Session.START_SESSION);
		}
		Session newSession = new Session(getNextSessionID(), shortMethodName,
		System.currentTimeMillis(), threadId, false, callerIdentification);
		System.currentTimeMillis(), false, callerIdentification);
		mSessionMapper.put(threadId, newSession);
		}

		/**
		* Registers an external Session with the Manager using that external Session's sessionInfo.
		* Log.endSession will still need to be called at the end of the session.
		* @param sessionInfo Describes the external Session's information.
		* @param shortMethodName The method name of the new session that is being started.
		*/
		public synchronized void startExternalSession(Session.Info sessionInfo,
		String shortMethodName) {
		if(sessionInfo == null) {
		return;
		}

		android.util.Slog.v(LOGGING_TAG, Session.START_SESSION);
		int threadId = getCallingThreadId();
		Session threadSession = mSessionMapper.get(threadId);
		if (threadSession != null) {
		// We should never get into a situation where there is already an active session AND
		// an external session is added. We are just using that active session.
		Log.w(LOGGING_TAG, "trying to start an external session with a session " +
		"already active.");
		return;
		}

		// Create Session from Info and add to the sessionMapper under this ID.
		Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId,
		sessionInfo.shortMethodName, System.currentTimeMillis(),
		false /isStartedFromActiveSession/, null);
		externalSession.setIsExternal(true);
		// Mark the external session as already completed, since we have no way of knowing when
		// the external session actually has completed.
		externalSession.markSessionCompleted(Session.UNDEFINED);
		// Track the external session with the SessionMapper so that we can create and continue
		// an active subsession based on it.
		mSessionMapper.put(threadId, externalSession);
		// Create a subsession from this external Session parent node
		Session childSession = createSubsession();
		continueSession(childSession, shortMethodName);

		Log.d(LOGGING_TAG, Session.START_SESSION);
		}

		/**
		* Notifies the logging system that a subsession will be run at a later point and
		@@ -156,22 +207,22 @@ public class SessionManager {
		int threadId = getCallingThreadId();
		Session threadSession = mSessionMapper.get(threadId);
		if (threadSession == null) {
		android.util.Slog.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
		Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
		"active.");
		return null;
		}
		// Start execution time of the session will be overwritten in continueSession(...).
		Session newSubsession = new Session(threadSession.getNextChildId(),
		threadSession.getShortMethodName(), System.currentTimeMillis(), threadId,
		threadSession.getShortMethodName(), System.currentTimeMillis(),
		isStartedFromActiveSession, null);
		threadSession.addChild(newSubsession);
		newSubsession.setParentSession(threadSession);

		if (!isStartedFromActiveSession) {
		android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
		Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
		newSubsession.toString());
		} else {
		android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
		Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
		" (Invisible subsession)");
		}
		return newSubsession;
		@@ -201,21 +252,20 @@ public class SessionManager {
		return;
		}
		resetStaleSessionTimer();
		String callingMethodName = subsession.getShortMethodName();
		subsession.setShortMethodName(callingMethodName + "->" + shortMethodName);
		subsession.setShortMethodName(shortMethodName);
		subsession.setExecutionStartTimeMs(System.currentTimeMillis());
		Session parentSession = subsession.getParentSession();
		if (parentSession == null) {
		android.util.Slog.d(LOGGING_TAG, "Log.continueSession was called with no session " +
		Log.i(LOGGING_TAG, "Log.continueSession was called with no session " +
		"active for method " + shortMethodName);
		return;
		}

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

		completedSession.markSessionCompleted(System.currentTimeMillis());
		if (!completedSession.isStartedFromActiveSession()) {
		android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
		Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
		completedSession.getLocalExecutionTime() + " mS)");
		} else {
		android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION +
		Log.v(LOGGING_TAG, Session.END_SUBSESSION +
		" (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() +
		" ms)");
		}
		@@ -260,25 +310,37 @@ public class SessionManager {
		if (!subsession.isSessionCompleted() \|\| subsession.getChildSessions().size() != 0) {
		return;
		}

		Session parentSession = subsession.getParentSession();
		if (parentSession != null) {
		subsession.setParentSession(null);
		parentSession.removeChild(subsession);
		// Report the child session of the external session as being complete to the listeners,
		// not the external session itself.
		if (parentSession.isExternal()) {
		long fullSessionTimeMs =
		System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
		notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
		}
		endParentSessions(parentSession);
		} else {
		// All of the subsessions have been completed and it is time to report on the full
		// running time of the session.
		long fullSessionTimeMs =
		System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
		android.util.Slog.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
		Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
		+ " ms): " + subsession.toString());
		for (ISessionListener l : mSessionListeners) {
		l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs);
		if (!subsession.isExternal()) {
		notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
		}
		}
		}

		private void notifySessionCompleteListeners(String methodName, long sessionTimeMs) {
		for (ISessionListener l : mSessionListeners) {
		l.sessionComplete(methodName, sessionTimeMs);
		}
		}

		public String getSessionId() {
		Session currentSession = mSessionMapper.get(getCallingThreadId());
		return currentSession != null ? currentSession.toString() : "";
		@@ -299,24 +361,22 @@ public class SessionManager {
		return getBase64Encoding(nextId);
		}

		@VisibleForTesting
		public synchronized void restartSessionCounter() {
		private synchronized void restartSessionCounter() {
		sCodeEntryCounter = 0;
		}

		@VisibleForTesting
		public String getBase64Encoding(int number) {
		private String getBase64Encoding(int number) {
		byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array();
		idByteArray = Arrays.copyOfRange(idByteArray, 2, 4);
		return Base64.encodeToString(idByteArray, Base64.NO_WRAP \| Base64.NO_PADDING);
		}

		public int getCallingThreadId() {
		private int getCallingThreadId() {
		return mCurrentThreadId.get();
		}

		@VisibleForTesting
		private synchronized void cleanupStaleSessions(long timeoutMs) {
		public synchronized void cleanupStaleSessions(long timeoutMs) {
		String logMessage = "Stale Sessions Cleaned:\n";
		boolean isSessionsStale = false;
		long currentTimeMs = System.currentTimeMillis();
		@@ -335,9 +395,9 @@ public class SessionManager {
		}
		}
		if (isSessionsStale) {
		android.util.Slog.w(LOGGING_TAG, logMessage);
		Log.w(LOGGING_TAG, logMessage);
		} else {
		android.util.Slog.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
		Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
		}
		}