Merge "Update calllog insertion logic"
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;