src.android.telecom.Logging.SessionManager Maven / Gradle / Ivy
/*
* 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);
}
private 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();
}
@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);
}
}
© 2015 - 2025 Weber Informatics LLC | Privacy Policy