今天发现一个初始设置错误可能导致的CTS问题，进行下记录
问题初探
测试命令： run cts -m CtsServicesHostTestCases -t android.server.cts.ActivityManagerDockedStackTests#testDockedStackToMinimizeWhenUnlocked
在host log中报错如下:
|
1 2 3 4 5 6 7 |
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，如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 |
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中打出调用栈
|
1 2 3 4 5 6 7 8 |
private void notifyDockedStackMinimizedChanged(boolean minimizedDock, boolean animate, boolean isHomeStackResizable){ RuntimeException e1 = new RuntimeException(); e1.fillInStackTrace(); e1.printStackTrace(); ... } |
然后重新打包复现，可以发现如下log:
手机灭屏时关键log:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 |
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 |
可以看到，这里会进行最小化的操作，也就是说到灭屏前是完全没问题的，那么我们将重点放在灭屏后
然后对比正常日志，
|
1 2 3 4 5 |
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) |
异常日志：
|
1 2 3 4 5 6 7 8 |
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，就可以看出原因：
首先，亮屏后(执行菜单键)，可以看到提前最小化的栈在
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 |
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操作导致的最小化，在往前看看，找到原因了
|
1 2 3 |
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 |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
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
|
1 2 3 4 5 6 7 |
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，维护没有正确设置可能造成的问题，防止这种情况再次发生，做无用的分析