New issue
Advanced search Search tips

Issue 912234 link

Starred by 2 users
Status: Assigned
Owner:
jdufault@chromium.org
Cc:
apronin@chromium.org
derat@chromium.org
xiy...@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug



Sign in to add a comment

Chrome login test fails frequently with rikku-release

Project Member Reported by mukai@chromium.org, Dec 5 
It seems ChromeLogin / MashLogin / SingleProcessMashLogin are frequently failing with rikku-release for "Chrome login failed: not mounted for testuser@gmail.com: context deadline exceeded".

Samples:
- https://stainless.corp.google.com/browse/chromeos-autotest-results/263817783-chromeos-test/
- https://stainless.corp.google.com/browse/chromeos-autotest-results/263305189-chromeos-test/


The test log fails on cryptohome mounting.

2018/12/03 19:59:40 Started test ui.ChromeLogin
2018/12/03 19:59:40 [19:59:40.091] Waiting for org.chromium.SessionManager D-Bus service
2018/12/03 19:59:40 [19:59:40.093] Restarting ui job
2018/12/03 19:59:41 [19:59:41.173] Waiting for org.chromium.SessionManager D-Bus service
2018/12/03 19:59:41 [19:59:41.190] Asking session_manager to enable Chrome testing
2018/12/03 19:59:41 [19:59:41.195] Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/12/03 19:59:42 [19:59:42.237] Removing cryptohome for testuser@gmail.com
2018/12/03 19:59:42 [19:59:42.272] Finding OOBE DevTools target
2018/12/03 19:59:42 [19:59:42.418] Connecting to Chrome at ws://127.0.0.1:58572/devtools/page/39016176EAF75AFFCC90BFFD082DDD75
2018/12/03 19:59:42 [19:59:42.670] Waiting for OOBE
2018/12/03 19:59:45 [19:59:45.067] Logging in as user "testuser@gmail.com"
2018/12/03 19:59:45 [19:59:45.372] Waiting for cryptohome for user "testuser@gmail.com"
2018/12/03 20:01:37 [20:01:37.738] cryptohome status:
{
   "installattrs": {
      "first_install": true,
      "initialized": true,
      "invalid": false,
      "lockbox_index": 536870916,
      "lockbox_nvram_version": 2,
      "secure": true,
      "size": 0,
      "version": 1
   },
   "mounts": [  ],
   "tpm": {
      "being_owned": false,
      "can_connect": true,
      "can_decrypt": true,
      "can_encrypt": true,
      "can_load_srk": true,
      "can_load_srk_pubkey": true,
      "enabled": true,
      "has_context": true,
      "has_cryptohome_key": true,
      "has_key_handle": true,
      "last_error": 0,
      "owned": true,
      "srk_vulnerable_roca": true
   }
}
2018/12/03 20:01:37 [20:01:37.769] /sys/class/misc/tpm0/device/owned contains "1"
2018/12/03 20:01:37 [20:01:37.769] Error at chrome_login.go:40: Chrome login failed: not mounted for testuser@gmail.com: context deadline exceeded; last error follows: /home/user/c5fafb3eb3db468d47416c099dcf05a7bcdb7c6e not found
2018/12/03 20:01:37 [20:01:37.769] Stack trace:
Chrome login failed
	at chromiumos/tast/local/bundles/cros/ui.ChromeLogin (chrome_login.go:40)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:195)
	at chromiumos/tast/testing.runStages.func1.1 (stage.go:39)
	at chromiumos/tast/testing.runAndRecover.func1 (stage.go:69)
	at runtime.goexit (asm_amd64.s:2361)
not mounted for testuser@gmail.com
	at chromiumos/tast/local/cryptohome.WaitForUserMount (cryptohome.go:210)
	at chromiumos/tast/local/chrome.(*Chrome).logIn (chrome.go:565)
	at chromiumos/tast/local/chrome.New (chrome.go:192)
	at chromiumos/tast/local/bundles/cros/ui.ChromeLogin (chrome_login.go:38)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:195)
	at chromiumos/tast/testing.runStages.func1.1 (stage.go:39)
	at chromiumos/tast/testing.runAndRecover.func1 (stage.go:69)
	at runtime.goexit (asm_amd64.s:2361)
context deadline exceeded; last error follows
	at chromiumos/tast/testing.Poll (poll.go:72)
	at chromiumos/tast/local/cryptohome.WaitForUserMount (cryptohome.go:186)
	at chromiumos/tast/local/chrome.(*Chrome).logIn (chrome.go:565)
	at chromiumos/tast/local/chrome.New (chrome.go:192)
	at chromiumos/tast/local/bundles/cros/ui.ChromeLogin (chrome_login.go:38)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:195)
	at chromiumos/tast/testing.runStages.func1.1 (stage.go:39)
	at chromiumos/tast/testing.runAndRecover.func1 (stage.go:69)
	...
/home/user/c5fafb3eb3db468d47416c099dcf05a7bcdb7c6e not found
	at chromiumos/tast/local/cryptohome.WaitForUserMount.func1 (cryptohome.go:193)
	at chromiumos/tast/testing.Poll (poll.go:57)
	at chromiumos/tast/local/cryptohome.WaitForUserMount (cryptohome.go:186)
	at chromiumos/tast/local/chrome.(*Chrome).logIn (chrome.go:565)
	at chromiumos/tast/local/chrome.New (chrome.go:192)
	at chromiumos/tast/local/bundles/cros/ui.ChromeLogin (chrome_login.go:38)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:195)
	at chromiumos/tast/testing.runStages.func1.1 (stage.go:39)
	...
2018/12/03 20:01:37 Completed test ui.ChromeLogin in 1m57.702s with 1 error(s)

Comment 1 by mukai@chromium.org, Dec 5

Components: Tests>Tast Infra>Client>ChromeOS>Test
Looks very similar to  issue 875263

Comment 2 by mukai@chromium.org, Dec 11

Cc: xiy...@chromium.org
cc: the current sheriff.

reported this as internal b/120789934

Comment 3 by xiy...@chromium.org, Dec 11

Cc: apronin@chromium.org derat@chromium.org
This still happens.
e.g.
tast.ui.ChromeLogin 
https://stainless.corp.google.com/browse/chromeos-autotest-results/265801767-chromeos-test/

Anything special about rikku-release? Is this a known issue?

Comment 4 by mukai@chromium.org, Dec 11 

Notes: in the previous week (when I was the sheriff), this did not happen always but happened multiple times. So far I'm still puzzled, but some log indicates that it falls into enrollment setup screen. For example,  chrome_20181210-134616 says


[6491:6491:1210/134621.093893:VERBOSE1:wizard_controller.cc(836)] SkipToLoginForTesting.
[6491:6491:1210/134621.094900:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia).
[6491:6491:1210/134621.094940:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5
[6491:6491:1210/134621.095310:VERBOSE1:wizard_controller.cc(2092)] Showing enrollment screen. Forcing interactive enrollment: 0.
[6491:6491:1210/134621.095367:VERBOSE1:wizard_controller.cc(1360)] SetCurrentScreenSmooth: oauth-enrollment
[6491:6491:1210/134621.095597:VERBOSE1:gaia_screen_handler.cc(848)] HandleCompleteLogin
[6491:6491:1210/134621.151296:ERROR:CONSOLE(10495)] "TypeError: Cannot read property 'showStep' of null
    at Object.api.(anonymous function) [as showStep] (chrome://oobe/oobe.js:416:28)
    at <anonymous>:1:29", source: chrome://oobe/oobe.js (10495)
[6491:6491:1210/134621.151387:ERROR:CONSOLE(416)] "Uncaught TypeError: Cannot read property 'showStep' of null", source: chrome://oobe/oobe.js (416)
[6491:6491:1210/134621.166078:WARNING:CONSOLE(2651)] "Could not find style data in module named", source: chrome://resources/polymer/v1_0/polymer/polymer-extracted.js (2651)
[6491:6491:1210/134621.369099:WARNING:CONSOLE(293)] "<webview>: The load has aborted with error -3: ERR_ABORTED.", source: extensions::webViewEvents (293)
[6491:6491:1210/134621.433944:VERBOSE1:signin_screen_handler.cc(1372)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0
[6491:6491:1210/134621.434232:VERBOSE1:webui_login_view.cc(595)] Login WebUI >> login-prompt-visible
[6491:6491:1210/134621.446439:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134622.956359:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134622.983697:WARNING:CONSOLE(17394)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/oobe.js (17394)
[6491:6491:1210/134645.864692:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134710.431164:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134739.935763:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update


This looks a bit weird. I guess some flag on a device got in a weird state and we need to reset it -- that's why I filed the internal one. Sorry if I'm wrong.

Comment 5 by apronin@chromium.org, Dec 11 

Re #3:
I don't know what's special about rikku: can they be configured to force enrollment unlike other DUTs? I don't quite understand Chrome logs but it seems to me it shows enrollment screen - need Chrome UI guys to take a look and confirm.

1) it started here:
START	----	tast.security.NetworkListenersNonARC	timestamp=1544477901	localtime=Dec 10 13:38:21	
	FAIL	----	tast.security.NetworkListenersNonARC	timestamp=1544478018	localtime=Dec 10 13:40:18	Failed to log in: not mounted for testuser@gmail.com: context deadline exceeded; last error follows: /home/user/be5e0b8aff341a753d579df71751645c3f41e5c2 not found

by the time this test is run, everything is initialized just fine:
2018-12-10T21:38:21.348757+00:00 INFO cryptohomed[830]: Attestation: Prepared successfully (7099 ms).

We initiate login, the user is not on disk yet, will need to create it (expected iiuc):
2018-12-10T21:38:23.739365+00:00 WARNING cryptohomed[830]: No valid keysets on disk for be5e0b8aff341a753d579df71751645c3f41e5c2


Eventually, Chrome gets to this point and doesn't seem to actually login, instead it shows enrollment screen ("SetCurrentScreenSmooth: oauth-enrollment")?
[3962:3962:1210/133826.883271:VERBOSE1:wizard_controller.cc(836)] SkipToLoginForTesting.
[3962:3962:1210/133826.883932:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia).
[3962:3962:1210/133826.883970:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5
[3962:3962:1210/133826.884096:VERBOSE1:wizard_controller.cc(2092)] Showing enrollment screen. Forcing interactive enrollment: 0.
[3962:3962:1210/133826.884145:VERBOSE1:wizard_controller.cc(1360)] SetCurrentScreenSmooth: oauth-enrollment
[3962:3962:1210/133826.888201:VERBOSE1:gaia_screen_handler.cc(848)] HandleCompleteLogin
...
[3962:3962:1210/133827.249442:VERBOSE1:webui_login_view.cc(595)] Login WebUI >> login-prompt-visible
[3962:3962:1210/133827.304483:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[3962:4019:1210/133827.649848:WARNING:spdy_session.cc(3178)] Received HEADERS for invalid stream 3
[3962:3962:1210/133828.890813:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[3962:3962:1210/133828.920542:WARNING:CONSOLE(17394)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/oobe.js (17394)
[3962:3962:1210/133851.468272:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[3962:3962:1210/133918.591697:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[3962:3962:1210/133942.624258:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update



2) when tast.ui.ChromeLogin eventually runs (there are more test failures before that):
START	----	tast.ui.ChromeLogin	timestamp=1544478375	localtime=Dec 10 13:46:15	
	FAIL	----	tast.ui.ChromeLogin	timestamp=1544478493	localtime=Dec 10 13:48:13	Chrome login failed: not mounted for testuser@gmail.com: context deadline exceeded; last error follows: /home/user/be5e0b8aff341a753d579df71751645c3f41e5c2 not found
END FAIL	----	tast.ui.ChromeLogin	timestamp=1544478493	localtime=Dec 10 13:48:13

Chrome just crashed at the end of the previous test:
2018-12-10T21:46:15.752134+00:00 WARNING crash_reporter[6307]: [user] Received crash notification for chrome[6166] sig 11, user 1000 group 1000 (ignoring call by kernel - chrome crash; waiting for chrome to call us directly)
2018-12-10T21:46:15.816713+00:00 INFO session_manager[6148]: [INFO:session_manager_service.cc(306)] Browser process 6166 exited with signal 11 (Segmentation fault)

But other than that, same thing as in #1:
user is not there yet:
2018-12-10T21:46:17.965059+00:00 WARNING cryptohomed[830]: No valid keysets on disk for be5e0b8aff341a753d579df71751645c3f41e5c2

Chrome shows enrollment screen?
[6491:6491:1210/134621.093893:VERBOSE1:wizard_controller.cc(836)] SkipToLoginForTesting.
[6491:6491:1210/134621.094900:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia).
[6491:6491:1210/134621.094940:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5
[6491:6491:1210/134621.095310:VERBOSE1:wizard_controller.cc(2092)] Showing enrollment screen. Forcing interactive enrollment: 0.
[6491:6491:1210/134621.095367:VERBOSE1:wizard_controller.cc(1360)] SetCurrentScreenSmooth: oauth-enrollment
[6491:6491:1210/134621.095597:VERBOSE1:gaia_screen_handler.cc(848)] HandleCompleteLogin
...
[6491:6491:1210/134621.434232:VERBOSE1:webui_login_view.cc(595)] Login WebUI >> login-prompt-visible
[6491:6491:1210/134621.446439:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134622.956359:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134622.983697:WARNING:CONSOLE(17394)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/oobe.js (17394)
[6491:6491:1210/134645.864692:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134710.431164:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[6491:6491:1210/134739.935763:WARNING:enrollment_screen_handler.cc(686)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update

Comment 6 by derat@chromium.org, Dec 11

Owner: jdufault@chromium.org
Status: Assigned (was: Untriaged)
Jacob, can you figure out why Chrome is showing the enrollment screen on some rikku devices in the lab?

Comment 7 by xiy...@chromium.org, Dec 11 

It maybe as Jun suspected that is caused by some config on the lab device and some caused this line [1] is reached. Jun file b/120789934 to check that out.

[1] https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/wizard_controller.cc?rcl=7ff583308e6209af7f37f5a2605dfb9aa6c21a72&l=1244

Comment 8 by jdufault@chromium.org, Dec 11 

Nothing stands out - since this has been a frequent issue I'm going to add some logging which explains why we're showing enrollment.
Project Member

Comment 9 by bugdroid1@chromium.org, Dec 11 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/91782b91fea6ad588b5c221a79b1dc3cbb4c696c

commit 91782b91fea6ad588b5c221a79b1dc3cbb4c696c
Author: Jacob Dufault <jdufault@google.com>
Date: Tue Dec 11 22:05:16 2018

cros: Add some additional logging for why enrollment is shown

Bug: 912234
Change-Id: I1f1e0a22c0866ecca1c988695b6651851120fe4d
Reviewed-on: https://chromium-review.googlesource.com/c/1372528
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Jacob Dufault <jdufault@chromium.org>
Cr-Commit-Position: refs/heads/master@{#615682}
[modify] https://crrev.com/91782b91fea6ad588b5c221a79b1dc3cbb4c696c/chrome/browser/chromeos/login/existing_user_controller.cc
[modify] https://crrev.com/91782b91fea6ad588b5c221a79b1dc3cbb4c696c/chrome/browser/chromeos/login/wizard_controller.cc

Comment 10 by xiy...@chromium.org, Dec 14 

Also happened on guado_moblab-release.

https://stainless.corp.google.com/browse/chromeos-autotest-results/266775684-chromeos-test/

In chrome_20181213-063519, which corresponds to ui.ChromeLogin
====
[378:378:1213/063523.637814:VERBOSE1:wizard_controller.cc(1260)] StartEnrollment from OnDeviceDisabledChecked(device_disabled=0) skip_update_enroll_after_eula_=0, prescribed_enrollment_config_.should_enroll()=1, configuration_forced_enrollment=0
====

prescribed_enrollment_config_.should_enroll()=1 triggers enrollment. Is it because the device has some state?

Comment 11 by mukai@chromium.org, Dec 26 

Happened again with guado_moblab-release: same log entry found

[8617:8617:1225/060727.548057:VERBOSE1:wizard_controller.cc(1130)] StartEnrollment from OnDeviceDisabledChecked(device_disabled=0) skip_update_enroll_after_eula_=0, prescribed_enrollment_config_.should_enroll()=1, configuration_forced_enrollment=0

(https://00e9e64bac0660b9c90ca9aaf3d6d87413425b9a92cc2ab4d0-apidata.googleusercontent.com/download/storage/v1/b/chromeos-autotest-results/o/270480517-chromeos-test%2Fchromeos2-row2-rack8-host5%2Ftast%2Fresults%2Fsystem_logs%2Fchrome%2Fchrome_20181225-060722?qk=AD5uMEvz-_lIzlhdCKpgCD9FOdSQPKo21ARd6hwmGnxFCEuhypy6lgnQx_sKFXOPr1u_3cCGK2-nGfk0aOZMRY_tJfZPoW_0tesiQiH-Ci4vFhpf7b0vMYvoafrzUbdFLwVbcTxjCYyZ1eiOqxj1bKzMv5EI9uaZNgXOFCv_afxh8H-xgRJHLNin08AH8H3YiGrGKTyjzbQPB1Ui8OhaN2jqUnWT2wDW_mFksn8zd2Zh6bMcEtrilr5dNVJePtL9lSCK9xf4Qo_vNNo1fhBATfqoffG-V4MMwE20b4G44cTfkaLff5orYHzEGshDPwNfPymNtxa94mbfgOL-roSIm_slkJkhEn7vL9Ue0i-nxrkJHAwQxzZd2VNLT79rlaKCHxkQdCVnsdq55QjDaZ0W-kNZQJIIOpmTqLxHHFnZiyF0-10Q9H2k7Oo9vMGfgIZJsrxEnzU-zj2OP2Vi0rY-983asN1yNrh8wb6u_qC4s-L059NhGE7P_i7kH5uyrGZHBVkk0W6d39WsiI1IiB3D_TPnPM0qUYpHc07_oQqzXx6XEYVEZ3BBt_zkBRy3pg2aOnYjNL1NTkYqy4zkHrixE9Q3lLhsXUIZUIJwYRtE6SWYkquoFGyVCF48KReHmIjMJq9DMUBtYAzb1Cb60O0y0cfuevcWn_pabXbX54v-P9JH0E-ihhfy8fiOG_bNtFqqMBmO3bZWhQb1xd-CYks9q8WdTv_GHRYCKPZah3L7Q3bheAnAe64a6prOGzAUJrNrFZApnECfc7v-twdAwUDRcd32kIaQVy4GjnpZgWiEsH6AUP1K2FltWHdyHBgOgu_t7X6nj4EkJWTKiKixS09fyHUrQnJDBLhjFcwKVdOtRkOrJ1tY3ZQIYFFRtEADhIGUg2jHZRPgKe0f1ezrKprFtJk47jmLwglGfQ)
►

Sign in to add a comment