diff --git a/telecomm/java/android/telecom/Log.java b/telecomm/java/android/telecom/Log.java index 249d32b385a74..1e5769fad1df2 100644 --- a/telecomm/java/android/telecom/Log.java +++ b/telecomm/java/android/telecom/Log.java @@ -188,6 +188,15 @@ public static void startSession(String shortMethodName, String callerIdentificat 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(); } diff --git a/telecomm/java/android/telecom/Logging/Session.java b/telecomm/java/android/telecom/Logging/Session.java index 510abddb4f932..093c0f921c06e 100644 --- a/telecomm/java/android/telecom/Logging/Session.java +++ b/telecomm/java/android/telecom/Logging/Session.java @@ -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 CREATOR = + new Parcelable.Creator () { + @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 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 void setShortMethodName(String shortMethodName) { 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 boolean isStartedFromActiveSession() { 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 @@ private void printSessionTree(int tabI, StringBuilder sb) { } } + // 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 String toString() { 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); diff --git a/telecomm/java/android/telecom/Logging/SessionManager.java b/telecomm/java/android/telecom/Logging/SessionManager.java index add12374136a2..173e7ee553878 100644 --- a/telecomm/java/android/telecom/Logging/SessionManager.java +++ b/telecomm/java/android/telecom/Logging/SessionManager.java @@ -21,6 +21,7 @@ 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 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 interface ICurrentThreadId { @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 @@ private synchronized void resetStaleSessionTimer() { } } + /** + * 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 synchronized void startSession(String shortMethodName, 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); - - android.util.Slog.v(LOGGING_TAG, Session.START_SESSION); } + /** + * 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; + } + + 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 @@ private synchronized Session createSubsession(boolean isStartedFromActiveSession 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 synchronized void continueSession(Session subsession, String shortMethodN 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 synchronized void endSession() { 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 @@ private void endParentSessions(Session subsession) { 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 @@ private synchronized String getNextSessionID() { 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 @@ private synchronized void cleanupStaleSessions(long timeoutMs) { } } 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..."); } }