telecomm/java/android/telecom/Logging/SessionManager.java - platform/frameworks/base - Gitiles

 /*
  * 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.provider.Settings;
 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.
     public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds

     private static 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<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100);
     @VisibleForTesting
     public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper());
     @VisibleForTesting
     public java.lang.Runnable sCleanStaleSessions = () ->
             cleanupStaleSessions(getSessionCleanupTimeoutMs());

     // Overridden in LogTest to skip query to ContentProvider
     private interface ISessionCleanupTimeoutMs {
         long get();
     }

     @VisibleForTesting
     public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> {
         // 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<ISessionListener> 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 sSessionCleanupTimeoutMs.get();
     }

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

     /**
      * 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 = sSessionMapper.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;
         }
         Session newSession = new Session(getNextSessionID(), shortMethodName,
                 System.currentTimeMillis(), threadId, false, callerIdentification);
         sSessionMapper.put(threadId, newSession);

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


     /**
      * 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 = sSessionMapper.get(threadId);
         if (threadSession == null) {
             android.telecom.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,
                 isStartedFromActiveSession, null);
         threadSession.addChild(newSubsession);
         newSubsession.setParentSession(threadSession);

         if (!isStartedFromActiveSession) {
             android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
                     newSubsession.toString());
         } else {
             android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
                     " (Invisible subsession)");
         }
         return newSubsession;
     }

     /**
      * 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.
      */
     public synchronized void cancelSubsession(Session subsession) {
         if (subsession == null) {
             return;
         }

         subsession.markSessionCompleted(0);
         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();
         String callingMethodName = subsession.getShortMethodName();
         subsession.setShortMethodName(callingMethodName + "->" + shortMethodName);
         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);
             return;
         }

         sSessionMapper.put(getCallingThreadId(), subsession);
         if (!subsession.isStartedFromActiveSession()) {
             android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
         } else {
             android.telecom.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 = sSessionMapper.get(threadId);
         if (completedSession == null) {
             android.telecom.Log.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: " +
                     completedSession.getLocalExecutionTime() + " mS)");
         } else {
             android.telecom.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();
         sSessionMapper.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);
         }
     }

     // 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);
             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.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
                     + " ms): " + subsession.toString());
             // TODO: Add analytics hook
             for (ISessionListener l : mSessionListeners) {
                 l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs);
             }
         }
     }

     public String getSessionId() {
         Session currentSession = sSessionMapper.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);
     }

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

     @VisibleForTesting
     public 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() {
         return android.os.Process.myTid();
     }

     @VisibleForTesting
     private 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<ConcurrentHashMap.Entry<Integer, Session>> it =
              sSessionMapper.entrySet().iterator(); it.hasNext(); ) {
             ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
             Session session = entry.getValue();
             if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
                 it.remove();
                 logMessage += session.printFullSessionTree() + "\n";
                 isSessionsStale = true;
             }
         }
         if (isSessionsStale) {
             android.telecom.Log.w(LOGGING_TAG, logMessage);
         } else {
             android.telecom.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);
     }
 }
	/*
	* 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.provider.Settings;
	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.
	public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds

	private static 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<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100);
	@VisibleForTesting
	public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper());
	@VisibleForTesting
	public java.lang.Runnable sCleanStaleSessions = () ->
	cleanupStaleSessions(getSessionCleanupTimeoutMs());

	// Overridden in LogTest to skip query to ContentProvider
	private interface ISessionCleanupTimeoutMs {
	long get();
	}

	@VisibleForTesting
	public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> {
	// 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<ISessionListener> 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 sSessionCleanupTimeoutMs.get();
	}

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

	/**
	* 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 = sSessionMapper.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;
	}
	Session newSession = new Session(getNextSessionID(), shortMethodName,
	System.currentTimeMillis(), threadId, false, callerIdentification);
	sSessionMapper.put(threadId, newSession);

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


	/**
	* 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 = sSessionMapper.get(threadId);
	if (threadSession == null) {
	android.telecom.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,
	isStartedFromActiveSession, null);
	threadSession.addChild(newSubsession);
	newSubsession.setParentSession(threadSession);

	if (!isStartedFromActiveSession) {
	android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
	newSubsession.toString());
	} else {
	android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
	" (Invisible subsession)");
	}
	return newSubsession;
	}

	/**
	* 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.
	*/
	public synchronized void cancelSubsession(Session subsession) {
	if (subsession == null) {
	return;
	}

	subsession.markSessionCompleted(0);
	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();
	String callingMethodName = subsession.getShortMethodName();
	subsession.setShortMethodName(callingMethodName + "->" + shortMethodName);
	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);
	return;
	}

	sSessionMapper.put(getCallingThreadId(), subsession);
	if (!subsession.isStartedFromActiveSession()) {
	android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
	} else {
	android.telecom.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 = sSessionMapper.get(threadId);
	if (completedSession == null) {
	android.telecom.Log.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: " +
	completedSession.getLocalExecutionTime() + " mS)");
	} else {
	android.telecom.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();
	sSessionMapper.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);
	}
	}

	// 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);
	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.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
	+ " ms): " + subsession.toString());
	// TODO: Add analytics hook
	for (ISessionListener l : mSessionListeners) {
	l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs);
	}
	}
	}

	public String getSessionId() {
	Session currentSession = sSessionMapper.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);
	}

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

	@VisibleForTesting
	public 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() {
	return android.os.Process.myTid();
	}

	@VisibleForTesting
	private 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<ConcurrentHashMap.Entry<Integer, Session>> it =
	sSessionMapper.entrySet().iterator(); it.hasNext(); ) {
	ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
	Session session = entry.getValue();
	if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
	it.remove();
	logMessage += session.printFullSessionTree() + "\n";
	isSessionsStale = true;
	}
	}
	if (isSessionsStale) {
	android.telecom.Log.w(LOGGING_TAG, logMessage);
	} else {
	android.telecom.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);
	}
	}