Autotest login timeout, particularly on buddy |
||||||||||||
Issue description"Unhandled LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed." e.g. https://wmatrix.googleplex.com/testrun/unfiltered?test_ids=467925201 04/16 13:31:47.524 INFO | oobe:0039| Invoking Oobe.loginForTesting 04/16 13:46:56.982 ERROR| browser:0065| Failure while starting browser backend. Traceback (most recent call last): File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 58, in __init__ self._browser_backend.Start() File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 169, in Start + self._GetLoginStatus()) File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 277, in _RaiseOnLoginFailure raise exceptions.LoginException(error) LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed. 04/16 13:46:56.987 ERROR| chrome:0169| Timed out logging in, tries=2, error=LoginException('Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.',) 04/16 13:46:57.003 WARNI| test:0615| The test failed with the following exception Traceback (most recent call last): File "/usr/local/autotest/common_lib/test.py", line 609, in _exec _call_test_function(self.execute, *p_args, **p_dargs) File "/usr/local/autotest/common_lib/test.py", line 823, in _call_test_function raise error.UnhandledTestFail(e) UnhandledTestFail: Unhandled LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed. Traceback (most recent call last): File "/usr/local/autotest/common_lib/test.py", line 817, in _call_test_function return func(*args, **dargs) File "/usr/local/autotest/common_lib/test.py", line 470, in execute dargs) File "/usr/local/autotest/common_lib/test.py", line 347, in _call_run_once_with_retry postprocess_profiled_run, args, dargs) File "/usr/local/autotest/common_lib/test.py", line 380, in _call_run_once self.run_once(*args, **dargs) File "/usr/local/autotest/cros/enterprise/enterprise_policy_base.py", line 475, in run_once self.run_test_case(self.case) File "/usr/local/autotest/tests/policy_DisableScreenshots/policy_DisableScreenshots.py", line 136, in run_test_case self.setup_case(self.POLICY_NAME, case_value, self.SUPPORTING_POLICIES) File "/usr/local/autotest/cros/enterprise/enterprise_policy_base.py", line 198, in setup_case self._launch_chrome_browser() File "/usr/local/autotest/cros/enterprise/enterprise_policy_base.py", line 403, in _launch_chrome_browser autotest_ext=True) File "/usr/local/autotest/common_lib/cros/chrome.py", line 158, in __init__ self._browser = browser_to_create.Create(finder_options) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_finder.py", line 50, in Create self._credentials_path) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_with_oobe.py", line 14, in __init__ backend, platform_backend, credentials_path) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 58, in __init__ self._browser_backend.Start() File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 169, in Start + self._GetLoginStatus()) File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 277, in _RaiseOnLoginFailure raise exceptions.LoginException(error) LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.
,
Apr 19 2017
There should be a screenshot in /var/log/screenshots. Can you attach it to this bug?
,
May 10 2017
https://wmatrix.googleplex.com/platform/unfiltered?suites=bvt-inline&platforms=buddy&hide_experimental=true&builds=R59-9460.*,R59-9459.*,R59-9458.*,R59-9457.*,R59-9456.*,R59-9455.*,R59-9454.*,R59-9453.*,R59-9452.*,R59-9451.*,R59-9450.*,R59-9449.*,R59-9448.*,R59-9447.*,R59-9446.*,R59-9445.*,R59-9444.*,R59-9443.*,R59-9442.*,R59-9441.*,R59-9440.* This failure has happened every M59 build since branch point on several bvt-inline tests for buddy (and buddy only). login_Cryptohome login_CryptohomeIncognito login_LoginSuccess login_LogoutProcessCleanup login_OwnershipNotRetaken login_OwnershipTaken security_ProfilePermissions.login Similarly, the security_ProfilePermissions.guest test fails with "Unhandled LoginException: Failed to restart browser in guest mode (pid 14663)." Looks like the failures on buddy started happening between 59.0.3068.1 and 59.0.3071.8. I'm not able to reproduce this locally, even using an autotest bundle from a failing build.
,
May 11 2017
Upping priority here, this is preventing us from updating buddy on 58 stable, its failing there too. https://uberchromeos-server38.corp.google.com/new_tko/#tab_id=spreadsheet_view&row=job_name%252Ctest_name&column=status&show_incomplete=true&show_only_latest=false&show_invalid=true&condition=job_name%2520LIKE%2520%27buddy-release/R58-9334.69.0/bvt-inline/%2525%27%2520AND%2520test_name%2520%253C%253E%2520%27SERVER_JOB%27%2520AND%2520test_name%2520NOT%2520LIKE%2520%27CLIENT%255C_JOB%2525%27 The other devices of this family are all passing, what could be special about buddy?
,
May 11 2017
,
May 12 2017
,
May 12 2017
This problem on Buddy appears to have hit all channels at about the same time in mid April. Conveniently enough, that's about when all the buddy DVTs in the lab finally got switched out for PVT units: https://buganizer.corp.google.com/issues/28559092
,
May 17 2017
If we think this might be a hardware issue with the PVT units, whom is the best owner here, do we have an eng owner for Buddy?
,
May 17 2017
There shouldn't be any HW difference between Buddy DVT and PVT so I doubt it's HW causing the issue even though it coincides with the DVT to PVT swap in the lab. kathrelkeld@ - when you ran the test locally, are you using a PVT or a DVT Buddy unit?
,
May 17 2017
I figured out what is happening in https://bugs.chromium.org/p/chromium/issues/detail?id=723772#c2
,
May 17 2017
Issue 723772 has been merged into this issue.
,
May 17 2017
When any test tries to login it is presented with an extra enrollment step (see attached screenshot). Then the test times out with error "Unhandled LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed."
,
May 17 2017
Tests that clear stateful (e.g autoupdate_endtoendtest or provision_Autoupdate.double) put buddy at a different OOBE Screen than the new MD one.
,
May 17 2017
Just took a look at 1 of the buddy's where these tests are failing. Buddy devices go to enterprise enrollment screen, specifically 'remora' / CFM enrollment screen by default, this would be the case with any buddy that has "oem_device_requisition"="remora" in vpd. Could it be that the previous DVT buddy's did not have the remora enrollment enabled by default? To get around this oem_device_requisition key will need to be removed from vpd. localhost ~ # vpd -l -i RW_VPD "gbind_attribute"="=CisKILsuT3HQ_PfUHKBf5zDmd8Tr5npXWZY0SbaJyNLxFGU7EAAaBWJ1ZGR5EKTjwqYI" "ubind_attribute"="=CisKIPvA6zX7Ppb2bde4gSU-19OwJ76gWwGT_KYueWyBUgjtEAEaBWJ1ZGR5EMmai4kM" "oem_device_requisition"="remora"
,
May 17 2017
,
May 17 2017
That seems reasonable, and would explain why swapping caused this, we just need to ssh into these in the lab and nuke that VPD entry on all the buddy systems.
,
May 17 2017
If we can get these VPD entries nuked out soon we can bring buddy into the next push (we should theoretically be able to retroactively run these tests as well, though it would be good to get passing tomorrow).
,
May 17 2017
To avoid this issue in the future: https://bugs.chromium.org/p/chromium/issues/detail?id=723903
,
May 18 2017
Is this a recent change that cause this problem ? Who is setting oem_device_requisition ? Is it always there ? Removing the value might make the test work but this might be a change in how we interpret the value in 58 ?
,
May 18 2017
According to #c7, this is been happening since we switched to PVT units in the lab. It is possible that the PVT units are Hangout/hotrod SKUs and hence have that VPD flag set.
,
May 18 2017
,
May 22 2017
Can someone change the VPD entry "oem_device_requisition"="remora" to "oem_device_requisition"="none" and see if those devices pass those tests? That's the VPD entry that sets the CfM mode.
,
May 22 2017
This should be fixed, I sshed into the buddy systems in the lab and nuked the oem_device_requisition VPD entry. vpd -i RW_VPD -d oem_device_requisition Now we just need to rerun tests.
,
May 22 2017
[Auto-generated comment by a script] We noticed that this issue is targeted for M-58; it appears the fix may have landed after branch point, meaning a merge might be required. Please confirm if a merge is required here - if so add Merge-Request-58 label, otherwise remove Merge-TBD label. Thanks.
,
Jun 15 2017
,
Jul 28 2017
,
May 2 2018
|
||||||||||||
►
Sign in to add a comment |
||||||||||||
Comment 1 by kathrelk...@chromium.org
, Apr 17 2017Owner: ----
Status: Available (was: Assigned)