/* * Copyright (C) 2016 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License */ 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.telecom.Log; import android.util.Base64; import com.android.internal.annotations.VisibleForTesting; import java.nio.ByteBuffer; import java.util.ArrayList; import java.util.Arrays; import java.util.Iterator; import java.util.List; import java.util.concurrent.ConcurrentHashMap; /** * TODO: Create better Sessions Documentation * @hide */ 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. 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 private int sCodeEntryCounter = 0; private Context mContext; @VisibleForTesting public ConcurrentHashMap mSessionMapper = new ConcurrentHashMap<>(100); @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 { long get(); } // Overridden in tests to provide test Thread IDs public interface ICurrentThreadId { int get(); } @VisibleForTesting public ICurrentThreadId mCurrentThreadId = Process::myTid; private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> { // mContext may be null in some cases, such as testing. For these cases, use the // default value. if (mContext == null) { return DEFAULT_SESSION_TIMEOUT_MS; } return getCleanupTimeout(mContext); }; // Usage is synchronized on this class. private List mSessionListeners = new ArrayList<>(); public interface ISessionListener { /** * This method is run when a full Session has completed. * @param sessionName The name of the Session that has completed. * @param timeMs The time it took to complete in ms. */ void sessionComplete(String sessionName, long timeMs); } public interface ISessionIdQueryHandler { String getSessionId(); } public void setContext(Context context) { mContext = context; } public SessionManager() { } private long getSessionCleanupTimeoutMs() { return mSessionCleanupTimeoutMs.get(); } private synchronized void resetStaleSessionTimer() { mSessionCleanupHandler.removeCallbacksAndMessages(null); // Will be null in Log Testing if (mCleanStaleSessions != null) { mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs()); } } /** * 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(). */ public synchronized void startSession(String shortMethodName, String callerIdentification) { resetStaleSessionTimer(); int threadId = getCallingThreadId(); 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) { 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(), 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; } 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. Log.d(LOGGING_TAG, Session.START_EXTERNAL_SESSION); Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId, sessionInfo.methodPath, 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); } /** * Notifies the logging system that a subsession will be run at a later point and * allocates the resources. Returns a session object that must be used in * Log.continueSession(...) to start the subsession. */ public Session createSubsession() { return createSubsession(false); } /** * Creates a new subsession based on an existing session. Will not be started until * {@link #continueSession(Session, String)} or {@link #cancelSubsession(Session)} is called. *

* Only public for testing! * @param isStartedFromActiveSession true if this subsession is being created for a task on the * same thread, false if it is being created for a related task on another thread. * @return a new {@link Session}, call {@link #continueSession(Session, String)} to continue the * session and {@link #endSession()} when done with this subsession. */ @VisibleForTesting public synchronized Session createSubsession(boolean isStartedFromActiveSession) { int threadId = getCallingThreadId(); Session threadSession = mSessionMapper.get(threadId); if (threadSession == null) { 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(), isStartedFromActiveSession, null); threadSession.addChild(newSubsession); newSubsession.setParentSession(threadSession); if (!isStartedFromActiveSession) { Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " + newSubsession.toString()); } else { Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " (Invisible subsession)"); } return newSubsession; } /** * Retrieve the information of the currently active Session. This information is parcelable and * is used to create an external Session ({@link #startExternalSession(Session.Info, String)}). * If there is no Session active, this method will return null. */ public synchronized Session.Info getExternalSession() { int threadId = getCallingThreadId(); Session threadSession = mSessionMapper.get(threadId); if (threadSession == null) { Log.d(LOGGING_TAG, "Log.getExternalSession was called with no session " + "active."); return null; } return threadSession.getInfo(); } /** * 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 mSessionCleanupHandler forcefully later. */ public synchronized void cancelSubsession(Session subsession) { if (subsession == null) { return; } subsession.markSessionCompleted(Session.UNDEFINED); endParentSessions(subsession); } /** * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method * must be called at the end of this method. The full session will complete when all * subsessions are completed. */ public synchronized void continueSession(Session subsession, String shortMethodName) { if (subsession == null) { return; } resetStaleSessionTimer(); subsession.setShortMethodName(shortMethodName); subsession.setExecutionStartTimeMs(System.currentTimeMillis()); Session parentSession = subsession.getParentSession(); if (parentSession == null) { Log.i(LOGGING_TAG, "Log.continueSession was called with no session " + "active for method " + shortMethodName); return; } mSessionMapper.put(getCallingThreadId(), subsession); if (!subsession.isStartedFromActiveSession()) { Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION); } else { Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION + " (Invisible Subsession) with Method " + shortMethodName); } } /** * Ends the current session/subsession. Must be called after a Log.startSession(...) and * Log.continueSession(...) call. */ public synchronized void endSession() { int threadId = getCallingThreadId(); Session completedSession = mSessionMapper.get(threadId); if (completedSession == null) { Log.w(LOGGING_TAG, "Log.endSession was called with no session active."); return; } completedSession.markSessionCompleted(System.currentTimeMillis()); if (!completedSession.isStartedFromActiveSession()) { Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " + completedSession.getLocalExecutionTime() + " mS)"); } else { Log.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(); 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()) { mSessionMapper.put(threadId, parentSession); } } // Recursively deletes all complete parent sessions of the current subsession if it is a leaf. private void endParentSessions(Session subsession) { // Session is not completed or not currently a leaf, so we can not remove because a child is // still running 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(); Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs + " ms): " + subsession.toString()); 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() : ""; } public synchronized void registerSessionListener(ISessionListener l) { if (l != null) { mSessionListeners.add(l); } } private synchronized String getNextSessionID() { Integer nextId = sCodeEntryCounter++; if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) { restartSessionCounter(); nextId = sCodeEntryCounter++; } return getBase64Encoding(nextId); } private synchronized void restartSessionCounter() { sCodeEntryCounter = 0; } 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); } private int getCallingThreadId() { return mCurrentThreadId.get(); } /** * @return A String representation of the active sessions at the time that this method is * called. */ @VisibleForTesting public synchronized String printActiveSessions() { StringBuilder message = new StringBuilder(); for (ConcurrentHashMap.Entry entry : mSessionMapper.entrySet()) { message.append(entry.getValue().printFullSessionTree()); message.append("\n"); } return message.toString(); } @VisibleForTesting public synchronized void cleanupStaleSessions(long timeoutMs) { String logMessage = "Stale Sessions Cleaned:\n"; boolean isSessionsStale = false; long currentTimeMs = System.currentTimeMillis(); // Remove references that are in the Session Mapper (causing GC to occur) on // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS. // If this occurs, then there is most likely a Session active that never had // Log.endSession called on it. for (Iterator> it = mSessionMapper.entrySet().iterator(); it.hasNext(); ) { ConcurrentHashMap.Entry entry = it.next(); Session session = entry.getValue(); if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) { it.remove(); logMessage += session.printFullSessionTree() + "\n"; isSessionsStale = true; } } if (isSessionsStale) { Log.w(LOGGING_TAG, logMessage); } else { Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned..."); } } /** * Returns the amount of time after a Logging session has been started that Telecom is set to * perform a sweep to check and make sure that the session is still not incomplete (stale). */ private long getCleanupTimeout(Context context) { return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX + "stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS); } }