Introduces sessions into Telecom Logging
Sessions are introduced into the Telecom logging framework in order
to better trace code execution paths in the Telecom logs. Mostly,
this code keeps track of threads that are currently executing code in
Telecom and when a log or event is recorded, the unique session
information is appended to the log/event.
Change-Id: Ied3940fbb33e097636a99571e946dd40a154d64b
diff --git a/src/com/android/server/telecom/Log.java b/src/com/android/server/telecom/Log.java
index 69ad261..cdd49c3 100644
--- a/src/com/android/server/telecom/Log.java
+++ b/src/com/android/server/telecom/Log.java
@@ -20,14 +20,17 @@
import android.telecom.PhoneAccount;
import android.telephony.PhoneNumberUtils;
import android.text.TextUtils;
+import android.util.Base64;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.util.IndentingPrintWriter;
+import java.nio.ByteBuffer;
import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
+import java.util.Arrays;
import java.util.Date;
import java.util.HashMap;
import java.util.IllegalFormatException;
@@ -35,6 +38,7 @@
import java.util.List;
import java.util.Locale;
import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.LinkedBlockingQueue;
/**
@@ -201,6 +205,9 @@
public static final int MAX_CALLS_TO_CACHE_DEBUG = 20; // Arbitrarily chosen.
private static final long EXTENDED_LOGGING_DURATION_MILLIS = 60000 * 30; // 30 minutes
+ // Currently using 3 letters, So don't exceed 64^3
+ private static final long SESSION_ID_ROLLOVER_THRESHOLD = 1024;
+
// Generic tag for all In Call logging
@VisibleForTesting
public static String TAG = "Telecom";
@@ -217,6 +224,15 @@
private static LinkedBlockingQueue<CallEventRecord> mCallEventRecords =
new LinkedBlockingQueue<CallEventRecord>(MAX_CALLS_TO_CACHE);
+ // Synchronized in all method calls
+ private static int sCodeEntryCounter = 0;
+ @VisibleForTesting
+ public static ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100);
+
+ // Set the logging container to be the system's. This will only change when being mocked
+ // during testing.
+ private static SystemLoggingContainer systemLogger = new SystemLoggingContainer();
+
/**
* Tracks whether user-activated extended logging is enabled.
*/
@@ -267,6 +283,136 @@
TAG = tag;
}
+ @VisibleForTesting
+ public static void setLoggingContainer(SystemLoggingContainer logger) {
+ systemLogger = logger;
+ }
+
+ /**
+ * Call at an entry point to the Telecom code to track the session. This code must be
+ * accompanied by a Log.endSession().
+ */
+ public static void startSession(String shortMethodName) {
+ int threadId = getCallingThreadId();
+ Session newSession = new Session(getNextSessionID(), shortMethodName,
+ System.currentTimeMillis());
+ sSessionMapper.put(threadId, newSession);
+
+ Log.i(TAG, Session.START_SESSION + " " + newSession.toString());
+ }
+
+
+ /**
+ * 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 static synchronized Session createSubsession() {
+ int threadId = getCallingThreadId();
+ Session threadSession = sSessionMapper.get(threadId);
+ if (threadSession == null) {
+ Log.d(TAG, "Log.createSubsession was called with no session active.");
+ return null;
+ }
+ Session newSubsession = new Session(threadSession.getNextChildId(),
+ threadSession.getShortMethodName(), System.currentTimeMillis());
+ threadSession.addChild(newSubsession);
+ newSubsession.setParentSession(threadSession);
+
+ Log.i(TAG, Session.CREATE_SUBSESSION + " " + newSubsession.toString());
+ return newSubsession;
+ }
+
+ /**
+ * 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 static void continueSession(Session subsession, String shortMethodName){
+ if (subsession == null) {
+ return;
+ }
+ String callingMethodName = subsession.getShortMethodName();
+ subsession.setShortMethodName(shortMethodName);
+ Session threadSession = subsession.getParentSession();
+ if (threadSession == null) {
+ Log.d(TAG, "Log.continueSession was called with no session active for method %s.",
+ shortMethodName);
+ return;
+ }
+
+ sSessionMapper.put(getCallingThreadId(), subsession);
+ Log.i(TAG, Session.CONTINUE_SUBSESSION + " " + callingMethodName + "->" +
+ subsession.toString());
+ }
+
+
+ /**
+ * Ends the current session/subsession. Must be called after a Log.startSession(...) and
+ * Log.continueSession(...) call.
+ */
+ public static synchronized void endSession() {
+ Session completedSession = sSessionMapper.remove(getCallingThreadId());
+ if (completedSession == null) {
+ Log.d(TAG, "Log.endSession was called with no session active.");
+ return;
+ }
+
+ completedSession.markSessionCompleted(System.currentTimeMillis());
+ Log.i(TAG, Session.END_SUBSESSION + " " + completedSession.toString() +
+ " Local dur: " + completedSession.getLocalExecutionTime() + " mS");
+
+ endParentSessions(completedSession);
+ }
+
+ // Recursively deletes all complete parent sessions of the current subsession if it is a leaf.
+ private static 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();
+ Log.i(TAG, Session.END_SESSION + " " + subsession.toString() +
+ " Full dur: " + fullSessionTimeMs + " ms");
+ }
+ }
+
+ private synchronized static String getNextSessionID() {
+ Integer nextId = sCodeEntryCounter++;
+ if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) {
+ restartSessionCounter();
+ nextId = sCodeEntryCounter++;
+ }
+ return getBase64Encoding(nextId);
+ }
+
+ @VisibleForTesting
+ public synchronized static void restartSessionCounter() {
+ sCodeEntryCounter = 0;
+ }
+
+ @VisibleForTesting
+ public static 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 static int getCallingThreadId() {
+ return android.os.Process.myTid();
+ }
+
public static void event(Call call, String event) {
event(call, event, null);
}
@@ -325,93 +471,93 @@
public static void d(String prefix, String format, Object... args) {
if (mIsUserExtendedLoggingEnabled) {
maybeDisableLogging();
- android.util.Slog.i(TAG, buildMessage(prefix, format, args));
+ systemLogger.i(TAG, buildMessage(prefix, format, args));
} else if (DEBUG) {
- android.util.Slog.d(TAG, buildMessage(prefix, format, args));
+ systemLogger.d(TAG, buildMessage(prefix, format, args));
}
}
public static void d(Object objectPrefix, String format, Object... args) {
if (mIsUserExtendedLoggingEnabled) {
maybeDisableLogging();
- android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
} else if (DEBUG) {
- android.util.Slog.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
}
}
public static void i(String prefix, String format, Object... args) {
if (INFO) {
- android.util.Slog.i(TAG, buildMessage(prefix, format, args));
+ systemLogger.i(TAG, buildMessage(prefix, format, args));
}
}
public static void i(Object objectPrefix, String format, Object... args) {
if (INFO) {
- android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
}
}
public static void v(String prefix, String format, Object... args) {
if (mIsUserExtendedLoggingEnabled) {
maybeDisableLogging();
- android.util.Slog.i(TAG, buildMessage(prefix, format, args));
+ systemLogger.i(TAG, buildMessage(prefix, format, args));
} else if (VERBOSE) {
- android.util.Slog.v(TAG, buildMessage(prefix, format, args));
+ systemLogger.v(TAG, buildMessage(prefix, format, args));
}
}
public static void v(Object objectPrefix, String format, Object... args) {
if (mIsUserExtendedLoggingEnabled) {
maybeDisableLogging();
- android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
} else if (VERBOSE) {
- android.util.Slog.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
}
}
public static void w(String prefix, String format, Object... args) {
if (WARN) {
- android.util.Slog.w(TAG, buildMessage(prefix, format, args));
+ systemLogger.w(TAG, buildMessage(prefix, format, args));
}
}
public static void w(Object objectPrefix, String format, Object... args) {
if (WARN) {
- android.util.Slog.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
+ systemLogger.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
}
}
public static void e(String prefix, Throwable tr, String format, Object... args) {
if (ERROR) {
- android.util.Slog.e(TAG, buildMessage(prefix, format, args), tr);
+ systemLogger.e(TAG, buildMessage(prefix, format, args), tr);
}
}
public static void e(Object objectPrefix, Throwable tr, String format, Object... args) {
if (ERROR) {
- android.util.Slog.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args),
+ systemLogger.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args),
tr);
}
}
public static void wtf(String prefix, Throwable tr, String format, Object... args) {
- android.util.Slog.wtf(TAG, buildMessage(prefix, format, args), tr);
+ systemLogger.wtf(TAG, buildMessage(prefix, format, args), tr);
}
public static void wtf(Object objectPrefix, Throwable tr, String format, Object... args) {
- android.util.Slog.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args),
+ systemLogger.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args),
tr);
}
public static void wtf(String prefix, String format, Object... args) {
String msg = buildMessage(prefix, format, args);
- android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg));
+ systemLogger.wtf(TAG, msg, new IllegalStateException(msg));
}
public static void wtf(Object objectPrefix, String format, Object... args) {
String msg = buildMessage(getPrefixFromObject(objectPrefix), format, args);
- android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg));
+ systemLogger.wtf(TAG, msg, new IllegalStateException(msg));
}
public static String piiHandle(Object pii) {
@@ -502,6 +648,12 @@
}
private static String buildMessage(String prefix, String format, Object... args) {
+ // Incorporate thread ID and calling method into prefix
+ Session currentSession = sSessionMapper.get(getCallingThreadId());
+ if(currentSession != null) {
+ prefix = prefix + " " + currentSession.toString();
+ }
+
String msg;
try {
msg = (args == null || args.length == 0) ? format
diff --git a/src/com/android/server/telecom/Session.java b/src/com/android/server/telecom/Session.java
new file mode 100644
index 0000000..0c11ee5
--- /dev/null
+++ b/src/com/android/server/telecom/Session.java
@@ -0,0 +1,152 @@
+/*
+ * Copyright (C) 2015 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 com.android.server.telecom;
+
+import android.annotation.NonNull;
+
+import java.util.ArrayList;
+
+/**
+ * The session that stores information about a thread's point of entry into the Telecom code that
+ * persists until the thread exits Telecom.
+ */
+public class Session {
+
+ public static final String START_SESSION = "START_SESSION";
+ public static final String CREATE_SUBSESSION = "CREATE_SUBSESSION";
+ public static final String CONTINUE_SUBSESSION = "CONTINUE_SUBSESSION";
+ public static final String END_SUBSESSION = "END_SUBSESSION";
+ public static final String END_SESSION = "END_SESSION";
+
+ public static final int UNDEFINED = -1;
+
+ private String mSessionId;
+ private String mShortMethodName;
+ private long mExecutionStartTimeMs;
+ private long mExecutionEndTimeMs = UNDEFINED;
+ private Session mParentSession;
+ private ArrayList<Session> mChildSessions;
+ private boolean mIsCompleted = false;
+
+ public Session(String sessionId, String shortMethodName, long startTimeMs) {
+ setSessionId(sessionId);
+ setShortMethodName(shortMethodName);
+ mExecutionStartTimeMs = startTimeMs;
+ mParentSession = null;
+ mChildSessions = new ArrayList<>(5);
+ }
+
+ public void setSessionId(@NonNull String sessionId) {
+ if(sessionId == null) {
+ mSessionId = "?";
+ }
+ mSessionId = sessionId;
+ }
+
+ public String getShortMethodName() {
+ return mShortMethodName;
+ }
+
+ public void setShortMethodName(String shortMethodName) {
+ if(shortMethodName == null) {
+ shortMethodName = "";
+ }
+ mShortMethodName = shortMethodName;
+ }
+
+ public void setParentSession(Session parentSession) {
+ mParentSession = parentSession;
+ }
+
+ public void addChild(Session childSession) {
+ if(childSession != null) {
+ mChildSessions.add(childSession);
+ }
+ }
+
+ public void removeChild(Session child) {
+ if(child != null) {
+ mChildSessions.remove(child);
+ }
+ }
+
+ public long getExecutionStartTimeMilliseconds() {
+ return mExecutionStartTimeMs;
+ }
+
+ public Session getParentSession() {
+ return mParentSession;
+ }
+
+ public ArrayList<Session> getChildSessions() {
+ return mChildSessions;
+ }
+
+ public boolean isSessionCompleted() {
+ return mIsCompleted;
+ }
+
+ // Mark this session complete. This will be deleted by Log when all subsessions are complete
+ // as well.
+ public void markSessionCompleted(long executionEndTimeMs) {
+ mExecutionEndTimeMs = executionEndTimeMs;
+ mIsCompleted = true;
+ }
+
+ public long getLocalExecutionTime() {
+ if(mExecutionEndTimeMs == UNDEFINED) {
+ return UNDEFINED;
+ }
+ return mExecutionEndTimeMs - mExecutionStartTimeMs;
+ }
+
+ public String getNextChildId() {
+ return String.valueOf(mChildSessions.size());
+ }
+
+ @Override
+ public boolean equals(Object obj) {
+ if (!(obj instanceof Session)) {
+ return false;
+ }
+ if (obj == this) {
+ return true;
+ }
+ Session otherSession = (Session) obj;
+ return (mSessionId.equals(otherSession.mSessionId)) &&
+ (mShortMethodName.equals(otherSession.mShortMethodName)) &&
+ mExecutionStartTimeMs == otherSession.mExecutionStartTimeMs &&
+ mParentSession == otherSession.mParentSession &&
+ mChildSessions.equals(otherSession.mChildSessions) &&
+ mIsCompleted == otherSession.mIsCompleted &&
+ mExecutionEndTimeMs == otherSession.mExecutionEndTimeMs;
+ }
+
+ // Builds full session id recursively
+ private String getFullSessionId() {
+ if(mParentSession == null) {
+ return mSessionId;
+ } else {
+ return mParentSession.getFullSessionId() + "_" + mSessionId;
+ }
+ }
+
+ @Override
+ public String toString() {
+ return mShortMethodName + "@" + getFullSessionId();
+ }
+}
diff --git a/src/com/android/server/telecom/SystemLoggingContainer.java b/src/com/android/server/telecom/SystemLoggingContainer.java
new file mode 100644
index 0000000..0b65b09
--- /dev/null
+++ b/src/com/android/server/telecom/SystemLoggingContainer.java
@@ -0,0 +1,47 @@
+/*
+ * Copyright (C) 2015 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 com.android.server.telecom;
+
+/**
+ * Create a container for the Android Logging class so that it can be mocked in testing.
+ */
+public class SystemLoggingContainer {
+
+ public void v(String TAG, String msg) {
+ android.util.Slog.v(TAG, msg);
+ }
+
+ public void d(String TAG, String msg) {
+ android.util.Slog.d(TAG, msg);
+ }
+
+ public void i(String TAG, String msg) {
+ android.util.Slog.i(TAG, msg);
+ }
+
+ public void w(String TAG, String msg) {
+ android.util.Slog.w(TAG, msg);
+ }
+
+ public void e(String TAG, String msg, Throwable tr) {
+ android.util.Slog.e(TAG, msg, tr);
+ }
+
+ public void wtf(String TAG, String msg, Throwable tr) {
+ android.util.Slog.wtf(TAG, msg, tr);
+ }
+}
diff --git a/tests/src/com/android/server/telecom/tests/LogTest.java b/tests/src/com/android/server/telecom/tests/LogTest.java
new file mode 100644
index 0000000..80bfe20
--- /dev/null
+++ b/tests/src/com/android/server/telecom/tests/LogTest.java
@@ -0,0 +1,393 @@
+/*
+ * Copyright (C) 2015 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 com.android.server.telecom.tests;
+
+import android.os.Handler;
+import android.os.HandlerThread;
+import android.os.Message;
+
+import com.android.internal.os.SomeArgs;
+import com.android.server.telecom.Session;
+import com.android.server.telecom.SystemLoggingContainer;
+import com.android.server.telecom.Log;
+
+import org.junit.Assert;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+
+import java.util.ArrayList;
+import java.util.Random;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import static org.mockito.Matchers.contains;
+import static org.mockito.Matchers.eq;
+import static org.mockito.Mockito.timeout;
+import static org.mockito.Mockito.verify;
+
+/**
+ * Unit tests for Telecom's Logging system.
+ */
+public class LogTest extends TelecomTestCase{
+
+ /**
+ * This helper class captures the logs that are sent to Log and stores them in an array to be
+ * verified by LogTest.
+ */
+ private class TestLoggingContainer extends SystemLoggingContainer {
+ public ArrayList<String> receivedStrings;
+
+ public TestLoggingContainer() {
+ receivedStrings = new ArrayList<>(100);
+ }
+
+ @Override
+ public void i(String msgTag, String msg) {
+ if(msgTag.equals(LogTest.TESTING_TAG)) {
+ synchronized (this) {
+ receivedStrings.add(msg);
+ }
+ }
+ }
+
+ public boolean didReceiveMessage(int timeoutMs, String msg) {
+ String matchedString = null;
+ // Wait for timeout to expire before checking received messages
+ if (timeoutMs > 0) {
+ try {
+ Thread.sleep(timeoutMs);
+ } catch (InterruptedException e) {
+ Log.w(LogTest.TESTING_TAG, "TestLoggingContainer: Thread Interrupted!");
+ }
+ }
+ synchronized (this) {
+ for (String receivedString : receivedStrings) {
+ if (receivedString.contains(msg)) {
+ matchedString = receivedString;
+ break;
+ }
+ }
+ if (matchedString != null) {
+ receivedStrings.remove(matchedString);
+ return true;
+ }
+ }
+ android.util.Log.i(TESTING_TAG, "Did not receive message: " + msg);
+ return false;
+ }
+
+ public boolean isMessagesEmpty() {
+ boolean isEmpty = receivedStrings.isEmpty();
+ if(!isEmpty) {
+ printMessagesThatAreLeft();
+ }
+ return isEmpty;
+ }
+
+ public synchronized void printMessagesThatAreLeft() {
+ android.util.Log.i(TESTING_TAG, "Remaining Messages in Log Queue:");
+ for (String receivedString : receivedStrings) {
+ android.util.Log.i(TESTING_TAG, "\t- " + receivedString);
+ }
+ }
+ }
+
+ public static final int TEST_THREAD_COUNT = 150;
+ public static final int TEST_SLEEP_TIME_MS = 50;
+ // Should be larger than TEST_SLEEP_TIME_MS!
+ public static final int TEST_VERIFY_TIMEOUT_MS = 100;
+ public static final String TEST_ENTER_METHOD1 = "TEM1";
+ public static final String TEST_ENTER_METHOD2 = "TEM2";
+ public static final String TEST_ENTER_METHOD3 = "TEM3";
+ public static final String TEST_CLASS_NAME = "LogTest";
+
+ private static final int EVENT_START_TEST_SLEEPY_METHOD = 0;
+ private static final int EVENT_START_TEST_SLEEPY_MULTIPLE_METHOD = 1;
+ private static final int EVENT_LAST_MESSAGE = 2;
+
+ private static final long RANDOM_NUMBER_SEED = 6191991;
+
+ Random rng = new Random(RANDOM_NUMBER_SEED);
+
+ private Handler mSleepyHandler = new Handler(
+ new HandlerThread("sleepyThread"){{start();}}.getLooper()) {
+ @Override
+ public void handleMessage(Message msg) {
+ SomeArgs args = (SomeArgs) msg.obj;
+ Session subsession = (Session) args.arg1;
+ Log.continueSession(subsession, "lTSH.hM");
+ switch (msg.what) {
+ case EVENT_START_TEST_SLEEPY_METHOD:
+ sleepyMethod(TEST_SLEEP_TIME_MS);
+ break;
+ }
+ Log.endSession();
+ }
+ };
+
+ private boolean isHandlerCompleteWithEvents;
+ private Handler mSleepyMultipleHandler = new Handler(
+ new HandlerThread("sleepyMultipleThread"){{start();}}.getLooper()){
+ @Override
+ public void handleMessage(Message msg) {
+ switch (msg.what) {
+ case EVENT_START_TEST_SLEEPY_MULTIPLE_METHOD:
+ SomeArgs args = (SomeArgs) msg.obj;
+ Session subsession = (Session) args.arg1;
+ Log.continueSession(subsession, "lTSCH.hM");
+ sleepyMultipleMethod();
+ Log.endSession();
+ break;
+ case EVENT_LAST_MESSAGE:
+ isHandlerCompleteWithEvents = true;
+ break;
+ }
+ }
+ };
+
+ private AtomicInteger mCompleteCount;
+ class LogTestRunnable implements Runnable {
+ private String mshortMethodName;
+ public LogTestRunnable(String shortMethodName) {
+ mshortMethodName = shortMethodName;
+ }
+
+ public void run() {
+ Log.startSession(mshortMethodName);
+ sleepyCallerMethod(TEST_SLEEP_TIME_MS);
+ Log.endSession();
+ mCompleteCount.incrementAndGet();
+ }
+ }
+
+ TestLoggingContainer mTestSystemLogger;
+
+ @Override
+ public void setUp() throws Exception {
+ super.setUp();
+ MockitoAnnotations.initMocks(this);
+ mTestSystemLogger = new TestLoggingContainer();
+ Log.setLoggingContainer(mTestSystemLogger);
+ Log.restartSessionCounter();
+ }
+
+ @Override
+ public void tearDown() throws Exception {
+ mTestSystemLogger = null;
+ Log.setLoggingContainer(new SystemLoggingContainer());
+ super.tearDown();
+ }
+
+ public void testSingleThreadSession() throws Exception {
+ String sessionName = "LT.sTS";
+ Log.startSession(sessionName);
+ sleepyMethod(TEST_SLEEP_TIME_MS);
+ Log.endSession();
+
+ verifyEventResult(Session.START_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyMethodCall(sessionName, 0, "", TEST_ENTER_METHOD1, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+
+ assertEquals(Log.sSessionMapper.size(), 0);
+ assertEquals(true, mTestSystemLogger.isMessagesEmpty());
+ }
+
+ public void testSingleHandlerThreadSession() throws Exception {
+ String sessionName = "LT.tSHTS";
+ Log.startSession(sessionName);
+ Session subsession = Log.createSubsession();
+ SomeArgs args = SomeArgs.obtain();
+ args.arg1 = subsession;
+ mSleepyHandler.obtainMessage(EVENT_START_TEST_SLEEPY_METHOD, args).sendToTarget();
+ Log.endSession();
+
+ verifyEventResult(Session.START_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.CREATE_SUBSESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyContinueEventResult(sessionName, "lTSH.hM", "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyMethodCall("lTSH.hM", 0, "_0", TEST_ENTER_METHOD1, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, "lTSH.hM", "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+
+ assertEquals(Log.sSessionMapper.size(), 0);
+ assertEquals(true, mTestSystemLogger.isMessagesEmpty());
+ }
+
+ public void testSpawnMultipleThreadSessions() throws Exception {
+ final String sessionName = "LT.lTR";
+ mCompleteCount = new AtomicInteger(0);
+ for(int i = 0; i < TEST_THREAD_COUNT; i++) {
+ Thread.sleep(10);
+ new Thread(new LogTestRunnable(sessionName)).start();
+ }
+
+ // Poll until all of the threads have completed
+ while(mCompleteCount.get() < TEST_THREAD_COUNT) {
+ Thread.sleep(1000);
+ }
+
+ // Loop through verification separately to spawn threads fast so there is possible overlap
+ // (verifyEventResult(...) delays)
+ for(int i = 0; i < TEST_THREAD_COUNT; i++) {
+ verifyEventResult(Session.START_SESSION, sessionName, "", i, 0);
+ verifyMethodCall(sessionName, i, "", TEST_ENTER_METHOD2, 0);
+ verifyMethodCall(sessionName, i, "", TEST_ENTER_METHOD1, 0);
+ verifyEventResult(Session.END_SUBSESSION, sessionName, "", i, 0);
+ verifyEventResult(Session.END_SESSION, sessionName, "", i, 0);
+ }
+
+ assertEquals(Log.sSessionMapper.size(), 0);
+ assertEquals(true, mTestSystemLogger.isMessagesEmpty());
+ }
+
+ public void testSpawnMultipleThreadMultipleHandlerSession() throws Exception {
+ String sessionName = "LT.tSMTMHS";
+ Log.startSession(sessionName);
+ Session subsession = Log.createSubsession();
+ SomeArgs args = SomeArgs.obtain();
+ args.arg1 = subsession;
+ mSleepyMultipleHandler.obtainMessage(EVENT_START_TEST_SLEEPY_MULTIPLE_METHOD,
+ args).sendToTarget();
+ Log.endSession();
+
+ verifyEventResult(Session.START_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.CREATE_SUBSESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyContinueEventResult(sessionName, "lTSCH.hM", "_0", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyMethodCall("lTSCH.hM", 0, "_0", TEST_ENTER_METHOD3, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, "lTSCH.hM", "_0", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.CREATE_SUBSESSION, "lTSCH.hM", "", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyContinueEventResult("lTSCH.hM", "lTSH.hM", "_0_0", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyMethodCall("lTSH.hM", 0, "_0_0", TEST_ENTER_METHOD1, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SUBSESSION, "lTSH.hM", "_0_0", 0, TEST_VERIFY_TIMEOUT_MS);
+ verifyEventResult(Session.END_SESSION, sessionName, "", 0, TEST_VERIFY_TIMEOUT_MS);
+
+ assertEquals(Log.sSessionMapper.size(), 0);
+ assertEquals(true, mTestSystemLogger.isMessagesEmpty());
+ }
+
+ public void testSpawnMultipleThreadMultipleHandlerSessions() throws Exception {
+ String sessionName = "LT.tSMTMHSs";
+ isHandlerCompleteWithEvents = false;
+ for(int i = 0; i < TEST_THREAD_COUNT; i++) {
+ Log.startSession(sessionName);
+ Session subsession = Log.createSubsession();
+ SomeArgs args = SomeArgs.obtain();
+ args.arg1 = subsession;
+ mSleepyMultipleHandler.obtainMessage(EVENT_START_TEST_SLEEPY_MULTIPLE_METHOD,
+ args).sendToTarget();
+ Log.endSession();
+ }
+ // Send a message that denotes the last message that is sent. We poll until this message
+ // is processed in order to verify the results without waiting an arbitrary amount of time
+ // (that can change per device).
+ mSleepyMultipleHandler.obtainMessage(EVENT_LAST_MESSAGE).sendToTarget();
+
+ while(!isHandlerCompleteWithEvents){
+ Thread.sleep(1000);
+ }
+
+ for(int i = 0; i < TEST_THREAD_COUNT; i++) {
+ verifyEventResult(Session.START_SESSION, sessionName, "", i, 0);
+ verifyEventResult(Session.END_SUBSESSION, sessionName, "", i, 0);
+ verifyEventResult(Session.CREATE_SUBSESSION, sessionName, "", i, 0);
+ verifyContinueEventResult(sessionName, "lTSCH.hM", "_0", i, 0);
+ verifyMethodCall("lTSCH.hM", i, "_0", TEST_ENTER_METHOD3, 0);
+ verifyEventResult(Session.END_SUBSESSION, "lTSCH.hM", "_0", i, 0);
+ verifyEventResult(Session.CREATE_SUBSESSION, "lTSCH.hM", "", i, 0);
+ verifyContinueEventResult("lTSCH.hM", "lTSH.hM", "_0_0", i, 0);
+ verifyMethodCall("lTSH.hM", i, "_0_0", TEST_ENTER_METHOD1, 0);
+ verifyEventResult(Session.END_SUBSESSION, "lTSH.hM", "_0_0", i, 0);
+ verifyEventResult(Session.END_SESSION, sessionName, "", i, 0);
+ }
+
+ assertEquals(Log.sSessionMapper.size(), 0);
+ assertEquals(true, mTestSystemLogger.isMessagesEmpty());
+ }
+
+ private void verifyMethodCall(String methodName, int sessionId, String subsession,
+ String shortMethodName, int timeoutMs) {
+ boolean isMessageReceived = mTestSystemLogger.didReceiveMessage(timeoutMs,
+ buildExpectedResult(methodName, sessionId, subsession, shortMethodName));
+
+ assertEquals(true, isMessageReceived);
+ }
+
+ private String buildExpectedSession(String shortMethodName, int sessionId) {
+ return shortMethodName + "@" + Log.getBase64Encoding(sessionId);
+ }
+
+ private String buildExpectedResult(String shortMethodName, int sessionId,
+ String subsessionId, String logText) {
+ return TEST_CLASS_NAME + " " + buildExpectedSession(shortMethodName, sessionId) +
+ subsessionId + ": " + logText;
+ }
+
+ private void verifyContinueEventResult(String shortOldMethodName, String shortNewMethodName,
+ String subsession, int sessionId, int timeoutMs) {
+ String expectedSession = buildExpectedSession(shortNewMethodName, sessionId);
+ boolean isMessageReceived = mTestSystemLogger.didReceiveMessage(timeoutMs,
+ Session.CONTINUE_SUBSESSION + " " + shortOldMethodName + "->" + expectedSession +
+ subsession);
+ assertEquals(true, isMessageReceived);
+ }
+
+ private void verifyEventResult(String event, String shortMethodName, String subsession,
+ int sessionId, int timeoutMs) {
+ String expectedSession = buildExpectedSession(shortMethodName, sessionId);
+ boolean isMessageReceived = mTestSystemLogger.didReceiveMessage(timeoutMs,
+ event + " " + expectedSession + subsession);
+ assertEquals(true, isMessageReceived);
+ }
+
+ private void sleepyCallerMethod(int timeToSleepMs) {
+ Log.i(TEST_CLASS_NAME, TEST_ENTER_METHOD2);
+ try {
+ Thread.sleep(timeToSleepMs);
+ sleepyMethod(rng.nextInt(TEST_SLEEP_TIME_MS));
+ } catch(InterruptedException e) {
+ // This should not happen
+ Assert.fail("Thread sleep interrupted: " + e.getMessage());
+ }
+
+ }
+
+ private void sleepyMultipleMethod() {
+ Log.i(TEST_CLASS_NAME, TEST_ENTER_METHOD3);
+ Session subsession = Log.createSubsession();
+ SomeArgs args = SomeArgs.obtain();
+ args.arg1 = subsession;
+ mSleepyHandler.obtainMessage(EVENT_START_TEST_SLEEPY_METHOD, args).sendToTarget();
+ try {
+ Thread.sleep(TEST_SLEEP_TIME_MS);
+ } catch(InterruptedException e) {
+ // This should not happen
+ Assert.fail("Thread sleep interrupted: " + e.getMessage());
+ }
+ }
+
+ private void sleepyMethod(int timeToSleepMs) {
+ Log.i(TEST_CLASS_NAME, TEST_ENTER_METHOD1);
+ try {
+ Thread.sleep(timeToSleepMs);
+ } catch(InterruptedException e) {
+ // This should not happen
+ Assert.fail("Thread sleep interrupted: " + e.getMessage());
+ }
+ }
+
+}
diff --git a/tests/src/com/android/server/telecom/tests/TelecomTestCase.java b/tests/src/com/android/server/telecom/tests/TelecomTestCase.java
index 144ef66..9c9d0d8 100644
--- a/tests/src/com/android/server/telecom/tests/TelecomTestCase.java
+++ b/tests/src/com/android/server/telecom/tests/TelecomTestCase.java
@@ -23,7 +23,7 @@
import android.test.AndroidTestCase;
public abstract class TelecomTestCase extends AndroidTestCase {
- private static final String TESTING_TAG = "Telecom-TEST";
+ protected static final String TESTING_TAG = "Telecom-TEST";
MockitoHelper mMockitoHelper = new MockitoHelper();
ComponentContextFixture mComponentContextFixture;