Improve transition logging

This passes a "debug" id along with transitioninfo
so that we can correspond transitions across processes.

Also adds debug-names to remotes so that they can
be identified across processes as well.

Bug: 276349701
Test: just added logs, so no tests needed.
Change-Id: If67524f8a82de366db2f96c8821b08eaec45ecb5

7 files changed, 54 insertions, 34 deletions

diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/DefaultMixedHandler.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/DefaultMixedHandler.java
index 586cab07c508..17732d2c75d3 100644
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/DefaultMixedHandler.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/DefaultMixedHandler.java
@@ -234,6 +234,7 @@ public class DefaultMixedHandler implements Transitions.TransitionHandler,
     private TransitionInfo subCopy(@NonNull TransitionInfo info,
             @WindowManager.TransitionType int newType, boolean withChanges) {
         final TransitionInfo out = new TransitionInfo(newType, withChanges ? info.getFlags() : 0);
+        out.setDebugId(info.getDebugId());
         if (withChanges) {
             for (int i = 0; i < info.getChanges().size(); ++i) {
                 out.getChanges().add(info.getChanges().get(i));
diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/OneShotRemoteHandler.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/OneShotRemoteHandler.java
index 485b400f458d..4e3d220f1ea2 100644
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/OneShotRemoteHandler.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/OneShotRemoteHandler.java
@@ -63,7 +63,7 @@ public class OneShotRemoteHandler implements Transitions.TransitionHandler {
             @NonNull Transitions.TransitionFinishCallback finishCallback) {
         if (mTransition != transition) return false;
         ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Using registered One-shot remote"
-                + " transition %s for %s.", mRemote, transition);
+                + " transition %s for #%d.", mRemote, info.getDebugId());
 
         final IBinder.DeathRecipient remoteDied = () -> {
             Log.e(Transitions.TAG, "Remote transition died, finishing");
@@ -113,9 +113,6 @@ public class OneShotRemoteHandler implements Transitions.TransitionHandler {
     public void mergeAnimation(@NonNull IBinder transition, @NonNull TransitionInfo info,
             @NonNull SurfaceControl.Transaction t, @NonNull IBinder mergeTarget,
             @NonNull Transitions.TransitionFinishCallback finishCallback) {
-        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Using registered One-shot remote"
-                + " transition %s for %s.", mRemote, transition);
-
         IRemoteTransitionFinishedCallback cb = new IRemoteTransitionFinishedCallback.Stub() {
             @Override
             public void onTransitionFinished(WindowContainerTransaction wct,
@@ -154,4 +151,10 @@ public class OneShotRemoteHandler implements Transitions.TransitionHandler {
                 + " for %s: %s", transition, remote);
         return new WindowContainerTransaction();
     }
+
+    @Override
+    public String toString() {
+        return "OneShotRemoteHandler:" + mRemote.getDebugName() + ":"
+                + mRemote.getRemoteTransition();
+    }
 }
diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/RemoteTransitionHandler.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/RemoteTransitionHandler.java
index 3c4e8898f215..5b7231c5a5fb 100644
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/RemoteTransitionHandler.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/RemoteTransitionHandler.java
@@ -101,8 +101,8 @@ public class RemoteTransitionHandler implements Transitions.TransitionHandler {
         }
         RemoteTransition pendingRemote = mRequestedRemotes.get(transition);
         if (pendingRemote == null) {
-            ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition %s doesn't have "
-                    + "explicit remote, search filters for match for %s", transition, info);
+            ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition doesn't have "
+                    + "explicit remote, search filters for match for %s", info);
             // If no explicit remote, search filters until one matches
             for (int i = mFilters.size() - 1; i >= 0; --i) {
                 ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, " Checking filter %s",
@@ -116,8 +116,8 @@ public class RemoteTransitionHandler implements Transitions.TransitionHandler {
                 }
             }
         }
-        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, " Delegate animation for %s to %s",
-                transition, pendingRemote);
+        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, " Delegate animation for #%d to %s",
+                info.getDebugId(), pendingRemote);
 
         if (pendingRemote == null) return false;
 
@@ -184,9 +184,10 @@ public class RemoteTransitionHandler implements Transitions.TransitionHandler {
     public void mergeAnimation(@NonNull IBinder transition, @NonNull TransitionInfo info,
             @NonNull SurfaceControl.Transaction t, @NonNull IBinder mergeTarget,
             @NonNull Transitions.TransitionFinishCallback finishCallback) {
-        final IRemoteTransition remote = mRequestedRemotes.get(mergeTarget).getRemoteTransition();
-        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, " Attempt merge %s into %s",
-                transition, remote);
+        final RemoteTransition remoteTransition = mRequestedRemotes.get(mergeTarget);
+        final IRemoteTransition remote = remoteTransition.getRemoteTransition();
+        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "   Merge into remote: %s",
+                remoteTransition);
         if (remote == null) return;
 
         IRemoteTransitionFinishedCallback cb = new IRemoteTransitionFinishedCallback.Stub() {
diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/SleepHandler.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/SleepHandler.java
index 0386ec38a3ff..1879bf721fed 100644
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/SleepHandler.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/SleepHandler.java
@@ -19,7 +19,6 @@ package com.android.wm.shell.transition;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
 import android.os.IBinder;
-import android.util.Log;
 import android.view.SurfaceControl;
 import android.window.TransitionInfo;
 import android.window.TransitionRequestInfo;
@@ -59,7 +58,6 @@ class SleepHandler implements Transitions.TransitionHandler {
     @Override
     public void onTransitionConsumed(@NonNull IBinder transition, boolean aborted,
             @Nullable SurfaceControl.Transaction finishTransaction) {
-        Log.e(Transitions.TAG, "Sleep transition was consumed. This doesn't make sense");
         mSleepTransitions.remove(transition);
     }
 }
diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java
index beabf1842f8d..d1f7d42be8db 100644
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java
@@ -182,6 +182,14 @@ public class Transitions implements RemoteCallable<Transitions> {
 
         /** Ordered list of transitions which have been merged into this one. */
         private ArrayList<ActiveTransition> mMerged;
+
+        @Override
+        public String toString() {
+            if (mInfo != null && mInfo.getDebugId() >= 0) {
+                return "(#" + mInfo.getDebugId() + ")" + mToken;
+            }
+            return mToken.toString();
+        }
     }
 
     /** Keeps track of transitions which have been started, but aren't ready yet. */
@@ -525,8 +533,8 @@ public class Transitions implements RemoteCallable<Transitions> {
                             activeTransition -> activeTransition.mToken).toArray()));
         }
         if (activeIdx > 0) {
-            Log.e(TAG, "Transition became ready out-of-order " + transitionToken + ". Expected"
-                    + " order: " + Arrays.toString(mPendingTransitions.stream().map(
+            Log.e(TAG, "Transition became ready out-of-order " + mPendingTransitions.get(activeIdx)
+                    + ". Expected order: " + Arrays.toString(mPendingTransitions.stream().map(
                             activeTransition -> activeTransition.mToken).toArray()));
         }
         // Move from pending to ready
@@ -543,6 +551,7 @@ public class Transitions implements RemoteCallable<Transitions> {
         if (info.getType() == TRANSIT_SLEEP) {
             if (activeIdx > 0 || !mActiveTransitions.isEmpty() || mReadyTransitions.size() > 1) {
                 // Sleep starts a process of forcing all prior transitions to finish immediately
+                ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Start finish-for-sleep");
                 finishForSleep(null /* forceFinish */);
                 return;
             }
@@ -551,8 +560,8 @@ public class Transitions implements RemoteCallable<Transitions> {
         if (info.getRootCount() == 0 && !alwaysReportToKeyguard(info)) {
             // No root-leashes implies that the transition is empty/no-op, so just do
             // housekeeping and return.
-            ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "No transition roots (%s): %s",
-                    transitionToken, info);
+            ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "No transition roots in %s so"
+                    + " abort", active);
             onAbort(active);
             return;
         }
@@ -581,6 +590,8 @@ public class Transitions implements RemoteCallable<Transitions> {
                 && allOccluded)) {
             // Treat this as an abort since we are bypassing any merge logic and effectively
             // finishing immediately.
+            ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS,
+                    "Non-visible anim so abort: %s", active);
             onAbort(active);
             return;
         }
@@ -648,21 +659,21 @@ public class Transitions implements RemoteCallable<Transitions> {
             return;
         }
         ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition %s ready while"
-                + " another transition %s is still animating. Notify the animating transition"
-                + " in case they can be merged", ready.mToken, playing.mToken);
+                + " %s is still animating. Notify the animating transition"
+                + " in case they can be merged", ready, playing);
         playing.mHandler.mergeAnimation(ready.mToken, ready.mInfo, ready.mStartT,
                 playing.mToken, (wct, cb) -> onMerged(playing, ready));
     }
 
     private void onMerged(@NonNull ActiveTransition playing, @NonNull ActiveTransition merged) {
-        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition was merged %s",
-                merged.mToken);
+        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition was merged: %s into %s",
+                merged, playing);
         int readyIdx = 0;
         if (mReadyTransitions.isEmpty() || mReadyTransitions.get(0) != merged) {
-            Log.e(TAG, "Merged transition out-of-order?");
+            Log.e(TAG, "Merged transition out-of-order? " + merged);
             readyIdx = mReadyTransitions.indexOf(merged);
             if (readyIdx < 0) {
-                Log.e(TAG, "Merged a transition that is no-longer queued?");
+                Log.e(TAG, "Merged a transition that is no-longer queued? " + merged);
                 return;
             }
         }
@@ -683,6 +694,7 @@ public class Transitions implements RemoteCallable<Transitions> {
     }
 
     private void playTransition(@NonNull ActiveTransition active) {
+        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Playing animation for %s", active);
         for (int i = 0; i < mObservers.size(); ++i) {
             mObservers.get(i).onTransitionStarting(active.mToken);
         }
@@ -784,12 +796,12 @@ public class Transitions implements RemoteCallable<Transitions> {
         int activeIdx = mActiveTransitions.indexOf(active);
         if (activeIdx < 0) {
             Log.e(TAG, "Trying to finish a non-running transition. Either remote crashed or "
-                    + " a handler didn't properly deal with a merge. " + active.mToken,
+                    + " a handler didn't properly deal with a merge. " + active,
                     new RuntimeException());
             return;
         } else if (activeIdx != 0) {
             // Relevant right now since we only allow 1 active transition at a time.
-            Log.e(TAG, "Finishing a transition out of order. " + active.mToken);
+            Log.e(TAG, "Finishing a transition out of order. " + active);
         }
         mActiveTransitions.remove(activeIdx);
 
@@ -797,7 +809,7 @@ public class Transitions implements RemoteCallable<Transitions> {
             mObservers.get(i).onTransitionFinished(active.mToken, active.mAborted);
         }
         ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition animation finished "
-                + "(aborted=%b), notifying core %s", active.mAborted, active.mToken);
+                + "(aborted=%b), notifying core %s", active.mAborted, active);
         if (active.mStartT != null) {
             // Applied by now, so clear immediately to remove any references. Do not set to null
             // yet, though, since nullness is used later to disambiguate malformed transitions.
@@ -913,6 +925,8 @@ public class Transitions implements RemoteCallable<Transitions> {
     /** Start a new transition directly. */
     public IBinder startTransition(@WindowManager.TransitionType int type,
             @NonNull WindowContainerTransaction wct, @Nullable TransitionHandler handler) {
+        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Directly starting a new transition "
+                + "type=%d wct=%s handler=%s", type, wct, handler);
         final ActiveTransition active = new ActiveTransition();
         active.mHandler = handler;
         active.mToken = mOrganizer.startNewTransition(type, wct);
@@ -944,8 +958,7 @@ public class Transitions implements RemoteCallable<Transitions> {
             return;
         }
         if (forceFinish != null && mActiveTransitions.contains(forceFinish)) {
-            Log.e(TAG, "Forcing transition to finish due to sleep timeout: "
-                    + forceFinish.mToken);
+            Log.e(TAG, "Forcing transition to finish due to sleep timeout: " + forceFinish);
             forceFinish.mAborted = true;
             // Last notify of it being consumed. Note: mHandler should never be null,
             // but check just to be safe.
@@ -963,6 +976,8 @@ public class Transitions implements RemoteCallable<Transitions> {
                 // Try to signal that we are sleeping by attempting to merge the sleep transition
                 // into the playing one.
                 final ActiveTransition nextSleep = mReadyTransitions.get(sleepIdx);
+                ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, " Attempt to merge SLEEP %s"
+                        + " into %s", nextSleep, playing);
                 playing.mHandler.mergeAnimation(nextSleep.mToken, nextSleep.mInfo, dummyT,
                         playing.mToken, (wct, cb) -> {});
             } else {
diff --git a/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/splitscreen/SplitTransitionTests.java b/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/splitscreen/SplitTransitionTests.java
index df78d92a90c8..1089a1e6c113 100644
--- a/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/splitscreen/SplitTransitionTests.java
+++ b/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/splitscreen/SplitTransitionTests.java
@@ -181,7 +181,7 @@ public class SplitTransitionTests extends ShellTestCase {
 
         IBinder transition = mSplitScreenTransitions.startEnterTransition(
                 TRANSIT_SPLIT_SCREEN_PAIR_OPEN, new WindowContainerTransaction(),
-                new RemoteTransition(testRemote), mStageCoordinator, null, null);
+                new RemoteTransition(testRemote, "Test"), mStageCoordinator, null, null);
         mMainStage.onTaskAppeared(mMainChild, createMockSurface());
         mSideStage.onTaskAppeared(mSideChild, createMockSurface());
         boolean accepted = mStageCoordinator.startAnimation(transition, info,
@@ -407,7 +407,8 @@ public class SplitTransitionTests extends ShellTestCase {
         TransitionInfo enterInfo = createEnterPairInfo();
         IBinder enterTransit = mSplitScreenTransitions.startEnterTransition(
                 TRANSIT_SPLIT_SCREEN_PAIR_OPEN, new WindowContainerTransaction(),
-                new RemoteTransition(new TestRemoteTransition()), mStageCoordinator, null, null);
+                new RemoteTransition(new TestRemoteTransition(), "Test"),
+                mStageCoordinator, null, null);
         mMainStage.onTaskAppeared(mMainChild, createMockSurface());
         mSideStage.onTaskAppeared(mSideChild, createMockSurface());
         mStageCoordinator.startAnimation(enterTransit, enterInfo,
diff --git a/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/transition/ShellTransitionTests.java b/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/transition/ShellTransitionTests.java
index 60d697823f64..5cd548bfe5ab 100644
--- a/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/transition/ShellTransitionTests.java
+++ b/libs/WindowManager/Shell/tests/unittest/src/com/android/wm/shell/transition/ShellTransitionTests.java
@@ -277,7 +277,7 @@ public class ShellTransitionTests extends ShellTestCase {
         IBinder transitToken = new Binder();
         transitions.requestStartTransition(transitToken,
                 new TransitionRequestInfo(TRANSIT_OPEN, null /* trigger */,
-                        new RemoteTransition(testRemote)));
+                        new RemoteTransition(testRemote, "Test")));
         verify(mOrganizer, times(1)).startTransition(eq(transitToken), any());
         TransitionInfo info = new TransitionInfoBuilder(TRANSIT_OPEN)
                 .addChange(TRANSIT_OPEN).addChange(TRANSIT_CLOSE).build();
@@ -422,7 +422,7 @@ public class ShellTransitionTests extends ShellTestCase {
                 new TransitionFilter.Requirement[]{new TransitionFilter.Requirement()};
         filter.mRequirements[0].mModes = new int[]{TRANSIT_OPEN, TRANSIT_TO_FRONT};
 
-        transitions.registerRemote(filter, new RemoteTransition(testRemote));
+        transitions.registerRemote(filter, new RemoteTransition(testRemote, "Test"));
         mMainExecutor.flushAll();
 
         IBinder transitToken = new Binder();
@@ -466,11 +466,12 @@ public class ShellTransitionTests extends ShellTestCase {
         final int transitType = TRANSIT_FIRST_CUSTOM + 1;
 
         OneShotRemoteHandler oneShot = new OneShotRemoteHandler(mMainExecutor,
-                new RemoteTransition(testRemote));
+                new RemoteTransition(testRemote, "Test"));
         // Verify that it responds to the remote but not other things.
         IBinder transitToken = new Binder();
         assertNotNull(oneShot.handleRequest(transitToken,
-                new TransitionRequestInfo(transitType, null, new RemoteTransition(testRemote))));
+                new TransitionRequestInfo(transitType, null,
+                        new RemoteTransition(testRemote, "Test"))));
         assertNull(oneShot.handleRequest(transitToken,
                 new TransitionRequestInfo(transitType, null, null)));