【GTS】com.google.android.stagedinstall.gts.host.StagedInstallTest#testSamegradeSystemTzdataApe Fail问题

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:mtkpower@1.0-se 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最新文档进行配置。