Java中CTS的含义,CTS问题分析8

CTS/GTS问题分析8

今天发现一个初始设置错误可能导致的CTS问题，进行下记录

问题初探

测试命令： run cts -m CtsServicesHostTestCases -t android.server.cts.ActivityManagerDockedStackTests#testDockedStackToMinimizeWhenUnlocked

在host log中报错如下:

junit.framework.AssertionFailedError

at junit.framework.Assert.fail(Assert.java:55)

at junit.framework.Assert.assertTrue(Assert.java:22)

at junit.framework.Assert.assertTrue(Assert.java:31)

at junit.framework.TestCase.assertTrue(TestCase.java:201)

at android.server.cts.ActivityManagerDockedStackTests.assertDockMinimized(ActivityManagerDockedStackTests.java:559)

at android.server.cts.ActivityManagerDockedStackTests.testDockedStackToMinimizeWhenUnlocked(ActivityManagerDockedStackTests.java:438)

case的大致流程是：

启动TestActivity，将TestActivity放到stack 3，灭屏，重新点亮屏幕，观察当前window状态 (dumpsys window -a ) ，若mMinimizedDock = true，则case pass，否则fail

看了下bugreport中的event log，如下：

10-23 21:41:13.636 1000 1523 1523 I screen_toggled: 1

10-23 21:41:13.636 1000 1523 1523 I power_screen_broadcast_send: 1

10-23 21:41:13.637 1000 1523 1629 I am_set_resumed_activity: [0,android.server.cts/.TestActivity,resumeTopActivityInnerLocked]

10-23 21:41:13.640 1000 1523 1629 I am_resume_activity: [9521,113644122,55,android.server.cts/.TestActivity]

10-23 21:41:13.678 10157 9521 9521 I am_on_resume_called: [0,android.server.cts.TestActivity,RESUME_ACTIVITY]

10-23 21:41:13.682 1000 1523 1611 I am_pss : [6167,10012,com.android.defcontainer,4247552,3424256,0]

10-23 21:41:13.714 1000 1523 1523 I power_screen_broadcast_done: [1,78,1]

10-23 21:41:13.825 1000 1523 1629 I sysui_multi_action: [757,198,758,1,759,0,793,205]

10-23 21:41:13.825 1000 1523 1629 I power_screen_state: [1,0,0,0,205]

10-23 21:41:14.319 1000 1523 2988 I am_uid_stopped: 10157

10-23 21:41:14.319 1000 1523 2988 I am_kill : [0,9521,android.server.cts,0,stop android.server.cts: from process:9660]

10-23 21:41:14.321 1000 1523 2988 I am_finish_activity: [0,113644122,55,android.server.cts/.TestActivity,proc died without state saved]

重新亮屏时并没有发现异常的event log，说明就是mMinimizedDock这个值为false导致的错误，先转给分屏看了下，发现关闭Skip Screen lock测试即可通过；因此分屏没有继续看下去，但是这其实是不符合正常的CTS测试设置的，因此还是有继续调研的必要。

问题分析

发现mMinimizedDock这个值可以等价于DividerView的mDockedStackMinimized属性，DividerView是分屏时中间的分割符，这样就可以将问题定位到DividerView的变化，其是由DockedStackDividerController控制的；因此，我们在其中的notifyDockedStackMinimizedChanged中打出调用栈

private void notifyDockedStackMinimizedChanged(boolean minimizedDock, boolean animate,

boolean isHomeStackResizable) {

RuntimeException e1 = new RuntimeException();

e1.fillInStackTrace();

e1.printStackTrace();

...

}

然后重新打包复现，可以发现如下log:

手机灭屏时关键log:

10-25 14:17:34.328 1605 2091 W BaseMiuiPhoneWindowManager: keyCode:26 down:true eventTime:12643277 downTime:12643277 policyFlags:22000000 flags:8 deviceId:5 isScreenOn:true keyguardActive:false repeatCount:0

10-25 14:17:34.434 1605 2091 W BaseMiuiPhoneWindowManager: keyCode:26 down:false eventTime:12643384 downTime:12643277 policyFlags:22000000 flags:8 deviceId:5 isScreenOn:true keyguardActive:false repeatCount:0

10-25 14:17:34.435 1605 1605 I WindowManager: Started going to sleep... (why=2)

10-25 14:17:34.762 1605 1709 I DisplayPowerController: Blocking screen off

10-25 14:17:34.776 1605 1709 I DisplayPowerController: Unblocked screen off after 14 ms

10-25 14:17:34.777 1605 1709 I WindowManager: Screen turned off...

10-25 14:17:35.319 1605 2453 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.miui.home/.launcher.Launcher} from uid 1000

10-25 14:17:35.324 1605 2453 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{da4a56d com.miui.home} is now in focus and seems to be in full-screen mode

10-25 14:17:35.324 1605 2453 E ActivityTrigger: activityResumeTrigger: not whiteListedcom.miui.home/com.miui.home.launcher.Launcher/4063011

10-25 14:17:35.326 1605 2453 W System.err: java.lang.RuntimeException

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.DockedStackDividerController.notifyDockedStackMinimizedChanged(DockedStackDividerController.java:481)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.DockedStackDividerController.setMinimizedDockedStack(DockedStackDividerController.java:808)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.DockedStackDividerController.setMinimizedDockedStack(DockedStackDividerController.java:700)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.DockedStackDividerController.checkMinimizeChanged(DockedStackDividerController.java:665)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.DockedStackDividerController.notifyAppVisibilityChanged(DockedStackDividerController.java:580)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.AppWindowToken.setVisibility(AppWindowToken.java:457)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.wm.AppWindowContainerController.setVisibility(AppWindowContainerController.java:461)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityRecord.setVisibility(ActivityRecord.java:1780)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStack.resumeTopActivityInnerLocked(ActivityStack.java:2756)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStack.resumeTopActivityUncheckedLocked(ActivityStack.java:2350)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStackSupervisor.resumeFocusedStackTopActivityLocked(ActivityStackSupervisor.java:2190)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStackSupervisor.resumeFocusedStackTopActivityLocked(ActivityStackSupervisor.java:2151)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStack.moveTaskToFrontLocked(ActivityStack.java:4872)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStarter.setTargetStackAndMoveToFrontIfNeeded(ActivityStarter.java:1785)

10-25 14:17:35.326 1605 2453 W System.err: at com.android.server.am.ActivityStarter.startActivityUnchecked(ActivityStarter.java:1246)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityStarter.startActivity(ActivityStarter.java:1121)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityStarter.startActivity(ActivityStarter.java:630)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityStarter.startActivityLocked(ActivityStarter.java:278)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityStarter.startActivityMayWait(ActivityStarter.java:936)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityManagerService.startActivityAsUser(ActivityManagerService.java:4722)

10-25 14:17:35.327 1605 2453 W System.err: at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:2314)

10-25 14:17:35.327 1605 2453 W System.err: at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:3049)

10-25 14:17:35.327 1605 2453 W System.err: at android.os.Binder.execTransact(Binder.java:681)

10-25 14:17:35.327 2461 3254 D Divider : onDockedStackMinimizedChanged minimized=true animDuration=0

可以看到，这里会进行最小化的操作，也就是说到灭屏前是完全没问题的，那么我们将重点放在灭屏后

然后对比正常日志，

10-25 16:28:33.764 1605 2493 W ActivityManager: Force removing ActivityRecord{d37a66f u0 android.server.cts/.TestActivity t59}: app died, no saved state

10-25 16:28:33.788 2461 3254 D Divider : onDockedStackMinimizedChanged minimized=false animDuration=0

10-25 16:28:33.802 2461 3254 D Divider : onDividerVisibilityChanged visible=false

10-25 16:28:33.836 2461 2461 D EventBus: [2461, u0] -> DividerView [0x284c897, P1] onBusEvent(MultiWindowStateChangedEvent)

异常日志：

10-25 09:46:49.264 2461 4530 D Divider : onDockedStackMinimizedChanged minimized=false animDuration=250

10-25 09:46:49.934 1605 3297 W ActivityManager: Force removing ActivityRecord{c57c476 u0 android.server.cts/.TestActivity t17}: app died, no saved state

10-25 09:46:49.947 2461 2480 D Divider : onDockedStackExistsChanged exists=false

10-25 09:46:49.964 2461 2480 D Divider : onDividerVisibilityChanged visible=false

10-25 09:46:49.977 2461 2461 D EventBus: [2461, u0] -> DividerView [0x284c897, P1] onBusEvent(MultiWindowStateChangedEvent)

正常日志是将测试进程force-stop后再进行销毁工作，DividerView最小化，然后销毁；异常日志是DividerView最小化在前面执行，导致case fail；

然后我们仔细观察异常log，就可以看出原因：

首先，亮屏后(执行菜单键)，可以看到提前最小化的栈在

10-25 09:46:49.160 1605 5703 W BaseMiuiPhoneWindowManager: keyCode:82 down:true eventTime:846050 downTime:846050 policyFlags:2b000000 flags:0 deviceId:-1 isScreenOn:true keyguardActive:false repeatCount:0

10-25 09:46:49.162 14122 14122 I Input : injectKeyEvent: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_MENU, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=846050, downTime=846050, deviceId=-1, source=0x101 }

10-25 09:46:49.162 1605 5703 W BaseMiuiPhoneWindowManager: keyCode:82 down:false eventTime:846050 downTime:846050 policyFlags:2b000000 flags:0 deviceId:-1 isScreenOn:true keyguardActive:false repeatCount:0

10-25 09:46:49.182 2461 2461 D RecentsImpl: startRecentsActivity runningTask: ComponentInfo{com.miui.home/com.miui.home.launcher.Launcher}

10-25 09:46:49.262 1605 2074 W System.err: java.lang.RuntimeException

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.DockedStackDividerController.notifyDockedStackMinimizedChanged(DockedStackDividerController.java:481)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.DockedStackDividerController.animateForMinimizedDockedStack(DockedStackDividerController.java:862)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.DockedStackDividerController.animate(DockedStackDividerController.java:821)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.WindowAnimator.animate(WindowAnimator.java:250)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.WindowAnimator.lambda$-com_android_server_wm_WindowAnimator_4083(WindowAnimator.java:109)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.-$Lambda$OQfQhd_xsxt9hoLAjIbVfOwa-jY.$m$0(Unknown Source:4)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.wm.-$Lambda$OQfQhd_xsxt9hoLAjIbVfOwa-jY.doFrame(Unknown Source:0)

10-25 09:46:49.262 1605 2074 W System.err: at android.view.Choreographer$CallbackRecord.run(Choreographer.java:1024)

10-25 09:46:49.262 1605 2074 W System.err: at android.view.Choreographer.doCallbacks(Choreographer.java:838)

10-25 09:46:49.262 1605 2074 W System.err: at android.view.Choreographer.doFrame(Choreographer.java:766)

10-25 09:46:49.262 1605 2074 W System.err: at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:1012)

10-25 09:46:49.262 1605 2074 W System.err: at android.os.Handler.handleCallback(Handler.java:792)

10-25 09:46:49.262 1605 2074 W System.err: at android.os.Handler.dispatchMessage(Handler.java:98)

10-25 09:46:49.262 1605 2074 W System.err: at android.os.Looper.loop(Looper.java:176)

10-25 09:46:49.262 1605 2074 W System.err: at android.os.HandlerThread.run(HandlerThread.java:65)

10-25 09:46:49.262 1605 2074 W System.err: at com.android.server.ServiceThread.run(ServiceThread.java:46)

10-25 09:46:49.262 4260 4532 D PowerKeeper: PowerStateMachine:onDockedStackMinimizedChanged minimized=false

10-25 09:46:49.262 4260 4356 D PowerKeeper: PowerStateMachine:EVENT_ID_MULTI_SCREEN_MINIMIZED mIsMultiScreenMinimized=false

10-25 09:46:49.264 2461 4530 D Divider : onDockedStackMinimizedChanged minimized=false animDuration=250

是执行DockedStackDividerController.animate操作导致的最小化，在往前看看，找到原因了

10-25 09:46:49.215 2461 2461 D EventBus: [2461, u0] -> DividerView [0x284c897, P1] onBusEvent(RecentsActivityStartingEvent)

10-25 09:46:49.215 2461 2461 D EventBus: [2461, u0] onBusEvent(RecentsActivityStartingEvent) duration: 131 microseconds, avg: 71

10-25 09:46:49.215 1605 2091 I InputReader: Reconfiguring input devices. changes=0x00000004

1144 public final void onBusEvent(RecentsDrawnEvent drawnEvent) {

1145 if (mState.animateAfterRecentsDrawn) {

1146 mState.animateAfterRecentsDrawn = false;

1147 updateDockSide();

1148

1149 mHandler.post(() -> {

1150 // Delay switching resizing mode because this might cause jank in recents animation

1151 // that's longer than this animation.

1152 stopDragging(getCurrentPosition(), mSnapAlgorithm.getMiddleTarget(),

1153 mLongPressEntraceAnimDuration, Interpolators.FAST_OUT_SLOW_IN,

1154 200 /* endDelay */);

1155 });

1156 }

1157 if (mState.growAfterRecentsDrawn) {

1158 mState.growAfterRecentsDrawn = false;

1159 updateDockSide();

1160 EventBus.getDefault().send(new RecentsGrowingEvent());

1161 stopDragging(getCurrentPosition(), mSnapAlgorithm.getMiddleTarget(), 336,

1162 Interpolators.FAST_OUT_SLOW_IN);

1163 }

1164 }

10-25 09:46:49.258 2461 2461 D EventBus: [2461, u0] -> DividerView [0x284c897, P1] onBusEvent(RecentsDrawnEvent)

10-25 09:46:49.259 2461 2461 D EventBus: [2461, u0] onBusEvent(RecentsDrawnEvent) duration: 8 microseconds, avg: 68

407 public void stopDragging(int position, float velocity, boolean avoidDismissStart,

408 boolean logMetrics) {

409 mHandle.setTouching(false, true /* animate */);

410 fling(position, velocity, avoidDismissStart, logMetrics);

411 mWindowManager.setSlippery(true);

412 releaseBackground();

413 }

可以很明显的看到，DividerView会执行一个滑动操作，那么应该会执行到animate，将状态从最小化状态还原。而我们MIUI默认将menu菜单键的功能设置为最近任务功能，怀疑是没有设置正确导致的问题

那么我们可以将Skip Screen lock开关打开来测试了，将菜单键置为本来功能，发现case果然pass；这里我们也可以看到为什么Skip Screen lock开关关闭也能过了，因为一直没有解锁，导致DividerView没有走后面的还原过程，虽然case也是pass的，但是这其实不符合case本身的用意

问题总结

问题本身不难，但是这样无用的分析是浪费资源的

1.再次强调，让所有测试都明确测试配置

2.建议维护一个wiki，维护没有正确设置可能造成的问题，防止这种情况再次发生，做无用的分析