Add more logging to Activity Lifecycler.

This changelist introduces temporary logging targeting an issue
where lifecycle transactions are executing for non-existent client
records. Additional details are retained and exposed in this case
to help better understand what is happening.

Bug: 71506345
Test: manual
Change-Id: Ibfdbbd5ef0c465294709383405403aa0d3508ecb

diff --git a/core/java/android/app/ActivityThread.java b/core/java/android/app/ActivityThread.java
index 70c383b..78d6e0a 100644 (file)
--- a/core/java/android/app/ActivityThread.java
+++ b/core/java/android/app/ActivityThread.java
@@ -166,6 +166,7 @@ import java.lang.reflect.Field;
 import java.lang.reflect.Method;
 import java.net.InetAddress;
 import java.text.DateFormat;
+import java.util.ArrayDeque;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
@@ -220,6 +221,9 @@ public final class ActivityThread extends ClientTransactionHandler {
     // Whether to invoke an activity callback after delivering new configuration.
     private static final boolean REPORT_TO_ACTIVITY = true;
 
+    // Maximum number of recent tokens to maintain for debugging purposes
+    private static final int MAX_RECENT_TOKENS = 10;
+
     /**
      * Denotes an invalid sequence number corresponding to a process state change.
      */
@@ -252,6 +256,8 @@ public final class ActivityThread extends ClientTransactionHandler {
     final H mH = new H();
     final Executor mExecutor = new HandlerExecutor(mH);
     final ArrayMap<IBinder, ActivityClientRecord> mActivities = new ArrayMap<>();
+    final ArrayDeque<Integer> mRecentTokens = new ArrayDeque<>();
+
     // List of new activities (via ActivityRecord.nextIdle) that should
     // be reported when next we idle.
     ActivityClientRecord mNewActivities = null;
@@ -2168,6 +2174,18 @@ public final class ActivityThread extends ClientTransactionHandler {
         pw.println(String.format(format, objs));
     }
 
+    @Override
+    public void dump(PrintWriter pw, String prefix) {
+        pw.println(prefix + "mActivities:");
+
+        for (ArrayMap.Entry<IBinder, ActivityClientRecord> entry : mActivities.entrySet()) {
+            pw.println(prefix + "  [token:" + entry.getKey().hashCode() + " record:"
+                    + entry.getValue().toString() + "]");
+        }
+
+        pw.println(prefix + "mRecentTokens:" + mRecentTokens);
+    }
+
     public static void dumpMemInfoTable(PrintWriter pw, Debug.MemoryInfo memInfo, boolean checkin,
             boolean dumpFullInfo, boolean dumpDalvik, boolean dumpSummaryOnly,
             int pid, String processName,
@@ -2852,6 +2870,11 @@ public final class ActivityThread extends ClientTransactionHandler {
             r.setState(ON_CREATE);
 
             mActivities.put(r.token, r);
+            mRecentTokens.push(r.token.hashCode());
+
+            if (mRecentTokens.size() > MAX_RECENT_TOKENS) {
+                mRecentTokens.removeLast();
+            }
 
         } catch (SuperNotCalledException e) {
             throw e;

diff --git a/core/java/android/app/ClientTransactionHandler.java b/core/java/android/app/ClientTransactionHandler.java
index 45c0e0c..0f66652 100644 (file)
--- a/core/java/android/app/ClientTransactionHandler.java
+++ b/core/java/android/app/ClientTransactionHandler.java
@@ -24,6 +24,7 @@ import android.os.IBinder;
 
 import com.android.internal.content.ReferrerIntent;
 
+import java.io.PrintWriter;
 import java.util.List;
 
 /**
@@ -121,4 +122,11 @@ public abstract class ClientTransactionHandler {
      * provided token.
      */
     public abstract ActivityThread.ActivityClientRecord getActivityClient(IBinder token);
+
+    /**
+     * Debugging output.
+     * @param pw {@link PrintWriter} to write logs to.
+     * @param prefix Prefix to prepend to output.
+     */
+    public abstract void dump(PrintWriter pw, String prefix);
 }

diff --git a/core/java/android/app/servertransaction/ActivityLifecycleItem.java b/core/java/android/app/servertransaction/ActivityLifecycleItem.java
index 0fdc7c5..9a50a00 100644 (file)
--- a/core/java/android/app/servertransaction/ActivityLifecycleItem.java
+++ b/core/java/android/app/servertransaction/ActivityLifecycleItem.java
@@ -17,7 +17,9 @@
 package android.app.servertransaction;
 
 import android.annotation.IntDef;
+import android.os.Parcel;
 
+import java.io.PrintWriter;
 import java.lang.annotation.Retention;
 import java.lang.annotation.RetentionPolicy;
 
@@ -26,6 +28,7 @@ import java.lang.annotation.RetentionPolicy;
  * @hide
  */
 public abstract class ActivityLifecycleItem extends ClientTransactionItem {
+    private String mDescription;
 
     @IntDef(prefix = { "UNDEFINED", "PRE_", "ON_" }, value = {
             UNDEFINED,
@@ -53,4 +56,39 @@ public abstract class ActivityLifecycleItem extends ClientTransactionItem {
     /** A final lifecycle state that an activity should reach. */
     @LifecycleState
     public abstract int getTargetState();
+
+
+    protected ActivityLifecycleItem() {
+    }
+
+    protected ActivityLifecycleItem(Parcel in) {
+        mDescription = in.readString();
+    }
+
+    @Override
+    public void writeToParcel(Parcel dest, int flags) {
+        dest.writeString(mDescription);
+    }
+
+    /**
+     * Sets a description that can be retrieved later for debugging purposes.
+     * @param description Description to set.
+     * @return The {@link ActivityLifecycleItem}.
+     */
+    public ActivityLifecycleItem setDescription(String description) {
+        mDescription = description;
+        return this;
+    }
+
+    /**
+     * Retrieves description if set through {@link #setDescription(String)}.
+     */
+    public String getDescription() {
+        return mDescription;
+    }
+
+    void dump(PrintWriter pw, String prefix) {
+        pw.println(prefix + "target state:" + getTargetState());
+        pw.println(prefix + "description: " + mDescription);
+    }
 }

diff --git a/core/java/android/app/servertransaction/ClientTransaction.java b/core/java/android/app/servertransaction/ClientTransaction.java
index 08ad2f0..fc07879 100644 (file)
--- 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;
@@ -237,4 +238,12 @@ public class ClientTransaction implements Parcelable, ObjectPoolItem {
         result = 31 * result + Objects.hashCode(mLifecycleStateRequest);
         return result;
     }
+
+    void dump(PrintWriter pw, String prefix) {
+        pw.println(prefix + "mActivityToken:" + mActivityToken.hashCode());
+        pw.println(prefix + "mLifecycleStateRequest:");
+        if (mLifecycleStateRequest != null) {
+            mLifecycleStateRequest.dump(pw, prefix + "  ");
+        }
+    }
 }

diff --git a/core/java/android/app/servertransaction/DestroyActivityItem.java b/core/java/android/app/servertransaction/DestroyActivityItem.java
index 83da5f3..cbcf6c7 100644 (file)
--- a/core/java/android/app/servertransaction/DestroyActivityItem.java
+++ b/core/java/android/app/servertransaction/DestroyActivityItem.java
@@ -76,12 +76,14 @@ public class DestroyActivityItem extends ActivityLifecycleItem {
     /** Write to Parcel. */
     @Override
     public void writeToParcel(Parcel dest, int flags) {
+        super.writeToParcel(dest, flags);
         dest.writeBoolean(mFinished);
         dest.writeInt(mConfigChanges);
     }
 
     /** Read from Parcel. */
     private DestroyActivityItem(Parcel in) {
+        super(in);
         mFinished = in.readBoolean();
         mConfigChanges = in.readInt();
     }

diff --git a/core/java/android/app/servertransaction/PauseActivityItem.java b/core/java/android/app/servertransaction/PauseActivityItem.java
index 880fef7..70a4755 100644 (file)
--- a/core/java/android/app/servertransaction/PauseActivityItem.java
+++ b/core/java/android/app/servertransaction/PauseActivityItem.java
@@ -114,6 +114,7 @@ public class PauseActivityItem extends ActivityLifecycleItem {
     /** Write to Parcel. */
     @Override
     public void writeToParcel(Parcel dest, int flags) {
+        super.writeToParcel(dest, flags);
         dest.writeBoolean(mFinished);
         dest.writeBoolean(mUserLeaving);
         dest.writeInt(mConfigChanges);
@@ -122,6 +123,7 @@ public class PauseActivityItem extends ActivityLifecycleItem {
 
     /** Read from Parcel. */
     private PauseActivityItem(Parcel in) {
+        super(in);
         mFinished = in.readBoolean();
         mUserLeaving = in.readBoolean();
         mConfigChanges = in.readInt();

diff --git a/core/java/android/app/servertransaction/ResumeActivityItem.java b/core/java/android/app/servertransaction/ResumeActivityItem.java
index 9249c6e..ed90f2c 100644 (file)
--- a/core/java/android/app/servertransaction/ResumeActivityItem.java
+++ b/core/java/android/app/servertransaction/ResumeActivityItem.java
@@ -113,6 +113,7 @@ public class ResumeActivityItem extends ActivityLifecycleItem {
     /** Write to Parcel. */
     @Override
     public void writeToParcel(Parcel dest, int flags) {
+        super.writeToParcel(dest, flags);
         dest.writeInt(mProcState);
         dest.writeBoolean(mUpdateProcState);
         dest.writeBoolean(mIsForward);
@@ -120,6 +121,7 @@ public class ResumeActivityItem extends ActivityLifecycleItem {
 
     /** Read from Parcel. */
     private ResumeActivityItem(Parcel in) {
+        super(in);
         mProcState = in.readInt();
         mUpdateProcState = in.readBoolean();
         mIsForward = in.readBoolean();

diff --git a/core/java/android/app/servertransaction/StopActivityItem.java b/core/java/android/app/servertransaction/StopActivityItem.java
index 5c5c304..b814d1a 100644 (file)
--- a/core/java/android/app/servertransaction/StopActivityItem.java
+++ b/core/java/android/app/servertransaction/StopActivityItem.java
@@ -83,12 +83,14 @@ public class StopActivityItem extends ActivityLifecycleItem {
     /** Write to Parcel. */
     @Override
     public void writeToParcel(Parcel dest, int flags) {
+        super.writeToParcel(dest, flags);
         dest.writeBoolean(mShowWindow);
         dest.writeInt(mConfigChanges);
     }
 
     /** Read from Parcel. */
     private StopActivityItem(Parcel in) {
+        super(in);
         mShowWindow = in.readBoolean();
         mConfigChanges = in.readInt();
     }

diff --git a/core/java/android/app/servertransaction/TransactionExecutor.java b/core/java/android/app/servertransaction/TransactionExecutor.java
index 5b0ea6b..78b393a 100644 (file)
--- a/core/java/android/app/servertransaction/TransactionExecutor.java
+++ b/core/java/android/app/servertransaction/TransactionExecutor.java
@@ -33,6 +33,8 @@ import android.util.Slog;
 
 import com.android.internal.annotations.VisibleForTesting;
 
+import java.io.PrintWriter;
+import java.io.StringWriter;
 import java.util.List;
 
 /**
@@ -122,6 +124,21 @@ public class TransactionExecutor {
         final IBinder token = transaction.getActivityToken();
         final ActivityClientRecord r = mTransactionHandler.getActivityClient(token);
 
+        // TODO(b/71506345): Remove once root cause is found.
+        if (r == null) {
+            final StringWriter stringWriter = new StringWriter();
+            final PrintWriter pw = new PrintWriter(stringWriter);
+            final String prefix = "  ";
+
+            pw.println("Lifecycle transaction does not have valid ActivityClientRecord.");
+            pw.println("Transaction:");
+            transaction.dump(pw, prefix);
+            pw.println("Executor:");
+            dump(pw, prefix);
+
+            Slog.wtf(TAG, stringWriter.toString());
+        }
+
         // Cycle to the state right before the final requested state.
         cycleToPath(r, lifecycleItem.getTargetState(), true /* excludeLastState */);
 
@@ -245,4 +262,9 @@ public class TransactionExecutor {
     private static void log(String message) {
         if (DEBUG_RESOLVER) Slog.d(TAG, message);
     }
+
+    private void dump(PrintWriter pw, String prefix) {
+        pw.println(prefix + "mTransactionHandler:");
+        mTransactionHandler.dump(pw, prefix + "  ");
+    }
 }

diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java
index b5fbee6..b58d0af 100644 (file)
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -372,6 +372,10 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo
         }
     }
 
+    String getLifecycleDescription(String reason) {
+        return "packageName=" + packageName + ", state=" + state + ", reason=" + reason;
+    }
+
     void dump(PrintWriter pw, String prefix) {
         final long now = SystemClock.uptimeMillis();
         pw.print(prefix); pw.print("packageName="); pw.print(packageName);
@@ -1611,12 +1615,16 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo
 
             // If the activity is stopped or stopping, cycle to the paused state.
             if (state == STOPPED || state == STOPPING) {
+                // Capture reason before state change
+                final String reason = getLifecycleDescription("makeVisibleIfNeeded");
+
                 // An activity must be in the {@link PAUSING} state for the system to validate
                 // the move to {@link PAUSED}.
                 state = PAUSING;
                 service.mLifecycleManager.scheduleTransaction(app.thread, appToken,
                         PauseActivityItem.obtain(finishing, false /* userLeaving */,
-                                configChangeFlags, false /* dontReport */));
+                                configChangeFlags, false /* dontReport */)
+                                .setDescription(reason));
             }
         } catch (Exception e) {
             // Just skip on any failure; we'll make it visible when it next restarts.

diff --git a/services/core/java/com/android/server/am/ActivityStack.java b/services/core/java/com/android/server/am/ActivityStack.java
index a343965..dbe5b6f 100644 (file)
--- a/services/core/java/com/android/server/am/ActivityStack.java
+++ b/services/core/java/com/android/server/am/ActivityStack.java
@@ -2639,7 +2639,9 @@ class ActivityStack<T extends StackWindowController> extends ConfigurationContai
                     next.clearOptionsLocked();
                     mService.mLifecycleManager.scheduleTransaction(next.app.thread, next.appToken,
                             ResumeActivityItem.obtain(next.app.repProcState,
-                                    mService.isNextTransitionForward()));
+                                    mService.isNextTransitionForward())
+                                    .setDescription(next.getLifecycleDescription(
+                                            "resumeTopActivityInnerLocked")));
 
                     if (DEBUG_STATES) Slog.d(TAG_STATES, "resumeTopActivityLocked: Resumed "
                             + next);
@@ -3419,7 +3421,8 @@ class ActivityStack<T extends StackWindowController> extends ConfigurationContai
                 EventLogTags.writeAmStopActivity(
                         r.userId, System.identityHashCode(r), r.shortComponentName);
                 mService.mLifecycleManager.scheduleTransaction(r.app.thread, r.appToken,
-                        StopActivityItem.obtain(r.visible, r.configChangeFlags));
+                        StopActivityItem.obtain(r.visible, r.configChangeFlags)
+                                .setDescription(r.getLifecycleDescription("stopActivityLocked")));
                 if (shouldSleepOrShutDownActivities()) {
                     r.setSleeping(true);
                 }
@@ -4225,7 +4228,8 @@ class ActivityStack<T extends StackWindowController> extends ConfigurationContai
             try {
                 if (DEBUG_SWITCH) Slog.i(TAG_SWITCH, "Destroying: " + r);
                 mService.mLifecycleManager.scheduleTransaction(r.app.thread, r.appToken,
-                        DestroyActivityItem.obtain(r.finishing, r.configChangeFlags));
+                        DestroyActivityItem.obtain(r.finishing, r.configChangeFlags)
+                            .setDescription(r.getLifecycleDescription("destroyActivityLocked")));
             } catch (Exception e) {
                 // We can just ignore exceptions here...  if the process
                 // has crashed, our death notification will clean things

diff --git a/services/core/java/com/android/server/am/ActivityStackSupervisor.java b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
index b567303..822ad67 100644 (file)
--- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java
+++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
@@ -1422,7 +1422,8 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D
                 // Set desired final state.
                 final ActivityLifecycleItem lifecycleItem;
                 if (andResume) {
-                    lifecycleItem = ResumeActivityItem.obtain(mService.isNextTransitionForward());
+                    lifecycleItem = ResumeActivityItem.obtain(mService.isNextTransitionForward())
+                            .setDescription(r.getLifecycleDescription("realStartActivityLocked"));
                 } else {
                     lifecycleItem = PauseActivityItem.obtain();
                 }