Improve transaction logging

Add more detailed conditional logs to transaction executor on the
client side for easier debugging. This will print out transaction
callbacks and final state requests, as well as target activity
names.

Test: Manual
Change-Id: I14ab1a34985975bfd8c1f90b9c5945e354f79446

6 files changed, 139 insertions, 50 deletions

diff --git a/core/java/android/app/ActivityThread.java b/core/java/android/app/ActivityThread.java
index 2daa5779bde7..151e9a5a4908 100644
--- a/core/java/android/app/ActivityThread.java
+++ b/core/java/android/app/ActivityThread.java
@@ -2731,7 +2731,8 @@ public final class ActivityThread extends ClientTransactionHandler {
     }
 
     public final Activity getActivity(IBinder token) {
-        return mActivities.get(token).activity;
+        final ActivityClientRecord activityRecord = mActivities.get(token);
+        return activityRecord != null ? activityRecord.activity : null;
     }
 
     @Override
diff --git a/core/java/android/app/ClientTransactionHandler.java b/core/java/android/app/ClientTransactionHandler.java
index 193f933df782..b5295d15ee8d 100644
--- a/core/java/android/app/ClientTransactionHandler.java
+++ b/core/java/android/app/ClientTransactionHandler.java
@@ -66,6 +66,8 @@ public abstract class ClientTransactionHandler {
 
     abstract void sendMessage(int what, Object obj);
 
+    /** Get activity instance for the token. */
+    public abstract Activity getActivity(IBinder token);
 
     // Prepare phase related logic and handlers. Methods that inform about about pending changes or
     // do other internal bookkeeping.
diff --git a/core/java/android/app/servertransaction/ClientTransaction.java b/core/java/android/app/servertransaction/ClientTransaction.java
index 2c1e59bfc066..2a33342836f7 100644
--- a/core/java/android/app/servertransaction/ClientTransaction.java
+++ b/core/java/android/app/servertransaction/ClientTransaction.java
@@ -26,6 +26,7 @@ import android.os.RemoteException;
 
 import com.android.internal.annotations.VisibleForTesting;
 
+import java.io.PrintWriter;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Objects;
@@ -164,32 +165,6 @@ public class ClientTransaction implements Parcelable, ObjectPoolItem {
         ObjectPool.recycle(this);
     }
 
-    @Override
-    public String toString() {
-        final StringBuilder sb = new StringBuilder(64);
-        sb.append("ClientTransaction{");
-        if (mActivityToken != null) {
-            sb.append(" a:").append(Integer.toHexString(System.identityHashCode(mActivityToken)));
-        }
-        if (mActivityCallbacks != null && !mActivityCallbacks.isEmpty()) {
-            sb.append(" c:");
-            final int size = mActivityCallbacks.size();
-            for (int i = 0; i < size; i++) {
-                sb.append(mActivityCallbacks.get(i).getClass().getSimpleName());
-                if (i < size - 1) {
-                    sb.append(",");
-                }
-            }
-        }
-        if (mLifecycleStateRequest != null) {
-            sb.append(" s:");
-            sb.append(mLifecycleStateRequest.getClass().getSimpleName());
-        }
-        sb.append(" }");
-        return sb.toString();
-    }
-
-
     // Parcelable implementation
 
     /** Write to Parcel. */
@@ -262,4 +237,23 @@ public class ClientTransaction implements Parcelable, ObjectPoolItem {
         result = 31 * result + Objects.hashCode(mLifecycleStateRequest);
         return result;
     }
+
+    /** Dump transaction items callback items and final lifecycle state request. */
+    public void dump(String prefix, PrintWriter pw) {
+        pw.append(prefix).println("ClientTransaction{");
+        pw.append(prefix).print("  callbacks=[");
+        final int size = mActivityCallbacks != null ? mActivityCallbacks.size() : 0;
+        if (size > 0) {
+            pw.println();
+            for (int i = 0; i < size; i++) {
+                pw.append(prefix).append("    ").println(mActivityCallbacks.get(i).toString());
+            }
+            pw.append(prefix).println("  ]");
+        } else {
+            pw.println("]");
+        }
+        pw.append(prefix).append("  stateRequest=").println(mLifecycleStateRequest != null
+                ? mLifecycleStateRequest.toString() : null);
+        pw.append(prefix).println("}");
+    }
 }
diff --git a/core/java/android/app/servertransaction/TransactionExecutor.java b/core/java/android/app/servertransaction/TransactionExecutor.java
index 503e18b62cae..20e0da3ead8a 100644
--- a/core/java/android/app/servertransaction/TransactionExecutor.java
+++ b/core/java/android/app/servertransaction/TransactionExecutor.java
@@ -24,7 +24,11 @@ import static android.app.servertransaction.ActivityLifecycleItem.ON_RESUME;
 import static android.app.servertransaction.ActivityLifecycleItem.ON_START;
 import static android.app.servertransaction.ActivityLifecycleItem.ON_STOP;
 import static android.app.servertransaction.ActivityLifecycleItem.UNDEFINED;
+import static android.app.servertransaction.TransactionExecutorHelper.getShortActivityName;
+import static android.app.servertransaction.TransactionExecutorHelper.getStateName;
 import static android.app.servertransaction.TransactionExecutorHelper.lastCallbackRequestingState;
+import static android.app.servertransaction.TransactionExecutorHelper.tId;
+import static android.app.servertransaction.TransactionExecutorHelper.transactionToString;
 
 import android.app.ActivityThread.ActivityClientRecord;
 import android.app.ClientTransactionHandler;
@@ -63,6 +67,8 @@ public class TransactionExecutor {
      * either remain in the initial state, or last state needed by a callback.
      */
     public void execute(ClientTransaction transaction) {
+        if (DEBUG_RESOLVER) Slog.d(TAG, tId(transaction) + "Start resolving transaction");
+
         final IBinder token = transaction.getActivityToken();
         if (token != null) {
             final Map<IBinder, ClientTransactionItem> activitiesToBeDestroyed =
@@ -77,18 +83,20 @@ public class TransactionExecutor {
                 if (mTransactionHandler.getActivityClient(token) == null) {
                     // The activity has not been created but has been requested to destroy, so all
                     // transactions for the token are just like being cancelled.
-                    Slog.w(TAG, "Skip pre-destroyed " + transaction);
+                    Slog.w(TAG, tId(transaction) + "Skip pre-destroyed transaction:\n"
+                            + transactionToString(transaction, mTransactionHandler));
                     return;
                 }
             }
         }
-        log("Start resolving transaction for client: " + mTransactionHandler + ", token: " + token);
+
+        if (DEBUG_RESOLVER) Slog.d(TAG, transactionToString(transaction, mTransactionHandler));
 
         executeCallbacks(transaction);
 
         executeLifecycleState(transaction);
         mPendingActions.clear();
-        log("End resolving transaction");
+        if (DEBUG_RESOLVER) Slog.d(TAG, tId(transaction) + "End resolving transaction");
     }
 
     /** Cycle through all states requested by callbacks and execute them at proper times. */
@@ -99,7 +107,7 @@ public class TransactionExecutor {
             // No callbacks to execute, return early.
             return;
         }
-        log("Resolving callbacks");
+        if (DEBUG_RESOLVER) Slog.d(TAG, tId(transaction) + "Resolving callbacks in transaction");
 
         final IBinder token = transaction.getActivityToken();
         ActivityClientRecord r = mTransactionHandler.getActivityClient(token);
@@ -116,12 +124,12 @@ public class TransactionExecutor {
         final int size = callbacks.size();
         for (int i = 0; i < size; ++i) {
             final ClientTransactionItem item = callbacks.get(i);
-            log("Resolving callback: " + item);
+            if (DEBUG_RESOLVER) Slog.d(TAG, tId(transaction) + "Resolving callback: " + item);
             final int postExecutionState = item.getPostExecutionState();
             final int closestPreExecutionState = mHelper.getClosestPreExecutionState(r,
                     item.getPostExecutionState());
             if (closestPreExecutionState != UNDEFINED) {
-                cycleToPath(r, closestPreExecutionState);
+                cycleToPath(r, closestPreExecutionState, transaction);
             }
 
             item.execute(mTransactionHandler, token, mPendingActions);
@@ -135,7 +143,7 @@ public class TransactionExecutor {
                 // Skip the very last transition and perform it by explicit state request instead.
                 final boolean shouldExcludeLastTransition =
                         i == lastCallbackRequestingState && finalState == postExecutionState;
-                cycleToPath(r, postExecutionState, shouldExcludeLastTransition);
+                cycleToPath(r, postExecutionState, shouldExcludeLastTransition, transaction);
             }
         }
     }
@@ -147,10 +155,14 @@ public class TransactionExecutor {
             // No lifecycle request, return early.
             return;
         }
-        log("Resolving lifecycle state: " + lifecycleItem);
 
         final IBinder token = transaction.getActivityToken();
         final ActivityClientRecord r = mTransactionHandler.getActivityClient(token);
+        if (DEBUG_RESOLVER) {
+            Slog.d(TAG, tId(transaction) + "Resolving lifecycle state: "
+                    + lifecycleItem + " for activity: "
+                    + getShortActivityName(token, mTransactionHandler));
+        }
 
         if (r == null) {
             // Ignore requests for non-existent client records for now.
@@ -158,7 +170,7 @@ public class TransactionExecutor {
         }
 
         // Cycle to the state right before the final requested state.
-        cycleToPath(r, lifecycleItem.getTargetState(), true /* excludeLastState */);
+        cycleToPath(r, lifecycleItem.getTargetState(), true /* excludeLastState */, transaction);
 
         // Execute the final transition with proper parameters.
         lifecycleItem.execute(mTransactionHandler, token, mPendingActions);
@@ -167,8 +179,8 @@ public class TransactionExecutor {
 
     /** Transition the client between states. */
     @VisibleForTesting
-    public void cycleToPath(ActivityClientRecord r, int finish) {
-        cycleToPath(r, finish, false /* excludeLastState */);
+    public void cycleToPath(ActivityClientRecord r, int finish, ClientTransaction transaction) {
+        cycleToPath(r, finish, false /* excludeLastState */, transaction);
     }
 
     /**
@@ -176,20 +188,30 @@ public class TransactionExecutor {
      * sequence. This is used when resolving lifecycle state request, when the last transition must
      * be performed with some specific parameters.
      */
-    private void cycleToPath(ActivityClientRecord r, int finish,
-            boolean excludeLastState) {
+    private void cycleToPath(ActivityClientRecord r, int finish, boolean excludeLastState,
+            ClientTransaction transaction) {
         final int start = r.getLifecycleState();
-        log("Cycle from: " + start + " to: " + finish + " excludeLastState:" + excludeLastState);
+        if (DEBUG_RESOLVER) {
+            Slog.d(TAG, tId(transaction) + "Cycle activity: "
+                    + getShortActivityName(r.token, mTransactionHandler)
+                    + " from: " + getStateName(start) + " to: " + getStateName(finish)
+                    + " excludeLastState: " + excludeLastState);
+        }
         final IntArray path = mHelper.getLifecyclePath(start, finish, excludeLastState);
-        performLifecycleSequence(r, path);
+        performLifecycleSequence(r, path, transaction);
     }
 
     /** Transition the client through previously initialized state sequence. */
-    private void performLifecycleSequence(ActivityClientRecord r, IntArray path) {
+    private void performLifecycleSequence(ActivityClientRecord r, IntArray path,
+            ClientTransaction transaction) {
         final int size = path.size();
         for (int i = 0, state; i < size; i++) {
             state = path.get(i);
-            log("Transitioning to state: " + state);
+            if (DEBUG_RESOLVER) {
+                Slog.d(TAG, tId(transaction) + "Transitioning activity: "
+                        + getShortActivityName(r.token, mTransactionHandler)
+                        + " to state: " + getStateName(state));
+            }
             switch (state) {
                 case ON_CREATE:
                     mTransactionHandler.handleLaunchActivity(r, mPendingActions,
@@ -225,8 +247,4 @@ public class TransactionExecutor {
             }
         }
     }
-
-    private static void log(String message) {
-        if (DEBUG_RESOLVER) Slog.d(TAG, message);
-    }
 }
diff --git a/core/java/android/app/servertransaction/TransactionExecutorHelper.java b/core/java/android/app/servertransaction/TransactionExecutorHelper.java
index 01b13a28aed1..0ea8c3c159fa 100644
--- a/core/java/android/app/servertransaction/TransactionExecutorHelper.java
+++ b/core/java/android/app/servertransaction/TransactionExecutorHelper.java
@@ -26,11 +26,16 @@ import static android.app.servertransaction.ActivityLifecycleItem.ON_STOP;
 import static android.app.servertransaction.ActivityLifecycleItem.PRE_ON_CREATE;
 import static android.app.servertransaction.ActivityLifecycleItem.UNDEFINED;
 
+import android.app.Activity;
 import android.app.ActivityThread.ActivityClientRecord;
+import android.app.ClientTransactionHandler;
+import android.os.IBinder;
 import android.util.IntArray;
 
 import com.android.internal.annotations.VisibleForTesting;
 
+import java.io.PrintWriter;
+import java.io.StringWriter;
 import java.util.List;
 
 /**
@@ -243,4 +248,73 @@ public class TransactionExecutorHelper {
 
         return lastRequestingCallback;
     }
+
+    /** Dump transaction to string. */
+    static String transactionToString(ClientTransaction transaction,
+            ClientTransactionHandler transactionHandler) {
+        final StringWriter stringWriter = new StringWriter();
+        final PrintWriter pw = new PrintWriter(stringWriter);
+        final String prefix = tId(transaction);
+        transaction.dump(prefix, pw);
+        pw.append(prefix + "Target activity: ")
+                .println(getActivityName(transaction.getActivityToken(), transactionHandler));
+        return stringWriter.toString();
+    }
+
+    /** @return A string in format "tId:<transaction hashcode> ". */
+    static String tId(ClientTransaction transaction) {
+        return "tId:" + transaction.hashCode() + " ";
+    }
+
+    /** Get activity string name for provided token. */
+    static String getActivityName(IBinder token, ClientTransactionHandler transactionHandler) {
+        final Activity activity = getActivityForToken(token, transactionHandler);
+        if (activity != null) {
+            return activity.getComponentName().getClassName();
+        }
+        return "Not found for token: " + token;
+    }
+
+    /** Get short activity class name for provided token. */
+    static String getShortActivityName(IBinder token, ClientTransactionHandler transactionHandler) {
+        final Activity activity = getActivityForToken(token, transactionHandler);
+        if (activity != null) {
+            return activity.getComponentName().getShortClassName();
+        }
+        return "Not found for token: " + token;
+    }
+
+    private static Activity getActivityForToken(IBinder token,
+            ClientTransactionHandler transactionHandler) {
+        if (token == null) {
+            return null;
+        }
+        return transactionHandler.getActivity(token);
+    }
+
+    /** Get lifecycle state string name. */
+    static String getStateName(int state) {
+        switch (state) {
+            case UNDEFINED:
+                return "UNDEFINED";
+            case PRE_ON_CREATE:
+                return "PRE_ON_CREATE";
+            case ON_CREATE:
+                return "ON_CREATE";
+            case ON_START:
+                return "ON_START";
+            case ON_RESUME:
+                return "ON_RESUME";
+            case ON_PAUSE:
+                return "ON_PAUSE";
+            case ON_STOP:
+                return "ON_STOP";
+            case ON_DESTROY:
+                return "ON_DESTROY";
+            case ON_RESTART:
+                return "ON_RESTART";
+            default:
+                throw new IllegalArgumentException("Unexpected lifecycle state: " + state);
+        }
+    }
 }
diff --git a/core/tests/coretests/src/android/app/servertransaction/TransactionExecutorTests.java b/core/tests/coretests/src/android/app/servertransaction/TransactionExecutorTests.java
index 3d114f4b7c6c..a788a938357f 100644
--- a/core/tests/coretests/src/android/app/servertransaction/TransactionExecutorTests.java
+++ b/core/tests/coretests/src/android/app/servertransaction/TransactionExecutorTests.java
@@ -283,12 +283,12 @@ public class TransactionExecutorTests {
         // Verify resolution that should get to onPause
         mClientRecord.setState(ON_RESUME);
         mExecutor.executeCallbacks(transaction);
-        verify(mExecutor, times(1)).cycleToPath(eq(mClientRecord), eq(ON_PAUSE));
+        verify(mExecutor, times(1)).cycleToPath(eq(mClientRecord), eq(ON_PAUSE), eq(transaction));
 
         // Verify resolution that should get to onStart
         mClientRecord.setState(ON_STOP);
         mExecutor.executeCallbacks(transaction);
-        verify(mExecutor, times(1)).cycleToPath(eq(mClientRecord), eq(ON_START));
+        verify(mExecutor, times(1)).cycleToPath(eq(mClientRecord), eq(ON_START), eq(transaction));
     }
 
     @Test