1.首先找到host_log_xxx.txt文件查看测试fail项堆栈,如下:
12-08 13:25:51 I/ModuleListener: [1/1] com.android.compatibility.common.tradefed.testtype.JarHostTest com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApex FAILURE: java.lang.AssertionError: on-device tests failed:
com.google.android.stagedinstall.gts.StagedInstallTest#testSamegradeSystemTzdataApex_Commit:
expected to be true
at com.google.android.stagedinstall.gts.StagedInstallTest.waitForSessionReady(StagedInstallTest.java:329)
at com.google.android.stagedinstall.gts.StagedInstallTest.stageApexAndWaitForSessionReady(StagedInstallTest.java:241)
at com.google.android.stagedinstall.gts.StagedInstallTest.testSamegradeSystemTzdataApex_Commit(StagedInstallTest.java:117)
at com.android.tradefed.testtype.junit4.BaseHostJUnit4Test.runDeviceTests(BaseHostJUnit4Test.java:669)
at com.android.tradefed.testtype.junit4.BaseHostJUnit4Test.runDeviceTests(BaseHostJUnit4Test.java:571)
at com.android.tradefed.testtype.junit4.BaseHostJUnit4Test.runDeviceTests(BaseHostJUnit4Test.java:517)
at com.android.tradefed.testtype.junit4.BaseHostJUnit4Test.runDeviceTests(BaseHostJUnit4Test.java:339)
at com.android.tradefed.testtype.junit4.BaseHostJUnit4Test.runDeviceTests(BaseHostJUnit4Test.java:295)
at com.google.android.stagedinstall.gts.host.StagedInstallTest.runPhase(StagedInstallTest.java:61)
at com.google.android.stagedinstall.gts.host.StagedInstallTest.testSamegradeSystemTzdataApex(StagedInstallTest.java:96)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:52)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at com.android.tradefed.testtype.DeviceJUnit4ClassRunner.runChild(DeviceJUnit4ClassRunner.java:108)
at com.android.tradefed.testtype.DeviceJUnit4ClassRunner.runChild(DeviceJUnit4ClassRunner.java:60)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at com.android.tradefed.testtype.DeviceJUnit4ClassRunner.run(DeviceJUnit4ClassRunner.java:144)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.android.tradefed.testtype.HostTest.runJUnit4Tests(HostTest.java:704)
at com.android.tradefed.testtype.HostTest.runTestClasses(HostTest.java:600)
at com.android.tradefed.testtype.HostTest.run(HostTest.java:545)
at com.android.compatibility.common.tradefed.testtype.JarHostTest.run(JarHostTest.java:55)
at com.android.tradefed.testtype.suite.GranularRetriableTestWrapper.intraModuleRun(GranularRetriableTestWrapper.java:286)
at com.android.tradefed.testtype.suite.GranularRetriableTestWrapper.run(GranularRetriableTestWrapper.java:216)
at com.android.tradefed.testtype.suite.ModuleDefinition.run(ModuleDefinition.java:471)
at com.android.tradefed.testtype.suite.ITestSuite.runSingleModule(ITestSuite.java:788)
at com.android.tradefed.testtype.suite.ITestSuite.run(ITestSuite.java:675)
at com.android.tradefed.invoker.InvocationExecution.runTest(InvocationExecution.java:739)
at com.android.tradefed.invoker.InvocationExecution.runTests(InvocationExecution.java:595)
at com.android.tradefed.invoker.TestInvocation.prepareAndRun(TestInvocation.java:445)
at com.android.tradefed.invoker.TestInvocation.performInvocation(TestInvocation.java:237)
at com.android.tradefed.invoker.TestInvocation.invoke(TestInvocation.java:940)
at com.android.tradefed.command.CommandScheduler$InvocationThread.run(CommandScheduler.java:607)
如上堆栈来看,在waitForSessionReady的时候发生异常,怀疑与Session有关;继续分析logcat。
2.为了准确定位到异常相关logcat的时间点,则从host_log_xxxxxx.txt中查找时间点,搜索PrettyTestEventLogger来确认测试的时间区间,如下:
对应的实际log如下:
12-08 13:25:47 D/PrettyTestEventLogger:
==================== com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApex STARTED: Tue Dec 08 13:25:47 CST 2020 ====================
......
12-08 13:25:51 I/TestFailureListener: FailureListener.testFailed com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApex false
12-08 13:25:51 D/PrettyTestEventLogger:
==================== com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApex ENDED: Tue Dec 08 13:25:51 CST 2020 ====================
12-08 13:25:51 I/ModuleListener: [1/1] com.android.compatibility.common.tradefed.testtype.JarHostTest com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApex FAILURE: java.lang.AssertionError: on-device tests failed:
com.google.android.stagedinstall.gts.StagedInstallTest#testSamegradeSystemTzdataApex_Commit:
expected to be true
......
3.分析device_logcat_test_xxxxxx.txt,搜索"TestRunner"关键字;
Line 540: 12-08 13:25:49.608 27229 27253 I TestRunner: run started: 1 tests
Line 541: 12-08 13:25:49.610 27229 27253 I TestRunner: started: testSamegradeSystemTzdataApex_Commit(com.google.android.stagedinstall.gts.StagedInstallTest)
Line 581: 12-08 13:25:50.343 27229 27253 E TestRunner: failed: testSamegradeSystemTzdataApex_Commit(com.google.android.stagedinstall.gts.StagedInstallTest)
Line 582: 12-08 13:25:50.344 27229 27253 E TestRunner: ----- begin exception -----
Line 583: 12-08 13:25:50.344 27229 27253 E TestRunner: expected to be true
Line 584: 12-08 13:25:50.344 27229 27253 E TestRunner: at com.google.android.stagedinstall.gts.StagedInstallTest.waitForSessionReady(StagedInstallTest.java:329)
Line 585: 12-08 13:25:50.344 27229 27253 E TestRunner: at com.google.android.stagedinstall.gts.StagedInstallTest.stageApexAndWaitForSessionReady(StagedInstallTest.java:241)
Line 586: 12-08 13:25:50.344 27229 27253 E TestRunner: at com.google.android.stagedinstall.gts.StagedInstallTest.testSamegradeSystemTzdataApex_Commit(StagedInstallTest.java:117)
Line 587: 12-08 13:25:50.344 27229 27253 E TestRunner: ----- end exception -----
Line 588: 12-08 13:25:50.345 27229 27253 I TestRunner: finished: testSamegradeSystemTzdataApex_Commit(com.google.android.stagedinstall.gts.StagedInstallTest)
Line 589: 12-08 13:25:50.349 27229 27253 I TestRunner: run finished: 1 tests, 1 failed, 0 ignored
4.继续分析started和failed的中间的信息,详细日志如下:
12-08 13:25:49.608 27229 27253 I TestRunner: run started: 1 tests
12-08 13:25:49.610 27229 27253 I TestRunner: started: testSamegradeSystemTzdataApex_Commit(com.google.android.stagedinstall.gts.StagedInstallTest)
12-08 13:25:49.625 1109 4266 I InputDispatcher: setInputWindows displayId=0 Window{a09e8f7 u0 ScreenDecorOverlay} Window{ec202f5 u0 NavigationBar0} Window{2d00129 u0 StatusBar} Window{8d49532 u0 com.android.settings/com.android.settings.applications.InstalledAppDetails} Window{8e8785d u0 com.android.settings/com.android.settings.applications.InstalledAppDetails} Window{6820d63 u0 com.android.systemui.ImageWallpaper}
12-08 13:25:49.642 1109 7968 I InputDispatcher: setInputWindows displayId=0 Window{a09e8f7 u0 ScreenDecorOverlay} Window{ec202f5 u0 NavigationBar0} Window{2d00129 u0 StatusBar} Window{8d49532 u0 com.android.settings/com.android.settings.applications.InstalledAppDetails} Window{8e8785d u0 com.android.settings/com.android.settings.applications.InstalledAppDetails} Window{6820d63 u0 com.android.systemui.ImageWallpaper}
12-08 13:25:49.646 27229 27253 V CtsSystemUtil: Running command: pm bypass-staged-installer-check true
12-08 13:25:49.683 27229 27253 I System.out: JNI not loaded
12-08 13:25:49.687 27229 27253 V CtsSystemUtil: Running command: pm bypass-staged-installer-check false
12-08 13:25:49.728 1109 7968 I PowerHalWrapper: <setInstallationBoost> enable:true
12-08 13:25:49.729 487 566 I libPowerHal: [perfLockAcq] idx:0 hdl:2149 hint:29 pid:487 duration:15000 => ret_hdl:2149
12-08 13:25:49.729 487 566 I libPowerHal: [PE] scn:0 hdl:2149 hint:29 comm:[email protected] pid:487
12-08 13:25:49.730 487 566 I libPowerHal: MTKPOWER_HINT_PMS_INSTALL: cpu_ctrl set cpu freq: 2001000 -1
12-08 13:25:49.730 487 566 I libPowerHal: [PE] MTKPOWER_HINT_PMS_INSTALL update cmd:1000000, param:0
12-08 13:25:49.730 487 566 I libPowerHal: [PE] MTKPOWER_HINT_PMS_INSTALL update cmd:1000000 param:0
12-08 13:25:49.829 1109 1185 D StagingManager: Starting preRebootVerification for session 1393966886
12-08 13:25:49.832 1109 1185 W ActivityManager: [HMDenterprise broadcastIntentLocked] intent=Intent { cmp=com.google.android.stagedinstall.gts/.StagedInstallTest$LocalIntentSender (has extras) }
12-08 13:25:49.835 310 310 I servicemanager: Since 'apexservice' could not be found, trying to start it as a lazy AIDL service
12-08 13:25:49.883 1109 1118 I system_server: Background young concurrent copying GC freed 103659(6771KB) AllocSpace objects, 14(344KB) LOS objects, 16% free, 24MB/29MB, paused 326us total 142.906ms
12-08 13:25:49.985 310 310 I BpBinder: onLastStrongRef automatically unlinking death recipients: <uncached descriptor>
12-08 13:25:49.986 310 310 I servicemanager: Tried to unregister apexservice, but there is about to be a client.
12-08 13:25:49.998 322 334 D vold : Disk at 7:216 changed
12-08 13:25:50.036 322 334 D vold : Disk at 7:216 changed
12-08 13:25:50.074 322 334 D vold : Disk at 252:2 changed
12-08 13:25:50.288 1109 1234 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.973) failed {.code = ERROR_NOT_SUPPORTED, .description = }
12-08 13:25:50.075 322 334 D vold : Disk at 252:2 changed
12-08 13:25:50.295 1109 1234 W ActivityManager: [HMDenterprise broadcastIntentLocked] intent=Intent { act=android.net.wifi.RSSI_CHANGED flg=0x4000000 (has extras) }
12-08 13:25:50.301 1109 4266 D PowerManagerService: updateWakeLockSummaryLocked: mWakefulness=Awake, mWakeLockSummary=0x1
12-08 13:25:50.301 1109 4266 D PowerManagerService: updateUserActivitySummaryLocked: mWakefulness=Awake, mUserActivitySummary=0x1, nextTimeout=57073601 (in 1745476 ms)
12-08 13:25:50.302 1109 4266 D PowerManagerService: updateDisplayPowerStateLocked: mDisplayReady=true, policy=3, mWakefulness=1, mWakeLockSummary=0x1, mUserActivitySummary=0x1, mBootCompleted=true, screenBrightnessOverride=NaN, useAutoBrightness=true, mScreenBrightnessBoostInProgress=false, mIsVrModeEnabled= false, sQuiescent=false
12-08 13:25:50.302 1109 4266 D PowerManagerService: Acquiring suspend blocker "PowerManagerService.WakeLocks".
12-08 13:25:50.306 322 334 D vold : Disk at 7:216 changed
12-08 13:25:50.315 5640 5673 I CarrierServices: [492] csk.onConnectivityChange: FiST: Wifi connectivity status true
12-08 13:25:50.316 5640 16784 I CarrierServices: [556] dag.c: (PEv2-SM): DisabledState: event Connectivity event [null]
12-08 13:25:50.317 5640 5673 I CarrierServices: [492] ctc.d: Connected state: [1], networkType: [WIFI]
12-08 13:25:50.319 1109 4266 D PowerManagerService: updateWakeLockSummaryLocked: mWakefulness=Awake, mWakeLockSummary=0x0
12-08 13:25:50.319 1109 4266 D PowerManagerService: updateUserActivitySummaryLocked: mWakefulness=Awake, mUserActivitySummary=0x1, nextTimeout=57073601 (in 1745458 ms)
12-08 13:25:50.319 1109 4266 D PowerManagerService: updateDisplayPowerStateLocked: mDisplayReady=true, policy=3, mWakefulness=1, mWakeLockSummary=0x0, mUserActivitySummary=0x1, mBootCompleted=true, screenBrightnessOverride=NaN, useAutoBrightness=true, mScreenBrightnessBoostInProgress=false, mIsVrModeEnabled= false, sQuiescent=false
12-08 13:25:50.319 1109 4266 D PowerManagerService: Releasing suspend blocker "PowerManagerService.WakeLocks".
12-08 13:25:50.320 1109 1134 D PackageInstallerSession: Marking session 1393966886 as failed: apexd verification failed : Could not mkdir /metadata/apex/sessions: No such file or directory
12-08 13:25:50.323 5640 5707 I CarrierServices: [521] dfx.d: RCS Configuration storage in Bugle is disabled by p/h flag, using ProvisioningEngineStateCacheUtil.getProvisioningConfigurationForGivenSim()
12-08 13:25:50.329 1109 1134 W ActivityManager: [HMDenterprise broadcastIntentLocked] intent=Intent { act=android.content.pm.action.SESSION_UPDATED pkg=com.google.android.stagedinstall.gts (has extras) }
12-08 13:25:50.329 1109 1134 D StagingManager: Stopping preRebootVerification for session 1393966886
12-08 13:25:50.343 27229 27253 E TestRunner: failed: testSamegradeSystemTzdataApex_Commit(com.google.android.stagedinstall.gts.StagedInstallTest)
12-08 13:25:50.344 27229 27253 E TestRunner: ----- begin exception -----
如上异常原因为sessions没有正常创建,但main log没有更多信息,继续分析kernel日志;
依然无法确认session没有创建的原因;对比pass的对比机日志继续分析发现,测试机该测试项直接跳过并没有进行测试,那么继续分析cts测试对比机测试执行记录executeShellCommandLog_xxxxxx.txt发现如下差异:
对比机:
测试机:
关于apex相关的命令 pm list packages --apex-only --show-versioncode -f执行的结果差异比较大;
随后在测试机上执行adb shell pm list packages --apex-only --show-versioncode -f发现确实有很大差异,则怀疑与apex相关配置有关;
随后查看测试机和对比机上system/apex目录的情况发现以下问题;
对比机:
测试机:
确认为与apex配置相关,随后了解了下apex的设计,apex是AndroidQ引入的特性,即系统组件更新机制;
APEX的实现源码位于:/system/apex/模块
与运行时库相关的APEX编译模块(com.android.runtime)位于art/build/apex模块,编译指令为:make com.android.runtime.release, 编译后替换/system/apex/相应文件,重启后将在/apex中挂载。启动这个功能需要相关的配置,并重新编译系统。
而添加支持的方式也很简单,在 {device.mk} 中添加一下语句,同时配置各个服务的 rc 文件,使服务支持 apex 更新。
$(call inherit-product, $(SRC_TARGET_DIR)/product/updatable_apex.mk
查找系统中的 updatable_apex.mk,确认该功能的启用会配置[ro.apex.updatable]: [true],则对比机中没有该属性,确认为启用该功能导致,该功能配置在项目的mk文件中,项目的mk文件引入了mainline的相关配置(mainline_module_r.mk),形式如下:
综上确认为mainline相关apex配置错误导致,需要参照以下google最新文档进行配置。