New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 853584 link

Starred by 3 users
Status: Verified
Owner:
khmel@chromium.org
Closed: Jun 2018
Cc:
█ lhchavez@chromium.org
kinaba@chromium.org
pwang@chromium.org
khmel@chromium.org
█ kazu@google.com
█ jbrandmeyer@chromium.org
mojahsu@chromium.org
yusukes@chromium.org
yllin@chromium.org
risan@chromium.org
manucornet@chromium.org
grundler@chromium.org
hashimoto@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: ----



Sign in to add a comment

CTS and GTS being flaky because of race between data mount and zygote start

Project Member Reported by sheriff-...@appspot.gserviceaccount.com, Jun 18 2018 
Filed by sheriff-o-matic@appspot.gserviceaccount.com on behalf of mojahsu@google.com

caroline-arcnext-paladin:738 failed

* Command: 
    adb -s 'chromeos6-row2-rack23-host17:22' shell pgrep -f 'org.chromium.arc.intent_helper'
Exit status: 1

Builders failed on: 
- caroline-arcnext-paladin: 
  https://cros-goldeneye.corp.google.com/chromeos/healthmonitoring/buildDetails?buildbucketId=8943432271252902048

Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/server/site_tests/cheets_GTS_P/cheets_GTS_P.py", line 131, in run_once
    precondition_commands=precondition_commands)
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 1186, in _run_tradefed_with_retries
    self._ready_arc()
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 380, in _ready_arc
    self._wait_for_arc_boot(host)
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 347, in _wait_for_arc_boot
    sleep_interval=constants.ARC_POLLING_INTERVAL_SECONDS)
  File "/usr/local/autotest/client/common_lib/utils.py", line 2615, in poll_for_condition
    value = condition()
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 339, in _intent_helper_running
    args=('shell', 'pgrep', '-f', 'org.chromium.arc.intent_helper'))
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 244, in _run_adb_cmd
    result = self._run('adb', **kwargs)
  File "/usr/local/autotest/server/cros/tradefed_test.py", line 746, in _run
    return utils.run(*args, **kwargs)
  File "/usr/local/autotest/client/common_lib/utils.py", line 749, in run
    "Command returned non-zero exit status")
CmdError: Command <adb -s 'chromeos6-row2-rack23-host17:22' shell pgrep -f 'org.chromium.arc.intent_helper'> failed, rc=1, Command returned non-zero exit status
* Command: 
    adb -s 'chromeos6-row2-rack23-host17:22' shell pgrep -f
    'org.chromium.arc.intent_helper'

Comment 2 by mojahsu@chromium.org, Jun 18 2018

Cc: grundler@chromium.org rrangel@chromium.org

Comment 3 by mojahsu@chromium.org, Jun 18 2018

Cc: -mojahsu@google.com mojahsu@chromium.org

Comment 4 by mojahsu@chromium.org, Jun 18 2018

Owner: ihf@chromium.org
Hello ihf@

I found the control.6.0_r1.GtsAdminTestCases is added by you.
Can you help to check this case?

Comment 5 by mojahsu@chromium.org, Jun 18 2018 

There are the same error for other DUT build.

And it passed the original fail test. GtsAdminTestaCases.

It may be a flaky.

https://luci-milo.appspot.com/buildbot/chromeos/kevin-arcnext-paladin/740



cheets_CTS_P.9.0_r1.arm.CtsAdminTestCases          [ PASSED ]
cheets_CTS_P.9.0_r1.arm.CtsAdminTestCases            retry_count: 1
cheets_GTS_P.6.0_r1.GtsPermissionTestCases         [ PASSED ]
cheets_GTS_P.6.0_r1.GtsPermissionTestCases           retry_count: 1
cheets_CTS_P.9.0_r1.arm.CtsAccelerationTestCases   [ FAILED ]
cheets_CTS_P.9.0_r1.arm.CtsAccelerationTestCases     ERROR: Command <adb -s 'chromeos6-row4-rack5-host17:22' shell pgrep -f 'org.chromium.arc.intent_helper'> failed, rc=1, Command returned non-zero exit status
cheets_CTS_P.9.0_r1.arm.CtsAccelerationTestCases     retry_count: 2

Comment 6 by uekawa@google.com, Jun 18 2018

Labels: ArcConstable

Comment 7 by khmel@chromium.org, Jun 18 2018

Cc: lhchavez@chromium.org khmel@chromium.org
Could repro it locally. It can pass several runs but next one fails.
I see exact fail reason.

When this happens I see on device "Settings keeps stopping" error

Comment 8 by khmel@chromium.org, Jun 18 2018 

06-18 16:25:04.131   178   178 I system_server: The ClassLoaderContext is a special shared library.
06-18 16:25:04.137   516   516 F DEBUG   : 
06-18 16:25:04.137   516   516 F DEBUG   : backtrace:
06-18 16:25:04.137   516   516 F DEBUG   :     #00 pc 00000a40  [vdso:f3d63000] (__kernel_vsyscall+16)
06-18 16:25:04.137   516   516 F DEBUG   :     #01 pc 0001fc68  /system/lib/libc.so (syscall+40)
06-18 16:25:04.137   516   516 F DEBUG   :     #02 pc 00032203  /system/lib/libc.so (abort+115)
06-18 16:25:04.137   516   516 F DEBUG   :     #03 pc 0051eb80  /system/lib/libart.so (art::Runtime::Abort(char const*)+1296)
06-18 16:25:04.137   516   516 F DEBUG   :     #04 pc 0061c343  /system/lib/libart.so (_ZNSt3__110__function6__funcIPFvPKcENS_9allocatorIS5_EES4_EclEOS3_+35)
06-18 16:25:04.137   516   516 F DEBUG   :     #05 pc 00007cae  /system/lib/libbase.so (android::base::LogMessage::~LogMessage()+734)
06-18 16:25:04.138   516   516 F DEBUG   :     #06 pc 004ab50a  /system/lib/libart.so (art::OatFileManager::SetOnlyUseSystemOatFiles()+1018)
06-18 16:25:04.138   516   516 F DEBUG   :     #07 pc 00465395  /system/lib/libart.so (art::ZygoteHooks_nativePostForkChild(_JNIEnv*, _jclass*, long long, int, unsigned char, unsigned char, _jstring*)+3525)
06-18 16:25:04.138   516   516 F DEBUG   :     #08 pc 00645f17  /system/lib/libart.so (art_quick_generic_jni_trampoline+71)
06-18 16:25:04.138   516   516 F DEBUG   :     #09 pc 006400d2  /system/lib/libart.so (art_quick_invoke_static_stub+418)
06-18 16:25:04.138   516   516 F DEBUG   :     #10 pc 000a307f  /system/lib/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+239)
06-18 16:25:04.138   516   516 F DEBUG   :     #11 pc 002b9629  /system/lib/libart.so (art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::ShadowFrame*, unsigned short, art::JValue*)+361)
06-18 16:25:04.138   516   516 F DEBUG   :     #12 pc 002b25c6  /system/lib/libart.so (bool art::interpreter::DoCall<true, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1302)
06-18 16:25:04.138   516   516 F DEBUG   :     #13 pc 0060d898  /system/lib/libart.so (MterpInvokeStaticRange+168)
06-18 16:25:04.138   516   516 F DEBUG   :     #14 pc 00632521  /system/lib/libart.so (ExecuteMterpImpl+15393)
06-18 16:25:04.138   516   516 F DEBUG   :     #15 pc 000ae6be  /system/framework/boot-core-libart.vdex (dalvik.system.ZygoteHooks.postForkChild+12)
06-18 16:25:04.138   516   516 F DEBUG   :     #16 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.138   516   516 F DEBUG   :     #17 pc 002898cf  /system/lib/libart.so (art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*, art::JValue*)+239)
06-18 16:25:04.138   516   516 F DEBUG   :     #18 pc 002b0efa  /system/lib/libart.so (bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1130)
06-18 16:25:04.138   516   516 F DEBUG   :     #19 pc 0060a44a  /system/lib/libart.so (MterpInvokeVirtual+682)
06-18 16:25:04.138   516   516 F DEBUG   :     #20 pc 006320a1  /system/lib/libart.so (ExecuteMterpImpl+14241)
06-18 16:25:04.138   516   516 F DEBUG   :     #21 pc 00c146ca  /system/framework/boot-framework.vdex (com.android.internal.os.Zygote.callPostForkChildHooks+4)
06-18 16:25:04.138   516   516 F DEBUG   :     #22 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.138   516   516 F DEBUG   :     #23 pc 002897ae  /system/lib/libart.so (art::interpreter::EnterInterpreterFromEntryPoint(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*)+126)
06-18 16:25:04.138   516   516 F DEBUG   :     #24 pc 005f613a  /system/lib/libart.so (artQuickToInterpreterBridge+1194)
06-18 16:25:04.138   516   516 F DEBUG   :     #25 pc 00645fed  /system/lib/libart.so (art_quick_to_interpreter_bridge+77)
06-18 16:25:04.138   516   516 F DEBUG   :     #26 pc 006400d2  /system/lib/libart.so (art_quick_invoke_static_stub+418)
06-18 16:25:04.138   516   516 F DEBUG   :     #27 pc 000a307f  /system/lib/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+239)
06-18 16:25:04.138   516   516 F DEBUG   :     #28 pc 005153ef  /system/lib/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+111)
06-18 16:25:04.138   516   516 F DEBUG   :     #29 pc 00514fb3  /system/lib/libart.so (art::InvokeWithVarArgs(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, char*)+419)
06-18 16:25:04.138   516   516 F DEBUG   :     #30 pc 003d6d8d  /system/lib/libart.so (art::JNI::CallStaticVoidMethodV(_JNIEnv*, _jclass*, _jmethodID*, char*)+1085)
06-18 16:25:04.138   516   516 F DEBUG   :     #31 pc 000704de  /system/lib/libandroid_runtime.so (_JNIEnv::CallStaticVoidMethod(_jclass*, _jmethodID*, ...)+62)
06-18 16:25:04.138   516   516 F DEBUG   :     #32 pc 0015c8d6  /system/lib/libandroid_runtime.so ((anonymous namespace)::ForkAndSpecializeCommon(_JNIEnv*, unsigned int, unsigned int, _jintArray*, int, _jobjectArray*, long long, long long, int, _jstring*, _jstring*, bool, _jintArray*, _jintArray*, bool, _jstring*, _jstring*)+5606)
06-18 16:25:04.138   516   516 F DEBUG   :     #33 pc 0015a788  /system/lib/libandroid_runtime.so (android::com_android_internal_os_Zygote_nativeForkAndSpecialize(_JNIEnv*, _jclass*, int, int, _jintArray*, int, _jobjectArray*, int, _jstring*, _jstring*, _jintArray*, _jintArray*, unsigned char, _jstring*, _jstring*)+584)
06-18 16:25:04.138   516   516 F DEBUG   :     #34 pc 00645f17  /system/lib/libart.so (art_quick_generic_jni_trampoline+71)
06-18 16:25:04.138   516   516 F DEBUG   :     #35 pc 006400d2  /system/lib/libart.so (art_quick_invoke_static_stub+418)
06-18 16:25:04.138   516   516 F DEBUG   :     #36 pc 000a307f  /system/lib/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+239)
06-18 16:25:04.138   516   516 F DEBUG   :     #37 pc 002b9629  /system/lib/libart.so (art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::ShadowFrame*, unsigned short, art::JValue*)+361)
06-18 16:25:04.138   516   516 F DEBUG   :     #38 pc 002b25c6  /system/lib/libart.so (bool art::interpreter::DoCall<true, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1302)
06-18 16:25:04.138   516   516 F DEBUG   :     #39 pc 0060d898  /system/lib/libart.so (MterpInvokeStaticRange+168)
06-18 16:25:04.138   516   516 F DEBUG   :     #40 pc 00632521  /system/lib/libart.so (ExecuteMterpImpl+15393)
06-18 16:25:04.138   516   516 F DEBUG   :     #41 pc 00c1468e  /system/framework/boot-framework.vdex (com.android.internal.os.Zygote.forkAndSpecialize+16)
06-18 16:25:04.138   516   516 F DEBUG   :     #42 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.138   516   516 F DEBUG   :     #43 pc 002898cf  /system/lib/libart.so (art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*, art::JValue*)+239)
06-18 16:25:04.138   516   516 F DEBUG   :     #44 pc 002b25a7  /system/lib/libart.so (bool art::interpreter::DoCall<true, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1271)
06-18 16:25:04.139   516   516 F DEBUG   :     #45 pc 0060d898  /system/lib/libart.so (MterpInvokeStaticRange+168)
06-18 16:25:04.139   516   516 F DEBUG   :     #46 pc 00632521  /system/lib/libart.so (ExecuteMterpImpl+15393)
06-18 16:25:04.139   516   516 F DEBUG   :     #47 pc 00c12984  /system/framework/boot-framework.vdex (com.android.internal.os.ZygoteConnection.processOneCommand+528)
06-18 16:25:04.139   516   516 F DEBUG   :     #48 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.139   516   516 F DEBUG   :     #49 pc 002898cf  /system/lib/libart.so (art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*, art::JValue*)+239)
06-18 16:25:04.139   516   516 F DEBUG   :     #50 pc 002b0efa  /system/lib/libart.so (bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1130)
06-18 16:25:04.139   516   516 F DEBUG   :     #51 pc 0060a44a  /system/lib/libart.so (MterpInvokeVirtual+682)
06-18 16:25:04.139   516   516 F DEBUG   :     #52 pc 006320a1  /system/lib/libart.so (ExecuteMterpImpl+14241)
06-18 16:25:04.139   516   516 F DEBUG   :     #53 pc 00c14400  /system/framework/boot-framework.vdex (com.android.internal.os.ZygoteServer.runSelectLoop+208)
06-18 16:25:04.139   516   516 F DEBUG   :     #54 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.139   516   516 F DEBUG   :     #55 pc 002898cf  /system/lib/libart.so (art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*, art::JValue*)+239)
06-18 16:25:04.139   516   516 F DEBUG   :     #56 pc 002b0efa  /system/lib/libart.so (bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+1130)
06-18 16:25:04.139   516   516 F DEBUG   :     #57 pc 0060a44a  /system/lib/libart.so (MterpInvokeVirtual+682)
06-18 16:25:04.139   516   516 F DEBUG   :     #58 pc 006320a1  /system/lib/libart.so (ExecuteMterpImpl+14241)
06-18 16:25:04.139   516   516 F DEBUG   :     #59 pc 00c13826  /system/framework/boot-framework.vdex (com.android.internal.os.ZygoteInit.main+536)
06-18 16:25:04.139   516   516 F DEBUG   :     #60 pc 00282095  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEb.llvm.1813777599+597)
06-18 16:25:04.139   516   516 F DEBUG   :     #61 pc 002897ae  /system/lib/libart.so (art::interpreter::EnterInterpreterFromEntryPoint(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame*)+126)
06-18 16:25:04.139   516   516 F DEBUG   :     #62 pc 005f613a  /system/lib/libart.so (artQuickToInterpreterBridge+1194)
06-18 16:25:04.139   516   516 F DEBUG   :     #63 pc 00645fed  /system/lib/libart.so (art_quick_to_interpreter_bridge+77)
06-18 16:25:04.139   516   516 F DEBUG   :     #64 pc 006400d2  /system/lib/libart.so (art_quick_invoke_static_stub+418)
06-18 16:25:04.141   516   516 F DEBUG   :     #65 pc 000a307f  /system/lib/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+239)
06-18 16:25:04.141   516   516 F DEBUG   :     #66 pc 005153ef  /system/lib/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+111)
06-18 16:25:04.141   516   516 F DEBUG   :     #67 pc 00514fb3  /system/lib/libart.so (art::InvokeWithVarArgs(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, char*)+419)
06-18 16:25:04.141   516   516 F DEBUG   :     #68 pc 003d6d8d  /system/lib/libart.so (art::JNI::CallStaticVoidMethodV(_JNIEnv*, _jclass*, _jmethodID*, char*)+1085)
06-18 16:25:04.141   516   516 F DEBUG   :     #69 pc 000704de  /system/lib/libandroid_runtime.so (_JNIEnv::CallStaticVoidMethod(_jclass*, _jmethodID*, ...)+62)
06-18 16:25:04.141   516   516 F DEBUG   :     #70 pc 00073858  /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, android::Vector<android::String8> const&, bool)+744)
06-18 16:25:04.141   516   516 F DEBUG   :     #71 pc 00001c32  /system/bin/app_process32 (main+1570)
06-18 16:25:04.141   516   516 F DEBUG   :     #72 pc 000d0fc4  /system/lib/libc.so (__libc_init+100)
18_09_24_51S_eve.log
1.1 MB View Download

Comment 9 by rrangel@chromium.org, Jun 18 2018

Cc: -rrangel@chromium.org jbrandmeyer@chromium.org

Comment 10 by steve...@chromium.org, Jun 18 2018

Cc: manucornet@chromium.org
Components: Infra>Client>ARC
Labels: Build-PFQ-Failures
Also failing in caroline-arcnext-chrome-pfq:
https://cros-goldeneye.corp.google.com/chromeos/legoland/builderHistory?buildConfig=caroline-arcnext-chrome-pfq&buildBranch=master

Comment 12 by khmel@chromium.org, Jun 18 2018 

So this problem is flaky. It first appears in PFQ while trying to uprev 4842345. Last stable build looks 4841952.

Comment 14 by khmel@chromium.org, Jun 18 2018 

We downgraded android container to last known good version and submitted a revert of the problem CL. but it may take a time for next uprev due another problem in ToT.

Comment 15 by khmel@chromium.org, Jun 18 2018

Status: Fixed (was: Available)
https://luci-milo.appspot.com/buildbot/chromeos/kevin-arcnext-paladin/747 is green with downgraded version of ARC P. Assume fixed. Next automatic uprev should have the fix.

Comment 16 by khmel@chromium.org, Jun 21 2018

Owner: khmel@chromium.org
Status: Started (was: Fixed)
Reopening this.
This problem is back again. Top level error is the same, however reason looks different.

06/21 01:03:26.463 DEBUG|             utils:0215| Running 'adb -s 'chromeos6-row2-rack21-host9:22' shell pgrep -f 'org.chromium.arc.intent_helper''
06/21 01:03:26.523 DEBUG|              test:0410| Test failed due to Command <adb -s 'chromeos6-row2-rack21-host9:22' shell pgrep -f 'org.chromium.arc.intent_helper'> failed, rc=1, Command returned non-zero exit status
* Command: 
    adb -s 'chromeos6-row2-rack21-host9:22' shell pgrep -f
    'org.chromium.arc.intent_helper'
Exit status: 1

Comment 17 by lhchavez@chromium.org, Jun 21 2018

Status: Fixed (was: Started)
That particular error is being tracked in  crbug.com/854383

Comment 18 by khmel@chromium.org, Jun 21 2018 

Note, that underlying reason is different although top-level reproduction is the same.

Comment 19 by khmel@chromium.org, Jun 22 2018

Status: Started (was: Fixed)

Comment 20 by khmel@chromium.org, Jun 22 2018 

Reopen it again. It still appears in PFQ, paladin. Locally reproducible however repro rate is ~10-20%.

Investigation showed that it possible race condition between vold and zygote start.

Comment 21 by khmel@chromium.org, Jun 23 2018

Cc: hashimoto@chromium.org risan@chromium.org yusukes@chromium.org kazu@google.com
+Yusuke, +Risan, +Ryo, +Kazu (as next constable)

I think we have deep race condition here mounting data and zygote start.

So I found common pattern when test fails.

It is:

...
I zygote  : option[0]=-Xzygote
...
W zygote  : CanWriteToDalvikCache returned error other than EACCES: No such file or directory
....
vold    : e4crypt_init_user0

Key point here, e4crypt_init_user0 is called after zygote start.


In all successful runs 
We have 
e4crypt_init_user0 goes before zygote.
and we don't have 
W zygote  : CanWriteToDalvikCache returned error other than EACCES: No such 

As result of this problem 15 oat files are not available. 

To confirm this I did following hack: ag/4408534
and reproduced conditions when test fails and with this hack I had successful run.

Yusuke, do you see any potential problem mounting boot caches?
Risan and Ryo, the same question about vold. Do we have any specific in e4crypt_init_user0?

Comment 22 by grundler@chromium.org, Jun 25 2018 

master-paladin build #18956 failed due to this again.
But it was with kevin-arcnext-paladin:

  https://luci-logdog.appspot.com/v/?s=chromeos/bb/chromeos/kevin-arcnext-paladin/799/+/recipes/steps/HWTest__bvt-arc_/0/stdout


heets_GTS_P.6.0_r1.GtsAdminTestCases              [ PASSED ]
cheets_GTS_P.6.0_r1.GtsAdminTestCases                retry_count: 1
cheets_CTS_P.9.0_r1.arm.CtsAdminTestCases          [ FAILED ]
cheets_CTS_P.9.0_r1.arm.CtsAdminTestCases            FAIL: Error: Timed out waiting for intent helper.
cheets_CTS_P.9.0_r1.arm.CtsAdminTestCases            retry_count: 2

Comment 23 by khmel@chromium.org, Jun 25 2018 

ag/4414471 is in review

Comment 24 by kinaba@chromium.org, Jun 25 2018

Cc: kinaba@chromium.org

Comment 25 by hashimoto@chromium.org, Jun 26 2018

Summary: CTS and GTS being flaky because of race between data mount and zygote start (was: caroline-arcnext-paladin:738 failed)
Updating the summary to make it more noticeable (please correct it if it's wrong).
ARC-specific changes in Vold by me and Risan are to support auxiliary features and they shouldn't affect the boot-time events.

Comment 26 by yllin@chromium.org, Jun 26 2018 

Issue 856445 has been merged into this issue.

Comment 27 by pwang@chromium.org, Jun 26 2018

Cc: pwang@chromium.org

Comment 28 by yllin@chromium.org, Jun 26 2018 

collecting some messages from the crbug.com/856445

kevin-arcnext-paladin:804 and kevin-arcnext-pi-android-pfq:433 failed

Builders failed on: 
- kevin-arcnext-paladin: 
  https://cros-goldeneye.corp.google.com/chromeos/healthmonitoring/buildDetails?buildbucketId=8942712181483083712
- kevin-arcnext-pi-android-pfq
https://cros-goldeneye.corp.google.com/chromeos/healthmonitoring/buildDetails?buildbucketId=8942704909226426000

Both fails with  cheets_GTS_P.6.0_r1.GtsAdminTestCases                FAIL: Error: Timed out waiting for intent helper.

Comment 29 by yllin@chromium.org, Jun 26 2018

Cc: yllin@chromium.org

Comment 31 by lhchavez@chromium.org, Jun 26 2018 

We expect this to be fixed when go/ab/4861569 is picked by the Android PFQ. But that is being blocked by cheets_LoginScreen, since it expects Zygote to be running. khmel@'s change made it such that it's *not* running, so we need to adjust that test.

Comment 32 by khmel@chromium.org, Jun 26 2018

Labels: -Pri-0 Pri-1
Downgrading this to P1. This change is not propagated to build yet however severity is lower.

Comment 35 by lhchavez@chromium.org, Jun 27 2018 

That run still does not contain khmel@'s fix: It uses go/ab/4859924 and we need go/ab/4861569

Comment 36 by xixuan@chromium.org, Jun 27 2018 

This CL is merged at build 811, and it's a client-side test, I think it doesn't need push-to-prod. 

But kevin-arcnext-paladin & caroline paladin are still flaky?

https://uberchromegw.corp.google.com/i/chromeos/builders/kevin-arcnext-paladin/builds/814
https://uberchromegw.corp.google.com/i/chromeos/builders/kevin-arcnext-paladin/builds/813

Comment 37 by lhchavez@chromium.org, Jun 27 2018 

As it turns out, we fixed the wrong test ^^;;

https://chrome-internal-review.googlesource.com/c/chromeos/autotest-cheets/+/645788 is the correct fix (note the difference between cheets_LoginScreen and cheets_LoginScreen_P. we failed to notice that yesterday).

Comment 39 by xixuan@chromium.org, Jun 27 2018 

Re# 37, Let's chump 645788?
Project Member

Comment 40 by bugdroid1@chromium.org, Jun 27 2018 

The following revision refers to this bug:
  https://chrome-internal.googlesource.com/chromeos/autotest-cheets/+/c0308d2d21f7cb7a5b5316766af64e978db59501

commit c0308d2d21f7cb7a5b5316766af64e978db59501
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Wed Jun 27 16:50:08 2018

Comment 41 by xixuan@chromium.org, Jun 27 2018 

The fix is not working?

https://luci-milo.appspot.com/buildbot/chromeos/kevin-arcnext-pi-android-pfq/441 still fails with this chumped CL.

Comment 42 by khmel@chromium.org, Jun 27 2018 

#41 that build is 10822.0.0-rc6. 	10823.0.0 is required.

Comment 43 by lhchavez@chromium.org, Jun 27 2018 

I can also see that the stacktrace corresponds to the old version, so that run did not use the updated test :(

Let's wait for https://uberchromegw.corp.google.com/i/chromeos/builders/kevin-arcnext-pi-android-pfq/builds/442

Comment 44 by xixuan@chromium.org, Jun 27 2018 

Right, I manually checked build 442, the change is in autotest_package.tar. 

Re #42, why this change is picked up by next round of build (823), not the current round (822)?

Comment 46 by lhchavez@chromium.org, Jun 27 2018

Status: Verified (was: Started)
Green build is enough verification for me :D

Comment 47 by khmel@chromium.org, Jun 27 2018 

:) may be it is just flaky
►

Sign in to add a comment