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

Issue 712369 link

Starred by 3 users

Issue metadata

Status: Verified
Owner:
Closed: May 2017
Cc:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

Autotest login timeout, particularly on buddy

Project Member Reported by kathrelk...@chromium.org, Apr 17 2017

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.
 
Cc: achuith@chromium.org kathrelk...@chromium.org
Owner: ----
Status: Available (was: Assigned)
Achuith, any ideas here?
There should be a screenshot in /var/log/screenshots. Can you attach it to this bug?
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.
Labels: ReleaseBlock-Stable M-60 M-59 M-58
Labels: bvttriage
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
Owner: yungleem@chromium.org
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?

Comment 9 by yungleem@google.com, 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?
I figured out what is happening in https://bugs.chromium.org/p/chromium/issues/detail?id=723772#c2
Issue 723772 has been merged into this issue.
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."



IMG_20170517_141600.jpg
3.9 MB View Download
Tests that clear stateful (e.g autoupdate_endtoendtest or provision_Autoupdate.double) put buddy at a different OOBE Screen than the new MD one. 
IMG_20170517_141246.jpg
3.5 MB View Download
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"


Cc: harpreet@chromium.org
Cc: akes...@chromium.org chingcodes@chromium.org
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.


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). 
To avoid this issue in the future:
https://bugs.chromium.org/p/chromium/issues/detail?id=723903

Comment 19 by dchan@google.com, 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 ?
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. 


Cc: abod...@chromium.org
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.
Owner: bhthompson@google.com
Status: Fixed (was: Available)
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.
Labels: Merge-TBD
[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.
Status: Verified (was: Fixed)
https://wmatrix.googleplex.com/paygen_au_beta?releases=60
Project Member

Comment 26 by sheriffbot@chromium.org, Jul 28 2017

Labels: -Merge-TBD
Labels: -ent-autotest ent-automation

Sign in to add a comment