Readability improvements in Logging

We now truncate Session method paths and IDs based on the Logging level
to improve Session Logging readability in logcat. If another external
session is started off of an existing external Session, the preceding
histories are replaced with "..." so that the Session information is not
overwhelming.

Bug: 26571395
Test: Unit Tests and manual tests pass
Change-Id: I9ffda3d64f1072fa6228a82a86116a5e47d18c96

5 files changed, 90 insertions, 42 deletions

diff --git a/telecomm/java/android/telecom/ConnectionService.java b/telecomm/java/android/telecom/ConnectionService.java
index 66d704b2fe81..f177a419e4c6 100644
--- a/telecomm/java/android/telecom/ConnectionService.java
+++ b/telecomm/java/android/telecom/ConnectionService.java
@@ -515,9 +515,12 @@ public abstract class ConnectionService extends Service {
                         final boolean isUnknown = args.argi2 == 1;
                         if (!mAreAccountsInitialized) {
                             Log.d(this, "Enqueueing pre-init request %s", id);
-                            mPreInitializationConnectionRequests.add(new Runnable() {
+                            mPreInitializationConnectionRequests.add(
+                                    new android.telecom.Logging.Runnable(
+                                            SESSION_HANDLER + SESSION_CREATE_CONN + ".pICR",
+                                            null /*lock*/) {
                                 @Override
-                                public void run() {
+                                public void loggedRun() {
                                     createConnection(
                                             connectionManagerPhoneAccount,
                                             id,
@@ -525,7 +528,7 @@ public abstract class ConnectionService extends Service {
                                             isIncoming,
                                             isUnknown);
                                 }
-                            });
+                            }.prepare());
                         } else {
                             createConnection(
                                     connectionManagerPhoneAccount,
@@ -1378,9 +1381,9 @@ public abstract class ConnectionService extends Service {
             public void onResult(
                     final List<ComponentName> componentNames,
                     final List<IBinder> services) {
-                mHandler.post(new Runnable() {
+                mHandler.post(new android.telecom.Logging.Runnable("oAA.qRCS.oR", null /*lock*/) {
                     @Override
-                    public void run() {
+                    public void loggedRun() {
                         for (int i = 0; i < componentNames.size() && i < services.size(); i++) {
                             mRemoteConnectionManager.addConnectionService(
                                     componentNames.get(i),
@@ -1389,17 +1392,17 @@ public abstract class ConnectionService extends Service {
                         onAccountsInitialized();
                         Log.d(this, "remote connection services found: " + services);
                     }
-                });
+                }.prepare());
             }
 
             @Override
             public void onError() {
-                mHandler.post(new Runnable() {
+                mHandler.post(new android.telecom.Logging.Runnable("oAA.qRCS.oE", null /*lock*/) {
                     @Override
-                    public void run() {
+                    public void loggedRun() {
                         mAreAccountsInitialized = true;
                     }
-                });
+                }.prepare());
             }
         });
     }
diff --git a/telecomm/java/android/telecom/Log.java b/telecomm/java/android/telecom/Log.java
index 446bbbb69996..ced6627e8d34 100644
--- a/telecomm/java/android/telecom/Log.java
+++ b/telecomm/java/android/telecom/Log.java
@@ -48,13 +48,13 @@ public class Log {
     // Generic tag for all Telecom logging
     @VisibleForTesting
     public static String TAG = "TelecomFramework";
+    public static boolean DEBUG = isLoggable(android.util.Log.DEBUG);
+    public static boolean INFO = isLoggable(android.util.Log.INFO);
+    public static boolean VERBOSE = isLoggable(android.util.Log.VERBOSE);
+    public static boolean WARN = isLoggable(android.util.Log.WARN);
+    public static boolean ERROR = isLoggable(android.util.Log.ERROR);
 
     private static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */
-    public static final boolean DEBUG = isLoggable(android.util.Log.DEBUG);
-    public static final boolean INFO = isLoggable(android.util.Log.INFO);
-    public static final boolean VERBOSE = isLoggable(android.util.Log.VERBOSE);
-    public static final boolean WARN = isLoggable(android.util.Log.WARN);
-    public static final boolean ERROR = isLoggable(android.util.Log.ERROR);
 
     // Used to synchronize singleton logging lazy initialization
     private static final Object sSingletonSync = new Object();
@@ -340,6 +340,11 @@ public class Log {
 
     public static void setTag(String tag) {
         TAG = tag;
+        DEBUG = isLoggable(android.util.Log.DEBUG);
+        INFO = isLoggable(android.util.Log.INFO);
+        VERBOSE = isLoggable(android.util.Log.VERBOSE);
+        WARN = isLoggable(android.util.Log.WARN);
+        ERROR = isLoggable(android.util.Log.ERROR);
     }
 
     /**
diff --git a/telecomm/java/android/telecom/Logging/Runnable.java b/telecomm/java/android/telecom/Logging/Runnable.java
index 56c52bfde3b3..6e810538cc62 100644
--- a/telecomm/java/android/telecom/Logging/Runnable.java
+++ b/telecomm/java/android/telecom/Logging/Runnable.java
@@ -27,7 +27,7 @@ public abstract class Runnable {
 
     private Session mSubsession;
     private final String mSubsessionName;
-    private final Object mLock = new Object();
+    private final Object mLock;
     private final java.lang.Runnable mRunnable = new java.lang.Runnable() {
         @Override
         public void run() {
@@ -45,7 +45,18 @@ public abstract class Runnable {
         }
     };
 
-    public Runnable(String subsessionName) {
+    /**
+     * Creates a new Telecom Runnable that incorporates Session Logging into it. Useful for carrying
+     * Logging Sessions through different threads as well as through handlers.
+     * @param subsessionName The name that will be used in the Logs to mark this Session
+     * @param lock The synchronization lock that will be used to lock loggedRun().
+     */
+    public Runnable(String subsessionName, Object lock) {
+        if (lock == null) {
+            mLock = new Object();
+        } else {
+            mLock = lock;
+        }
         mSubsessionName = subsessionName;
     }
 
@@ -85,4 +96,4 @@ public abstract class Runnable {
      */
     abstract public void loggedRun();
 
-}
+}
\ No newline at end of file
diff --git a/telecomm/java/android/telecom/Logging/Session.java b/telecomm/java/android/telecom/Logging/Session.java
index 3a7b8c09203a..c45bd6b04145 100644
--- a/telecomm/java/android/telecom/Logging/Session.java
+++ b/telecomm/java/android/telecom/Logging/Session.java
@@ -19,6 +19,7 @@ package android.telecom.Logging;
 import android.annotation.NonNull;
 import android.os.Parcel;
 import android.os.Parcelable;
+import android.telecom.Log;
 import android.text.TextUtils;
 
 import com.android.internal.annotations.VisibleForTesting;
@@ -26,20 +27,23 @@ import com.android.internal.annotations.VisibleForTesting;
 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.
+ * Stores information about a thread's point of entry into that should persist until that thread
+ * exits.
  * @hide
  */
 public class Session {
 
     public static final String START_SESSION = "START_SESSION";
+    public static final String START_EXTERNAL_SESSION = "START_EXTERNAL_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 String SUBSESSION_SEPARATION_CHAR = "->";
+    public static final String SESSION_SEPARATION_CHAR_CHILD = "_";
     public static final String EXTERNAL_INDICATOR = "E-";
+    public static final String TRUNCATE_STRING = "...";
 
     /**
      * Initial value of mExecutionEndTimeMs and the final value of {@link #getLocalExecutionTime()}
@@ -49,15 +53,19 @@ public class Session {
 
     public static class Info implements Parcelable {
         public final String sessionId;
-        public final String shortMethodName;
+        public final String methodPath;
 
-        private Info(String id, String methodName) {
+        private Info(String id, String path) {
             sessionId = id;
-            shortMethodName = methodName;
+            methodPath = path;
         }
 
         public static Info getInfo (Session s) {
-            return new Info(s.getFullSessionId(), s.getShortMethodName());
+            // Create Info based on the truncated method path if the session is external, so we do
+            // not get multiple stacking external sessions (unless we have DEBUG level logging or
+            // lower).
+            return new Info(s.getFullSessionId(), s.getFullMethodPath(
+                    !Log.DEBUG && s.isSessionExternal()));
         }
 
         /** Responsible for creating Info objects for deserialized Parcels. */
@@ -86,7 +94,7 @@ public class Session {
         @Override
         public void writeToParcel(Parcel destination, int flags) {
             destination.writeString(sessionId);
-            destination.writeString(shortMethodName);
+            destination.writeString(methodPath);
         }
     }
 
@@ -226,7 +234,15 @@ public class Session {
         if (parentSession == null) {
             return mSessionId;
         } else {
-            return parentSession.getFullSessionId() + "_" + mSessionId;
+            if (Log.VERBOSE) {
+                return parentSession.getFullSessionId() +
+                        // Append "_X" to subsession to show subsession designation.
+                        SESSION_SEPARATION_CHAR_CHILD + mSessionId;
+            } else {
+                // Only worry about the base ID at the top of the tree.
+                return parentSession.getFullSessionId();
+            }
+
         }
     }
 
@@ -259,16 +275,18 @@ public class Session {
     }
 
     // Recursively concatenate mShortMethodName with the parent Sessions to create full method
-    // path. Caches this string so that multiple calls for the path will be quick.
-    public String getFullMethodPath() {
+    // path. if truncatePath is set to true, all other external sessions (except for the most
+    // recent) will be truncated to "..."
+    public String getFullMethodPath(boolean truncatePath) {
         StringBuilder sb = new StringBuilder();
-        getFullMethodPath(sb);
+        getFullMethodPath(sb, truncatePath);
         return sb.toString();
     }
 
-    private synchronized void getFullMethodPath(StringBuilder sb) {
-        // Don't calculate if we have already figured it out!
-        if (!TextUtils.isEmpty(mFullMethodPathCache)) {
+    private synchronized void getFullMethodPath(StringBuilder sb, boolean truncatePath) {
+        // Return cached value for method path. When returning the truncated path, recalculate the
+        // full path without using the cached value.
+        if (!TextUtils.isEmpty(mFullMethodPathCache) && !truncatePath) {
             sb.append(mFullMethodPathCache);
             return;
         }
@@ -278,25 +296,37 @@ public class Session {
             // Check to see if the session has been renamed yet. If it has not, then the session
             // has not been continued.
             isSessionStarted = !mShortMethodName.equals(parentSession.mShortMethodName);
-            parentSession.getFullMethodPath(sb);
+            parentSession.getFullMethodPath(sb, truncatePath);
             sb.append(SUBSESSION_SEPARATION_CHAR);
         }
         // Encapsulate the external session's method name so it is obvious what part of the session
-        // is external.
+        // is external or truncate it if we do not want the entire history.
         if (isExternal()) {
-            sb.append("(");
-            sb.append(mShortMethodName);
-            sb.append(")");
+            if (truncatePath) {
+                sb.append(TRUNCATE_STRING);
+            } else {
+                sb.append("(");
+                sb.append(mShortMethodName);
+                sb.append(")");
+            }
         } else {
             sb.append(mShortMethodName);
         }
-
-        if(isSessionStarted) {
+        // If we are returning the truncated path, do not save that path as the full path.
+        if (isSessionStarted && !truncatePath) {
             // Cache this value so that we do not have to do this work next time!
             // We do not cache the value if the session being evaluated hasn't been continued yet.
             mFullMethodPathCache = sb.toString();
         }
     }
+    // Recursively move to the top of the tree to see if the parent session is external.
+    private boolean isSessionExternal() {
+        if (getParentSession() == null) {
+            return isExternal();
+        } else {
+            return getParentSession().isSessionExternal();
+        }
+    }
 
     @Override
     public int hashCode() {
@@ -350,7 +380,7 @@ public class Session {
             return mParentSession.toString();
         } else {
             StringBuilder methodName = new StringBuilder();
-            methodName.append(getFullMethodPath());
+            methodName.append(getFullMethodPath(false /*truncatePath*/));
             if (mOwnerInfo != null && !mOwnerInfo.isEmpty()) {
                 methodName.append("(InCall package: ");
                 methodName.append(mOwnerInfo);
diff --git a/telecomm/java/android/telecom/Logging/SessionManager.java b/telecomm/java/android/telecom/Logging/SessionManager.java
index 8ced7f8181c5..949f7b7a89ae 100644
--- a/telecomm/java/android/telecom/Logging/SessionManager.java
+++ b/telecomm/java/android/telecom/Logging/SessionManager.java
@@ -177,8 +177,9 @@ public class SessionManager {
         }
 
         // 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.shortMethodName, System.currentTimeMillis(),
+                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
@@ -190,8 +191,6 @@ public class SessionManager {
         // Create a subsession from this external Session parent node
         Session childSession = createSubsession();
         continueSession(childSession, shortMethodName);
-
-        Log.d(LOGGING_TAG, Session.START_SESSION);
     }
 
     /**